Mining the journalctl logs

tomoqv · December 7, 2021, 2:32pm

It seems my journalctl logs are flooded, so I started digging around a bit in the issue.

purism@pureos:~$ journalctl --disk-usage
Archived and active journals take up 1.8G in the file system.

This sounds huge! Question is if it is the log level that is to low or if there really are problems being logged, such as:

dec 07 15:02:55 pureos kernel: redpine_91x: Packet Dropped as Key ID not matched with both current and previous Key ID

filling up the logs. The above line takes up several hundred lines, when I run journalctl -r -q

The last lines of this are as follows:

dec 07 15:23:16 pureos gsd-color[1562]: unable to get EDID for xrandr-DSI-1: unable to get EDID for output
dec 07 15:23:16 pureos gsd-xsettings[1589]: Failed to get current UI legacy scaling factor
dec 07 15:23:16 pureos gsd-xsettings[1589]: Failed to get current UI legacy scaling factor
dec 07 15:23:16 pureos kernel: edt_ft5x06 2-0038: Unable to fetch data, error: -6
dec 07 15:20:56 pureos kernel: bq25890-charger 3-006a: Disabling OTG_EN pin
dec 07 15:20:56 pureos kernel: bq25890-charger 3-006a: Upstream supply changed: 1.
dec 07 15:20:55 pureos kernel: bq25890-charger 3-006a: Disabling OTG_EN pin
dec 07 15:20:55 pureos kernel: bq25890-charger 3-006a: Upstream supply changed: 1.
dec 07 15:20:55 pureos kernel: bq25890-charger 3-006a: Disabling OTG_EN pin
dec 07 15:20:55 pureos kernel: bq25890-charger 3-006a: Upstream supply changed: 1.
dec 07 15:20:01 pureos cron[3871]: Autentiseringsfel
dec 07 15:20:01 pureos CRON[3871]: Autentiseringsfel
dec 07 15:20:01 pureos CRON[3871]: pam_unix(cron:account): account root has expired (account expired)
dec 07 15:19:16 pureos ModemManager[782]: <info>  [modem1/call2] call state changed: active -> terminated (unknown)
dec 07 15:19:14 pureos pulseaudio[3601]: Playback after capture (-222), drop sink 160
dec 07 15:19:13 pureos pulseaudio[3601]: Playback after capture (-195), drop sink 152
dec 07 15:19:12 pureos gnome-control-c[3220]: g_utf8_casefold: assertion 'str != NULL' failed
dec 07 15:19:12 pureos gnome-control-c[3220]: g_utf8_casefold: assertion 'str != NULL' failed
dec 07 15:19:12 pureos gnome-control-c[3220]: g_utf8_casefold: assertion 'str != NULL' failed
dec 07 15:19:12 pureos gnome-control-c[3220]: g_utf8_casefold: assertion 'str != NULL' failed
dec 07 15:19:12 pureos gnome-control-c[3220]: g_str_has_prefix: assertion 'str != NULL' failed
dec 07 15:19:12 pureos gnome-control-c[3220]: g_utf8_casefold: assertion 'str != NULL' failed
dec 07 15:19:12 pureos gnome-control-c[3220]: g_utf8_casefold: assertion 'str != NULL' failed
dec 07 15:19:12 pureos callaudiod[1534]: no available input found!
dec 07 15:19:12 pureos callaudiod[1534]: no available output found!
dec 07 15:19:12 pureos pulseaudio[3601]: Playback after capture (-5511), drop sink 2192
dec 07 15:19:12 pureos pulseaudio[3601]: Doing resync
dec 07 15:19:12 pureos callaudiod[1534]: no available input found!
dec 07 15:19:12 pureos pulseaudio[3601]: Cannot set requested sink latency of 50,00 ms, adjusting to 100,00 ms
dec 07 15:19:12 pureos pulseaudio[3601]: Cannot set requested source latency of 60,75 ms, adjusting to 100,00 ms
dec 07 15:19:12 pureos pulseaudio[3601]: Configured latency of 200,00 ms is smaller than minimum latency, using minimum instead
dec 07 15:19:12 pureos pulseaudio[3601]: Cannot set requested source latency of 50,00 ms, adjusting to 100,00 ms
dec 07 15:19:12 pureos pulseaudio[3601]: Cannot set requested sink latency of 50,00 ms, adjusting to 100,00 ms
dec 07 15:19:12 pureos pulseaudio[3601]: Configured maximum latency is smaller than latency, using latency instead
dec 07 15:19:12 pureos pulseaudio[3601]: Cannot set requested source latency of 50,00 ms, adjusting to 100,00 ms
dec 07 15:19:12 pureos pulseaudio[3601]: Cannot set requested sink latency of 50,00 ms, adjusting to 100,00 ms
dec 07 15:19:12 pureos pulseaudio[3601]: Configured maximum latency is smaller than latency, using latency instead
dec 07 15:19:12 pureos ModemManager[782]: <info>  [modem1/call2] call state changed: ringing-in -> active (accepted)
dec 07 15:19:12 pureos ModemManager[782]: <info>  [modem1/call2] call is accepted
dec 07 15:19:11 pureos ModemManager[782]: <info>  [modem1/call2] user request to accept call
dec 07 15:19:10 pureos ModemManager[782]: <warn>  [modem1] unexpected incoming call to number '*98#' reported in call list: stat>
dec 07 15:19:08 pureos ModemManager[782]: <warn>  [modem1] unexpected incoming call to number '*98#' reported in call list: stat>
dec 07 15:19:06 pureos ModemManager[782]: <warn>  [modem1] unexpected incoming call to number '*98#' reported in call list: stat>
dec 07 15:19:03 pureos ModemManager[782]: <info>  [modem1/call2] call state changed: unknown -> ringing-in (incoming-new)
dec 07 15:18:36 pureos ModemManager[782]: <info>  [modem1/call1] call state changed: active -> terminated (terminated)
dec 07 15:18:36 pureos ModemManager[782]: <warn>  [modem1/call1] couldn't hangup single call with call id '2': Unknown error
dec 07 15:18:36 pureos ModemManager[782]: <info>  [modem1/call1] user request to hangup call
dec 07 15:17:01 pureos cron[3853]: Autentiseringsfel
dec 07 15:17:01 pureos CRON[3853]: Autentiseringsfel
dec 07 15:17:01 pureos CRON[3853]: pam_unix(cron:account): account root has expired (account expired)
dec 07 15:10:01 pureos CRON[3710]: Autentiseringsfel
dec 07 15:10:01 pureos cron[3710]: Autentiseringsfel
dec 07 15:10:01 pureos CRON[3710]: pam_unix(cron:account): account root has expired (account expired)
dec 07 15:07:42 pureos pulseaudio[3601]: Playback after capture (-185), drop sink 144
dec 07 15:03:00 pureos pulseaudio[3601]: Playback after capture (-502), drop sink 272
dec 07 15:02:58 pureos wpa_supplicant[602]: wlan0: WPA: Group rekeying completed with 78:8a:20:82:e6:13 [GTK=CCMP]
dec 07 15:02:57 pureos kernel: redpine_91x: Packet Dropped as Key ID not matched with both current and previous Key ID
dec 07 15:02:57 pureos kernel: redpine_91x: Packet Dropped as Key ID not matched with both current and previous Key ID

