Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

pkg/util/log: flush buffered log sinks on shutdown/panic #106345

Closed
abarganier opened this issue Jul 6, 2023 · 0 comments · Fixed by #108928 or #109186
Closed

pkg/util/log: flush buffered log sinks on shutdown/panic #106345

abarganier opened this issue Jul 6, 2023 · 0 comments · Fixed by #108928 or #109186
Assignees
@abarganier
Labels
A-observability-inf C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior. db-cy-23

Comments

@abarganier
Copy link
Contributor

abarganier commented Jul 6, 2023 •
edited by cockroach-jira-scripts
Loading

Describe the problem

Currently, when a cockroach process shuts down, we buffered file log sinks, but we don't flush the buffered network sinks (e.g. fluent-servers, http-servers). This is not only annoying when it comes to missing log lines on shutdown, but even worse, panic logs may not make it to their destination, leaving a gap in observability.

We tried to make this flush happen in the past, but ended up introducing a bug (1629e11, 69a6a8f) because the forceSync output option used by the buffered sink has a high probability of triggering a panic, which can leave the mutex used in the buffered log sink code locked.

We need to find the right solution to close this observability gap for network logging.

Expected behavior
All logs on shutdown/panic handling should be flushed, including those in buffered network sinks.

Jira issue: CRDB-29518
@abarganier abarganier added C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior. T-observability-inf labels Jul 6, 2023
This was referenced Aug 17, 2023
Merged
Merged
@craig craig bot closed this as completed in 598b463 Aug 24, 2023
craig bot pushed a commit that referenced this issue Aug 28, 2023
@abarganier @erikgrinaker @nvanbenschoten
Merge #109186 #109578 #109610
6a31120 
109186: pkg/util/log: flush buffered network sinks on panic r=knz a=abarganier

Previously, our crash reporter system would flush file log sinks
as part of the process to handle a panic.

This was an incomplete process, since buffered network sinks were
not included in part of this flush process. This means that many
times, panic logs would not make it to the network target, leading
to a loss in observability.

This patch introduces `log.FlushAllSync()`, which flushes both file
and buffered network log sinks. It then updates the crash reporter
to call into this, instead of just flushing file log sinks.

`FlushAllSync()` contains timeout logic to prevent the process from
completing if one of the underlying child sinks that a bufferedSink
wraps becomes unavailable/hangs on its `output()` call.

We originally attempted to fix this in #101562, but a bug in the 
bufferedSink code led us to roll back those changes. The bug in the 
bufferedSink code has since been fixed (#108928), so we can safely 
introduce this logic again.

Release note: none

Fixes: #106345

109578: rpc: increase gRPC server timeout from 1x to 2x NetworkTimeout r=andrewbaptist a=erikgrinaker

This is intended as a conservative backport that changes as little as possible. For 23.2, we should restructure these settings a bit, possibly by removing NetworkTimeout and using independent timeouts for each component/parameter, since they have unique considerations (e.g. whether they are enforced above the Go runtime or by the OS, to what extent they are subject to RPC head-of-line blocking, etc).

---

This patch increases the gRPC server timeout from 1x to 2x NetworkTimeout. This timeout determines how long the server will wait for a TCP send to receive a TCP ack before automatically closing the connection. gRPC enforces this via the OS TCP stack by setting TCP_USER_TIMEOUT on the network socket.

While NetworkTimeout should be sufficient here, we have seen instances where this is affected by node load or other factors, so we set it to 2x NetworkTimeout to avoid spurious closed connections. An aggressive timeout is not particularly beneficial here, because the client-side timeout (in our case the CRDB RPC heartbeat) is what matters for recovery time following network or node outages -- the server side doesn't really care if the connection remains open for a bit longer.

Touches #109317.

Epic: none
Release note (ops change): The default gRPC server-side send timeout has been increased from 2 seconds to 4 seconds (1x to 2x of COCKROACH_NETWORK_TIMEOUT), to avoid spurious connection failures in certain scenarios. This can be controlled via the new environment variable COCKROACH_RPC_SERVER_TIMEOUT.

109610: kv: remove assertions around non-txn'al locking reqs r=nvanbenschoten a=nvanbenschoten

Closes #107860.
Closes #109222.
Closes #109581.
Closes #109582.

We might want to re-introduce these assertions in the future and reject these requests higher up the stack. For now, just remove them to deflake tests.

Release note: None

Co-authored-by: Alex Barganier <[email protected]>
Co-authored-by: Erik Grinaker <[email protected]>
Co-authored-by: Nathan VanBenschoten <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@abarganier abarganier

Labels
A-observability-inf C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior. db-cy-23
Projects
None yet
Milestone
No milestone
2 participants
@dhartunian @abarganier