lkml.org 
[lkml]   [2018]   [Nov]   [17]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
SubjectRe: [PATCH v6 1/3] printk: Add line-buffered printk() API.
From
Date
On 2018/11/12 16:59, Sergey Senozhatsky wrote:
> On (11/09/18 15:10), Petr Mladek wrote:
>>>
>>> If I'm not mistaken, this is for the futute "printk injection" work.
>>
>> The above code only tries to push complete lines to the main log buffer
>> and consoles ASAP. It sounds like a Good Idea(tm).
>
> Probably it is. So *quite likely* I'm wrong here.

In the future, I want to inject caller information to standard console output,
for syzbot is using serial console

[ 0.000000] Linux version 4.20.0-rc2-next-20181116+ (syzkaller@ci) (gcc version 8.0.1 20180413 (experimental) (GCC)) #120 SMP PREEMPT Fri Nov 16 20:21:42 UTC 2018
[ 0.000000] Command line: BOOT_IMAGE=/vmlinuz root=/dev/sda1 console=ttyS0 earlyprintk=serial vsyscall=native rodata=n oops=panic panic_on_warn=1 nmi_watchdog=panic panic=86400 security=apparmor ima_policy=tcb workqueue.watchdog_thresh=140 kvm-intel.nested=1 nf-conntrack-ftp.ports=20000 nf-conntrack-tftp.ports=20000 nf-conntrack-sip.ports=20000 nf-conntrack-irc.ports=20000 nf-conntrack-sane.ports=20000 vivid.n_devs=16 vivid.multiplanar=1,2,1,2,1,2,1,2,1,2,1,2,1,2,1,2 nopcid

and is experiencing confusion due to concurrent printk() like

[ 552.907865] syz-executor0: vmalloc: allocation failure: 256 bytes, mode:0x6000c0(GFP_KERNEL), nodemask=(null)
[ 552.921666] ------------[ cut here ]------------
[ 552.926434] DEBUG_LOCKS_WARN_ON(depth <= 0)
[ 552.926563] WARNING: CPU: 0 PID: 24211 at kernel/locking/lockdep.c:3595 lock_release+0x740/0xa10
[ 552.927489] syz-executor0 cpuset=syz0 mems_allowed=0
[ 552.930893] Kernel panic - not syncing: panic_on_warn set ...
[ 552.943750] CPU: 1 PID: 24208 Comm: syz-executor0 Not tainted 4.20.0-rc1-next-20181109+ #110
[ 552.959345] Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
[ 552.968694] Call Trace:
[ 552.971296] dump_stack+0x244/0x39d
[ 552.974934] ? dump_stack_print_info.cold.1+0x20/0x20
[ 552.980138] ? rcu_lockdep_current_cpu_online+0x1a4/0x210
[ 552.985685] warn_alloc.cold.116+0xb7/0x1bd
[ 552.990011] ? zone_watermark_ok_safe+0x3f0/0x3f0
[ 552.994884] ? __get_vm_area_node+0x130/0x3a0
[ 552.999387] ? rcu_read_lock_sched_held+0x14f/0x180
[ 553.004414] ? __might_fault+0x12b/0x1e0
[ 553.008487] ? __get_vm_area_node+0x2e5/0x3a0
[ 553.013000] __vmalloc_node_range+0x472/0x750
[ 553.017514] ? do_replace+0x23b/0x4c0
[ 553.021327] vmalloc+0x6f/0x80
(...snipped...)
[ 553.296333] __warn.cold.8+0x20/0x45
[ 553.296353] ? lock_release+0x740/0xa10
[ 553.329854] Node 0 DMA free:15908kB min:164kB low:204kB high:244kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15992kB managed:15908kB mlocked:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[ 553.332731] report_bug+0x254/0x2d0
[ 553.332796] do_error_trap+0x11b/0x200
[ 553.332822] do_invalid_op+0x36/0x40
[ 553.336825] lowmem_reserve[]: 0 2818 6321 6321
[ 553.362888] ? lock_release+0x740/0xa10
[ 553.362906] invalid_op+0x14/0x20
[ 553.362920] RIP: 0010:lock_release+0x740/0xa10
[ 553.362935] Code: 03 38 d0 7c 08 84 d2 0f 85 da 02 00 00 8b 35 a7 95 b3 08 85 f6 75 15 48 c7 c6 20 66 2b 88 48 c7 c7 c0 33 2b 88 e8 10 36 e7 ff <0f> 0b 48 8b 95 e8 fe ff ff 4c 89 f7 48 8b b5 f0 fe ff ff e8 e8 58
[ 553.362941] RSP: 0018:ffff8801839ef868 EFLAGS: 00010086
[ 553.362950] RAX: 0000000000000000 RBX: 1ffff1003073df12 RCX: ffffc9000be41000
[ 553.362957] RDX: 00000000000087b4 RSI: ffffffff8165ba15 RDI: 0000000000000006
[ 553.362966] RBP: ffff8801839ef998 R08: ffff88017c010600 R09: fffffbfff12b2254
[ 553.362974] R10: fffffbfff12b2254 R11: ffffffff895912a3 R12: ffffffff8b0e27a0
[ 553.362989] R13: ffff8801839ef970 R14: ffff88017c010600 R15: ffff8801839ef8b0
[ 553.373138] Node 0 DMA32 free:2887356kB min:30052kB low:37564kB high:45076kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:3129332kB managed:2888772kB mlocked:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:1416kB local_pcp:0kB free_cma:0kB
[ 553.374209] ? vprintk_func+0x85/0x181
[ 553.387199] lowmem_reserve[]: 0 0 3503 3503
[ 553.390755] ? lock_release+0x740/0xa10
[ 553.390840] ? loop_control_ioctl+0xf5/0x4e0

in https://syzkaller.appspot.com/bug?id=e7838e1e659de1ba566bb17410438b9d1dc59eb7 .

Thus, I appreciate if we could mitigate KERN_CONT problem using try_buffered_printk()
and move on to "caller information injection" topic. I'm fine with starting with
CONFIG_DEBUG_AID_FOR_SYZBOT=y.

\
 
 \ /
  Last update: 2018-11-17 11:15    [W:0.132 / U:0.044 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site