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.2 required=5.0 tests=DKIM_SIGNED,DKIM_VALID, DKIM_VALID_AU,DKIM_VALID_EF,FREEMAIL_FROM,RCVD_IN_DNSWL_NONE autolearn=ham autolearn_force=no version=3.4.2 Received: from mail-lf1-x143.google.com (mail-lf1-x143.google.com [IPv6:2a00:1450:4864:20::143]) by inbox.vuxu.org (OpenSMTPD) with ESMTP id 51b7e3a2 for ; Sat, 16 Feb 2019 02:15:10 +0000 (UTC) Received: by mail-lf1-x143.google.com with SMTP id n23so8578579lfl.4 for ; Fri, 15 Feb 2019 18:15:10 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=mime-version:in-reply-to:references:from:date:message-id:subject:to :cc; bh=dTD/n78oWVvBzDFnrGD9HhCvw+1gFpnDOmmOCb60Gcc=; b=OIMBbCBr1pU6SgZDmIUb2l9I1mxegZNGVx7AFF1slw1iukbkhtyRq6yfY48WYXDvtF zArUIxH7TokpISdWP8u0SVc9BObifeBOptsDut9NYnPCOGeHNanxxsMg+kxB/LVeruj9 nTye0/Eder5+Y8xHl7BPptyxiCJcj0z9igml4PwUjAvxRMbY7M5Jo8Tbb1qJ2QrgvyQs ZBriDRwv7QBEKmZy58zdEBYThdH/4ouNT1wO5e4gS3SV49hO1rbxVDUtt7wgJx8qjorm vp7L+GVc0Tgw1LdQy3QYe4LQ0i//+sPsFUlAEMu/7Ew4+qBtWCVaYf152MQmE5LtQK5a wn5Q== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:in-reply-to:references:from:date :message-id:subject:to:cc; bh=dTD/n78oWVvBzDFnrGD9HhCvw+1gFpnDOmmOCb60Gcc=; b=Rae4GdejzE+l28LR5YSAFqZnZHge6uAI6kh6cu/5K+OmCbYnBhgIzPaaHmGBfpUnPy 5M2ZzDaPJUa7lOooiP+asVggxf1AIg8s7ngv170Q63JlCdrrwbAb9OkHkQMdeJZw09Ms JXay+PjhDotQKP4jIic8HIY1W+CCQ6eUHKu4D6J2CVCx7E28vr2zzXf5uSa/OgGUeu8A rClE1+zUxSvFjZAJd8EASQcoe4r5bzJFWZWMcG6LPD/sGn7D1ioU+8YHVeU0WTVKCKfX MnpAWket6QXFNlns86OcrBiUhfPQgS8TDLBMLFhGh2ZtjWDgtj4Luu1s2XiET4c1uo4S pdmg== X-Gm-Message-State: AHQUAuZmxkAC4MW4IxqzyKTzqid/Mp9sc5ohGEaJNUWMsMUDRb3u301R SqiCwLoI6HqLonv94o5jXOPj3j3jtTTe2Hb9T6M= X-Google-Smtp-Source: AHgI3IaesZpIAl/iicwuUkziJLSDUZzWZOiU0Vdh/VH0cctgHMiAmaXw5RKe9DkozsS0usBt7B7Sj5ijqg4kfwS6diU= X-Received: by 2002:a19:c942:: with SMTP id z63mr7128350lff.162.1550283308970; Fri, 15 Feb 2019 18:15:08 -0800 (PST) MIME-Version: 1.0 Received: by 2002:ab3:4e8a:0:0:0:0:0 with HTTP; Fri, 15 Feb 2019 18:15:07 -0800 (PST) In-Reply-To: <87mumyvxxc.fsf@vuxu.org> References: <87mumyvxxc.fsf@vuxu.org> From: Diego Augusto Molina Date: Sat, 16 Feb 2019 02:15:07 +0000 Message-ID: Subject: Re: epona.vuxu.org outage post mortem To: Leah Neukirchen Cc: leahutils@inbox.vuxu.org, voidlinux@googlegroups.com Content-Type: text/plain; charset="UTF-8" List-Id: On 2/14/19, Leah Neukirchen wrote: > > 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. "Oh, no! How could someone possibly drink and sysadmin!" Said no other sysadmin ever. > > 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 > Here's my suggestion: # ss -nlpt | grep 3722 That should include your offending instance of socat listening on TCP 3722, stating the PID that has the resource (a.k.a., the socat process that opened the port). Killing that PID blindly might not always do the trick (e.g. "while true; do socat ...; sleep 1; done") so you may want to kill parents/children too. With that PID in mind use "ps faux" to navigate through the process tree. My way is: # ps faux | grep -vF \[ | less -SRI The grep is to remove kernel processes which drown the output. Bye.