epona.vuxu.org outage post mortem

[Leah Neukirchen <leah@vuxu.org>]

At 00:20 CET tonight (2019-02-14) epona.vuxu.org, a virtual machine
host that runs, among others, git.vuxu.org/inbox.vuxu.org and
hestia.vuxu.org, the aarch64 builder for Void Linux, went down and
only came up around 11 CET again.

This was entirely my fault, but how it happened is interesting:

I was informed a user-space port forwarding was not working.  It was
realized using socat, supervised by runit (the init system of Void
Linux):

	socat TCP4-LISTEN:3722,fork,su=nobody TCP6:hestia.vuxu.org:22

However, starting this showed the address was already in use:

	2019/02/14 00:20:44 socat[5049] E bind(5, {AF=2 0.0.0.0:3722}, 16): Address already in use

My assumption was there was a runaway instance of socat running (for
unknown reasons), and I decided to kill all socat instances.  My usual
tool of choice would have been `killall socat`, but as there were other
socat instances running on the machine, I only wanted to kill the port
3722 ones.

A quick test with `pgrep` showed a plausible list of PIDs, so I ran

	kill $(pgrep -f socat.*3722)

which seemed to work fine at first.

Several seconds later I was greeted with this message:

	Connection to epona.vuxu.org closed by remote host.
	Connection to epona.vuxu.org closed.

And the box didn't ping anymore...

As experienced SSH user, this indicated that the host shut down in
some controlled way, else I would have gotten a `broken pipe` message.

But how could the `pkill` shut down the machine?  I could not come up
with any plausible theory, but it was already late and there was alcohol
involved as well.  So I decided to leave it at rest until the morning.

In the morning, the box still was not up and there was no evidence of
a network issue or anything.  I decided to enter the Hetzner Control
Panel and trigger an "automated reset".  Nothing changed, the box
still didn't ping.  I tried to activate the "vKVM rescue system", to
no avail.

At this point I actually assumed some hardware issue, and I called for
a "manual reset", which means someone has to get up, walk to the
machine, restart it, and watch a bit whether it seems to boot
properly.

Of course, the true reason was much simpler: the box was powered off.

Unfortuately, nothing about the Hetzner Control Panel shows you this
simple fact, so I guess I'm not the only one to send poor support
folks to go boot other people's machines.

The box booted fine and all services were restored within minutes.

The remaining question is how it's possible that the command shut down
the machine, and it's easy to answer too:
`runsvdir`, the main runit process that controls "stage 2", i.e.
while the system is up, displays error messages of all direct
child processes in it's `argv[0]`, so you can check for unlogged
messages with `ps`:

	runsvdir -P /run/runit/runsvdir/current log: ....logs here....

Unfortunately, in above sitation this resulted in both "socat" and
"3722" to appear in the error messages, and thus the process title,
which made `pkill -f` match it and, as commanded, kill `runsvdir`,
which results in exiting stage 2 and runit performing an orderly
shutdown of the system.  Duh.

Lessons learned:
- The first intuition is often right, even if it's not plausible at first.
- Don't use `pkill -f` as root, at least not without careful checking
  and regexp anchoring.
- If a box doesn't react to reset requests, try sending wake-on-lan to
  turn it on.
- runit should reboot by default, not shutdown!

-- 
Leah Neukirchen  <leah@vuxu.org>  http://leah.zone