Re: [PATCH bpf v3 2/2] selftests/bpf: add a test for subprogram extables

[Krister Johansen <kjlx@templeofstupid.com>]

On Fri, Jun 09, 2023 at 11:15:18AM -0700, Alexei Starovoitov wrote:
> On Thu, Jun 8, 2023 at 5:11 PM Krister Johansen <kjlx@templeofstupid.com> wrote:
> > +SEC("fexit/bpf_testmod_return_ptr")
> > +int BPF_PROG(handle_fexit_ret_subprogs, int arg, struct file *ret)
> > +{
> > +       *(volatile long *)ret;
> > +       *(volatile int *)&ret->f_mode;
> > +       bpf_for_each_map_elem(&test_array, test_cb, NULL, 0);
> > +       return 0;
> > +}
> > +
> > +SEC("fexit/bpf_testmod_return_ptr")
> > +int BPF_PROG(handle_fexit_ret_subprogs2, int arg, struct file *ret)
> > +{
> > +       *(volatile long *)ret;
> > +       *(volatile int *)&ret->f_mode;
> > +       bpf_for_each_map_elem(&test_array, test_cb, NULL, 0);
> > +       return 0;
> > +}
> > +
> > +SEC("fexit/bpf_testmod_return_ptr")
> > +int BPF_PROG(handle_fexit_ret_subprogs3, int arg, struct file *ret)
> > +{
> > +       *(volatile long *)ret;
> > +       *(volatile int *)&ret->f_mode;
> > +       bpf_for_each_map_elem(&test_array, test_cb, NULL, 0);
> > +       return 0;
> > +}
> 
> What is the point of attaching 3 the same progs to the same hook?
> One would be enough to test it, no?

I thought so too, initially.  However, when I went to move this from the
original test case I submitted to the selftest, I found it was fairly
inconsistent about reproducing the problem with a single program.  I
believe this is because the kallsyms are stored in a binary tree, and
the prog and func[0] are identical.  Depending on where the item is
placed, the func[0] with the extable can sometimes be looked up instead
of the prog without.

Yonghong requested that I make note of this in the patch commit message.
I'll make sure that's included in the next version I send out.

> In other news...
> Looks like this test is triggering a bug on s390.

