Bug 1913734 - Stop RHEL 8.3 / CentOS 8.3 systemd-nspawn container with timeout 120 seconds with message "A stop job is running for User Manager for UID 0"
Summary: Stop RHEL 8.3 / CentOS 8.3 systemd-nspawn container with timeout 120 seconds ...
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Red Hat Enterprise Linux 8
Classification: Red Hat
Component: systemd
Version: 8.4
Hardware: x86_64
OS: Linux
unspecified
high
Target Milestone: rc
: 8.0
Assignee: David Tardon
QA Contact: Frantisek Sumsal
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2021-01-07 13:46 UTC by Gena Makhomed
Modified: 2022-05-19 07:17 UTC (History)
5 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2022-05-19 07:17:27 UTC
Type: Bug
Target Upstream Version:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Bugzilla 1866888 0 unspecified CLOSED Login session cleanup failed from systemd-239-18 to 239-29 (Update CentOS 8.1 to 8.2) 2021-02-22 00:41:40 UTC

Description Gena Makhomed 2021-01-07 13:46:03 UTC
Description of problem:

Stop RHEL 8.3 / CentOS 8.3 systemd-nspawn container with timeout 120 seconds with message "A stop job is running for User Manager for UID 0"

Version-Release number of selected component (if applicable):

systemd-239-41.el8_3.x86_64
systemd-container-239-41.el8_3.x86_64

How reproducible:

always

Steps to Reproduce:

1. install RHEL 8.3 / CentOS 8.3

1.1 disable SELinux

1.2 reboot

2. install systemd-container:

yum install systemd-container

3. create container test:

yum --installroot=/var/lib/machines/test --releasever=8 install systemd vim mc

4. start container test:

machinectl start test

5. enter inside container: // WARNING!!! this step is REQUIRED to reproduce this bug

machinectl shell test

6. logout from container test: 

logout

7. stop container test:

machinectl stop test

8. check in container is still running:

watch machinectl list

Actual results:

After executing command "machinectl stop test" container test will be runned for 120 seconds and will be shutdowned only after 120 seconds timeout.

Expected results:

After executing command "machinectl stop test" expected immediate container shutdown, without 120 seconds timeout.

Additional info:

Container system journal fragment:

Jan 07 14:55:16 test systemd[1]: Stopped D-Bus System Message Bus.
Jan 07 14:55:16 test systemd[1]: console-getty.service: Succeeded.
Jan 07 14:55:16 test systemd[1]: Stopped Console Getty.
Jan 07 14:56:55 test systemd[1]: user@0.service: Processes still around after final SIGKILL. Entering failed mode.
Jan 07 14:56:55 test systemd[1]: user@0.service: Failed with result 'timeout'.
Jan 07 14:56:55 test systemd[1]: Stopped User Manager for UID 0.
Jan 07 14:56:55 test systemd[1]: Stopping /run/user/0 mount wrapper...
Jan 07 14:56:55 test systemd[1]: Removed slice User Slice of UID 0.
Jan 07 14:56:55 test systemd[1]: Stopping Permit User Sessions...
Jan 07 14:56:55 test systemd[1]: run-user-0.mount: Succeeded.
Jan 07 14:56:55 test systemd[1]: Unmounted /run/user/0.
Jan 07 14:56:55 test systemd[1]: systemd-user-sessions.service: Succeeded.
Jan 07 14:56:55 test systemd[1]: Stopped Permit User Sessions.
Jan 07 14:56:55 test systemd[1]: Stopped target Remote File Systems.
Jan 07 14:56:55 test systemd[1]: user-runtime-dir@0.service: Succeeded.
Jan 07 14:56:55 test systemd[1]: Stopped /run/user/0 mount wrapper.

Host system journal fragment:

