Add journald tag as SYSLOG_IDENTIFIER #35570

zemanlx · Nov 22, 2017

- What I did
This PR fixes #30023 (not showing journald tag in basic journalctl output).
See example below.

Run container with logging driver journald with option tag:

docker run --log-driver=journald --log-opt tag="{{.ImageName}}/{{.Name}}/{{.ID}}" --rm alpine ping -c 1 8.8.8.8

Currently, logs are sent to journald without setting tag to SYSLOG_IDENTIFIER which causing that user inspecting logs from cli using journalctl is not able to assign log record to container/tag. All logs are shown as dockerd messages.

Nov 21 14:58:05 DB0275 kernel: docker0: port 3(vethd3b8cf9) entered blocking state
Nov 21 14:58:05 DB0275 kernel: docker0: port 3(vethd3b8cf9) entered disabled state
Nov 21 14:58:05 DB0275 kernel: device vethd3b8cf9 entered promiscuous mode
Nov 21 14:58:05 DB0275 kernel: IPv6: ADDRCONF(NETDEV_UP): vethd3b8cf9: link is not ready
Nov 21 14:58:05 DB0275 dockerd[1616]: time="2017-11-21T14:58:05.717108935Z" level=info msg="No non-localhost DNS nameservers are left in resolv.conf. Using default external servers: [nameserver 8.8.8.8 nameserver 8.8.4.4]"
Nov 21 14:58:05 DB0275 dockerd[1616]: time="2017-11-21T14:58:05.717126983Z" level=info msg="IPv6 enabled; Adding default IPv6 external servers: [nameserver 2001:4860:4860::8888 nameserver 2001:4860:4860::8844]"
Nov 21 14:58:05 DB0275 kernel: IPVS: Creating netns size=2168 id=693
Nov 21 14:58:05 DB0275 kernel: eth0: renamed from vethe369a76
Nov 21 14:58:05 DB0275 kernel: IPv6: ADDRCONF(NETDEV_CHANGE): vethd3b8cf9: link becomes ready
Nov 21 14:58:05 DB0275 kernel: docker0: port 3(vethd3b8cf9) entered blocking state
Nov 21 14:58:05 DB0275 kernel: docker0: port 3(vethd3b8cf9) entered forwarding state
Nov 21 14:58:06 DB0275 dockerd[1616]: PING 8.8.8.8 (8.8.8.8): 56 data bytes
Nov 21 14:58:06 DB0275 dockerd[1616]: 64 bytes from 8.8.8.8: seq=0 ttl=58 time=5.034 ms
Nov 21 14:58:06 DB0275 dockerd[1616]:
Nov 21 14:58:06 DB0275 dockerd[1616]: --- 8.8.8.8 ping statistics ---
Nov 21 14:58:06 DB0275 dockerd[1616]: 1 packets transmitted, 1 packets received, 0% packet loss
Nov 21 14:58:06 DB0275 dockerd[1616]: round-trip min/avg/max = 5.034/5.034/5.034 ms
Nov 21 14:58:06 DB0275 kernel: docker0: port 3(vethd3b8cf9) entered disabled state
Nov 21 14:58:06 DB0275 kernel: vethe369a76: renamed from eth0
Nov 21 14:58:06 DB0275 kernel: docker0: port 3(vethd3b8cf9) entered disabled state
Nov 21 14:58:06 DB0275 kernel: device vethd3b8cf9 left promiscuous mode
Nov 21 14:58:06 DB0275 kernel: docker0: port 3(vethd3b8cf9) entered disabled state

Adding tag also to SYSLOG_IDENTIFIER enable a user to see it in journalctl and use --identifier with pattern matching. Useful if tag contains swarm stack name, service name, task, etc. It will also do not confuse a user which reads documentation about tags.

