oxidecomputer / oxidecomputer/omicron
Logging configuration and overflow
Nobody has claimed this yet.
- Dominant language
- Rust
- Stars
- 572
- Forks
- 97
- Avg merge
- 2d 12h
- Merged PRs (30d)
- 96
Description
This grew out of #971, which was a specific instance of noticing errors like this while running tests:
Apr 25 02:00:39.762 ERRO slog-async: logger dropped messages due to channel overflow, count: 171, producer_id: a6458b7d-87c3-4483-be96-854d814c20de, component: collection-task, collector_id: 39e6175b-4df2-4730-b11d-cbc1e60a2e78, component: oximeter-agent
The root cause of that - an erroneously spammy logger - has been fixed, but it brought up the question of our logging configuration. @davepacheco asked three questions on that issue, which I'll repeat here:
- We probably should be using synchronous logging everywhere? I think we want to throttle activity rather than lose messages.
- If they should be async, yeah, we should increase the channel size.
- Why are we producing so many log messages?
The final question was answered in the case above, but the first two apply to logging generally. We currently configure three loggers directly in omicron, the latter two of which are command-line utilties and less relevant (or perhaps completely irrelevant):
I believe (but please correct me if I'm wrong!) all remaining services rely on dropshot's logging initialiation, which is very similar.
All of these use slog_async::Async::new() with default settings. It's probably worth spelling out slog_async's behavior, particularly because its docs note that it should be considered "a reasonable reference implementation" and lightly encourages using it as a starting point to create one's own async drain. None of this is surprising given the content of the errors logged above, but the default behavior/configuration as of 2.7.0 is:
- A bounded crossbeam channel is created with size 128
- An unnamed thread is spawned to receive messages from that channel and send them to the inner drain
- An
AyncCoreis created; it holds the sending half of the channel and is configured to not block - The
AsyncCoreis held by theAsyncwe use; it is configured to count dropped log messages - When we log a message:
a. If theAsynchas a nonzero count of previously-dropped log messages, it (attempts to) emit the error log we see above; the channel still being full here is not considered an error, but it is counted as another dropped log
b. AnAsyncRecordis created andtry_sendis used to send it to the logging thread, which fails immediately if the channel is full
c. If thetry_sendfails, the previously-dropped log messages count is incremented
Dropping log messages under load is almost certainly not the behavior we want (as noted by Dave above). A relatively easy change to make would be to configure the drain with OverflowStrategy::Block, which would change the try_send in step 5b above to a blocking send, which would apply backpressure on the logger(s) if the logging thread is unable to keep up. I'm not sure how we would want to test this (and/or decide if 128 is a reasonable channel size for any given service); it would also require changing dropshot to either set OverflowStrategy::Block or expose more logging configuration options.
Side note - none of our logging setups use an AsyncGuard to flush logs when exiting. Should they?
Contributor guide
First steps
- Read the whole issue, then the project's contributing guide.
- Comment on the issue to say you are picking it up — it saves two people doing the same work.
- Fork the repository and make your change on a branch.
- Open a pull request that references the issue number.
Research direction
Start by comparing the logger setup in oximeter/db/src/bin/oxdb.rs, gateway-cli/src/main.rs, and internal-dns/src/bin/dnsadm.rs with dropshot/src/logging.rs. Read the referenced slog_async behavior and determine the desired overflow, channel-size, and shutdown-flush policies. Done means the project has an agreed configuration approach, appropriate tests, and consistent handling across the relevant services.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- rust
- Domain
- observability
- Issue type
- Feature
- Difficulty
- 5/5
- Estimated time
- Over a week
- Activity status
- Quiet
- Clarity
- Needs clarification
- Newbie friendliness
- 35/100