Disturbing messages from infamous host erlangen - they call it a BUG

English Open Chat
#1 
erlangen:~ # journalctl -b -1 --dmesg -g BUG
Jun 30 08:01:14 erlangen kernel: BUG: kernel NULL pointer dereference, address: 000000000000008f
Jun 30 08:02:07 erlangen kernel: BUG: workqueue lockup - pool cpus=7 node=0 flags=0x0 nice=0 stuck for 52s!
Jun 30 08:02:39 erlangen kernel: BUG: workqueue lockup - pool cpus=7 node=0 flags=0x0 nice=0 stuck for 84s!
Jun 30 08:03:10 erlangen kernel: BUG: workqueue lockup - pool cpus=7 node=0 flags=0x0 nice=0 stuck for 115s!
Jun 30 08:03:43 erlangen kernel: BUG: workqueue lockup - pool cpus=7 node=0 flags=0x0 nice=0 stuck for 148s!
Jun 30 08:04:15 erlangen kernel: BUG: workqueue lockup - pool cpus=7 node=0 flags=0x0 nice=0 stuck for 180s!
Jun 30 08:04:47 erlangen kernel: BUG: workqueue lockup - pool cpus=7 node=0 flags=0x0 nice=0 stuck for 212s!
Jun 30 08:05:19 erlangen kernel: BUG: workqueue lockup - pool cpus=7 node=0 flags=0x0 nice=0 stuck for 244s!
Jun 30 08:05:51 erlangen kernel: BUG: workqueue lockup - pool cpus=7 node=0 flags=0x0 nice=0 stuck for 276s!
Jun 30 08:06:23 erlangen kernel: BUG: workqueue lockup - pool cpus=7 node=0 flags=0x0 nice=0 stuck for 308s!
Jun 30 08:06:55 erlangen kernel: BUG: workqueue lockup - pool cpus=7 node=0 flags=0x0 nice=0 stuck for 340s!
Jun 30 08:07:27 erlangen kernel: BUG: workqueue lockup - pool cpus=7 node=0 flags=0x0 nice=0 stuck for 372s!
Jun 30 08:07:57 erlangen kernel: BUG: workqueue lockup - pool cpus=7 node=0 flags=0x0 nice=0 stuck for 402s!
Jun 30 08:08:28 erlangen kernel: BUG: workqueue lockup - pool cpus=7 node=0 flags=0x0 nice=0 stuck for 433s!
Jun 30 08:08:59 erlangen kernel: BUG: workqueue lockup - pool cpus=7 node=0 flags=0x0 nice=0 stuck for 464s!
Jun 30 08:09:29 erlangen kernel: BUG: workqueue lockup - pool cpus=7 node=0 flags=0x0 nice=0 stuck for 494s!
Jun 30 08:10:00 erlangen kernel: BUG: workqueue lockup - pool cpus=7 node=0 flags=0x0 nice=0 stuck for 525s!
erlangen:~ #
#2

Hello Karl – that’s not nice – dereferencing the NULL pointer means that something is trying to access nothing …

  • Terribly complicated because the German language uses „null” and „Null” to mean the digit “zero” → “0” – which ain’t NULL …
  • The NULL pointer points to nothing – which, mathematically, isn’t the number “zero” / “0” …

Possibly not your case but, there is a year old inactive Kernel Bug Report related to filesystem testing: <https://bugzilla.kernel.org/show_bug.cgi?id=215903>

#3

More trouble on resuming from Suspend To RAM: Got some 4,000 messages from pipewire. Needed to kill the graphics session and start again.

Jul 02 05:20:48 erlangen pipewire[1134]: spa.alsa: front:1: snd_pcm_mmap_begin error: Streams pipe error

After session kill and restart:

Jul 02 05:22:57 erlangen pipewire[11138]: mod.rt: RTKit error: org.freedesktop.DBus.Error.AccessDenied
Jul 02 05:22:57 erlangen pipewire[11138]: mod.rt: could not set nice-level to -11: Permission denied
Jul 02 05:22:57 erlangen pipewire[11138]: mod.rt: RTKit error: org.freedesktop.DBus.Error.AccessDenied
Jul 02 05:22:57 erlangen pipewire[11138]: mod.rt: could not make thread 11151 realtime using RTKit: Permission denied

Could be caused by an underlying hardware problem.

#4

