Scheduled Maintenance: We are aware of an issue with Google, AOL, and Yahoo services as email providers which are blocking new registrations. We are trying to fix the issue and we have several internal and external support tickets in process to resolve the issue. Please see: viewtopic.php?t=158230

 

 

 

90 second shutdown delay after upgrading to Stretch

If none of the specific sub-forums seem right for your thread, ask here.
Post Reply
Message
Author
spsx272
Posts: 8
Joined: 2017-02-21 03:00

90 second shutdown delay after upgrading to Stretch

#1 Post by spsx272 »

After upgrading Debian from Jessie to Stretch, I noticed (occassionally, once every several shutdowns) that the computer would wait around 90 seconds before shutting down. Note that I did not receive any error messages about a "stop job" or similar, the screen just showed a blinking cursor during that time. This issue had never occured before with Jessie, and I enabled the journal debug log and the debug terminal to take a look. I'm running Gnome 3.22.2 with GDM, on an Intel i5-3570k with a Nvidia 550ti (closed-source drivers).

Here is an excerpt of the journal during a 90 second shutdown (actually a reboot but the result is the same). Look at the timestamps to see where it occurs. The complete log is posted here for your convenience.

Code: Select all

Aug 05 22:37:59 C2 /usr/lib/gdm3/gdm-x-session[1180]: (II) UnloadModule: "libinput"
Aug 05 22:37:59 C2 /usr/lib/gdm3/gdm-x-session[1180]: (II) systemd-logind: releasing fd for 13:69
Aug 05 22:37:59 C2 systemd[1]: Stopped CUPS Scheduler.
Aug 05 22:37:59 C2 /usr/lib/gdm3/gdm-x-session[1180]: (II) UnloadModule: "libinput"
Aug 05 22:37:59 C2 /usr/lib/gdm3/gdm-x-session[1180]: (II) systemd-logind: releasing fd for 13:68
Aug 05 22:37:59 C2 /usr/lib/gdm3/gdm-x-session[1180]: (II) UnloadModule: "libinput"
Aug 05 22:37:59 C2 /usr/lib/gdm3/gdm-x-session[1180]: (II) systemd-logind: releasing fd for 13:67
Aug 05 22:37:59 C2 /usr/lib/gdm3/gdm-x-session[1180]: (II) UnloadModule: "libinput"
Aug 05 22:37:59 C2 /usr/lib/gdm3/gdm-x-session[1180]: (II) systemd-logind: releasing fd for 13:65
Aug 05 22:37:59 C2 dbus[568]: [system] Activating via systemd: service name='org.freedesktop.Accounts' unit='accounts-daemon.service'
Aug 05 22:37:59 C2 dbus[568]: [system] Activation via systemd failed for unit 'accounts-daemon.service': Refusing activation, D-Bus is shutting down.
Aug 05 22:37:59 C2 gdm3[752]: Failed to contact accountsservice: Error calling StartServiceByName for org.freedesktop.Accounts: GDBus.Error:org.freedesktop.systemd1.ShuttingDown: Refusing activation, D-Bus is shutting down.
Aug 05 22:37:59 C2 /usr/lib/gdm3/gdm-x-session[1180]: (II) UnloadModule: "libinput"
Aug 05 22:37:59 C2 /usr/lib/gdm3/gdm-x-session[1180]: (II) systemd-logind: releasing fd for 13:66
Aug 05 22:37:59 C2 gdm3[752]: GLib: g_hash_table_find: assertion 'version == hash_table->version' failed
Aug 05 22:37:59 C2 systemd[1]: Stopped GNOME Display Manager.
Aug 05 22:37:59 C2 systemd[1]: Starting Show Plymouth Reboot Screen...
Aug 05 22:37:59 C2 systemd[1]: Stopped /etc/rc.local Compatibility.
Aug 05 22:37:59 C2 systemd[1]: Stopped target Network is Online.
Aug 05 22:37:59 C2 systemd[1]: Stopped Network Manager Wait Online.
Aug 05 22:38:00 C2 systemd[1]: Received SIGRTMIN+20 from PID 2490 (plymouthd).
Aug 05 22:38:00 C2 systemd[1]: Started Show Plymouth Reboot Screen.
Aug 05 22:38:00 C2 /usr/lib/gdm3/gdm-x-session[1180]: (II) NVIDIA(GPU-0): Deleting GPU-0
Aug 05 22:38:00 C2 /usr/lib/gdm3/gdm-x-session[1180]: (WW) xf86CloseConsole: KDSETMODE failed: Input/output error
Aug 05 22:38:00 C2 /usr/lib/gdm3/gdm-x-session[1180]: (WW) xf86CloseConsole: VT_GETMODE failed: Input/output error
Aug 05 22:38:00 C2 /usr/lib/gdm3/gdm-x-session[1180]: (WW) xf86CloseConsole: VT_ACTIVATE failed: Input/output error
Aug 05 22:38:00 C2 /usr/lib/gdm3/gdm-x-session[1180]: (II) Server terminated successfully (0). Closing log file.
Aug 05 22:38:00 C2 systemd[1]: Stopped Session 3 of user system.
Aug 05 22:38:00 C2 systemd[1]: Removed slice User Slice of system.
Aug 05 22:38:00 C2 systemd-logind[576]: Removed session 3.
Aug 05 22:38:00 C2 systemd[1]: Unmounted /run/user/1000.
Aug 05 22:39:29 C2 systemd[1074]: at-spi-dbus-bus.service: State 'stop-sigterm' timed out. Killing.
Aug 05 22:39:29 C2 systemd[1]: session-c2.scope: Stopping timed out. Killing.
Aug 05 22:39:29 C2 systemd[1]: session-c2.scope: Killing process 1081 (Xorg) with signal SIGKILL.
Aug 05 22:39:29 C2 systemd[1074]: at-spi-dbus-bus.service: Killing process 1098 (at-spi-bus-laun) with signal SIGKILL.
Aug 05 22:39:30 C2 systemd[1074]: at-spi-dbus-bus.service: Main process exited, code=killed, status=9/KILL
Aug 05 22:39:30 C2 systemd[1074]: Stopped Accessibility services bus.
Aug 05 22:39:30 C2 systemd[1074]: at-spi-dbus-bus.service: Unit entered failed state.
Aug 05 22:39:30 C2 systemd[1074]: at-spi-dbus-bus.service: Failed with result 'timeout'.
Aug 05 22:39:30 C2 systemd[1074]: Stopped target Basic System.
Aug 05 22:39:30 C2 systemd[1074]: Stopped target Paths.
Aug 05 22:39:30 C2 systemd[1074]: Stopped target Timers.
Aug 05 22:39:30 C2 systemd[1074]: Stopped target Sockets.
Aug 05 22:39:30 C2 systemd[1074]: Closed GnuPG network certificate management daemon.
Aug 05 22:39:30 C2 systemd[1074]: Closed GnuPG cryptographic agent and passphrase cache (restricted).
Aug 05 22:39:30 C2 systemd[1074]: Closed GnuPG cryptographic agent (access for web browsers).
Aug 05 22:39:30 C2 systemd[1074]: Closed Sound System.
Aug 05 22:39:30 C2 systemd[1074]: Closed GnuPG cryptographic agent (ssh-agent emulation).
Aug 05 22:39:30 C2 systemd[1074]: Closed D-Bus User Message Bus Socket.
Aug 05 22:39:30 C2 systemd[1074]: Closed GnuPG cryptographic agent and passphrase cache.
Aug 05 22:39:30 C2 systemd[1074]: Reached target Shutdown.
Aug 05 22:39:30 C2 systemd[1074]: Starting Exit the Session...
Aug 05 22:39:30 C2 systemd[1074]: Received SIGRTMIN+24 from PID 2510 (kill).
Aug 05 22:39:30 C2 systemd[1075]: pam_unix(systemd-user:session): session closed for user Debian-gdm
Aug 05 22:39:30 C2 systemd[1]: Stopped User Manager for UID 120.
Aug 05 22:39:30 C2 kernel: nvidia-modeset: Freed GPU:0 (GPU-f46a9fa1-e13e-5c6a-4b2e-746f0126ccba) @ PCI:0000:01:00.0
Aug 05 22:39:30 C2 systemd[1]: Stopped Session c2 of user Debian-gdm.
Aug 05 22:39:30 C2 systemd[1]: session-c2.scope: Unit entered failed state.
Aug 05 22:39:30 C2 systemd[1]: Removed slice User Slice of Debian-gdm.
Aug 05 22:39:30 C2 systemd[1]: Stopping Login Service...
Aug 05 22:39:30 C2 systemd[1]: Stopping Permit User Sessions...
Aug 05 22:39:30 C2 systemd[1]: Stopped Permit User Sessions.
Aug 05 22:39:30 C2 systemd[1]: Stopped target Remote File Systems.
Aug 05 22:39:30 C2 systemd[1]: Stopped target Remote File Systems (Pre).
Aug 05 22:39:30 C2 systemd[1]: Stopped target NFS client services.
Aug 05 22:39:30 C2 systemd[1]: Stopped target Network.
Aug 05 22:39:30 C2 NetworkManager[590]: <info>  [1501987170.1835] caught SIGTERM, shutting down normally.
Aug 05 22:39:30 C2 systemd[1]: Stopping Network Manager...
Aug 05 22:39:30 C2 systemd[1]: Stopping WPA supplicant...
Aug 05 22:39:30 C2 systemd[1]: Stopping Raise network interfaces...
Aug 05 22:39:30 C2 systemd[1]: Stopped WPA supplicant.
Aug 05 22:39:30 C2 NetworkManager[590]: <info>  [1501987170.2060] exiting (success)
Aug 05 22:39:30 C2 systemd[1]: Stopped Raise network interfaces.
Aug 05 22:39:30 C2 systemd[1]: Stopped Network Manager.
Aug 05 22:39:30 C2 systemd[1]: Stopping D-Bus System Message Bus...
Aug 05 22:39:30 C2 systemd[1]: Stopped D-Bus System Message Bus.
Aug 05 22:39:30 C2 systemd[1]: Failed to propagate agent release message: Transport endpoint is not connected
Aug 05 22:39:30 C2 systemd[1]: Failed to propagate agent release message: Transport endpoint is not connected
Aug 05 22:39:30 C2 systemd[1]: Stopped Login Service.
Aug 05 22:39:30 C2 systemd[1]: Stopped target User and Group Name Lookups.
Aug 05 22:39:30 C2 systemd[1]: Stopped target Basic System.
Aug 05 22:39:30 C2 systemd[1]: Stopped Forward Password Requests to Plymouth Directory Watch.
Aug 05 22:39:30 C2 systemd[1]: Stopped target Slices.
Aug 05 22:39:30 C2 systemd[1]: Stopped target Paths.
Aug 05 22:39:30 C2 systemd[1]: Stopped CUPS Scheduler.
Aug 05 22:39:30 C2 systemd[1]: Stopped target Sockets.
Aug 05 22:39:30 C2 systemd[1]: Closed CUPS Scheduler.
Aug 05 22:39:30 C2 systemd[1]: Closed UUID daemon activation socket.
Aug 05 22:39:30 C2 systemd[1]: Closed Syslog Socket.
Aug 05 22:39:30 C2 systemd[1]: Closed Avahi mDNS/DNS-SD Stack Activation Socket.
Aug 05 22:39:30 C2 systemd[1]: Closed PC/SC Smart Card Daemon Activation Socket.
Aug 05 22:39:30 C2 systemd[1]: Closed D-Bus System Message Bus Socket.
Aug 05 22:39:30 C2 systemd[1]: Stopped target System Initialization.
Aug 05 22:39:30 C2 systemd[1]: Stopped target Swap.
Aug 05 22:39:30 C2 systemd[1]: Stopped Apply Kernel Variables.
Aug 05 22:39:30 C2 systemd[1]: Stopped Load Kernel Modules.
Aug 05 22:39:30 C2 systemd[1]: Stopping Load/Save Random Seed...
Aug 05 22:39:30 C2 systemd[1]: Stopping Update UTMP about System Boot/Shutdown...
Aug 05 22:39:30 C2 systemd[1]: Stopped target Encrypted Volumes.
Aug 05 22:39:30 C2 systemd[1]: Stopped Forward Password Requests to Wall Directory Watch.
Aug 05 22:39:30 C2 systemd[1]: Stopping Network Time Synchronization...
Aug 05 22:39:30 C2 systemd[1]: Removed slice User and Session Slice.
Aug 05 22:39:30 C2 systemd[1]: Stopped Load/Save Random Seed.
Aug 05 22:39:30 C2 systemd[1]: Stopped Update UTMP about System Boot/Shutdown.
Aug 05 22:39:30 C2 systemd[1]: Stopped Network Time Synchronization.
Aug 05 22:39:30 C2 systemd[1]: Stopped Create Volatile Files and Directories.
Aug 05 22:39:30 C2 systemd[1]: Stopped target Local File Systems.
Aug 05 22:39:30 C2 systemd[1]: Unmounting /home...
Aug 05 22:39:30 C2 systemd[1]: Unmounting /run/user/120...
Aug 05 22:39:30 C2 systemd[1]: Unmounting /mnt/ramdisk...
Aug 05 22:39:30 C2 systemd[1]: Unmounting /tmp...
Aug 05 22:39:30 C2 systemd[1]: Unmounted /run/user/120.
Aug 05 22:39:30 C2 systemd[1]: Unmounted /tmp.
Aug 05 22:39:30 C2 systemd[1]: Unmounted /mnt/ramdisk.
Aug 05 22:39:30 C2 systemd[1]: Unmounted /home.
Aug 05 22:39:30 C2 systemd[1]: Reached target Unmount All Filesystems.
Aug 05 22:39:30 C2 systemd[1]: Stopped File System Check on /dev/disk/by-uuid/9536bca4-419a-4862-a590-f319ecf70fb3.
Aug 05 22:39:30 C2 systemd[1]: Removed slice system-systemd\x2dfsck.slice.
Aug 05 22:39:30 C2 systemd[1]: Stopped target Local File Systems (Pre).
Aug 05 22:39:30 C2 systemd[1]: Stopped Create Static Device Nodes in /dev.
Aug 05 22:39:30 C2 systemd[1]: Stopped Remount Root and Kernel File Systems.
Aug 05 22:39:30 C2 systemd[1]: Reached target Shutdown.
Aug 05 22:39:30 C2 systemd[1]: Reached target Final Step.
Aug 05 22:39:30 C2 systemd[1]: Starting Reboot...
Aug 05 22:39:30 C2 systemd[1]: Shutting down.
Aug 05 22:39:30 C2 systemd[1]: Hardware watchdog 'iTCO_wdt', version 0
Aug 05 22:39:30 C2 systemd[1]: Set hardware watchdog to 10min.
Aug 05 22:39:30 C2 kernel: watchdog: watchdog0: watchdog did not stop!
Aug 05 22:39:30 C2 kernel: systemd-shutdow: 36 output lines suppressed due to ratelimiting
Aug 05 22:39:30 C2 systemd-shutdown[1]: Sending SIGTERM to remaining processes...
Aug 05 22:39:30 C2 systemd-journald[243]: Journal stopped
I also took a look at the session-status

