Re: possible trace_printk() bug in v5.19-rc1

[Steven Rostedt <rostedt@goodmis.org>]

On Mon, 27 Jun 2022 17:19:18 +0000
Chuck Lever III <chuck.lever@oracle.com> wrote:

> > Would you be able to send me a trace.dat file that has this issue?  
> 
> Sending under separate cover.

I found this is the kallsyms output:

ffffffffac820000 b __brk_early_pgt_alloc
ffffffffac830000 B _end
ffffffffac830000 B __brk_limit
ffffffffc0948205 0944410 t qrtr_alloc_ctrl_packet       [qrtr]
ffffffffc0944470 t qrtr_node_enqueue    [qrtr]
ffffffffc094d100 b __key.5      [qrtr]
ffffffffc09448b0 t qrtr_reset_ports     [qrtr]
ffffffffc094c1c0 d qrtr_ports   [qrtr]
ffffffffc094d100 b __key.3      [qrtr]
ffffffffc094d100 b __key.4      [qrtr]

The line with:

  ffffffffc0948205 0944410 t qrtr_alloc_ctrl_packet       [qrtr]

Causes the parsing to stop, because it is not of a proper format. It has
that extra "0944410" in it, which will break the parsing.

Now the question is, why does that exist? And yes, that's a kernel bug.

The kallsyms code that outputs this file is:

static int s_show(struct seq_file *m, void *p)
{
	void *value;
	struct kallsym_iter *iter = m->private;

	/* Some debugging symbols have no name.  Ignore them. */
	if (!iter->name[0])
		return 0;

	value = iter->show_value ? (void *)iter->value : NULL;

	if (iter->module_name[0]) {
		char type;

		/*
		 * Label it "global" if it is exported,
		 * "local" if not exported.
		 */
		type = iter->exported ? toupper(iter->type) :
					tolower(iter->type);
		seq_printf(m, "%px %c %s\t[%s]\n", value,
			   type, iter->name, iter->module_name);
	} else
		seq_printf(m, "%px %c %s\n", value,
			   iter->type, iter->name);
	return 0;
}

So how did it get that strange output.

Hmm, I bet it is because trace-cmd reads it in BUFSIZ blocks, and that the
seq_file code got confused when parsing between two elements, I bet
something got dropped. I'll go see if there was any seq_file updates that
could have caused this.

-- Steve