Skip to content

fix(observe): unify daemon logs through single channel - #605

Open
mccormickt wants to merge 2 commits into
aurae-runtime:mainfrom
mccormickt:push-wzqwsnpsqxxx
Open

mccormickt wants to merge 2 commits into
aurae-runtime:mainfrom
mccormickt:push-wzqwsnpsqxxx

Conversation

@mccormickt

Copy link
Copy Markdown
Contributor

This PR unifies auraed's logging patterns through a single LogChannel, leveraging tracing_subscriber::MakeWriter and a new BroadcastWriter struct to properly broadcast log messages to all subscribers.

Before this change, aer observe get-aurae-daemon-log-stream would never display logs.

Now:

» aer observe get-aurae-daemon-log-stream
Streaming
GetAuraeDaemonLogStreamResponse {
    item: Some(
        LogItem {
            channel: "auraed",
            line: "{\"timestamp\":\"2026-09-12T12:53:56.653520Z\",\"level\":\"INFO\",\"fields\":{\"message\":\"Nested auraed running with host pid 3858842\"},\"target\":\"auraed::cells::cell_service::cells::nested_auraed::nested_auraed\",\"span\":{\"request\":\"ValidatedCellServiceAllocateRequest { cell: ValidatedCell { name: CellName(\\\"test\\\"), cpu: Some(ValidatedCpuController { weight: None, max: None, period: None }), cpuset: Some(ValidatedCpusetController { cpus: None, mems: None }), memory: Some(ValidatedMemoryController { min: None, low: None, high: None, max: None }), isolate_process: false, isolate_network: false } }\",\"name\":\"allocate\"},\"spans\":[{\"request\":\"ValidatedCellServiceAllocateRequest { cell: ValidatedCell { name: CellName(\\\"test\\\"), cpu: Some(ValidatedCpuController { weight: None, max: None, period: None }), cpuset: Some(ValidatedCpusetController { cpus: None, mems: None }), memory: Some(ValidatedMemoryController { min: None, low: None, high: None, max: None }), isolate_process: false, isolate_network: false } }\",\"name\":\"allocate\"}]}",
            timestamp: 1789217636,
        },
    ),
}
GetAuraeDaemonLogStreamResponse {
    item: Some(
        LogItem {
            channel: "auraed",
            line: "{\"timestamp\":\"2026-09-12T12:53:56.664483Z\",\"level\":\"INFO\",\"fields\":{\"message\":\"Attach nested Auraed pid 3858842 to cgroup test\"},\"target\":\"auraed::cells::cell_service::cells::cell\",\"span\":{\"request\":\"ValidatedCellServiceAllocateRequest { cell: ValidatedCell { name: CellName(\\\"test\\\"), cpu: Some(ValidatedCpuController { weight: None, max: None, period: None }), cpuset: Some(ValidatedCpusetController { cpus: None, mems: None }), memory: Some(ValidatedMemoryController { min: None, low: None, high: None, max: None }), isolate_process: false, isolate_network: false } }\",\"name\":\"allocate\"},\"spans\":[{\"request\":\"ValidatedCellServiceAllocateRequest { cell: ValidatedCell { name: CellName(\\\"test\\\"), cpu: Some(ValidatedCpuController { weight: None, max: None, period: None }), cpuset: Some(ValidatedCpusetController { cpus: None, mems: None }), memory: Some(ValidatedMemoryController { min: None, low: None, high: None, max: None }), isolate_process: false, isolate_network: false } }\",\"name\":\"allocate\"}]}",
            timestamp: 1789217636,
        },
    ),
}
GetAuraeDaemonLogStreamResponse {
    item: Some(
        LogItem {
            channel: "auraed",
            line: "{\"timestamp\":\"2026-09-12T13:06:31.753030Z\",\"level\":\"INFO\",\"fields\":{\"message\":\"CellService: free() cell_name=CellName(\\\"test\\\")\"},\"target\":\"auraed::cells::cell_service::cell_service\",\"span\":{\"request\":\"ValidatedCellServiceFreeRequest { cell_name: CellName(\\\"test\\\") }\",\"name\":\"free\"},\"spans\":[{\"request\":\"Request { metadata: MetadataMap { headers: {\\\"te\\\": \\\"trailers\\\", \\\"content-type\\\": \\\"application/grpc\\\", \\\"user-agent\\\": \\\"tonic/0.14.2\\\"} }, message: CellServiceFreeRequest { cell_name: \\\"test\\\" }, extensions: Extensions }\",\"name\":\"free\"},{\"request\":\"ValidatedCellServiceFreeRequest { cell_name: CellName(\\\"test\\\") }\",\"name\":\"free\"}]}",
            timestamp: 1789218391,
        },
    ),
}

We also now properly handle shutdown of log forwarders, so an ObserveService client does not prevent auraed from exiting and shuts down properly.

Comment thread auraed/src/ebpf/perf_buffer_reader.rs Outdated

// Clear cached readiness after draining the buffer so the
// next call to `readable_mut` waits for more events.
if events.read == 0 {

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.

part of a different change?

@mccormickt mccormickt Sep 12, 2026 •

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

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

Happy to split it out if you'd like, but this was another fix that I encountered and is required for this change to work as well. I missed this in #601, and not clearing readiness caused the Tokio worker pool to be consumed by log reader tasks. This would block any gRPC startup tasks from making progress and caused a livelock.

Comment thread auraed/src/init/logging.rs
dmah42
dmah42 previously approved these changes Sep 12, 2026
Auraed polls each per-CPU eBPF perf buffer through Tokio AsyncFd. After a buffer became readable, the reader drained it but left AsyncFd readiness cached. Empty reads then completed immediately and the reader tasks consumed the Tokio worker pool. This prevented gRPC startup, cell requests, and signal handling from making progress.

Clear readiness after an empty read so the task waits for the next kernel notification. Keep readiness set after a non-empty read so busy buffers continue draining.
Use one LogChannel for the tracing subscriber and ObserveService. Stop log forwarders during graceful shutdown.

This branch has not been deployed

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

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants