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

[Petr Mladek <pmladek@suse.com>]

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