[Kind of Solved]systemd-journeld.service watchdog timeout (TTY locked)

nstgc · 2014-08-31 22:35:03

[edit8] I still don't know what cuased the issue, nor exactly what happened, however it hasn't occured in a while so I'm just going to make this as "solved". [/edit8]

A few minutes ago I ran a system upgrade, which is something I do every afternoon (previously every morning). This time, after finishing, when I tried to start Chromium, it wouldn't load. Since gstreamer updated I assumed I needed to restart X. And so I log out of Gnome Shell which sends me to TTY1 which shows X trying to stop. After a bit I got "systemd-jour...". The next think I did was hit ctrl+alt+f2 to get into TTY2, however instead of a login prompt I just get "systemd-j...". I then try ctrl+z, which does free up the TTY1 command line, but, as soon as I put in "$ top" it all starts over again. I try ctrl+z again, but now it isn't going anything.

I don't have any other error messages to post since I can't get into anything.

[edit] I don't want to turn my computer off at the power button, but I don't see any alternative at this time. I haven't yet and won't until I hear someone say I should I'm running btrfs and worry about the consequences.

[edit2] One other potentionally useful peice of info. The last useful thing my computer printed was "waiting for X server to shutdown .....(EE) Server terminated successfully (0). Closing log file.

[edit3] Aso, its normal for me to go strait from Gnome Shell to a TTY since I don't have a welcomer.

[edit4] I've read that you can run into issues since the journel can become highly fragmented on btrfs volumes, however I regularly defragment from another installtion.

[edit5] Shutdown got stuck after shutting down all dhcp deamons for more than an hour so I forced a restart from the motherboard. I'm currently scrubbing my btrfs volumes from my bacup arch installation.

[edit6] As I had said I would do in my last post in this thread, I replaced my Arch subvolume with the newest snapshot. I ran "pacman -Syu" without any difficulty, and now its working fine. I still don't know what caused this, which is just as important as figuring out what to do about it which I hope to prevent this from happening again. For that reason I am not tagging it as "solved", but the urgency certainly has diminished.

[edit7] Just FYI: Its been several days now, and this hasn't occured a second time.

Last edited by nstgc (2014-09-12 17:21:41)

ewaller · 2014-08-31 23:59:24

Is this still an Antergos system?
I ran a full upgrade a few minutes ago, am posting from Chromium. Everything here works swimmingly. I don not use Gnome, I use i3. Mayhaps that is the root cause.

nstgc · 2014-09-01 00:02:59

No, this is Arch. I did at one time have an Antergos installation, but that has since been removed.

I doubt it has anything to do with Chromium, or Gnome. X, maybe (very slim "maybe").

I'm currently checking my btrfs volumes. Once that's done I can start pulling up logs. I dare not touch a thing until the filing system is given a clean bill of health.

ewaller · 2014-09-01 00:21:32

Okay, I'll update my notes. If you do reboot, it is not a big deal to boot from an install media and use a chroot environment to fix things. But, I do agree, finish checking the file systems if you can.

Moderator mode Edit: And could you please update your email?

Last edited by ewaller (2014-09-01 00:23:02)

nstgc · 2014-09-01 01:00:00

While I'm waiting for the scrub to finish, which logs would be helpful. I figure my pacman.log to see what exactly changed, as well as systemd journal, assuming I can read it. Is there anything else that I haven't thought of?

ewaller · 2014-09-01 01:15:51

ewaller wrote:

Moderator mode Edit: And could you please update your email?

Bad assumption on my part. My apologies.

nstgc · 2014-09-01 01:23:51

Here is the last few days for pacman.log

[2014-08-29 21:02] [PACMAN] Running 'pacman --color auto -Sy'
[2014-08-29 21:02] [PACMAN] synchronizing package lists
[2014-08-29 21:02] [PACMAN] Running 'pacman --color auto -S -u'
[2014-08-29 21:02] [PACMAN] starting full system upgrade
[2014-08-29 21:03] [PACMAN] upgraded libreoffice-still-en-US (4.2.6-3 -> 4.2.6-4)
[2014-08-29 21:03] [PACMAN] upgraded libreoffice-still-common (4.2.6-3 -> 4.2.6-4)
[2014-08-29 21:03] [PACMAN] upgraded libreoffice-still-calc (4.2.6-3 -> 4.2.6-4)
[2014-08-29 21:03] [PACMAN] upgraded libreoffice-still-writer (4.2.6-3 -> 4.2.6-4)
[2014-08-29 21:03] [PACMAN] upgraded man-pages (3.70-1 -> 3.71-1)
[2014-08-29 21:03] [PACMAN] upgraded mutagen (1.23-1 -> 1.24-1)
[2014-08-29 21:03] [PACMAN] upgraded python2-pillow (2.5.3-1 -> 2.5.3-2)
[2014-08-30 16:27] [PACMAN] Running 'pacman --color auto -S pdfunite'
[2014-08-30 16:34] [PACMAN] Running 'pacman --color auto -S community/pdfsam'
[2014-08-30 16:34] [PACMAN] installed pdfsam (2.2.4-1)
[2014-08-31 17:58] [PACMAN] Running 'pacman --color auto -Sy'
[2014-08-31 17:58] [PACMAN] synchronizing package lists
[2014-08-31 17:59] [PACMAN] Running 'pacman --color auto -S -u'
[2014-08-31 17:59] [PACMAN] starting full system upgrade

