[Crash-utility] log -m reports wrong log level value

Wed Jan 30 16:48:19 UTC 2013

----- Original Message -----
> Hi Dave,
> 
> While finishing my work on the makedumpfile --dump-dmesg fix for kernels
> higher than 3.5, I may have found a minor bug in your 'log -m' command.
> I was trying to compare my output from makedumpfile --dump-dmesg with
> your log -m output. Or else I misunderstood your 'dump_log_entry'
> command and how the message log level should look.
> 
> When running in -d1 on an F18 kernel, I get the following :
> 
> > crash> log -m | tail
> > log 45368dc -> msg: 45368ec ts_nsec: 83443019994 level: 21026 text_len: 54 dict_len: 0
> > [   83.443019] <21026>RIP  [<ffffffff81393986>] sysrq_handle_crash+0x16/0x20
> > 
> > log 4536924 -> msg: 4536934 ts_nsec: 83443019994 level: 8322 text_len: 23 dict_len: 0
> > [   83.443019] <8322> RSP <ffff8800363dde38> 
> > 
> > log 453694c -> msg: 453695c ts_nsec: 83443019994 level: 17286 text_len: 21 dict_len: 0
> > [   83.443019] <17286>CR2: 0000000000000000
> 
> The message log level in brackets that is displayed seems dubious to me.
> Since I didn't have access to the log.level offset in the vmcoreinfo, I
> had to hack and hard code the structure offset in makedumpfile. While
> doing that, I used a 3 bit mask to get the level:3 element but it looks
> like what you report is the full log.level value.

That's right:

  crash> help log
  ...
      -m  Display the message log level in brackets preceding each message.  For
          the variable-length record format, the level will be displayed in 
          hexadecimal, and depending upon the kernel version, also contains the
          facility or flags bits.

I got tired of dealing with the constant changes in the upstream log structure
associated with the damn flags/level/facility fields, so I just decided to show
the whole combined field.

To be honest, I find the log-level pretty much useless anyway.  And for example,
the vmcore-dmesg facility that comes with the kexec-tools package ignores
it when dumping a variable-length record log.

I should also mention that I'm almost finished with a new crash feature
to dump the log from a vmcore without having the vmlinux file, also
by using just the vmcoreinfo data.  And similar to dmesg-dump, I'm 
also ignoring the log-level for the variable length record log buffer:

$ crash --log vmcore_c_d31 | head
[    0.000000] Initializing cgroup subsys cpuset
[    0.000000] Initializing cgroup subsys cpu
[    0.000000] Linux version 3.6.0-0.29.el7.x86_64 (mockbuild@) (gcc version 4.7.2 20121015 (Red Hat 4.7.2-5) (GCC) ) #1 SMP Fri Nov 9 10:06:26 EST 2012
[    0.000000] Command line: BOOT_IMAGE=/vmlinuz-3.6.0-0.29.el7.x86_64 root=/dev/mapper/rhel_dell--pec5125--01-root ro console=ttyS1,115200n81 rd.md=0 rd.dm=0 rd.lvm.lv=rhel_dell-pec5125-01/root rd.lvm.lv=rhel_dell-pec5125-01/swap crashkernel=auto rd.luks=0
[    0.000000] e820: BIOS-provided physical RAM map:
[    0.000000] BIOS-e820: [mem 0x0000000000000000-0x0000000000095bff] usable
[    0.000000] BIOS-e820: [mem 0x0000000000095c00-0x000000000009ffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000000e6000-0x00000000000fffff] reserved
[    0.000000] BIOS-e820: [mem 0x0000000000100000-0x000000007fd3ffff] usable
[    0.000000] BIOS-e820: [mem 0x000000007fd4e000-0x000000007fd4ffff] reserved
...[ cut ] ...
[  977.816732]  [<ffffffff813890a7>] __handle_sysrq+0x127/0x190
[  977.817373]  [<ffffffff8138915a>] write_sysrq_trigger+0x4a/0x50
[  977.818062]  [<ffffffff811ea879>] proc_reg_write+0x79/0xb0
[  977.818713]  [<ffffffff8118991c>] vfs_write+0xac/0x180
[  977.819335]  [<ffffffff81189c4a>] sys_write+0x4a/0x90
[  977.819962]  [<ffffffff815dcae9>] system_call_fastpath+0x16/0x1b
[  977.820671] Code: 39 65 2c 75 cd 4c 89 ef e8 88 f7 ff ff eb c3 66 0f 1f 44 00 00 55 48 89 e5 66 66 66 66 90 c7 05 81 d7 79 00 01 00 00 00 0f ae f8 <c6> 04 25 00 00 00 00 01 5d c3 55 48 89 e5 53 48 83 ec 08 66 66 
[  977.823234] RIP  [<ffffffff81388986>] sysrq_handle_crash+0x16/0x20
[  977.823905]  RSP <ffff880079f4be38>
[  977.824284] CR2: 0000000000000000
$ 

That being said, if you can make crash work with the older and newer
log structure formats by pulling the flags/level format from debuginfo
data, post a patch.  

Thanks,
  Dave

> 
> So I ported back what I had done in makedumpfile in your dump_log_entry
> (patch attached) and tested on crash 6.1.2. I got :
> 
> > crash> log -m | tail
> > log 458df8c -> msg: 458df9c ts_nsec: 83443019994 flags/level: 22 text_len: 54 dict_len: 0
> > [   83.443019] <2>RIP  [<ffffffff81393986>] sysrq_handle_crash+0x16/0x20
> > 
> > log 458dfd4 -> msg: 458dfe4 ts_nsec: 83443019994 flags/level: 82 text_len: 23 dict_len: 0
> > [   83.443019] <2> RSP <ffff8800363dde38>
> > 
> > log 458dffc -> msg: 458e00c ts_nsec: 83443019994 flags/level: 86 text_len: 21 dict_len: 0
> > [   83.443019] <6>CR2: 0000000000000000
> 
> Does the message log level looks correct to you with that modification ?
> 
> Kind regards,
> 
> ...Louis

I don't recall the details, but the problem has to do with the changes
to the log structure itself.

> --
> Louis Bouchard
> Backline Support Analyst
> Canonical Ltd
> Ubuntu support: http://landscape.canonical.com
> 