Loki: promtail uses previous unit label for dmesg messages

[mweinelt]

Describe the bug
When something gets logged to dmesg (/dev/kmsg), then the (systemd) unit label of the previous log message persists for that dmesg entry.

To Reproduce
Steps to reproduce the behavior:

1. Started Loki (1.6.1)
2. Started Promtail (1.6.1) and scrape the systemd journal
3. Log message to dmesg: echo "foo" > /dev/kmsg

Expected behavior
Messages from dmesg should not be marked as related to a random systemd unit.

Environment:

• Infrastructure: NixOS, KVM and bare-metal
• Deployment tool: NixOS

Screenshots, Promtail config, or terminal output

2020-09-23T15:39:05+02:00 {job="systemd-journal", machine="juno.lossy.network", unit="sshd.service"} Connection from 218.92.0.208 port 52087 on 159.69.156.50 port 22 rdomain ""
2020-09-23T15:39:06+02:00 {job="systemd-journal", machine="juno.lossy.network", unit="sshd.service"} bar

The bar message resulted from

# echo "bar" > /dev/kmsg

It should not be labeled with unit="sshd.service"

[stale[bot]]

This issue has been automatically marked as stale because it has not had any activity in the past 30 days. It will be closed in 7 days if no further activity occurs. Thank you for your contributions.

[mweinelt]

I still consider having a wrong label on kernel ringbuffer messages an error. Not being able to filter for dmesg messages is also a bit disappointing.

[stale[bot]]

This issue has been automatically marked as stale because it has not had any activity in the past 30 days. It will be closed in 7 days if no further activity occurs. Thank you for your contributions.

[mweinelt]

Still an issue on 1.6.1, I am currently unable to check 2.0.

[andir]

Same issue here.

[JJJollyjim]

Semi-reproduced on 2.0.0, but it's a little more complicated:

Watching with logcli --tail, I see this:

2020-11-25T13:36:49+13:00 {syslog_identifier="systemd", unit="minecraft-exporter.socket"} some minecraft-exporter output
2020-11-25T13:36:49+13:00 {syslog_identifier="systemd", unit="minecraft-exporter.socket"} more minecraft-exporter output
2020-11-25T13:36:49+13:00 {syslog_identifier="kernel"} refused connection: [...]
2020-11-25T13:36:53+13:00 {syslog_identifier="kernel", unit="minecraft-exporter.socket"} refused connection: [...]
2020-11-25T13:36:56+13:00 {syslog_identifier="kernel", unit="minecraft-exporter.socket"} refused connection: [...]
2020-11-25T13:36:58+13:00 {syslog_identifier="kernel", unit="minecraft-exporter.socket"} refused connection: [...]

But if I ctrl-c and re-run logcli, those same logs logs are displayed correctly:

2020-11-25T13:36:49+13:00 {syslog_identifier="systemd", unit="minecraft-exporter.socket"} some minecraft-exporter info
2020-11-25T13:36:49+13:00 {syslog_identifier="systemd", unit="minecraft-exporter.socket"} more minecraft-exporter info
2020-11-25T13:36:49+13:00 {syslog_identifier="kernel"} refused connection: [...]
2020-11-25T13:36:53+13:00 {syslog_identifier="kernel"} refused connection: [...]
2020-11-25T13:36:56+13:00 {syslog_identifier="kernel"} refused connection: [...]
2020-11-25T13:36:58+13:00 {syslog_identifier="kernel"} refused connection: [...]

Do either of you see the issue when not tailing?

---

Edit: they also display fine in Grafana, but I can't try live view in Grafana since my reverse proxy is not set up correctly for websockets -_-