On Sat 2018-11-24 23:28:36, Tetsuo Handa wrote:
> Since /sys/module/printk/parameters/time can change from N to Y between
> "msg_print_text() called print_prefix() with buf == NULL" and
> "msg_print_text() again calls print_prefix() with buf != NULL", it is not
> safe for print_time() to unconditionally return 0 if printk_time == false.
>
> But print_prefix() is called by only msg_print_text(), and print_prefix()
> is called once more for calculating output length of prefix, and there is
> no need to recalculate it when one log entry contains multiple lines.
>
> Since max output length for syslog marker and timestamp are known to be
> small enough, let's close this race by deduplicating print_prefix() calls.
>
> Signed-off-by: Tetsuo Handa <penguin-ker...@i-love.sakura.ne.jp>
> ---
> kernel/printk/printk.c | 64
> +++++++++++++++-----------------------------------
> 1 file changed, 19 insertions(+), 45 deletions(-)
>
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 1b2a029..eac4c80 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1213,50 +1213,26 @@ static inline void boot_delay_msec(int level)
> static bool printk_time = IS_ENABLED(CONFIG_PRINTK_TIME);
> module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);
>
> -static size_t print_time(u64 ts, char *buf)
> -{
> - unsigned long rem_nsec;
> -
> - if (!printk_time)
> - return 0;
> -
> - rem_nsec = do_div(ts, 1000000000);
> -
> - if (!buf)
> - return snprintf(NULL, 0, "[%5lu.000000] ", (unsigned long)ts);
> -
> - return sprintf(buf, "[%5lu.%06lu] ",
> - (unsigned long)ts, rem_nsec / 1000);
> -}
> -
> -static size_t print_prefix(const struct printk_log *msg, bool syslog, char
> *buf)
> -{
> - size_t len = 0;
> - unsigned int prefix = (msg->facility << 3) | msg->level;
> -
> - if (syslog) {
> - if (buf) {
> - len += sprintf(buf, "<%u>", prefix);
> - } else {
> - len += 3;
> - if (prefix > 999)
> - len += 3;
> - else if (prefix > 99)
> - len += 2;
> - else if (prefix > 9)
> - len++;
> - }
> - }
> -
> - len += print_time(msg->ts_nsec, buf ? buf + len : NULL);
> - return len;
> -}
> -
> static size_t msg_print_text(const struct printk_log *msg, bool syslog, char
> *buf, size_t size)
> {
> const char *text = log_text(msg);
> size_t text_size = msg->text_len;
> size_t len = 0;
> + char prefix[32]; /* "<2047>[18446744073.709551] " */
> + size_t prefix_len = 0;
> +
> + if (syslog)
> + prefix_len += snprintf(prefix, sizeof(prefix), "<%u>",
> + (msg->facility << 3) | msg->level);
> + if (printk_time) {
This does not solve the real problem (buffer overflow) in
syslog_print_all() and kmsg_dump_get_buffer().
> + u64 ts = msg->ts_nsec;
> + unsigned long rem_nsec = do_div(ts, 1000000000);
> +
> + prefix_len += snprintf(prefix + prefix_len,
> + sizeof(prefix) - prefix_len,
> + "[%5lu.%06lu] ", (unsigned long)ts,
> + rem_nsec / 1000);
> + }
I am not against removing some optimizations when buf == NULL.
It is a crazy code and the win is questionable. But the helper
functions still might make sense. msg_print_text() is complicated
enough as is.
Finally, I have mixed feelings about the memcpy() of the prefix.
On one hand, it makes some conditions a bit more readable.
On the other hand, it looks strange to copy it when most
messages have only one line and one prefix. It does not
look like a win in the end.
Let's fix the buffer overflow first and do any code clean up
later in a separate patch.
Best Regards,
Petr
