[RFC V2] printk: add warning while drop partial text in msg

[RFC V2] printk: add warning while drop partial text in msg

[pierre Kuo]

If the buffer pass to msg_print_text is not big enough to put both all
prefixes and log_text(msg), kernel will quietly break.
That means the user may not have the chance to know whether the
log_text(msg) is fully printed into buffer or not.

In this patch, once above case happened, we try to calculate how many
characters of log_text(msg) are dropped and add warning for debugging
purpose.

Signed-off-by: pierre Kuo <vichy.kuo@gmail.com>
---
Changes since v2:
 * fix typo in commit message from "waring for debugging purpose" to "warning for debugging purpose"

 kernel/printk/printk.c | 23 ++++++++++++++++++++++-
 1 file changed, 22 insertions(+), 1 deletion(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index fc47863..6cbb3699 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -558,6 +558,12 @@ static u32 msg_used_size(u16 text_len, u16 dict_len, u32 *pad_len)
 #define MAX_LOG_TAKE_PART 4
 static const char trunc_msg[] = "<truncated>";
 
+/*
+ * Define max drop msg length that we put in next msg
+ */
+#define MAX_DROP_MSG_LENGTH 32
+static char drop_msg[MAX_DROP_MSG_LENGTH];
+
 static u32 truncate_msg(u16 *text_len, u16 *trunc_msg_len,
 			u16 *dict_len, u32 *pad_len)
 {
@@ -1264,8 +1270,23 @@ static size_t msg_print_text(const struct printk_log *msg, bool syslog, char *bu
 
 		if (buf) {
 			if (print_prefix(msg, syslog, NULL) +
-			    text_len + 1 >= size - len)
+			    text_len + 1 >= size - len) {
+				/* below stores dropped characters
+				 * related information in next msg
+				 */
+				size_t drop_len;
+
+				drop_len = scnprintf(drop_msg,
+					MAX_DROP_MSG_LENGTH,
+					"<%u characters dropped>",
+					(next) ?
+					(unsigned int)(text_size + next - text) :
+					(unsigned int)text_size);
+				drop_msg[drop_len] = 0;
+				log_store(msg->facility, msg->level, msg->flags,
+					0, NULL, 0, drop_msg, strlen(drop_msg));
 				break;
+			}
 
 			len += print_prefix(msg, syslog, buf + len);
 			memcpy(buf + len, text, text_len);
-- 
1.9.1

Re: [RFC V2] printk: add warning while drop partial text in msg

[Sergey Senozhatsky]

On (07/30/17 21:37), pierre Kuo wrote:
> If the buffer pass to msg_print_text is not big enough to put both all
> prefixes and log_text(msg), kernel will quietly break.
> That means the user may not have the chance to know whether the
> log_text(msg) is fully printed into buffer or not.
> 
> In this patch, once above case happened, we try to calculate how many
> characters of log_text(msg) are dropped and add warning for debugging
> purpose.
[..]

Hello,

this is not the only place that can truncate the message.
vprintk_emit() can do so as well /* vscnprintf() */. but
I think we don't care that much. a user likely will  notice
truncated messages. we report lost messages, because this
is a completely different sort of problem.


[..]
> @@ -1264,8 +1270,23 @@ static size_t msg_print_text(const struct printk_log *msg, bool syslog, char *bu
>  
>  		if (buf) {
>  			if (print_prefix(msg, syslog, NULL) +
> -			    text_len + 1 >= size - len)
> +			    text_len + 1 >= size - len) {
> +				/* below stores dropped characters
> +				 * related information in next msg
> +				 */
> +				size_t drop_len;
> +
> +				drop_len = scnprintf(drop_msg,
> +					MAX_DROP_MSG_LENGTH,
> +					"<%u characters dropped>",
> +					(next) ?
> +					(unsigned int)(text_size + next - text) :
> +					(unsigned int)text_size);
> +				drop_msg[drop_len] = 0;
> +				log_store(msg->facility, msg->level, msg->flags,
> +					0, NULL, 0, drop_msg, strlen(drop_msg));
>  				break;
> +			}

this change, most likely, will confuse people. because msg_print_text() is
called on a message that is being currently processed, which is not
necessarily the last message in the logbuf. for example, see console_unlock().
we do something like this:

		while (console_seq != log_next_seq) {
			msg = log_from_idx(console_idx);
			msg_print_text(msg);
			console_idx = log_next(console_idx);
			console_seq++;
		}

your log_store(), invoked from msg_print_text(), will append the error
message to the logbuf (tail), possibly far-far-far away from console_idx.
so your "characters dropped" warning will appear much later.


>  			len += print_prefix(msg, syslog, buf + len);
>  			memcpy(buf + len, text, text_len);


but more importantly, msg_print_text() is called from several places. and
can even be called from a user space, potentially triggering the same
"<characters dropped>" error log_store() over and over again, wiping out
the actually important kernel messages. which is
	a) not nice
and
	b) can be used to deliberately "hide" something really important.


so, no. sorry, I don't like this change.

	-ss

Re: [RFC V2] printk: add warning while drop partial text in msg

[pierre kuo]

hi Sergey
> this is not the only place that can truncate the message.
> vprintk_emit() can do so as well /* vscnprintf() */. but
> I think we don't care that much. a user likely will  notice
> truncated messages. we report lost messages, because this
> is a completely different sort of problem.
Usually people will more easily find message truncated from semantics
by vscnprintf,
since it brute force truncate input message by the upper limit of output buffer.

In msg_print_text, it use memchr to find "\n" as copying unit while
memcping msg->text to output buffer.
People will more difficultly to find out some part of message is left behind.
That is the reason I try to add such warning in msg_print_text.

>
>
> [..]
>> @@ -1264,8 +1270,23 @@ static size_t msg_print_text(const struct printk_log *msg, bool syslog, char *bu
>>
>>               if (buf) {
>>                       if (print_prefix(msg, syslog, NULL) +
>> -                         text_len + 1 >= size - len)
>> +                         text_len + 1 >= size - len) {
>> +                             /* below stores dropped characters
>> +                              * related information in next msg
>> +                              */
>> +                             size_t drop_len;
>> +
>> +                             drop_len = scnprintf(drop_msg,
>> +                                     MAX_DROP_MSG_LENGTH,
>> +                                     "<%u characters dropped>",
>> +                                     (next) ?
>> +                                     (unsigned int)(text_size + next - text) :
>> +                                     (unsigned int)text_size);
>> +                             drop_msg[drop_len] = 0;
>> +                             log_store(msg->facility, msg->level, msg->flags,
>> +                                     0, NULL, 0, drop_msg, strlen(drop_msg));
>>                               break;
>> +                     }
>
> this change, most likely, will confuse people. because msg_print_text() is
> called on a message that is being currently processed, which is not
> necessarily the last message in the logbuf. for example, see console_unlock().
> we do something like this:
>
>                 while (console_seq != log_next_seq) {
>                         msg = log_from_idx(console_idx);
>                         msg_print_text(msg);
>                         console_idx = log_next(console_idx);
>                         console_seq++;
>                 }
>
> your log_store(), invoked from msg_print_text(), will append the error
> message to the logbuf (tail), possibly far-far-far away from console_idx.
> so your "characters dropped" warning will appear much later.
>
>
>>                       len += print_prefix(msg, syslog, buf + len);
>>                       memcpy(buf + len, text, text_len);
>
>
> but more importantly, msg_print_text() is called from several places. and
> can even be called from a user space, potentially triggering the same
> "<characters dropped>" error log_store() over and over again, wiping out
> the actually important kernel messages. which is
>         a) not nice
> and
>         b) can be used to deliberately "hide" something really important.
>
>
> so, no. sorry, I don't like this change.
>
>         -ss

Re: [RFC V2] printk: add warning while drop partial text in msg

[pierre kuo]

hi Sergey:
(Please ignore previous mail, I apologize for pressing send button too early :)
>> this is not the only place that can truncate the message.
>> vprintk_emit() can do so as well /* vscnprintf() */. but
>> I think we don't care that much. a user likely will  notice
>> truncated messages. we report lost messages, because this
>> is a completely different sort of problem.
Usually people will more easily find message truncated from semantics
by vscnprintf, since it brute force truncate input message by the
upper limit of output buffer.

In msg_print_text, it use memchr to find "\n" as copying unit while
memcping msg->text to output buffer.
And people will be hard to find out some part of message is left behind.
(since the tail of original message is elegantly dropped by "\n")
That is the reason I try to add such warning in msg_print_text.

> your log_store(), invoked from msg_print_text(), will append the error
> message to the logbuf (tail), possibly far-far-far away from console_idx.
> so your "characters dropped" warning will appear much later.
Got ur point and thanks for your advising.

>>                       len += print_prefix(msg, syslog, buf + len);
>>                       memcpy(buf + len, text, text_len);
>
>
> but more importantly, msg_print_text() is called from several places. and
> can even be called from a user space, potentially triggering the same
> "<characters dropped>" error log_store() over and over again, wiping out
> the actually important kernel messages. which is
>         a) not nice
> and
>         b) can be used to deliberately "hide" something really important.
>
how about we directly adding warning message in buffer instead of
log_store like below?
Appreciate your review and advising.

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index fc47863..fcd1dd4 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -557,6 +557,7 @@ static u32 msg_used_size(u16 text_len, u16
dict_len, u32 *pad_len)
  */
 #define MAX_LOG_TAKE_PART 4
 static const char trunc_msg[] = "<truncated>";
