[Crash-utility] [PATCH] log: output logs of printk safe buffers

[d.hatayama at fujitsu.com]

Hi,

> 
> ________________________________________
> From: crash-utility-bounces at redhat.com <crash-utility-bounces at redhat.com> on behalf of shogo.matsumoto at fujitsu.com <shogo.matsumoto at fujitsu.com>
> Sent: Thursday, December 16, 2021 16:39
> To: 'crash-utility at redhat.com'
> Subject: [Crash-utility] [PATCH] log: output logs of printk safe buffers
> 
> We sometimes overlook logs written to printk safe buffers
> (safe_print_seq/nmi_print_seq) which have not been flushed yet.
> 
> This patch will output unflushed logs of the safe buffers
> at the bottom of log command output as follows:
> 
> [nmi_print_seq] CPU: 0  BUFFER: ffff888063c18ac0  LEN: 28
> nmi print seq test message
> [safe_print_seq] CPU: 1  BUFFER: ffff888063d19ae0  LEN: 30
> safe print seq test message

Could you share how to test this patch?
such as how to create a memory dump where some messages are left
in each log buffers without being flushed.
I guess it would be helpful for reviewers.

> 
> Note that the safe buffer (struct printk_safe_seq_buf) was introduced
> in kernel-4.11 and removed in kernel-5.15.

Describing the exact commit hashs in the kernel git repo are helpful.

> 
> Signed-off-by: Shogo Matsumoto <shogo.matsumoto at fujitsu.com>
> ---
>  defs.h   |  3 +++
>  kernel.c | 58 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++
>  2 files changed, 61 insertions(+)
> 
> diff --git a/defs.h b/defs.h
> index 7e2a16e..3ee51e0 100644
> --- a/defs.h
> +++ b/defs.h
> @@ -2146,6 +2146,8 @@ struct offset_table {                    /* stash of commonly-used offsets */
>         long wait_queue_entry_private;
>         long wait_queue_head_head;
>         long wait_queue_entry_entry;
> +       long printk_safe_seq_buf_len;
> +       long printk_safe_seq_buf_buffer;
>  };
> 
>  struct size_table {         /* stash of commonly-used sizes */
> @@ -2310,6 +2312,7 @@ struct size_table {         /* stash of commonly-used sizes */
>         long prb_desc;
>         long wait_queue_entry;
>         long task_struct_state;
> +       long printk_safe_seq_buf_buffer;
>  };

Could you add support for the new members to help -o?

help -o dumps contents of offset_table, size_table and array_table:

crash> help help

NAME
  help -get help
...snip...
    -n - dumpfile contents/statistics
    -o - offset_table and size_table
    -p - program_context
    -r - dump registers from dumpfile header
    -s - symbol table data
    -t - task_table
    -T - task_table plus context_array
    -v - vm_table
    -V - vm_table (verbose)
    -x - text cache
    -z - help options
crash> help -o | tail
              prio_array_queue: 0
            height_to_maxindex: 0
            height_to_maxnodes: 0
                      pid_hash: 0
               kmem_cache_node: 1024
           kmem_cache_cpu_slab: 0
           rt_prio_array_queue: 0
              task_struct_rlim: 0
            signal_struct_rlim: 0
                  vm_numa_stat: 0


> 
>  struct array_table {
> diff --git a/kernel.c b/kernel.c
> index f4598ea..cc97176 100644
> --- a/kernel.c
> +++ b/kernel.c
> @@ -93,6 +93,7 @@ static void source_tree_init(void);
>  static ulong dump_audit_skb_queue(ulong);
>  static ulong __dump_audit(char *);
>  static void dump_audit(void);
> +static void dump_printk_safe_seq_buf(void);
>  static char *vmcoreinfo_read_string(const char *);
>  static void check_vmcoreinfo(void);
>  static int is_pvops_xen(void);
> @@ -5048,6 +5049,7 @@ cmd_log(void)
>         }
> 
>         dump_log(msg_flags);
> +       dump_printk_safe_seq_buf();
>  }
> 
> 
> @@ -11534,6 +11536,62 @@ dump_audit(void)
>                 error(INFO, "kernel audit log is empty\n");
>  }
> 
> +static void
> +__dump_printk_safe_seq_buf(char *buf_name)
> +{
> +       int cpu, buffer_size;
> +       char *buffer;
> +
> +       if (!symbol_exists(buf_name)) {
> +               return;
> +       }
> +
> +       buffer_size = SIZE(printk_safe_seq_buf_buffer);
> +       buffer = GETBUF(buffer_size);
> +       for (cpu = 0; cpu < kt->cpus; cpu++) {
> +               ulong len_addr, buffer_addr;
> +               int len;
> +
> +               len_addr = symbol_value(buf_name) + kt->__per_cpu_offset[cpu] + OFFSET(printk_safe_seq_buf_len);
> +               buffer_addr = symbol_value(buf_name) + kt->__per_cpu_offset[cpu] + OFFSET(printk_safe_seq_buf_buffer);
> +               readmem(len_addr, KVADDR, &len, STRUCT_SIZE("atomic_t"), "printk_safe_seq_buf len", FAULT_ON_ERROR);
> +               readmem(buffer_addr, KVADDR, buffer, buffer_size, "printk_safe_seq_buf buffer", FAULT_ON_ERROR);
> +
> +               if (len > 0) {
> +                       int i, n;
> +                       char *p;
> +                       fprintf(fp, "[%s] CPU: %d  BUFFER: %lx  LEN: %d\n", buf_name, cpu, buffer_addr, len);
> +                       n = (len <= buffer_size) ? len : buffer_size;
> +                       for (i = 0, p = buffer; i < n; i++, p++) {
> +                               if (*p == 0x1) { //SOH
> +                                       i++; p++;
> +                                       continue;
> +                               } else {
> +                                       fputc(ascii(*p) ? *p : '.', fp);
> +                               }
> +                       }
> +                       fputc('\n', fp);
> +               }
> +       }
> +       FREEBUF(buffer);
> +}
> +
> +static void
> +dump_printk_safe_seq_buf(void)
> +{
> +       if (!STRUCT_EXISTS("printk_safe_seq_buf"))
> +               return;
> +
> +       if (INVALID_SIZE(printk_safe_seq_buf_buffer)) {
> +               MEMBER_OFFSET_INIT(printk_safe_seq_buf_len, "printk_safe_seq_buf", "len");
> +               MEMBER_OFFSET_INIT(printk_safe_seq_buf_buffer, "printk_safe_seq_buf", "buffer");
> +               MEMBER_SIZE_INIT(printk_safe_seq_buf_buffer, "printk_safe_seq_buf", "buffer");
> +       }
> +
> +       __dump_printk_safe_seq_buf("nmi_print_seq");
> +       __dump_printk_safe_seq_buf("safe_print_seq");
> +}
> +
>  /*
>   * Reads a string value from the VMCOREINFO data stored in (live) memory.
>   *