sysrq loglevel

sysrq loglevel

[Andy Whitcroft]

It seems that we deliberatly manage the console_loglevel while handling a
sysrq request.  Raising it to 7 to emit the sysrq command header, and then
lower it before processing the command itself.  When booting the kernel
'quiet' this means that we only see the header of the command and not its
output on the console, the whole thing is in dmesg and thereby in syslog
(if it is working).

void __handle_sysrq(int key, struct tty_struct *tty, int check_mask)
[...]
        console_loglevel = 7;
        printk(KERN_INFO "SysRq : ");
[...]
                        printk("%s\n", op_p->action_msg);
                        console_loglevel = orig_log_level;
                        op_p->handler(key, tty);
[...]

Is this intentional?  I can see arguments both ways.  One way to look at
it would be that I asked for the output so I should get it regardless.
The other side might be that consoles can be really slow (serial or
something) and so only outputting it there if logging is enabled
generally is sane.

Obviously we can work round this at the moment using sysrq-7 to up the
loglevel before the command and sysrq-4 after to restore quiet.

What do people think.  If we are happy with the status quo then I will
spin a documentation patch to point out this behaviour and the work
around.  Else I will happily spin a patch to fix it.

Thoughts?

-apw

Re: sysrq loglevel

[Andrew Morton]

On Wed, 7 Jan 2009 12:37:58 +0000 Andy Whitcroft <apw@canonical.com> wrote:

> It seems that we deliberatly manage the console_loglevel while handling a
> sysrq request.  Raising it to 7 to emit the sysrq command header, and then
> lower it before processing the command itself.  When booting the kernel
> 'quiet' this means that we only see the header of the command and not its
> output on the console, the whole thing is in dmesg and thereby in syslog
> (if it is working).

I always thought it was fairly stupid.  Wouldn't we get the same effect
by tossing that code and switching those printks to KERN_EMERG?

> void __handle_sysrq(int key, struct tty_struct *tty, int check_mask)
> [...]
>         console_loglevel = 7;
>         printk(KERN_INFO "SysRq : ");
> [...]
>                         printk("%s\n", op_p->action_msg);
>                         console_loglevel = orig_log_level;
>                         op_p->handler(key, tty);
> [...]
> 
> Is this intentional?  I can see arguments both ways.  One way to look at
> it would be that I asked for the output so I should get it regardless.
> The other side might be that consoles can be really slow (serial or
> something) and so only outputting it there if logging is enabled
> generally is sane.
> 
> Obviously we can work round this at the moment using sysrq-7 to up the
> loglevel before the command and sysrq-4 after to restore quiet.
> 
> What do people think.  If we are happy with the status quo then I will
> spin a documentation patch to point out this behaviour and the work
> around.  Else I will happily spin a patch to fix it.
> 

There is a legitimate use case, I think: to emit the sysrq command's
output into the log bufffer and not to the console[s].  So you can do

	echo t > /proc/sysrq-trigger
	dmesg -s 1000000 > foo

Re: sysrq loglevel

[Andy Whitcroft]

On Wed, Jan 07, 2009 at 11:25:39AM -0800, Andrew Morton wrote:
> On Wed, 7 Jan 2009 12:37:58 +0000 Andy Whitcroft <apw@canonical.com> wrote:
> 
> > It seems that we deliberatly manage the console_loglevel while handling a
> > sysrq request.  Raising it to 7 to emit the sysrq command header, and then
> > lower it before processing the command itself.  When booting the kernel
> > 'quiet' this means that we only see the header of the command and not its
> > output on the console, the whole thing is in dmesg and thereby in syslog
> > (if it is working).
> 
> I always thought it was fairly stupid.  Wouldn't we get the same effect
> by tossing that code and switching those printks to KERN_EMERG?

I believe it is different as the level is still KERN_INFO and that is
what the consumers of /proc/kmsg will see, and that might affect where
they are logged to.

