Very slow reboot or shutdown

English Install/Boot/Login
1

I have several machines on 15.3 now. One was a fresh install and others were upgrades from 15.2
I am having a problem shutting down or rebooting. I hit a 1.5 minute shutdown pause quite often. The message is: ending session for user 1000 (me), ending session for user ronnie (also me, same user), or ending session 2 for user ronnie ( I never had a second session open)
This did not exist on any of the 15.2 machines. It does occur in at least 2 of the 15.3 machines.
I followed a suggestion from dcurtisfra](https://forums.opensuse.org/member.php/42186-dcurtisfra) on a 15.2 post and edited /etc/systemd/logind.conf to kill user ronnie, which did not work after reboot.

Another user in the 15.2 post suggested that removing LVM packages solved his problem, but I do use LVM, so that is not an option.
My drives are basic Luks, formatted in EXT4.

2

I would check the drive as it might be failing. Had a similar issue with long shutdowns that were due to the drive going bad.

3

1,5 minutes (90 sec) seems a systemd service does not close…

So press ESC to see, what is going on.

4

I think it is a user process that does not shutdown when it should.

I use LUKS LVM and ext4. I am not seeing this problem.

I do run a script on logout that does “pulseaudio --kill”. I don’t know if that is why I don’t see this problem.

5

I have never allowed pulse or pipewire to be installed. My last shutdown was quick, but my system was not up for long. The problem seems to occur more often when my system is up for a longer time.

Pressing “esc” is how I saw the messages: "ending session for user “” and it is accompanied by a 1:30 timer. I see no other messages that might indicate which process is not shutting down properly. All processes that I run were also being run on 15.2 before the upgrade, and had no problem.

6

It’s an M.2 drive and it has been verified good by testing with full scan by Mfr’s software.

7

Is it possible that it has something to do with drive caching? I do often move large files and the “write” policy is set to whatever the openSUSE default is. I have 64GB of RAM and the write cache often fills 99% of it.

8

I’m doubting that. Your problem seems to be with user processes, while drive caching is managed by system processes.

9

It may be unrelated, but I’ll mention it since Luks was brought up earlier. When I booted this morning, one of my Luks volumes was not mounted. Upon checking, it no longer had an entry in /dev/mapper. The drive and partition showed up in Yast partitioner, but mounting options were not available. I manually re-created the mapping via cryptsetup and gave it the original name. Once that was done, the partitioner showed the original correct mounting path.

This partition is mounted within my “home” partition, making user “me” the owner. Is it possible the system is having problems releasing that drive, and thus can’t end my session? Also, would it be possible that the mapping of the drive was lost in crypttab and /dev/mapper/ because the drive was forced to stop (after 1:30) before operations were completed? The disk passes diagnostic tests, and these problems did not exist in openSUSE 15.2

10

It’s hard to know. With that information, I would be guessing.

I will note, however, that the 15.3 installer may have set them up a little differently from the 15.2 installer.

After an install, I sometimes edit “/etc/crypttab” to set them up as I want. And if I change anything there, then I make any corresponding changes in “/etc/fstab” and then run “mkinitrd” to regenerate the “initrd”.

11

When trying to diagnose I always rely on journal:

**erlangen:~ #** journalctl -b -7 -u *.target           
-- Journal begins at Sun 2021-07-04 13:18:26 CEST, ends at Wed 2021-07-07 10:05:14 CEST. -- 
Jul 04 13:54:30 erlangen systemd[1]: Stopped target Graphical Interface. 
Jul 04 13:54:30 erlangen systemd[1]: Stopped target Multi-User System. 
Jul 04 13:54:30 erlangen systemd[1]: Stopped target Login Prompts. 
Jul 04 13:54:30 erlangen systemd[1]: Stopped target Sound Card. 
Jul 04 13:54:30 erlangen systemd[1]: Stopped target Timers. 
Jul 04 13:54:30 erlangen systemd[1]: Stopped target Network is Online. 
Jul 04 13:54:32 erlangen systemd[1]: Stopped target System Time Synchronized. 
Jul 04 13:54:32 erlangen systemd[1]: Stopped target System Time Set. 
**Jul 04 13:54:32 erlangen systemd[1]: Stopped target Host and Network Name Lookups. **
**Jul 04 13:56:03 erlangen systemd[1]: Stopped target Basic System. **
Jul 04 13:56:03 erlangen systemd[1]: Stopped target Network. 
Jul 04 13:56:03 erlangen systemd[1]: Stopped target Paths. 
Jul 04 13:56:03 erlangen systemd[1]: Stopped target Remote File Systems. 
Jul 04 13:56:03 erlangen systemd[1]: Stopped target Slices. 
Jul 04 13:56:03 erlangen systemd[1]: Stopped target Sockets. 
Jul 04 13:56:03 erlangen systemd[1]: Stopped target System Initialization. 
Jul 04 13:56:03 erlangen systemd[1]: Stopped target Local Encrypted Volumes. 
Jul 04 13:56:03 erlangen systemd[1]: Stopped target Local Verity Integrity Protected Volumes. 
Jul 04 13:56:03 erlangen systemd[1]: Stopped target Local File Systems. 
**erlangen:~ #**

[noparse]Shutdown obviously hangs for 1:30 minutes. User session fragment from ‘journalctl -b -7 -u user@1000.service’:[/noparse]

Jul 04 13:54:32 erlangen systemd[1200]: Closed Sound System. 
**Jul 04 13:56:02 erlangen systemd[1200]: **app-\x2fusr\x2fbin\x2fkorgac-17b5bada49dd4f33bf9e0ea72e4f3c3e.scope: Stopping timed out. Killing.**
Jul 04 13:56:02 erlangen systemd[1200]: **app-\x2fusr\x2fbin\x2fkorgac-17b5bada49dd4f33bf9e0ea72e4f3c3e.scope: Killing process 1506 (mysqld) with signal SIGKILL.**
Jul 04 13:56:02 erlangen systemd[1200]: **app-\x2fusr\x2fbin\x2fkorgac-17b5bada49dd4f33bf9e0ea72e4f3c3e.scope: Killing process 1525 (mysqld) with signal SIGKILL.**
Jul 04 13:56:03 erlangen systemd[1200]: **app-\x2fusr\x2fbin\x2fkorgac-17b5bada49dd4f33bf9e0ea72e4f3c3e.scope: Failed with result 'timeout'.**
Jul 04 13:56:03 erlangen systemd[1200]: Stopped /usr/bin/korgac. 
Jul 04 13:56:03 erlangen systemd[1200]: **app-\x2fusr\x2fbin\x2fkorgac-17b5bada49dd4f33bf9e0ea72e4f3c3e.scope: Consumed 12.626s CPU time.**
**Jul 04 13:56:03 erlangen systemd[1200]: Removed slice User Application Slice. 
Jul 04 13:56:03 erlangen systemd[1200]: **app.slice: Consumed 14min 51.318s CPU time.**
Jul 04 13:56:03 erlangen systemd[1200]: Reached target Shutdown. 
Jul 04 13:56:03 erlangen systemd[1200]: systemd-exit.service: Deactivated successfully. 
Jul 04 13:56:03 erlangen systemd[1200]: Finished Exit the Session. 
Jul 04 13:56:03 erlangen systemd[1200]: Reached target Exit the Session. 
Jul 04 13:56:03 erlangen systemd[1201]: **pam_warn(systemd-user:setcred): function=[pam_sm_setcred] flags=0x8004 service=[systemd-user] terminal=<unknown>] user=[karl] ruser=<unknown>] rhost=<unknown>]**
Jul 04 13:56:03 erlangen systemd[1]: user@1000.service: Deactivated successfully. 
Jul 04 13:56:03 erlangen systemd[1]: Stopped User Manager for UID 1000. 
Jul 04 13:56:03 erlangen systemd[1]: **user@1000.service: Consumed 14min 52.558s CPU time.**

