Bug 743518

Does "sync && poweroff -f" work reliably?

Created attachment 526449 [details]
List of installed RPM packages

I'm attaching a list of installed RPM packages generated using 

rpm -qa --qf '%{name}-%{version}-%{release}.%{arch}.rpm\n' | sort

(In reply to comment #1)

Yes.

Is it reproducible if you boot with the parameter "single" and try to poweroff from there?
And how about with "emergency"?

(In reply to comment #4)

In single mode everything works correctly.

Please boot with "systemd.log_level=debug systemd.log_target=kmsg rd_NO_PLYMOUTH plymouth.enable=0" on the kernel cmdline. Then shutdown and paste here (or take a photo if necessary) the last output you see on screen when the machine is stuck.

(In reply to comment #6)

Kernel command line: BOOT_IMAGE=/boot/vmlinuz-3.1.0-0.rc8.git0.1.fc16.x86_64 root=UUID=dc19289c-125b-42c1-bf58-6c86ffeb3b22 ro quiet rhgb SYSFONT=ter-u20b LANG=en_US.UTF-8 KEYTABLE=ru systemd.log_level=debug systemd.log_target=kmsg rd_NO_PLYMOUTH plymouth.enable=0

No messages on the screen (after Ctrl+Alt+Del from a text console), the screen is black (I see two unrelated ALSA warning messages).

xorg.log:
...
(II) UnloadModule: "evdev"
(II) Unloading evdev
(II) NOUVEAU(0): Closed GPU channel 2
Server terminated successfully (0). Closing log file.

lxdm.log:
...
** (process:1095): CRITICAL **: QUIT BY SIGNAL
** Message: quit code 0
** Message: exit cb
Server terminated successfully (0). Closing log file.
** Message: free session

messages:
Oct 11 17:29:27 localhost kernel: Kernel logging (proc) stopped.
Oct 11 17:29:27 localhost rsyslogd: [origin software="rsyslogd" swVersion="5.8.5" x-pid="807" x-info="http://www.rsyslog.com"] exiting on signal 15.

That's all. After hard reboot (via a button on the case) / and /home are both in the dirty state: "warning: mounting unchecked fs, running e2fsck is recommended"

/ is indeed very badly "unmounted" :)

e2fsck -D -C 0 -v -t /dev/sda9
e2fsck 1.41.12 (17-May-2010)
ROOT64 was not cleanly unmounted, check forced.
Pass 1: Checking inodes, blocks, and sizes
Deleted inode 655842 has zero dtime.  Fix<y>? yes
Deleted inode 655844 has zero dtime.  Fix<y>? yes
Deleted inode 655846 has zero dtime.  Fix<y>? yes
Deleted inode 655848 has zero dtime.  Fix<y>? yes
Deleted inode 655876 has zero dtime.  Fix<y>? yes

Pass 2: Checking directory structure
Pass 3: Checking directory connectivity
Pass 3A: Optimizing directories
Pass 4: Checking reference counts
Pass 5: Checking group summary information
Block bitmap differences:  -(2661804--2661807) -(2663568--2663572) -(2720703--2720781) -(2765774--2766380)
Fix<y>? yes

Free blocks count wrong for group #81 (3849, counted=3858).
Fix<y>? yes

Free blocks count wrong for group #83 (15515, counted=15594).
Fix<y>? yes

Free blocks count wrong for group #84 (15551, counted=16158).
Fix<y>? yes

Free blocks count wrong (2163597, counted=2164292).
Fix<y>? yes

Inode bitmap differences:  -655842 -655844 -655846 -655848 -655876
Fix<y>? yes

Free inodes count wrong for group #80 (615, counted=620).
Fix<y>? yes

Free inodes count wrong (680368, counted=680373).
Fix<y>? yes

ROOT64: ***** FILE SYSTEM WAS MODIFIED *****

(In reply to comment #7)
> No messages on the screen (after Ctrl+Alt+Del from a text console), the screen
> is black (I see two unrelated ALSA warning messages).

Any chance you could arrange for capturing the debug messages using a serial console or netconsole?

(In reply to comment #9)

That's gonna be difficult if not impossible. My PC lacks COM ports and my PC is the only computer device in my apartment.

So, let's pursue another avenue - is there a way to make sure that upon hitting Ctrl+Alt+Del in a text console systemd does switch to a virtual console where it dumps all the messages?

I'm asking this question because if I reboot from a graphical session, then I always hit this virtual console where systemd shows its shutdown progress. Ostensibly initiating a shutdown sequence from a text console doesn't always lead to the same result.

Maybe there's a way to force systemd to dump its shutdown messages to the same text console from where I called a shutdown sequence?

Try systemd.log_target=console

This package has changed ownership in the Fedora Package Database.  Reassigning to the new owner of this component.

It turns out systemd just hangs (or waits for something) for a whole 30 seconds at some stage of the shutdown process but since I see no meaningful messages on the screen (even in a verbose mode) I cannot say what's happening.

I can upload the entire image of my root filesystem if anyone's interested in debugging this problem in a virtual machine.

During this pause I see nothing on the screen, and when systemd finally awakes it shows:

"Sending TERM signal to remaining processes ..."

then the system reboot/shutdowns almost instantly.

however this pause is killing me as it happens almost every time.

Please follow the method described in this message to capture logs from the shutdown:
http://lists.fedoraproject.org/pipermail/devel/2011-November/158955.html

Created attachment 531928 [details]
shutdown-log.txt.bz2

(In reply to comment #15)

NetworkManager is having trouble quitting:

[   23.597625] systemd[1]: Trying to enqueue job reboot.target/start/replace
...
[   23.598044] systemd[1]: Installed new job NetworkManager.service/stop as 443
...
[   24.138436] systemd[1]: Job network.target/stop finished, result=done
[   24.138509] systemd[1]: NetworkManager.service changed running -> stop-sigterm
...
[   24.147265] NetworkManager[886]: NetworkManager[886]: <warn> disconnected by the system bus.
[   24.147268] NetworkManager[886]: NetworkManager[886]: <info> caught signal 15, shutting down normally.
...
[  114.051313] systemd[1]: NetworkManager.service stopping timed out. Killing.
[  114.051430] systemd[1]: NetworkManager.service changed stop-sigterm -> stop-sigkill
[  114.051444] systemd[1]: Running GC...
[  114.075205] systemd[1]: Received SIGCHLD from PID 886 (NetworkManager).

Apparently NM received the SIGTERM, but it kept running for some reason, until a timeout kicked in and sent a SIGKILL.

This looks like bug 739836.

*** This bug has been marked as a duplicate of bug 739836 ***

Artem, are you able to reproduce the issue? Does it happen every time or just sometimes? Bug 739836 suggest that F16 GOLD is not affected any more.

Are you able to quit NetworkManager with sending NM TERM signal?
# pkill -TERM NetworkManager

glib2 could possible influence this bug, but I don't manage to provoke it on any system.

(In reply to comment #18)

I have reinstalled the system and disabled NetworkManager altogether, so I cannot reproduce this issue, because the faulty component is no longer active. (I have a static Internet connection so using NetworkManager makes no sense).

If I ever reproduce it on a different system, I'll reopen this bug report.