Jan  7 14:55:16 test-hosting systemd-nspawn[87722]: [  OK  ] Stopped D-Bus System Message Bus.
Jan  7 14:55:16 test-hosting systemd-nspawn[87722]: [  OK  ] Stopped Console Getty.
Jan  7 14:56:55 test-hosting systemd-nspawn[87722]: [  *** ] A stop job is running for User Manager for UID 0 (5s / 1min 39s)#015#033[K[   ***] A stop job is running for User Manager for UID 0 (5s / 1min 39s)#015#033[K[    **] A stop job is running for User Manager for UID 0 (6s / 1min 39s)#015#033[K[     *] A stop job is running for User Manager for UID 0 (6s / 1min 39s)#015#033[K[    **] A stop job is running for User Manager for UID 0 (7s / 1min 39s)#015#033[K[   ***] A stop job is running for User Manager for UID 0 (7s / 1min 39s)#015#033[K[  *** ] A stop job is running for User Manager for UID 0 (8s / 1min 39s)#015#033[K[ ***  ] A stop job is running for User Manager for UID 0 (8s / 1min 39s)#015#033[K[***   ] A stop job is running for User Manager for UID 0 (9s / 1min 39s)#015#033[K[**    ] A stop job is running for User Manager for UID 0 (9s / 1min 39s)#015#033[K[*     ] A stop job is running for User Manager for UID 0 (10s / 1min 39s)#015#033[K[**    ] A stop job is running for User Manager for UID 0 (10s / 1min 39s)#015#033[K[***   ] A stop job is running for User Manager for UID 0 (11s / 1min 39s)#015#033[K[ ***  ] A stop job is running for User Manager for UID 0 (11s / 1min 39s)#015#033[K[  *** ] A stop job is running for User Manager for UID 0 (12s / 1min 39s)#015#033[K[   ***] A stop job is running for User Manager for UID 0 (12s / 1min 39s)#015#033[K[    **] A stop job is running for User Manager for UID 0 (13s / 1min 39s)#015#033[K[     *] A stop job is running for User Manager for UID 0 (13s / 1min 39s)#015#033[K[    **] A stop job is running for User Manager for UID 0 (14s / 1min 39s)#015#033[K[   ***] A stop job is running for User Manager for UID 0 (14s / 1min 39s)#015#033[K[  *** ] A stop job is running for User Manager for UID 0 (15s / 1min 39s)#015#033[K[ ***  ] A stop job is running for User Manager for UID 0 (15s / 1min 39s)#015#033[K[***   ] A stop job is running for User Manager for UID 0 (16s / 1min 39s)#015#033[K[**    ] A stop job is running for User Manager for UID 0 (16s / 1min 39s)#015#033[K[*     ] A stop job is running for User Manager for UID 0 (17s / 1min 39s)#015#033[K[**    ] A stop job is running for User Manager for UID 0 (17s / 1min 39s)#015#033[K[***   ] A stop job is running for User Manager for UID 0 (18s / 1min 39s)#015#033[K[ ***  ] A stop job is running for User Manager for UID 0 (18s / 1min 39s)#015#033[K[  *** ] A stop job is running for User Manager for UID 0 (19s / 1min 39s)#015#033[K[   ***] A stop job is running for User Manager for UID 0 (19s / 1min 39s)#015#033[K[    **] A stop job is running for User Manager for UID 0 (20s / 1min 39s)#015#033[K[     *] A stop job is running for User Manager for UID 0 (20s / 1min 39s)#015#033[K[    **] A stop job is running for User Manager for UID 0 (21s / 1min 39s)#015#033[K[   ***] A stop job is running for User Manager for UID 0 (21s / 1min 39s)#015#033[K[  *** ] A stop job is running for User Manager for UID 0 (22s / 1min 39s)#015#033[K[ ***  ] A stop job is running for User Manager for UID 0 (22s / 1min 39s)#015#033[K[***   ] A stop job is running for User Manager for UID 0 (23s / 1min 39s)#015#033[K[**    ] A stop job is running for User Manager for UID 0 (23s / 1min 39s)#015#033[K[*     ] A stop job is running for User Manager for UID 0 (24s / 1min 39s)#015#033[K[**    ] A stop job is running for User Manager for UID 0 (24s / 1min 39s)#015#033[K[***   ] A stop job is running for User Manager for UID 0 (25s / 1min 39s)#015#033[K[ ***  ] A stop job is running for User Manager for UID 0 (25s / 1min 39s)#015#033[K[  *** ] A stop job is running for User Manager for UID 0 (26s / 1min 39s)#015#033[K[   ***] A stop job is running for User Manager for UID 0 (26s / 1min 39s)#015#033[K[    **] A stop job is running for User Manager for UID 0 (27s / 1min 39s)#015#033[K[     *] A stop job is running for User Manager for UID 0 (27s / 1min 39s)#015#033[K[    **] A stop job is running for User Manager for UID 0 (28s / 1min 39s)#015#033[K[   ***] A stop job is running for User Manager for UID 0 (28s / 1min 39s)#015#033[K[  *** ] A stop job is running for User Manager for UID 0 (29s / 1min 39s)#015#033[K[ ***  ] A stop job is running for User Manager for UID 0 (29s / 1min 39s)#015#033[K[***   ] A stop job is running for User Manager for UID 0 (30s / 1min 39s)#015#033[K[**    ] A stop job is running for User Manager for UID 0 (30s / 1min 39s)#015#033[K[*     ] A stop job is running for User Manager for UID 0 (31s / 1min 39s)#015#033[K[**    ] A stop job is running for User Manager for UID 0 (31s / 1min 39s)#015#033[K[***   ] A stop job is running for User Manager for UID 0 (32s / 1min 39s)#015#033[K[ ***  ] A stop job is running for User Manager for UID 0 (32s / 1min 39s)#015#033[K[  *** ] A stop job is running for User Manager for UID 0 (33s / 1min 39s)#015#033[K[   ***] A stop job is running for User Manager for UID 0 (33s / 1min 39s)#015#033[K[    **] A stop job is running for User Manager for UID 0 (34s / 1min 39s)#015#033[K[     *] A stop job is running for User Manager for UID 0 (34s / 1min 39s)#015#033[K[    **] A stop job is running for User Manager for UID 0 (35s / 1min 39s)#015#033[K[   ***] A stop job is running for User Manager for UID 0 (35s / 1min 39s)#015#033[K[  *** ] A stop job is running for User Manager for UID 0 (36s / 1min 39s)#015#033[K[ ***  ] A stop job is running for User Manager for UID 0 (36s / 1min 39s)#015#033[K[***   ] A stop job is running for User Manager for UID 0 (37s / 1min 39s)#015#033[K[**    ] A stop job is running for User Manager for UID 0 (37s / 1min 39s)#015#033[K[*     ] A stop job is running for User Manager for UID 0 (38s / 1min 39s)#015#033[K[**    ] A stop job is running for User Manager for UID 0 (38s / 1min 39s)#015#033[K[***   ] A stop job is running for User Manager for UID 0 (39s / 1min 39s)#015#033[K[ ***  ] A stop job is running for User Manager for UID 0 (39s / 1min 39s)#015#033[K[  *** ] A stop job is running for User Manager for UID 0 (40s / 1min 39s)#015#033[K[   ***] A stop job is running for User Manager for UID 0 (40s / 1min 39s)#015#033[K[    **] A stop job is running for User Manager for UID 0 (41s / 1min 39s)#015#033[K[     *] A stop job is running for User Manager for UID 0 (41s / 1min 39s)#015#033[K[    **] A stop job is running for User Manager for UID 0 (42s / 1min 39s)#015#033[K[   ***] A stop job is running for User Manager for UID 0 (42s / 1min 39s)#015#033[K[  *** ] A stop job is running for User Manager for UID 0 (43s / 1min 39s)#015#033[K[ ***  ] A stop job is running for User Manager for UID 0 (43s / 1min 39s)#015#033[K[***   ] A stop job is running for User Manager for UID 0 (44s / 1min 39s)#015#033[K[**    ] A stop job is running for User Manager for UID 0 (44s / 1min 39s)#015#033[K[*     ] A stop job is running for User Manager for UID 0 (45s / 1min 39s)#015#033[K[**    ] A stop job is running for User Manager for UID 0 (45s / 1min 39s)#015#033[K[***   ] A stop job is running for User Manager for UID 0 (46s / 1min 39s)#015#033[K[ ***  ] A stop job is running for User Manager for UID 0 (46s / 1min 39s)#015#033[K[  *** ] A stop job is running for User Manager for UID 0 (47s / 1min 39s)#015#033[K[   ***] A stop job is running for User Manager for UID 0 (47s / 1min 39s)#015#033[K[    **] A stop job is running for User Manager for UID 0 (48s / 1min 39s)#015#033[K[     *] A stop job is running for User Manager for UID 0 (48s / 1min 39s)#015#033[K[    **] A stop job is running for User Manager for UID 0 (49s / 1min 39s)#015#033[K[   ***] A stop job is running for User Manager for UID 0 (49s / 1min 39s)#015#033[K[  *** ] A stop job is running for User Manager for UID 0 (50s / 1min 39s)#015#033[K[ ***  ] A stop job is running for User Manager for UID 0 (50s / 1min 39s)#015#033[K[***   ] A stop job is running for User Manager for UID 0 (51s / 1min 39s)#015#033[K[**    ] A stop job is running for User Manager for UID 0 (51s / 1min 39s)#015#033[K[*     ] A stop job is running for User Manager for UID 0 (52s / 1min 39s)#015#033[K[**    ] A stop job is running for User Manager for UID 0 (52s / 1min 39s)#015#033[K[***   ] A stop job is running for User
Jan  7 14:56:55 test-hosting systemd-nspawn[87722]:         Stopping /run/user/0 mount wrapper...
Jan  7 14:56:55 test-hosting systemd-nspawn[87722]: [  OK  ] Removed slice User Slice of UID 0.
Jan  7 14:56:55 test-hosting systemd-nspawn[87722]:         Stopping Permit User Sessions...
Jan  7 14:56:55 test-hosting systemd-nspawn[87722]: [  OK  ] Unmounted /run/user/0.
Jan  7 14:56:55 test-hosting systemd-nspawn[87722]: [  OK  ] Stopped Permit User Sessions.
Jan  7 14:56:55 test-hosting systemd-nspawn[87722]: [  OK  ] Stopped target Remote File Systems.
Jan  7 14:56:55 test-hosting systemd-nspawn[87722]: [  OK  ] Stopped /run/user/0 mount wrapper.

