diff --git a/src/worker/src/uv_ipc.c b/src/worker/src/uv_ipc.c index ae72d4eb..af1e16dd 100644 --- a/src/worker/src/uv_ipc.c +++ b/src/worker/src/uv_ipc.c @@ -6,6 +6,7 @@ #include "uv_ipc.h" #include "xcecd.h" #include "xcelog.h" +#include #include #include #include @@ -986,6 +987,22 @@ void ipc_worker_request_job() * @param status_message * @return void */ + +/* job_exit_log_level - a JOB_EXITED status can mean either a deliberate, + * expected termination (worker_signal_callback(), xcecd_worker.c, only ever + * sends SIGTERM/SIGKILL to cancel/force-kill a job -- process_exit_callback() + * there already logs a plain-INFO "Child %d killed by signal %d" for exactly + * this case) or a genuine unexpected crash signal (SIGSEGV/SIGBUS/SIGABRT/ + * etc.). exit_code is always 128+term_signal here (process_exit_callback(), + * xcecd_worker.c), so it reliably distinguishes the two. */ +static LogLevel job_exit_log_level(int exit_code) +{ + if ((exit_code == 128 + SIGTERM) || (exit_code == 128 + SIGKILL)) { + return XCE_LOG_INFO; + } + return XCE_LOG_ERROR; +} + void ipc_worker_send_status(job_runtime_info_t* job_info, const char* status_message) { @@ -1045,8 +1062,9 @@ void ipc_worker_send_status(job_runtime_info_t* job_info, XCECD_WORKER_LOG(XCE_LOG_ERROR, "Job %s failed: %s", jobidStr, status_message); } else if (job_info->job_status == JOB_EXITED) { - XCECD_WORKER_LOG(XCE_LOG_ERROR, "Job %s exited with code %d: %s", - jobidStr, job_info->exit_code, status_message); + XCECD_WORKER_LOG(job_exit_log_level(job_info->exit_code), + "Job %s exited with code %d: %s", jobidStr, + job_info->exit_code, status_message); } } diff --git a/src/worker/testsuite/meson.build b/src/worker/testsuite/meson.build index 449e145b..b580d152 100644 --- a/src/worker/testsuite/meson.build +++ b/src/worker/testsuite/meson.build @@ -77,3 +77,19 @@ test('worker dbus_workers_update test', dbus_workers_update_test, suite: 'worker', timeout: 60, env: ['ASAN_OPTIONS=detect_leaks=0']) + +# User-reported log-severity bug: a deliberately-killed job (SIGTERM/SIGKILL +# via worker_signal_callback(), xcecd_worker.c) was logged at ERROR by +# ipc_worker_send_status() (uv_ipc.c) even though process_exit_callback() +# two lines earlier already judges the same event INFO-worthy. See +# test_uv_ipc_job_exit_severity.c's own header comment. +uv_ipc_job_exit_severity_test = executable('uv_ipc_job_exit_severity_test', + 'test_uv_ipc_job_exit_severity.c', + include_directories: [worker_test_incdir], + dependencies: worker_test_deps, + install: false) + +test('worker uv_ipc job_exit_severity test', uv_ipc_job_exit_severity_test, + suite: 'worker', + timeout: 60, + env: ['ASAN_OPTIONS=detect_leaks=0']) diff --git a/src/worker/testsuite/test_uv_ipc_job_exit_severity.c b/src/worker/testsuite/test_uv_ipc_job_exit_severity.c new file mode 100644 index 00000000..eb780f18 --- /dev/null +++ b/src/worker/testsuite/test_uv_ipc_job_exit_severity.c @@ -0,0 +1,91 @@ +/* + * test_uv_ipc_job_exit_severity.c - regression test for the worker's + * kill-job log-severity bug: process_exit_callback() (xcecd_worker.c) + * already treats a signal-terminated job exit as INFO-worthy ("Child %d + * killed by signal %d"), but the status-broadcast log two lines later + * (ipc_worker_send_status(), uv_ipc.c) independently re-logged the SAME + * event at ERROR for every JOB_EXITED status, regardless of whether the + * signal was a deliberate kill (worker_signal_callback() only ever sends + * SIGTERM/SIGKILL for a normal job cancel/force-kill) or a genuine crash + * signal (SIGSEGV/SIGBUS/SIGABRT/...). User-reported: `xcecd_worker.log` + * showed `[ERROR] Job ... exited with code 137: Killed` for ordinary, + * expected job kills (exit code 137 = 128+SIGKILL). + * + * White-box #include of ../src/uv_ipc.c (same convention this suite's + * other tests already establish, e.g. test_resource_sync.c) -- exercises + * only the pure, dependency-free job_exit_log_level() helper extracted + * from ipc_worker_send_status(), no libuv/IPC machinery involved. + */ +#include + +#include + +#include "xcecd.h" + +/* xcecd.h-required global for this white-box TU (same idiom + * test_resource_sync.c already establishes) -- unused by + * job_exit_log_level() itself, just needed to satisfy uv_ipc.c's includes. */ +xcecd_context_t xcecd_ctx; + +#include "../src/uv_ipc.c" + +/* Link-only stubs (same idiom test_resource_sync.c establishes): uv_ipc.c + * references these two (xcecd_worker_utils.c/controller_connector.c, not + * linked here) in code paths this test never calls -- job_exit_log_level() + * is a pure function with no dependency on either. */ +xcecd_worker_t* find_worker_by_pid(void* worker_list, int pid) +{ + (void)worker_list; + (void)pid; + return NULL; +} + +int xcecd_job_remote_start(uint64_t jobid, const char* hostname, + const char* command) +{ + (void)jobid; + (void)hostname; + (void)command; + return 0; +} + +void setUp(void) { return; } +void tearDown(void) { return; } + +static void test_deliberate_sigterm_kill_logs_info(void) +{ + TEST_ASSERT_EQUAL_INT(XCE_LOG_INFO, + job_exit_log_level(128 + SIGTERM)); +} + +static void test_deliberate_sigkill_kill_logs_info(void) +{ + TEST_ASSERT_EQUAL_INT(XCE_LOG_INFO, + job_exit_log_level(128 + SIGKILL)); +} + +static void test_genuine_crash_signal_still_logs_error(void) +{ + TEST_ASSERT_EQUAL_INT(XCE_LOG_ERROR, + job_exit_log_level(128 + SIGSEGV)); + TEST_ASSERT_EQUAL_INT(XCE_LOG_ERROR, + job_exit_log_level(128 + SIGABRT)); + TEST_ASSERT_EQUAL_INT(XCE_LOG_ERROR, + job_exit_log_level(128 + SIGBUS)); +} + +static void test_unrecognized_exit_code_defaults_to_error(void) +{ + TEST_ASSERT_EQUAL_INT(XCE_LOG_ERROR, job_exit_log_level(1)); + TEST_ASSERT_EQUAL_INT(XCE_LOG_ERROR, job_exit_log_level(0)); +} + +int main(void) +{ + UNITY_BEGIN(); + RUN_TEST(test_deliberate_sigterm_kill_logs_info); + RUN_TEST(test_deliberate_sigkill_kill_logs_info); + RUN_TEST(test_genuine_crash_signal_still_logs_error); + RUN_TEST(test_unrecognized_exit_code_defaults_to_error); + return UNITY_END(); +}