Fix handling the ring buffer for 'log' command.
 

Hi,

I found there is a 'log' command problem related to handling the ring
buffer, and this patch fixes it.

The ring buffer can be cleared by klogctl(2) from a user process, but
current crash utility does not consider this case. The following output
of current crash utility is example of this case. You see there is the
panic message "SysRq : Trigger a crashdump" inside even if it should be
output in the end:

crash > log
[snip]
exception[8291] trap divide error rip:4004c0 rsp:7fffb56cdf60 error:0
exception[8293] trap divide error rip:4004c0 rsp:7fffbb0628f0 error:0
SysRq : Trigger a crashdump
14 15) *0, disabled.
ACPI: PCI Interrupt Link [LNKF] (IRQs 4 5 6 7 10 14 15) *0, disabled.
ACPI: PCI Interrupt Link [LNKG] (IRQs 3 4 5 6 7 10 14 15) *0, disabled.
[snip]
crash >

This patch fixes this invalid output to the folloing:

crash > log
[snip]
exception[8291] trap divide error rip:4004c0 rsp:7fffb56cdf60 error:0
exception[8293] trap divide error rip:4004c0 rsp:7fffbb0628f0 error:0
SysRq : Trigger a crashdump
crash>

I have one concern about this fixing:
If applying this patch, 'log' command outputs the log data from the time
of klogctl(2) call for the log clearance. If making the other patch, we
will be able to extract the former log data, because a kernel does not
clear the ring buffer and it just clears "logged_chars" internally.
I feel this patch is better, because the log data can be cleared only by
a root user and he decided the former log data is unnecessary.
What do you think of this?


Thanks
Ken'ichi Ohmichi

Signed-off-by: Ken'ichi Ohmichi <oomichi@mxs.nes.nec.co.jp>
---
--- crash-4.0-7.7/kernel.c.orig 2009-02-06 01:13:43.000000000 +0900
+++ crash-4.0-7.7/kernel.c 2009-02-17 12:07:33.000000000 +0900
@@ -3364,13 +3364,13 @@ cmd_log(void)
void
dump_log(int msg_level)
{
- int i;
+ int i, j;
ulong log_buf, logged_chars;
char *buf;
char last;
ulong index;
struct syment *nsp;
- int log_wrap, loglevel, log_buf_len;
+ int loglevel, log_buf_len;

if (symbol_exists("log_buf_len")) {
get_symbol_data("log_buf_len", sizeof(int), &log_buf_len);
@@ -3391,29 +3391,28 @@ dump_log(int msg_level)
}

buf = GETBUF(log_buf_len);
- log_wrap = FALSE;
get_symbol_data("logged_chars", sizeof(ulong), &logged_chars);
readmem(log_buf, KVADDR, buf,
log_buf_len, "log_buf contents", FAULT_ON_ERROR);

+ get_symbol_data("log_end", sizeof(ulong), &index);
+ index &= (log_buf_len - 1);
if (logged_chars < log_buf_len) {
- index = 0;
- } else {
- get_symbol_data("log_end", sizeof(ulong), &index);
- index &= log_buf_len-1;
- }
+ if (logged_chars <= index)
+ index -= logged_chars;
+ else
+ index = log_buf_len - (logged_chars - index);
+ }

if ((logged_chars < log_buf_len) && (index == 0) && (buf[index] == '<'))
loglevel = TRUE;
else
loglevel = FALSE;

