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.