See also bugreport https://bugzilla.redhat.com/show_bug.cgi?id=1866888 for more details of this bug.

Comment 1 Gena Makhomed 2021-09-11 18:02:44 UTC
This bug also reproduces with RHEL 8.4 / CentOS 8.4

Version-Release number of selected component:

systemd-239-45.el8_4.3.x86_64
systemd-container-239-45.el8_4.3.x86_64

Comment 2 David Tardon 2022-05-18 13:46:07 UTC
Does this still happen with 8.6? We've backported some fixes related to user session handling since 8.4.

Comment 3 rhbug 2022-05-18 19:07:00 UTC
This server is running a few systemd-nspawn instances with ssh-sessions to containers and hardware node.

120s timeout on 8.5 reboot:
May 18 19:46:42 server1 systemd[1]: dracut-shutdown.service: Succeeded.
May 18 19:48:41 server1 systemd[1]: user@0.service: State 'stop-sigterm' timed out. Killing.
May 18 19:48:41 server1 systemd[1]: user@0.service: Killing process 5500 (systemd) with signal SIGKILL.
May 18 19:48:41 server1 systemd[1]: user@0.service: Failed with result 'timeout'.
May 18 19:48:41 server1 systemd[1]: Stopped User Manager for UID 0.

No timeout on 8.6 reboot:
May 18 19:56:44 server1 systemd[1]: user@0.service: Succeeded

This is just a quick test but looks good so far. Thanks!

Comment 4 David Tardon 2022-05-19 07:17:27 UTC
Thanks! Let's assume the issue is gone then.


Note You need to log in before you can comment on or make changes to this bug.