Not sure if this is worth mentioning, but when I run with
panic_on_oops=0 to capture the stack, I'm seeing some additional
warnings that follow the bpf bug.  Is any of this of interest?

   BUG: sleeping function called from invalid context at include/linux/percpu-rwsem.h:49
   in_atomic(): 0, irqs_disabled(): 0, non_block: 0, pid: 1132, name: test_progs
   preempt_count: 0, expected: 0
   RCU nest depth: 2, expected: 0
   INFO: lockdep is turned off.
   CPU: 0 PID: 1132 Comm: test_progs Tainted: G      D    OE      6.4.0-rc3+ #2
   Call Trace:
    <TASK>
    dump_stack_lvl+0x63/0x90
    dump_stack+0x14/0x20
    __might_resched+0x21d/0x230
    __might_sleep+0x45/0x70
    exit_signals+0x35/0x200
    do_exit+0xc6/0x920
    ? rewind_stack_and_make_dead+0x17/0x20
    ? make_task_dead+0xbe/0x140
    ? make_task_dead+0xbe/0x140
    make_task_dead+0x88/0x140
    rewind_stack_and_make_dead+0x17/0x20
   RIP: 0033:0x7fb5da00a392
   Code: ac 00 00 f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb be 0f 1f 80 00 00 00 00 f3 0f 1e fa 64 8b 04 25 18 00 00 00 85 c0 75 10 0f 05 <48> 3d 00 f0 ff ff 77 56 c3 0f 1f 44 00 00 48 83 ec 28 48 89 54 24
   RSP: 002b:00007ffc5b3cab68 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
   RAX: ffffffffffffffda RBX: 000055bee7b8b100 RCX: 00007fb5da00a392
   RDX: 00000000000001c8 RSI: 0000000000000000 RDI: 0000000000000009
   RBP: 00007ffc5b3caba0 R08: 0000000000000000 R09: 0000000000000037
   R10: 000055bee7b8c2a7 R11: 0000000000000246 R12: 000055bee78f1f60
   R13: 00007ffc5b3cae90 R14: 0000000000000000 R15: 0000000000000000
    </TASK>
   ------------[ cut here ]------------
   Voluntary context switch within RCU read-side critical section!
   WARNING: CPU: 0 PID: 1132 at kernel/rcu/tree_plugin.h:318 rcu_note_context_switch+0x4c0/0x5f0
   Modules linked in: bpf_testmod(OE) nls_iso8859_1 dm_multipath scsi_dh_rdac scsi_dh_emc scsi_dh_alua intel_rapl_msr intel_rapl_common intel_uncore_frequency_common ppdev nfit crct10dif_pclmul crc32_pclmul psmouse ghash_clmulni_intel sha512_ssse3 aesni_intel parport_pc crypto_simd cryptd input_leds parport rapl ena i2c_piix4 mac_hid serio_raw ramoops reed_solomon pstore_blk drm pstore_zone efi_pstore autofs4 [last unloaded: bpf_testmod(OE)]
   CPU: 0 PID: 1132 Comm: test_progs Tainted: G      D W  OE      6.4.0-rc3+ #2
   RIP: 0010:rcu_note_context_switch+0x4c0/0x5f0
   Code: fb ff ff 0f 0b e9 e0 fb ff ff e8 4b dd e3 ff a8 04 75 b5 0f 0b eb b1 c6 05 e4 03 a4 02 01 48 c7 c7 45 4a a1 ab e8 c0 e2 f1 ff <0f> 0b e9 f7 fb ff ff 0f 0b 45 84 f6 0f 84 d6 fb ff ff e9 e7 fb ff
   RSP: 0018:ffffb30c4291f9a8 EFLAGS: 00010046
   RAX: 4599311900096300 RBX: ffff92e644bf2a40 RCX: 0000000000000027
   RDX: 0000000000000000 RSI: ffffb30c4291f830 RDI: ffff92e95ee21948
   RBP: ffffb30c4291f9f8 R08: 0000000000000000 R09: ffffb30c4291f7d0
   R10: 00000000fffeffff R11: c0000000fffeffff R12: ffff92e95ee36680
   R13: ffffb30c4291fc58 R14: 0000000000000000 R15: 0000000000000000
   FS:  0000000000000000(0000) GS:ffff92e95ee00000(0000) knlGS:0000000000000000
   CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
   CR2: 000000000000000c CR3: 000000000d25e001 CR4: 00000000007706f0
   DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
   DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
   PKRU: 55555554
   Call Trace:
    <TASK>
    ? lock_release+0x46/0x330
    __schedule+0x173/0x1730
    ? trace_hardirqs_on+0x56/0xb0
    ? irqentry_exit+0x72/0xa0
    ? sysvec_irq_work+0x4a/0x90
    ? asm_sysvec_irq_work+0x1f/0x30
    schedule+0x6f/0xc0
    schedule_timeout+0x35/0x110
    ? native_write_msr+0xe/0x40
    ? __pfx_schedule_timeout+0x10/0x10
    ? trace_hardirqs_on+0x56/0xb0
    ? __pfx_schedule_timeout+0x10/0x10
    do_wait_for_common+0xe9/0x170
    ? __pfx_schedule_timeout+0x10/0x10
    ? __pfx_call_rcu+0x10/0x10
    wait_for_completion+0x53/0x70
    __wait_rcu_gp+0x12f/0x150
    synchronize_rcu_tasks_rude+0x67/0xc0
    ? __pfx_wakeme_after_rcu+0x10/0x10
    ? mutex_unlock+0x16/0x20
    ? __pfx_call_rcu_tasks_rude+0x10/0x10
    ftrace_shutdown+0x1ea/0x290
    ? 0xffffffffc04b8000
    unregister_ftrace_function+0x30/0x190
    ? 0xffffffffc04b8000
    ? 0xffffffffc04b8000
    unregister_ftrace_direct+0x51/0xf0
    ? __pfx_bpf_testmod_return_ptr+0x10/0x10 [bpf_testmod]
    ? 0xffffffffc04b8000
    bpf_trampoline_update+0x273/0x6d0
    bpf_trampoline_unlink_prog+0xb4/0x110
    bpf_tracing_link_release+0x1d/0x50
    bpf_link_put+0xd0/0x100
    bpf_link_release+0x19/0x30
    __fput+0x107/0x250
    ____fput+0x12/0x20
    task_work_run+0x89/0xd0
    do_exit+0x263/0x920
    ? make_task_dead+0xbe/0x140
    ? make_task_dead+0xbe/0x140
    make_task_dead+0x88/0x140
    rewind_stack_and_make_dead+0x17/0x20
   RIP: 0033:0x7fb5da00a392
   Code: Unable to access opcode bytes at 0x7fb5da00a368.
   RSP: 002b:00007ffc5b3cab68 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
   RAX: ffffffffffffffda RBX: 000055bee7b8b100 RCX: 00007fb5da00a392
   RDX: 00000000000001c8 RSI: 0000000000000000 RDI: 0000000000000009
   RBP: 00007ffc5b3caba0 R08: 0000000000000000 R09: 0000000000000037
   R10: 000055bee7b8c2a7 R11: 0000000000000246 R12: 000055bee78f1f60
   R13: 00007ffc5b3cae90 R14: 0000000000000000 R15: 0000000000000000
    </TASK>
   irq event stamp: 62970
   hardirqs last  enabled at (62969): [<ffffffffab1e14ba>] syscall_enter_from_user_mode+0x2a/0x1e0
   hardirqs last disabled at (62970): [<ffffffffab1e0bb1>] exc_page_fault+0x41/0x210
   softirqs last  enabled at (62912): [<ffffffffaa2e2ae2>] bpf_link_settle+0x32/0x50
   softirqs last disabled at (62910): [<ffffffffaa2e2acd>] bpf_link_settle+0x1d/0x50
   ---[ end trace 0000000000000000 ]---

-K