Repository navigation
fix: apply SIGUSR1/SIGUSR2 log level changes outside the signal handler - #5217
Conversation
Logger::usrHandler changed the level and called Info() from the handler. Info() takes log_mutex, glibc's syslog and tzset locks (syslog, localtime_r) and the database queue's mutex, and allocates. A SIGUSR1 or SIGUSR2 delivered to a thread already inside one of those waits on itself, and the process hangs until zmwatch/zmdc kill it. The handler now only adds +1/-1 to a lock-free atomic, as the SIGWINCH branch already sets a flag. Logger::fetch(), which every log macro calls before its level check, applies a pending change under log_mutex and logs "Level changed" from normal context, so the new level is in effect at the next log call on any thread. Several signals before that add up to one change, clamped to NOLOG..DEBUG9. logInit() drops a change still pending for the logger it replaces. fixes ZoneMinder#5216 Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
connortechnology
left a comment
There was a problem hiding this comment.
The diagnosis is right and the fix is sound. Flagging instead of logging matches the SIGWINCH branch, exchange(0) makes sure only one thread applies a given change, and the reset in initialise() keeps a pending change from carrying over to a new logger. Picking the change up in fetch() rather than logPrint() is the right call: it means a raise from INFO takes effect at the next Debug call site.
I built this branch locally and ran the tests (Debian, Debug build, -DBUILD_TEST_SUITE=ON). The four SIGUSR cases pass, including the two new ones. On the full ~[notCI] run, the only failures were the font and annotate tests, which load font files by relative path and fail when run from build/, so they look unrelated to this change. I did not rerun the tgkill stress test.
Two small things:
- The PR description has a leftover placeholder: "Fixes: #5216: #:".
- release-1.38 has the same handler (no SIGWINCH branch), so it needs the hand port mentioned in the description.
| // limit() first: level() ignores anything at or below NOOPT. | ||
| new_level = level(limit(mLevel + change)); | ||
| } | ||
| Info("Logger - Level changed to %d %s", new_level, smCodes[new_level].c_str()); |
There was a problem hiding this comment.
Minor: this now runs on whichever thread makes the next log call. If that thread is inside a DatabaseLogPause (zmDbDo, the queue's own Warning), the "Level changed" line goes to the file and syslog but never reaches the Logs table. It can't deadlock: dbQueue.push() only takes the queue's mMutex, and Error() calls made while holding db_mutex already rely on that. I don't think this needs a change; mentioning it in case someone goes looking for that line in the Logs table.
TL;DR
Logger::fetch(), which every log macro calls before its level check, applies it underlog_mutexand logs "Level changed" from normal context; 3 files, +85/-4fetch(); level changes take effect at the next log call on any thread instead of inside the handler; the existing SIGUSR1 unit tests pass unchangedDetails: reproduction, change, checks
Before
Upstream master
c3d2e542b, clean plain build, five zmc; 3 runs of 200 rounds of SIGUSR1/SIGUSR2sent to every thread of every zmc:
New unit test on master's code:
Change
src/zm_logger.cpp,src/zm_logger.h: newstatic std::atomic<int> smLevelChange(
static_assertlock-free).usrHandlerincrements/decrements it and returns, like theSIGWINCH branch.
Logger::fetch()checks it (relaxed load) and calls the newapplyLevelChange():exchange(0),level(limit(mLevel + change))underlog_mutex, thenInfo("Logger - Level changed to %d %s", ...)outside the lock.initialise()resets it, so achange pending when
logInit()replaces the logger isn't applied to the new one.tests/zm_logger_rotate.cpp, 2 cases: the handler writes nothing and the next log calllogs the change before its own line; several signals add up; lowering clamps at NOLOG;
a pending change doesn't carry over to a new logger. The first fails on master.
Behaviour changes
logPrintlike SIGWINCH:logPrintis only reached for lines at or below the current level, so raising from INFO would wait for the next Info line; infetch()every Debug call site applies itfetch()raise(SIGUSR1); Debug(1, ...)still logs); live:Logger - Level changed to 1 DB1thento 0 INFin LogsSide fixes in this PR: none. Not changed:
mLevel/mEffectiveLevelstay plain ints readwithout the lock on the hot path (ThreadSanitizer still reports that read against the write,
now made under
log_mutex); making them atomic is a separate change.Related: #5203 (logger reload, open) touches the same files; the two merge without conflicts.
After
Branch
fix/b55-usr-level-signal-safeat367e19d4f(basec3d2e542b), tested in a merge withtwo other fixes from the same lab session (
combo= master + this +fix/b65-zmc-stop-during-startup+fix/b77-monitorlink-token-leak; no shared files):check-changed.py: unit-tests, script-tests, smoke, resilience, events, dblog --quick, signals --quick)zmonvif-probe.pldiscovery, known), resilience PASS=5, events PASS=10 (record, mocord, modect-only, nodect, monitor, linked, jpegs, reload, filters, purge), dblog --quick PASS=1 XFAIL=2 (thread-error, contention: known on master, #5197/#5208), signals --quick PASS=4 (hup-default, usr, usr-threads, startup-stop)Not run: the deep set. Backport to release-1.38: same bug; the commit doesn't cherry-pick
(1.38's handler has no SIGWINCH branch and no
DatabaseLogPause), a hand port is a few lines (not prepared).Tested as
389f9e5aa;367e19d4fis the same tree withfixes #5216added to the message.fixes #5216
🤖 Generated with Claude Code