Note how it doesn't actually say anything was upgraded. This is not the case. A lot of somethings were upgraded.

As for systemd journel, the output of "# journalctl -p 0..3 -xn" is below. It was run in a chroot environment.

Aug 31 18:02:10 Lain-Arch kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 31 18:02:10 Lain-Arch kernel: INFO: task kworker/u12:13:138 blocked for more than 120 seconds.
Aug 31 18:02:10 Lain-Arch kernel:       Tainted: P           O  3.16.1-1-ARCH #1
Aug 31 18:02:10 Lain-Arch kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 31 18:02:10 Lain-Arch kernel: INFO: task btrfs-transacti:204 blocked for more than 120 seconds.
Aug 31 18:02:10 Lain-Arch kernel:       Tainted: P           O  3.16.1-1-ARCH #1
Aug 31 18:02:10 Lain-Arch kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 31 18:02:10 Lain-Arch kernel: INFO: task kworker/u12:5:964 blocked for more than 120 seconds.
Aug 31 18:02:10 Lain-Arch kernel:       Tainted: P           O  3.16.1-1-ARCH #1
Aug 31 18:02:10 Lain-Arch kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

[edit] Here is part of the output of "# journel -p 0..3 -x" which should be more informative since it has more then just the tail.

Aug 29 21:47:36 {mycomputername} pulseaudio[778]: [pulseaudio] pid.c: Daemon already running.
-- Reboot --
Aug 30 08:20:07 {mycomputername} kernel: ata14.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6
Aug 30 08:20:07 {mycomputername} kernel: ata14.00: irq_stat 0x40000001
Aug 30 08:20:07 {mycomputername} kernel: ata14.00: cmd a0/01:00:00:00:01/00:00:00:00:00/a0 tag 3 dma 16640 in
                                           res 00/00:00:00:00:00/00:00:00:00:00/00 Emask 0x3 (HSM violation)
Aug 30 08:20:08 {mycomputername} kernel: EDAC sbridge: ECC is disabled. Aborting
Aug 30 08:20:08 {mycomputername} kernel: EDAC sbridge: Couldn't find mci handler
Aug 30 08:21:02 {mycomputername} pulseaudio[14923]: GetManagedObjects() failed: org.freedesktop.systemd1.LoadFailed: Unit dbus-org.bluez.service failed to load: No such file or dire
Aug 30 08:21:02 {mycomputername} pulseaudio[15056]: [pulseaudio] pid.c: Daemon already running.
Aug 30 08:33:43 {mycomputername} kernel: watchdog watchdog0: watchdog did not stop!
-- Reboot --
Aug 30 08:34:24 {mycomputername} kernel: ata14.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
Aug 30 08:34:24 {mycomputername} kernel: ata14.00: irq_stat 0x40000001
Aug 30 08:34:24 {mycomputername} kernel: ata14.00: cmd a0/01:00:00:00:01/00:00:00:00:00/a0 tag 3 dma 16640 in
                                           res 50/00:02:00:00:00/00:00:00:00:00/a0 Emask 0x1 (device error)
Aug 30 08:34:24 {mycomputername} kernel: ata14.00: status: { DRDY }
Aug 30 08:34:24 {mycomputername} kernel: EDAC sbridge: ECC is disabled. Aborting
Aug 30 08:34:24 {mycomputername} kernel: EDAC sbridge: Couldn't find mci handler
Aug 30 08:35:26 {mycomputername} kernel: watchdog watchdog0: watchdog did not stop!
-- Reboot --
Aug 30 09:54:04 {mycomputername} kernel: ata14.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
Aug 30 09:54:04 {mycomputername} kernel: ata14.00: irq_stat 0x40000001
Aug 30 09:54:04 {mycomputername} kernel: ata14.00: cmd a0/01:00:00:00:01/00:00:00:00:00/a0 tag 3 dma 16640 in
                                           res 50/00:02:00:00:00/00:00:00:00:00/a0 Emask 0x1 (device error)
