Re: [PATCH printk v2 7/7] printk: Handle dropped message smarter

Petr Mladek
2022-12-07T12:50:38Z

On Thu 2022-11-24 00:20:00, John Ogness wrote:
> From: Thomas Gleixner <tglx@linutronix.de>
>
> If a 'dropped message' is to be printed, move the record text to be
> directly appended to the 'dropped message' and let console->write()
> output it in one go.
>
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2741,6 +2712,60 @@ static void __console_unlock(void)
> up_console_sem();
> }
>
> +/*
> + * A maximum dropped message together with a maximum regular message
> + * must be able to fit within console_buffers->ext_text.
> + */
> +#if DROPPED_TEXT_MAX > (CONSOLE_EXT_LOG_MAX - CONSOLE_LOG_MAX)
> +#error "DROPPED_TEXT_MAX too large for console_buffers->ext_text"
> +#endif
> +
> +/**
> + * msg_print_dropped - Prepend a "dropped message" if required
> + * @desc: Pointer to the output descriptor
> + * @dropped: The number of dropped messages to report
> + *
> + * Inserts the "dropped message" into the output buffer if @dropped is
> + * not 0 and the regular format is requested. Extended format does not
> + * need this message because it prints the sequence numbers.
> + *
> + * In regular format, the extended message buffer is not in use. So
> + * string-print the dropped message there and move the record text to be
> + * appended to the dropped message. The extended message buffer is much
> + * larger and can accommodate both messages.
> + *
> + * In case a dropped message is needed, this returns with @desc->outbuf
> + * and @desc->len updated. The caller is responsible for tracking and
> + * resetting the dropped count. If no dropped message is required then
> + * @desc is not modified.
> + */
> +static void msg_print_dropped(struct console_message *cmsg, unsigned long dropped)
> +{
> + struct console_buffers *cbufs = cmsg->cbufs;
> + char *ext_text = &cbufs->ext_text[0];
> + size_t len;
> +
> + if (!dropped || cmsg->is_extmsg)
> + return;
> +
> + if (WARN_ON_ONCE(cmsg->outbuf != &cbufs->text[0]))
> + return;
> +
> + /* Print it into ext_text, which is unused. */
> + len = snprintf(ext_text, DROPPED_TEXT_MAX,
> + "** %lu printk messages dropped **\n", dropped);
> +

I would feel better if we check here that the text fits into the rest
of the buffer.

if (WARN_ON_ONCE(len + cmsg->outbuf_len < sizeof(cbufs->ext_text)))
return;

I know that it is kind-of guaranteed by the above compilation check
of the *_MAX values. But there might be a bug and cmsg->outbuf_len
might contains a garbage.

> + /*
> + * Append the record text to the dropped message so that it
> + * goes out with one write.
> + */
> + memcpy(ext_text + len, &cbufs->text[0], cmsg->outbuf_len);
> +
> + /* Update the output buffer descriptor. */
> + cmsg->outbuf = ext_text;
> + cmsg->outbuf_len += len;

I still think that it would be better to rename the buffers in
struct console_message and avoid the switches of the purpose
of the two buffers.

We could print the message about dropped text into a local buffer
on stack. IMHO, 64 bytes are acceptable. And we could insert it
into the outbuf by shuffling the existing text. Something like:

static void msg_print_dropped(struct console_message *cmsg,
unsinged long dropped)
{
char dropped_msg[DROPPED_TEXT_MAX];
int dropped_len;

if (!con->dropped)
return 0;

/* Print it into ext_text, which is unused. */
dropped_len = snprintf(dropped_msg, sizeof(dropped_msg),
"** %lu printk messages dropped **\n", con->dropped);

/*
* The buffer might already be full only where the message consist
* of many very short lines. It is not much realistic.
*/
if (cmsg->outbuf_len + dropped_len + 1 > sizeof(cmsg->outbuf)) {
/* Should never happen. */
if (WARN_ON_ONCE(dropped_len + 1 > sizeof(cmsg->outbuf)))
return;

/* Trunk the message like in record_print_text() */
cmsg->outbuf_len = sizeof(cmsg->outbuf) - dropped_len;
cmsg->outbuf[cmsg->outbuf_len] = '\0';
}

memmove(cmsg->outbuf + dropped_len, cmsg->outbuf, cmsg->outbuf_len + 1);
memcpy(cmsg->outbuf, dropped_msg, dropped_len);
}

The handling of the full buffer is a bit ugly. I though about other
alternatives. For example, returning -ENOMEM, so that the caller
could print the line later. Or just using WARN_ON_ONCE() and return.

Any solution has its pros and cons. But is a corner case. It need
not be perfect. I solved it the same way as we already do in
record_print_text().

Otherwise, the move of the code makes sense.

Best Regards,
Petr