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

No crash reason in logs despite roachtest: tpcc/mixed-headroom/n5cpu16 failing due to process exiting with exit code 1 #90483

Closed
joshimhoff opened this issue Oct 21, 2022 · 0 comments · Fixed by #90478
Closed

No crash reason in logs despite roachtest: tpcc/mixed-headroom/n5cpu16 failing due to process exiting with exit code 1 #90483

joshimhoff opened this issue Oct 21, 2022 · 0 comments · Fixed by #90478
Labels
C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior.

Comments

@joshimhoff
Copy link
Collaborator

joshimhoff commented Oct 21, 2022 •
edited
Loading

@renatolabs was debugging a roachtest failure and did the following the discover that the cause of the failure was cockroachdb/pebble#2019:

The logs didn’t include anything indeed, which is why this has been a tough test failure to debug (we need to fix whatever is not right with logging). I instrumented exit.WithCode as suggested in this thread but that led nowhere. To get the stack trace, I compiled cockroach with a patched version of the stdlib that dumps a stack trace on os.Exit, and running the test with that

This indicates a bug of some kind. We do not expect to have a process crash without any info about the crash reason in the logs, if the CRDB process is doing the crashing (as opposed to the OOM killer or similar). With that said, it might be a test-only bug.

Here's a theory: Within a roachtest context but NOT within a production context, we are using the pebble default logger, instead of the CRDB logger. The latter takes care to get a log line in an expected file; the former does not seem to, based on the presence of this bug. See the pebble default logger here: https://github.com/cockroachdb/pebble/blob/bee0c60e96bc1f12308484c9789c10cb4b19f77a/logger.go#L29. Within the context of cockroachdb/pebble#2019, I believe it is called here: https://github.com/cockroachdb/pebble/blob/master/internal/base/filenames.go#L167. Actually, I think the stacktrace given at cockroachdb/pebble#2019 confirms that within the context of the roachtest we are using the pebble default logger: github.com/cockroachdb/pebble/external/com_github_cockroachdb_pebble/logger.go:32 +0x49 is in the stacktrace, and that corresponds to this line in the code: https://github.com/cockroachdb/pebble/blob/bee0c60e96bc1f12308484c9789c10cb4b19f77a/logger.go#L32. With all that said, I am not sure why the pebble default logger fails to get a log line in an expected file pre-crash.

Jira issue: CRDB-20795
@joshimhoff joshimhoff added the C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior. label Oct 21, 2022
This was referenced Oct 21, 2022
Merged
Closed
renatolabs added a commit to renatolabs/cockroach that referenced this issue Oct 21, 2022
@renatolabs
server: write pebble log messages to storage channel
0592cee 
Previously, when setting up the server, the pebble engine would be
initialized with Pebble's default logger. The reason for this is that
the pebble initialization code calls `EnsureDefaults` on the
configuration options _before_ checking if the `options.Logger` is
nil/unset. At that point, it will never be unset, as `EnsureDefaults`
will set the logger to `pebble.DefaultLogger` if it was not previously
set.

This change overwrites the pebble logger if its found to be the
`DefaultLogger`. We never want to use pebble's `DefaultLogger` in CRDB
as that would mean pebble would use the standard library `log`
package, making every message emitted by Pebble to be treated as
`INFO` level messages, regardless of severity (including `log.Fatal`
calls).

Related to cockroachdb#83079.

Fixes cockroachdb#90483.

Release note: None.
craig bot pushed a commit that referenced this issue Oct 25, 2022
@renatolabs @adityamaru
Merge #90478 #90632
847c146 
90478: server: write pebble log messages to storage channel r=knz a=renatolabs

Previously, when setting up the server, the pebble engine would be initialized with Pebble's default logger. The reason for this is that the pebble initialization code calls `EnsureDefaults` on the configuration options _before_ checking if the `options.Logger` is nil/unset. At that point, it will never be unset, as `EnsureDefaults` will set the logger to `pebble.DefaultLogger` if it was not previously set.

This change overwrites the pebble logger if its found to be the `DefaultLogger`. We never want to use pebble's `DefaultLogger` in CRDB as that would mean pebble would use the standard library `log` package, making every message emitted by Pebble to be treated as `INFO` level messages, regardless of severity (including `log.Fatal` calls).

Related to #83079.

Fixes #72683.
Fixes #90483.

Release note: None.

90632: kv/kvserver: skip TestStoreMetrics r=jbowens a=adityamaru

Refs: #90631

Reason: flaky test

Generated by bin/skip-test.

Release justification: non-production code changes

Release note: None

Co-authored-by: Renato Costa <[email protected]>
Co-authored-by: adityamaru <[email protected]>
@craig craig bot closed this as completed in 2b7ac6c Oct 25, 2022
blathers-crl bot pushed a commit that referenced this issue Oct 25, 2022
@renatolabs
server: write pebble log messages to storage channel
3cae346 
Previously, when setting up the server, the pebble engine would be
initialized with Pebble's default logger. The reason for this is that
the pebble initialization code calls `EnsureDefaults` on the
configuration options _before_ checking if the `options.Logger` is
nil/unset. At that point, it will never be unset, as `EnsureDefaults`
will set the logger to `pebble.DefaultLogger` if it was not previously
set.

This change overwrites the pebble logger if its found to be the
`DefaultLogger`. We never want to use pebble's `DefaultLogger` in CRDB
as that would mean pebble would use the standard library `log`
package, making every message emitted by Pebble to be treated as
`INFO` level messages, regardless of severity (including `log.Fatal`
calls).

Related to #83079.

Fixes #72683.
Fixes #90483.

Release note: None.
This was referenced Oct 25, 2022
Merged
Merged
renatolabs added a commit that referenced this issue Oct 26, 2022
@renatolabs
server: write pebble log messages to storage channel
d672a52 
Previously, when setting up the server, the pebble engine would be
initialized with Pebble's default logger. The reason for this is that
the pebble initialization code calls `EnsureDefaults` on the
configuration options _before_ checking if the `options.Logger` is
nil/unset. At that point, it will never be unset, as `EnsureDefaults`
will set the logger to `pebble.DefaultLogger` if it was not previously
set.

This change overwrites the pebble logger if its found to be the
`DefaultLogger`. We never want to use pebble's `DefaultLogger` in CRDB
as that would mean pebble would use the standard library `log`
package, making every message emitted by Pebble to be treated as
`INFO` level messages, regardless of severity (including `log.Fatal`
calls).

Related to #83079.

Fixes #72683.
Fixes #90483.

Release note: None.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior.
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

server: write pebble log messages to storage channel renatolabs/cockroach
1 participant
@joshimhoff