You are not logged in.

#1 2012-09-02 17:11:25

PaulBx1
Member
Registered: 2008-10-18
Posts: 142

Two red messages in log

Whenever I do a shutdown, this appears in journalctl. I have prefaced the red lines with "{RED}":

Sep 02 08:41:44 myhost dbus-daemon[344]: dbus[344]: [system] Activating via systemd: service name='org.freedesktop.UPower' unit='upower.service'
Sep 02 08:41:44 myhost dbus[344]: [system] Activating via systemd: service name='org.freedesktop.UPower' unit='upower.service'
Sep 02 08:41:44 myhost dbus-daemon[344]: dbus[344]: [system] Successfully activated service 'org.freedesktop.UPower'
Sep 02 08:41:44 myhost dbus[344]: [system] Successfully activated service 'org.freedesktop.UPower'
Sep 02 08:41:46 myhost login[420]: pam_unix(login:session): session closed for user root
{RED}Sep 02 08:41:47 myhost login[420]: pam_systemd(login:session): Failed to connect to system bus: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
Sep 02 08:41:51 myhost umount[1101]: umount: /var: target is busy.
Sep 02 08:41:51 myhost umount[1101]: (In some cases useful info about processes that use
Sep 02 08:41:51 myhost umount[1101]: the device is found by lsof(8) or fuser(1))
Sep 02 08:41:51 myhost systemd[1]: var.mount mount process exited, code=exited status=32
{RED}Sep 02 08:41:56 myhost systemd-cryptsetup[1092]: Failed to deactivate: Invalid argument
Sep 02 08:41:56 myhost systemd[1]: systemd-cryptsetup@cryptvar.service: control process exited, code=exited status=1
Sep 02 08:41:56 myhost systemd[1]: Unit systemd-cryptsetup@cryptvar.service entered failed state.
Sep 02 08:41:56 myhost systemd[1]: Shutting down.
Sep 02 08:41:56 myhost systemd[1]: Hardware watchdog 'iTCO_wdt', version 0
Sep 02 08:41:56 myhost systemd[1]: Set hardware watchdog to 10min.
Sep 02 08:41:56 myhost systemd-journal[167]: Journal stopped
----- Reboot -----

I don't know if the two errors are related. Earlier I was getting the trouble with unmounting var but not the pam_systemd thing. If anyone has any suggestions, I'd appreciate it. I have dug around some but I haven't had much luck tracing this down or even figuring out what has /var tied up so it can't be unmounted.

Offline

#2 2012-11-15 17:13:18

Leonid.I
Member
From: Aethyr
Registered: 2009-03-22
Posts: 973

Re: Two red messages in log

Regarding cryptsetup, I think there is some error in the way it is called.

Unmounting /var fails because of the journal which wants to write into /var/log/journal until the very end. This sounds like a bug in systemd.

