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.

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

coreos-metadata logging doesn't work under systemd #2290

Closed
bgilbert opened this Issue Dec 14, 2017 · 6 comments

Comments

Projects
None yet
3 participants
@bgilbert
Member

bgilbert commented Dec 14, 2017

Issue Report

Bug

Container Linux Version

$ cat /etc/os-release
NAME="Container Linux by CoreOS"
ID=coreos
VERSION=1618.0.0+2017-12-06-0025
VERSION_ID=1618.0.0
BUILD_ID=2017-12-06-0025
PRETTY_NAME="Container Linux by CoreOS 1618.0.0+2017-12-06-0025 (Ladybug)"
ANSI_COLOR="38;5;75"
HOME_URL="https://coreos.com/"
BUG_REPORT_URL="https://issues.coreos.com"
COREOS_BOARD="amd64-usr"

Environment

Any

Expected Behavior

coreos-metadata log messages are written to the journal.

Actual Behavior

coreos-metadata log messages are not recorded anywhere.

Reproduction Steps

  1. journalctl -u coreos-metadata-sshkeys@core.service

Other Information

When run directly from the command line, coreos-metadata writes logs to stderr. However, systemd sends stderr to the journal by default, and no log messages show up there. Adding StandardError=kmsg to the unit doesn't send log messages to dmesg. Adding strace -f to the ExecStart= line shows no log messages being written to stderr.

@sdemos

This comment has been minimized.

Show comment
Hide comment
@sdemos

sdemos Dec 14, 2017

Member

I believe that regular, info level log messages are printing to stdout, not stderr. I'll do some investigation on the logging library I'm using to make sure that's the case, and make sure it's logging in all situations.

Member

sdemos commented Dec 14, 2017

I believe that regular, info level log messages are printing to stdout, not stderr. I'll do some investigation on the logging library I'm using to make sure that's the case, and make sure it's logging in all situations.

@bgilbert

This comment has been minimized.

Show comment
Hide comment
@bgilbert

bgilbert Dec 14, 2017

Member

In my tests on the command line, info messages go to stderr as well. In any event, systemd should also be capturing stdout.

Member

bgilbert commented Dec 14, 2017

In my tests on the command line, info messages go to stderr as well. In any event, systemd should also be capturing stdout.

@sdemos

This comment has been minimized.

Show comment
Hide comment
@sdemos

sdemos Dec 14, 2017

Member

well that's not what I expected. I've been meaning to update the logging library to print synchronously anyway, and it looks like that will give us some more control over exactly where that gets printed.

I'm still not sure why it isn't logging to the journal though. Perhaps that also has to do with the async logging interacting with systemd running it and redirecting the output? I'm going to explore that possibility.

Member

sdemos commented Dec 14, 2017

well that's not what I expected. I've been meaning to update the logging library to print synchronously anyway, and it looks like that will give us some more control over exactly where that gets printed.

I'm still not sure why it isn't logging to the journal though. Perhaps that also has to do with the async logging interacting with systemd running it and redirecting the output? I'm going to explore that possibility.

@lucab

This comment has been minimized.

Show comment
Hide comment
@lucab

lucab Dec 14, 2017

Member

A cargo update seems to be fixing the issue for me on my local (Debian) machine. However I didn't spot any relevant commit in our dependencies.

This is the list of outdated deps that could be related:

$ cargo outdated -R
Name          Project  Compat   Latest   Kind    Platform
----          -------  ------   ------   ----    --------
base64        0.6.0    ---      0.8.0    Normal  ---
byteorder     1.1.0    1.2.1    1.2.1    Normal  ---
clap          2.27.1   2.29.0   2.29.0   Normal  ---
clippy        0.0.169  0.0.175  0.0.175  Normal  ---
hyper         0.11.6   0.11.9   0.11.9   Normal  ---
openssh-keys  0.2.0    0.2.1    0.2.1    Normal  ---
openssl       0.9.20   0.9.23   0.9.23   Normal  ---
reqwest       0.7.3    ---      0.8.1    Normal  ---
serde         1.0.19   1.0.24   1.0.24   Normal  ---
serde_derive  1.0.19   1.0.24   1.0.24   Normal  ---
serde_json    1.0.5    1.0.8    1.0.8    Normal  ---
slog          2.0.12   2.1.1    2.1.1    Normal  ---
slog-async    2.1.0    2.2.0    2.2.0    Normal  ---
slog-term     2.2.0    2.3.0    2.3.0    Normal  ---
Member

lucab commented Dec 14, 2017

A cargo update seems to be fixing the issue for me on my local (Debian) machine. However I didn't spot any relevant commit in our dependencies.

This is the list of outdated deps that could be related:

$ cargo outdated -R
Name          Project  Compat   Latest   Kind    Platform
----          -------  ------   ------   ----    --------
base64        0.6.0    ---      0.8.0    Normal  ---
byteorder     1.1.0    1.2.1    1.2.1    Normal  ---
clap          2.27.1   2.29.0   2.29.0   Normal  ---
clippy        0.0.169  0.0.175  0.0.175  Normal  ---
hyper         0.11.6   0.11.9   0.11.9   Normal  ---
openssh-keys  0.2.0    0.2.1    0.2.1    Normal  ---
openssl       0.9.20   0.9.23   0.9.23   Normal  ---
reqwest       0.7.3    ---      0.8.1    Normal  ---
serde         1.0.19   1.0.24   1.0.24   Normal  ---
serde_derive  1.0.19   1.0.24   1.0.24   Normal  ---
serde_json    1.0.5    1.0.8    1.0.8    Normal  ---
slog          2.0.12   2.1.1    2.1.1    Normal  ---
slog-async    2.1.0    2.2.0    2.2.0    Normal  ---
slog-term     2.2.0    2.3.0    2.3.0    Normal  ---
@lucab

This comment has been minimized.

Show comment
Hide comment
@lucab

lucab May 16, 2018

Member

This may just be a matter of coreos-metadata writing to stdout/stderr and then being too quick at exiting. Journald in that case loses the systemd/systemd#2913 race and some service metadata are missing. Log line are still visible via sudo journalctl -t coreos-metadata though.
The logs from #2361 (comment) also seems to be only missing error lines, not info messages.

Member

lucab commented May 16, 2018

This may just be a matter of coreos-metadata writing to stdout/stderr and then being too quick at exiting. Journald in that case loses the systemd/systemd#2913 race and some service metadata are missing. Log line are still visible via sudo journalctl -t coreos-metadata though.
The logs from #2361 (comment) also seems to be only missing error lines, not info messages.

@bgilbert

This comment has been minimized.

Show comment
Hide comment
@bgilbert

bgilbert Jul 6, 2018

Member

Looks like this is working in alpha 1828.0.0. Closing.

Member

bgilbert commented Jul 6, 2018

Looks like this is working in alpha 1828.0.0. Closing.

@bgilbert bgilbert closed this Jul 6, 2018

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