Nov 21 14:54:27 cec571b26922 kernel: docker0: port 1(vetha146757) entered blocking state
Nov 21 14:54:27 cec571b26922 kernel: docker0: port 1(vetha146757) entered disabled state
Nov 21 14:54:27 cec571b26922 kernel: device vetha146757 entered promiscuous mode
Nov 21 14:54:27 cec571b26922 kernel: IPVS: Creating netns size=2168 id=692
Nov 21 14:54:27 cec571b26922 kernel: eth0: renamed from veth9334d15
Nov 21 14:54:27 cec571b26922 kernel: docker0: port 1(vetha146757) entered blocking state
Nov 21 14:54:27 cec571b26922 kernel: docker0: port 1(vetha146757) entered forwarding state
Nov 21 14:54:27 cec571b26922 alpine/naughty_dijkstra/bf037aee4dcf[217]: PING 8.8.8.8 (8.8.8.8): 56 data bytes
Nov 21 14:54:27 cec571b26922 alpine/naughty_dijkstra/bf037aee4dcf[217]: 64 bytes from 8.8.8.8: seq=0 ttl=57 time=5.079 ms
Nov 21 14:54:27 cec571b26922 alpine/naughty_dijkstra/bf037aee4dcf[217]:
Nov 21 14:54:27 cec571b26922 alpine/naughty_dijkstra/bf037aee4dcf[217]: --- 8.8.8.8 ping statistics ---
Nov 21 14:54:27 cec571b26922 alpine/naughty_dijkstra/bf037aee4dcf[217]: 1 packets transmitted, 1 packets received, 0% packet loss
Nov 21 14:54:27 cec571b26922 alpine/naughty_dijkstra/bf037aee4dcf[217]: round-trip min/avg/max = 5.079/5.079/5.079 ms
Nov 21 14:54:27 cec571b26922 kernel: docker0: port 1(vetha146757) entered disabled state
Nov 21 14:54:27 cec571b26922 kernel: veth9334d15: renamed from eth0
Nov 21 14:54:27 cec571b26922 kernel: docker0: port 1(vetha146757) entered disabled state
Nov 21 14:54:27 cec571b26922 kernel: device vetha146757 left promiscuous mode
Nov 21 14:54:27 cec571b26922 kernel: docker0: port 1(vetha146757) entered disabled state

- How I did it
Added logging driver option tag not only as CONTAINER_TAG (visible only in extended view, which is not usable for practical troubleshooting) but also as SYSLOG_IDENTIFIER which support pattern matching.

- How to verify it

See what I did

- Description for the changelog

Add journald tag as SYSLOG_IDENTIFIER

- A picture of a cute animal (not mandatory but encouraged)

http://clipart-library.com/clipart/LTd5bk6pc.htm

Signed-off-by: Vlastimil Zeman <vlastimil.zeman@diffblue.com>

boaz0 · Nov 22, 2017

/cc @thaJeztah @bobrik @zarnovican @stevvooe

thaJeztah · Nov 22, 2017

Thanks for contributing! While this seems like a good addition, I'd like to discuss this a bit more before we go ahead, and get input from more people. Changing the format could be a breaking change for people that consume the logs, so we should be careful to enable this by default.

An alternative could be to have a separate option to set the identifier (e.g. --identifier={{.ImageName}}/{{.Name}}/{{.ID}}), and/or an option to enable this functionality (--set-identifier).

Open to input/suggestions on this 👍

zemanlx · Nov 22, 2017

@thaJeztah Thanks for quick response!
Re --identifier:

Right now log that you can see in journalctl are almost useless as you do not know to which container it belongs to so IMHO there is no reasonable/useful way to base filtering on that data. If somebody did some filtering it has to be based on extended/json format where you can see CONTAINER_TAG and that stays the same.
identifier is an alias for tag according documentation so adding --identifier can lead to more confusion from user perspective.

PS I am not against --set-identifier, I will take anything that can solve my problem 😉

thaJeztah · Nov 30, 2017

Discussing in the maintainers meeting, and generally, we think it's ok to make this change, but I'm checking with some other people to be sure about the change in output format 👍

thaJeztah · Nov 30, 2017

One issue is being raised that the identifier in journald was added for compatibility with syslog, which takes a specific format, in which case it would contain application name, process-id and message-id; so wondering if that should be taken into account

zemanlx · Dec 5, 2017

@thaJeztah Thanks for carrying this forward!
Do you mean that SYSLOG_IDENTIFIER in journald driver should be set by default to application name, process-id and message-id and if user use --log-opt tag="surprise" then we should set it also as SYSLOG_IDENTIFIER?

thaJeztah · Dec 6, 2017