Aug 30 09:54:04 {mycomputername} kernel: ata14.00: status: { DRDY }
Aug 30 09:54:05 {mycomputername} kernel: EDAC sbridge: ECC is disabled. Aborting
Aug 30 09:54:05 {mycomputername} kernel: EDAC sbridge: Couldn't find mci handler
Aug 30 09:54:53 {mycomputername} pulseaudio[644]: GetManagedObjects() failed: org.freedesktop.systemd1.LoadFailed: Unit dbus-org.bluez.service failed to load: No such file or direct
Aug 30 09:54:53 {mycomputername} pulseaudio[773]: [pulseaudio] pid.c: Daemon already running.
Aug 30 10:14:47 {mycomputername} pulseaudio[644]: Unable to read or parse data from client.
-- Reboot --
Aug 30 13:06:07 {mycomputername} kernel: ata14.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
Aug 30 13:06:07 {mycomputername} kernel: ata14.00: irq_stat 0x40000001
Aug 30 13:06:07 {mycomputername} kernel: ata14.00: cmd a0/01:00:00:00:01/00:00:00:00:00/a0 tag 3 dma 16640 in
                                           res 50/00:02:00:00:00/00:00:00:00:00/a0 Emask 0x1 (device error)
Aug 30 13:06:07 {mycomputername} kernel: ata14.00: status: { DRDY }
Aug 30 13:06:08 {mycomputername} kernel: EDAC sbridge: ECC is disabled. Aborting
Aug 30 13:06:08 {mycomputername} kernel: EDAC sbridge: Couldn't find mci handler
Aug 30 13:06:42 {mycomputername} pulseaudio[650]: GetManagedObjects() failed: org.freedesktop.systemd1.LoadFailed: Unit dbus-org.bluez.service failed to load: No such file or direct
Aug 30 13:06:42 {mycomputername} pulseaudio[781]: [pulseaudio] pid.c: Daemon already running.
Aug 30 16:27:56 {mycomputername} sudo[2055]: {myusername} : a password is required ; TTY=pts/0 ; PWD=/home/{myusername} ; USER=root ; COMMAND=list /usr/bin/pacman --color auto -S pdfunite
Aug 30 17:22:14 {mycomputername} kernel: watchdog watchdog0: watchdog did not stop!
-- Reboot --
Aug 30 19:05:08 {mycomputername} kernel: ata14.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
Aug 30 19:05:08 {mycomputername} kernel: ata14.00: irq_stat 0x40000001
Aug 30 19:05:08 {mycomputername} kernel: ata14.00: cmd a0/01:00:00:00:01/00:00:00:00:00/a0 tag 3 dma 16640 in
                                           res 50/00:02:00:00:00/00:00:00:00:00/a0 Emask 0x1 (device error)
Aug 30 19:05:08 {mycomputername} kernel: ata14.00: status: { DRDY }
Aug 30 19:05:09 {mycomputername} kernel: EDAC sbridge: ECC is disabled. Aborting
Aug 30 19:05:09 {mycomputername} kernel: EDAC sbridge: Couldn't find mci handler
Aug 30 19:05:34 {mycomputername} pulseaudio[648]: GetManagedObjects() failed: org.freedesktop.systemd1.LoadFailed: Unit dbus-org.bluez.service failed to load: No such file or direct
Aug 30 19:05:34 {mycomputername} pulseaudio[779]: [pulseaudio] pid.c: Daemon already running.
Aug 30 20:50:03 {mycomputername} kernel: watchdog watchdog0: watchdog did not stop!
-- Reboot --
Aug 31 08:45:48 {mycomputername} kernel: ata14.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
Aug 31 08:45:48 {mycomputername} kernel: ata14.00: irq_stat 0x40000001
Aug 31 08:45:48 {mycomputername} kernel: ata14.00: cmd a0/01:00:00:00:01/00:00:00:00:00/a0 tag 3 dma 16640 in
                                           res 50/00:02:00:00:00/00:00:00:00:00/a0 Emask 0x1 (device error)
