journalctl container logs add extra line jumps and changes formatting

[pipex]

trafficstars

This can be seen when downloading logs from the dashboard

Logs on 12.0.9

to start udev!
25.02.21 13:47:23 (-0300) Started service 'fanshim sha256:5f34bbde61308a747186285e3488316c8039a9ebd0e0283fb271065a2480c6c6'
25.02.21 13:47:24 (-0300) <undefined> 
25.02.21 13:47:24 (-0300) <undefined> Starting fan control with configuration
25.02.21 13:47:24 (-0300) <undefined> On threshold: 65.0
25.02.21 13:47:24 (-0300) <undefined> Off threshold 55.0
25.02.21 13:47:25 (-0300) <undefined> 
25.02.21 13:47:25 (-0300) <undefined> > [email protected] start /usr/src/app
25.02.21 13:47:25 (-0300) <undefined> > node server.js
25.02.21 13:47:25 (-0300) <undefined> 
25.02.21 13:47:25 (-0300) <undefined> Example app listening on port  80
25.02.21 13:49:13 (-0300) Supervisor starting
25.02.21 13:47:24 (-0300) <undefined> 
25.02.21 13:47:24 (-0300) <undefined> Starting fan control with configuration
25.02.21 13:47:24 (-0300) <undefined> On threshold: 65.0
25.02.21 13:47:24 (-0300) <undefined> Off threshold 55.0
25.02.21 13:47:23 (-0300) <undefined> Unable to start udev, container must be run in privileged mode to start udev!
25.02.21 13:47:25 (-0300) <undefined>

On 12.1.0

25.02.21 13:52:50 (-0300) Supervisor starting
25.02.21 13:49:29 (-0300) <undefined> 

25.02.21 13:49:29 (-0300) <undefined> Starting fan control with configuration

25.02.21 13:49:29 (-0300) <undefined> On threshold: 65.0

25.02.21 13:49:29 (-0300) <undefined> Off threshold 55.0

25.02.21 13:49:19 (-0300) <undefined> Unable to start udev, container must be run in privileged mode to start udev!

25.02.21 13:49:19 (-0300) <undefined> 

25.02.21 13:49:19 (-0300) <undefined> > [email protected] start /usr/src/app

25.02.21 13:49:19 (-0300) <undefined> > node server.js

25.02.21 13:49:19 (-0300) <undefined> 

25.02.21 13:49:20 (-0300) <undefined> Example app listening on port  80

[jellyfish-bot]

[pipex] This issue has attached support thread https://jel.ly.fish/944c7071-53ea-4820-9797-b6458c9bf2fe

[pipex]

Edited the issue title to broaden the scope. Journalctl obtained logs are also apparently changing the encoding from utf8 to win-1252. For my app, on supervisor 12.0.9 I see this on the dashboard

01.03.21 16:45:43 (-0300)  fanshim  On threshold: 65.0°
01.03.21 16:45:43 (-0300)  fanshim  Off threshold 55.0°

On 12.1.0 i see this

01.03.21 16:45:43 (-0300)  fanshim  On threshold: 65.0°
01.03.21 16:45:43 (-0300)  fanshim  Off threshold 55.0°

[jellyfish-bot]

[pipex] This issue has attached support thread https://jel.ly.fish/9b2860f2-c179-4f6f-9db3-ef8351151ee5

[pipex]

At least for the extra lines, this is the answer. The supervisor is running containers with tty by default, which adds an extra carriage return \r when using the journalctl driver

https://docs.docker.com/config/containers/logging/journald/#view-logs-for-a-container-with-a-tty-enabled

The solution would be either to strip the carriage return, or figure out the impact of not using tty by default in containers.

[pipex]

Related https://github.com/balena-os/balena-supervisor/pull/771

[bbugh]

Unfortunately, because of this carriage return, reading journald with JSON format forces it into byte array mode. This is causing all of our log messages to come out in big byte arrays, forcing us to parse the log message into human-readable format before storing it, which really slows it down a lot and uses extra CPU we would rather not sacrifice just for capturing logs.

Out of the hundreds of messages we've spot checked, all of the byte arrays were caused by this extra carriage return, and could have been sent via plaintext over the supervisor journald api if not for this.

Is there any workaround for this, perhaps in a configuration file, so that it does not output the \r?

[pipex]

Hi @bbugh, could you try configuring your containers with tty: false? This is an old issue and I don’t know if my previous comments still apply, but I’m pretty sure the byte arrays are related to that.

[bbugh]

@pipex thanks for the quick reply. I was able to try that, all compose services now have tty: false and it resolves half of the issue!

We still have a lot of unwanted output related to the tty:

Apr 08 20:45:34 732886f agetty[63702]: /dev/ttyS0: not a tty
Apr 08 20:45:44 732886f agetty[63713]: /dev/ttyS0: not a tty
Apr 08 20:45:55 732886f agetty[63725]: /dev/ttyS0: not a tty
Apr 08 20:46:05 732886f agetty[63738]: /dev/ttyS0: not a tty
Apr 08 20:46:15 732886f agetty[63765]: /dev/ttyS0: not a tty
Apr 08 20:46:21 732886f healthdog[63778]: try: 1, refid: D133A1EE, correction: 0.000033975, skew: 12.568
Apr 08 20:46:25 732886f agetty[63783]: /dev/ttyS0: not a tty
Apr 08 20:46:36 732886f agetty[63808]: /dev/ttyS0: not a tty
Apr 08 20:46:37 732886f 93518c04edc1[1381]: [info]    Reported current state to the cloud
Apr 08 20:46:37 732886f balena-supervisor[3657]: [info]    Reported current state to the cloud
Apr 08 20:46:46 732886f agetty[63862]: /dev/ttyS0: not a tty

but the MESSAGE field is coming through without the carriage returns in JSON now, which is an improvement, and lets us spend less processing time on it.

{ 
  "MESSAGE" : "D: [alsa-sink-USB Audio] alsa-sink.c: Wakeup from ALSA!"
}

Thanks!