feat(worker): distinguish signal-killed job exits from real crashes in logs
A JOB_EXITED status could mean either a deliberate, expected termination (worker_signal_callback() only ever sends SIGTERM/SIGKILL to cancel/ force-kill a job) or a genuine unexpected crash signal. Both logged at ERROR, drowning real crashes in expected-cancellation noise. Added job_exit_log_level(): exit_code == 128+SIGTERM/SIGKILL logs at INFO (matching process_exit_callback()'s existing plain-INFO treatment for the same case), anything else stays ERROR. Verified: worker test suite 5/5 including the new test_uv_ipc_job_exit_severity coverage. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_019QxaSzHRB7pmYFp4cVnwkA
This commit is contained in:
parent
83cb660b44
commit
347e996e76
3 changed files with 127 additions and 2 deletions
|
|
@ -6,6 +6,7 @@
|
|||
#include "uv_ipc.h"
|
||||
#include "xcecd.h"
|
||||
#include "xcelog.h"
|
||||
#include <signal.h>
|
||||
#include <stdio.h>
|
||||
#include <stdlib.h>
|
||||
#include <string.h>
|
||||
|
|
@ -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);
|
||||
}
|
||||
}
|
||||
|
||||
|
|
|
|||
|
|
@ -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'])
|
||||
|
|
|
|||
91
src/worker/testsuite/test_uv_ipc_job_exit_severity.c
Normal file
91
src/worker/testsuite/test_uv_ipc_job_exit_severity.c
Normal file
|
|
@ -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 <signal.h>
|
||||
|
||||
#include <unity/unity.h>
|
||||
|
||||
#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();
|
||||
}
|
||||
Loading…
Add table
Add a link
Reference in a new issue