oxidecomputer / oxidecomputer/omicron

Logging configuration and overflow

Open
#1,014 3 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

Debugging
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:

  1. A bounded crossbeam channel is created with size 128
  2. An unnamed thread is spawned to receive messages from that channel and send them to the inner drain
  3. An AyncCore is created; it holds the sending half of the channel and is configured to not block
  4. The AsyncCore is held by the Async we use; it is configured to count dropped log messages
  5. When we log a message:
    a. If the Async has 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. An AsyncRecord is created and try_send is used to send it to the logging thread, which fails immediately if the channel is full
    c. If the try_send fails, 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

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. 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

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.