systemd-logind triggered poweroffs ignore upstart services

[dann frazier]

systemd-logind has a facility to detect non-ACPI power-off events (e.g. a power button push) and initiate a system shutdown. This facility works in Ubuntu - it manages to shutdown the sysvinit services, but upstart services do not appear to be cleanly shutdown. Among other things, it means that local filesystems don't get properly unmounted.

[Steve Langasek (vorlon)]

Dann, what upstart services fail to be shut down? The last messages shown in your log are from /etc/init.d/sendsigs and /etc/init.d/reboot, which on an upstart system are only ever called via /etc/init/rc.conf, systemd notwithstanding.

[dann frazier (dannf)]

On Mon, Jul 28, 2014 at 3:46 PM, Steve Langasek
<email address hidden> wrote:
> Dann, what upstart services fail to be shut down? The last messages
> shown in your log are from /etc/init.d/sendsigs and /etc/init.d/reboot,
> which on an upstart system are only ever called via /etc/init/rc.conf,
> systemd notwithstanding.

When shutting down by running 'poweroff', I see:

ubuntu@ubuntu:~$ sudo poweroff

Broadcast message from ubuntu@ubuntu
    (/dev/ttyS0) at 18:02 ...

The system is going down for power off NOW!
ubuntu@ubuntu:~$wait-for-state stop/waiting
 * Stopping rsync daemon rsync [ OK ]
 * Asking all remaining processes to terminate... [ OK ]
 * All processes ended within 1 seconds... [ OK ]
 * Deactivating swap... [ OK ]
 * Unmounting local filesystems... [ OK ]
 * Will now halt
[ 46.799956] reboot: Power down

When shutting down via the power button, I see:

ubuntu login: wait-for-state stop/waiting
 * Stopping rsync daemon rsync [ OK ]
 * Asking all remaining processes to terminate... [ OK ]
[ 54.199961] reboot: Power down

So on this system with a minimal install, I'm failing to see evidence
of it deactivating swap or umounting local filesystems.

I should be clear that my bug title is speculation - I saw rsync being
shutdown which I know ships a sysvinit script, but that it missed
doing some other "normal" things that upstart does on shutdown. I
guessed that systemd was triggering shutdown in a manner that only
tickled the sysvinit compat code - but perhaps this is another pid
matching bug in sendsigs or something.

 -dann

[Steve Langasek (vorlon)]

Ok. I don't have a theory as to what would be short-circuiting the tail end of /etc/rc0.d for this case. As far as I can see, logind just calls 'poweroff', which should do the right thing - and certainly, sendsigs should always be followed by umountnfs.sh, networking, umountfs, umountroot, and {halt,reboot}. If these scripts are not being called (as opposed to their output simply not being shown on the console), then that can only be due to something force-halting the system.

Is there any chance you could capture the output of 'udevadm monitor -e' in this situation? I would like to verify that the udev events are what we expect.

It might also be helpful to locally divert /sbin/reboot with a wrapper that records the args, and the details about the calling process, for later analysis.

[dann frazier (dannf)]

You're right, it is calling /sbin/poweroff, I made a wrapper to see what was going on there as you suggested. While using the wrapper (to prevent an actual poweroff), I noticed:

- 'udevadm monitor -e' logs no events
- No arguments are supplied to /sbin/poweroff
- '/sbin/poweroff' gets called multiple times (I counted 70 times)

Now, I'm not sure what explains the latter, but here's a guess. The event device that systemd-logind is listening to is exposed by the gpio-polled keybard driver, which I believe means that the GPIO line is polled at a regular interval and, if triggered, results in the kernel synthesizing a poweroff keyboard code. Perhaps it generates a new press each time it is polled and found to be asserted.

I also notice that if I make the wrapper a 1-and-done - i.e., I set a flag the first time we're called and turn subsequent /sbin/poweroff calls into no-ops, things behave as expected - swapoffs and umounts before powerdown.

So, it seems like multiple poweroff calls in succession result in the described behavior, is that expected? I wonder if you'd be able to reproduce this by nintendo advantaging a poweroff wrapper that does rapid-fire non-blocking calls to the real poweroff?

We could also experiment with asking the vendor to workaround this in firmware (assuming this is considered a bug) by disabling autorepeat and increase the poll interval to something higher.

[dann frazier (dannf)]

As you mentioned in IRC, this is probably just documented behavior. From reboot(8):

       When called with --force or when in runlevel 0 or 6, this tool invokes
       the reboot(2) system call itself (with REBOOTCOMMAND argument passed)
       and directly reboots the system. Otherwise this simply invokes the
       shutdown(8) tool with the appropriate arguments without passing REBOOT‐
       COMMAND argument.

[Steve Langasek (vorlon)]

Yes, per IRC, this is more or less the expected behavior of both systemd (logind) and upstart (poweroff). It's only the emergent behavior combined with a buggy kernel/hardware button behavior that's surprising.

As noted on IRC, there are three possible solutions:
 1) get the kernel fixed to not produce rapid-fire 'power button' events
 2) adjust logind to not process further poweroff events while one is still running (which requires special knowledge to know this is the case, since 'poweroff' returns immediately)
 3) change 'poweroff' itself to not behave this way when called by logind

I understand you've opted for option 1), which is what I recommended.

I am not closing this bug report as invalid, because while the trigger condition here is a kernel/hardware bug, it's still unexpected behavior that someone hitting the power button twice in quick succession on a server would cause an unclean shutdown, and we should ultimately also fix this via 2) or 3) as well.

[Martin Pitt (pitti)]

This can also be reproduced in QEMU by issuing "system_powerdown" twice in quick succession in the monitor.

[scoopex (ms-ubuntu)]

I also experienced a blocked system every time i shutdown or reboot my Dell Latitude 6530 with ubuntu 14.10 (64bit), after upgrading from 14.04). If i remove the "quiet splash" kernel option from the grub menu, the last message seen is "wait-for-state stop/waiting".

After installing "systemd-sysv" and a final shutdown problem on invoking "halt", the problem seems to be gone (2 reboots and one halt were successful).

[Martin Pitt (pitti)]

Vivid switched to systemd, so this isn't a problem there any more. I added an open utopic task, as that's still affected.