Add journald tag as SYSLOG_IDENTIFIER

[zemanlx]

- 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

[boaz0]

/cc @thaJeztah @bobrik @zarnovican @stevvooe

[thaJeztah]

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]

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

1. 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.
2. 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]

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]

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]

@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]

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

[zemanlx]

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

[thaJeztah]

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

[thaJeztah]

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

[cpuguy83]

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]

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]

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

[thaJeztah]

LGTM, thanks!

[cpuguy83]

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.