From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.2 (2018-09-13) on inbox.vuxu.org X-Spam-Level: X-Spam-Status: No, score=0.0 required=5.0 tests=RCVD_IN_DNSWL_NONE, UNPARSEABLE_RELAY autolearn=ham autolearn_force=no version=3.4.2 Received: from mail-ed1-f48.google.com (mail-ed1-f48.google.com [209.85.208.48]) by inbox.vuxu.org (OpenSMTPD) with ESMTP id 8ada03d6 for ; Thu, 14 Feb 2019 21:54:13 +0000 (UTC) Received: by mail-ed1-f48.google.com with SMTP id x7so6317577eds.8 for ; Thu, 14 Feb 2019 13:54:13 -0800 (PST) X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:user-agent :mime-version; bh=mzqFfpINwCiyHjDAb0cc55qXWSwAufBRNJksbWoW8Kc=; b=Vzp6ciuJcg9cSLy5oWsvgFANhPrUdT6n4MZz1Sm1J14GViSGpODDPz0fqvJ22+ZAYC 8cpIcRnW0XQt56otARM0BrFwCWAfcqpbDIlC5LlxFKg3Ov161veGuWy/cLV0+EAYftVh p+18ByOuV9cvVD1hWfq9zU+ju/kZqqsCyuAy7T29W0BgiOWNbRmjgXZonhktrma4nRQF x2dY0g84zwFceYMv9d+Zm3ET+0+xTbKjMjZKVU8ikk7vpcw3u3Ubo4hAwUDb94lecT+b XQOW/BK4OHMytJf7QkLBX3eTP91Q3OgdmdDXC7ZvQXkXpCDIaiFIlXGh4iVdXkNoqY7Q OKig== X-Gm-Message-State: AHQUAuYAZD+N48rb5FeRwB25A+ULSbInUNzHrQN6jNxHuDeeXtvR0Dgo 70v9l44DD9QWNOh3qdbBWMv9A3JO X-Google-Smtp-Source: AHgI3IbB0N978wSsYL4nj7oxc1J/g7ZRRH8a4JSg+uK3X+dGJIyYTKRMPchS0Ra/OuY4rN0aTX0juw== X-Received: by 2002:a17:906:95c3:: with SMTP id n3mr712865ejy.59.1550181252100; Thu, 14 Feb 2019 13:54:12 -0800 (PST) Return-Path: Received: from rhea.home.vuxu.org ([2001:7f0:3003:235f:f473:422b:501a:17fd]) by smtp.gmail.com with ESMTPSA id l25sm957563edr.45.2019.02.14.13.54.09 (version=TLS1_2 cipher=ECDHE-RSA-CHACHA20-POLY1305 bits=256/256); Thu, 14 Feb 2019 13:54:10 -0800 (PST) Received: from localhost (rhea.home.vuxu.org [local]) by rhea.home.vuxu.org (OpenSMTPD) with ESMTPA id ac22b5e6; Thu, 14 Feb 2019 21:54:08 +0000 (UTC) From: Leah Neukirchen To: leahutils@inbox.vuxu.org Cc: voidlinux@googlegroups.com Subject: epona.vuxu.org outage post mortem Date: Thu, 14 Feb 2019 22:54:07 +0100 Message-ID: <87mumyvxxc.fsf@vuxu.org> User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/26.1 (gnu/linux) MIME-Version: 1.0 Content-Type: text/plain List-Id: 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 http://leah.zone