- if (index != 0)
- log_wrap = TRUE;
+ for (i = index, j = 0; j < logged_chars; i++, j++) {
+ if (i >= log_buf_len)
+ i = 0;

-wrap_around:
-
- for (i = index; i < log_buf_len; i++) {
if (loglevel && !msg_level) {
switch (buf[i])
{
@@ -3444,13 +3443,6 @@ wrap_around:
}
}

- if (log_wrap) {
- log_buf_len = index;
- index = 0;
- log_wrap = FALSE;
- goto wrap_around;
- }
-
if (last != '
')
fprintf(fp, "
");


--
Crash-utility mailing list
Crash-utility@redhat.com
https://www.redhat.com/mailman/listinfo/crash-utility

Fix handling the ring buffer for 'log' command.
 

----- "Ken'ichi Ohmichi" <oomichi@mxs.nes.nec.co.jp> wrote:

> Hi,
>
> I found there is a 'log' command problem related to handling the ring
> buffer, and this patch fixes it.
>
> The ring buffer can be cleared by klogctl(2) from a user process, but
> current crash utility does not consider this case. The following output
> of current crash utility is example of this case. You see there is the
> panic message "SysRq : Trigger a crashdump" inside even if it should be
> output in the end:
>
> crash > log
> [snip]
> exception[8291] trap divide error rip:4004c0 rsp:7fffb56cdf60 error:0
> exception[8293] trap divide error rip:4004c0 rsp:7fffbb0628f0 error:0
> SysRq : Trigger a crashdump
> 14 15) *0, disabled.
> ACPI: PCI Interrupt Link [LNKF] (IRQs 4 5 6 7 10 14 15) *0, disabled.
> ACPI: PCI Interrupt Link [LNKG] (IRQs 3 4 5 6 7 10 14 15) *0, disabled.
> [snip]
> crash>
>
> This patch fixes this invalid output to the folloing:
>
> crash> log
> [snip]
> exception[8291] trap divide error rip:4004c0 rsp:7fffb56cdf60 error:0
> exception[8293] trap divide error rip:4004c0 rsp:7fffbb0628f0 error:0
> SysRq : Trigger a crashdump
> crash>
>
> I have one concern about this fixing:
> If applying this patch, 'log' command outputs the log data from the time
> of klogctl(2) call for the log clearance. If making the other patch, we
> will be able to extract the former log data, because a kernel does not
> clear the ring buffer and it just clears "logged_chars" internally.
> I feel this patch is better, because the log data can be cleared only by
> a root user and he decided the former log data is unnecessary.
> What do you think of this?
>

Good question -- I'm not sure.

If the buffer were "cleared" by the administrator, the logical "end" of
the buffer would not be the last thing displayed by the "log" command.
But that's really not a problem, given that the relevant kernel-crash-related
data is still available to be examined.

On the other hand, even though the administrator has "cleared" the log
buffer, the data is still there. My concern would be what if there is
crucial data in the log buffer that the administrator "cleared" out of
convenience? Like for example, I've often done a "dmesg -c" to clear
the buffer so that subsequent dmesg commands just dump the latest
information. But then I've gone back with the crash utility and
re-examined the log buffer data that still remains in memory -- which
can be still be seen with the "log" command.

So my initial leaning would be to continue to show what's actually there.
I trust myself as a crash analyzer more than I trust the administrator.

But I could be convinced otherwise.

What do others on the list think about this?

Dave


>
> Thanks
> Ken'ichi Ohmichi
>
> Signed-off-by: Ken'ichi Ohmichi <oomichi@mxs.nes.nec.co.jp>
> ---
> --- crash-4.0-7.7/kernel.c.orig 2009-02-06 01:13:43.000000000 +0900
> +++ crash-4.0-7.7/kernel.c 2009-02-17 12:07:33.000000000 +0900
> @@ -3364,13 +3364,13 @@ cmd_log(void)
> void
> dump_log(int msg_level)
> {
> - int i;
> + int i, j;
> ulong log_buf, logged_chars;
> char *buf;
> char last;
> ulong index;
> struct syment *nsp;
> - int log_wrap, loglevel, log_buf_len;
> + int loglevel, log_buf_len;
>
> if (symbol_exists("log_buf_len")) {
> get_symbol_data("log_buf_len", sizeof(int), &log_buf_len);
> @@ -3391,29 +3391,28 @@ dump_log(int msg_level)
> }
>
> buf = GETBUF(log_buf_len);
> - log_wrap = FALSE;
> get_symbol_data("logged_chars", sizeof(ulong), &logged_chars);
> readmem(log_buf, KVADDR, buf,
> log_buf_len, "log_buf contents", FAULT_ON_ERROR);
>
> + get_symbol_data("log_end", sizeof(ulong), &index);
> + index &= (log_buf_len - 1);
> if (logged_chars < log_buf_len) {
> - index = 0;
> - } else {
> - get_symbol_data("log_end", sizeof(ulong), &index);
> - index &= log_buf_len-1;
> - }
> + if (logged_chars <= index)
> + index -= logged_chars;
> + else
> + index = log_buf_len - (logged_chars - index);
> + }
>
> if ((logged_chars < log_buf_len) && (index == 0) && (buf[index] == '<'))
> loglevel = TRUE;
> else
> loglevel = FALSE;
>
> - if (index != 0)
> - log_wrap = TRUE;
> + for (i = index, j = 0; j < logged_chars; i++, j++) {
> + if (i >= log_buf_len)
> + i = 0;
>
> -wrap_around:
> -
> - for (i = index; i < log_buf_len; i++) {
> if (loglevel && !msg_level) {
> switch (buf[i])
> {
> @@ -3444,13 +3443,6 @@ wrap_around:
> }
> }
>
> - if (log_wrap) {
> - log_buf_len = index;
> - index = 0;
> - log_wrap = FALSE;
> - goto wrap_around;
> - }
> -
> if (last != '
')
> fprintf(fp, "
");
>
>
> --
> Crash-utility mailing list
> Crash-utility@redhat.com
> https://www.redhat.com/mailman/listinfo/crash-utility

--
Crash-utility mailing list
Crash-utility@redhat.com
https://www.redhat.com/mailman/listinfo/crash-utility

Fix handling the ring buffer for 'log' command.
 

Dave Anderson <anderson@redhat.com> writes:

> Good question -- I'm not sure.
>
> If the buffer were "cleared" by the administrator, the logical "end" of
> the buffer would not be the last thing displayed by the "log" command.
> But that's really not a problem, given that the relevant kernel-crash-related
> data is still available to be examined.
>
> On the other hand, even though the administrator has "cleared" the log
> buffer, the data is still there. My concern would be what if there is
> crucial data in the log buffer that the administrator "cleared" out of
> convenience? Like for example, I've often done a "dmesg -c" to clear
> the buffer so that subsequent dmesg commands just dump the latest
> information. But then I've gone back with the crash utility and
> re-examined the log buffer data that still remains in memory -- which
> can be still be seen with the "log" command.
>
> So my initial leaning would be to continue to show what's actually there.
> I trust myself as a crash analyzer more than I trust the administrator.
>
> But I could be convinced otherwise.
>
> What do others on the list think about this?

I would much rather see all of the contents of the log buffer.

Cheers,
Jeff

--
Crash-utility mailing list
Crash-utility@redhat.com
https://www.redhat.com/mailman/listinfo/crash-utility

Fix handling the ring buffer for 'log' command.
 

Hi Dave, Jeff,

Thank you for comments.

Jeff Moyer wrote:
> > Dave Anderson <anderson@redhat.com> writes:
> >
>> >> Good question -- I'm not sure.
>> >>
>> >> If the buffer were "cleared" by the administrator, the logical "end" of
>> >> the buffer would not be the last thing displayed by the "log" command.
>> >> But that's really not a problem, given that the relevant kernel-crash-related
>> >> data is still available to be examined.
>> >>
>> >> On the other hand, even though the administrator has "cleared" the log
>> >> buffer, the data is still there. My concern would be what if there is
>> >> crucial data in the log buffer that the administrator "cleared" out of
>> >> convenience? Like for example, I've often done a "dmesg -c" to clear
>> >> the buffer so that subsequent dmesg commands just dump the latest
>> >> information. But then I've gone back with the crash utility and
>> >> re-examined the log buffer data that still remains in memory -- which
>> >> can be still be seen with the "log" command.

Good comment, I see.


>> >> So my initial leaning would be to continue to show what's actually there.
>> >> I trust myself as a crash analyzer more than I trust the administrator.
>> >>
>> >> But I could be convinced otherwise.
>> >>
>> >> What do others on the list think about this?
> >
> > I would much rather see all of the contents of the log buffer.

OK, I attach a new patch for outputing all of the contents of the log
buffer. How about this patch ?


By the way, I'm implementing a new option '--dump-dmesg' of makedumpfile
command with Neil Horman. The option is similar to 'log' command of the
crash utility, so the option extracts log data from /proc/vmcore and dumps
it to a file. I will implement the option for outputting all of the contents
of the log buffer like this patch.


---
[Patch-v2] Fix handling the ring buffer for 'log' command.

Changelog of v2:
- Extending the output range of 'log' command to all the ring buffer.

I found there is a 'log' command problem related to handling the ring
buffer, and this patch fixes it.

The ring buffer can be cleared by klogctl(2) from a user process, but
current crash utility does not consider this case. The following output
of current crash utility is example of this case. You see there are some
messages after the panic message. These messages are the oldest log data,
so they should be output first.

crash > log
[snip]
exception[8291] trap divide error rip:4004c0 rsp:7fffb56cdf60 error:0
exception[8293] trap divide error rip:4004c0 rsp:7fffbb0628f0 error:0
SysRq : Trigger a crashdump
14 15) *0, disabled.
ACPI: PCI Interrupt Link [LNKF] (IRQs 4 5 6 7 10 14 15) *0, disabled.
ACPI: PCI Interrupt Link [LNKG] (IRQs 3 4 5 6 7 10 14 15) *0, disabled.
[snip]
crash >

This patch fixes this invalid output to the folloing:

crash > log
14 15) *0, disabled.
ACPI: PCI Interrupt Link [LNKF] (IRQs 4 5 6 7 10 14 15) *0, disabled.
ACPI: PCI Interrupt Link [LNKG] (IRQs 3 4 5 6 7 10 14 15) *0, disabled.
[snip]
exception[8291] trap divide error rip:4004c0 rsp:7fffb56cdf60 error:0
exception[8293] trap divide error rip:4004c0 rsp:7fffbb0628f0 error:0
SysRq : Trigger a crashdump
crash>


Thanks
Ken'ichi Ohmichi

Signed-off-by: Ken'ichi Ohmichi <oomichi@mxs.nes.nec.co.jp>
---
--- crash-4.0-7.7/kernel.c.orig 2009-02-06 01:13:43.000000000 +0900
+++ crash-4.0-7.7/kernel.c 2009-02-18 10:42:29.000000000 +0900
@@ -3365,7 +3365,7 @@ void
dump_log(int msg_level)
{
int i;
- ulong log_buf, logged_chars;
+ ulong log_buf, logged_chars, log_end;
char *buf;
char last;
ulong index;
@@ -3393,17 +3393,16 @@ dump_log(int msg_level)
buf = GETBUF(log_buf_len);
log_wrap = FALSE;
get_symbol_data("logged_chars", sizeof(ulong), &logged_chars);
+ get_symbol_data("log_end", sizeof(ulong), &log_end);
readmem(log_buf, KVADDR, buf,
log_buf_len, "log_buf contents", FAULT_ON_ERROR);

- if (logged_chars < log_buf_len) {
+ if (log_end < log_buf_len)
index = 0;
- } else {
- get_symbol_data("log_end", sizeof(ulong), &index);
- index &= log_buf_len-1;
- }
+ else
+ index = log_end & (log_buf_len - 1);

- if ((logged_chars < log_buf_len) && (index == 0) && (buf[index] == '<'))
+ if ((log_end < log_buf_len) && (index == 0) && (buf[index] == '<'))
loglevel = TRUE;
else
loglevel = FALSE;

--
Crash-utility mailing list
Crash-utility@redhat.com
https://www.redhat.com/mailman/listinfo/crash-utility