The error pam_systemd is the only one which I am confused about . In half of shutdowns I have it, in the other half -- this (https://bbs.archlinux.org/viewtopic.php?id=152959)

PS: Mods, is it possible to merge this thread and the one I linked, please? They discuss similar issues and I haven't done a good search before posting.

Last edited by Leonid.I (2012-11-15 17:13:42)


Arch Linux is more than just GNU/Linux -- it's an adventure

Offline

#3 2013-02-11 21:45:02

jchau
Member
Registered: 2013-02-11
Posts: 1

Re: Two red messages in log

Thanks for your analysis, Leonid.I.  I've been having this problem too and have been trying to find a solution.  The closest thing I found was to append "shutdown" to the list HOOKS in /etc/mkinitcpio.conf, and then to insert the command "/usr/sbin/ash" to the top of /run/initramfs/shutdown to get a shell during shutdown to see what's going on. 

From there, I can see that my partitions successfully unmount, but it seems that this is only done after cryptsetup fails at closing those partitions. 

For me, my partitions are:
/ (encrypted)
/boot
/home (encrypted)
/var (encrypted)
/var/log (encrypted)
swap (encrypted)

Both /var/log and /var initially have trouble unmounting and deactivating.  I also have the pam_systemd error in red.  And perhaps because I added the shutdown hook, I also see red for the "Stopped (with error)" lines. 

Feb 11 16:00:06 bunny login[551]: pam_unix(login:session): session closed for user root
Feb 11 16:00:06 bunny login[551]: pam_systemd(login:session): Failed to connect to system bus: Did not receive a reply. Possible causes include: the remote application did not send a reply, the mes
Feb 11 16:00:06 bunny iptables-flush[863]: /usr/sbin/iptables
Feb 11 16:00:06 bunny iptables-flush[867]: /usr/sbin/ip6tables
Feb 11 16:00:06 bunny systemd[1]: Deactivated swap /dev/dm-2.
Feb 11 16:00:06 bunny systemd[1]: Stopped D-Bus System Message Bus.
Feb 11 16:00:06 bunny systemd[1]: Stopping Permit User Sessions...
Feb 11 16:00:06 bunny systemd[1]: Deactivated swap /dev/disk/by-uuid/722ab14b-7939-4165-a55a-281def4b3fb3.
Feb 11 16:00:06 bunny systemd[1]: Deactivated swap /dev/disk/by-id/dm-uuid-CRYPT-PLAIN-swap.
Feb 11 16:00:06 bunny systemd[1]: Deactivated swap /dev/disk/by-id/dm-name-swap.
Feb 11 16:00:06 bunny systemd[1]: Deactivated swap /dev/mapper/swap.
Feb 11 16:00:06 bunny systemd[1]: Stopping /sys/devices/virtual/block/dm-2.
Feb 11 16:00:06 bunny systemd[1]: Stopped Login Service.
Feb 11 16:00:06 bunny systemd[1]: Stopped Packet Filtering Framework.
Feb 11 16:00:06 bunny systemd[1]: Stopped IPv6 Packet Filtering Framework.
Feb 11 16:00:06 bunny systemd[1]: Stopped Permit User Sessions.
Feb 11 16:00:06 bunny systemd[1]: Stopping Remote File Systems.
Feb 11 16:00:06 bunny systemd[1]: Stopped target Remote File Systems.
Feb 11 16:00:07 bunny systemd[1]: Stopped OpenSSH Daemon.
Feb 11 16:00:07 bunny systemd[1]: Stopped (with error) /dev/mapper/swap.
Feb 11 16:00:07 bunny systemd[1]: Stopped (with error) /dev/disk/by-uuid/722ab14b-7939-4165-a55a-281def4b3fb3.
Feb 11 16:00:07 bunny systemd[1]: Stopped (with error) /dev/disk/by-id/dm-uuid-CRYPT-PLAIN-swap.
Feb 11 16:00:07 bunny systemd[1]: Stopped (with error) /dev/disk/by-id/dm-name-swap.
Feb 11 16:00:07 bunny systemd[1]: Stopped (with error) /dev/dm-2.
Feb 11 16:00:07 bunny systemd[1]: Stopped (with error) /sys/devices/virtual/block/dm-2.
Feb 11 16:00:07 bunny kernel: tg3 0000:01:00.0: wake-up capability enabled by ACPI
Feb 11 16:00:07 bunny netcfg[864]: :: ethernet-static down [done]
Feb 11 16:00:07 bunny ifplugd[354]: Link beat lost.
Feb 11 16:00:07 bunny kernel: IPv6: ADDRCONF(NETDEV_UP): enp1s0: link is not ready
Feb 11 16:00:07 bunny ifplugd[354]: Executing '/etc/ifplugd/netcfg.action enp1s0 down'.
Feb 11 16:00:07 bunny ifplugd[354]: Program execution failed, return value is 1.
Feb 11 16:00:07 bunny ifplugd[354]: Exiting.
Feb 11 16:00:07 bunny systemd[1]: Stopped Provides automatic netcfg wired connection.
Feb 11 16:00:07 bunny systemd[1]: Stopping Basic System.
Feb 11 16:00:07 bunny systemd[1]: Stopped target Basic System.
Feb 11 16:00:07 bunny systemd[1]: Stopping Dispatch Password Requests to Console Directory Watch.
Feb 11 16:00:07 bunny systemd[1]: Stopped Dispatch Password Requests to Console Directory Watch.
Feb 11 16:00:07 bunny systemd[1]: Stopping Daily Cleanup of Temporary Directories.
Feb 11 16:00:07 bunny systemd[1]: Stopped Daily Cleanup of Temporary Directories.
Feb 11 16:00:07 bunny systemd[1]: Stopping Sockets.
Feb 11 16:00:07 bunny systemd[1]: Stopped target Sockets.
Feb 11 16:00:07 bunny systemd[1]: Stopping D-Bus System Message Bus Socket.
Feb 11 16:00:07 bunny systemd[1]: Closed D-Bus System Message Bus Socket.
Feb 11 16:00:07 bunny systemd[1]: Stopping Swap.
Feb 11 16:00:07 bunny systemd[1]: Stopped target Swap.
Feb 11 16:00:07 bunny systemd[1]: Stopping Local File Systems.
Feb 11 16:00:07 bunny systemd[1]: Stopped target Local File Systems.
Feb 11 16:00:07 bunny umount[921]: umount: /var/log: target is busy.
Feb 11 16:00:07 bunny umount[921]: (In some cases useful info about processes that use
Feb 11 16:00:07 bunny umount[921]: the device is found by lsof(8) or fuser(1))
Feb 11 16:00:07 bunny systemd[1]: var-log.mount mount process exited, code=exited status=32
Feb 11 16:00:07 bunny systemd[1]: Failed unmounting /var/log.
Feb 11 16:00:07 bunny systemd[1]: Unmounting /var...
Feb 11 16:00:07 bunny systemd[1]: Stopping /sys/devices/virtual/block/dm-3.
Feb 11 16:00:07 bunny systemd[1]: Unmounted /boot.
Feb 11 16:00:07 bunny systemd[1]: Unmounted Temporary Directory.
Feb 11 16:00:07 bunny umount[930]: umount: /var: target is busy.
Feb 11 16:00:07 bunny umount[930]: (In some cases useful info about processes that use
Feb 11 16:00:07 bunny umount[930]: the device is found by lsof(8) or fuser(1))
Feb 11 16:00:07 bunny systemd[1]: var.mount mount process exited, code=exited status=32
Feb 11 16:00:07 bunny systemd[1]: Failed unmounting /var.
Feb 11 16:00:07 bunny systemd[1]: Stopping /sys/devices/virtual/block/dm-1.
Feb 11 16:00:07 bunny systemd[1]: Unmounted /home.
Feb 11 16:00:07 bunny systemd[1]: Stopped Cryptography Setup for swap.
Feb 11 16:00:07 bunny systemd[1]: Stopping /sys/devices/virtual/block/dm-4.
Feb 11 16:00:07 bunny systemd[1]: Stopping Local File Systems (Pre).
Feb 11 16:00:07 bunny systemd[1]: Stopped target Local File Systems (Pre).
Feb 11 16:00:07 bunny systemd[1]: Stopping Remount Root and Kernel File Systems...
Feb 11 16:00:07 bunny systemd[1]: Starting Shutdown.
Feb 11 16:00:07 bunny systemd[1]: Reached target Shutdown.
Feb 11 16:00:07 bunny systemd[1]: Stopped Cryptography Setup for home.
Feb 11 16:00:07 bunny systemd[1]: Stopped /dev/mapper/home.
Feb 11 16:00:07 bunny systemd[1]: Stopped /dev/disk/by-uuid/fb844ea2-ef1d-4b94-a068-e8f3bf5db273.
Feb 11 16:00:07 bunny systemd[1]: Stopped /dev/disk/by-id/dm-uuid-CRYPT-LUKS1-1d2fabed41fd4f0ea1e624d04362d4ee-home.
Feb 11 16:00:07 bunny systemd[1]: Stopped /dev/disk/by-id/dm-name-home.
Feb 11 16:00:07 bunny systemd[1]: Stopped /dev/dm-4.
Feb 11 16:00:07 bunny systemd[1]: Stopped /sys/devices/virtual/block/dm-4.
Feb 11 16:00:08 bunny kernel: tg3 0000:01:00.0 enp1s0: Link is up at 100 Mbps, full duplex
Feb 11 16:00:08 bunny kernel: tg3 0000:01:00.0 enp1s0: Flow control is on for TX and on for RX
Feb 11 16:00:08 bunny kernel: IPv6: ADDRCONF(NETDEV_CHANGE): enp1s0: link becomes ready
Feb 11 16:00:12 bunny systemd-cryptsetup[926]: Failed to deactivate: Invalid argument
Feb 11 16:00:12 bunny systemd[1]: systemd-cryptsetup@var.service: control process exited, code=exited status=1
Feb 11 16:00:12 bunny systemd-cryptsetup[928]: Failed to deactivate: Invalid argument
Feb 11 16:00:12 bunny systemd[1]: Stopped Cryptography Setup for var.
Feb 11 16:00:12 bunny systemd[1]: Unit systemd-cryptsetup@var.service entered failed state
Feb 11 16:00:12 bunny systemd[1]: systemd-cryptsetup@root.service: control process exited, code=exited status=1
Feb 11 16:00:12 bunny systemd[1]: Stopped Cryptography Setup for root.
Feb 11 16:00:12 bunny systemd[1]: Unit systemd-cryptsetup@root.service entered failed state
Feb 11 16:00:12 bunny systemd-cryptsetup[925]: Failed to deactivate: Invalid argument
Feb 11 16:00:12 bunny systemd[1]: systemd-cryptsetup@log.service: control process exited, code=exited status=1
Feb 11 16:00:12 bunny systemd[1]: Stopped Cryptography Setup for log.
Feb 11 16:00:12 bunny systemd[1]: Unit systemd-cryptsetup@log.service entered failed state
Feb 11 16:00:12 bunny systemd[1]: Starting Unmount All Filesystems.
Feb 11 16:00:12 bunny systemd[1]: Reached target Unmount All Filesystems.
Feb 11 16:00:12 bunny systemd[1]: Starting Final Step.
Feb 11 16:00:12 bunny systemd[1]: Reached target Final Step.
Feb 11 16:00:12 bunny systemd[1]: Starting Reboot...
Feb 11 16:00:12 bunny systemd[1]: Shutting down.
Feb 11 16:00:12 bunny systemd[1]: Hardware watchdog 'iTCO_wdt', version 0
Feb 11 16:00:12 bunny systemd[1]: Set hardware watchdog to 10min.
Feb 11 16:00:12 bunny kernel: watchdog watchdog0: watchdog did not stop!
Feb 11 16:00:12 bunny systemd-journal[158]: Journal stopped

Offline

Board footer

Powered by FluxBB