Stop cascading logging errors in the Windows desktop app - #15197
Stop cascading logging errors in the Windows desktop app#15197rtibbles wants to merge 2 commits into
Conversation
github-actions
Bot
added
DEV: backend
🟡 Waiting for changesLast updated: 2026-08-19 04:35 UTC |
Build Artifacts
Smoke test screenshot |
rtibblesbot
left a comment
rtibblesbot
left a comment
There was a problem hiding this comment.
PR #15197 — the four-part diagnosis (contended file → handler error → re-logged through the captured stderr → unbounded queue) holds up against the code, and each fix lands where the cycle closes.
One blocking issue: bounding the queue makes QueueListener.stop() raise queue.Full in exactly the saturated state this PR expects, breaking server shutdown. Rest are suggestions/nitpicks inline.
Verified locally: pytest kolibri/utils/tests (526 passed), pytest platforms/desktop-app/tests/test_streams.py (5 passed), prek run --from-ref upstream/develop --to-ref HEAD clean. CI: no failures, one check still running. No UI files changed, so visual verification does not apply.
@rtibblesbot's comments are generated by an LLM, and should be evaluated accordingly
How was this generated?
Ran a phased review pipeline over the pull request diff:
- Classified the diff to select review passes (core, frontend, backend) and whether manual QA was required
- Core review pass checked correctness, design, architecture, testing, completeness, and DRY/SRP/Rule-of-Three principles
- Specialized frontend/backend review passes applied framework-specific lenses where those files changed
- For UI changes: manual QA and an accessibility audit against a live dev server, when available
- Checked CI status and linked issue acceptance criteria
- Synthesized one review from those passes and chose the verdict from the findings, CI status, and QA evidence
| Returns the queue listener which can be used to stop logging and clean up. | ||
| """ | ||
| log_queue = Queue() | ||
| log_queue = Queue(maxsize=LOG_QUEUE_MAX_SIZE) |
There was a problem hiding this comment.
✅ Resolved — addressed in the current code.
blocking: listener.stop() raises queue.Full on a saturated queue.
QueueListener.stop() calls enqueue_sentinel() → self.queue.put_nowait(self._sentinel). On a full bounded queue that raises; unbounded it never could. Reproduced on this branch (slow handler, maxsize=3, 20 records): stop() raised: Full.
Chain: LogPlugin.EXITED → cleanup_queue_logging → listener.stop() raises → magicbus publish() re-raises it as ChannelFailures at the end of the transition, which ProcessBus.exit() does not catch. The Windows server subprocess dies with a traceback instead of exiting, and self._thread stays set so the listener is never joined. The queue is full exactly in the log-storm case this PR exists for.
One override alongside handle on LoggerAwareQueueListener fixes it:
def enqueue_sentinel(self):
# Blocking put: the bounded queue must not make shutdown fail.
self.queue.put(self._sentinel)| DO_ROLLOVER = "doRollover" | ||
|
|
||
| NO_FILE_BASED_LOGGING = os.environ.get("KOLIBRI_NO_FILE_BASED_LOGGING", False) | ||
| LOG_QUEUE_MAX_SIZE = int(os.environ.get("KOLIBRI_LOG_QUEUE_MAX_SIZE", 10000)) |
There was a problem hiding this comment.
✅ Resolved — addressed in the current code.
suggestion: KOLIBRI_LOG_QUEUE_MAX_SIZE=0 silently restores the unbounded queue — Queue(maxsize) treats any value <= 0 as infinite, and someone reading env.py's "records are dropped" could set 0 to mean "don't queue".
A non-integer value is worse: int(...) raises at import of kolibri.utils.logger, one of the earliest modules loaded, so a typo becomes an uncatchable startup traceback that never names the variable. Consider clamping to a floor and falling back to the default on a parse failure.
| record._logger_name = self.logger_name | ||
| return record | ||
|
|
||
| def enqueue(self, record: logging.LogRecord) -> None: |
There was a problem hiding this comment.
suggestion: Dropped records leave no trace. Together with log.raiseExceptions = False in the desktop app, a log with a hole in it is indistinguishable from a quiet one — when the next report of this bug arrives, nothing in kolibri.txt will say records were lost.
The listener thread is outside the reentrant path, so a counter incremented here and reported from there (on drain, or at cleanup_queue_logging) would not reopen the cycle.
| super().doRollover() | ||
| try: | ||
| super().doRollover() | ||
| except OSError: |
There was a problem hiding this comment.
suggestion: The guard is both wider and narrower than the failure it documents.
Wider: except OSError also swallows ENOSPC, a logs/ directory that lost write permission, and a deleted KOLIBRI_HOME/logs — on every platform. All take the same path: postpone, log nothing, retry tomorrow, forever. getFilesToDelete only runs on the success path, so a permanently failing rotation also stops backupCount pruning: kolibri.txt grows unbounded and the archive stops advancing, silently. Before this branch the failure was noisy; after it, invisible.
Narrower: the archive work below (os.mkdir(self.archive_dir), os.rename in _rotation_files) touches the same directory under the same Windows lock and is unguarded. An OSError there reaches handleError — bounded, since rolloverAt has advanced — but leaves an unarchived kolibri-app.txt.YYYY-MM-DD in logs/ that getFilesToDelete (archive-only) never prunes. The mkdir is also now a two-process race, since the UI process and server subprocess write siblings into the same directory.
Narrowing the catch is not obviously right (PermissionError is the Windows case, but ENOSPC would then crash emit). The question is the discovery path for a rotation that never succeeds again — a postponed_rollovers counter on the handler would cost little and is outside the reentrant path.
| # at logging below. Once the report is queued rather than written inline, the | ||
| # LoggerWriter guard cannot see the cycle, and a persistently failing handler | ||
| # feeds itself for as long as the app runs (learningequality/kolibri#15150). | ||
| log.raiseExceptions = False |
There was a problem hiding this comment.
✅ Resolved — addressed in the current code.
suggestion: logging.raiseExceptions is module state, so importing kolibri_app.logger silences handleError for every handler in the process — including Kolibri core's file and console-error handlers and LoggerAwareQueueListener.handle's own handler.handleError(record). I agree the queued-report cycle can't be broken by the LoggerWriter guard alone, but a reader of kolibri/utils/logger.py has no way to know this was flipped.
What is the intended path for diagnosing a genuinely broken handler afterwards — KOLIBRI_NO_FILE_BASED_LOGGING, or something else? Worth naming in the comment, since the answer is no longer "look at stderr".
| """ | ||
| # The failed rollover closed the stream; FileHandler.emit reopens it. | ||
| current_time = int(time.time()) | ||
| rollover_at = self.computeRollover(current_time) |
There was a problem hiding this comment.
nitpick: This reproduces TimedRotatingFileHandler.doRollover's tail but not the DST correction. On 3.11+ computeRollover folds the adjustment in itself; on 3.6–3.10 dstAtRollover/addend live in doRollover, and the stdlib adds ±3600 for when='midnight' with utc=False — exactly the config get_logging_config uses. Costs one rotation landing at 23:00 or 01:00, twice a year, only after a rollover already failed. CI covers 3.8/3.9, so it is live rather than theoretical.
| listener = setup_queue_logging() | ||
| self.addCleanup(listener.stop) | ||
|
|
||
| self.assertEqual(listener.queue.maxsize, LOG_QUEUE_MAX_SIZE) |
There was a problem hiding this comment.
✅ Resolved — addressed in the current code.
nitpick: With _replace_handlers_with_queue mocked out this reduces to Queue(maxsize=LOG_QUEUE_MAX_SIZE).maxsize == LOG_QUEUE_MAX_SIZE — it catches only literal removal of the maxsize= kwarg. The sibling test_full_queue_drops_records_silently covers the behaviour that matters.
Also: neither test in QueueLoggingTestCase touches a model, setting or URL, so extending django.test.TestCase wraps each in a transaction for nothing. Per AGENTS.md, plain pytest functions fit here.
| written.append(line) | ||
| # Bounded so an unguarded writer fails the assertion below rather | ||
| # than recursing until the test runner gives up. | ||
| if len(written) < 100: |
There was a problem hiding this comment.
✅ Resolved — addressed in the current code.
praise: Bounding the recursive writer means an unguarded LoggerWriter gives a clean assertion failure rather than a RecursionError or a wedged runner.
Windows will not rename a log file a second process still holds open. The failed rollover left rolloverAt in the past, so every subsequent record retried the rename, and each retry's own error report fed back in as more records. Postpone the next attempt instead, and bound the log queue so a listener that cannot drain stops growing it. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01KXc8oMzGTawizmmAuxeJfg
The UI process and the server subprocess shared kolibri-app.txt, so at midnight one of them could never rotate it. Give the server its own file, and stop logging's handler-error reports from re-entering logging through the stdout/stderr redirect the app installs, both when they recurse in-thread and when the queue carries them across threads. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01KXc8oMzGTawizmmAuxeJfg
dfb4c61 to
76d7c0f
Compare
rtibblesbot
left a comment
rtibblesbot
left a comment
There was a problem hiding this comment.
PR #15197 — 5 of 8 prior findings resolved; 3 open, none new. CI passing.
- suggestion logger.py:66 — silent drops.
- suggestion logger.py:187 — rollover failure undiscoverable.
- nitpick logger.py:212 — no DST correction.
Prior-finding status
RESOLVED — kolibri/utils/logger.py:470 — stop() raises Full
RESOLVED — kolibri/utils/logger.py:17 — KOLIBRI_LOG_QUEUE_MAX_SIZE=0
RESOLVED — platforms/desktop-app/src/kolibri_app/logger.py:20 — raiseExceptions global
RESOLVED — kolibri/utils/tests/test_handler.py:120 — kwarg assertion
UNADDRESSED — kolibri/utils/logger.py:66 — silent drops
UNADDRESSED — kolibri/utils/logger.py:187 — rollover undiscoverable
UNADDRESSED — kolibri/utils/logger.py:212 — DST correction
ACKNOWLEDGED — platforms/desktop-app/tests/test_streams.py:50 — bounded writer
@rtibblesbot's comments are generated by an LLM, and should be evaluated accordingly
How was this generated?
Ran an automatic code-only delta review triggered by new commits on a previously reviewed PR:
- Retrieved prior bot reviews via the GitHub API
- Classified each prior finding as RESOLVED, UNADDRESSED, ACKNOWLEDGED, or CONTESTED
- Only raised NEW findings for newly introduced code
- Core review pass only — specialized frontend/backend lenses and manual QA run when a review is explicitly requested
- Synthesized one review from the passes and chose the verdict from the findings, CI status, and QA evidence
2 participants
Summary
Fixed by:
References
Fixes #15150
Reviewer guidance
kolibri-app-server.txtinC:\ProgramData\kolibri\logskolibri-app.txtalongside itNoting that the thing that seemed to set off the error in @pcenov's case was an error from a scheduled task - so running a background task might be sufficient to trigger this.
I have not tested on Windows.
AI usage
Used Claude Code to write the fix and its tests, then to review the resulting diff — that pass caught the Windows smoke test still looking for the renamed log file, and two guards that only closed the in-thread half of the loop. Verified with the
kolibri/utilsand desktop-app test suites, prek, and a local review pass over the diff.