+static const char drop_msg[] = "<dropped>";

 static u32 truncate_msg(u16 *text_len, u16 *trunc_msg_len,
                        u16 *dict_len, u32 *pad_len)
@@ -1264,8 +1265,14 @@ static size_t msg_print_text(const struct
printk_log *msg, bool syslog, char *bu

                if (buf) {
                        if (print_prefix(msg, syslog, NULL) +
-                           text_len + 1 >= size - len)
+                           text_len + 1 >= size - len) {
+                               /* below adding warning message
+                                * related information into output buffer
+                                */
+                               if ((size - len) > strlen(drop_msg))
+                                       memcpy(buf + len, drop_msg,
strlen(drop_msg));
                                break;
+                       }

                        len += print_prefix(msg, syslog, buf + len);
                        memcpy(buf + len, text, text_len);

Re: [RFC V2] printk: add warning while drop partial text in msg

[Petr Mladek]

On Fri 2017-08-11 00:55:48, pierre kuo wrote:
> hi Sergey:
> (Please ignore previous mail, I apologize for pressing send button too early :)
> >> this is not the only place that can truncate the message.
> >> vprintk_emit() can do so as well /* vscnprintf() */. but
> >> I think we don't care that much. a user likely will  notice
> >> truncated messages. we report lost messages, because this
> >> is a completely different sort of problem.
> Usually people will more easily find message truncated from semantics
> by vscnprintf, since it brute force truncate input message by the
> upper limit of output buffer.

Do you see the problem in the real life, please?

I ask because msg_print_text() seems to be used carefully.

For example, syslog_idx is bumped in syslog_print() only when
the message fits into the buffer. It repeats the read with an
empty buffer until the bigger userspace buffer is full.

Also kmsg_dump_get_buffer() first checks the size of the messages.
Then it calls msg_print_text() only for messages that fit into
the buffer.

These functions are called from userspace. Of course, all messages
do not fit into the userspace buffer. But userspace repeats the read
until all messages are read. IMHO, nothing is really dropped here.

Best Regards,
Petr

Re: [RFC V2] printk: add warning while drop partial text in msg

[Sergey Senozhatsky]

Hi,

On (08/11/17 00:55), pierre kuo wrote:
[..]
> And people will be hard to find out some part of message is left behind.
> (since the tail of original message is elegantly dropped by "\n")
> That is the reason I try to add such warning in msg_print_text.

have you ever seen it (the truncation) in real life?

	-ss

Re: [RFC V2] printk: add warning while drop partial text in msg

[pierre kuo]

[-- Attachment #1: Type: text/plain, Size: 4062 bytes --]

hi Sergey and Petr
> Hi,
> On (08/11/17 00:55), pierre kuo wrote:
> [..]
>> And people will be hard to find out some part of message is left behind.
>> (since the tail of original message is elegantly dropped by "\n")
>> That is the reason I try to add such warning in msg_print_text.
>
> have you ever seen it (the truncation) in real life?
The experimental steps are list as follows.
Feel free to give your comments.

Prerequisite:
a) kernel version:
    commit: a80099a152d0 ("Merge tag 'xfs-4.13-merge-6' of
git://git.kernel.org/pub/scm/fs/xfs/xfs-linux")

1. Add below patch in log_store to tell the content and length of log
that saved in log_text(msg) for below step #2 .
@@ -629,6 +629,11 @@ static int log_store(int facility, int level,
        msg->len = size;

        /* insert message */
+       if (msg->text_len > 512) {
+               trace_printk("%s\n", log_text(msg));
+               trace_printk("msg->text_len %d\n", msg->text_len);
+       }
+
        log_next_idx += msg->len;
        log_next_seq++;

2. Use below kernel thread sample for adding the string to msg.
int per_cpu_thread_fn(void* data)
{
    unsigned int index = 0;
    unsigned int len = 0;
    char* local_string = kzalloc(2048, GFP_KERNEL);

    do {
        len += sprintf((local_string + len), "this is the %d line\n", index++);
    }while(len < 576);
    printk_deferred("%s", local_string);
    return 0;
}

3. After running above #2, here is trace output from #1
(from the output, total "29 lines" of local_string has successfully
saved in log_buf)
# cat /sys/kernel/debug/tracing/trace;
# tracer: nop
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
  per_cpu_thread-81    [000] d..1    26.555745: log_store: this is the 0 line
this is the 1 line
this is the 2 line
this is the 3 line
this is the 4 line
this is the 5 line
this is the 6 line
this is the 7 line
this is the 8 line
this is the 9 line
this is the 10 line
this is the 11 line
this is the 12 line
this is the 13 line
this is the 14 line
this is the 15 line
this is the 16 line
this is the 17 line
this is the 18 line
this is the 19 line
this is the 20 line
this is the 21 line
this is the 22 line
this is the 23 line
this is the 24 line
this is the 25 line
this is the 26 line
this is the 27 line
this is the 28 line
this is the 29 line
  per_cpu_thread-81    [000] d..1    26.555753: log_store: msg->text_len 589

4. Write a user mode programs with buffer size 2MB, triple size bigger
than the text length in msg we saved in above #2, and repeatedly
calling SYSLOG_ACTION_READ for getting the log.
Then the log we got will _NOT_ show over than "this is the 26 line" as
below, that mean line#27 ~ line#29 are missing.
(the source is attached as "simple_log.tar.bz2")
<4>[   39.467710] this is the 0 line
<4>[   39.467710] this is the 1 line
<4>[   39.467710] this is the 2 line
<4>[   39.467710] this is the 3 line
<4>[   39.467710] this is the 4 line
<4>[   39.467710] this is the 5 line
<4>[   39.467710] this is the 6 line
<4>[   39.467710] this is the 7 line
<4>[   39.467710] this is the 8 line
<4>[   39.467710] this is the 9 line
<4>[   39.467710] this is the 10 line
<4>[   39.467710] this is the 11 line
<4>[   39.467710] this is the 12 line
<4>[   39.467710] this is the 13 line
<4>[   39.467710] this is the 14 line
<4>[   39.467710] this is the 15 line
<4>[   39.467710] this is the 16 line
<4>[   39.467710] this is the 17 line
<4>[   39.467710] this is the 18 line
<4>[   39.467710] this is the 19 line
<4>[   39.467710] this is the 20 line
<4>[   39.467710] this is the 21 line
<4>[   39.467710] this is the 22 line
<4>[   39.467710] this is the 23 line
<4>[   39.467710] this is the 24 line
<4>[   39.467710] this is the 25 line
<4>[   39.467710] this is the 26 line

[-- Attachment #2: simple_log.tar.bz2 --]
[-- Type: application/x-bzip2, Size: 755 bytes --]

Re: [RFC V2] printk: add warning while drop partial text in msg

[Sergey Senozhatsky]

Hi,

On (09/12/17 14:07), pierre kuo wrote:
[..]
> int per_cpu_thread_fn(void* data)
> {
>     unsigned int index = 0;
>     unsigned int len = 0;
>     char* local_string = kzalloc(2048, GFP_KERNEL);
> 
>     do {
>         len += sprintf((local_string + len), "this is the %d line\n", index++);
>     }while(len < 576);
>     printk_deferred("%s", local_string);
>     return 0;
> }

which is not a real world example, isn't it?

printk_deferred("%s", local_string[2048]) makes no sense anyway,
since we limit the message size to 1024 - HEADER chars in
vprintk_emit()  // see static char textbuf[LOG_LINE_MAX].

I'm not quite following what were you trying to prove, sorry.
does any function in the upstream kernel printk()-s buffers
larger than LOG_LINE_MAX? which one?


- the longest line in my dmesg output is 260 bytes in total (including timestamp)
- the second longest is 237 bytes (including timestamp)
- the third largest is 191 bytes (including timestamp)


the longest single printk() line known to me is from OOM code:

		show_node(zone);
		printk(KERN_CONT
			"%s"
			" free:%lukB"
			" min:%lukB"
			" low:%lukB"
			" high:%lukB"
			" active_anon:%lukB"
			" inactive_anon:%lukB"
			" active_file:%lukB"
			" inactive_file:%lukB"
			" unevictable:%lukB"
			" writepending:%lukB"
			" present:%lukB"
			" managed:%lukB"
			" mlocked:%lukB"
			" kernel_stack:%lukB"
			" pagetables:%lukB"
			" bounce:%lukB"
			" free_pcp:%lukB"
			" local_pcp:%ukB"
			" free_cma:%lukB"
			"\n",
			zone->name,
			K(zone_page_state(zone, NR_FREE_PAGES)),
			K(min_wmark_pages(zone)),
			K(low_wmark_pages(zone)),
			K(high_wmark_pages(zone)),
			K(zone_page_state(zone, NR_ZONE_ACTIVE_ANON)),
			K(zone_page_state(zone, NR_ZONE_INACTIVE_ANON)),
			K(zone_page_state(zone, NR_ZONE_ACTIVE_FILE)),
			K(zone_page_state(zone, NR_ZONE_INACTIVE_FILE)),
			K(zone_page_state(zone, NR_ZONE_UNEVICTABLE)),
			K(zone_page_state(zone, NR_ZONE_WRITE_PENDING)),
			K(zone->present_pages),
			K(zone->managed_pages),
			K(zone_page_state(zone, NR_MLOCK)),
			zone_page_state(zone, NR_KERNEL_STACK_KB),
			K(zone_page_state(zone, NR_PAGETABLE)),
			K(zone_page_state(zone, NR_BOUNCE)),
			K(free_pcp),
			K(this_cpu_read(zone->pageset->pcp.count)),
			K(zone_page_state(zone, NR_FREE_CMA_PAGES)));

but I believe even this line should be less than 1K bytes.
or are you aware of any cases when it passes the 1k limit?

we are straggling to resolve the _existing_ printk issues, so
_theoretical_ and never seen problems are not on my radar.

	-ss

Re: [RFC V2] printk: add warning while drop partial text in msg

[Joe Perches]

On Mon, 2017-09-18 at 18:39 +0900, Sergey Senozhatsky wrote:
> Hi,
> 
> On (09/12/17 14:07), pierre kuo wrote:
> [..]
> > int per_cpu_thread_fn(void* data)
> > {
> >     unsigned int index = 0;
> >     unsigned int len = 0;
> >     char* local_string = kzalloc(2048, GFP_KERNEL);
> > 
> >     do {
> >         len += sprintf((local_string + len), "this is the %d line\n", index++);
> >     }while(len < 576);
> >     printk_deferred("%s", local_string);
> >     return 0;
> > }
> 
> which is not a real world example, isn't it?
> 
> printk_deferred("%s", local_string[2048]) makes no sense anyway,
> since we limit the message size to 1024 - HEADER chars in
> vprintk_emit()  // see static char textbuf[LOG_LINE_MAX].
> 
> I'm not quite following what were you trying to prove, sorry.
> does any function in the upstream kernel printk()-s buffers
> larger than LOG_LINE_MAX? which one?
> 
> 
> - the longest line in my dmesg output is 260 bytes in total (including timestamp)

try a kernel with a few modules loaded

For instance:

$ dmesg | awk '{ print length($0), $0 }'|sort -rn | head -1
827 [337318.968616] Modules linked in: snd_usb_audio snd_usbmidi_lib ccm rfcomm bnep snd_hda_codec_hdmi dell_led snd_hda_codec_realtek snd_hda_codec_generic hid_multitouch binfmt_misc nls_iso8859_1 arc4 i2c_designware_platform i2c_designware_core dell_wmi snd_soc_skl snd_soc_skl_ipc snd_soc_sst_ipc snd_soc_sst_dsp snd_hda_ext_core snd_soc_sst_match snd_soc_core snd_compress ac97_bus snd_pcm_dmaengine snd_hda_intel dell_laptop intel_rapl snd_hda_codec dell_smbios dcdbas x86_pkg_temp_thermal snd_hda_core intel_powerclamp snd_hwdep coretemp kvm_intel snd_pcm kvm irqbypass crct10dif_pclmul crc32_pclmul ghash_clmulni_intel iwlmvm pcbc mac80211 snd_seq_midi snd_seq_midi_event aesni_intel aes_x86_64 crypto_simd snd_rawmidi glue_helper cryptd intel_cstate intel_rapl_perf snd_seq iwlwifi snd_seq_device uvcvideo videobuf2_vmalloc

Re: [RFC V2] printk: add warning while drop partial text in msg

[Sergey Senozhatsky]

On (09/18/17 03:00), Joe Perches wrote:
[..]
> > which is not a real world example, isn't it?
> > 
> > printk_deferred("%s", local_string[2048]) makes no sense anyway,
> > since we limit the message size to 1024 - HEADER chars in
> > vprintk_emit()  // see static char textbuf[LOG_LINE_MAX].
> > 
> > I'm not quite following what were you trying to prove, sorry.
> > does any function in the upstream kernel printk()-s buffers
> > larger than LOG_LINE_MAX? which one?
> > 
> > 
> > - the longest line in my dmesg output is 260 bytes in total (including timestamp)
> 
> try a kernel with a few modules loaded
> 
> For instance:
> 
> $ dmesg | awk '{ print length($0), $0 }'|sort -rn | head -1
> 827 [337318.968616] Modules linked in: snd_usb_audio snd_usbmidi_lib ccm rfcomm bnep snd_hda_codec_hdmi dell_led snd_hda_codec_realtek snd_hda_codec_generic hid_multitouch binfmt_misc nls_iso8859_1 arc4 i2c_designware_platform i2c_designware_core dell_wmi snd_soc_skl snd_soc_skl_ipc snd_soc_sst_ipc snd_soc_sst_dsp snd_hda_ext_core snd_soc_sst_match snd_soc_core snd_compress ac97_bus snd_pcm_dmaengine snd_hda_intel dell_laptop intel_rapl snd_hda_codec dell_smbios dcdbas x86_pkg_temp_thermal snd_hda_core intel_powerclamp snd_hwdep coretemp kvm_intel snd_pcm kvm irqbypass crct10dif_pclmul crc32_pclmul ghash_clmulni_intel iwlmvm pcbc mac80211 snd_seq_midi snd_seq_midi_event aesni_intel aes_x86_64 crypto_simd snd_rawmidi glue_helper cryptd intel_cstate intel_rapl_perf snd_seq iwlwifi snd_seq_device uvcvideo videobuf2_vmalloc

linked modules are not printed as a single line - printk("module linked in ................................").


it's a bunch of pr_cont() calls:

	printk(KERN_DEFAULT "Modules linked in:");
	list_for_each_entry_rcu(mod, &modules, list) {
		pr_cont(" %s%s", mod->name, module_flags(mod, buf))
	}


when pr_cont() buffer is getting full, we just flush it (log_store())

	if (cont.len + len > sizeof(cont.buf))
		cont_flush();


but the point is -- we don't truncate anything
here, and don't lose the content. don't we?

	-ss

Re: [RFC V2] printk: add warning while drop partial text in msg

[pierre kuo]

hi:
> printk_deferred("%s", local_string[2048]) makes no sense anyway,
> since we limit the message size to 1024 - HEADER chars in
> vprintk_emit()  // see static char textbuf[LOG_LINE_MAX].

In local_string[2048], it will all be 0 from [590] to [2047].
And vprintk_emit() will cut message from [LOG_LINE_MAX(992)] to [2047].

so, from [0] to [589], whole messages are saved in msg->text as
expected, from "this is the 0 line\n" to "this is the 29 line\n"
No truncating happen in this stage.
(sorry for declaring local_string[] as 2048 makes people confused.)

Below is what msg->text saved:
560 + 30 = 590
^^      ^^^
 |        |
 |        --> 30 "\n"
 |
 --> 560 chars without "\n" from  "this is the 0 line" to "this is the 29 line"

Below is complete message size output from msg_print_text:
18*30 + 590 = 540 + 590 = 1130 Bytes
^^^^^     ^^^
  |           |
  |           --> 590 chars of msg->text
  |
  -->30 lines with each 18 chars in the prefix(15 for timesatmap and 3
for levle and facility)

Below is the constituents that msg_print_text sent to buf[1024]
(the size of buf, 1024, pass to msg_print_text is < 1130)
18*27 + 530= 486 + 530=  1016 Bytes
^^^^^     ^^^
  |           |
  |           -->max chars found by memchr with "\n" as copying unit
to meet the upper bound, 1024.
  |               (from "this is the 0 line" to "this is the 26 line")
  |
  --> 27 lines with each 18 character in the prefix

so characters left in msg->text not putting to the buffer are 590 -
530 = 60 chars.
(Truncate the message from "this is the 27 line\n" to "this is the 29 line\n".)

We use the example in this mail since we try to collect the message at
different places in our driver.
And batch to printk for saving individual output time and group
message together.

> I'm not quite following what were you trying to prove, sorry.
>does any function in the upstream kernel printk()-s buffers
>larger than LOG_LINE_MAX? which one?

You are correct.
The upstream kernel printk()-s buffers are indeed smaller LOG_LINE_MAX
and not with multi "\n" like this example did.

> we are straggling to resolve the _existing_ printk issues, so
> _theoretical_ and never seen problems are not on my radar.

Got it and really appreciate your kind explanation.

Re: [RFC V2] printk: add warning while drop partial text in msg

[Sergey Senozhatsky]

On (09/27/17 21:59), pierre kuo wrote:
[..]
> We use the example in this mail since we try to collect the message at
> different places in our driver.
> And batch to printk for saving individual output time and group
> message together.

I see. well, printk batching (buffered mode) is a bit tricky and we
don't have it, nor we recommend it. the main problem - you lose your
data on panic. it seems to me, that the only way to do it is to re-use
printk-safe buffer on that particular CPU. but it comes at a price and
in general is a bit ugly.

	-ss

Re: [RFC V2] printk: add warning while drop partial text in msg

[Petr Mladek]

Hi,

I was curious why you see these results. I think that I finally
understand it.

On Tue 2017-09-12 14:07:09, pierre kuo wrote:
> The experimental steps are list as follows.
> Feel free to give your comments.
> 
> Prerequisite:
> a) kernel version:
>     commit: a80099a152d0 ("Merge tag 'xfs-4.13-merge-6' of
> git://git.kernel.org/pub/scm/fs/xfs/xfs-linux")
> 
> 1. Add below patch in log_store to tell the content and length of log
> that saved in log_text(msg) for below step #2 .
> @@ -629,6 +629,11 @@ static int log_store(int facility, int level,
>         msg->len = size;
> 
>         /* insert message */
> +       if (msg->text_len > 512) {
> +               trace_printk("%s\n", log_text(msg));
> +               trace_printk("msg->text_len %d\n", msg->text_len);
> +       }
> +
>         log_next_idx += msg->len;
>         log_next_seq++;
> 
> 2. Use below kernel thread sample for adding the string to msg.
> int per_cpu_thread_fn(void* data)
> {
>     unsigned int index = 0;
>     unsigned int len = 0;
>     char* local_string = kzalloc(2048, GFP_KERNEL);
> 
>     do {
>         len += sprintf((local_string + len), "this is the %d line\n", index++);
>     }while(len < 576);
>     printk_deferred("%s", local_string);

You call printk() for a string which length is slightly above 576
characters. Therefore it fits into textbuf[LOG_LINE_MAX] in vprintk_emit().
It is stored in a single record into the main log buffer.
Nothing is lost at this stage. So far so good.


>     return 0;
> }
> 
> 3. After running above #2, here is trace output from #1
> (from the output, total "29 lines" of local_string has successfully
> saved in log_buf)
> # cat /sys/kernel/debug/tracing/trace;
> # tracer: nop
> #
> #                              _-----=> irqs-off
> #                             / _----=> need-resched
> #                            | / _---=> hardirq/softirq
> #                            || / _--=> preempt-depth
> #                            ||| /     delay
> #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
> #              | |       |   ||||       |         |
>   per_cpu_thread-81    [000] d..1    26.555745: log_store: this is the 0 line
> this is the 1 line
> this is the 2 line
[...]
> this is the 27 line
> this is the 28 line
> this is the 29 line
>   per_cpu_thread-81    [000] d..1    26.555753: log_store: msg->text_len 589

The above messages are from ftrace buffer. Please note that the
timestamp is printed only for "this is the 0 line". It confirms
that all lines fit into textbuf[LOG_LINE_MAX] and were stored
as a single record by a single log_store() call.


> 4. Write a user mode programs with buffer size 2MB, triple size bigger
> than the text length in msg we saved in above #2, and repeatedly
> calling SYSLOG_ACTION_READ for getting the log.
> Then the log we got will _NOT_ show over than "this is the 26 line" as
> below, that mean line#27 ~ line#29 are missing.
> (the source is attached as "simple_log.tar.bz2")
> <4>[   39.467710] this is the 0 line
> <4>[   39.467710] this is the 1 line
[...]
> <4>[   39.467710] this is the 24 line
> <4>[   39.467710] this is the 25 line
> <4>[   39.467710] this is the 26 line

You used SYSLOG_ACTION_READ. Therefore the above lines were
formatted by msg_print_text() called from syslog_print().

Now, msg_print_text() could not write directly into the 2MB
big buffer because it is is from userspace. Instead, it writes
the messages into the temporary buffer that is later copied
to the userspace one by copy_to_user().

The temporary buffer is allocated in syslog_print():

	text = kmalloc(LOG_LINE_MAX + PREFIX_MAX, GFP_KERNEL);

The expectation is that there will be needed only one timestamp
(prefix) for each stored record (line).

But we saved more lines in a single record. Therefore msg_print_text()
has to add many timestamps (prefixes). As a result the original 576
bytes long message does not fit into 1024 bytes big buffer and
is shrunken.


There are several possible solutions:

+ We could update vprintk_emit() to detect all newlines and
  call log_store() for each part. But this would be a waste
  of the space.

+ We could increase the size provided by syslog_printk().
  But this is ugly.

+ We could go back to the original idea and print a warning
  about shrunken message when the first record is not fully
  stored by msg_print_text().

I think that the last solution is the best. Note that the
original patch was wrong because it warned in any
msg_print_text() and not only the first one.

Another question is that printk() is used a wrong way here.
I will comment this in another mail in this thread.

Best Regards,
Petr

Re: [RFC V2] printk: add warning while drop partial text in msg

[Petr Mladek]

On Wed 2017-09-27 21:59:52, pierre kuo wrote:
> hi:
> > printk_deferred("%s", local_string[2048]) makes no sense anyway,
> > since we limit the message size to 1024 - HEADER chars in
> > vprintk_emit()  // see static char textbuf[LOG_LINE_MAX].
> 
> We use the example in this mail since we try to collect the message at
> different places in our driver.
> And batch to printk for saving individual output time and group
> message together.

I wonder what is the motivation for the extra buffering. Did you
have troubles with direct printk() calls? For example, because
of performance, mixed messages, deadlocks?

Note that any buffering is potentially dangerous. You might miss
the messages if the system dies before they are flushed. Also
you might lose messages if the buffer is too small.


> > I'm not quite following what were you trying to prove, sorry.
> >does any function in the upstream kernel printk()-s buffers
> >larger than LOG_LINE_MAX? which one?
> 
> You are correct.
> The upstream kernel printk()-s buffers are indeed smaller LOG_LINE_MAX
> and not with multi "\n" like this example did.

You might go around this by flushing the buffer line by line.
Well, it might get quite complicated, see printk_safe_flush_buffer().
Another question is if the buffering makes sense then.

Best Regards,
Petr

Re: [RFC V2] printk: add warning while drop partial text in msg

[pierre kuo]

hi:
> There are several possible solutions:
>
> + We could update vprintk_emit() to detect all newlines and
>   call log_store() for each part. But this would be a waste
>   of the space.
>
> + We could increase the size provided by syslog_printk().
>   But this is ugly.
>
> + We could go back to the original idea and print a warning
>   about shrunken message when the first record is not fully
>   stored by msg_print_text().
>
> I think that the last solution is the best. Note that the
> original patch was wrong because it warned in any
> msg_print_text() and not only the first one.

Would you mind to let me know more about the wrong places you mean
about the patch?
(since I cannot quite understand the "warned in any msg_print_text()
and not only the first one" mean)

In Aug. 11, https://lkml.org/lkml/2017/8/10/707,
Only if below a) and b) are both true, the patch will try to put
warning message at the end of output buffer.
a) sizeof((the next phrase cut by "\n" token ) + prefix composed by
(level | facility | timestamp)) > left length of output buffer
b) (the left length of output buffer) > strlen ("<dropped>");

so If any one of above a) or b) is not satisfied, there will be no
warning message.
Meanwhile, console_seq, clear_seq and syslog_seq will still increase
for next msg_print_text() run.
So the warning message will not always shows.

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index fc47863..fcd1dd4 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -557,6 +557,7 @@ static u32 msg_used_size(u16 text_len, u16
dict_len, u32 *pad_len)
  */
 #define MAX_LOG_TAKE_PART 4
 static const char trunc_msg[] = "<truncated>";
