diff --git a/Makefile.am b/Makefile.am index d5108c9f..fe5b6850 100644 --- a/Makefile.am +++ b/Makefile.am @@ -65,7 +65,9 @@ test_spine_faults_SOURCES = $(spine_shared_sources) tests/test_spine_faults.c test_spine_faults_CPPFLAGS = $(AM_CPPFLAGS) -I$(srcdir) test_spine_faults_LDADD = test_spine_regressions-spine.$(OBJEXT) test_spine_faults_LDFLAGS = $(AM_LDFLAGS) -Wl,--wrap=strftime -Wl,--wrap=mysql_query -Wl,--wrap=mysql_ping -Wl,--wrap=mysql_errno \ - -Wl,--wrap=pipe -Wl,--wrap=socketpair -Wl,--wrap=posix_spawn \ + -Wl,--wrap=mysql_real_connect -Wl,--wrap=mysql_thread_id -Wl,--wrap=mysql_store_result \ + -Wl,--wrap=mysql_num_rows -Wl,--wrap=mysql_fetch_row -Wl,--wrap=mysql_free_result -Wl,--wrap=mysql_num_fields \ + -Wl,--wrap=pipe -Wl,--wrap=socketpair -Wl,--wrap=posix_spawn -Wl,--wrap=posix_spawnattr_setpgroup \ -Wl,--wrap=malloc -Wl,--wrap=strdup \ -Wl,--wrap=snmp_sess_open -Wl,--wrap=snmp_sess_close -Wl,--wrap=pthread_create \ -Wl,--wrap=getuid -Wl,--wrap=geteuid -Wl,--wrap=getgid -Wl,--wrap=getegid \ diff --git a/Makefile.in b/Makefile.in index 36a8b24c..8c9bc9c5 100644 --- a/Makefile.in +++ b/Makefile.in @@ -836,7 +836,9 @@ test_spine_regressions_CPPFLAGS = $(AM_CPPFLAGS) -I$(srcdir) -DSPINE_TEST_PROGRA @HAVE_LINKER_WRAP_TRUE@test_spine_faults_CPPFLAGS = $(AM_CPPFLAGS) -I$(srcdir) @HAVE_LINKER_WRAP_TRUE@test_spine_faults_LDADD = test_spine_regressions-spine.$(OBJEXT) @HAVE_LINKER_WRAP_TRUE@test_spine_faults_LDFLAGS = $(AM_LDFLAGS) -Wl,--wrap=strftime -Wl,--wrap=mysql_query -Wl,--wrap=mysql_ping -Wl,--wrap=mysql_errno \ -@HAVE_LINKER_WRAP_TRUE@ -Wl,--wrap=pipe -Wl,--wrap=socketpair -Wl,--wrap=posix_spawn \ +@HAVE_LINKER_WRAP_TRUE@ -Wl,--wrap=mysql_real_connect -Wl,--wrap=mysql_thread_id -Wl,--wrap=mysql_store_result \ +@HAVE_LINKER_WRAP_TRUE@ -Wl,--wrap=mysql_num_rows -Wl,--wrap=mysql_fetch_row -Wl,--wrap=mysql_free_result -Wl,--wrap=mysql_num_fields \ +@HAVE_LINKER_WRAP_TRUE@ -Wl,--wrap=pipe -Wl,--wrap=socketpair -Wl,--wrap=posix_spawn -Wl,--wrap=posix_spawnattr_setpgroup \ @HAVE_LINKER_WRAP_TRUE@ -Wl,--wrap=malloc -Wl,--wrap=strdup \ @HAVE_LINKER_WRAP_TRUE@ -Wl,--wrap=snmp_sess_open -Wl,--wrap=snmp_sess_close -Wl,--wrap=pthread_create \ @HAVE_LINKER_WRAP_TRUE@ -Wl,--wrap=getuid -Wl,--wrap=geteuid -Wl,--wrap=getgid -Wl,--wrap=getegid \ diff --git a/error.c b/error.c index 3f6a5874..80ece8d7 100644 --- a/error.c +++ b/error.c @@ -98,12 +98,15 @@ static void spine_signal_handler(int spine_signal) { const char *message = NULL; int saved_errno = errno; - /* A real fault (SIGSEGV/SIGBUS/...) resets to SIG_DFL and returns so the - * faulting instruction re-executes and dies with a core. SIGPIPE is a - * routine, recurring condition instead, and signal dispositions are - * process-wide: dropping it to SIG_DFL here, even briefly, would let a - * broken-pipe write on any other thread terminate the process during - * that window. Leave this handler permanently installed for SIGPIPE. */ + /* Every signal handled here except SIGSEGV, which exits with status 1 + * below, resets to SIG_DFL and is raised again before returning, so the + * process ends with that signal's default action and core. Returning alone only ended real faults, which re-execute; after + * SIGINT, SIGQUIT or a sent SIGBUS the poller logged FATAL and kept going. + * SIGPIPE is a routine, recurring condition instead, and signal + * dispositions are process-wide: dropping it to SIG_DFL here, even + * briefly, would let a broken-pipe write on any other thread terminate + * the process during that window. Leave this handler permanently + * installed for SIGPIPE. */ if (spine_signal != SIGPIPE) { signal(spine_signal, SIG_DFL); } @@ -149,6 +152,12 @@ static void spine_signal_handler(int spine_signal) { _exit(1); } + /* The signal stays blocked until this handler returns, then the default + * action ends the process. raise() is async-signal-safe. */ + if (spine_signal != SIGPIPE) { + (void) raise(spine_signal); + } + errno = saved_errno; } diff --git a/nft_popen.c b/nft_popen.c index 67898a4f..42537ccc 100644 --- a/nft_popen.c +++ b/nft_popen.c @@ -364,6 +364,9 @@ int nft_popen(const char * command, const char * type) { /* nft_popen() reports why process creation failed through errno, as * popen() does; cleanup below must not overwrite it. */ int failure_errno = 0; + posix_spawnattr_t attr; + int attr_valid = FALSE; + int attr_err; if (command == NULL || type == NULL) { errno = EINVAL; @@ -445,6 +448,21 @@ int nft_popen(const char * command, const char * type) { return -1; } + /* Each script leads its own process group so a timeout can kill the + * group. Killing only the shell left anything it had started running, + * still holding the pipe and counting against the process limit. */ + attr_err = posix_spawnattr_init(&attr); + if (attr_err == 0) { + attr_valid = TRUE; + attr_err = posix_spawnattr_setpgroup(&attr, 0); + } + if (attr_err == 0) attr_err = posix_spawnattr_setflags(&attr, POSIX_SPAWN_SETPGROUP); + if (attr_err != 0) { + failure_errno = attr_err; + SPINE_LOG(("ERROR: SCRIPT: posix_spawnattr setup failed: %s", strerror(attr_err))); + goto spawn_failed; + } + /* The pipe ends are close-on-exec, which is the point: another thread * spawning in this window must not inherit them. The child needs its own * end, and dup2 clears the flag on its target, so the usual paths are @@ -521,7 +539,7 @@ int nft_popen(const char * command, const char * type) { int spawn_err; retry: - spawn_err = posix_spawn(&pid, spawn_shell, &fa, NULL, argv, environ); + spawn_err = posix_spawn(&pid, spawn_shell, &fa, &attr, argv, environ); if (spawn_err != 0) { if ((spawn_err == EAGAIN || spawn_err == ENOMEM) && retry_count < 3) { @@ -540,6 +558,7 @@ int nft_popen(const char * command, const char * type) { * nft_pclose() in every poller thread and the daemon stops collecting * script data until it is restarted. */ posix_spawn_file_actions_destroy(&fa); + if (attr_valid) posix_spawnattr_destroy(&attr); if (inherit_fd != -1) { (void)close(inherit_fd); @@ -559,6 +578,7 @@ int nft_popen(const char * command, const char * type) { } posix_spawn_file_actions_destroy(&fa); + posix_spawnattr_destroy(&attr); /* The child holds its own duplicate. Keeping this one would hold the pipe's * write end open, so the reader never sees EOF and exec_poll() blocks to @@ -688,7 +708,8 @@ nft_pclose(int fd) pid = cur->pid; break; case 1: - (void)kill(cur->pid, SIGKILL); + /* The negative pid reaches the script's whole process group. */ + (void)kill(-cur->pid, SIGKILL); nft_abandon_child(cur->pid, "did not exit before pipe close"); errno = ETIMEDOUT; pid = -1; @@ -699,7 +720,7 @@ nft_pclose(int fd) * outside the sweep's reach. Preserve waitpid()'s errno. */ { int saved_errno = errno; - (void)kill(cur->pid, SIGKILL); + (void)kill(-cur->pid, SIGKILL); nft_abandon_child(cur->pid, "waitpid failed"); errno = saved_errno; } diff --git a/php.c b/php.c index ff318c5f..fc1d0582 100644 --- a/php.c +++ b/php.c @@ -84,6 +84,17 @@ static char *php_undefined_result(void) { return result; } +/* Script and script server arguments can carry SNMP communities and v3 + * passphrases, so logs name only the first token, the script, never the + * arguments. */ +void php_command_script(const char *command, char *script, size_t capacity) { + size_t length = strcspn(command, " \t\r\n"); + + if (length >= capacity) length = capacity - 1; + memcpy(script, command, length); + script[length] = '\0'; +} + static void php_fail_read(int php_process, int allow_restart) { php_processes[php_process].php_state = PHP_BUSY; if (allow_restart) { @@ -106,7 +117,7 @@ void php_processes_initialize(php_t *processes, int count) { } } -static char *php_read_result(int php_process, char *command, int allow_restart); +static char *php_read_result(int php_process, const char *command, int allow_restart); /* Block SIGPIPE in the calling thread around Spine's two pipe writes. The * daemon normally catches SIGPIPE with a no-op handler process-wide, but this local guard @@ -201,7 +212,11 @@ char *php_cmd(const char *php_command, int php_process) { /* if write status is <= 0 then the script server may be hung */ if (bytes <= 0) { - SPINE_LOG(("ERROR: SS[%i] PHP Script Server communications lost sending Command[%s]. Restarting PHP Script Server", php_process, command)); + char script[SMALL_BUFSIZE]; + + php_command_script(command, script, sizeof(script)); + SPINE_LOG(("ERROR: SS[%i] PHP Script Server communications lost sending a command. Restarting PHP Script Server", php_process)); + SPINE_LOG_DEBUG(("DEBUG: SS[%i] Unsent command for script '%s'", php_process, script)); php_close(php_process); retries++; @@ -323,7 +338,7 @@ char *php_read_result_for_test(int php_process, char *command, int allow_restart } #endif -/*! \fn char *php_readpipe(int php_process, char *command) +/*! \fn char *php_readpipe(int php_process, const char *command) * \brief read a line from a PHP Script Server process * \param php_process the PHP Script Server process to obtain output from * @@ -334,7 +349,7 @@ char *php_read_result_for_test(int php_process, char *command, int allow_restart * * \return a string pointer to the PHP Script Server response */ -/*! \fn static char *php_read_result(int php_process, char *command, int allow_restart) +/*! \fn static char *php_read_result(int php_process, const char *command, int allow_restart) * \brief reads one script server response. * * allow_restart is FALSE for the startup handshake. php_init() calls this to @@ -344,7 +359,7 @@ char *php_read_result_for_test(int php_process, char *command, int allow_restart * recursion, spawning a fresh server at every level. Refusing the restart on * the handshake bounds the depth at one by construction. */ -static char *php_read_result(int php_process, char *command, int allow_restart) { +static char *php_read_result(int php_process, const char *command, int allow_restart) { fd_set fds; struct timeval timeout; double begin_time = 0; @@ -353,6 +368,7 @@ static char *php_read_result(int php_process, char *command, int allow_restart) char *result_string; int response_timeout; double read_deadline; + char script[SMALL_BUFSIZE]; ssize_t i; char *cp; @@ -450,7 +466,9 @@ static char *php_read_result(int php_process, char *command, int allow_restart) case 0: /* record end time */ end_time = get_time_as_double(); - SPINE_LOG(("WARNING: SS[%i] The PHP Script Server did not respond in time for Timeout[%0.2f], Command[%s] and will therefore be restarted", php_process, end_time - begin_time, command)); + SPINE_LOG(("WARNING: SS[%i] The PHP Script Server did not respond in time for Timeout[%0.2f] and will therefore be restarted", php_process, end_time - begin_time)); + php_command_script(command, script, sizeof(script)); + SPINE_LOG_DEBUG(("DEBUG: SS[%i] Unanswered command for script '%s'", php_process, script)); SET_UNDEFINED(result_string); php_fail_read(php_process, allow_restart); break; @@ -478,7 +496,9 @@ static char *php_read_result(int php_process, char *command, int allow_restart) int ready = spine_wait_readable(php_processes[php_process].php_read_fd, read_deadline); if (ready <= 0) { - SPINE_LOG(("WARNING: SS[%i] The PHP Script Server sent a partial response and %s, Command[%s]", php_process, ready == 0 ? "timed out" : "failed", command)); + SPINE_LOG(("WARNING: SS[%i] The PHP Script Server sent a partial response and %s", php_process, ready == 0 ? "timed out" : "failed")); + php_command_script(command, script, sizeof(script)); + SPINE_LOG_DEBUG(("DEBUG: SS[%i] Unanswered command for script '%s'", php_process, script)); SET_UNDEFINED(result_string); read_ok = FALSE; break; @@ -529,13 +549,13 @@ static char *php_read_result(int php_process, char *command, int allow_restart) return result_string; } -/*! \fn char *php_readpipe(int php_process, char *command) +/*! \fn char *php_readpipe(int php_process, const char *command) * \brief reads a script server response, restarting a server that stops * answering. * * \return a string pointer to the PHP Script Server response */ -char *php_readpipe(int php_process, char *command) { +char *php_readpipe(int php_process, const char *command) { return php_read_result(php_process, command, TRUE); } diff --git a/php.h b/php.h index 5aa3fa9e..c2782a49 100644 --- a/php.h +++ b/php.h @@ -34,7 +34,8 @@ #ifndef SPINE_PHP_H #define SPINE_PHP_H extern char *php_cmd(const char *php_command, int php_process); -extern char *php_readpipe(int php_process, char *command); +extern char *php_readpipe(int php_process, const char *command); +extern void php_command_script(const char *command, char *script, size_t capacity); extern int php_init(int php_process); extern void php_close(int php_process); extern int php_get_process(void); diff --git a/poller.c b/poller.c index 23d994e2..2e0d8e56 100644 --- a/poller.c +++ b/poller.c @@ -213,8 +213,11 @@ static void record_result_error(const poll_error_context_t *context, const host_ context->host_id, context->thread_id, item->local_data_id, host->snmp.profile.version, host->hostname, item->rrd_name, item->arg1, result)); } else { + char script[SMALL_BUFSIZE]; + + php_command_script(item->arg1, script, sizeof(script)); SPINE_LOG(("WARNING: Invalid Response, Device[%i] HT[%i] DS[%i] SCRIPT: %s, output: %s", - context->host_id, context->thread_id, item->local_data_id, item->arg1, result)); + context->host_id, context->thread_id, item->local_data_id, script, result)); } } @@ -568,12 +571,13 @@ static void log_reindex_assertion(const reindex_evaluation_t *evaluation, const SPINE_LOG(("Device[%i] HT[%i] DQ[%i] RECACHE ASSERT FAILED: '%s%s%s'", evaluation->host->id, evaluation->work->host_thread, reindex->data_query_id, reindex->assert_value, failed ? reindex->op : "=", value != NULL ? value : "(null)")); } -static void queue_reindex(const reindex_evaluation_t *evaluation, const reindex_t *reindex) { - if (evaluation->work->host_thread != 1) return; +/* FALSE only when the queue write failed; other partitions never queue. */ +static bool queue_reindex(const reindex_evaluation_t *evaluation, const reindex_t *reindex) { + if (evaluation->work->host_thread != 1) return TRUE; char query[LRG_BUFSIZE]; snprintf(query, sizeof(query), "REPLACE INTO poller_command (poller_id, time, action, command) VALUES (%i, NOW(), %i, '%i:%i')", set.poller.poller_id, POLLER_COMMAND_REINDEX, evaluation->host->id, reindex->data_query_id); - if (set.poller.poller_id > 1 && set.poller.mode == REMOTE_ONLINE) db_insert(evaluation->remote, REMOTE, query); - else db_insert(evaluation->local, LOCAL, query); + if (set.poller.poller_id > 1 && set.poller.mode == REMOTE_ONLINE) return db_insert(evaluation->remote, REMOTE, query); + return db_insert(evaluation->local, LOCAL, query); } static void update_reindex_value(const reindex_evaluation_t *evaluation, const reindex_t *reindex, const char *value) { @@ -602,8 +606,10 @@ static bool evaluate_reindex_assertion(const reindex_evaluation_t *evaluation, c bool failed = reindex_assertion_failed(reindex, value); bool unavailable = value == NULL || IS_UNDEFINED(value) || STRIMATCH(value, "No Such Instance"); if (failed || unavailable) log_reindex_assertion(evaluation, reindex, value, failed); - if (failed) queue_reindex(evaluation, reindex); - if (failed || STRMATCH(reindex->op, ">") || STRMATCH(reindex->op, "<")) update_reindex_value(evaluation, reindex, value); + /* Advancing the stored value without a queued reindex would lose the + * reindex for good: the next poll compares against the new value. */ + bool queued = !failed || queue_reindex(evaluation, reindex); + if (queued && (failed || STRMATCH(reindex->op, ">") || STRMATCH(reindex->op, "<"))) update_reindex_value(evaluation, reindex, value); /* A failed uptime assertion means the counters reset, so the sample is a spike. */ if (failed && (STRMATCH(reindex->op, "<") || STRMATCH(reindex->arg1, ".1.3.6.1.2.1.1.3.0") || @@ -685,6 +691,7 @@ static char *poll_reindex_snmp(host_t *host, reindex_t *reindex, int host_thread static char *poll_reindex_action(host_t *host, reindex_t *reindex, int host_thread, char *sysUptime, bool *unavailable) { char *poll_result = NULL; int php_process; + char script[SMALL_BUFSIZE]; switch(reindex->action) { case POLLER_ACTION_SNMP: poll_result = poll_reindex_snmp(host, reindex, host_thread, sysUptime, unavailable); @@ -699,7 +706,8 @@ static char *poll_reindex_action(host_t *host, reindex_t *reindex, int host_thre poll_result = trim(exec_poll(host, reindex->arg1, reindex->data_query_id, "DQ")); - SPINE_LOG_DEVICE(host->id, POLLER_VERBOSITY_MEDIUM, ("Device[%i] HT[%i] DQ[%i] RECACHE CMD: %s, output: %s", host->id, host_thread, reindex->data_query_id, reindex->arg1, poll_result)); + php_command_script(reindex->arg1, script, sizeof(script)); + SPINE_LOG_DEVICE(host->id, POLLER_VERBOSITY_MEDIUM, ("Device[%i] HT[%i] DQ[%i] RECACHE CMD: %s, output: %s", host->id, host_thread, reindex->data_query_id, script, poll_result)); break; case POLLER_ACTION_PHP_SCRIPT_SERVER: /* script (php script server) */ @@ -707,7 +715,8 @@ static char *poll_reindex_action(host_t *host, reindex_t *reindex, int host_thre poll_result = trim(php_cmd(reindex->arg1, php_process)); - SPINE_LOG_DEVICE(host->id, POLLER_VERBOSITY_MEDIUM, ("Device[%i] HT[%i] DQ[%i] RECACHE SERVER: %s, output: %s", host->id, host_thread, reindex->data_query_id, reindex->arg1, poll_result)); + php_command_script(reindex->arg1, script, sizeof(script)); + SPINE_LOG_DEVICE(host->id, POLLER_VERBOSITY_MEDIUM, ("Device[%i] HT[%i] DQ[%i] RECACHE SERVER: %s, output: %s", host->id, host_thread, reindex->data_query_id, script, poll_result)); break; case POLLER_ACTION_SNMP_COUNT: { /* snmp; count items */ @@ -737,7 +746,8 @@ static char *poll_reindex_action(host_t *host, reindex_t *reindex, int host_thre snprintf(poll_result, BUFSIZE, "%d", char_count(count_result, '\n')); SPINE_FREE(count_result); - SPINE_LOG_DEVICE(host->id, POLLER_VERBOSITY_MEDIUM, ("Device[%i] HT[%i] DQ[%i] RECACHE CMD COUNT: %s, output: %s", host->id, host_thread, reindex->data_query_id, reindex->arg1, poll_result)); + php_command_script(reindex->arg1, script, sizeof(script)); + SPINE_LOG_DEVICE(host->id, POLLER_VERBOSITY_MEDIUM, ("Device[%i] HT[%i] DQ[%i] RECACHE CMD COUNT: %s, output: %s", host->id, host_thread, reindex->data_query_id, script, poll_result)); break; } @@ -753,7 +763,8 @@ static char *poll_reindex_action(host_t *host, reindex_t *reindex, int host_thre spine_snprintf(poll_result, BUFSIZE, "%d", char_count(count_result, '\n')); SPINE_FREE(count_result); - SPINE_LOG_DEVICE(host->id, POLLER_VERBOSITY_MEDIUM, ("Device[%i] HT[%i] DQ[%i] RECACHE SERVER COUNT: %s, output: %s", host->id, host_thread, reindex->data_query_id, reindex->arg1, poll_result)); + php_command_script(reindex->arg1, script, sizeof(script)); + SPINE_LOG_DEVICE(host->id, POLLER_VERBOSITY_MEDIUM, ("Device[%i] HT[%i] DQ[%i] RECACHE SERVER COUNT: %s, output: %s", host->id, host_thread, reindex->data_query_id, script, poll_result)); break; } @@ -781,9 +792,9 @@ static void load_reindex_item(reindex_t *reindex, MYSQL_ROW row) { if (row[4] != NULL) snprintf(reindex->arg1, sizeof(reindex->arg1), "%s", row[4]); } -static void poll_host_reindex(host_t *host, reindex_t *reindex, const char *query, +static bool poll_host_reindex(host_t *host, reindex_t *reindex, const char *query, const reindex_evaluation_t *evaluation) { - if (host->ignore_host || evaluation->work->host_id == 0) return; + if (host->ignore_host || evaluation->work->host_id == 0) return TRUE; int thread = evaluation->work->host_thread; MYSQL_RES *result = db_query(evaluation->local, LOCAL, query); if (result == NULL) { @@ -819,6 +830,7 @@ static void poll_host_reindex(host_t *host, reindex_t *reindex, const char *quer snmp_host_cleanup(host->snmp.session); host->snmp.session = NULL; } + return result != NULL; } static void load_poll_item(target_t *item, MYSQL_ROW row) { @@ -911,10 +923,12 @@ static void poll_script_item(host_t *host, target_t *item, } SPINE_FREE(poll_result); double thread_end = get_time_as_double(); + char script[SMALL_BUFSIZE]; + php_command_script(item->arg1, script, sizeof(script)); if (script_server) { - SPINE_LOG_DEVICE(errors->host_id, POLLER_VERBOSITY_MEDIUM, ("Device[%i] HT[%i] DS[%i] TT[%.2f] SS[%i] SERVER: %s, output: %s", errors->host_id, errors->thread_id, item->local_data_id, (float) ((thread_end - thread_start) * 1000), php_process, item->arg1, item->result)); + SPINE_LOG_DEVICE(errors->host_id, POLLER_VERBOSITY_MEDIUM, ("Device[%i] HT[%i] DS[%i] TT[%.2f] SS[%i] SERVER: %s, output: %s", errors->host_id, errors->thread_id, item->local_data_id, (float) ((thread_end - thread_start) * 1000), php_process, script, item->result)); } else { - SPINE_LOG_DEVICE(errors->host_id, POLLER_VERBOSITY_MEDIUM, ("Device[%i] HT[%i] DS[%i] TT[%.2f] SCRIPT: %s, output: %s", errors->host_id, errors->thread_id, item->local_data_id, (float) ((thread_end - thread_start) * 1000), item->arg1, item->result)); + SPINE_LOG_DEVICE(errors->host_id, POLLER_VERBOSITY_MEDIUM, ("Device[%i] HT[%i] DS[%i] TT[%.2f] SCRIPT: %s, output: %s", errors->host_id, errors->thread_id, item->local_data_id, (float) ((thread_end - thread_start) * 1000), script, item->result)); } /* insert a NaN in place of the actual value if the snmp agent restarts */ if (!IS_UNDEFINED(item->result) && spike_kill && !strstr(item->result, ":")) SET_UNDEFINED(item->result); @@ -1197,6 +1211,7 @@ static int collect_poll_items(host_t *host, snmp_poll_batch_t *batch, int num_ro int i = 0; int rows_processed = 0; double thread_start = 0; + char script[SMALL_BUFSIZE]; while ((i < num_rows) && (!host->ignore_host)) { thread_start = get_time_as_double(); @@ -1211,7 +1226,8 @@ static int collect_poll_items(host_t *host, snmp_poll_batch_t *batch, int num_ro poll_script_item(host, &batch->items[i], batch->errors, thread_start, spike_kill, TRUE); break; default: /* unknown action, generate error */ - SPINE_LOG(("Device[%i] HT[%i] DS[%i] ERROR: Unknown Poller Action: %s", batch->errors->host_id, batch->errors->thread_id, batch->items[i].local_data_id, batch->items[i].arg1)); + php_command_script(batch->items[i].arg1, script, sizeof(script)); + SPINE_LOG(("Device[%i] HT[%i] DS[%i] ERROR: Unknown Poller Action: %s", batch->errors->host_id, batch->errors->thread_id, batch->items[i].local_data_id, script)); break; } @@ -1246,9 +1262,16 @@ static void release_poll_connections(const poller_thread_t *work, } } -/* FALSE requests the existing missing-device early return. Other database - * failures leave the host ignored and continue through the normal caller. */ -static bool load_poll_host(MYSQL *mysql, const poller_queries_t *queries, +typedef enum { + POLL_HOST_LOADED, + POLL_HOST_MISSING, + POLL_HOST_FAILED +} poll_host_load_t; + +/* A device deleted since selection returns quietly. A failed device query + * fails the device: treating it as an ignored host would still advance its + * schedule and drop the samples it never collected. */ +static poll_host_load_t load_poll_host(MYSQL *mysql, const poller_queries_t *queries, host_t *host, ping_t *ping, const poller_thread_t *work) { /* host_id=0 denotes a data source without a device. */ if (!work->host_id) { @@ -1256,22 +1279,22 @@ static bool load_poll_host(MYSQL *mysql, const poller_queries_t *queries, host->snmp.max_oids = 1; host->snmp.session = NULL; host->ignore_host = FALSE; - return TRUE; + return POLL_HOST_LOADED; } MYSQL_RES *result = db_query(mysql, LOCAL, queries->host); if (result == NULL) { - host->ignore_host = TRUE; - return TRUE; + SPINE_LOG(("Device[%i] HT[%i] ERROR: Unable to load the device", work->host_id, work->host_thread)); + return POLL_HOST_FAILED; } if (spine_count_to_int(mysql_num_rows(result)) != 1) { db_free_result(result); - return FALSE; + return POLL_HOST_MISSING; } MYSQL_ROW row = mysql_fetch_row(result); if (row == NULL) { SPINE_LOG(("Device[%i] HT[%i] ERROR: MySQL Returned a Null Device Result", host->id, work->host_thread)); host->ignore_host = TRUE; - return TRUE; + return POLL_HOST_LOADED; } load_host_metadata(mysql, row, host, work); db_free_result(result); @@ -1280,48 +1303,30 @@ static bool load_poll_host(MYSQL *mysql, const poller_queries_t *queries, if (work->host_thread == 1) { persist_host_status(mysql, host, include_system_information && host->ignore_host != TRUE); } - return TRUE; + return POLL_HOST_LOADED; } +/* Publish each partition only after its bookkeeping writes finish. The last + * partition records polling time and advances the schedule after every earlier + * write succeeded. Database waits never hold LOCK_THDET. */ static void complete_poll_host(MYSQL *mysql, poller_queries_t *queries, const poller_thread_t *work, const poll_error_context_t *error_context, - bool output_failed, double poll_start) { + bool output_failed, bool poll_failed, double poll_start) { extern poller_thread_t **details; int host_id = work->host_id; int host_thread = work->host_thread; double host_time_double = work->host_time_double; int errors = *error_context->errors; const char *error_string = error_context->buffer; - double poll_time; - /* record the polling time for the device */ - poll_time = get_time_as_double() - poll_start; - SPINE_LOG_DEVICE(host_id, POLLER_VERBOSITY_MEDIUM, ("Device[%i] HT[%i] Total Time: %0.2g Seconds", host_id, host_thread, poll_time)); - - /* record the total time for the host */ - thread_mutex_lock(LOCK_THDET); poller_thread_t *device = details[work->device_counter]; - if (output_failed) { - device->output_failed = TRUE; - set.exit.exit_code = EXIT_FAILURE; - SPINE_LOG(("ERROR: Device[%i] HT[%i] output write failed; partial writes remain and due items stay eligible for recollection", host_id, host_thread)); - } - device->threads_complete++; - if (device->threads_complete == device->host_threads) { - /* Keep the due-item set stable until every device partition has finished. */ - if (set.poller.active_profiles != 1 && !device->output_failed) { - SPINE_LOG_MEDIUM(("Device[%i] HT[%i] Updating Poller Items for Next Poll", host_id, host_thread)); - db_query(mysql, LOCAL, queries->schedule); - } - device->complete = !device->output_failed; - - poll_time = get_time_as_double(); - queries->items[0] = '\0'; - snprintf(queries->items, BUFSIZE, "UPDATE host SET polling_time = %.3f - %.3f WHERE id = %i", poll_time, host_time_double, host_id); - db_query(mysql, LOCAL, queries->items); + double poll_time = get_time_as_double() - poll_start; + bool last_partition; + bool failed; + bool write_failed = FALSE; - } + SPINE_LOG_DEVICE(host_id, POLLER_VERBOSITY_MEDIUM, ("Device[%i] HT[%i] Total Time: %0.2g Seconds", host_id, host_thread, poll_time)); - if (errors > 0) { + if (!poll_failed && errors > 0) { int error_query_len = spine_count_to_int(strlen(error_string) + BUFSIZE); char *error_query = (char *)malloc(error_query_len); if (error_query == NULL) die("ERROR: Fatal malloc error: poller.c error_query!"); @@ -1333,12 +1338,52 @@ static void complete_poll_host(MYSQL *mysql, poller_queries_t *queries, " local_data_ids = CONCAT(local_data_ids, ', ', VALUES(local_data_ids))", host_id, set.poller.poller_id, errors, error_string); - db_query(mysql, LOCAL, error_query); + if (!db_insert(mysql, LOCAL, error_query)) write_failed = TRUE; free(error_query); } + + thread_mutex_lock(LOCK_THDET); + if (output_failed || write_failed) device->output_failed = TRUE; + if (poll_failed) device->poll_failed = TRUE; + failed = device->output_failed || device->poll_failed; + if (failed) { + device->complete = FALSE; + set.exit.exit_code = EXIT_FAILURE; + } + device->threads_complete++; + last_partition = device->threads_complete == device->host_threads; thread_mutex_unlock(LOCK_THDET); + + if (output_failed || poll_failed || write_failed) { + SPINE_LOG(("ERROR: Device[%i] HT[%i] polling or completion write failed; due items stay eligible for recollection", host_id, host_thread)); + } + if (!last_partition) return; + + if (!poll_failed) { + poll_time = get_time_as_double(); + snprintf(queries->items, BUFSIZE, "UPDATE host SET polling_time = %.3f - %.3f WHERE id = %i", poll_time, host_time_double, host_id); + if (!db_insert(mysql, LOCAL, queries->items)) write_failed = TRUE; + + /* Advancing the due-item set is the final write, after every partition + * and the device polling-time write have reported their outcome. */ + if (!failed && !write_failed && set.poller.active_profiles != 1) { + SPINE_LOG_MEDIUM(("Device[%i] HT[%i] Updating Poller Items for Next Poll", host_id, host_thread)); + if (!db_insert(mysql, LOCAL, queries->schedule)) write_failed = TRUE; + } + } + + thread_mutex_lock(LOCK_THDET); + if (write_failed) { + device->output_failed = TRUE; + set.exit.exit_code = EXIT_FAILURE; + } + device->complete = !device->output_failed && !device->poll_failed; + thread_mutex_unlock(LOCK_THDET); + if (write_failed) { + SPINE_LOG(("ERROR: Device[%i] HT[%i] device completion write failed; the device is not counted as polled", host_id, host_thread)); + } } void poll_host(const poller_thread_t *work, int *host_errors) { @@ -1361,6 +1406,8 @@ void poll_host(const poller_thread_t *work, int *host_errors) { int spike_kill = FALSE; int rows_processed = 0; bool output_failed = FALSE; + bool poll_failed = FALSE; + poll_host_load_t loaded; double poll_time = get_time_as_double(); @@ -1401,15 +1448,27 @@ void poll_host(const poller_thread_t *work, int *host_errors) { MYSQL_RES *result; local_cnn = db_get_connection(LOCAL); - if (local_cnn == NULL) die("ERROR: No local database connection available for polling"); - mysql = &local_cnn->mysql; - - if (set.poller.poller_id > 1 && set.poller.mode == REMOTE_ONLINE) { + if (local_cnn != NULL && set.poller.poller_id > 1 && set.poller.mode == REMOTE_ONLINE) { remote_cnn = db_get_connection(REMOTE); - if (remote_cnn == NULL) die("ERROR: No remote database connection available for polling"); - mysqlr = &remote_cnn->mysql; + if (remote_cnn == NULL) { + db_release_connection(LOCAL, local_cnn->id); + local_cnn = NULL; + } + } + + if (local_cnn == NULL) { + SPINE_LOG(("ERROR: Device[%i] HT[%i] No database connection available for polling", host_id, host_thread)); + complete_poll_host(NULL, NULL, work, &error_context, FALSE, TRUE, poll_time); + SPINE_FREE(error_string); + SPINE_FREE(buf_size); + SPINE_FREE(buf_errors); + mysql_thread_end(); + return; } + mysql = &local_cnn->mysql; + if (remote_cnn != NULL) mysqlr = &remote_cnn->mysql; + /* allocate host and ping structures with appropriate values */ if (!(host = (host_t *) malloc(sizeof(host_t)))) { die("ERROR: Fatal malloc error: poller.c host struct!"); @@ -1438,7 +1497,11 @@ void poll_host(const poller_thread_t *work, int *host_errors) { snprintf(ping->snmp_status, 50, "down"); snprintf(ping->snmp_response, SMALL_BUFSIZE, "SNMP not performed due to setting or ping result"); - if (!load_poll_host(mysql, &queries, host, ping, work)) { + loaded = load_poll_host(mysql, &queries, host, ping, work); + if (loaded == POLL_HOST_FAILED) { + complete_poll_host(mysql, &queries, work, &error_context, FALSE, TRUE, poll_time); + } + if (loaded != POLL_HOST_LOADED) { release_poll_connections(work, local_cnn, remote_cnn); SPINE_FREE(host); SPINE_FREE(reindex); @@ -1471,10 +1534,15 @@ void poll_host(const poller_thread_t *work, int *host_errors) { } const reindex_evaluation_t evaluation = {mysql, mysqlr, host, work, &errors, &spike_kill}; - poll_host_reindex(host, reindex, queries.reindex, &evaluation); + poll_failed = !poll_host_reindex(host, reindex, queries.reindex, &evaluation); /* calculate the number of poller items to poll this cycle */ - result = select_poll_items(mysql, &queries, host, work, &num_rows); + num_rows = 0; + result = NULL; + if (!poll_failed) { + result = select_poll_items(mysql, &queries, host, work, &num_rows); + poll_failed = result == NULL; + } if (num_rows > 0) { poll_item_storage_t storage = load_poll_items(result, host, num_rows); @@ -1514,7 +1582,7 @@ void poll_host(const poller_thread_t *work, int *host_errors) { SPINE_FREE(reindex); SPINE_FREE(ping); - complete_poll_host(mysql, &queries, work, &error_context, output_failed, poll_time); + complete_poll_host(mysql, &queries, work, &error_context, output_failed, poll_failed, poll_time); release_poll_connections(work, local_cnn, remote_cnn); @@ -1708,7 +1776,8 @@ static bool read_script_result(const script_result_context_t *context, int fd, d SPINE_LOG_MEDIUM(("Device[%i] ERROR: The NIFTY POPEN timed out", context->host->id)); int pid = nft_pchild(fd); if (pid > 1) { - kill(pid, SIGKILL); + /* nft_popen() made the script a group leader; take its descendants too. */ + kill(-pid, SIGKILL); } else { SPINE_LOG(("Device[%i] ERROR: Unable to find the timed-out POPEN child", context->host->id)); } @@ -1720,10 +1789,13 @@ static bool read_script_result(const script_result_context_t *context, int fd, d if (bytes > 0 && bytes < RESULTS_BUFFER) { result[bytes] = '\0'; } else { + char script[SMALL_BUFSIZE]; + + php_command_script(context->command, script, sizeof(script)); if (STRIMATCH(context->type, "DS")) { - SPINE_LOG(("Device[%i] DS[%i] ERROR: Empty result [%s]: '%s'", context->host->id, context->id, context->host->hostname, context->command)); + SPINE_LOG(("Device[%i] DS[%i] ERROR: Empty result [%s]: '%s'", context->host->id, context->id, context->host->hostname, script)); } else { - SPINE_LOG(("Device[%i] DQ[%i] ERROR: Empty result [%s]: '%s'", context->host->id, context->id, context->host->hostname, context->command)); + SPINE_LOG(("Device[%i] DQ[%i] ERROR: Empty result [%s]: '%s'", context->host->id, context->id, context->host->hostname, script)); } SET_UNDEFINED(result); } @@ -1803,7 +1875,8 @@ char *exec_poll(host_t *current_host, char *command, int id, const char *type) { strtok_r(executable, " ", &saveptr); } - SPINE_LOG_DEBUG(("The executable is '%s' in \'%s\'", executable, proc_command)); + /* executable is the first token; the arguments can carry credentials. */ + SPINE_LOG_DEBUG(("The executable is '%s'", executable)); if (access(executable, X_OK | F_OK) != -1) { cmd_fd = nft_popen(proc_command, "r"); @@ -1816,11 +1889,11 @@ char *exec_poll(host_t *current_host, char *command, int id, const char *type) { /* close pipe */ nft_pclose(cmd_fd); } else { - SPINE_LOG(("Device[%i] ERROR: Problem executing POPEN [%s]: '%s'", current_host->id, current_host->hostname, command)); + SPINE_LOG(("Device[%i] ERROR: Problem executing POPEN [%s]: '%s'", current_host->id, current_host->hostname, executable)); SET_UNDEFINED(result_string); } } else { - SPINE_LOG(("Device[%i] ERROR: Problem executing POPEN. File '%s' does not exist or is not executable.", current_host->id, command)); + SPINE_LOG(("Device[%i] ERROR: Problem executing POPEN. File '%s' does not exist or is not executable.", current_host->id, executable)); SET_UNDEFINED(result_string); } diff --git a/spine.c b/spine.c index ee1dd047..729ae1a5 100644 --- a/spine.c +++ b/spine.c @@ -651,6 +651,9 @@ static void report_worker_completion(int num_rows) { if (det->output_failed) { SPINE_LOG(("ERROR: Device[%i] output persistence failed; due items remain scheduled for retry", det->host_id)); } + if (det->poll_failed) { + SPINE_LOG(("ERROR: Device[%i] polling failed on a database error; due items remain scheduled for retry", det->host_id)); + } SPINE_LOG_HIGH(("INFO: Device[%i] Thread %scomplete and %d to %d sources", det->host_id, det->complete ? "":"in", @@ -712,6 +715,15 @@ static void launch_poll_workers(MYSQL *mysql, MYSQL_RES *result, int num_rows, while (canexit == FALSE && device_counter < num_rows) { if (change_host) { mysql_row = mysql_fetch_row(result); + /* num_rows comes from this result, so a short read is not expected; + * upstream guarded it and the dispatch refactor dropped the check. */ + if (mysql_row == NULL || mysql_row[0] == NULL || mysql_row[1] == NULL) { + SPINE_LOG(("ERROR: Device list ended after %i of %i devices", device_counter, num_rows)); + thread_mutex_lock(LOCK_THDET); + set.exit.exit_code = EXIT_FAILURE; + thread_mutex_unlock(LOCK_THDET); + break; + } host_id = atoi(mysql_row[0]); partition.threads = atoi(mysql_row[1]); current_thread = 1; @@ -745,6 +757,7 @@ static void launch_poll_workers(MYSQL *mysql, MYSQL_RES *result, int num_rows, poller_details->complete = FALSE; poller_details->threads_complete = 0; poller_details->output_failed = FALSE; + poller_details->poll_failed = FALSE; thread_mutex_lock(LOCK_THDET); details[device_counter] = poller_details; @@ -866,11 +879,12 @@ static double initialize_process_defaults(void) { static int initialize_main_database(MYSQL *mysql, MYSQL *mysqlr) { MYSQL_RES *result; int mode; + int has_output_regex; /* initialize mysql objects for threads */ mysql_library_init(0, NULL, NULL); /* connect for main loop */ - db_connect(LOCAL, mysql); + if (!db_connect(LOCAL, mysql)) die("FATAL: Unable to connect to the local database"); /* setup local connection pool for hosts */ db_pool_local = (pool_t *) calloc(set.poller.threads, sizeof(pool_t)); @@ -878,7 +892,7 @@ static int initialize_main_database(MYSQL *mysql, MYSQL *mysqlr) { db_create_connection_pool(LOCAL); if (set.poller.poller_id > 1 && set.poller.mode == REMOTE_ONLINE) { - db_connect(REMOTE, mysqlr); + if (!db_connect(REMOTE, mysqlr)) die("FATAL: Unable to connect to the remote database"); mode = REMOTE; /* setup remote connection pool for hosts */ @@ -892,20 +906,23 @@ static int initialize_main_database(MYSQL *mysql, MYSQL *mysqlr) { /* check for device 0 items */ result = db_query(mysql, LOCAL, "SELECT * FROM (SELECT COUNT(*) AS items FROM poller_item WHERE host_id = 0 AND poller_id = 1) AS rs WHERE rs.items > 0"); + if (result == NULL) die("FATAL: Unable to check for Device 0 poller items"); if (mysql_num_rows(result)) { set.hosts.has_device_0 = TRUE; } db_free_result(result); /* check if poller_item has the output_regex column (added in Cacti 1.3.1) */ - if (db_column_exists(mysql, LOCAL, "poller_item", "output_regex")) { + has_output_regex = db_column_exists(mysql, LOCAL, "poller_item", "output_regex"); + if (has_output_regex < 0) die("FATAL: Unable to inspect the poller_item table"); + if (has_output_regex) { set.hosts.has_output_regex = TRUE; SPINE_LOG_DEBUG(("DEBUG: poller_item.output_regex column detected")); } - /* Since MySQL 5.7 the sql_mode defaults are too strict for cacti */ - db_insert(mysql, LOCAL, "SET SESSION sql_mode = (SELECT REPLACE(@@sql_mode,'NO_ZERO_DATE', ''))"); - db_insert(mysql, LOCAL, "SET SESSION sql_mode = (SELECT REPLACE(@@sql_mode,'ONLY_FULL_GROUP_BY', ''))"); + /* Since MySQL 5.7 the sql_mode defaults are too strict for cacti. The + * same policy as the pool, which a reconnect of this handle reapplies. */ + if (!db_set_session_mode(mysql)) die("FATAL: Unable to configure the database session"); return mode; @@ -1148,6 +1165,7 @@ int main(int argc, char *argv[]) { initialize_main_php(); result = select_poll_hosts(&mysql); + if (result == NULL) die("FATAL: Unable to select the devices to poll"); prepare_worker_storage(result, &num_rows, &threads, &ids, &host_time); diff --git a/spine_types.h b/spine_types.h index 1b898bdd..48ff99e5 100644 --- a/spine_types.h +++ b/spine_types.h @@ -547,6 +547,7 @@ typedef struct poller_thread { int threads_complete; int complete; int output_failed; + int poll_failed; char host_time[40]; double host_time_double; spine_permits_t *thread_init_sem; diff --git a/sql.c b/sql.c index a1037ce4..0eb9032a 100644 --- a/sql.c +++ b/sql.c @@ -46,13 +46,22 @@ * \return TRUE if successful, or FALSE if not. * */ -static void retry_disconnected_query(MYSQL *mysql, int type, int error, const char *function, int *error_count) { - if (errno == EINTR) { +/* Returns FALSE when the statement should not be retried. A failed reconnect + * ends the attempt at once: db_connect() has already spent its own tries, and + * repeating it here only multiplies the wait while a worker holds its device. */ +static bool retry_disconnected_query(MYSQL *mysql, int type, int error, const char *function, int *error_count) { + /* Every attempt counts. A signal that interrupted the call gets a few + * in-place retries, but the client library does not reset errno, so a + * stale EINTR used to skip both the reconnect and the count forever. */ + if (++*error_count > 30) { + SPINE_LOG(("ERROR: Too many Reconnect Attempts in Function %s", function)); + return FALSE; + } + if (errno == EINTR && *error_count <= 3) { spine_sleep_usec(50000); - return; + return TRUE; } - db_reconnect(mysql, type, error, function); - if (++*error_count > 30) die("FATAL: Too many Reconnect Attempts!"); + return db_reconnect(mysql, type, error, function) >= 0; } int db_insert(MYSQL *mysql, int type, const char *query) { @@ -64,8 +73,9 @@ int db_insert(MYSQL *mysql, int type, const char *query) { while (mysql_query(mysql, query) != 0) { int error = mysql_errno(mysql); if (error == 2013 || error == 2006) { - retry_disconnected_query(mysql, type, error, "db_insert", &error_count); - continue; + if (retry_disconnected_query(mysql, type, error, "db_insert", &error_count)) continue; + SPINE_LOG(("ERROR: SQL Failed! Connection lost, SQL Fragment:'%s'", query_frag)); + return FALSE; } if (error == 1213 || error == 1205) { spine_sleep_usec(50000); @@ -81,6 +91,38 @@ int db_insert(MYSQL *mysql, int type, const char *query) { return TRUE; } +/*! \fn int db_set_session_mode(MYSQL *mysql) + * \brief relaxes the session sql_mode to what Cacti's schema needs. + * + * Uses mysql_query() directly so a failure here never recurses into the + * reconnect path. Every new session needs it, including one opened by a + * reconnect, since the server starts each session at its default mode. + * SQL_readonly does not skip it: it changes no data. + * + * \return TRUE when every statement succeeded + */ +int db_set_session_mode(MYSQL *mysql) { + static const char *const modes[] = { + "NO_ZERO_DATE", "NO_ZERO_IN_DATE", "ONLY_FULL_GROUP_BY", "NO_AUTO_VALUE_ON_ZERO", + "TRADITIONAL", "STRICT_ALL_TABLES", "STRICT_TRANS_TABLES" + }; + char query[BUFSIZE]; + size_t i; + + for (i = 0; i < sizeof(modes) / sizeof(modes[0]); i++) { + snprintf(query, sizeof(query), "SET SESSION sql_mode = (SELECT REPLACE(@@sql_mode,'%s', ''))", modes[i]); + if (mysql_query(mysql, query) != 0) { + SPINE_LOG(("ERROR: Unable to set the session sql_mode: %s", mysql_error(mysql))); + return FALSE; + } + } + + return TRUE; +} + +/* Returns TRUE after a reconnect, FALSE when the session was still alive, and + * -1 when the server could not be reached. After -1 the handle is initialized + * but unconnected, so the next attempt closes and reconnects it again. */ int db_reconnect(MYSQL *mysql, int type, int error, const char *function) { unsigned long mysql_thread = 0; char query[100]; @@ -93,12 +135,8 @@ int db_reconnect(MYSQL *mysql, int type, int error, const char *function) { SPINE_LOG(("WARNING: Connection Broken in Function %s with Error %i. Reconnect via mysql_ping() successful.", function, error)); snprintf(query, 100, "KILL %lu;", mysql_thread); mysql_query(mysql, query); - mysql_query(mysql, "SET SESSION sql_mode = (SELECT REPLACE(@@sql_mode,'NO_ZERO_DATE', ''))"); - mysql_query(mysql, "SET SESSION sql_mode = (SELECT REPLACE(@@sql_mode,'NO_ZERO_IN_DATE', ''))"); - mysql_query(mysql, "SET SESSION sql_mode = (SELECT REPLACE(@@sql_mode,'ONLY_FULL_GROUP_BY', ''))"); - mysql_query(mysql, "SET SESSION sql_mode = (SELECT REPLACE(@@sql_mode,'NO_AUTO_VALUE_ON_ZERO', ''))"); - mysql_query(mysql, "SET SESSION sql_mode = (SELECT REPLACE(@@sql_mode,'TRADITIONAL', ''))"); - mysql_query(mysql, "SET SESSION sql_mode = (SELECT REPLACE(@@sql_mode,'STRICT_ALL_TABLES', ''))"); + + if (!db_set_session_mode(mysql)) return -1; sleep(1); @@ -114,15 +152,14 @@ int db_reconnect(MYSQL *mysql, int type, int error, const char *function) { SPINE_LOG(("WARNING: Connection Broken in Function %s with Error %i. Attempting explicit reconnect.", function, error)); mysql_close(mysql); - db_connect(type, mysql); - if (mysql_thread_id(mysql) > 0) { + if (db_connect(type, mysql) && mysql_thread_id(mysql) > 0 && db_set_session_mode(mysql)) { SPINE_LOG(("WARNING: Explicit reconnect successful in Function %s.", function)); return TRUE; } SPINE_LOG(("WARNING: Connection Broken with Error %i. Reconnect failed.", error)); - return FALSE; + return -1; } /*! \fn MYSQL_RES *db_query(MYSQL *mysql, int type, const char *query) @@ -132,7 +169,9 @@ int db_reconnect(MYSQL *mysql, int type, int error, const char *function) { * * This function will execute the SQL statement specified in the query variable. * - * \return MYSQL_RES a MySQL result structure + * \return MYSQL_RES a MySQL result structure, or NULL when the statement + * failed or produced no result set; the caller decides whether a + * failure ends a device, a startup step or the process * */ MYSQL_RES *db_query(MYSQL *mysql, int type, const char *query) { @@ -143,20 +182,21 @@ MYSQL_RES *db_query(MYSQL *mysql, int type, const char *query) { while (mysql_query(mysql, query) != 0) { int error = mysql_errno(mysql); if (error == 2013 || error == 2006) { - retry_disconnected_query(mysql, type, error, "db_query", &error_count); - continue; + if (retry_disconnected_query(mysql, type, error, "db_query", &error_count)) continue; + SPINE_LOG(("ERROR: Database connection lost, SQL Fragment:'%s'", query_frag)); + return NULL; } if (error == 1213 || error == 1205) { spine_sleep_usec(50000); if (++error_count > 30) { - SPINE_LOG(("FATAL: Too many Lock/Deadlock errors occurred!, SQL Fragment:'%s'", query_frag)); - exit(1); + SPINE_LOG(("ERROR: Too many Lock/Deadlock errors occurred!, SQL Fragment:'%s'", query_frag)); + return NULL; } continue; } - SPINE_LOG(("FATAL: Database Error:'%i', Message:'%s'", error, mysql_error(mysql))); + SPINE_LOG(("ERROR: Database Error:'%i', Message:'%s'", error, mysql_error(mysql))); SPINE_LOG(("ERROR: The Query Was:'%s'", query)); - exit(1); + return NULL; } return mysql_store_result(mysql); } @@ -221,7 +261,10 @@ static void db_set_ssl_options(MYSQL *mysql, int type) { } #endif -void db_connect(int type, MYSQL *mysql) { +/* Reports failure instead of exiting: worker threads reconnect through here, + * and a lost database must fail a device rather than the poller. Startup + * callers turn FALSE into a process exit. */ +int db_connect(int type, MYSQL *mysql) { int tries; int attempts; int timeout; @@ -246,8 +289,8 @@ void db_connect(int type, MYSQL *mysql) { if (mysql_init(mysql) == NULL) { db_address_release(&address); - printf("FATAL: Database unable to allocate memory and therefore can not connect\n"); - exit(1); + printf("ERROR: Database unable to allocate memory and therefore can not connect\n"); + return FALSE; } db_set_option(mysql, MYSQL_OPT_READ_TIMEOUT, &rtimeout, "read timeout"); @@ -278,11 +321,9 @@ void db_connect(int type, MYSQL *mysql) { if (!connect_error) { error = mysql_errno(mysql); - if ((error == 2002 || error == 2003 || error == 2006 || error == 2013) && errno == EINTR) { - spine_sleep_usec(5000); - tries++; - success = FALSE; - } else if (error == 2002) { + /* A stale EINTR in errno used to refund the attempt here and made + * the loop unbounded; every failed connect now spends a try. */ + if (error == 2002) { printf("Database: Connection Failed: Attempt:'%d', Error:'%u', Message:'%s'\n", attempts, mysql_errno(mysql), mysql_error(mysql)); sleep(1); success = FALSE; @@ -307,13 +348,15 @@ void db_connect(int type, MYSQL *mysql) { if (!success){ - printf("FATAL: Connection Failed, Error:'%i', Message:'%s'\n", error, mysql_error(mysql)); - exit(1); + printf("ERROR: Connection Failed, Error:'%i', Message:'%s'\n", error, mysql_error(mysql)); + return FALSE; } SPINE_LOG_DEBUG(("DEBUG: Total Connections made %i", connections)); connections++; + + return TRUE; } /*! \fn void db_disconnect(MYSQL *mysql) @@ -342,15 +385,9 @@ void db_create_connection_pool(int type) { for(id = 0; id < set.poller.threads; id++) { SPINE_LOG_DEBUG(("DEBUG: Creating Local Connection %i.", id)); - db_connect(type, &db_pool_local[id].mysql); + if (!db_connect(type, &db_pool_local[id].mysql)) die("FATAL: Unable to create the local connection pool"); - db_insert(&db_pool_local[id].mysql, LOCAL, "SET SESSION sql_mode = (SELECT REPLACE(@@sql_mode,'NO_ZERO_DATE', ''))"); - db_insert(&db_pool_local[id].mysql, LOCAL, "SET SESSION sql_mode = (SELECT REPLACE(@@sql_mode,'NO_ZERO_IN_DATE', ''))"); - db_insert(&db_pool_local[id].mysql, LOCAL, "SET SESSION sql_mode = (SELECT REPLACE(@@sql_mode,'ONLY_FULL_GROUP_BY', ''))"); - db_insert(&db_pool_local[id].mysql, LOCAL, "SET SESSION sql_mode = (SELECT REPLACE(@@sql_mode,'NO_AUTO_VALUE_ON_ZERO', ''))"); - db_insert(&db_pool_local[id].mysql, LOCAL, "SET SESSION sql_mode = (SELECT REPLACE(@@sql_mode,'TRADITIONAL', ''))"); - db_insert(&db_pool_local[id].mysql, LOCAL, "SET SESSION sql_mode = (SELECT REPLACE(@@sql_mode,'STRICT_ALL_TABLES', ''))"); - db_insert(&db_pool_local[id].mysql, LOCAL, "SET SESSION sql_mode = (SELECT REPLACE(@@sql_mode,'STRICT_TRANS_TABLES', ''))"); + if (!db_set_session_mode(&db_pool_local[id].mysql)) die("FATAL: Unable to configure the local connection pool"); db_pool_local[id].free = TRUE; db_pool_local[id].id = id; @@ -361,15 +398,9 @@ void db_create_connection_pool(int type) { for(id = 0; id < set.poller.threads; id++) { SPINE_LOG_DEBUG(("DEBUG: Creating Remote Connection %i.", id)); - db_connect(type, &db_pool_remote[id].mysql); + if (!db_connect(type, &db_pool_remote[id].mysql)) die("FATAL: Unable to create the remote connection pool"); - db_insert(&db_pool_remote[id].mysql, LOCAL, "SET SESSION sql_mode = (SELECT REPLACE(@@sql_mode,'NO_ZERO_DATE', ''))"); - db_insert(&db_pool_remote[id].mysql, LOCAL, "SET SESSION sql_mode = (SELECT REPLACE(@@sql_mode,'NO_ZERO_IN_DATE', ''))"); - db_insert(&db_pool_remote[id].mysql, LOCAL, "SET SESSION sql_mode = (SELECT REPLACE(@@sql_mode,'ONLY_FULL_GROUP_BY', ''))"); - db_insert(&db_pool_remote[id].mysql, LOCAL, "SET SESSION sql_mode = (SELECT REPLACE(@@sql_mode,'NO_AUTO_VALUE_ON_ZERO', ''))"); - db_insert(&db_pool_remote[id].mysql, LOCAL, "SET SESSION sql_mode = (SELECT REPLACE(@@sql_mode,'TRADITIONAL', ''))"); - db_insert(&db_pool_remote[id].mysql, LOCAL, "SET SESSION sql_mode = (SELECT REPLACE(@@sql_mode,'STRICT_ALL_TABLES', ''))"); - db_insert(&db_pool_remote[id].mysql, LOCAL, "SET SESSION sql_mode = (SELECT REPLACE(@@sql_mode,'STRICT_TRANS_TABLES', ''))"); + if (!db_set_session_mode(&db_pool_remote[id].mysql)) die("FATAL: Unable to configure the remote connection pool"); db_pool_remote[id].free = TRUE; db_pool_remote[id].id = id; @@ -530,6 +561,7 @@ void db_free_result(MYSQL_RES *result) { mysql_free_result(result); } +/* TRUE or FALSE, or -1 when the probe itself failed. */ int db_column_exists(MYSQL *mysql, int type, const char *table, const char *column) { char query_frag[BUFSIZE]; MYSQL_RES *result; @@ -543,6 +575,7 @@ int db_column_exists(MYSQL *mysql, int type, const char *table, const char *colu SPINE_LOG_DEVDBG(("DEVDBG: db_column_exists('%s','%s'): %s", table, column, query_frag)); result = db_query(mysql, type, query_frag); + if (result == NULL) return -1; if (mysql_num_rows(result)) { exists = TRUE; } else { diff --git a/sql.h b/sql.h index 787a219c..06d8fda8 100644 --- a/sql.h +++ b/sql.h @@ -43,7 +43,7 @@ extern void db_address_release(db_address_t *address); extern int db_insert(MYSQL *mysql, int type, const char *query); extern MYSQL_RES *db_query(MYSQL *mysql, int type, const char *query); -extern void db_connect(int type, MYSQL *mysql); +extern int db_connect(int type, MYSQL *mysql); extern void db_disconnect(MYSQL *mysql); extern void db_escape(MYSQL *mysql, char *output, int max_size, const char *input); extern void db_free_result(MYSQL_RES *result); @@ -51,6 +51,7 @@ extern void db_create_connection_pool(int type); extern void db_close_connection_pool(int type); extern pool_t *db_get_connection(int type); extern void db_release_connection(int type, int id); +extern int db_set_session_mode(MYSQL *mysql); extern int db_reconnect(MYSQL *mysql, int type, int error, const char *location); extern int db_column_exists(MYSQL *mysql, int type, const char *table, const char *column); diff --git a/tests/regression/test_child_process_safety.sh b/tests/regression/test_child_process_safety.sh index 8a5fba6b..7691d018 100755 --- a/tests/regression/test_child_process_safety.sh +++ b/tests/regression/test_child_process_safety.sh @@ -37,7 +37,8 @@ grep -q 'spine_open_pipe_cloexec(php2cacti_pdes)' php.c || grep -q 'waitpid(pid, pstat, WNOHANG)' nft_popen.c || fail "nft_popen.c must reap child processes with WNOHANG" -grep -q 'kill(cur->pid, SIGKILL)' nft_popen.c || +# The negative pid kills the script's process group, descendants included. +grep -q 'kill(-cur->pid, SIGKILL)' nft_popen.c || fail "nft_popen.c must escalate a timed-out reap to SIGKILL" if grep -q 'waitpid(cur->pid, &pstat, 0)' nft_popen.c; then diff --git a/tests/test_spine_contracts.c b/tests/test_spine_contracts.c index 84195d08..cc131768 100644 --- a/tests/test_spine_contracts.c +++ b/tests/test_spine_contracts.c @@ -14,6 +14,7 @@ #include "common.h" #include "spine.h" #include +#include static void test_keyword_roundtrips(void) { typedef struct { const char *word; int value; } keyword_case_t; @@ -200,14 +201,13 @@ static void test_fatal_signal_contracts(void) { close(diagnostic[0]); assert(dup2(diagnostic[1], STDERR_FILENO) == STDERR_FILENO); close(diagnostic[1]); + /* The default action of several cases dumps core. */ + struct rlimit no_core = {0, 0}; + assert(setrlimit(RLIMIT_CORE, &no_core) == 0); assert(signal(cases[i].signal, SIG_DFL) != SIG_ERR); install_spine_signal_handler(); assert(raise(cases[i].signal) == 0); - assert(set.exit.exit_code == cases[i].signal); - struct sigaction restored; - assert(sigaction(cases[i].signal, NULL, &restored) == 0); - assert(restored.sa_handler == SIG_DFL); - uninstall_spine_signal_handler(); + /* A fatal signal must end the process once it is logged. */ _exit(0); } close(diagnostic[1]); @@ -223,8 +223,12 @@ static void test_fatal_signal_contracts(void) { close(diagnostic[0]); int status; assert(waitpid(child, &status, 0) == child); - assert(WIFEXITED(status)); - assert(WEXITSTATUS(status) == (cases[i].signal == SIGSEGV ? 1 : 0)); + fprintf(stderr, "fatal signal %d: raw_status=%d\n", cases[i].signal, status); + if (cases[i].signal == SIGSEGV) { + assert(WIFEXITED(status) && WEXITSTATUS(status) == 1); + } else { + assert(WIFSIGNALED(status) && WTERMSIG(status) == cases[i].signal); + } assert(strstr(message, cases[i].message) != NULL); } /* A broken pipe is an ordinary write failure: it must neither terminate @@ -258,6 +262,96 @@ void test_additional_contracts(void) { puts("production additional contracts passed"); } +/* The client library never clears errno, so an EINTR left over from an + * unrelated call must not stand in for an interrupted query. Run in a child + * so an unbounded retry shows up as the alarm instead of a hung suite. */ +static void assert_stale_interrupt_is_retried(void) { + fflush(NULL); + pid_t child = fork(); + assert(child >= 0); + if (child == 0) { + alarm(10); + MYSQL administrator; + MYSQL victim; + db_connect(LOCAL, &administrator); + db_connect(LOCAL, &victim); + char query[100]; + snprintf(query, sizeof(query), "KILL CONNECTION %lu", mysql_thread_id(&victim)); + if (mysql_query(&administrator, query) != 0) _exit(2); + errno = EINTR; + _exit(db_insert(&victim, LOCAL, "SET @spine_regression_interrupt=1") == TRUE ? 0 : 3); + } + int status; + assert(waitpid(child, &status, 0) == child); + fprintf(stderr, "stale EINTR retry: raw_status=%d\n", status); + assert(WIFEXITED(status) && WEXITSTATUS(status) == 0); +} + +/* Query wrappers report failure to the caller; only startup code may turn a + * database error into a process exit. Port 1 refuses the reconnect quickly + * and deterministically, which stands in for a server that is down. */ +static void assert_database_failures_return(void) { + fflush(NULL); + pid_t child = fork(); + assert(child >= 0); + if (child == 0) { + alarm(30); + MYSQL administrator; + MYSQL victim; + if (!db_connect(LOCAL, &administrator) || !db_connect(LOCAL, &victim)) _exit(2); + if (db_query(&administrator, LOCAL, "SELECT spine_regression_missing FROM spine_regression_missing") != NULL) _exit(3); + if (db_insert(&administrator, LOCAL, "UPDATE spine_regression_missing SET value=1") != FALSE) _exit(4); + char query[100]; + snprintf(query, sizeof(query), "KILL CONNECTION %lu", mysql_thread_id(&victim)); + if (mysql_query(&administrator, query) != 0) _exit(5); + unsigned int port = set.database.port; + set.database.port = 1; + double begin = spine_monotonic_time(); + if (db_query(&victim, LOCAL, "SELECT 1") != NULL) _exit(6); + if (db_insert(&victim, LOCAL, "SET @spine_regression_down=1") != FALSE) _exit(7); + if (db_reconnect(&victim, LOCAL, 2006, "regression_down_server") != -1) _exit(8); + if (spine_monotonic_time() - begin > 20) _exit(9); + /* The same handle recovers once the server is reachable again. */ + set.database.port = port; + MYSQL_RES *result = db_query(&victim, LOCAL, "SELECT 789"); + MYSQL_ROW row = result != NULL ? mysql_fetch_row(result) : NULL; + if (row == NULL || row[0] == NULL || strcmp(row[0], "789") != 0) _exit(10); + db_free_result(result); + _exit(0); + } + int status; + assert(waitpid(child, &status, 0) == child); + fprintf(stderr, "database failure propagation: raw_status=%d\n", status); + assert(WIFEXITED(status) && WEXITSTATUS(status) == 0); +} + +static bool session_mode_contains(MYSQL *mysql, const char *mode) { + MYSQL_RES *result = db_query(mysql, LOCAL, "SELECT @@SESSION.sql_mode"); + assert(result != NULL); + MYSQL_ROW row = mysql_fetch_row(result); + assert(row != NULL && row[0] != NULL); + bool found = strstr(row[0], mode) != NULL; + db_free_result(result); + return found; +} + +/* Pooled sessions run with Cacti's relaxed sql_mode. A reconnect opens a new + * session with the server default, so it must apply the same policy again. */ +static void assert_reconnect_restores_session_mode(MYSQL *mysql) { + MYSQL victim; + assert(db_connect(LOCAL, &victim)); + /* The fixture server's default mode is strict; otherwise this proves nothing. */ + assert(session_mode_contains(&victim, "STRICT_TRANS_TABLES")); + char query[100]; + snprintf(query, sizeof(query), "KILL CONNECTION %lu", mysql_thread_id(&victim)); + assert(mysql_query(mysql, query) == 0); + bool strict = session_mode_contains(&victim, "STRICT_TRANS_TABLES"); + bool zero_date = session_mode_contains(&victim, "NO_ZERO_DATE"); + fprintf(stderr, "reconnected session mode: strict=%d no_zero_date=%d\n", strict, zero_date); + assert(!strict && !zero_date); + db_disconnect(&victim); +} + void test_additional_database_contracts(MYSQL *mysql) { assert(db_column_exists(mysql, LOCAL, "host", "id") == TRUE); assert(db_column_exists(mysql, LOCAL, "host", "regression_missing_column") == FALSE); @@ -302,4 +396,7 @@ void test_additional_database_contracts(MYSQL *mysql) { } } db_disconnect(&victim); + assert_stale_interrupt_is_retried(); + assert_database_failures_return(); + assert_reconnect_restores_session_mode(mysql); } diff --git a/tests/test_spine_faults.c b/tests/test_spine_faults.c index 21db29d0..74084811 100644 --- a/tests/test_spine_faults.c +++ b/tests/test_spine_faults.c @@ -22,6 +22,15 @@ extern size_t __real_strftime(char *, size_t, const char *, const struct tm *); extern int __real_mysql_query(MYSQL *, const char *); extern int __real_mysql_ping(MYSQL *); extern unsigned int __real_mysql_errno(MYSQL *); +extern MYSQL *__real_mysql_real_connect(MYSQL *, const char *, const char *, const char *, + const char *, unsigned int, const char *, unsigned long); +extern unsigned long __real_mysql_thread_id(MYSQL *); +extern MYSQL_RES *__real_mysql_store_result(MYSQL *); +extern my_ulonglong __real_mysql_num_rows(MYSQL_RES *); +extern MYSQL_ROW __real_mysql_fetch_row(MYSQL_RES *); +extern void __real_mysql_free_result(MYSQL_RES *); +extern unsigned int __real_mysql_num_fields(MYSQL_RES *); +extern int __real_posix_spawnattr_setpgroup(posix_spawnattr_t *, pid_t); extern int __real_pipe(int [2]); extern int __real_socketpair(int, int, int, int [2]); extern int __real_posix_spawn(pid_t *, const char *, const posix_spawn_file_actions_t *, @@ -43,6 +52,34 @@ static int observed_query_error; static int query_fault_calls; static int query_ping_calls; static MYSQL *interrupted_connection; +/* A scripted server for database failure paths that make check reaches + * without a database. While fake_database is set every client call below + * answers from this script and nothing touches the network. */ +static bool fake_database; +static int fake_errors[64]; +static int fake_error_count; +static int fake_error_next; +static int fake_errno_value; +static int fake_connect_failures; +static int fake_fail_connect_number; +static int fake_connects; +static bool fake_session_mode_fails; +static bool fake_ping_reconnects; +static int setpgroup_failures; +static unsigned long fake_thread; +static my_ulonglong fake_rows; +/* Statements starting with fake_rows_prefix report fake_rows_matched rows. */ +static const char *fake_rows_prefix; +static my_ulonglong fake_rows_matched; +static my_ulonglong fake_rows_current; +/* A statement starting with fake_fail_prefix fails; fake_item_rows rows of + * fake_item_row are handed out to the next fetches. */ +static const char *fake_fail_prefix; +static int fake_item_rows; +static char *fake_item_row[21]; +static int fake_queries; +static int fake_result_storage; +#define FAKE_RESULT ((MYSQL_RES *)(void *)&fake_result_storage) static int interrupted_queries; static int interrupted_query_calls; static int pipe_failures; @@ -67,6 +104,8 @@ static int launch_fault_calls; static int launch_checkpoints; static int launch_device_counter; static spine_permits_t *launch_startup; +static int completion_writes; +static int completion_writes_locked; int __wrap_pthread_create(pthread_t *thread, const pthread_attr_t *attributes, void *(*start)(void *), void *arg) { @@ -106,7 +145,9 @@ static void inspect_worker_launch_completion(void) { static void verify_worker_launch_exit(void) { fflush(NULL); - fprintf(stderr, "worker launch checkpoint: checkpoints=%i calls=%i faults=%i pending=%i exit=%i\n", launch_checkpoints, launch_calls, launch_fault_calls, launch_failures, set.exit.exit_code); + fprintf(stderr, "worker launch checkpoint: checkpoints=%i calls=%i faults=%i pending=%i exit=%i completion_writes=%i locked=%i\n", launch_checkpoints, launch_calls, launch_fault_calls, launch_failures, set.exit.exit_code, completion_writes, completion_writes_locked); + assert(completion_writes_locked == 0); + assert(launch_error == EPERM || completion_writes > 0); assert(launch_checkpoints == 1 && launch_failures == 0); assert(launch_fault_calls == launch_expected_faults); assert(launch_calls == (launch_error == EAGAIN ? 2 : 1)); @@ -144,7 +185,22 @@ size_t __wrap_strftime(char *output, size_t capacity, const char *format, const } int __wrap_mysql_query(MYSQL *mysql, const char *query) { + if (fake_database) { + fake_queries++; + fake_rows_current = fake_rows_prefix != NULL && strncmp(query, fake_rows_prefix, strlen(fake_rows_prefix)) == 0 ? + fake_rows_matched : fake_rows; + if (strncmp(query, "SET SESSION sql_mode", strlen("SET SESSION sql_mode")) == 0) { + fake_errno_value = fake_session_mode_fails ? 1146 : 0; + } else if (fake_fail_prefix != NULL && strncmp(query, fake_fail_prefix, strlen(fake_fail_prefix)) == 0) { + fake_errno_value = 1146; + } else { + fake_errno_value = fake_error_next < fake_error_count ? fake_errors[fake_error_next++] : 0; + } + return fake_errno_value != 0; + } static const char completion[] = "UPDATE poller_time SET end_time=NOW() WHERE poller_id="; + static const char polling_time[] = "UPDATE host SET polling_time"; + static const char host_errors[] = "INSERT INTO host_errors"; /* The interrupted handle is never connected; it must not reach the client library. */ if (mysql == interrupted_connection) { interrupted_query_calls++; @@ -158,6 +214,14 @@ int __wrap_mysql_query(MYSQL *mysql, const char *query) { if (launch_case_active && strncmp(query, completion, sizeof(completion) - 1) == 0) { inspect_worker_launch_completion(); } + /* Device bookkeeping writes can wait out a read timeout and a reconnect; + * holding LOCK_THDET across them would stall every other worker. */ + if (launch_case_active && (strncmp(query, polling_time, sizeof(polling_time) - 1) == 0 || + strncmp(query, host_errors, sizeof(host_errors) - 1) == 0)) { + completion_writes++; + if (thread_mutex_trylock(LOCK_THDET) == 0) thread_mutex_unlock(LOCK_THDET); + else completion_writes_locked++; + } if (query_fault_armed && mysql == query_fault_connection && strcmp(query, query_fault_statement) == 0) { query_fault_armed = 0; bool reconnect = FALSE; @@ -176,14 +240,77 @@ int __wrap_mysql_query(MYSQL *mysql, const char *query) { int __wrap_mysql_ping(MYSQL *mysql) { if (mysql == query_fault_connection) query_ping_calls++; + if (fake_database) { + /* A client-side auto-reconnect shows up as a new thread id. */ + if (!fake_ping_reconnects) return 1; + fake_thread++; + return 0; + } return __real_mysql_ping(mysql); } unsigned int __wrap_mysql_errno(MYSQL *mysql) { if (mysql == interrupted_connection) return 2013; + if (fake_database) return (unsigned int)fake_errno_value; return __real_mysql_errno(mysql); } +MYSQL *__wrap_mysql_real_connect(MYSQL *mysql, const char *host, const char *user, const char *password, + const char *database, unsigned int port, const char *socket, unsigned long flags) { + if (!fake_database) return __real_mysql_real_connect(mysql, host, user, password, database, port, socket, flags); + fake_connects++; + if (fake_connect_failures > 0 || fake_connects == fake_fail_connect_number) { + if (fake_connect_failures > 0) fake_connect_failures--; + fake_thread = 0; + /* 2005 is the unknown-host error db_connect() does not retry. */ + fake_errno_value = 2005; + return NULL; + } + fake_thread++; + fake_errno_value = 0; + return mysql; +} + +unsigned long __wrap_mysql_thread_id(MYSQL *mysql) { + if (fake_database) return fake_thread; + return __real_mysql_thread_id(mysql); +} + +MYSQL_RES *__wrap_mysql_store_result(MYSQL *mysql) { + if (fake_database) return fake_errno_value == 0 ? FAKE_RESULT : NULL; + return __real_mysql_store_result(mysql); +} + +my_ulonglong __wrap_mysql_num_rows(MYSQL_RES *result) { + if (result == FAKE_RESULT) return fake_rows_current; + return __real_mysql_num_rows(result); +} + +MYSQL_ROW __wrap_mysql_fetch_row(MYSQL_RES *result) { + if (result == FAKE_RESULT) { + if (fake_item_rows <= 0) return NULL; + fake_item_rows--; + return fake_item_row; + } + return __real_mysql_fetch_row(result); +} + +/* No scripted result matches a transfer plan's column count. */ +unsigned int __wrap_mysql_num_fields(MYSQL_RES *result) { + if (result == FAKE_RESULT) return 0; + return __real_mysql_num_fields(result); +} + +void __wrap_mysql_free_result(MYSQL_RES *result) { + if (result == FAKE_RESULT) return; + __real_mysql_free_result(result); +} + +int __wrap_posix_spawnattr_setpgroup(posix_spawnattr_t *attributes, pid_t group) { + if (setpgroup_failures > 0) { setpgroup_failures--; return EINVAL; } + return __real_posix_spawnattr_setpgroup(attributes, group); +} + int __wrap_pipe(int descriptors[2]) { if (pipe_failures > 0) { pipe_failures--; errno = EMFILE; return -1; } return __real_pipe(descriptors); @@ -557,6 +684,15 @@ static void test_child_setup_failures(unsigned int expected_descriptors) { } } +static void test_spawn_group_failure(void) { + unsigned int descriptors = open_descriptor_count(); + setpgroup_failures = 1; + assert(nft_popen("printf unused", "r") == -1 && errno == EINVAL); + assert(setpgroup_failures == 0 && open_descriptor_count() == descriptors); + assert_cancel_state(PTHREAD_CANCEL_ENABLE); + puts("production script process-group setup failure regressions passed"); +} + static void test_process_creation_failures(void) { unsigned int descriptors = open_descriptor_count(); int unrelated[2]; @@ -681,6 +817,331 @@ static void test_snmpv3_privacy_copy_failure(void) { puts("production SNMPv3 privacy copy failure regressions passed"); } +static void fake_script(const int *errors, int count) { + assert(count >= 0 && count <= (int)(sizeof(fake_errors) / sizeof(fake_errors[0]))); + for (int i = 0; i < count; i++) fake_errors[i] = errors[i]; + fake_error_count = count; + fake_error_next = 0; + fake_connect_failures = 0; + fake_fail_connect_number = 0; + fake_connects = 0; + fake_queries = 0; + fake_session_mode_fails = FALSE; + fake_ping_reconnects = FALSE; + fake_rows = 0; + fake_rows_prefix = NULL; + fake_rows_matched = 0; + fake_fail_prefix = NULL; + fake_item_rows = 0; + errno = 0; +} + +static void fake_repeat(int error, int count) { + int errors[64]; + assert(count <= (int)(sizeof(errors) / sizeof(errors[0]))); + for (int i = 0; i < count; i++) errors[i] = error; + fake_script(errors, count); +} + +/* Every wrapper outcome a worker can see: a statement error, a lost + * connection whose reconnect fails, succeeds, or cannot set the session + * mode, and both retry budgets running out. None of them may exit. */ +static void test_fake_database_wrappers(void) { + MYSQL handle; + fake_database = TRUE; + fake_thread = 0; + set.poller.SQL_readonly = FALSE; + fake_script(NULL, 0); + assert(db_connect(LOCAL, &handle) && fake_connects == 1); + + static const int statement_error[] = {1146}; + fake_script(statement_error, 1); + assert(db_query(&handle, LOCAL, "SELECT missing FROM missing") == NULL); + fake_script(statement_error, 1); + assert(db_column_exists(&handle, LOCAL, "missing", "missing") == -1); + + static const int lost[] = {2006}; + fake_script(lost, 1); + fake_connect_failures = 1; + assert(db_insert(&handle, LOCAL, "UPDATE host SET status=1") == FALSE); + assert(fake_connects == 1 && fake_connect_failures == 0); + fake_script(lost, 1); + fake_connect_failures = 1; + assert(db_query(&handle, LOCAL, "SELECT 1") == NULL); + assert(db_reconnect(&handle, LOCAL, 2006, "fake_down_server") == TRUE); + + /* The reconnect reapplies the session mode before the retry. */ + static const int recovered[] = {2013, 0}; + fake_script(recovered, 2); + assert(db_insert(&handle, LOCAL, "UPDATE host SET status=1") == TRUE); + assert(fake_connects == 1 && fake_queries == 9); + fake_script(recovered, 2); + fake_session_mode_fails = TRUE; + assert(db_insert(&handle, LOCAL, "UPDATE host SET status=1") == FALSE); + assert(fake_queries == 2); + fake_session_mode_fails = FALSE; + assert(db_set_session_mode(&handle) == TRUE); + fake_script(NULL, 0); + fake_ping_reconnects = TRUE; + fake_session_mode_fails = TRUE; + assert(db_reconnect(&handle, LOCAL, 2006, "fake_ping_reconnect") == -1); + assert(fake_connects == 0); + + fake_repeat(2013, 40); + assert(db_insert(&handle, LOCAL, "UPDATE host SET status=1") == FALSE); + assert(fake_error_next == 31 && fake_connects == 30); + fake_repeat(1213, 40); + assert(db_query(&handle, LOCAL, "SELECT 1") == NULL); + assert(fake_error_next == 31); + + fake_script(NULL, 0); + fake_rows = 1; + assert(db_column_exists(&handle, LOCAL, "host", "id") == TRUE); + db_disconnect(&handle); + fake_database = FALSE; + puts("production scripted database wrapper regressions passed"); +} + +/* Pool creation and the collector push run in the main thread; the pool must + * get the session mode and the push must skip cleanly when either side is down. */ +static void test_fake_database_main_paths(void) { + config_t previous = set; + pool_t *previous_local = db_pool_local; + pool_t *previous_remote = db_pool_remote; + fake_database = TRUE; + set.logging.log_destination = 0; + set.poller.threads = 2; + db_pool_local = calloc(2, sizeof(*db_pool_local)); + db_pool_remote = calloc(2, sizeof(*db_pool_remote)); + assert(db_pool_local != NULL && db_pool_remote != NULL); + fake_script(NULL, 0); + db_create_connection_pool(LOCAL); + db_create_connection_pool(REMOTE); + assert(fake_connects == 4 && fake_queries == 28); + assert(db_pool_local[1].free && db_pool_remote[1].free && db_pool_remote[1].id == 1); + db_close_connection_pool(LOCAL); + db_close_connection_pool(REMOTE); + /* The push connects locally first, then to the main server. */ + for (int failing = 1; failing <= 2; failing++) { + fake_script(NULL, 0); + fake_fail_connect_number = failing; + set.exit.exit_code = EXIT_SUCCESS; + poller_push_data_to_main(); + assert(fake_connects == failing && fake_queries == 0); + assert(set.exit.exit_code == EXIT_FAILURE); + } + fake_database = FALSE; + db_pool_local = previous_local; + db_pool_remote = previous_remote; + set = previous; + puts("production scripted database main-thread regressions passed"); +} + +static void *fake_poll_worker(void *argument) { + assert(mysql_thread_init() == 0); + int errors = 0; + poll_host(argument, &errors); + return NULL; +} + +static void run_fake_poll(poller_thread_t *device, int host_id) { + memset(device, 0, sizeof(*device)); + device->host_id = host_id; + device->host_thread = 1; + device->host_threads = 1; + device->host_time_double = get_time_as_double(); + STRNCOPY(device->host_time, "1791244800"); + set.exit.exit_code = EXIT_SUCCESS; + pthread_t worker; + assert(pthread_create(&worker, NULL, fake_poll_worker, device) == 0); + assert(pthread_join(worker, NULL) == 0); + assert(device->threads_complete == 1); +} + +static void assert_fake_poll_failed(const poller_thread_t *device) { + assert(device->poll_failed && !device->complete && set.exit.exit_code == EXIT_FAILURE); + assert(db_pool_local[0].free); +} + +/* A worker that cannot use the database fails its device and returns. */ +static void test_fake_database_poll_host(void) { + config_t previous = set; + pool_t *previous_local = db_pool_local; + pool_t *previous_remote = db_pool_remote; + poller_thread_t **previous_details = details; + poller_thread_t device; + poller_thread_t *device_list[1] = {&device}; + details = device_list; + fake_database = TRUE; + set.logging.log_destination = 0; + set.poller.threads = 1; + set.poller.poller_id = 1; + set.poller.active_profiles = 2; + set.poller.poller_interval = 5; + set.availability.ping_only = FALSE; + db_pool_local = calloc(1, sizeof(*db_pool_local)); + assert(db_pool_local != NULL); + fake_script(NULL, 0); + assert(db_connect(LOCAL, &db_pool_local[0].mysql)); + db_pool_local[0].free = FALSE; + run_fake_poll(&device, 0); + assert(device.poll_failed && !device.complete && set.exit.exit_code == EXIT_FAILURE); + db_pool_local[0].free = TRUE; + + set.poller.poller_id = 2; + set.poller.mode = REMOTE_ONLINE; + pool_t busy_remote = {0}; + db_pool_remote = &busy_remote; + run_fake_poll(&device, 0); + assert_fake_poll_failed(&device); + set.poller.poller_id = 1; + db_pool_remote = previous_remote; + + static const int statement_error[] = {1146}; + fake_script(statement_error, 1); + run_fake_poll(&device, 902); + assert_fake_poll_failed(&device); + assert(fake_queries == 1); + fake_script(statement_error, 1); + run_fake_poll(&device, 0); + assert_fake_poll_failed(&device); + assert(fake_queries == 1); + + /* A device deleted since selection returns quietly, uncounted. */ + fake_script(NULL, 0); + memset(&device, 0, sizeof(device)); + device.host_id = 902; + device.host_thread = 1; + device.host_threads = 1; + STRNCOPY(device.host_time, "1791244800"); + pthread_t worker; + assert(pthread_create(&worker, NULL, fake_poll_worker, &device) == 0); + assert(pthread_join(worker, NULL) == 0); + assert(device.threads_complete == 0 && !device.poll_failed && db_pool_local[0].free); + /* A row count of one with no row ignores the device but completes it. */ + fake_script(NULL, 0); + fake_rows = 1; + run_fake_poll(&device, 902); + assert(!device.poll_failed && db_pool_local[0].free); + + /* An empty, successful poll advances the schedule and records the time. */ + fake_script(NULL, 0); + run_fake_poll(&device, 0); + assert(!device.poll_failed && device.complete && set.exit.exit_code == EXIT_SUCCESS); + assert(fake_queries == 3 && db_pool_local[0].free); + + /* A completion write that fails must leave the device incomplete and + * fail the run. One invalid script result makes a host_errors write. */ + static const char *const completion_writes[] = { + "UPDATE poller_item", "UPDATE host SET polling_time", "INSERT INTO host_errors" + }; + static char action[] = "1"; + static char command[] = "/usr/bin/printf invalid"; + static char local_data_id[] = "1"; + fake_item_row[0] = action; + fake_item_row[8] = command; + fake_item_row[11] = local_data_id; + assert(spine_permits_init(&available_scripts, 1) == 0); + set.php.script_timeout = 5; + /* Reach the per-item result lines, which must name only the script. */ + set.logging.spine_log_level = 2; + set.logging.log_level = POLLER_VERBOSITY_MEDIUM; + for (size_t failing = 0; failing < sizeof(completion_writes) / sizeof(completion_writes[0]); failing++) { + fake_script(NULL, 0); + fake_rows = 1; + fake_item_rows = 1; + fake_fail_prefix = completion_writes[failing]; + run_fake_poll(&device, 0); + fprintf(stderr, "completion write '%s' failing: complete=%d exit=%d queries=%d\n", + completion_writes[failing], device.complete, set.exit.exit_code, fake_queries); + assert(!device.complete && set.exit.exit_code == EXIT_FAILURE && db_pool_local[0].free); + } + assert(spine_permits_destroy(&available_scripts) == 0); + + db_disconnect(&db_pool_local[0].mysql); + free(db_pool_local); + fake_database = FALSE; + db_pool_local = previous_local; + details = previous_details; + set = previous; + puts("production scripted database worker regressions passed"); +} + +/* Startup reads still end the process on a database error. exit(), not + * _exit(), so the child's coverage is written like the parent's. */ +static void test_fake_database_startup_reads(void) { + for (int scenario = 0; scenario < 4; scenario++) { + fflush(NULL); + pid_t child = fork(); + assert(child >= 0); + if (child == 0) { + alarm(20); + fake_database = TRUE; + set.logging.log_destination = 0; + static const int statement_error[] = {1146}; + if (scenario == 0) { + fake_script(statement_error, 1); + } else { + fake_script(NULL, 0); + set.poller.poller_id = scenario == 2 ? 2 : 1; + set.poller.mode = REMOTE_ONLINE; + set.hosts.host_id_list[0] = '\0'; + if (scenario == 3) STRNCOPY(set.hosts.host_id_list, "902"); + } + read_config_options(); + exit(set.php.php_required ? 3 : 0); + } + int status; + assert(waitpid(child, &status, 0) == child); + fprintf(stderr, "fake startup read scenario=%d status=%d\n", scenario, status); + assert(WIFEXITED(status) && WEXITSTATUS(status) == (scenario == 0 ? EXIT_FAILURE : 0)); + } + puts("production scripted database startup regressions passed"); +} + +/* The whole main path against the scripted server: startup, both pools, a + * device list that ends early, completion and the collector push. */ +static int execute_fake_main_case(char *config) { + fake_database = TRUE; + fake_script(NULL, 0); + fake_rows_prefix = "SELECT SQL_NO_CACHE id, device_threads"; + fake_rows_matched = 1; + alarm(15); + char interval[] = "poller_interval:5"; + char *arguments[] = {"spine", "-C", "/nonexistent/spine-fault.conf", "--conf", config, + "-p", "2", "-t", "1", "-O", interval, "-S", "-V", "1", NULL}; + return spine_program_main((int)(sizeof(arguments) / sizeof(arguments[0]) - 1), arguments); +} + +static void test_fake_database_main(void) { + char directory[] = "/tmp/spine-fake-main-XXXXXX"; + assert(mkdtemp(directory) != NULL); + char config[SMALL_BUFSIZE]; + char log_path[SMALL_BUFSIZE]; + spine_snprintf(config, sizeof(config), "%s/spine.conf", directory); + spine_snprintf(log_path, sizeof(log_path), "%s/spine.log", directory); + FILE *file = fopen(config, "w"); + assert(file != NULL); + assert(fprintf(file, "DB_Host 127.0.0.1\nDB_Database spine_fake\nCacti_Log %s\n", log_path) > 0); + assert(fclose(file) == 0); + fflush(NULL); + pid_t process = fork(); + assert(process >= 0); + if (process == 0) { + execl("./test_spine_faults", "test_spine_faults", "--fake-main-case", config, NULL); + _exit(127); + } + int status; + assert(waitpid(process, &status, 0) == process); + fprintf(stderr, "fake main case status=%d\n", status); + /* One device was promised and none could be read: polling is incomplete. */ + assert(WIFEXITED(status) && WEXITSTATUS(status) == EXIT_FAILURE); + assert(unlink(config) == 0); + if (unlink(log_path) != 0) assert(errno == ENOENT); + assert(rmdir(directory) == 0); + puts("production scripted database main regressions passed"); +} + static void test_real_database_retry(void) { const char *hostname = getenv("SPINE_TEST_DB_HOST"); assert(hostname != NULL && hostname[0] != '\0'); @@ -942,14 +1403,23 @@ int main(int argc, char **argv) { if (argc == 4 && strcmp(argv[1], "--worker-launch-case") == 0) { return execute_worker_launch_case(argv[2], argv[3]); } + if (argc == 3 && strcmp(argv[1], "--fake-main-case") == 0) { + return execute_fake_main_case(argv[2]); + } config_defaults(); init_mutexes(); alarm(20); test_logger_format_failure(); test_process_creation_failures(); + test_spawn_group_failure(); test_interrupted_insert_retry(); test_snmpv3_privacy_copy_failure(); test_privilege_drop_faults(); + test_fake_database_wrappers(); + test_fake_database_main_paths(); + test_fake_database_poll_host(); + test_fake_database_startup_reads(); + test_fake_database_main(); if (argc == 2 && strcmp(argv[1], "--database") == 0) { test_real_database_retry(); test_ping_only_session_lifetime(); diff --git a/tests/test_spine_regressions.c b/tests/test_spine_regressions.c index a02f8ded..5ba6aef1 100644 --- a/tests/test_spine_regressions.c +++ b/tests/test_spine_regressions.c @@ -965,6 +965,107 @@ static void test_php_partial_response_timeout(void) { close(pipes[1]); } +/* Script server arguments can carry SNMP communities and v3 passphrases, so + * no failure line may repeat the command arguments, at any verbosity. + * Drives the timeout, partial-line and lost-server paths of the real code. */ +static void run_php_failure_logs(int level) { + static const char secret[] = "regression-community-7d1f"; + config_t previous_config = set; + php_t *previous_processes = php_processes; + char path[] = "spine-php-redaction-XXXXXX"; + int log_fd = mkstemp(path); + assert(log_fd >= 0 && close(log_fd) == 0); + set.logging.log_destination = LOGDEST_FILE; + set.logging.log_level = level; + set.logging.logfile_processed = TRUE; + set.console.stdout_notty = TRUE; + set.console.stderr_notty = TRUE; + strncopy(set.logging.path_logfile, path, sizeof(set.logging.path_logfile)); + set.php.php_servers = 1; + set.php.script_timeout = 1; + STRNCOPY(set.php.path_php, "/nonexistent-spine-regression-executable"); + char command[BUFSIZE]; + spine_snprintf(command, sizeof(command), "ss_regression.php ss_regression 127.0.0.1 %s\r\n", secret); + php_t process; + php_processes = &process; + for (int partial = 0; partial <= 1; partial++) { + int pipes[2]; + assert(pipe(pipes) == 0); + if (partial) assert(write(pipes[1], "7", 1) == 1); + php_processes_initialize(&process, 1); + process.php_read_fd = pipes[0]; + char *result = php_readpipe(0, command); + assert(strcmp(result, "U") == 0); + free(result); + if (process.php_read_fd >= 0) close(process.php_read_fd); + assert(close(pipes[1]) == 0); + } + int requests[2]; + assert(pipe(requests) == 0 && close(requests[0]) == 0); + int responses[2]; + assert(pipe(responses) == 0); + fflush(NULL); + pid_t server = fork(); + assert(server >= 0); + if (server == 0) { + pause(); + _exit(0); + } + php_processes_initialize(&process, 1); + process.php_state = PHP_READY; + process.php_pid = server; + process.php_write_fd = requests[1]; + process.php_read_fd = responses[0]; + /* The write fails with EPIPE; restarts fail on the missing executable. */ + char *result = php_cmd(command, 0); + assert(strcmp(result, "U") == 0); + free(result); + assert(close(responses[1]) == 0); + int status; + assert(waitpid(server, &status, 0) == server); + /* The script poller logs the same commands; drive its empty-result and + * missing-file lines with the secret in the arguments. */ + assert(spine_permits_init(&available_scripts, 1) == 0); + host_t host = {0}; + STRNCOPY(host.hostname, "regression-device"); + char script_command[BUFSIZE]; + spine_snprintf(script_command, sizeof(script_command), "/usr/bin/printf '' %s", secret); + result = exec_poll(&host, script_command, 1, "DS"); + assert(strcmp(result, "U") == 0); + free(result); + spine_snprintf(script_command, sizeof(script_command), "/spine-regression/missing-script %s", secret); + result = exec_poll(&host, script_command, 1, "DS"); + assert(strcmp(result, "U") == 0); + free(result); + assert(spine_permits_destroy(&available_scripts) == 0); + FILE *file = fopen(path, "r"); + assert(file != NULL); + char logged[16384]; + size_t bytes = fread(logged, 1, sizeof(logged) - 1, file); + assert(!ferror(file) && fclose(file) == 0); + logged[bytes] = '\0'; + assert(strstr(logged, "did not respond in time") != NULL); + assert(strstr(logged, "partial response") != NULL); + assert(strstr(logged, "communications lost") != NULL); + assert(strstr(logged, "Empty result [regression-device]: '/usr/bin/printf'") != NULL); + assert(strstr(logged, "File '/spine-regression/missing-script' does not exist") != NULL); + fprintf(stderr, "php failure logs at level %d contain command arguments: %s\n", level, strstr(logged, secret) != NULL ? "yes" : "no"); + assert(strstr(logged, secret) == NULL); + /* Debug output still names the script, which is enough to find it. */ + if (level == POLLER_VERBOSITY_DEBUG) { + assert(strstr(logged, "ss_regression.php") != NULL); + assert(strstr(logged, "The executable is '/usr/bin/printf'") != NULL); + } + assert(unlink(path) == 0); + php_processes = previous_processes; + set = previous_config; +} + +static void test_php_failure_logs_omit_command(void) { + run_php_failure_logs(POLLER_VERBOSITY_LOW); + run_php_failure_logs(POLLER_VERBOSITY_DEBUG); +} + static void test_script_execution(void) { assert(spine_permits_init(&available_scripts, 1) == 0); host_t host = {0}; @@ -1020,6 +1121,59 @@ static void test_script_execution(void) { set.php.script_timeout = previous_timeout; } +/* A timed-out script is killed with everything it started. The background + * sleep inherits the write end of the witness pipe, so EOF on the read end + * proves that no descendant outlived the timeout. */ +static void test_script_timeout_kills_descendants(void) { + assert(spine_permits_init(&available_scripts, 1) == 0); + host_t host = {0}; + STRNCOPY(host.hostname, "regression-device"); + int previous_timeout = set.php.script_timeout; + set.php.script_timeout = 1; + int witness[2]; + assert(pipe(witness) == 0); + char command[] = "/bin/sh -c '/bin/sleep 30 & /bin/sleep 30'"; + char *result = exec_poll(&host, command, 1, "DS"); + assert(strcmp(result, "U") == 0); + free(result); + assert(close(witness[1]) == 0); + assert(witness[0] < FD_SETSIZE); + fd_set readable; + FD_ZERO(&readable); + FD_SET(witness[0], &readable); + struct timeval timeout = {3, 0}; + int ready = select(witness[0] + 1, &readable, NULL, NULL, &timeout); + char byte; + fprintf(stderr, "script timeout descendants: ready=%d\n", ready); + assert(ready == 1 && read(witness[0], &byte, 1) == 0); + assert(close(witness[0]) == 0); + assert(spine_permits_available(&available_scripts) == 1); + assert(spine_permits_destroy(&available_scripts) == 0); + set.php.script_timeout = previous_timeout; +} + +/* nft_pclose() kills a script that is still running after its output was + * read, and the kill must reach the script's descendants as well. */ +static void test_pclose_kills_descendants(void) { + int witness[2]; + assert(pipe(witness) == 0); + int fd = nft_popen("printf 7; /bin/sleep 30 & /bin/sleep 30", "r"); + assert(fd >= 0); + char byte; + assert(read(fd, &byte, 1) == 1 && byte == '7'); + assert(nft_pclose(fd) == -1 && errno == ETIMEDOUT); + assert(close(witness[1]) == 0); + assert(witness[0] < FD_SETSIZE); + fd_set readable; + FD_ZERO(&readable); + FD_SET(witness[0], &readable); + struct timeval timeout = {3, 0}; + int ready = select(witness[0] + 1, &readable, NULL, NULL, &timeout); + fprintf(stderr, "pclose descendants: ready=%d\n", ready); + assert(ready == 1 && read(witness[0], &byte, 1) == 0); + assert(close(witness[0]) == 0); +} + static void test_php_command(size_t length) { char command[BUFSIZE]; assert(length <= sizeof(command) - 3); @@ -1605,6 +1759,8 @@ static void *test_poll_worker(void *argument) { return NULL; } +/* A worker without a connection fails its device and returns; the process + * keeps polling other devices and still exits with a failure status. */ static void test_poll_missing_connection(const poller_thread_t *work) { for (int remote = 0; remote <= 1; remote++) { pid_t child = fork(); @@ -1616,13 +1772,23 @@ static void test_poll_missing_connection(const poller_thread_t *work) { set.poller.mode = REMOTE_ONLINE; db_pool_remote = &unavailable; } else db_pool_local[0].free = FALSE; + extern poller_thread_t **details; + poller_thread_t *device = details[work->device_counter]; + device->complete = FALSE; + device->threads_complete = 0; int errors = 0; + set.exit.exit_code = EXIT_SUCCESS; poll_host(work, &errors); - _exit(0); + if (!device->poll_failed || device->complete || device->threads_complete != 1) _exit(3); + /* The local slot borrowed for a remote poll goes back to the pool. */ + if (remote && !db_pool_local[0].free) _exit(4); + /* The failure still reaches the process exit status. */ + _exit(set.exit.exit_code == EXIT_FAILURE ? 0 : 5); } int status; assert(waitpid(child, &status, 0) == child); - assert(WIFEXITED(status) && WEXITSTATUS(status) == EXIT_FAILURE); + fprintf(stderr, "missing connection: remote=%d raw_status=%d\n", remote, status); + assert(WIFEXITED(status) && WEXITSTATUS(status) == 0); } } @@ -1686,6 +1852,28 @@ static void test_reindex_pipeline(MYSQL *mysql, test_poll_work_t *work) { assert(db_insert(mysql, LOCAL, "DELETE FROM poller_command")); } +/* A reindex that could not be queued must leave the stored assertion alone; + * advancing it would hide the change from every later poll. Hiding the + * poller_command table makes the server itself reject the queue write. */ +static void test_reindex_queue_failure(MYSQL *mysql, test_poll_work_t *work) { + assert(db_insert(mysql, LOCAL, "DELETE FROM poller_reindex")); + assert(db_insert(mysql, LOCAL, "DELETE FROM poller_command")); + assert(db_insert(mysql, LOCAL, "INSERT INTO poller_reindex(host_id,data_query_id,action,op,assert_value,arg1) VALUES (43,7,1,'=','122','/usr/bin/printf 123'),(43,8,1,'>','122','/usr/bin/printf 123')")); + assert(db_insert(mysql, LOCAL, "RENAME TABLE poller_command TO poller_command_regression_hidden")); + work->thread.complete = FALSE; + work->thread.threads_complete = 0; + work->errors = 0; + pthread_t worker; + assert(pthread_create(&worker, NULL, test_poll_worker, work) == 0); + assert(pthread_join(worker, NULL) == 0); + assert(db_insert(mysql, LOCAL, "RENAME TABLE poller_command_regression_hidden TO poller_command")); + long long kept = (long long)database_count(mysql, "SELECT COUNT(*) FROM poller_reindex WHERE (data_query_id=7 AND assert_value='122') OR (data_query_id=8 AND assert_value='122')"); + fprintf(stderr, "reindex queue failure: assertions kept=%lld\n", kept); + assert(kept == 2); + assert(work->thread.threads_complete == 1); + assert(db_insert(mysql, LOCAL, "DELETE FROM poller_reindex")); +} + static void test_reindex_query_shortcut(MYSQL *mysql, test_poll_work_t *work) { assert(db_insert(mysql, LOCAL, "DELETE FROM poller_reindex")); assert(db_insert(mysql, LOCAL, "DELETE FROM poller_command")); @@ -1744,6 +1932,51 @@ static void test_profile_schedule_completion(MYSQL *mysql, test_poll_work_t *agg set = previous; } +/* A real, non-retryable SQL error inside a worker fails that device and the + * worker returns: the schedule is not advanced, nothing is written, and the + * connection goes back to the pool for the next device. The item query names + * a column the fixture schema lacks, so MariaDB itself rejects it. */ +static void test_poll_database_failure(MYSQL *mysql, test_poll_work_t *aggregate) { + config_t previous = set; + test_poll_work_t original = *aggregate; + assert(database_count(mysql, "SELECT COUNT(*) FROM information_schema.COLUMNS WHERE TABLE_SCHEMA=DATABASE() AND TABLE_NAME='poller_item' AND COLUMN_NAME='output_regex'") == 0); + set.poller.active_profiles = 2; + set.poller.poller_interval = 5; + assert(db_insert(mysql, LOCAL, "DELETE FROM poller_item WHERE host_id=43 AND local_data_id NOT IN (601,602)")); + for (int failing = 1; failing >= 0; failing--) { + set.hosts.has_output_regex = failing; + assert(db_insert(mysql, LOCAL, "UPDATE poller_item SET rrd_step=300,rrd_next_step=0 WHERE host_id=43")); + assert(db_insert(mysql, LOCAL, "DELETE FROM poller_output")); + assert(db_insert(mysql, LOCAL, "DELETE FROM poller_output_boost")); + aggregate->thread.host_thread = 1; + aggregate->thread.host_threads = 1; + aggregate->thread.host_data_ids = 0; + aggregate->thread.complete = FALSE; + aggregate->thread.threads_complete = 0; + aggregate->thread.output_failed = FALSE; + aggregate->thread.poll_failed = FALSE; + set.exit.exit_code = EXIT_SUCCESS; + pthread_t worker; + assert(pthread_create(&worker, NULL, test_poll_worker, aggregate) == 0); + assert(pthread_join(worker, NULL) == 0); + assert(aggregate->thread.threads_complete == 1); + assert(db_pool_local[0].free && spine_permits_available(&available_scripts) == 2); + if (failing) { + assert(aggregate->thread.poll_failed && !aggregate->thread.complete); + assert(set.exit.exit_code == EXIT_FAILURE); + assert(database_count(mysql, "SELECT COUNT(*) FROM poller_output") == 0); + assert(database_count(mysql, "SELECT COUNT(*) FROM poller_item WHERE host_id=43 AND rrd_next_step=0") == 2); + } else { + assert(!aggregate->thread.poll_failed && aggregate->thread.complete); + assert(set.exit.exit_code == EXIT_SUCCESS); + assert(database_count(mysql, "SELECT COUNT(*) FROM poller_output WHERE (local_data_id=601 AND output='123') OR (local_data_id=602 AND output='U')") == 2); + assert(database_count(mysql, "SELECT COUNT(*) FROM poller_item WHERE host_id=43 AND rrd_next_step=295") == 2); + } + } + *aggregate = original; + set = previous; +} + static void prepare_nullable_snmp_profile(MYSQL *mysql) { /* These fields are nullable in the shipped schema; missing values * must survive the real row-loader/session handoff. */ @@ -1892,7 +2125,9 @@ static void test_poll_pipeline(MYSQL *mysql) { if (host_id == 43) { test_reindex_pipeline(mysql, work); test_reindex_query_shortcut(mysql, work); + test_reindex_queue_failure(mysql, work); test_profile_schedule_completion(mysql, work); + test_poll_database_failure(mysql, work); } /* End this fixture binding before the next host or caller runs. */ details = previous_details; @@ -2573,10 +2808,13 @@ int main(int argc, char **argv) { test_php_command(4); test_php_command(BUFSIZE - 3); test_invalid_php_commands(); + test_php_failure_logs_omit_command(); test_php_startup(argv[0]); test_php_owned_shutdown(); test_host_status_transitions(); test_script_execution(); + test_script_timeout_kills_descendants(); + test_pclose_kills_descendants(); test_script_stream_contracts(); test_cli_alias_contracts(); test_privilege_contracts(); diff --git a/tests/unit/test_util_paths.c b/tests/unit/test_util_paths.c index f20c7673..5dee8318 100644 --- a/tests/unit/test_util_paths.c +++ b/tests/unit/test_util_paths.c @@ -108,7 +108,7 @@ MYSQL_ROW test_mysql_fetch_row(MYSQL_RES *res) { return cells; } -void db_connect(int type, MYSQL *mysql) {} +int db_connect(int type, MYSQL *mysql) { return TRUE; } void db_disconnect(MYSQL *mysql) {} MYSQL_RES *db_query(MYSQL *mysql, int type, const char *query) { (void) mysql; (void) type; diff --git a/tests/unit/test_util_strings.c b/tests/unit/test_util_strings.c index 53cd2ec4..aeda4df6 100644 --- a/tests/unit/test_util_strings.c +++ b/tests/unit/test_util_strings.c @@ -17,7 +17,7 @@ char config_paths[CONFIG_PATHS][BUFSIZE]; int *debug_devices = NULL; /* Mock functions needed by util.c */ -void db_connect(int type, MYSQL *mysql) {} +int db_connect(int type, MYSQL *mysql) { return TRUE; } void db_disconnect(MYSQL *mysql) {} MYSQL_RES *db_query(MYSQL *mysql, int type, const char *query) { return NULL; } void db_free_result(MYSQL_RES *result) {} diff --git a/util.c b/util.c index f88878de..cbf6658f 100644 --- a/util.c +++ b/util.c @@ -250,6 +250,19 @@ typedef struct setting_cache_entry { static setting_cache_t *settings_cache = NULL; static int settings_cache_count = 0; +/* Settings are read in the main thread before polling starts, so a database + * error here is a configuration failure and ends the process, as it did when + * db_query() exited on its own. An empty or missing result is not an error. */ +static MYSQL_RES *config_query(MYSQL *psql, int mode, const char *query) { + MYSQL_RES *result = db_query(psql, mode, query); + + if (result == NULL && mysql_errno(psql) != 0) { + die("FATAL: Unable to read the Cacti configuration from the database"); + } + + return result; +} + static void settings_cache_free(void) { int i; @@ -276,7 +289,7 @@ static void settings_cache_load(MYSQL *psql, int mode) { settings_cache_free(); - result = db_query(psql, mode, "SELECT SQL_NO_CACHE name, value FROM settings"); + result = config_query(psql, mode, "SELECT SQL_NO_CACHE name, value FROM settings"); if (result == NULL) return; @@ -361,7 +374,7 @@ static char *getsetting(MYSQL *psql, int mode, const char *setting) { spine_snprintf(qstring, sizeof(qstring), "SELECT SQL_NO_CACHE value FROM settings WHERE name = '%s'", setting); - result = db_query(psql, mode, qstring); + result = config_query(psql, mode, qstring); if (result == NULL) return strdup(""); mysql_row = mysql_num_rows(result) > 0 ? mysql_fetch_row(result) : NULL; retval = mysql_row != NULL && mysql_row[0] != NULL ? strdup(mysql_row[0]) : strdup(""); @@ -434,7 +447,7 @@ static char *getpsetting(MYSQL *psql, int mode, const char *setting) { spine_snprintf(qstring, sizeof(qstring), "SELECT SQL_NO_CACHE %s FROM poller WHERE id = '%d'", setting, set.poller.poller_id); - result = db_query(psql, mode, qstring); + result = config_query(psql, mode, qstring); if (result == NULL) return NULL; mysql_row = mysql_num_rows(result) > 0 ? mysql_fetch_row(result) : NULL; retval = mysql_row != NULL && mysql_row[0] != NULL ? strdup(mysql_row[0]) : NULL; @@ -513,7 +526,7 @@ static char *getglobalvariable(MYSQL *psql, int mode, const char *setting) { spine_snprintf(qstring, sizeof(qstring), "SHOW GLOBAL VARIABLES LIKE '%s'", setting); - result = db_query(psql, mode, qstring); + result = config_query(psql, mode, qstring); if (result == NULL) return NULL; mysql_row = mysql_num_rows(result) > 0 ? mysql_fetch_row(result) : NULL; retval = mysql_row != NULL && mysql_row[1] != NULL ? strdup(mysql_row[1]) : NULL; @@ -860,8 +873,8 @@ static void read_php_requirement(MYSQL *mysql) { sqlp += spine_snprintf(sqlp, sizeof(sqlbuf) - (size_t)(sqlp - sqlbuf), " AND poller_id=%i", set.poller.poller_id); spine_snprintf(sqlp, sizeof(sqlbuf) - (size_t)(sqlp - sqlbuf), " LIMIT 1"); - result = db_query(mysql, LOCAL, sqlbuf); - num_rows = spine_count_to_int(mysql_num_rows(result)); + result = config_query(mysql, LOCAL, sqlbuf); + num_rows = result != NULL ? spine_count_to_int(mysql_num_rows(result)) : 0; db_free_result(result); if (num_rows > 0) set.php.php_required = TRUE; @@ -878,8 +891,8 @@ static void read_php_requirement(MYSQL *mysql) { sqlp += spine_snprintf(sqlp, sizeof(sqlbuf) - (size_t)(sqlp - sqlbuf), " AND poller_id=%i", set.poller.poller_id); spine_snprintf(sqlp, sizeof(sqlbuf) - (size_t)(sqlp - sqlbuf), " LIMIT 1"); - result = db_query(mysql, LOCAL, sqlbuf); - num_rows = spine_count_to_int(mysql_num_rows(result)); + result = config_query(mysql, LOCAL, sqlbuf); + num_rows = result != NULL ? spine_count_to_int(mysql_num_rows(result)) : 0; db_free_result(result); if (num_rows > 0) set.php.php_required = TRUE; @@ -996,13 +1009,13 @@ void read_config_options() { int mode; char *res; - db_connect(LOCAL, &mysql); + if (!db_connect(LOCAL, &mysql)) die("FATAL: Unable to connect to the local database"); /* one round trip instead of one per setting */ settings_cache_load(&mysql, LOCAL); if (set.poller.poller_id > 1 && set.poller.mode == REMOTE_ONLINE) { - db_connect(REMOTE, &mysqlr); + if (!db_connect(REMOTE, &mysqlr)) die("FATAL: Unable to connect to the remote database"); mode = REMOTE; } else { mode = LOCAL; @@ -1224,8 +1237,20 @@ bool poller_transfer_status(MYSQL *source, MYSQL *destination) { void poller_push_data_to_main(void) { MYSQL source; MYSQL destination; - db_connect(LOCAL, &source); - db_connect(REMOTE, &destination); + /* A failed connect leaves an initialized handle that still has to be closed. */ + if (!db_connect(LOCAL, &source)) { + db_disconnect(&source); + SPINE_LOG(("ERROR: Collector synchronization skipped; the local database is unavailable. Local rows are retained for retry.")); + set.exit.exit_code = EXIT_FAILURE; + return; + } + if (!db_connect(REMOTE, &destination)) { + db_disconnect(&destination); + db_disconnect(&source); + SPINE_LOG(("ERROR: Collector synchronization skipped; the main server is unavailable. Local rows are retained for retry.")); + set.exit.exit_code = EXIT_FAILURE; + return; + } /* Preserve the supported zero-date and GROUP BY session policies. */ bool configured = db_insert(&source, LOCAL, "SET SESSION sql_mode = (SELECT REPLACE(@@sql_mode,'NO_ZERO_DATE', ''))") && db_insert(&source, LOCAL, "SET SESSION sql_mode = (SELECT REPLACE(@@sql_mode,'ONLY_FULL_GROUP_BY', ''))") && @@ -2264,7 +2289,7 @@ static int parse_cacti_version(const char *value) { int get_cacti_version(MYSQL *psql, int mode) { assert(psql != NULL); - MYSQL_RES *result = db_query(psql, mode, "SELECT cacti FROM version LIMIT 1"); + MYSQL_RES *result = config_query(psql, mode, "SELECT cacti FROM version LIMIT 1"); if (result == NULL) return 0; MYSQL_ROW row = mysql_fetch_row(result); int version = row != NULL && row[0] != NULL ? parse_cacti_version(row[0]) : 0;