Skip to content

fix(log): make console sink non-blocking to avoid event-loop stalls - #10140

Open
biao-1010 wants to merge 1 commit into
AstrBotDevs:masterfrom
biao-1010:fix/console-sink-blocking
Open

biao-1010 wants to merge 1 commit into
AstrBotDevs:masterfrom
biao-1010:fix/console-sink-blocking

Conversation

@biao-1010

@biao-1010 biao-1010 commented Sep 19, 2026

Copy link
Copy Markdown

Problem

The console loguru sink writes to sys.stdout synchronously on the event loop
thread
. The file sink and the trace sink both pass enqueue=True, but the
console sink does not:

# astrbot/core/log.py  (_setup_loguru)
cls._console_sink_id = _loguru.add(
    sys.stdout,
    level="DEBUG",
    colorize=True,
    # <-- missing enqueue=True
    ...
)

When the console blocks (Windows QuickEdit with text selected, a stalled
terminal, a full pipe), write() blocks, and with it the whole asyncio event
loop
.

Evidence

On a Windows deployment, logs/event_loop_watchdog.log captured thread stacks
showing the main thread stuck at:

astrbot/core/log.py:140  emit
  -> loguru._handler.emit
  -> loguru._simple_sinks.py:16  write
    -> self._stream.write(message)

for 32.938s and 34.828s. The lag monitor separately reported
Event loop lag detected: 201.203s (threshold 15.000s).

During that window the platform websocket heartbeat could not be sent
(ClientConnectionResetError: Cannot write to closing transport), so the bot
lost its connection for roughly five minutes.

Fix

Add enqueue=True to both console sink registrations, so the console sink
behaves like the file and trace sinks. Logging then goes through loguru's
background queue and a blocking console can no longer stall the event loop.

Notes

  • Output format, level and colour are unchanged.
  • Same trade-off as the existing file sink: on a hard crash the very last
    queued lines may be lost.
  • Tested on Windows 11 with AstrBot 4.28.1: restart clean, logs still written
    to file, no errors.

Summary by Sourcery

Bug Fixes:

  • Prevent blocking console writes from stalling the asyncio event loop and disrupting long-lived websocket connections.

The console loguru sink wrote to sys.stdout synchronously on the event loop
thread. A blocking console (Windows QuickEdit with text selected, stalled
terminal, full pipe) therefore stalled the whole asyncio loop. Observed
stalls of 33s/35s in event_loop_watchdog.log, which killed the websocket
heartbeat and dropped the platform connection.

File/trace sinks already used enqueue=True; the console sink did not.

@sourcery-ai sourcery-ai Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hey - I've found 1 issue

Prompt for AI Agents
Please address the comments from this code review:

## Individual Comments

### Comment 1
<location path="astrbot/core/log.py" line_range="517" />
<code_context>
                         sys.stdout,
                         level=configured_level,
                         colorize=True,
+                        enqueue=True,  # NOTE(n100): non-blocking, see above
                         filter=lambda record: (
                             not record["extra"].get("is_trace", False)
</code_context>
<issue_to_address>
**issue (bug_risk):** When `configure_logger()` replaces the console sink while its background worker is blocked in `sys.stdout.write()`, `_loguru.remove(cls._console_sink_id)` waits for that queued sink thread to finish. Because `configure_logger()` runs on the event-loop thread, logger reconfiguration still stalls the event loop until the console becomes writable.

**Triggers:** When the log level is reconfigured while the console output is blocked.

**Suggested fix:** Perform sink replacement outside the event-loop thread, or update the sink without synchronously joining a blocked enqueue worker.

```suggestion
                        enqueue=False,  # Avoid joining a blocked worker during reconfiguration
```
</issue_to_address>

Sourcery assessment

Approval pending. 1 finding to address first.

Blocking findings: astrbot/core/log.py:517


Sourcery is free for open source - if you like our reviews please consider sharing them ✨

Comment thread astrbot/core/log.py
sys.stdout,
level=configured_level,
colorize=True,
enqueue=True, # NOTE(n100): non-blocking, see above

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

issue (bug_risk): When configure_logger() replaces the console sink while its background worker is blocked in sys.stdout.write(), _loguru.remove(cls._console_sink_id) waits for that queued sink thread to finish. Because configure_logger() runs on the event-loop thread, logger reconfiguration still stalls the event loop until the console becomes writable.

Triggers: When the log level is reconfigured while the console output is blocked.

Suggested fix: Perform sink replacement outside the event-loop thread, or update the sink without synchronously joining a blocked enqueue worker.

Suggested change
enqueue=True, # NOTE(n100): non-blocking, see above
enqueue=False, # Avoid joining a blocked worker during reconfiguration

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant