Bug 1104792 - magic-sysrq output does not show up on current selected console tty but only in dmesg
magic-sysrq output does not show up on current selected console tty but only ...
Status: REOPENED
Classification: openSUSE
Product: openSUSE Tumbleweed
Classification: openSUSE
Component: Kernel
Current
Other Other
: P5 - None : Normal (vote)
: ---
Assigned To: Petr Mladek
E-mail List
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2018-08-14 11:13 UTC by Oliver Kurz
Modified: 2019-01-11 16:29 UTC (History)
5 users (show)

See Also:
Found By: ---
Services Priority:
Business Priority:
Blocker: ---
Marketing QA Status: ---
IT Deployment: ---


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Oliver Kurz 2018-08-14 11:13:30 UTC
## Observation

Calling "magic-syrq" requests does not show the corresponding output on the current tty but only in the kernel log messages, e.g. seen when calling `dmesg`. This makes the operations that should show output pretty useless when one can not log into the system anymore.


## Steps to reproduce

* Select console tty with "ctrl-alt-f1"
* Press "alt-sysrq-t" to show "current tasks"
* Observe that only the header line is shown, the actual output is hidden in the kernel log files


## Expected result

The output should be shown on the current selected console tty


## Further details

I assume this is a regression and has worked in the past. Crosschecking with openSUSE Leap 42.3 has shown the same behaviour. I crosschecked with Fedora 27: It has the expected result, i.e. showing the output on the current selected console tty
Comment 1 Oliver Kurz 2018-08-14 11:53:59 UTC
Crosschecked SLE12 SP2 which has the expected behaviour, magic-sysrq output is shown on the current selected console tty. I installed SLES 12 SP2 unregistered with the patterns "x11" and "gnome" deselected for faster installation.

Checking with SLE15 (unregistered, hence resulting in minimal system, xfs root, no home), same problem as reported for openSUSE Tumbleweed is true, different than SLE12SP2.
Comment 2 Michal Kubeček 2018-08-15 05:50:46 UTC
AFAICS output of Alt-SysRq-T uses the same level (KERN_INFO) in SLE12-SP2-LTSS
and Tumbleweed. Are you sure you have the threshold (/proc/sys/kernel/printk)
set to the same value on both?
Comment 3 Petr Mladek 2018-08-16 08:32:36 UTC
The visibility of the messages on the console is decided by:

    + console_loglevel, see the first value in /proc/sys/kernel/printk
    + ignore_loglevel, see /sys/module/printk/parameters/ignore_loglevel

The sysrq header line might be seen because the sysrq handler temporary increases console_loglevel when printing this line. But the other messages are printed with the configured console_loglevel.

I personally do not see any regression. I mean that I do _not_ see the sysrq output even on SLE11-SP1 with the default console_loglevel and ignore_loglevel setting. Also I do not see any relevant changes in the code.

Oliver, could you please make sure that proc/sys/kernel/printk and /sys/module/printk/parameters/ignore_loglevel are set the same on your test systems?
Comment 4 Oliver Kurz 2018-10-10 14:58:41 UTC
Please keep in mind that my test systems are all using the default values provided by the installation. I did not change anything there.

What I see:

* openSUSE Leap 42.3: works, /proc/sys/kernel/printk: 4 4 1 7 and /sys/module/printk/parameters/ignore_loglevel: N
* openSUSE Leap 15.0: does not work, 
/proc/sys/kernel/printk: 4 4 1 7 and /sys/module/printk/parameters/ignore_loglevel: N
* SLE 12 SP4 RC2c1 (build 0421, linux 4.12.14-94.38-default): does not work, /proc/sys/kernel/printk: 7(!) 4 1 7 and /sys/module/printk/parameters/ignore_loglevel: N

