snap logs dies on journald binary MESSAGE data

[Ian Johnson]

Sometimes we get messages from journald's json format that is formatted like:

{ "__CURSOR" : "s=a2c27451c4d644bba4d36e1f80378bd6;i=1e0f8;b=9ba166d005f828cc887b2f00a4031bc1;m=26dd42a016;t=5addf597dddc6;x=7b954cea7f63b51", "__REALTIME_TIMESTAMP" : "1598549674286534", "__MONOTONIC_TIMESTAMP" : "166920888342", "_BOOT_ID" : "9ba166d005f828cc887b2f00a4031bc1", "PRIORITY" : "6", "_MACHINE_ID" : "b36af8c8821a47c5aeb9b437257e0f43", "_HOSTNAME" : "pandora", "SYSLOG_FACILITY" : "3", "_UID" : "0", "_GID" : "0", "_SYSTEMD_SLICE" : "system.slice", "_CAP_EFFECTIVE" : "3fffffffff", "_TRANSPORT" : "stdout", "_COMM" : "snap-runner", "_EXE" : "/usr/bin/dash", "_CMDLINE" : "/bin/sh -e /snap/micro-xrce-dds-agent/x1/usr/bin/snap-runner", "SYSLOG_IDENTIFIER" : "micro-xrce-dds-agent.daemon", "_SELINUX_CONTEXT" : "snap.micro-xrce-dds-agent.daemon (enforce)\n", "_SYSTEMD_CGROUP" : "/system.slice/snap.micro-xrce-dds-agent.daemon.service", "_SYSTEMD_UNIT" : "snap.micro-xrce-dds-agent.daemon.service", "_STREAM_ID" : "55ff7549b9b04963a7e136a8d4d1e13f", "_PID" : "15898", "_SYSTEMD_INVOCATION_ID" : "74f5abfb62454bf3b4148446bae3aa9c", "MESSAGE" : [ 87, 101, 100, 32, 74, 117, 110, 32, 32, 49, 32, 49, 52, 58, 51, 53, 58, 50, 54, 32, 85, 84, 67, 32, 50, 48, 49, 54, 13 ] }

which then snapd fails to decode because we simplistically define systemd.Log as a map[string]string and we can't decode the array of integers for MESSAGE as a string, producing the following error in the daemon:

Aug 27 10:49:49 host snapd[9577]: response.go:365: cannot stream response; problem reading: json: cannot unmarshal array into Go value of type string

We should handle this better. It's slightly complicated because there's also this bit from the manpage:

> Journal entries permit non-unique fields within the same log entry. JSON does not allow non-unique fields within objects. Due to this, if a non-unique field is encountered a JSON array is used as field value, listing all field values as elements.

which implies that we not only have to worry about sometimes strings showing up as arrays of integers, but also non-unique keys in the original journald message showing up as a single string to an array of values.

Ideally someone should look at journald source code to figure out what all we need to handle, from snapd's source code we currently only really care about:

* __REALTIME_TIMESTAMP
* _PID
* SYSLOG_IDENTIFIER
* SYSLOG_PID
* MESSAGE

with the first two keys being "trusted" by systemd, so it seems unlikely those could ever be not a string, but the other three could be arbitrary from an app, so we need to have better handling there.

[Ian Johnson (anonymouse67)]

PR up: https://github.com/snapcore/snapd/pull/9234

the PR may be too naive, but it was what I could throw together quickly so we'll see how it does

[Ian Johnson (anonymouse67)]

This will be fixed in snapd 2.50.