> > void __handle_sysrq(int key, struct tty_struct *tty, int check_mask)
> > [...]
> >         console_loglevel = 7;
> >         printk(KERN_INFO "SysRq : ");
> > [...]
> >                         printk("%s\n", op_p->action_msg);
> >                         console_loglevel = orig_log_level;
> >                         op_p->handler(key, tty);
> > [...]
> > 
> > Is this intentional?  I can see arguments both ways.  One way to look at
> > it would be that I asked for the output so I should get it regardless.
> > The other side might be that consoles can be really slow (serial or
> > something) and so only outputting it there if logging is enabled
> > generally is sane.
> > 
> > Obviously we can work round this at the moment using sysrq-7 to up the
> > loglevel before the command and sysrq-4 after to restore quiet.
> > 
> > What do people think.  If we are happy with the status quo then I will
> > spin a documentation patch to point out this behaviour and the work
> > around.  Else I will happily spin a patch to fix it.
> > 
> 
> There is a legitimate use case, I think: to emit the sysrq command's
> output into the log bufffer and not to the console[s].  So you can do
> 
> 	echo t > /proc/sysrq-trigger
> 	dmesg -s 1000000 > foo

Yeah I agree.  I will spin a documentation patch to capture this
reasoning so we don't end up asking again in a years time.

-apw

[PATCH 0/3] document sysrq interaction with loglevels

[Andy Whitcroft]

Following on from our discussion on sysrq and its interaction with
console loglevels here are some documentation updates, both to the
Documenation/sysrq.txt as well as to the source, to clarify how things
work and why.

Following this email are three patches.  The first simply removes a
redundant 'last modified date' within the documentation file, git does
this far better.  The second adds a new documentation section indicating
why you might only see the header of the sysrq command you have requested.
The last adds a comment to the console_loglevel modifications within the
sysrq code paths explaining why we might do this.

Andrew please consider for -mm.

-apw

Andy Whitcroft (3):
  sysrq documentation: remove the redundant updated date
  sysrq documentation: document why the command header only is shown
  sysrq: add commentary on why we use the console loglevel over using
    KERN_EMERG

 Documentation/sysrq.txt |   19 ++++++++++++++++++-
 drivers/char/sysrq.c    |    6 ++++++
 2 files changed, 24 insertions(+), 1 deletions(-)

[PATCH 1/3] sysrq documentation: remove the redundant updated date

[Andy Whitcroft]

git is maintaining the last update time much more accuratly than
the internal update time.  Remove it.

Signed-off-by: Andy Whitcroft <apw@canonical.com>
---
 Documentation/sysrq.txt |    1 -
 1 files changed, 0 insertions(+), 1 deletions(-)

diff --git a/Documentation/sysrq.txt b/Documentation/sysrq.txt
index 10a0263..265f637 100644
--- a/Documentation/sysrq.txt
+++ b/Documentation/sysrq.txt
@@ -1,6 +1,5 @@
 Linux Magic System Request Key Hacks
 Documentation for sysrq.c
-Last update: 2007-AUG-04
 
 *  What is the magic SysRq key?
 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
-- 
1.6.0.4.911.gc990

[PATCH 2/3] sysrq documentation: document why the command header only is shown

[Andy Whitcroft]

Document the interactions between loglevel and the sysrq output.  Also
document how to work round it should output on the console be required.

Signed-off-by: Andy Whitcroft <apw@canonical.com>
---
 Documentation/sysrq.txt |   18 ++++++++++++++++++
 1 files changed, 18 insertions(+), 0 deletions(-)

