From 8642007d0e17ba9c6ba66c30838de5dcf16b16c7 Mon Sep 17 00:00:00 2001 From: Joachim Wiberg Date: Sun, 22 Feb 2026 10:43:42 +0100 Subject: [PATCH] Debug shutdown hangs and guard with timer watchdog Signed-off-by: Joachim Wiberg --- src/sig.c | 6 ++++++ src/sm.c | 53 ++++++++++++++++++++++++++++++++++++++++++++++++++++- src/sm.h | 5 +++++ 3 files changed, 63 insertions(+), 1 deletion(-) diff --git a/src/sig.c b/src/sig.c index e3e25b52..38f16608 100644 --- a/src/sig.c +++ b/src/sig.c @@ -303,6 +303,8 @@ void do_shutdown(shutop_t op) int in_cont = in_container(); int signo = SIGTERM; + if (SHUTDOWN_DEBUG) cprintf("do_shutdown: entered, op=%d\n", op); + if (!in_cont) { /* * On a PREEMPT-RT system, Finit must run as the highest prioritized @@ -322,6 +324,7 @@ void do_shutdown(shutop_t op) * Tell remaining non-monitored processes to exit, give them * time to exit gracefully, 2 sec was customary, we go for 1. */ + if (SHUTDOWN_DEBUG) cprintf("do_shutdown: killing remaining processes ...\n"); iterate_proc(kill_cb, &signo); if (do_wait(1)) { signo = SIGKILL; @@ -329,6 +332,7 @@ void do_shutdown(shutop_t op) } /* Exit plugins gracefully */ + if (SHUTDOWN_DEBUG) cprintf("do_shutdown: plugin_exit() + cond_exit() ...\n"); plugin_exit(); /* We can no longer act on conditions, activate script runner */ @@ -351,12 +355,14 @@ void do_shutdown(shutop_t op) for (int fd = 3; fd < 128; fd++) close(fd); + if (SHUTDOWN_DEBUG) cprintf("do_shutdown: vfork, child will reboot ...\n"); if (vfork()) { /* * Put PID 1 aside and let child perform reboot/halt * kernel may exit child and we don't want to exit PID 1 * ... causing "aiii killing init" during reboot ... */ + if (SHUTDOWN_DEBUG) cprintf("do_shutdown: PID 1 returning from vfork\n"); return; } diff --git a/src/sm.c b/src/sm.c index 85510ff8..ab3abdb9 100644 --- a/src/sm.c +++ b/src/sm.c @@ -63,9 +63,37 @@ static struct { int skip_bootstrap; /* Set to skip bootstrap waiting */ } sm; +/* Shutdown trace: set SHUTDOWN_DEBUG to 1 in sm.h to enable */ +#define shutdbg(fmt, args...) do { \ + if (SHUTDOWN_DEBUG && (runlevel == 0 || runlevel == 6)) \ + cprintf("shutdown[%c]: " fmt "\n", \ + sm_rl2ch(runlevel), ##args); \ +} while (0) + static uev_t console_watcher; static int console_fd = -1; +/* + * Shutdown watchdog: if graceful service stop takes too long, + * force do_shutdown() directly from the event loop callback. + * Default timeout is 30 seconds, adjustable at build time. + */ +#ifndef SHUTDOWN_WDT_TIMEOUT +#define SHUTDOWN_WDT_TIMEOUT 30 +#endif +static uev_t shutdown_wdt; + +static void shutdown_wdt_cb(uev_t *w, void *arg, int events) +{ + (void)w; + (void)arg; + (void)events; + + logit(LOG_CONSOLE | LOG_CRIT, "Timed out (%d sec) waiting for services to stop, forcing shutdown.", + SHUTDOWN_WDT_TIMEOUT); + do_shutdown(halt); +} + /* * Console input callback - handles Ctrl-C during bootstrap wait */ @@ -350,6 +378,7 @@ restart: /* reload ? */ if (sm.reload) { + shutdbg("RUNNING got reload request!"); sm.reload = 0; sm.state = SM_RELOAD_CHANGE_STATE; } @@ -362,9 +391,15 @@ restart: /* Restore terse mode and run hooks before shutdown */ if (runlevel == 0 || runlevel == 6) { + shutdbg("entering CHANGE state, starting %d sec watchdog", + SHUTDOWN_WDT_TIMEOUT); + uev_timer_init(ctx, &shutdown_wdt, shutdown_wdt_cb, + NULL, SHUTDOWN_WDT_TIMEOUT * 1000, 0); api_exit(); log_exit(); + shutdbg("running HOOK_SHUTDOWN ..."); plugin_run_hooks(HOOK_SHUTDOWN); + shutdbg("HOOK_SHUTDOWN done"); } dbg("Setting new runlevel --> %c <-- previous %c", sm_rl2ch(runlevel), sm_rl2ch(prevlevel)); @@ -384,12 +419,14 @@ restart: } /* Reset once flag of runtasks */ + shutdbg("runtask_clean + step_all ..."); service_runtask_clean(); dbg("Stopping services not allowed in new runlevel ..."); sm.in_reload = 1; service_step_all(SVC_TYPE_ANY); + shutdbg("CHANGE done, entering WAIT"); sm.state = SM_RUNLEVEL_WAIT_STATE; break; @@ -400,10 +437,13 @@ restart: */ svc = svc_stop_completed(); if (svc) { + shutdbg("WAIT, collecting %s[%d] ...", svc_ident(svc, NULL, 0), svc->pid); dbg("Waiting to collect %s, cmd %s(%d) ...", svc_ident(svc, NULL, 0), svc->cmd, svc->pid); break; } + shutdbg("WAIT done, all services stopped"); + /* Prev runlevel services stopped, call hooks before starting new runlevel ... */ dbg("All services have been stopped, calling runlevel change hooks ..."); plugin_run_hooks(HOOK_RUNLEVEL_CHANGE); /* Reconfigure HW/VLANs/etc here */ @@ -416,6 +456,7 @@ restart: sm.in_reload = 0; service_step_all(SVC_TYPE_ANY); + shutdbg("entering CLEAN"); sm.state = SM_RUNLEVEL_CLEAN_STATE; break; @@ -427,11 +468,15 @@ restart: */ svc = svc_clean_completed(); if (svc) { + shutdbg("CLEAN, waiting for %s[%d] (%s) ...", + svc_ident(svc, NULL, 0), svc->pid, svc_status(svc)); dbg("Waiting to collect post/cleanup script for %s, cmd %s(%d) ...", svc_ident(svc, NULL, 0), svc->cmd, svc->pid); break; } + shutdbg("CLEAN done, all post/cleanup scripts collected"); + /* Cleanup stale services */ svc_clean_dynamic(service_unregister); @@ -447,9 +492,15 @@ restart: * Tannhäuser Gate. All those .. moments .. will be lost in time, like * tears ... in ... rain." */ - if (runlevel == 0 || runlevel == 6) + if (runlevel == 0 || runlevel == 6) { + shutdbg("calling do_shutdown()"); + uev_timer_stop(&shutdown_wdt); do_shutdown(halt); + shutdbg("do_shutdown() returned to SM!"); + } + shutdbg("entering RUNNING (reload=%d, newlevel=%d)", + sm.reload, sm.newlevel); sm.state = SM_RUNNING_STATE; break; diff --git a/src/sm.h b/src/sm.h index 15e7bc1f..ada6df23 100644 --- a/src/sm.h +++ b/src/sm.h @@ -24,6 +24,11 @@ #ifndef FINIT_SM_H_ #define FINIT_SM_H_ +/* Set to 1 to enable shutdown trace logging (independent of 'initctl debug') */ +#ifndef SHUTDOWN_DEBUG +#define SHUTDOWN_DEBUG 1 +#endif + void sm_init (void); void sm_step (void);