2017-07-30 13:38:15

by pierre kuo

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

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 <[email protected]>
---
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


2017-08-01 02:42:52

by Sergey Senozhatsky

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

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

2017-08-10 16:26:12

by pierre kuo

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

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

2017-08-10 16:55:51

by pierre kuo

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

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);

2017-08-16 09:21:43

by Petr Mladek

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

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

2017-08-17 01:05:27

by Sergey Senozhatsky

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

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

2017-09-12 06:07:13

by pierre kuo

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

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


Attachments:
simple_log.tar.bz2 (755.00 B)

2017-09-18 09:39:14

by Sergey Senozhatsky

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

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

2017-09-18 10:00:09

by Joe Perches

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

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

2017-09-18 10:09:06

by Sergey Senozhatsky

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

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

2017-09-27 13:59:57

by pierre kuo

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

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.

2017-09-30 03:14:39

by Sergey Senozhatsky

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

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