Aug 31 08:45:48 {mycomputername} kernel: ata14.00: status: { DRDY }
Aug 31 08:45:50 {mycomputername} kernel: EDAC sbridge: ECC is disabled. Aborting
Aug 31 08:45:50 {mycomputername} kernel: EDAC sbridge: Couldn't find mci handler
Aug 31 08:53:25 {mycomputername} pulseaudio[650]: GetManagedObjects() failed: org.freedesktop.systemd1.LoadFailed: Unit dbus-org.bluez.service failed to load: No such file or direct
Aug 31 09:43:54 {mycomputername} pulseaudio[650]: Unable to read or parse data from client.
Aug 31 09:43:56 {mycomputername} kernel: watchdog watchdog0: watchdog did not stop!
-- Reboot --
Aug 31 13:19:53 {mycomputername} kernel: ata14.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
Aug 31 13:19:53 {mycomputername} kernel: ata14.00: irq_stat 0x40000001
Aug 31 13:19:53 {mycomputername} kernel: ata14.00: cmd a0/01:00:00:00:01/00:00:00:00:00/a0 tag 3 dma 16640 in
                                           res 50/00:02:00:00:00/00:00:00:00:00/a0 Emask 0x1 (device error)
Aug 31 13:19:53 {mycomputername} kernel: ata14.00: status: { DRDY }
Aug 31 13:19:54 {mycomputername} kernel: EDAC sbridge: ECC is disabled. Aborting
Aug 31 13:19:54 {mycomputername} kernel: EDAC sbridge: Couldn't find mci handler
Aug 31 13:20:30 {mycomputername} login[460]: pam_tally(login:auth): pam_get_uid; no such user
Aug 31 13:20:46 {mycomputername} pulseaudio[646]: GetManagedObjects() failed: org.freedesktop.systemd1.LoadFailed: Unit dbus-org.bluez.service failed to load: No such file or direct
Aug 31 13:20:46 {mycomputername} pulseaudio[776]: [pulseaudio] pid.c: Daemon already running.
-- Reboot --
Aug 31 14:41:13 {mycomputername} kernel: ata14.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
Aug 31 14:41:13 {mycomputername} kernel: ata14.00: irq_stat 0x40000001
Aug 31 14:41:13 {mycomputername} kernel: ata14.00: cmd a0/01:00:00:00:01/00:00:00:00:00/a0 tag 3 dma 16640 in
                                           res 50/00:02:00:00:00/00:00:00:00:00/a0 Emask 0x1 (device error)
Aug 31 14:41:13 {mycomputername} kernel: ata14.00: status: { DRDY }
Aug 31 14:41:13 {mycomputername} kernel: EDAC sbridge: ECC is disabled. Aborting
Aug 31 14:41:13 {mycomputername} kernel: EDAC sbridge: Couldn't find mci handler
Aug 31 14:42:55 {mycomputername} pulseaudio[644]: GetManagedObjects() failed: org.freedesktop.systemd1.LoadFailed: Unit dbus-org.bluez.service failed to load: No such file or direct
Aug 31 14:42:55 {mycomputername} pulseaudio[779]: [pulseaudio] pid.c: Daemon already running.
Aug 31 15:23:16 {mycomputername} login[459]: pam_systemd(login:session): Failed to release session: Interrupted system call
-- Reboot --
Aug 31 16:36:15 {mycomputername} kernel: ata14.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
Aug 31 16:36:15 {mycomputername} kernel: ata14.00: irq_stat 0x40000001
Aug 31 16:36:15 {mycomputername} kernel: ata14.00: cmd a0/01:00:00:00:01/00:00:00:00:00/a0 tag 3 dma 16640 in
                                           res 50/00:02:00:00:00/00:00:00:00:00/a0 Emask 0x1 (device error)
Aug 31 16:36:15 {mycomputername} kernel: ata14.00: status: { DRDY }
Aug 31 16:36:16 {mycomputername} kernel: EDAC sbridge: ECC is disabled. Aborting
Aug 31 16:36:16 {mycomputername} kernel: EDAC sbridge: Couldn't find mci handler
Aug 31 16:36:51 {mycomputername} pulseaudio[644]: GetManagedObjects() failed: org.freedesktop.systemd1.LoadFailed: Unit dbus-org.bluez.service failed to load: No such file or direct
Aug 31 16:36:51 {mycomputername} pulseaudio[777]: [pulseaudio] pid.c: Daemon already running.
Aug 31 16:51:34 {mycomputername} kernel: watchdog watchdog0: watchdog did not stop!
-- Reboot --
Aug 31 17:50:14 {mycomputername} kernel: ata14.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6
Aug 31 17:50:14 {mycomputername} kernel: ata14.00: irq_stat 0x40000001
Aug 31 17:50:14 {mycomputername} kernel: ata14.00: cmd a0/01:00:00:00:01/00:00:00:00:00/a0 tag 3 dma 16640 in
                                           res 00/00:00:00:00:00/00:00:00:00:00/00 Emask 0x3 (HSM violation)