The above tells me korgac is the culprit.

12

If normal reboot or power-off work, but take a suspiciously long time, for a more detailed log file then:

boot with the debug options:

systemd.log_level=debug systemd.log_target=kmsg log_buf_len=1M enforcing=0

save the following script as “/usr/lib/systemd/system-shutdown/debug.sh” and make it executable:

#!/bin/sh
mount -o remount,rw /
dmesg > /shutdown-log.txt
mount -o remount,ro /

reboot

Check the resulting file shutdown-log.txt

13

On this particular machine, I upgraded from 15.2 and Yast kept the original partitioning and mounting setup. 15.2 on this machine was a fresh install. I originally opened the drives manually with cryptsetup and then instructed Yast Partitioner of the desired path for mounting.

14

No joy:


RYZEN9:~ # journalctl -b -7 -u *.target
Specifying boot ID or boot offset has no effect, no persistent journal was found..

The second command produces identical output.

15

I’m not having any luck with producing the file during shutdown. If I run the script manually, dmesg produces over 5000 lines of output to the file.
Should “systemd.log_target=kmsg” in your debugging options be “target=dmesg”?

16

Trigger persitent journalling and try again: https://forums.opensuse.org/showthread.php/557014-Audio-level-is-too-high-after-startup?p=3049876#post3049876

