hardkernel / linux

Linux kernel source tree
Other
427 stars 408 forks source link

[XU4] [4.9.51-1-ARCH] systemd-networkd watchdog timeout - network stack seemingly FUBARs #317

Open aphirst opened 6 years ago

aphirst commented 6 years ago

Please feel free to rename/retag this as and when the underlying issue becomes clear

I originally posted this on the rpi tracker but it occurs to me that this issue might not be the same, as I had superficially thought.

My XU4 "server" went down suddenly today, and I was unable to SSH back in. (EDIT: I also couldn't reach the device via ping.) Foolishly I neglected to try UART, and instead just did a power cycle. Afterwards I took some journalctl -xe logs. https://pastebin.com/ZVAgLFJH

It looks as if I was under ssh login bombardment. (I've since reconfigured my firewall, and disabled password login - keys are better anyway.) But as of about line 805, you see this:

Oct 08 18:35:24 alarm kernel: fb_ili9340 spi1.0: I/O Error: rx-0 tx-1 res:rx-p tx-f len-4096
Oct 08 18:35:24 alarm kernel: fb_ili9340 spi1.0: SPI transfer failed: -5
Oct 08 18:35:24 alarm kernel: spi_master spi1: failed to transfer one message from queue
Oct 08 18:35:24 alarm kernel: fb_ili9340 spi1.0: fbtft_update_display: write_vmem failed to update display buffer
Oct 08 18:35:46 alarm kernel: INFO: rcu_preempt detected stalls on CPUs/tasks:
Oct 08 18:35:46 alarm kernel:         4-...: (1 GPs behind) idle=75b/140000000000000/0 softirq=4893732/4893733 fqs=1986
Oct 08 18:35:46 alarm kernel:         (detected by 1, t=4202 jiffies, g=2562895, c=2562894, q=602)
Oct 08 18:35:46 alarm kernel: Task dump for CPU 4:
Oct 08 18:35:46 alarm kernel: kworker/4:0     R  running task        0 30198      2 0x00000002
Oct 08 18:35:46 alarm kernel: Workqueue: events fb_deferred_io_work
Oct 08 18:35:46 alarm kernel: [<c0968994>] (__schedule) from [<00000001>] (0x1)
Oct 08 18:36:38 alarm systemd[1]: systemd-timesyncd.service: Watchdog timeout (limit 3min)!
Oct 08 18:36:38 alarm systemd[1]: systemd-timesyncd.service: Killing process 343 (systemd-timesyn) with signal SIGABRT.
Oct 08 18:36:49 alarm kernel: INFO: rcu_preempt detected stalls on CPUs/tasks:
Oct 08 18:36:49 alarm kernel:         4-...: (1 GPs behind) idle=75b/140000000000000/0 softirq=4893732/4893733 fqs=8125
Oct 08 18:36:49 alarm kernel:         (detected by 0, t=16809 jiffies, g=2562895, c=2562894, q=974)
Oct 08 18:36:49 alarm kernel: Task dump for CPU 4:
Oct 08 18:36:49 alarm kernel: kworker/4:0     R  running task        0 30198      2 0x00000002
Oct 08 18:36:49 alarm kernel: Workqueue: events fb_deferred_io_work
Oct 08 18:36:49 alarm kernel: [<c0968994>] (__schedule) from [<00000001>] (0x1)
Oct 08 18:37:38 alarm systemd[1]: systemd-networkd.service: Watchdog timeout (limit 3min)!
Oct 08 18:37:38 alarm systemd[1]: systemd-networkd.service: Killing process 283 (systemd-network) with signal SIGABRT.
Oct 08 18:37:52 alarm kernel: INFO: rcu_preempt detected stalls on CPUs/tasks:
Oct 08 18:37:52 alarm kernel:         4-...: (1 GPs behind) idle=75b/140000000000000/0 softirq=4893732/4893733 fqs=14073
Oct 08 18:37:52 alarm kernel:         (detected by 1, t=29412 jiffies, g=2562895, c=2562894, q=1116)
Oct 08 18:37:52 alarm kernel: Task dump for CPU 4:
Oct 08 18:37:52 alarm kernel: kworker/4:0     R  running task        0 30198      2 0x00000002
Oct 08 18:37:52 alarm kernel: Workqueue: events fb_deferred_io_work
Oct 08 18:37:52 alarm kernel: [<c0968994>] (__schedule) from [<00000001>] (0x1)
-- Reboot --

At the end, you can see where I pulled the plug, and after that is just the log from a normal boot.

The module mentioned at the top is that for the CloudShell2 LCD panel (which I am indeed using, or at least, I use the CS2 and enabled the LCD via modprobe.conf, though I haven't really set a use for it yet with a custom script).

How should I best proceed from here?

polyzen commented 6 years ago

Had you upgraded openssh and were making use of hmac-ripemd160?

https://github.com/stribika/stribika.github.io/commit/6cb1ee5619d1e4479554fc285156416a9e05f918 https://github.com/stribika/stribika.github.io/issues/46

aphirst commented 6 years ago

Just after I did the hard reboot and just before I decided to start looking into the issue I did a pacman -Syu and got an update to openssh-7.6p1-1.

I don't know what hpac-ripemd is so I don't think I'm using it. But since the upgrade SSH works, so I guess I wasn't?

aphirst commented 6 years ago

It's probably worth mentioning that I also couldn't ping the device, Destination Unreachable was I think the message. I guess @polyzen was thinking that I updated OpenSSH and due to the removal of that algorithm, couldn't log in for that reason.

ardje commented 6 years ago

Kernel bugs that kill the network and ssh are not really related. In this case however, systemd tries to kill systemd-network, which might explain why the network was down, especially if you do not use EUI64 ipv6 link local. All in all it does seem to be pointing at the SPI display driver, after which a single cpu got stuck and probably held all processes run on that cpu hostage.

aphirst commented 6 years ago

@ardje Yeah, the SSH stuff is probably just a red herring (and like I say, shouldn't happen again since I've locked everything down).

In the meantime I've unloaded (and blacklisted) the display driver, but that's clearly not really a solution. Is there any further info I could provide which might help?

ardje commented 6 years ago

I've taken a look at your log. The sshd "pounding" is moot. It's an average ssh port scan that you will see on any reachable ssh server. It's just a friendly reminder to always turn off password authentications and root logins for any unknown networks. For now the only thing that seems to fail is the SPI, which -I assume- probably triggered systemd to kill the network. No, the SPI should not fail, but I also think it did not cause the network outage, the remainder of the system somehow was triggered by that.

aphirst commented 6 years ago

For now the only thing that seems to fail is the SPI, which -I assume- probably triggered systemd to kill the network.

No, the SPI should not fail, but I also think it did not cause the network outage

@ardje This reads a bit strangely, as if it actually contradicts itself, so as a result I'm not sure I understood what you really meant. Could you clarify?

radfish commented 6 years ago

Btw, does 'ip set link down dev eth0' and 'ip set link up dev eth0' bring the network back up? (Assuming you have a serial console where you can type this.) It did in my issue with network stack dying on Odroid U3 in 4.9 and 4.13.

ardje commented 6 years ago

@aphirst : what I meant was that the SPI breakage broke another daemon, at which systemd decided to do a watchdog reboot. So the network was just a symptom of systemd failing to do a watchdog reboot. As an admin I'm always confused of why they kill the network first. It always takes some work to make sure that sshd starts first and stops last and that networking also stops much later.