Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1730673 > unrolled thread

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

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: [RFC V2] printk: add warning while drop partial text in msg pierre kuo <vichy.kuo@gmail.com> - 2017-09-12 08:10 +0200
    Re: [RFC V2] printk: add warning while drop partial text in msg Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-09-18 11:40 +0200
      Re: [RFC V2] printk: add warning while drop partial text in msg Joe Perches <joe@perches.com> - 2017-09-18 12:10 +0200
        Re: [RFC V2] printk: add warning while drop partial text in msg Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-09-18 12:10 +0200

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

[Multipart message — attachments visible in raw view] — view raw

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

[toc] | [next] | [standalone]

#1733907

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

[toc] | [prev] | [next] | [standalone]

#1733994

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

[toc] | [prev] | [next] | [standalone]

#1733996

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

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web