17

I am not familiar with journalctl enough to know how to modify the switches. Still no luck.


journalctl -b -7 -u *.target
Data from the specified boot (-7) is not available: No such boot ID in journal
18

Run as root: mkdir /var/log/journal
Reboot the machine
Check as root previous boot by running ‘journalctl -b -1 -u *.target’ and post output:

**erlangen:~ #** journalctl -b -1 -u *.target 
-- Journal begins at Sat 2021-07-17 20:44:14 CEST, ends at Sun 2021-07-18 14:42:11 CEST. -- 
Jul 18 12:23:14 erlangen systemd[1]: Reached target System Initialization. 
Jul 18 12:23:14 erlangen systemd[1]: Reached target Paths. 
Jul 18 12:23:14 erlangen systemd[1]: Reached target Basic System. 
Jul 18 12:23:14 erlangen systemd[1]: Reached target Initrd Root Device. 
Jul 18 12:23:14 erlangen systemd[1]: Reached target Remote File Systems (Pre). 
Jul 18 12:23:14 erlangen systemd[1]: Reached target Remote File Systems. 
Jul 18 12:23:14 erlangen systemd[1]: Reached target Initrd Root File System. 
Jul 18 12:23:15 erlangen systemd[1]: Reached target Initrd File Systems. 
Jul 18 12:23:15 erlangen systemd[1]: Reached target Initrd Default Target. 
Jul 18 12:23:15 erlangen systemd[1]: Stopped target Initrd Default Target. 
Jul 18 12:23:15 erlangen systemd[1]: Stopped target Basic System. 
Jul 18 12:23:15 erlangen systemd[1]: Stopped target Initrd Root Device. 
Jul 18 12:23:15 erlangen systemd[1]: Stopped target Paths. 
Jul 18 12:23:15 erlangen systemd[1]: Stopped target Remote File Systems. 
Jul 18 12:23:15 erlangen systemd[1]: Stopped target Remote File Systems (Pre). 
Jul 18 12:23:15 erlangen systemd[1]: Stopped target Slices. 
Jul 18 12:23:15 erlangen systemd[1]: Stopped target Sockets. 
Jul 18 12:23:15 erlangen systemd[1]: Stopped target System Initialization. 
Jul 18 12:23:15 erlangen systemd[1]: Stopped target Swap. 
Jul 18 12:23:15 erlangen systemd[1]: Stopped target Timers. 
Jul 18 12:23:15 erlangen systemd[1]: Stopped target Local File Systems. 
Jul 18 12:23:15 erlangen systemd[1]: Reached target Switch Root. 
Jul 18 12:23:15 erlangen systemd[1]: Reached target Local File Systems (Pre). 
Jul 18 12:23:15 erlangen systemd[1]: Reached target Local File Systems. 
Jul 18 12:23:15 erlangen systemd[1]: Condition check resulted in First Boot Complete being skipped. 
Jul 18 12:23:15 erlangen systemd[1]: Reached target System Initialization. 
Jul 18 12:23:15 erlangen systemd[1]: Reached target Paths. 
Jul 18 12:23:15 erlangen systemd[1]: Reached target Sockets. 
Jul 18 12:23:15 erlangen systemd[1]: Reached target Basic System. 
Jul 18 12:23:16 erlangen systemd[1]: Reached target Network. 
Jul 18 12:23:16 erlangen systemd[1]: Reached target Network is Online. 
Jul 18 12:23:16 erlangen systemd[1]: Reached target Host and Network Name Lookups. 
Jul 18 12:23:16 erlangen systemd[1]: Reached target System Time Synchronized. 
Jul 18 12:23:16 erlangen systemd[1]: Reached target Timers. 
Jul 18 12:23:16 erlangen systemd[1]: Reached target Login Prompts. 
Jul 18 12:23:16 erlangen systemd[1]: Reached target Sound Card. 
Jul 18 12:23:16 erlangen systemd[1]: Reached target Multi-User System. 
Jul 18 12:23:16 erlangen systemd[1]: Reached target Graphical Interface. 
Jul 18 13:31:22 erlangen systemd[1]: Stopped target Graphical Interface. 
Jul 18 13:31:22 erlangen systemd[1]: Stopped target Multi-User System. 
Jul 18 13:31:22 erlangen systemd[1]: Stopped target Login Prompts. 
Jul 18 13:31:22 erlangen systemd[1]: Stopped target Sound Card. 
Jul 18 13:31:22 erlangen systemd[1]: Stopped target Timers. 
Jul 18 13:31:22 erlangen systemd[1]: Stopped target Network is Online. 
Jul 18 13:31:23 erlangen systemd[1]: Stopped target System Time Synchronized. 
Jul 18 13:31:23 erlangen systemd[1]: Stopped target System Time Set. 
Jul 18 13:31:23 erlangen systemd[1]: Stopped target Host and Network Name Lookups. 
Jul 18 13:31:24 erlangen systemd[1]: Stopped target Basic System. 
Jul 18 13:31:24 erlangen systemd[1]: Stopped target Network. 
Jul 18 13:31:24 erlangen systemd[1]: Stopped target Paths. 
Jul 18 13:31:24 erlangen systemd[1]: Stopped target Remote File Systems. 
Jul 18 13:31:24 erlangen systemd[1]: Stopped target Slices. 
Jul 18 13:31:24 erlangen systemd[1]: Stopped target Sockets. 
Jul 18 13:31:24 erlangen systemd[1]: Stopped target System Initialization. 
Jul 18 13:31:24 erlangen systemd[1]: Stopped target Local Encrypted Volumes. 
Jul 18 13:31:24 erlangen systemd[1]: Stopped target Swap. 
Jul 18 13:31:24 erlangen systemd[1]: Stopped target Local Verity Integrity Protected Volumes. 
Jul 18 13:31:24 erlangen systemd[1]: Stopped target Local File Systems. 
**erlangen:~ #**
19

