refactor(logs): homogeneous logging with LOG_LEVEL debug mode - #417
Open
MateoLostanlen wants to merge 18 commits into
Open
refactor(logs): homogeneous logging with LOG_LEVEL debug mode#417MateoLostanlen wants to merge 18 commits into
MateoLostanlen wants to merge 18 commits into
Conversation
Libraries no longer configure the root logger: basicConfig is called only from the two entrypoints, with the same format in both services. LOG_LEVEL is now plumbed through docker-compose and documented in .env.example.
Per-pose captures, raw predictions and no-detection results move to DEBUG. Each pass now ends with one INFO summary (analyzed/failed/positive/max confidence/duration). Detections and alerts stay at INFO. Startup retries are warnings instead of errors, unexpected failures use logger.exception, and every camera line carries a [cam_id] prefix. Classifier no longer mutates the module logger level from its constructor.
One INFO line per patrol cycle, per-pose moves and captures move to DEBUG. The static loop stays silent while healthy and reports recovery instead of repeating a warning every 30s during a skip window. ffmpeg stderr, FPS meter, mock no-ops and unsupported Linovision features drop to DEBUG. RTSP URLs and ffmpeg commands are redacted before logging, using a shared helper extracted from the RTSP adapter.
Wiring LOG_LEVEL to the engine made the healthcheck grep for strings that are only emitted at INFO, so LOG_LEVEL=WARNING would mark a healthy engine unhealthy. The main loop now refreshes data/heartbeat and the healthcheck checks its freshness instead. The night sleep is chunked so it stays fresh. Third-party loggers are also clamped to the configured level: pinning them to WARNING let their warnings through an ERROR root logger.
Refresh the heartbeat per pose and during the end-of-loop sleep so a slow round or a large --period cannot exceed the healthcheck window. The heartbeat path is now its own --heartbeat-file option instead of being derived from --cache, so it stays aligned with the healthcheck.
Uvicorn keeps its own handlers with propagate=False, so its startup and access lines kept a timestamp-less format of their own. They now go through the root handler like every other line.
Splitting on the first @ leaked the tail of any password containing one: rtsp://admin:p@ssword@host became rtsp://***:***@ssword@host. It also mangled credential-free URLs whose path contains @, dropping the host. Parse the URL and mask the netloc userinfo instead, and leave anything that is not a scheme://host URL untouched so the helper stays safe to map over a whole ffmpeg command line.
Uvicorn's dictConfig pins an explicit INFO level on uvicorn and uvicorn.error, so its startup lines stayed visible at LOG_LEVEL=ERROR. Reset them to NOTSET so they inherit the configured level.
verbose was accepted but ignored, so library callers passing verbose=False started seeing detection and model setup lines. Gate those logs per instance, downgrading them to DEBUG, which restores the observable behaviour without the old global logger.setLevel side effect.
One redaction module covers userinfo, credential query params and MediaMTX streamid forms; a handler filter scrubs relayed lines (ffmpeg stderr) too. rest.py and url.py delegate to it instead of keeping weaker copies.
Written only on successful capture, night sleep or responsive autofocus, and deleted at startup, so a blind or crash-looping engine goes unhealthy instead of keeping a stale file fresh. Healthcheck window 10 min, start_period covers the cold-boot model download. The summary counts the predictor's ongoing verdict so hysteresis-kept events no longer read as a quiet round. Drop the dead tee/engine.log wrapper.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Replaces #392, closed by mistake (GitHub cannot reopen a PR once its branch was deleted).
What changes
pyroengine,pyro_camera_apiandpyro-predictor: only the two entrypoints configure logging, both with the same format, and verbosity is driven by a newLOG_LEVELenv var wired through docker-compose. Library modules no longer calllogging.basicConfig(force=True)at import. Uvicorn lines are routed through the same formatter too, so every line in both containers shares one format.logger.exception, a known down camera is reported once instead of every 30s, and every camera scoped line carries a[cam_id]prefix.Examples
Output below was captured by running the same script on
developand on this branch.One quiet round, 4 poses, nothing detected (every 30s)
Before, 18 lines:
After, 1 line:
The prediction array was printed twice per pose, once by
vision.pyand once byengine.py.Run focus finderprinted on every round even thoughfocus_finder()only acts once an hour.A real detection stays visible
Format now carries the logger name
The camera API used a different format in the same deployment. Both now share one format, and engine logs go to stdout explicitly instead of stderr.
Uvicorn kept its own handlers with
propagate=False, so its lines had no timestamp at all:The per request access line is now DEBUG only, since the engine polls the capture endpoints every few seconds. At
LOG_LEVEL=DEBUGit comes back, in the shared format:Levels
Patrol cycle, 4 poses every 30s
Credentials
Nothing is lost at LOG_LEVEL=DEBUG
Deployment note
The engine healthcheck no longer greps
engine.log. It now checks the freshness of the heartbeat file refreshed by the main loop (option--heartbeat-file, defaultdata/heartbeat). On first start the container is unhealthy until the first loop completes, so bumpstart_periodif your rollout treats unhealthy as fatal.