Yes, wondering if that should be the correct use, but perhaps we're over-thinking it 😅

zemanlx · Dec 14, 2017

@thaJeztah I would be glad for getting this basic version in and maybe add syslogy version if somebody complains.

thaJeztah · Jan 4, 2018

I have not hear objections since last time, so moving to code review

thaJeztah · Jan 4, 2018

@cpuguy83 wants to double-check, and give this another look

cpuguy83 · Jan 5, 2018

This is really strange... it seems like there's a regression here because I'm pretty sure it used to log deatils about the container and have them viewable in journalctl.

cpuguy83 · Jan 5, 2018

From the journald docs:

Syslog compatibility fields containing the facility (formatted as decimal string), the identifier string (i.e. "tag"), and the client PID. (Note that the tag is usually derived from glibc's program_invocation_short_name variable, see program_invocation_short_name(3).)

So I guess this is good.

cpuguy83

LGTM

thaJeztah · Jan 5, 2018

@cpuguy83 I think it was always like this, but see #20443 (comment)

thaJeztah

LGTM, thanks!

cpuguy83 · Jan 5, 2018

Yeah, I could be thinking about syslog...
Would be cool if we could set a default identifier to program_invocation_short_name, which is effectively argv[0] (from the main of the executed processes) with just the base executable name (no path).
Also, the pid would be cool... though we don't have either of these in the log context.

Add journald tag as SYSLOG_IDENTIFIER

ae557f9

Signed-off-by: Vlastimil Zeman <vlastimil.zeman@diffblue.com>

GordonTheTurtle added the status/0-triage label Nov 22, 2017

boaz0 added status/1-design-review and removed status/0-triage labels Nov 22, 2017

GordonTheTurtle assigned runcom Dec 7, 2017

thaJeztah added status/2-code-review and removed status/1-design-review labels Jan 4, 2018

thaJeztah assigned cpuguy83 and unassigned runcom Jan 4, 2018

cpuguy83 approved these changes Jan 5, 2018

View reviewed changes

thaJeztah added area/logging impact/changelog labels Jan 5, 2018

thaJeztah approved these changes Jan 5, 2018

View reviewed changes

thaJeztah merged commit d80c13a into moby:master Jan 5, 2018

zemanlx deleted the feature/journald-with-SYSLOG_IDENTIFIER branch January 10, 2018 09:28

gbarr01 mentioned this pull request Jan 27, 2018

Document journald tag as SYSLOG_IDENTIFIER docker/docs#5843

Closed

zemanlx mentioned this pull request Feb 12, 2018

Document journald tag as SYSLOG_IDENTIFIER docker/docs#5989

Merged

thaJeztah mentioned this pull request Oct 19, 2018

It seems docker does not set SYSLOG_IDENTIFIER via --log-opt #38060

Closed

Search code, repositories, users, issues, pull requests...

Add journald tag as SYSLOG_IDENTIFIER #35570

Add journald tag as SYSLOG_IDENTIFIER #35570

Uh oh!

Conversation

zemanlx commented Nov 22, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

boaz0 commented Nov 22, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

thaJeztah commented Nov 22, 2017

Uh oh!

zemanlx commented Nov 22, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

thaJeztah commented Nov 30, 2017

Uh oh!

thaJeztah commented Nov 30, 2017

Uh oh!

zemanlx commented Dec 5, 2017

Uh oh!

thaJeztah commented Dec 6, 2017

Uh oh!

zemanlx commented Dec 14, 2017

Uh oh!

thaJeztah commented Jan 4, 2018

Uh oh!

thaJeztah commented Jan 4, 2018

Uh oh!

cpuguy83 commented Jan 5, 2018

Uh oh!

cpuguy83 commented Jan 5, 2018

Uh oh!

cpuguy83 left a comment

Choose a reason for hiding this comment

Uh oh!

thaJeztah commented Jan 5, 2018

Uh oh!

thaJeztah left a comment

Choose a reason for hiding this comment

Uh oh!

cpuguy83 commented Jan 5, 2018

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

6 participants

zemanlx commented Nov 22, 2017 •

edited

Loading

boaz0 commented Nov 22, 2017 •

edited

Loading

zemanlx commented Nov 22, 2017 •

edited

Loading