http://bugzilla.suse.com/show_bug.cgi?id=1042933 Thomas Blume changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |systemd-maintainers@suse.de -- You are receiving this mail because: You are on the CC list for the bug.

http://bugzilla.suse.com/show_bug.cgi?id=1042933 http://bugzilla.suse.com/show_bug.cgi?id=1042933#c2 Takashi Iwai changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |bpetkov@suse.com, | |tiwai@suse.com --- Comment #2 from Takashi Iwai --- You certainly love such a weird issue, Boris? :) -- You are receiving this mail because: You are on the CC list for the bug.

http://bugzilla.suse.com/show_bug.cgi?id=1042933 http://bugzilla.suse.com/show_bug.cgi?id=1042933#c5 Thomas Blume changed: What |Removed |Added ---------------------------------------------------------------------------- Flags|needinfo?(thomas.blume@suse | |.com) | --- Comment #5 from Thomas Blume --- (In reply to Borislav Petkov from comment #4)

Can you reproduce if you remove all that hp crap, i.e., "rmmod hpwdt" ?

AFAIR, that module depends on other modules so rmmod them all and then retry.

Hm, the goal of the test is to talk to the watchdog. So, removing the watchdog driver prevents the crash, but also fails the test, because it cannot open the watchdog. -- You are receiving this mail because: You are on the CC list for the bug.

http://bugzilla.suse.com/show_bug.cgi?id=1042933 http://bugzilla.suse.com/show_bug.cgi?id=1042933#c7 --- Comment #7 from Thomas Blume --- (In reply to Borislav Petkov from comment #6)

Well, someone had the brilliant idea to panic the system unconditionally in the hpwdt driver:

hpwdt_pretimeout |-> nmi_panic

nmi_panic(regs, "An NMI occurred. Depending on your system the reason " "for the NMI is logged in any one of the following " "resources:\n" "1. Integrated Management Log (IML)\n" "2. OA Syslog\n" "3. OA Forward Progress Log\n" "4. iLO Event Log");

Apparently, that driver goes down into the BIOS to ask what the NMI reason was but since the test is causing the NMI and doesn't do any special dancing to tell the BIOS that it is a test running and that when asked, the BIOS should reply something so that the watchdog doesn't panic the system, this happens.

But from looking at your testcase again, you only want to ping it once:

ioctl(watchdog_fd, WDIOC_KEEPALIVE, 0);

and then close it. Right?

No sorry, I left out parts of the code that comes after the call that causes the crash. The full code is: --> r = watchdog_set_timeout(&t); if (r < 0) printf("Failed to open watchdog"); for (i = 0; i < 5; i++) { printf("Pinging..."); r = watchdog_ping(); if (r < 0) printf("Failed to ping watchdog: %m", r); usleep(t/2); } watchdog_close(true); return 0; --<

If so, from looking at the code, it apparently expects a magical 'V' written to /dev/watchdog so that when you close /dev/watchdog (or your test exists) it will stop the timer and won't trigger an NMI.

So, IINM, if you write a 'V' at the end of open_watchdog(), it should work. Alternatively, you can simply send it WDIOS_DISABLECARD flag with WDIOC_SETOPTIONS and it'll stop the watchdog timer too.

Thanks for the hints, this seems to be included in the watchdog_close function: --> void watchdog_close(bool disarm) { [...] if (disarm) { int flags; /* Explicitly disarm it */ flags = WDIOS_DISABLECARD; r = ioctl(watchdog_fd, WDIOC_SETOPTIONS, &flags); if (r < 0) log_warning_errno(errno, "Failed to disable hardware watchdog: %m"); /* To be sure, use magic close logic, too */ for (;;) { static const char v = 'V'; if (write(watchdog_fd, &v, 1) > 0) break; if (errno != EINTR) { log_error_errno(errno, "Failed to disarm watchdog timer: %m"); break; } } --< Still, the kernel panics in watchdog_set_timeout, e.g. before watchdog_close is reached. I saw another message on the console like: "unexpected close, not stopping watchdog" So, I guess this is the reason why the watchdog timer expires, triggering the panic. However, this seems to be a bug in the systemd testcode, not a kernel issue. Thanks for the background, I tanking back this bug.

I still fail to see what this is then even testing but whatever...

The test was introduced with this commit: --> commit e96d6be763014be75d480fde503d0b77f41194a0 Author: Lennart Poettering Date: Thu Apr 5 22:08:10 2012 +0200 systemd: add hardware watchdog support This adds minimal hardware watchdog support to PID 1. The idea is that PID 1 supervises and watchdogs system services, while the hardware watchdog is used to supervise PID 1. This adds two hardware watchdog configuration options, for the runtime watchdog and for a shutdown watchdog. The former is active during normal operation, the latter only at reboots to ensure that if a clean reboot times out we reboot nonetheless. If the runtime watchdog is enabled PID 1 will automatically wake up at half the configured interval and write to the watchdog daemon. [...] --< -- You are receiving this mail because: You are on the CC list for the bug.

http://bugzilla.suse.com/show_bug.cgi?id=1042933 http://bugzilla.suse.com/show_bug.cgi?id=1042933#c8 --- Comment #8 from Takashi Iwai --- Some details are written in http://0pointer.de/blog/projects/watchdog.html -- You are receiving this mail because: You are on the CC list for the bug.

http://bugzilla.suse.com/show_bug.cgi?id=1042933 http://bugzilla.suse.com/show_bug.cgi?id=1042933#c10 --- Comment #10 from Thomas Blume --- (In reply to Borislav Petkov from comment #9)

...

So, I guess this is the reason why the watchdog timer expires, triggering the panic.

So I still am unclear as to why exactly the NMI fires. The test sets the watchdog timeout to 10 seconds. That would mean, the test runs for longer than 10 seconds, yes?

You hit the nail. The watchdog test takes ages. Increasing the timeout to 100s let the test succeeds: --> teviot:/systemd-testsuite/run # ./test-watchdog Hardware watchdog 'HPE iLO2+ HW Watchdog Timer', version 0 Set hardware watchdog to 1min 40s. Pinging... Pinging... [ 5266.922072] systemd-journald[401]: Sent WATCHDOG=1 notification. Pinging... [ 5336.922068] systemd-journald[401]: Sent WATCHDOG=1 notification. Pinging... Pinging... [ 5446.922087] systemd-journald[401]: Sent WATCHDOG=1 notification. teviot:/systemd-testsuite/run # --< The only question is now why it takes so long on SUSE whereas on RH/Debian 10s are apparently sufficient. -- You are receiving this mail because: You are on the CC list for the bug.

http://bugzilla.suse.com/show_bug.cgi?id=1042933 http://bugzilla.suse.com/show_bug.cgi?id=1042933#c12 Thomas Blume changed: What |Removed |Added ---------------------------------------------------------------------------- Flags| |needinfo?(bpetkov@suse.com) --- Comment #12 from Thomas Blume --- (In reply to Borislav Petkov from comment #11)

(In reply to Thomas Blume from comment #10)

...

You hit the nail. The watchdog test takes ages.

I C.

...

The only question is now why it takes so long on SUSE whereas on RH/Debian 10s are apparently sufficient.

Add more debugging output :-)

Here is a summary of my findings: The code sets the watchdog timeout and then does a loop for pinging the watchdog 5 times. On each iteration it sleeps for half of the watchdog timeout. The watchdog_ping function opens the watchdog but doesn't call watchdog_close after the ping is finished. Only the watchdog_close function contains the code to stop the watchdog timer with the methods mentioned in commment#6. This function is called only after the loop has finished which summarizes to a minimum time of 5*watchdog_timeout/2 for the test. Obviously this much too high for the timeout. Boris, I'm wondering when exactly the watchdog timer starts counting down. Is it when opening /dev/watchdog or when doing the ping (ioctl(watchdog_fd, WDIOC_KEEPALIVE, 0) or something else? -- You are receiving this mail because: You are on the CC list for the bug.

http://bugzilla.suse.com/show_bug.cgi?id=1042933 http://bugzilla.suse.com/show_bug.cgi?id=1042933#c16 --- Comment #16 from Thomas Blume --- (In reply to Borislav Petkov from comment #15)

pr_err("%s: NMI raised\n", __func__);

//tblume: suppress NMI return NMI_HANDLED;

so that we can see when it hits.

Ok, now I get this: --> teviot:~ # /systemd-testsuite/run/test-watchdog Hardware watchdo[ 356.497530] hpwdt: tblume: reload variable is: 234 [ 356.497597] hpwdt: tblume: New timer passed in is 10 seconds g 'HPE iLO2+ HW [ 356.499686] hpwdt: tblume: reload variable is: 78 Watchdog Timer',[ 356.499717] hpwdt: tblume: reload variable is: 78 version 0 Set [ 356.500778] hpwdt: tblume: reload variable is: 78 hardware watchdog to 10s. Pinging... [ 356.501780] hpwdt: tblume: reload variable is: 78 [ 357.745055] hpwdt: hpwdt_pretimeout: NMI raised Pinging... [ 361.502857] hpwdt: tblume: reload variable is: 78 Pinging... Pinging... [ 366.502937] hpwdt: tblume: reload variable is: 78 [ 371.504020] hpwdt: tblume: reload variable is: 78 [ 371.508413] systemd-journald[363]: Sent WATCHDOG=1 notification. Pinging... [ 376.505052] hpwdt: tblume: reload variable is: 78 --< I also found that the NMI is only raised at the first test run after reboot. Wen I repeat the test, there is no more NMI and the ping just succeeds - until the next reboot. -- You are receiving this mail because: You are on the CC list for the bug.

http://bugzilla.suse.com/show_bug.cgi?id=1042933 http://bugzilla.suse.com/show_bug.cgi?id=1042933#c18 --- Comment #18 from Thomas Blume --- (In reply to Borislav Petkov from comment #17)

Can you disable the watchdog before you run the test:

# echo 0 > /proc/sys/kernel/nmi_watchdog

as root.

See if the NMI gets raised still.

Yes, the NMI is still visible.

If it does, do this:

static void hpwdt_ping(void) { iowrite16(reload, hpwdt_timer_reg);

pr_err("%s: reload: %d, time left: %d\n", __func__, reload, hpwdt_time_left()); }

so that we can see what *actually* gets written into the timer each time.

Sorry, that took a while since I got some compile errors. That's fixed now and I get this: --> teviot:~ # modprobe -r hpwdt teviot:~ # teviot:~ # teviot:~ # insmod /usr/src/linux-4.11.4-1/drivers/watchdog/hpwdt.ko [ 69.481330] hpwdt: no symbol version for module_layout [ 69.482380] hpwdt: loading out-of-tree module taints kernel. [ 69.484632] hpwdt: tblume: New timer passed in is 30 seconds [ 69.485922] hpwdt 0000:00:04.0: HPE Watchdog Timer Driver: NMI decoding initialized, allow kernel dump: ON (default = 1/ON) [ 69.488473] hpwdt 0000:00:04.0: HPE Watchdog Timer Driver: 1.4.0, timer margin: 30 seconds (nowayout=0). teviot:~ # teviot:~ # teviot:~ # /systemd-testsuite/run/test-watchdog [ 78.964690] hpwdt: hpwdt_ping: reload: 234, time left: 29 Hardware watchdo[ 78.965863] hpwdt: tblume: New timer passed in is 10 seconds g 'HPE iLO2+ HW [ 78.967012] hpwdt: hpwdt_ping: reload: 78, time left: 9 Watchdog Timer',[ 78.968197] hpwdt: hpwdt_ping: reload: 78, time left: 9 version 0 Set [ 78.969320] hpwdt: hpwdt_ping: reload: 78, time left: 9 hardware watchdo[ 78.970401] hpwdt: hpwdt_ping: reload: 78, time left: 9 g to 10s. Pinging... [ 80.213826] hpwdt: hpwdt_pretimeout: NMI raised Pinging... [ 83.971642] hpwdt: hpwdt_ping: reload: 78, time left: 9 Pinging... [ 88.972910] hpwdt: hpwdt_ping: reload: 78, time left: 9 Pinging... [ 93.974104] hpwdt: hpwdt_ping: reload: 78, time left: 9 Pinging... [ 98.975338] hpwdt: hpwdt_ping: reload: 78, time left: 9 [ 98.980675] systemd-journald[367]: Sent WATCHDOG=1 notification. [ 103.976561] hpwdt: hpwdt_ping: reload: 78, time left: 9 teviot:~ # [ 195.508137] systemd-journald[367]: Sent WATCHDOG=1 notification. --<

Also, the third thing to try is try to reproduce on another HP box. Maybe this one's hpwdt BIOS crap is busted (wouldn't be a stretch).

Ok, trying to find another one for a second reproducer. -- You are receiving this mail because: You are on the CC list for the bug.

http://bugzilla.suse.com/show_bug.cgi?id=1042933 http://bugzilla.suse.com/show_bug.cgi?id=1042933#c20 --- Comment #20 from Thomas Blume --- (In reply to Borislav Petkov from comment #19)

...

Ok, trying to find another one for a second reproducer.

Yeah, that would be a good idea.

I could reproduce the NMI on a second machine: --> ettrick:~ # ettrick:~ # insmod -f /usr/src/linux-4.11.7-1/drivers/watchdog/hpwdt.ko [ 3605.252817] hpwdt: module_layout: kernel tainted. [ 3605.254047] Disabling lock debugging due to kernel taint [ 3605.255254] hpwdt: loading out-of-tree module taints kernel. [ 3605.261819] hpwdt: tblume: New timer passed in is 30 seconds [ 3605.263395] hpwdt 0000:01:04.0: HPE Watchdog Timer Driver: NMI decoding initialized, allow kernel dump: ON (default = 1/ON) [ 3605.266632] hpwdt 0000:01:04.0: HPE Watchdog Timer Driver: 1.4.0, timer margin: 30 seconds (nowayout=0). ettrick:~ # ettrick:~ # /systemd-testsuite/run/test-watchdog [ 3619.636192] hpwdt: tblume: New timer passed in is 10 seconds Hardware watchdog 'HPE iLO2+ HW Watchdog Timer', version 0 Set hardware watchdog to 10s. Pinging... [ 3620.881380] hpwdt: hpwdt_pretimeout: NMI raised Pinging... Pinging... Pinging... Pinging... ettrick:~ # --< -- You are receiving this mail because: You are on the CC list for the bug.

http://bugzilla.suse.com/show_bug.cgi?id=1042933 http://bugzilla.suse.com/show_bug.cgi?id=1042933#c25 --- Comment #25 from Borislav Petkov --- (In reply to Jerry Hoemann from comment #24)

In your example, by setting the timeout to 10 seconds, and updating only every 5 seconds, the system should get an NMI sent to it 1 second after your app pings the timer. (the driver implicitly pings once when starting the timer.)

Let me see if I undertstand this correctly: When one programs 10 sec into the watchdog, it will send an NMI after 10 - 9 = 1 seconds due to the pretimeout thing. So in order for the test not to panic the box, one either has to program a timeout T + 9 or disable ASR (if that's even possible). Yes? -- You are receiving this mail because: You are on the CC list for the bug.

http://bugzilla.suse.com/show_bug.cgi?id=1042933 http://bugzilla.suse.com/show_bug.cgi?id=1042933#c28 --- Comment #28 from Jerry Hoemann --- (In reply to Borislav Petkov from comment #27)

(In reply to Jerry Hoemann from comment #26)

...

Proper programming of a watchdog is a bit of an art form.

That's the nice way to put it.

...

Note, the ASR is disabled by default, it must be turned on by an application opening /dev/watchdog etc.,. The ASR can later be explicitly disabled after being previously enabled.

So Thomas' example opens /dev/watchdog. How does one disable the ASR? And while we're disabling things, how can one disable the pretimeout too?

This way you'll have the watchdog behave as one expects it to. Just for the sake of the test.

Thanks.

Sorry, I didn't get an email notification on this comment and didn't see your question until I pulled up the bz to review for the other NMI issue I'm looking into. For HPE hpwdt, the ASR is disabled by writing the "magic" close to /dev/watchdog: E.g: echo V > /dev/watchdog. Re-opening /dev/watchdog will start the timer again. The hpwdt driver doesn't separate the pretimeout feature from ASR feature. So there is no way a user can turn off just the pretimeout NMI and leave the ASR feature enabled. Documentation/watchdog/watchdog-api.txt describes in greater detail both the magic close and the pretimeout feature. -- You are receiving this mail because: You are on the CC list for the bug.