However, on SLE12SP4 I noticed now one strange thing which I can reproduce on that system but not on my openSUSE Leap 15.0 system: On tty1 When I send sysrq-w it shows only the header line as in the initial report. When I press sysrq-t it shows the message "This sysrq operation is disabled.". However, after this message the next press of sysrq-w shows also the content, not just the header! This works until next reboot (or maybe console switch?).
Comment 5 Oliver Kurz 2018-10-10 15:10:29 UTC
(In reply to Oliver Kurz from comment #4)
> […] When I press sysrq-t it shows the message "This sysrq operation is disabled."

Sorry, that should say "sysrq-l"
Comment 6 Petr Mladek 2019-01-10 15:17:14 UTC
(In reply to Oliver Kurz from comment #4)
> What I see:
> 
> * openSUSE Leap 42.3: works, /proc/sys/kernel/printk: 4 4 1 7 and
> /sys/module/printk/parameters/ignore_loglevel: N

Strange. I see _no_ output with "sysrq-l" openSUSE Leap 42.3 with
the same setting as you.

It is because the console handling is deferred in SUSE's
kernel-4.4 (avoid softlockups, bug 744692). As a result
it does not help to temporarily increase the loglevel
in __handle_sysrq()). The messages are handled later
and filtered by the original loglevel (4).

I wonder why you saw the expected behavior. Have you
tried "sysrq-l" in panic situation or in a normal
system state?


> * openSUSE Leap 15.0: does not work, 
> /proc/sys/kernel/printk: 4 4 1 7 and
> /sys/module/printk/parameters/ignore_loglevel: N

I could see only the sysrq header line here. If I get it
correctly, you saw the same.

It is because the kernel 4.12 prevents the softlockups another way.
The console is deferred only when more CPUs are calling printk
in parallel. The temporary increased loglevel (in __handle_sysrq())
allows to see the header line. The other lines are not visible
because the real handler is called with the original loglevel.


> * SLE 12 SP4 RC2c1 (build 0421, linux 4.12.14-94.38-default): does not work,
> /proc/sys/kernel/printk: 7(!) 4 1 7 and
> /sys/module/printk/parameters/ignore_loglevel: N

I looked at SLE12 SP4 GM default installation. I see the same
behavior as with openSUSE Leap 15.0. The explanation
is the same as well.

Note that I see "1 4 1 7" in /proc/sys/kernel/printk.
The log level "1" is forced by rsyslogd, see the bug #593699.

I am not sure why you saw "7" in rc2c1.


> However, on SLE12SP4 I noticed now one strange thing which I can reproduce
> on that system but not on my openSUSE Leap 15.0 system: On tty1 When I send
> sysrq-w it shows only the header line as in the initial report. When I press
> sysrq-t it shows the message "This sysrq operation is disabled.". However,
> after this message the next press of sysrq-w shows also the content, not
> just the header! This works until next reboot (or maybe console switch?).

Great catch! There is a bug. The original loglevel is not restored
in __handle_sysrq() when the message about disabled sysrq operation
is printed. As a result, the console stays verbose. I am going
to send a patch upstream for this.
Comment 7 Petr Mladek 2019-01-10 15:44:15 UTC
I have described and explained my observation in the comment #6.

Regarding Fedora 27 (in the 1st comment), I am not sure why it worked as expected. I do not see anything special in the Fedora kernel sources.
It should work the same as SUSE's kernel-4.12 on SLE15 or SLE12-SP4.
One possibility is that they do not use "quiet" kernel parameter and
have the default loglevel "7".

Now, the question is what should be the expected behavior.

The current (wrong?) behavior has been there for ages. I see it in 2.6.12-rc2 (first git commit).

I guess that the reason is that there are situations where people do not want to print everything on the console. For example, because it is too slow. People want to control even sysrq output by the console_loglevel.

I have just realized that you could change the loglevel by sysrq-<number>.

Result:

The current behavior makes sense. You could always increase the console verbosity
by sysrq when necessary.
Comment 8 Oliver Kurz 2019-01-10 19:46:31 UTC
(In reply to Petr Mladek from comment #7)
> The current behavior makes sense. You could always increase the console
> verbosity by sysrq when necessary.

Well, that works, thanks for the hint for sure.

But still I consider the current behaviour highly misleading because either the key presses do not have a visible effect and one would need to know that the log level is too low and should be increased by key press or – maybe even worse – there is only part of the output and again one needs to understand the actual implementation to know that the log level should be increased by key press. But if you still want to keep the issue as WONTFIX I will have to respect that.
Comment 9 Petr Mladek 2019-01-11 16:29:15 UTC
I have sent upstream a patch to show a warning about that the messages are filtered and a hint how to enable them using sysrq, see
https://lkml.kernel.org/r/20190111162038.19771-4-pmladek@suse.com
I am not sure if it will be acceptable though.

I have also sent patch to restore the right conosle_loglevel when the sysrq
was disabled, see https://lkml.kernel.org/r/20190111162038.19771-2-pmladek@suse.com.