• 90 secs delay on shutdown, old known bug?


    Hello mates,

    when I power off the laptop it takes 90 seconds countdown to power off, aparently doing nothing just waiting. Look at 13:13:51 in the log.

    I’ve read about an old bug on systemd waiting for unmount units before shutdown (or something similar); about some bluetooth issues also… I’m lost :(

    journalctl -b -1

    relevant part from “power off” order is:

    Out 31 13:12:21 arch gnome-session[841]: gnome-session-binary[841]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
    Out 31 13:12:21 arch systemd-logind[431]: System is powering down.
    Out 31 13:12:21 arch systemd[1]: Stopping Accounts Service...
    Out 31 13:12:21 arch systemd[1]: Stopping RealtimeKit Scheduling Policy Service...
    Out 31 13:12:21 arch systemd[1]: Deactivating swap /dev/disk/by-id/wwn-0x50014ee6008a0476-part6...
    Out 31 13:12:21 arch systemd[1]: Stopped target Timers.
    Out 31 13:12:21 arch systemd[1]: Stopped target Sound Card.
    Out 31 13:12:21 arch systemd[1]: Stopping Manage, Install and Generate Color Profiles...
    Out 31 13:12:21 arch systemd[1]: Stopped target Graphical Interface.
    Out 31 13:12:21 arch systemd[1]: Stopped Bumblebee C Daemon.
    Out 31 13:12:21 arch systemd[1]: Stopping Session c2 of user elodin.
    Out 31 13:12:21 arch org.gnome.Calendar[847]: (gnome-calendar:1993): Gdk-WARNING **: gnome-calendar: Fatal IO error 11 (Recurso non dispoñible temporalmente) on X server :0.
    Out 31 13:12:21 arch systemd[1]: Starting Store Sound Card State...
    Out 31 13:12:21 arch systemd[1]: Stopping Daemon for power management...
    Out 31 13:12:21 arch systemd[1]: Stopping User Manager for UID 1000...
    Out 31 13:12:21 arch systemd[1]: Closed Load/Save RF Kill Switch Status /dev/rfkill Watch.
    Out 31 13:12:21 arch systemd[1]: Stopping TLP system startup/shutdown...
    Out 31 13:12:21 arch systemd[1]: Removed slice system-macspoof.slice.
    Out 31 13:12:21 arch systemd[1]: Stopping Disk Manager...
    Out 31 13:12:21 arch systemd[1]: Stopped Daily Cleanup of Temporary Directories.
    Out 31 13:12:21 arch systemd[1]: Stopping Authorization Manager...
    Out 31 13:12:21 arch systemd[1]: Stopping WPA supplicant...
    Out 31 13:12:21 arch systemd[1]: Starting Generate shutdown-ramfs...
    Out 31 13:12:21 arch systemd[1]: Stopping Light Display Manager...
    

    then, in 1 o r 2 seconds it repeats about 100 times (yes, at least 100 times) this lines.

    Out 31 13:12:22 arch NetworkManager[432]:   Failed to acquire wpa_supplicant proxy: (Produciuse un erro ao chamar a StartServiceByName para fi.w1.wpa_supplicant1:GDBus.Error:org.freedesktop.systemd1.ShuttingDown: Refusing activation, D-Bus is shutting down.) Out 31 13:12:22 arch NetworkManager[432]:   (wlp4s0b1): supplicant interface state: starting -> down
    

    So I guess this is a fail, but not the cause of the 90 seconds delay

    Continues here:

    Out 31 13:12:22 arch systemd[1]: Stopped TLP system startup/shutdown.
    Out 31 13:12:22 arch systemd[1]: Stopped target Multi-User System.
    Out 31 13:12:22 arch systemd[1]: Stopping D-Bus System Message Bus...
    Out 31 13:12:22 arch systemd[1]: Stopping Login Service...
    Out 31 13:12:22 arch systemd[1]: Stopped target Login Prompts.
    Out 31 13:12:22 arch systemd[1]: Stopping Getty on tty1...
    Out 31 13:12:22 arch systemd[1]: Stopped Script de supresión das mensaxe do driver broadcom.
    Out 31 13:12:22 arch systemd[1]: Stopped Apply cpupower configuration.
    Out 31 13:12:22 arch bluetoothd[442]: Disconnected from D-Bus. Exiting.
    Out 31 13:12:22 arch NetworkManager[432]:   disconnected by the system bus.
    Out 31 13:12:22 arch NetworkManager[432]:   Failed to acquire wpa_supplicant proxy: (Produciuse un erro ao chamar a StartServiceByName para fi.w1.wpa_supplicant1:A conexión está pechado)
    Out 31 13:12:22 arch NetworkManager[432]:   (wlp4s0b1): supplicant interface state: starting -> down
    Out 31 13:12:22 arch NetworkManager[432]:   caught SIGTERM, shutting down normally.
    Out 31 13:12:22 arch NetworkManager[432]:   (wlp4s0b1): device state change: unavailable -> unmanaged (reason 'unmanaged') [20 10 3]
    Out 31 13:12:22 arch NetworkManager[432]:   (enp3s0): device state change: unavailable -> unmanaged (reason 'unmanaged') [20 10 3]
    Out 31 13:12:22 arch NetworkManager[432]:   exiting (success)
    Out 31 13:12:22 arch bluetoothd[442]: Stopping SDP server
    Out 31 13:12:22 arch bluetoothd[442]: Exit
    Out 31 13:12:22 arch systemd[1]: Stopping Initialize hardware monitoring sensors...
    Out 31 13:12:22 arch systemd[1]: Stopped Daily rotation of log files.
    Out 31 13:12:22 arch systemd[1]: Stopped Daily man-db cache update.
    Out 31 13:12:22 arch ntpd[489]: ntpd exiting on signal 15 (Terminated)
    Out 31 13:12:22 arch systemd[1]: Stopped Daily verification of password and group files.
    Out 31 13:12:22 arch systemd[1]: Stopping Network Time Service...
    Out 31 13:12:22 arch systemd[1]: Stopping Bluetooth service...
    Out 31 13:12:22 arch systemd[1]: Stopped D-Bus System Message Bus.
    Out 31 13:12:22 arch systemd[1]: Stopped Bluetooth service.
    Out 31 13:12:23 arch systemd[1]: Stopped Getty on tty1.
    Out 31 13:12:23 arch systemd[1]: Stopped Login Service.
    Out 31 13:12:23 arch systemd[1]: Stopped Network Time Service.
    Out 31 13:12:23 arch systemd[1]: Stopped Initialize hardware monitoring sensors.
    Out 31 13:12:23 arch systemd[1]: Stopped target Network.
    Out 31 13:12:23 arch systemd[1]: Stopped target Network (Pre).
    Out 31 13:12:23 arch systemd[1]: Stopping Network Manager...
    Out 31 13:12:23 arch systemd[1]: Removed slice system-getty.slice.
    Out 31 13:12:23 arch systemd[1]: Stopped Network Manager.
    Out 31 13:12:23 arch mkinitcpio[2173]: ==> Build complete.
    Out 31 13:12:23 arch systemd[1]: Started Generate shutdown-ramfs.
    Out 31 13:12:27 arch kernel: atkbd serio0: Unknown key pressed (translated set 2, code 0x71 on isa0060/serio0).
    Out 31 13:12:27 arch kernel: atkbd serio0: Use 'setkeycodes 71 ' to make it known.
    

    and here comes de delay on timestamp (the stoped User Manager UID 1000 is what I read on power off secuence).

    Out 31 13:1**3:51 arch systemd[1]: user@1000.service: State 'stop-sigterm' timed out. Killing.
    Out 31 13:13:51 arch systemd[822]: dbus.service: State 'stop-final-sigterm' timed out. Killing.
    Out 31 13:13:51 arch systemd[1]: Stopped User Manager for UID 1000.
    Out 31 13:13:51 arch systemd[1]: user@1000.service: Unit entered failed state.
    Out 31 13:13:51 arch systemd[1]: user@1000.service: Failed with result 'timeout'.
    Out 31 13:13:51 arch systemd[1]: Removed slice user-1000.slice.**
    Out 31 13:13:51 arch systemd[1]: Stopping Permit User Sessions...
    Out 31 13:13:52 arch systemd[1]: Stopped Permit User Sessions.
    Out 31 13:13:52 arch systemd[1]: Stopped target Remote File Systems.
    Out 31 13:13:52 arch systemd[1]: Stopped target Basic System.
    Out 31 13:13:52 arch systemd[1]: Stopped target Slices.
    Out 31 13:13:52 arch systemd[1]: Removed slice User and Session Slice.
    Out 31 13:13:52 arch systemd[1]: Stopped target Sockets.
    Out 31 13:13:52 arch systemd[1]: Stopped Apply Kernel Variables.
    Out 31 13:13:52 arch systemd[1]: Stopped target Swap.
    Out 31 13:13:52 arch systemd[1]: Stopped target Encrypted Volumes.
    Out 31 13:13:52 arch systemd[1]: Stopping Load/Save Random Seed...
    Out 31 13:13:52 arch systemd[1]: Stopped Setup Virtual Console.
    Out 31 13:13:52 arch systemd[1]: Stopping Load/Save Screen Backlight Brightness of backlight:acpi_video0...
    Out 31 13:13:52 arch systemd[1]: Stopping Update UTMP about System Boot/Shutdown...
    Out 31 13:13:52 arch systemd[1]: Stopped target Paths.
    Out 31 13:13:52 arch systemd[1]: Stopped Dispatch Password Requests to Console Directory Watch.
    Out 31 13:13:52 arch systemd[1]: Stopped Forward Password Requests to Wall Directory Watch.
    Out 31 13:13:52 arch systemd[1]: Stopped target User and Group Name Lookups.
    Out 31 13:13:52 arch systemd[1]: Stopped Load/Save Random Seed.
    Out 31 13:13:52 arch systemd[1]: Stopped Load/Save Screen Backlight Brightness of backlight:acpi_video0.
    Out 31 13:13:52 arch systemd[1]: Removed slice system-systemd\x2dbacklight.slice.
    Out 31 13:13:52 arch systemd[1]: Stopped Update UTMP about System Boot/Shutdown.
    Out 31 13:13:52 arch systemd[1]: Stopped Create Volatile Files and Directories.
    Out 31 13:13:52 arch systemd[1]: Stopped target Local File Systems.
    Out 31 13:13:52 arch systemd[1]: Unmounting /run/media/elodin/AlmacenEXT4...
    Out 31 13:13:52 arch systemd[1]: Unmounting /tmp...
    Out 31 13:13:52 arch systemd[1]: Unmounting /run/user/1000...
    Out 31 13:13:52 arch systemd[1]: Unmounting /home...
    Out 31 13:13:52 arch systemd[1]: Unmounted /tmp.
    Out 31 13:13:52 arch systemd[1]: Unmounted /run/user/1000.
    Out 31 13:13:52 arch systemd[1]: Unmounted /run/media/elodin/AlmacenEXT4.
    Out 31 13:13:52 arch systemd[1]: Stopped File System Check on /dev/disk/by-uuid/22b5e6dd-820a-46a1-a34e-c106dfcc6f52.
    Out 31 13:13:52 arch systemd[1]: Removed slice system-systemd\x2dfsck.slice.
    Out 31 13:13:52 arch systemd[1]: Unmounted /home.
    Out 31 13:13:52 arch systemd[1]: Reached target Unmount All Filesystems.
    Out 31 13:13:52 arch systemd[1]: Stopped target Local File Systems (Pre).
    Out 31 13:13:52 arch systemd[1]: Stopped Remount Root and Kernel File Systems.
    Out 31 13:13:52 arch systemd[1]: Stopped Create Static Device Nodes in /dev.
    Out 31 13:13:52 arch systemd[1]: Reached target Shutdown.
    Out 31 13:13:52 arch systemd[1]: Reached target Final Step.
    Out 31 13:13:52 arch systemd[1]: Starting Power-Off...
    Out 31 13:13:52 arch systemd[1]: Shutting down.
    Out 31 13:13:52 arch systemd-shutdown[1]: Sending SIGTERM to remaining processes...
    Out 31 13:13:52 arch systemd-journald[167]: Journal stopped
    

    Any help or tip will be wellcome. If you need the complete log I’ll attach it here.

  • @XoseM I have the same issue since like last month or something. It doesn’t happen on every single shutdown, but on most. Though I don’t have any issues with wpa-supplicant, the timeout kill is the same on my laptop.

  • Hello, this problem both comme antergos Arch, was solved by me, as root:

    mkinitcpio -p linux

    Greetings !

  • I’ve read about network-manager waiting to unmout disks from /etc/fstab (I’ve change the way I mount there one partition, but unsuccesfully).

    so rebuild the system/kernel start with mkinitcpio. I’ll try that

    thanks @cbix @judd

poweroff2 networkmanager13 systemd25 delay2 wpasupplicant2 Posts 4Views 2617
Log in to reply