Stuff happens: No sound when resuming from suspend on 0.3.72 (#3315) · Issues · PipeWire / pipewire · GitLab

#5

Get some oops every few days:

Jul 05 05:00:50 backup kernel: Oops: 0000 [#1] PREEMPT SMP NOPTI
Jul 05 05:00:50 backup kernel:  ? page_fault_oops+0x14d/0x490

Removed stale configuration files:

karl@erlangen:~> find -name '*pipewire*'|xargs ls -dl
drwx------ 1 karl users   30 15. Jul 2021  ./.config/pipewire
drwx------ 1 karl users    0  3. Nov 2020  ./.config/pipewire-media-session
drwxr-xr-x 1 karl users   38  5. Mai 2022  ./.config/systemd/user/pipewire.service.wants
-rw-r--r-- 1 karl users  554 23. Jan 2022  ./.local/share/okular/docdata/1270.pipewire.md.xml
drwx------ 1 karl users   30  6. Dez 2021  ./.local/state/pipewire
drwx------ 1 karl users    0 13. Sep 2020  ./.pipewire-media-session
karl@erlangen:~>

No more annoying messages from pipewire:

karl@erlangen:~> journalctl --user -b -u 'pipewire*'
Jul 05 06:35:07 erlangen systemd[1099]: Listening on PipeWire PulseAudio.
Jul 05 06:35:07 erlangen systemd[1099]: Listening on PipeWire Multimedia System Socket.
Jul 05 06:35:15 erlangen systemd[1099]: Started PipeWire Multimedia Service.
Jul 05 06:35:16 erlangen systemd[1099]: Started PipeWire PulseAudio.
karl@erlangen:~>

However audio applet disappeared from KDE System Settings and System Tray in the panel. Any idea?

#6

  1. Had inadvertently removed package plasma5-pa. Reinstall fixed the issue.

  2. Powered down erlangen, removed the RAM modules, cleaned the slots with an interdental brush using some 99,9% isopropanol and refitted the modules. Journal from pipewire and wireplumber is now as terse as it was before the mishap.

karl@erlangen:~> journalctl --user -b -u 'pipewire*' -u 'wireplumber*'
Jul 06 06:30:24 erlangen systemd[1105]: Listening on PipeWire PulseAudio.
Jul 06 06:30:24 erlangen systemd[1105]: Listening on PipeWire Multimedia System Socket.
Jul 06 06:30:33 erlangen systemd[1105]: Started PipeWire Multimedia Service.
Jul 06 06:30:33 erlangen systemd[1105]: Started Multimedia Service Session Manager.
Jul 06 06:30:33 erlangen wireplumber[1927]: GetManagedObjects() failed: org.freedesktop.DBus.Error.NameHasNoOwner
Jul 06 06:30:34 erlangen systemd[1105]: Started PipeWire PulseAudio.
karl@erlangen:~>
1 Like
'BUG: unable to handle page fault' and 'BUG: workqueue lockup'
#7

Pipewire did some heavy spamming . Lots of unused data were detected by journal --verify. Clean-up resulted in deletion of some hundred files:

erlangen:~ # journalctl --vacuum-size 100M
Vacuuming done, freed 0B of archived journals from /var/log/journal.
Vacuuming done, freed 0B of archived journals from /run/log/journal.
Deleted archived journal /var/log/journal/94f3af277bac4a8eb57da425c9677379/user-1004@d8e0006754b747b7926bbba34d7fb0f4-0000000000292a22-0005ffadb2a4329d.journal (4.1M).
...
Deleted archived journal /var/log/journal/94f3af277bac4a8eb57da425c9677379/user-1000@6f7ef31b2e4c44138638df81bae85c07-00000000004828a0-0005ffdd7ec2745e.journal (74.3M).
Vacuuming done, freed 1.2G of archived journals from /var/log/journal/94f3af277bac4a8eb57da425c9677379.
erlangen:~ #

Journal is now great again:

erlangen:~ # journalctl --verify
PASS: /var/log/journal/94f3af277bac4a8eb57da425c9677379/system.journal                                                                                                                
PASS: /var/log/journal/94f3af277bac4a8eb57da425c9677379/system@f832dd6b45614c25ad0b7155dc59b250-00000000004828a1-0005ffdd7ec62e1e.journal                                             
PASS: /var/log/journal/94f3af277bac4a8eb57da425c9677379/user-1000.journal                                                                                                             
PASS: /var/log/journal/94f3af277bac4a8eb57da425c9677379/user-1005.journal                                                                                                             
erlangen:~ # 

erlangen:~ # journalctl --disk-usage 
Archived and active journals take up 35.5M in the file system.
erlangen:~ #
#8

Pipewire may start at any time to generate spam:

erlangen:~ # journalctl -q -g Suppressed
Jul 07 10:00:46 erlangen systemd-journald[680]: [🡕] Suppressed 219399 messages from user@1000.service
Jul 07 10:01:16 erlangen systemd-journald[680]: [🡕] Suppressed 247512 messages from user@1000.service
Jul 07 10:01:46 erlangen systemd-journald[680]: [🡕] Suppressed 278576 messages from user@1000.service
Jul 07 10:02:16 erlangen systemd-journald[680]: [🡕] Suppressed 313053 messages from user@1000.service
Jul 07 10:02:46 erlangen systemd-journald[680]: [🡕] Suppressed 351158 messages from user@1000.service
erlangen:~ #
#9

A new process was created automatically, delivering way more spam before being killed and replaced by another instance:

erlangen:~ # journalctl -q -g Suppressed
Jul 07 10:00:46 erlangen systemd-journald[680]: [🡕] Suppressed 219399 messages from user@1000.service
Jul 07 10:01:16 erlangen systemd-journald[680]: [🡕] Suppressed 247512 messages from user@1000.service
Jul 07 10:01:46 erlangen systemd-journald[680]: [🡕] Suppressed 278576 messages from user@1000.service
Jul 07 10:02:16 erlangen systemd-journald[680]: [🡕] Suppressed 313053 messages from user@1000.service
Jul 07 10:02:46 erlangen systemd-journald[680]: [🡕] Suppressed 351158 messages from user@1000.service
Jul 07 12:58:03 erlangen systemd-journald[675]: [🡕] Suppressed 2400 messages from user@1000.service
Jul 07 12:58:33 erlangen systemd-journald[675]: [🡕] Suppressed 6751 messages from user@1000.service
Jul 07 12:59:03 erlangen systemd-journald[675]: [🡕] Suppressed 11576 messages from user@1000.service
Jul 07 12:59:33 erlangen systemd-journald[675]: [🡕] Suppressed 16927 messages from user@1000.service
Jul 07 13:00:03 erlangen systemd-journald[675]: [🡕] Suppressed 22854 messages from user@1000.service
Jul 07 13:00:33 erlangen systemd-journald[675]: [🡕] Suppressed 29443 messages from user@1000.service
Jul 07 13:01:03 erlangen systemd-journald[675]: [🡕] Suppressed 36742 messages from user@1000.service
Jul 07 13:01:33 erlangen systemd-journald[675]: [🡕] Suppressed 44837 messages from user@1000.service
Jul 07 13:02:03 erlangen systemd-journald[675]: [🡕] Suppressed 53814 messages from user@1000.service
Jul 07 13:02:33 erlangen systemd-journald[675]: [🡕] Suppressed 63770 messages from user@1000.service
Jul 07 13:03:03 erlangen systemd-journald[675]: [🡕] Suppressed 74813 messages from user@1000.service
Jul 07 13:03:33 erlangen systemd-journald[675]: [🡕] Suppressed 87059 messages from user@1000.service
Jul 07 13:04:03 erlangen systemd-journald[675]: [🡕] Suppressed 100640 messages from user@1000.service
Jul 07 13:04:33 erlangen systemd-journald[675]: [🡕] Suppressed 115703 messages from user@1000.service
Jul 07 13:05:03 erlangen systemd-journald[675]: [🡕] Suppressed 132404 messages from user@1000.service
Jul 07 13:05:33 erlangen systemd-journald[675]: [🡕] Suppressed 150933 messages from user@1000.service
Jul 07 13:06:03 erlangen systemd-journald[675]: [🡕] Suppressed 171478 messages from user@1000.service
Jul 07 13:06:33 erlangen systemd-journald[675]: [🡕] Suppressed 194265 messages from user@1000.service
Jul 07 13:07:03 erlangen systemd-journald[675]: [🡕] Suppressed 219530 messages from user@1000.service
Jul 07 13:07:33 erlangen systemd-journald[675]: [🡕] Suppressed 247562 messages from user@1000.service
Jul 07 13:08:03 erlangen systemd-journald[675]: [🡕] Suppressed 278644 messages from user@1000.service
Jul 07 13:08:33 erlangen systemd-journald[675]: [🡕] Suppressed 313113 messages from user@1000.service
Jul 07 13:09:03 erlangen systemd-journald[675]: [🡕] Suppressed 351334 messages from user@1000.service
Jul 07 13:09:33 erlangen systemd-journald[675]: [🡕] Suppressed 393719 messages from user@1000.service
Jul 07 13:10:03 erlangen systemd-journald[675]: [🡕] Suppressed 440758 messages from user@1000.service
Jul 07 13:10:33 erlangen systemd-journald[675]: [🡕] Suppressed 492912 messages from user@1000.service
Jul 07 13:11:03 erlangen systemd-journald[675]: [🡕] Suppressed 550745 messages from user@1000.service
Jul 07 13:11:33 erlangen systemd-journald[675]: [🡕] Suppressed 614878 messages from user@1000.service
Jul 07 13:12:03 erlangen systemd-journald[675]: [🡕] Suppressed 686007 messages from user@1000.service
Jul 07 13:12:33 erlangen systemd-journald[675]: [🡕] Suppressed 764910 messages from user@1000.service
Jul 07 13:13:03 erlangen systemd-journald[675]: [🡕] Suppressed 852410 messages from user@1000.service
Jul 07 13:13:33 erlangen systemd-journald[675]: [🡕] Suppressed 949436 messages from user@1000.service
Jul 07 13:14:03 erlangen systemd-journald[675]: [🡕] Suppressed 1057054 messages from user@1000.service
Jul 07 13:14:33 erlangen systemd-journald[675]: [🡕] Suppressed 1176407 messages from user@1000.service
Jul 07 13:15:03 erlangen systemd-journald[675]: [🡕] Suppressed 1308769 messages from user@1000.service
Jul 07 13:15:33 erlangen systemd-journald[675]: [🡕] Suppressed 1455391 messages from user@1000.service
Jul 07 13:16:03 erlangen systemd-journald[675]: [🡕] Suppressed 1618372 messages from user@1000.service
Jul 07 13:16:33 erlangen systemd-journald[675]: [🡕] Suppressed 1798857 messages from user@1000.service
Jul 07 13:17:03 erlangen systemd-journald[675]: [🡕] Suppressed 1999102 messages from user@1000.service
Jul 07 13:17:33 erlangen systemd-journald[675]: [🡕] Suppressed 2221056 messages from user@1000.service
Jul 07 13:18:03 erlangen systemd-journald[675]: [🡕] Suppressed 2467440 messages from user@1000.service
Jul 07 13:18:33 erlangen systemd-journald[675]: [🡕] Suppressed 2740147 messages from user@1000.service
Jul 07 13:19:03 erlangen systemd-journald[675]: [🡕] Suppressed 3043136 messages from user@1000.service
Jul 07 13:19:33 erlangen systemd-journald[675]: [🡕] Suppressed 3373001 messages from user@1000.service
Jul 07 13:20:03 erlangen systemd-journald[675]: [🡕] Suppressed 3745227 messages from user@1000.service
erlangen:~ # 

erlangen:~ # journalctl --disk-usage 
Archived and active journals take up 1012.2M in the file system.
erlangen:~ #
#10

As spamming would occur only with user karl I double-checked for stale configuration files and indeed found some remnants dating back to August 2016 in folder ./.local/share/systemd:

drwxr-xr-x 1 karl users 54 15. Okt 2019  timers
lrwxrwxrwx 1 karl users 29 16. Aug 2016  user -> ../../../.config/systemd/user
insgesamt 0
-rw-r-xr-x 1 karl users 0 13. Nov 2019  stamp-spotify-easyrpm.timer
karl@erlangen:~>

Removed cruft related to spotify from folders ./.config/systemd and ./.local/share/systemd. A few error messages still occur, but their number is down from eight to one digit:

karl@erlangen:~> journalctl _PID=1885 -o short-monotonic 
[ 1730.753812] erlangen pipewire[1885]: spa.alsa: front:1: snd_pcm_mmap_begin error: Fehler in Stream-Pipe
[ 1730.792610] erlangen pipewire[1885]: spa.alsa: front:1: snd_pcm_mmap_begin error: Fehler in Stream-Pipe
[ 1730.792807] erlangen pipewire[1885]: spa.alsa: front:1: snd_pcm_mmap_begin error: Fehler in Stream-Pipe
[ 1730.792922] erlangen pipewire[1885]: spa.alsa: front:1: snd_pcm_mmap_begin error: Fehler in Stream-Pipe
[ 1730.792959] erlangen pipewire[1885]: spa.alsa: front:1: snd_pcm_mmap_begin error: Fehler in Stream-Pipe
[ 1730.792992] erlangen pipewire[1885]: spa.alsa: front:1: snd_pcm_mmap_begin error: Fehler in Stream-Pipe
[ 1730.793024] erlangen pipewire[1885]: spa.alsa: front:1: snd_pcm_mmap_begin error: Fehler in Stream-Pipe
[ 1730.793051] erlangen pipewire[1885]: spa.alsa: front:1: snd_pcm_mmap_begin error: Fehler in Stream-Pipe
[ 1730.793078] erlangen pipewire[1885]: spa.alsa: front:1: snd_pcm_mmap_begin error: Fehler in Stream-Pipe
karl@erlangen:~>

Users beware of exotic installs!

#11

No more messages from pipewire:

karl@erlangen:~> journalctl --user --boot --unit pipewire --since 2023-07-09
-- No entries --
karl@erlangen:~>

Had paused daily dups. Re-enabled the timer:

 erlangen:~ # systemctl list-timers dup
NEXT                         LEFT     LAST                         PASSED    UNIT      ACTIVATES  
Tue 2023-07-11 00:00:00 CEST 18h left Mon 2023-07-10 05:25:40 CEST 14min ago dup.timer dup.service

1 timers listed.
Pass --all to see loaded but inactive timers, too.
erlangen:~ #
#12

More spam:

karl@erlangen:~> journalctl --user --unit pipewire|wc
5341727 64100711 576906378
karl@erlangen:~> journalctl --disk-usage 
Archived and active journals take up 2.3G in the file system.
karl@erlangen:~> journalctl -u init.scope -g pipewire
-- No entries --
karl@erlangen:~> journalctl --user -u init.scope -g pipewire
Jul 14 11:25:53 erlangen systemd[1121]: Listening on PipeWire PulseAudio.
Jul 14 11:25:53 erlangen systemd[1121]: Listening on PipeWire Multimedia System Socket.
Jul 14 11:26:00 erlangen systemd[1121]: Started PipeWire Multimedia Service.
Jul 14 11:26:01 erlangen systemd[1121]: Started PipeWire PulseAudio.
Jul 14 22:26:34 erlangen systemd[1121]: Stopping PipeWire Multimedia Service...
Jul 14 22:26:34 erlangen systemd[1121]: Stopped PipeWire Multimedia Service.
Jul 14 22:26:34 erlangen systemd[1121]: pipewire.service: Consumed 45min 24.470s CPU time.
Jul 14 22:26:34 erlangen systemd[1121]: Started PipeWire Multimedia Service.
karl@erlangen:~>

Restarting stopped the spam:

karl@erlangen:~> systemctl --user status pipewire
● pipewire.service - PipeWire Multimedia Service
     Loaded: loaded (/usr/lib/systemd/user/pipewire.service; disabled; preset: disabled)
     Active: active (running) since Fri 2023-07-14 22:26:34 CEST; 10min ago
TriggeredBy: ● pipewire.socket
   Main PID: 2470 (pipewire)
      Tasks: 2 (limit: 4915)
     Memory: 6.0M
        CPU: 1.086s
     CGroup: /user.slice/user-1000.slice/user@1000.service/session.slice/pipewire.service
             └─2470 /usr/bin/pipewire

Jul 14 22:26:34 erlangen systemd[1121]: Started PipeWire Multimedia Service.
karl@erlangen:~> 

erlangen:~ # journalctl -g Suppressed
Jul 14 22:23:11 erlangen systemd-journald[686]: [🡕] Suppressed 4421175 messages from user@1000.service
Jul 14 22:23:41 erlangen systemd-journald[686]: [🡕] Suppressed 3968367 messages from user@1000.service
Jul 14 22:24:11 erlangen systemd-journald[686]: [🡕] Suppressed 4109487 messages from user@1000.service
Jul 14 22:24:41 erlangen systemd-journald[686]: [🡕] Suppressed 4335954 messages from user@1000.service
Jul 14 22:25:11 erlangen systemd-journald[686]: [🡕] Suppressed 4526994 messages from user@1000.service
Jul 14 22:25:41 erlangen systemd-journald[686]: [🡕] Suppressed 4483151 messages from user@1000.service
Jul 14 22:26:11 erlangen systemd-journald[686]: [🡕] Suppressed 4493050 messages from user@1000.service
erlangen:~ #
#13