diff --git a/Documentation/sysrq.txt b/Documentation/sysrq.txt
index 265f637..a262ffb 100644
--- a/Documentation/sysrq.txt
+++ b/Documentation/sysrq.txt
@@ -210,6 +210,24 @@ within a function called by handle_sysrq, you must be aware that you are in
 a lock (you are also in an interrupt handler, which means don't sleep!), so
 you must call __handle_sysrq_nolock instead.
 
+*  When I hit a sysrq combination only the header appears on the console, why?
+~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
+Sysrq output is subject to the same console loglevel control as all
+other console output.  This means that if the kernel was booted 'quiet'
+as is common on distro kernels the output may not appear on the actual
+console, even though it will appear in the dmesg buffer, and be accessible
+via the dmesg command and to the consumers of /proc/kmsg.  As a specific
+exception the header line from the sysrq command is passed to all console
+consumers as if the current loglevel was maximum.  If only the header
+is emitted it is almost cirtain that the kernel loglevel is too low.
+Should you require the output on the console channel then you will need
+to temporarily up the console loglevel using alt-sysrq-8 or:
+
+    echo 8 > /proc/sysrq-trigger
+
+Remember to return the loglevel to normal after triggering the sysrq
+command you are interested in.
+
 *  I have more questions, who can I ask?
 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
 And I'll answer any questions about the registration system you got, also
-- 
1.6.0.4.911.gc990

[PATCH 3/3] sysrq: add commentary on why we use the console loglevel over using KERN_EMERG

[Andy Whitcroft]

Add an explanitory comment as to why we modify the kernel console
loglevel rather than simply moving sysrq messages to KERN_EMERG level.

Signed-off-by: Andy Whitcroft <apw@canonical.com>
---
 drivers/char/sysrq.c |    6 ++++++
 1 files changed, 6 insertions(+), 0 deletions(-)

diff --git a/drivers/char/sysrq.c b/drivers/char/sysrq.c
index d41b9f6..33a9351 100644
--- a/drivers/char/sysrq.c
+++ b/drivers/char/sysrq.c
@@ -473,6 +473,12 @@ void __handle_sysrq(int key, struct tty_struct *tty, int check_mask)
 	unsigned long flags;
 
 	spin_lock_irqsave(&sysrq_key_table_lock, flags);
+	/*
+	 * Raise the apparent loglevel to maximum so that the sysrq header
+	 * is shown to provide the user with positive feedback.  We do not
+	 * simply emit this at KERN_EMERG as that would change message
+	 * routing in the consumers of /proc/kmsg.
+	 */
 	orig_log_level = console_loglevel;
 	console_loglevel = 7;
 	printk(KERN_INFO "SysRq : ");
-- 
1.6.0.4.911.gc990

Re: [PATCH 2/3] sysrq documentation: document why the command header only is shown

[Randy Dunlap]

Andy Whitcroft wrote:
> Document the interactions between loglevel and the sysrq output.  Also
> document how to work round it should output on the console be required.
> 
> Signed-off-by: Andy Whitcroft <apw@canonical.com>
> ---
>  Documentation/sysrq.txt |   18 ++++++++++++++++++
>  1 files changed, 18 insertions(+), 0 deletions(-)
> 
> diff --git a/Documentation/sysrq.txt b/Documentation/sysrq.txt
> index 265f637..a262ffb 100644
> --- a/Documentation/sysrq.txt
> +++ b/Documentation/sysrq.txt
> @@ -210,6 +210,24 @@ within a function called by handle_sysrq, you must be aware that you are in
>  a lock (you are also in an interrupt handler, which means don't sleep!), so
>  you must call __handle_sysrq_nolock instead.
>  
> +*  When I hit a sysrq combination only the header appears on the console, why?

   *  When I hit a sysrq key combination, only the header appears on the console. Why?
> +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
> +Sysrq output is subject to the same console loglevel control as all
> +other console output.  This means that if the kernel was booted 'quiet'
> +as is common on distro kernels the output may not appear on the actual
> +console, even though it will appear in the dmesg buffer, and be accessible
> +via the dmesg command and to the consumers of /proc/kmsg.  As a specific
> +exception the header line from the sysrq command is passed to all console
> +consumers as if the current loglevel was maximum.  If only the header
> +is emitted it is almost cirtain that the kernel loglevel is too low.

                           certain

> +Should you require the output on the console channel then you will need
> +to temporarily up the console loglevel using alt-sysrq-8 or:
> +
> +    echo 8 > /proc/sysrq-trigger
> +
> +Remember to return the loglevel to normal after triggering the sysrq
> +command you are interested in.
> +
>  *  I have more questions, who can I ask?
>  ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
>  And I'll answer any questions about the registration system you got, also


-- 
~Randy

[PATCH 0/3] document sysrq interaction with loglevels V2

[Andy Whitcroft]

[Updated patch series incorporating feedback from Martin Mares and Randy
Dunlap.]

Following on from our discussion on sysrq and its interaction with
console loglevels here are some documentation updates, both to the
Documenation/sysrq.txt as well as to the source, to clarify how things
work and why.

Following this email are three patches.  The first simply removes a
redundant 'last modified date' within the documentation file, git does
this far better.  The second adds a new documentation section indicating
why you might only see the header of the sysrq command you have requested.
The last adds a comment to the console_loglevel modifications within the
sysrq code paths explaining why we might do this.

Andrew please consider for -mm.

-apw

Andy Whitcroft (3):
  sysrq documentation: remove the redundant updated date
  sysrq documentation: document why the command header only is shown
  sysrq: add commentary on why we use the console loglevel over using
    KERN_EMERG

 Documentation/sysrq.txt |   19 ++++++++++++++++++-
 drivers/char/sysrq.c    |    6 ++++++
 2 files changed, 24 insertions(+), 1 deletions(-)

[PATCH 1/3] sysrq documentation: remove the redundant updated date

[Andy Whitcroft]

git is maintaining the last update time much more accuratly than
the internal update time.  Remove it.

Signed-off-by: Andy Whitcroft <apw@canonical.com>
---
 Documentation/sysrq.txt |    1 -
 1 files changed, 0 insertions(+), 1 deletions(-)

diff --git a/Documentation/sysrq.txt b/Documentation/sysrq.txt
index 10a0263..265f637 100644
--- a/Documentation/sysrq.txt
+++ b/Documentation/sysrq.txt
@@ -1,6 +1,5 @@
 Linux Magic System Request Key Hacks
 Documentation for sysrq.c
-Last update: 2007-AUG-04
 
 *  What is the magic SysRq key?
 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
-- 
1.6.0.4.911.gc990

[PATCH 2/3] sysrq documentation: document why the command header only is shown

[Andy Whitcroft]

Document the interactions between loglevel and the sysrq output.  Also
document how to work round it should output be required on the console.

Signed-off-by: Andy Whitcroft <apw@canonical.com>
Cc: Martin Mares <mj@ucw.cz>
Cc: Randy Dunlap <randy.dunlap@oracle.com>

---
 Documentation/sysrq.txt |   18 ++++++++++++++++++
 1 files changed, 18 insertions(+), 0 deletions(-)

diff --git a/Documentation/sysrq.txt b/Documentation/sysrq.txt
index 265f637..9e592c7 100644
--- a/Documentation/sysrq.txt
+++ b/Documentation/sysrq.txt
@@ -210,6 +210,24 @@ within a function called by handle_sysrq, you must be aware that you are in
 a lock (you are also in an interrupt handler, which means don't sleep!), so
 you must call __handle_sysrq_nolock instead.
 
+*  When I hit a SysRq key combination only the header appears on the console?
+~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
+Sysrq output is subject to the same console loglevel control as all
+other console output.  This means that if the kernel was booted 'quiet'
+as is common on distro kernels the output may not appear on the actual
+console, even though it will appear in the dmesg buffer, and be accessible
+via the dmesg command and to the consumers of /proc/kmsg.  As a specific
+exception the header line from the sysrq command is passed to all console
+consumers as if the current loglevel was maximum.  If only the header
+is emitted it is almost certain that the kernel loglevel is too low.
+Should you require the output on the console channel then you will need
+to temporarily up the console loglevel using alt-sysrq-8 or:
+
+    echo 8 > /proc/sysrq-trigger
+
+Remember to return the loglevel to normal after triggering the sysrq
+command you are interested in.
+
 *  I have more questions, who can I ask?
 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
 And I'll answer any questions about the registration system you got, also
-- 
1.6.0.4.911.gc990

[PATCH 3/3] sysrq: add commentary on why we use the console loglevel over using KERN_EMERG

[Andy Whitcroft]

Add an explanitory comment as to why we modify the kernel console
loglevel rather than simply moving sysrq messages to KERN_EMERG level.

Signed-off-by: Andy Whitcroft <apw@canonical.com>
---
 drivers/char/sysrq.c |    6 ++++++
 1 files changed, 6 insertions(+), 0 deletions(-)

diff --git a/drivers/char/sysrq.c b/drivers/char/sysrq.c
index d41b9f6..33a9351 100644
--- a/drivers/char/sysrq.c
+++ b/drivers/char/sysrq.c
@@ -473,6 +473,12 @@ void __handle_sysrq(int key, struct tty_struct *tty, int check_mask)
 	unsigned long flags;
 
 	spin_lock_irqsave(&sysrq_key_table_lock, flags);
+	/*
+	 * Raise the apparent loglevel to maximum so that the sysrq header
+	 * is shown to provide the user with positive feedback.  We do not
+	 * simply emit this at KERN_EMERG as that would change message
+	 * routing in the consumers of /proc/kmsg.
+	 */
 	orig_log_level = console_loglevel;
 	console_loglevel = 7;
 	printk(KERN_INFO "SysRq : ");
-- 
1.6.0.4.911.gc990

Re: [PATCH 3/3] sysrq: add commentary on why we use the console loglevel over using KERN_EMERG

[Nick Andrew]

On Wed, Jan 07, 2009 at 09:49:18PM +0000, Andy Whitcroft wrote:
> Add an explanitory comment as to why we modify the kernel console

         explanatory

> loglevel rather than simply moving sysrq messages to KERN_EMERG level.
> 
> Signed-off-by: Andy Whitcroft <apw@canonical.com>

Nick.