+static const char drop_msg[] = "<dropped>";

 static u32 truncate_msg(u16 *text_len, u16 *trunc_msg_len,
                        u16 *dict_len, u32 *pad_len)
@@ -1264,8 +1265,14 @@ static size_t msg_print_text(const struct
printk_log *msg, bool syslog, char *bu

                if (buf) {
                        if (print_prefix(msg, syslog, NULL) +
-                           text_len + 1 >= size - len)
+                           text_len + 1 >= size - len) {
+                               /* below adding warning message
+                                * related information into output buffer
+                                */
+                               if ((size - len) > strlen(drop_msg))
+                                       memcpy(buf + len, drop_msg,
strlen(drop_msg));
                                break;
+                       }

>Another question is that printk() is used a wrong way here.
>I will comment this in another mail in this thread.
please see my answer in another mail.

Re: [RFC V2] printk: add warning while drop partial text in msg

[pierre kuo]

hi Petr and Sergey:
> I wonder what is the motivation for the extra buffering. Did you
> have troubles with direct printk() calls? For example, because
> of performance, mixed messages, deadlocks?

Yes, when using direct printk() calls, we suffer performance and mix
message issues.
(Since originally we try to collect the status of hardware and driver
at different places,
then use a work queue periodically for printk() the results of above
collections or
also do some simple analysis and calculation before printk().)

>
> Note that any buffering is potentially dangerous. You might miss
> the messages if the system dies before they are flushed. Also
> you might lose messages if the buffer is too small.
> You might go around this by flushing the buffer line by line.

Yes, you are right.
Except flushing the buffer line by line, we try to shrink the buffer size
to the number that plus prefix words will not over the size of
textbuf[], say 992 Bytes.
(that mean "size of buffer + 18*(number of "\n") < 992 Bytes")


> Well, it might get quite complicated, see printk_safe_flush_buffer().

BTW,  after checking printk_safe_flush_buffer() and related functions,
we have one question:
a) Why in printk_safe_log_store(), we need to use  atomic_xxxx operation in it?
    printk_safe_log_store() will be called in either one of below case
    i) PRINTK_NMI_CONTEXT_MASK
    ii) PRINTK_SAFE_CONTEXT_MASK
    and each of them will bring each CPU's own nmi_print_seq or
safe_print_seq separately.
    why it still need atomic_xxx operations like below *** show?

kernel/printk/printk_safe.c
-->static __printf(2, 0) int printk_safe_log_store(struct
printk_safe_seq_buf *s,
                                                const char *fmt, va_list args)
{
        int add;
        size_t len;
again:
        len = atomic_read(&s->len);          **************************


> Another question is if the buffering makes sense then.
We explained our initial thought above.

Appreciate you and Sergey's great comment and help,

Re: [RFC V2] printk: add warning while drop partial text in msg

[Sergey Senozhatsky]

On (10/18/17 01:10), pierre kuo wrote:
[..]
> > Well, it might get quite complicated, see printk_safe_flush_buffer().
> 
> BTW,  after checking printk_safe_flush_buffer() and related functions,
> we have one question:
> a) Why in printk_safe_log_store(), we need to use  atomic_xxxx operation in it?

because IRQ flush work iterates all CPUs and modifies CPUs' buffer state,
and this easily can race with printk_safe() or printk_nmi() on some of the
CPUs.

	-ss