Code: Select all

loginctl session-status c2
using the debug terminal while the delay was happening. It looks like as if Xorg is what's holding it back.

Code: Select all

c2 - Debian-gdm (120)
	   Since: Sat 2017-08-05 22:32:39 EDT; 5min ago
	  Leader: 1061
	    Seat: seat0; vc1
	     TTY: /dev/tty1
	 Service: gdm-launch-environment; type x11; class greeter
	   State: closing
	    Unit: session-c2.scope
		  `-1081 /usr/lib/xorg/Xorg vt1 -displayfd 3 -auth /run/user/120/gdm/Xauthority -background none -noreset -keeptty -verbose 3

Aug 05 22:32:50 C2 /usr/lib/gdm3/gdm-x-session[1079]: (**) Option "fd" "43"
Aug 05 22:32:50 C2 /usr/lib/gdm3/gdm-x-session[1079]: (**) Option "fd" "44"
Aug 05 22:32:50 C2 /usr/lib/gdm3/gdm-x-session[1079]: (**) Option "fd" "43"
Aug 05 22:32:50 C2 /usr/lib/gdm3/gdm-x-session[1079]: (II) systemd-logind: got pause for 13:65
Aug 05 22:32:50 C2 /usr/lib/gdm3/gdm-x-session[1079]: (II) systemd-logind: got pause for 13:67
Aug 05 22:32:50 C2 /usr/lib/gdm3/gdm-x-session[1079]: (II) systemd-logind: got pause for 13:66
Aug 05 22:32:50 C2 /usr/lib/gdm3/gdm-x-session[1079]: (II) systemd-logind: got pause for 13:68
Aug 05 22:32:50 C2 /usr/lib/gdm3/gdm-x-session[1079]: (II) systemd-logind: got pause for 13:64
Aug 05 22:32:50 C2 /usr/lib/gdm3/gdm-x-session[1079]: (II) systemd-logind: got pause for 13:69
Aug 05 22:37:59 C2 systemd[1]: Stopping Session c2 of user Debian-gdm.
And the jobs taking place during the delay

Code: Select all

systemctl list-jobs

Code: Select all

 JOB UNIT                                                          TYPE  STATE  
1477 systemd-user-sessions.service                                 stop  waiting
1557 remote-fs.target                                              stop  waiting
1537 systemd-tmpfiles-setup-dev.service                            stop  waiting
1515 cups.path                                                     stop  waiting
1548 nfs-client.target                                             stop  waiting
1509 cryptsetup.target                                             stop  waiting
1576 remote-fs-pre.target                                          stop  waiting
1589 final.target                                                  start waiting
1496 wpa_supplicant.service                                        stop  waiting
1577 systemd-modules-load.service                                  stop  waiting
1463 user@120.service                                              stop  running
1533 systemd-remount-fs.service                                    stop  waiting
1473 local-fs-pre.target                                           stop  waiting
1512 systemd-sysctl.service                                        stop  waiting
1456 systemd-reboot.service                                        start waiting
1579 umount.target                                                 start waiting
1490 sockets.target                                                stop  waiting
1483 systemd-update-utmp.service                                   stop  waiting
1521 cups.socket                                                   stop  waiting
1480 systemd-logind.service                                        stop  waiting
1517 pcscd.socket                                                  stop  waiting
1458 user.slice                                                    stop  waiting
1503 system-systemd\x2dfsck.slice                                  stop  waiting
1562 paths.target                                                  stop  waiting
1582 mnt-ramdisk.mount                                             stop  waiting
1470 systemd-tmpfiles-setup.service                                stop  waiting
1464 session-c2.scope                                              stop  running
1491 dbus.socket                                                   stop  waiting
1462 user-120.slice                                                stop  waiting
1455 reboot.target                                                 start waiting
1478 nss-user-lookup.target                                        stop  waiting
1500 NetworkManager.service                                        stop  waiting
1563 systemd-random-seed.service                                   stop  waiting
1581 run-user-120.mount                                            stop  waiting
1504 systemd-fsck@dev-dis…\x2d4862\x2da590\x2df319ecf70fb3.service stop  waiting
1507 local-fs.target                                               stop  waiting
1568 sysinit.target                                                stop  waiting
1551 avahi-daemon.socket                                           stop  waiting
1584 tmp.mount                                                     stop  waiting
1482 systemd-ask-password-plymouth.path                            stop  waiting
1505 home.mount                                                    stop  waiting
1508 systemd-ask-password-wall.path                                stop  waiting
1495 dbus.service                                                  stop  waiting
1574 uuidd.socket                                                  stop  waiting
1534 swap.target                                                   stop  waiting
1527 syslog.socket                                                 stop  waiting
1526 systemd-timesyncd.service                                     stop  waiting
1522 basic.target                                                  stop  waiting
1457 shutdown.target                                               start waiting
1535 networking.service                                            stop  waiting
1541 slices.target                                                 stop  waiting
1561 network.target                                                stop  waiting

52 jobs listed.
I have a log of a "good" shutdown (i.e. one where the 90 second delay didn't appear - it's random!) available here.

Here's a bug report of the same issue from Red Hat users also using Gnome (except that they get the "stop job" message and I don't). It remains unfixed.

It's worth mentioning that this issue DOES NOT occur if I first logout my account and then shutdown the computer from the login screen. I've tried some of the fixes mentioned on the internet (e.g. disabling coredump, using X instead of Wayland for GDM) without success. Any suggestions about what I should do next?
Last edited by spsx272 on 2017-08-08 01:14, edited 2 times in total.

lbuiyzxl
Posts: 66
Joined: 2017-05-11 08:35

Re: 90 second shutdown delay after upgrading to Stretch

#2 Post by lbuiyzxl »

I experience same(or similar) random shutdown delay problem.
I no found why,but I solved this problem by change following file:
/etc/systemd/user.conf
/etc/systemd/system.conf

uncomment "DefaultTimeoutStopSec" and set it to your want value.
Last edited by lbuiyzxl on 2017-10-30 16:50, edited 1 time in total.
I'm sorry for my bad English skills
I'm don't want to be a nuisance.

spsx272
Posts: 8
Joined: 2017-02-21 03:00

Re: 90 second shutdown delay after upgrading to Stretch

#3 Post by spsx272 »

I'm aware that I can change the delay, the problem is that this isn't really a fix but more in the sense of "looking the other way" and not attacking the problem directly. There's something wrong here, whether it's a bug in an unknown component or some issues with my current configuration.

spsx272
Posts: 8
Joined: 2017-02-21 03:00

Re: 90 second shutdown delay after upgrading to Stretch

#4 Post by spsx272 »

I disabled at-spi-dbus-bus.service (I ended up renaming the .service file in /user/lib/systemd/user to do so, your command didn't work as root since it's a user service and disabling it as a regular user caused it to reappear at reboot). Unfortunately, the issue still persists with the computer having to kill Xorg after the 90 second wait. Obviously, the lines regarding the accessiblilty bus timing out have disappeared from the journal since that service has been removed.

Here's an excerpt of the journal, with the complete log available here.

Code: Select all

Aug 07 20:50:25 C2 systemd[1]: Stopped GNOME Display Manager.
Aug 07 20:50:25 C2 systemd[1]: Starting Show Plymouth Reboot Screen...
Aug 07 20:50:25 C2 systemd[1]: Stopped /etc/rc.local Compatibility.
Aug 07 20:50:25 C2 systemd[1]: Stopped target Network is Online.
Aug 07 20:50:25 C2 systemd[1]: Stopped Network Manager Wait Online.
Aug 07 20:50:25 C2 systemd[1]: Received SIGRTMIN+20 from PID 2646 (plymouthd).
Aug 07 20:50:25 C2 systemd[1]: Started Show Plymouth Reboot Screen.
Aug 07 20:50:25 C2 systemd[1]: Stopped RealtimeKit Scheduling Policy Service.
Aug 07 20:50:25 C2 /usr/lib/gdm3/gdm-x-session[1164]: (II) NVIDIA(GPU-0): Deleting GPU-0
Aug 07 20:50:25 C2 /usr/lib/gdm3/gdm-x-session[1164]: (WW) xf86CloseConsole: KDSETMODE failed: Input/output error
Aug 07 20:50:25 C2 /usr/lib/gdm3/gdm-x-session[1164]: (WW) xf86CloseConsole: VT_GETMODE failed: Input/output error
Aug 07 20:50:25 C2 /usr/lib/gdm3/gdm-x-session[1164]: (WW) xf86CloseConsole: VT_ACTIVATE failed: Input/output error
Aug 07 20:50:25 C2 /usr/lib/gdm3/gdm-x-session[1164]: (II) Server terminated successfully (0). Closing log file.
Aug 07 20:50:25 C2 systemd[1]: Stopped Session 3 of user system.
Aug 07 20:50:25 C2 systemd[1]: Removed slice User Slice of system.
Aug 07 20:50:25 C2 systemd-logind[566]: Removed session 3.
Aug 07 20:50:25 C2 systemd[1]: Unmounted /run/user/1000.
Aug 07 20:51:55 C2 systemd[1]: session-c2.scope: Stopping timed out. Killing.
Aug 07 20:51:55 C2 systemd[1]: session-c2.scope: Killing process 1075 (Xorg) with signal SIGKILL.
Aug 07 20:51:55 C2 kernel: nvidia-modeset: Freed GPU:0 (GPU-f46a9fa1-e13e-5c6a-4b2e-746f0126ccba) @ PCI:0000:01:00.0
Aug 07 20:51:55 C2 systemd[1]: Stopped Session c2 of user Debian-gdm.
Aug 07 20:51:55 C2 systemd[1]: session-c2.scope: Unit entered failed state.
Aug 07 20:51:55 C2 systemd[1]: Removed slice User Slice of Debian-gdm.
Aug 07 20:51:55 C2 systemd[1]: Stopping Login Service...
Aug 07 20:51:55 C2 systemd[1]: Stopping Permit User Sessions...
Aug 07 20:51:55 C2 systemd[1]: Stopped Permit User Sessions.
Aug 07 20:51:55 C2 systemd[1]: Stopped target Remote File Systems.
Aug 07 20:51:55 C2 systemd[1]: Stopped target Remote File Systems (Pre).
Aug 07 20:51:55 C2 systemd[1]: Stopped target NFS client services.
Aug 07 20:51:55 C2 systemd[1]: Stopped target Network.
Aug 07 20:51:55 C2 systemd[1]: Stopping Network Manager...
Aug 07 20:51:55 C2 NetworkManager[582]: <info>  [1502153515.4981] caught SIGTERM, shutting down normally.
Aug 07 20:51:55 C2 systemd[1]: Stopping Raise network interfaces...
Aug 07 20:51:55 C2 systemd[1]: Stopping WPA supplicant...
Aug 07 20:51:55 C2 systemd[1]: Stopped WPA supplicant.
Aug 07 20:51:55 C2 NetworkManager[582]: <info>  [1502153515.5204] exiting (success)
Aug 07 20:51:55 C2 systemd[1]: Stopped Network Manager.
Aug 07 20:51:55 C2 systemd[1]: Stopping D-Bus System Message Bus...
Aug 07 20:51:55 C2 systemd[1]: Stopped D-Bus System Message Bus.
Aug 07 20:51:55 C2 systemd[1]: Stopped Raise network interfaces.
Aug 07 20:51:55 C2 systemd[1]: Failed to propagate agent release message: Transport endpoint is not connected
Aug 07 20:51:55 C2 systemd[1]: Stopped Login Service.
Aug 07 20:51:55 C2 systemd[1]: Stopped target Basic System.
Aug 07 20:51:55 C2 systemd[1]: Stopped target Sockets.
Aug 07 20:51:55 C2 systemd[1]: Closed PC/SC Smart Card Daemon Activation Socket.
Aug 07 20:51:55 C2 systemd[1]: Closed UUID daemon activation socket.
Aug 07 20:51:55 C2 systemd[1]: Closed Avahi mDNS/DNS-SD Stack Activation Socket.
Aug 07 20:51:55 C2 systemd[1]: Closed Syslog Socket.
Aug 07 20:51:55 C2 systemd[1]: Closed CUPS Scheduler.
Aug 07 20:51:55 C2 systemd[1]: Stopped target Slices.
Aug 07 20:51:55 C2 systemd[1]: Stopped target Paths.
Aug 07 20:51:55 C2 systemd[1]: Stopped CUPS Scheduler.
Aug 07 20:51:55 C2 systemd[1]: Stopped Forward Password Requests to Plymouth Directory Watch.
Aug 07 20:51:55 C2 systemd[1]: Closed D-Bus System Message Bus Socket.
Aug 07 20:51:55 C2 systemd[1]: Removed slice User and Session Slice.
Aug 07 20:51:55 C2 systemd[1]: Stopped target System Initialization.
Aug 07 20:51:55 C2 systemd[1]: Stopping Update UTMP about System Boot/Shutdown...
Aug 07 20:51:55 C2 systemd[1]: Stopped target Encrypted Volumes.
Aug 07 20:51:55 C2 systemd[1]: Stopped Forward Password Requests to Wall Directory Watch.
Aug 07 20:51:55 C2 systemd[1]: Stopping Network Time Synchronization...
Aug 07 20:51:55 C2 systemd[1]: Stopped target Swap.
Aug 07 20:51:55 C2 systemd[1]: Stopped Apply Kernel Variables.
Aug 07 20:51:55 C2 systemd[1]: Stopped Load Kernel Modules.
Aug 07 20:51:55 C2 systemd[1]: Stopping Load/Save Random Seed...
Aug 07 20:51:55 C2 systemd[1]: Stopped target User and Group Name Lookups.
Aug 07 20:51:55 C2 systemd[1]: Stopped Load/Save Random Seed.
Aug 07 20:51:55 C2 systemd[1]: Stopped Update UTMP about System Boot/Shutdown.
Aug 07 20:51:55 C2 systemd[1]: Stopped Network Time Synchronization.
Aug 07 20:51:55 C2 systemd[1]: Stopped Create Volatile Files and Directories.
Aug 07 20:51:55 C2 systemd[1]: Stopped target Local File Systems.
Aug 07 20:51:55 C2 systemd[1]: Unmounting /home/system/gdrive...
Aug 07 20:51:55 C2 systemd[1]: Unmounting /mnt/ramdisk...
Aug 07 20:51:55 C2 systemd[1]: Unmounting /tmp...
Aug 07 20:51:55 C2 systemd[1]: Unmounting /run/user/120...
Aug 07 20:51:55 C2 systemd[1]: Unmounted /mnt/ramdisk.
Aug 07 20:51:55 C2 systemd[1]: Unmounted /run/user/120.
Aug 07 20:51:55 C2 systemd[1]: Unmounted /home/system/gdrive.
Aug 07 20:51:55 C2 systemd[1]: Unmounting /home...
Aug 07 20:51:55 C2 systemd[1]: Unmounted /tmp.
Aug 07 20:51:56 C2 systemd[1]: Unmounted /home.
Aug 07 20:51:56 C2 systemd[1]: Reached target Unmount All Filesystems.
Aug 07 20:51:56 C2 systemd[1]: Stopped File System Check on /dev/disk/by-uuid/9536bca4-419a-4862-a590-f319ecf70fb3.
Aug 07 20:51:56 C2 systemd[1]: Stopped target Local File Systems (Pre).
Aug 07 20:51:56 C2 systemd[1]: Stopped Create Static Device Nodes in /dev.
Aug 07 20:51:56 C2 systemd[1]: Stopped Remount Root and Kernel File Systems.
Aug 07 20:51:56 C2 systemd[1]: Removed slice system-systemd\x2dfsck.slice.
Aug 07 20:51:56 C2 systemd[1]: Reached target Shutdown.
Aug 07 20:51:56 C2 systemd[1]: Reached target Final Step.
Aug 07 20:51:56 C2 systemd[1]: Starting Reboot...
Aug 07 20:51:56 C2 systemd[1]: Shutting down.
Aug 07 20:51:56 C2 systemd[1]: Hardware watchdog 'iTCO_wdt', version 0
Aug 07 20:51:56 C2 systemd[1]: Set hardware watchdog to 10min.
Aug 07 20:51:56 C2 kernel: watchdog: watchdog0: watchdog did not stop!
Aug 07 20:51:56 C2 kernel: systemd-shutdow: 35 output lines suppressed due to ratelimiting
Aug 07 20:51:56 C2 systemd-shutdown[1]: Sending SIGTERM to remaining processes...
Aug 07 20:51:56 C2 systemd-journald[243]: Journal stopped
I also tried reverting to the nvidia-340 driver (since that was the driver I used in Jessie, and stretch has the 375 driver) just in case that had someting to do with Xorg failing. Didn't help.

spsx272
Posts: 8
Joined: 2017-02-21 03:00

Re: 90 second shutdown delay after upgrading to Stretch

#5 Post by spsx272 »

I'm going to file a bug report for this; but the problem is that I have no idea which package I should file the bug against! Does anyone have any suggestions?

User avatar
debiman
Posts: 3063
Joined: 2013-03-12 07:18

Re: 90 second shutdown delay after upgrading to Stretch

#6 Post by debiman »

spsx272 wrote:

Code: Select all

Aug 07 20:50:25 C2 systemd[1]: Unmounted /run/user/1000.
Aug 07 20:51:55 C2 systemd[1]: session-c2.scope: Stopping timed out. Killing.
well it just moved on to the next thing, but "unmounted /run/user/1000" is the common denominator.

spsx272
Posts: 8
Joined: 2017-02-21 03:00

Re: 90 second shutdown delay after upgrading to Stretch

#7 Post by spsx272 »

I switched from gdm to lightdm and the problems disappeared, so that's my current solution for now. A bug report will be later filed with gdm.

lbuiyzxl
Posts: 66
Joined: 2017-05-11 08:35

Re: 90 second shutdown delay after upgrading to Stretch

#8 Post by lbuiyzxl »

spsx272 wrote:I switched from gdm to lightdm and the problems disappeared, so that's my current solution for now. A bug report will be later filed with gdm.
I encounter this same random shutdown problem with lightdm and lxde-core.
So I think this problem not only for gdm (i.e. this problem not a part of gdm)
I'm sorry for my bad English skills
I'm don't want to be a nuisance.

User avatar
None1975
df -h | participant
df -h | participant
Posts: 1387
Joined: 2015-11-29 18:23
Location: Russia, Kaliningrad
Has thanked: 45 times
Been thanked: 64 times

Re: 90 second shutdown delay after upgrading to Stretch

#9 Post by None1975 »

lbuiyzxl wrote:
spsx272 wrote:I switched from gdm to lightdm and the problems disappeared, so that's my current solution for now. A bug report will be later filed with gdm.
I encounter this same random shutdown problem with lightdm and lxde-core.
So I think this problem not only for gdm (i.e. this problem not a part of gdm)
Personally, i never used login manager and never had problems like this :)
OS: Debian 12.4 Bookworm / DE: Enlightenment
Debian Wiki | DontBreakDebian, My config files on github

maciejr
Posts: 1
Joined: 2018-02-01 11:02

Re: 90 second shutdown delay after upgrading to Stretch

#10 Post by maciejr »

I have the same problem on a fresh install of Debian 9.3 (Stretch) with Gnome shell. I am a Linux newbie.

Searching for "failed" in the output of journalctl -b -1 I found some failures 90 seconds before the timeout. I can see the same failures in OP's complete log (link in the post). Here is the relevant part of OP's log:

Code: Select all

Aug 07 20:50:23 C2 gnome-session[1172]: gnome-session-binary[1172]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Aug 07 20:50:23 C2 gnome-session-binary[1172]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Aug 07 20:50:23 C2 gnome-session[1172]: gnome-session-binary[1172]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Aug 07 20:50:23 C2 gnome-session-binary[1172]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Aug 07 20:50:23 C2 gnome-session-binary[1172]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Aug 07 20:50:23 C2 gnome-session-binary[1172]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Aug 07 20:50:23 C2 gnome-session-binary[1172]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Aug 07 20:50:25 C2 gnome-session[1172]: gnome-session-binary[1172]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Aug 07 20:50:25 C2 gnome-session-binary[1172]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Aug 07 20:50:25 C2 gnome-session[1172]: gnome-session-binary[1172]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Aug 07 20:50:25 C2 gnome-session-binary[1172]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Aug 07 20:50:25 C2 gnome-session-binary[1172]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Aug 07 20:50:25 C2 gnome-session[1172]: gnome-session-binary[1172]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Aug 07 20:50:25 C2 gnome-session-binary[1172]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Aug 07 20:50:25 C2 gnome-session[1172]: gnome-session-binary[1172]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Aug 07 20:50:25 C2 gnome-session-binary[1172]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
I get the same two kinds of messages, in a slightly different pattern:

Code: Select all

lut 01 12:14:46 DEB93 gnome-session[781]: gnome-session-binary[781]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
lut 01 12:14:46 DEB93 gnome-session-binary[781]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
lut 01 12:14:46 DEB93 gnome-session[781]: gnome-session-binary[781]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
lut 01 12:14:46 DEB93 gnome-session[781]: gnome-session-binary[781]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
lut 01 12:14:46 DEB93 gnome-session-binary[781]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
lut 01 12:14:46 DEB93 gnome-session-binary[781]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
lut 01 12:14:46 DEB93 gnome-session-binary[781]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
lut 01 12:14:46 DEB93 gnome-session[781]: gnome-session-binary[781]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
lut 01 12:14:46 DEB93 gnome-session-binary[781]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
lut 01 12:14:48 DEB93 gnome-session[781]: gnome-session-binary[781]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
lut 01 12:14:48 DEB93 gnome-session-binary[781]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
lut 01 12:14:48 DEB93 gnome-session[781]: gnome-session-binary[781]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
lut 01 12:14:48 DEB93 gnome-session-binary[781]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
lut 01 12:14:48 DEB93 gnome-session-binary[781]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
lut 01 12:14:48 DEB93 gnome-session-binary[781]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
lut 01 12:14:48 DEB93 gnome-session[781]: gnome-session-binary[781]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
lut 01 12:14:48 DEB93 gnome-session-binary[781]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
So I suppose what happens is: one process is supposed to terminate the session, but cannot get a handle on it. 90 seconds later the session is still not terminated, so it gets killed.

I have found that other users also see these assertions, e.g.:
https://bugs.launchpad.net/ubuntu/+sour ... ug/1582496

However, I am not sure if that link is relevant to the problem we are discussing. I have found many irrelevant posts that mention these assertions. It seems that the assertions themselves are not specific to the shutdown issue, i.e. different issues, caused by different applications, can (and do) make these assertions fail. However here

spsx272
Posts: 8
Joined: 2017-02-21 03:00

Re: 90 second shutdown delay after upgrading to Stretch

#11 Post by spsx272 »

I would like to add that recently I have gotten the problem again with lightdm (the system shut down fine until now), but it occurs much more rarely than it did previously with gdm. I'm too busy now to investigate further, just putting this out there for anyone who might be interested. My logging parameters aren't set to full, so there is less detail (I've upped it for next time).

Code: Select all

Feb 03 18:18:34 C2 gnome-keyring-daemon[1075]: asked to register item /org/freedesktop/secrets/collection/login/10, but it's already registered
Feb 03 18:18:35 C2 gnome-keyring-daemon[1075]: asked to register item /org/freedesktop/secrets/collection/login/10, but it's already registered
Feb 03 18:19:36 C2 gnome-session[1077]: gnome-session-binary[1077]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Feb 03 18:19:36 C2 gnome-session-binary[1077]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Feb 03 18:19:36 C2 gnome-session[1077]: gnome-session-binary[1077]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Feb 03 18:19:36 C2 gnome-session-binary[1077]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Feb 03 18:19:36 C2 gnome-session[1077]: gnome-session-binary[1077]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Feb 03 18:19:36 C2 gnome-session[1077]: gnome-session-binary[1077]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Feb 03 18:19:36 C2 gnome-session-binary[1077]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Feb 03 18:19:36 C2 gnome-session-binary[1077]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Feb 03 18:19:36 C2 gnome-session-binary[1077]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Feb 03 18:19:36 C2 gnome-session[1077]: gnome-session-binary[1077]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Feb 03 18:19:36 C2 gnome-session-binary[1077]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Feb 03 18:19:37 C2 gnome-session[1077]: gnome-session-binary[1077]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Feb 03 18:19:37 C2 gnome-session[1077]: gnome-session-binary[1077]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Feb 03 18:19:37 C2 gnome-session-binary[1077]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Feb 03 18:19:37 C2 gnome-session[1077]: gnome-session-binary[1077]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Feb 03 18:19:37 C2 gnome-session-binary[1077]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Feb 03 18:19:37 C2 gnome-session-binary[1077]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Feb 03 18:19:37 C2 gnome-session-binary[1077]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Feb 03 18:19:37 C2 gnome-session-binary[1077]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Feb 03 18:19:37 C2 gnome-session-binary[1077]: GLib-GObject-CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Feb 03 18:19:37 C2 gnome-settings-[1301]: g_object_notify: object class 'UpClient' has no property named 'g-name-owner'
And I then pressed the hard reset button on my computer because I was short on time. If I get this issue again I'll post the complete log here.

lbuiyzxl
Posts: 66
Joined: 2017-05-11 08:35

Re: 90 second shutdown delay after upgrading to Stretch

#12 Post by lbuiyzxl »

Newly:
Seem 'DefaultTimeoutStopSec' not working for me.
Maybe another workaround is:

Code: Select all

sync;reboot -f
I'm sorry for my bad English skills
I'm don't want to be a nuisance.

kevinthefixer
Posts: 190
Joined: 2018-05-05 22:30

Re: 90 second shutdown delay after upgrading to Stretch

#13 Post by kevinthefixer »

I have the same symptoms, but mine does it more often than not, and I can pinpoint the problem because it started as soon as I set up samba client. It seems there is no shutdown script to unmount network filesystems. I found an article on the problem, but I can't locate it now, and it seems to have been written for Jessie; some of the files/folders I was supposed to modify don't exist in Stretch. I've just been living with it until someone rewrites that article or something else comes up--like this thread!

kevinthefixer
Posts: 190
Joined: 2018-05-05 22:30

Re: 90 second shutdown delay--Solution

#14 Post by kevinthefixer »

OK, got it sorted, and fixed, at least for me. Found the article that pointed me to NetworkManager here:
https://linuxnewbieguide.org/how-to-mou ... rmanently/
But not only is it old, it's aimed at Ubuntu. Nonetheless it did allow me to pinpoint the problem, NetworkManager runs its shutdown scripts before the system unmounts filesystems. However, NetworkManager has a built-in mechanism for running scripts before it downs the net interface(s); simply place a script in /etc/NetworkManager/dispatcher.d/pre-down.d. So I created the file nfs-umount.sh with this content:

Code: Select all

umount -a -t cifs
exit
and placed it there as root. I was proud of myself, I even remembered to

Code: Select all

chmod +x nfs-umount.sh
Note that the chmod doesn't take effect until a reboot, dunno why. But my system now shuts down in less than 5 seconds instead of the 95 that was the usual.

kevinthefixer
Posts: 190
Joined: 2018-05-05 22:30

Re: 90 second shutdown delay after upgrading to Stretch

#15 Post by kevinthefixer »

Perhaps I spoke too soon. Seems it's only fixed when running wired internet connection. Seems the shutdown scripts turn off the wi-fi radio before it gets to NetManager, leaving the same problem. Of course a portable computer isn't much good if it requires a cord. If/when I find a fix I'll add it here. But after all, it isn't really much of a problem, I can just walk away and it shuts down eventually anyway. It's rare I need to reboot it.

mrkapqa
Posts: 181
Joined: 2014-04-22 08:30

Re: 90 second shutdown delay after upgrading to Stretch

#16 Post by mrkapqa »

i noticed this too on my side when upgrading once jessie to stretch.


what about the 5 sec. delay when running apt-get ?

has this been resolved yet?

really very un-debian-like, such a waiting-queue.

Post Reply