Aug 31 17:50:15 {mycomputername} kernel: EDAC sbridge: ECC is disabled. Aborting
Aug 31 17:50:15 {mycomputername} kernel: EDAC sbridge: Couldn't find mci handler
Aug 31 17:58:21 {mycomputername} pulseaudio[640]: GetManagedObjects() failed: org.freedesktop.systemd1.LoadFailed: Unit dbus-org.bluez.service failed to load: No such file or direct
Aug 31 17:58:21 {mycomputername} pulseaudio[775]: [pulseaudio] pid.c: Daemon already running.
Aug 31 17:58:52 {mycomputername} sudo[1068]: {myusername} : a password is required ; TTY=pts/0 ; PWD=/home/{myusername} ; USER=root ; COMMAND=list /usr/bin/pacman --color auto -Sy
Aug 31 18:02:10 {mycomputername} kernel: INFO: task kworker/u12:3:110 blocked for more than 120 seconds.
Aug 31 18:02:10 {mycomputername} kernel:       Tainted: P           O  3.16.1-1-ARCH #1
Aug 31 18:02:10 {mycomputername} kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 31 18:02:10 {mycomputername} kernel: INFO: task kworker/u12:11:134 blocked for more than 120 seconds.
Aug 31 18:02:10 {mycomputername} kernel:       Tainted: P           O  3.16.1-1-ARCH #1
Aug 31 18:02:10 {mycomputername} kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 31 18:02:10 {mycomputername} kernel: INFO: task kworker/u12:13:138 blocked for more than 120 seconds.
Aug 31 18:02:10 {mycomputername} kernel:       Tainted: P           O  3.16.1-1-ARCH #1
Aug 31 18:02:10 {mycomputername} kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 31 18:02:10 {mycomputername} kernel: INFO: task btrfs-transacti:204 blocked for more than 120 seconds.
Aug 31 18:02:10 {mycomputername} kernel:       Tainted: P           O  3.16.1-1-ARCH #1
Aug 31 18:02:10 {mycomputername} kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 31 18:02:10 {mycomputername} kernel: INFO: task kworker/u12:5:964 blocked for more than 120 seconds.
Aug 31 18:02:10 {mycomputername} kernel:       Tainted: P           O  3.16.1-1-ARCH #1
Aug 31 18:02:10 {mycomputername} kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

[edit2] My main installation is not happy. I tried to complete a system upgrade with "pacman -Syu" from an arch-chroot, and got as an error

:: Synchronizing package databases...
error: failed to update core (unable to lock database)
error: failed to update extra (unable to lock database)
error: failed to update community (unable to lock database)
error: failed to update multilib (unable to lock database)
error: failed to synchronize any databases
error: failed to init transaction (unable to lock database)
error: could not lock database: File exists
  if you're sure a package manager is not already
  running, you can remove /var/lib/pacman/db.lck

Also when I tried to log startx, after booting it, and logging into my main user account, I got a frowny face telling me something's is badly messed up. Tommorrow I'll try rolling back to yesterday's snapshot. With luck, that will work. If not, I'm going to have to figure out, again, how to get clementine to play CD.

[edit3] As I had said I would do, I replaced my Arch subvolume with the newest snapshot. I ran "pacman -Syu" without any difficulty, and now its working fine. I still don't know what caused this, which is just as important as figuring out what to do about it which I hope to prevent this from happening again. For that reason I am not tagging it as "solved", but the urgency certainly has diminished.

Last edited by nstgc (2014-09-01 13:00:20)

Arch Linux

#1 2014-08-31 22:35:03

[Kind of Solved]systemd-journeld.service watchdog timeout (TTY locked)

#2 2014-08-31 23:59:24

Re: [Kind of Solved]systemd-journeld.service watchdog timeout (TTY locked)

#3 2014-09-01 00:02:59

Re: [Kind of Solved]systemd-journeld.service watchdog timeout (TTY locked)

#4 2014-09-01 00:21:32

Re: [Kind of Solved]systemd-journeld.service watchdog timeout (TTY locked)

#5 2014-09-01 01:00:00

Re: [Kind of Solved]systemd-journeld.service watchdog timeout (TTY locked)

#6 2014-09-01 01:15:51

Re: [Kind of Solved]systemd-journeld.service watchdog timeout (TTY locked)

#7 2014-09-01 01:23:51

Re: [Kind of Solved]systemd-journeld.service watchdog timeout (TTY locked)

Board footer