Re-check for any typos. I’ve just carried out that debug procedure and a log file “shutdown-log.txt” (in this case 873k in size) was correctly created in the root direcory.

If I run the script manually, dmesg produces over 5000 lines of output to the file.

The script is not intended to be ran manually, only as part of the systemd shutdown.

Should “systemd.log_target=kmsg” in your debugging options be “target=dmesg”?

No, kmsg is correct.

To reiterate - the procedure is:

  1. boot the system
  2. use the “e” key to enter edit mode during grub loading
  3. append “systemd.log_level=debug systemd.log_target=kmsg log_buf_len=1M enforcing=0” to the end of the kernel command line
  4. F10 to continue booting
  5. after the system has booted create the script file “debug.sh” with the following content:
#!/bin/sh
mount -o remount,rw /
dmesg > /shutdown-log.txt
mount -o remount,ro /
  1. save that file to “usr/lib/systemd/system-shutdown/” and ensure you have made it executable.
  2. re-boot

after that reboot you will find the log file “shutdown-log.txt” in the root directory.

( For reference, the procedure is documented here: Debugging )

20

I’m just checking in. I have the debugging options set and it is creating the “shutdown.txt” file during shutdown. The machine has not had the error during shutdown so far. It usually happens after large file transfers from drive to drive, even if I wait for an extended period after notification that the file transfer is completed.

Apparently “Session 2” of my user is left active if I close a super-user terminal window with the close icon, rather than using the “exit” command.

I doubt the two behaviors are related.

I will post back when I get better data.