I am not knowledgeable enough to make something out of this, but I guess someone else could. There seem to quite a bit of warnings related to e.g. ModemManager, calls and authentication.

I would appreciate a discussion around this in order to determine if there is something wrong with my phone setup or if this is just normal log spam.

irvinewade · December 8, 2021, 12:30am

It is, in my opinion. This post: How to get Lirem 5 kernel log in /var/log/syslog in addition to systemd journal? tells you how to limit the size automatically.

Purism may have thought that for a relatively new phone it is better to have too much in the journal than too little, for when something needs troubleshooting - and that is certainly a logical decision - but my journal eventually became so slow to interrogate that it became counterproductive.

mekhos · December 8, 2021, 8:23am

I don’t know enough to help with how to deal with the cause of your logs, but I’ve looked into it when I had some issues previously on my computer with logs and you can control-

The logrotation (It “rolls over” based on size or time elapsed, it stops recording in current file and begins a new one).
How many of the previous logs to keep.

good guide here if you want

irvinewade · December 8, 2021, 8:54am

I suspect that that doesn’t work here. That will operate on logs that work the way the traditional logs in /var/log work. I don’t think that works with the logs as manipulated by journalctl (which I think are in /var/log/journal).

Of course, as per the post I linked, you can have both types of log (with the journal being mirrored to syslog), in which case you need to control both types of log (using the config that I gave for the journal and logrotate for the copy in syslog).

tomoqv · December 8, 2021, 9:12am

I added
SystemMaxUse=500M
and
MaxFileSec=1month
to my /etc/systemd/journald.conf

and did a
sudo journalctl --vacuum-size=500M

to shrink the log size

Hopefully this will keep the journalctl log in check going forward.

irvinewade · December 8, 2021, 10:55am

May need journalctl --rotate before vacuuming, and you can in fact combine the rotate with the vacuum into a single journalctl command.

tomoqv · December 8, 2021, 12:32pm

Ok, but my --disk-usage came down to 568M after vaccuuming. Do I need the --rotate command anyway?

irvinewade · December 8, 2021, 11:31pm

If you do the rotate before the vacuum, either as a single journalctl command or as two commands, then you may vacuum up slightly more detritus - but doing the vacuum without a rotate can still be effective in reducing the amount of disk space used by the journal.

For the scenario that I found myself in (and which you apparently found yourself in) where you suddenly notice that the journal is huge because it is never being vacuumed, it is definitely OK and effective to vacuum without rotate (because some rotation occurs automatically behind the scenes).

If you configure journald.conf (as you and I have both done) then you don’t actually need to do a manual vacuum at all - unless you have a critical shortage of disk space - because that configuration ensures that vacuuming occurs automatically behind the scenes.

Unfortunately I don’t know what the automatic vacuuming schedule is but I would expect that once you configure journald.conf as you have done then disk space used by the journal would go down automatically within, say, 24 hours.