bug report: WARNING in bonding

bug report: WARNING in bonding

[Tariq Toukan]

Hi all,

In the past ~2-3 weeks, we started seeing the following WARNING and 
traces in our regression testing systems, almost every day.

Reproduction is not stable, and not isolated to a specific test, so it's 
hard to bisect.

Any idea what could this be?
Or what is the suspected offending patch?

We can provide any info / try stuff if needed.

Regards,
Tariq


  [12288.305076] WARNING: CPU: 4 PID: 701631 at 
drivers/net/bonding/bond_main.c:4310 bond_update_slave_arr+0x498/0×560 
[bonding]

  [12288.308167] Modules linked in: bonding nf_tables ipip tunnel4 
geneve ip6_gre ip6_tunnel tunnel6 ip_gre gre ip_tunnel mlx4_en ptp 
pps_core mlx4_ib mlx4_core rdma_ucm ib_uverbs ib_ipoib ib_umad macvlan 
vxlan ip6_udp_tunnel udp_tunnel 8021q garp mrp openvswitch nsh rpcrdma 
ib_iser libiscsi scsi_transport_iscsi rdma_cm iw_cm ib_cm ib_core 
xt_conntrack xt_MASQUERADE nf_conntrack_netlink nfnetlink xt_addrtype 
iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 
br_netfilter overlay [last unloaded: nf_tables]

  [12288.318333] CPU: 4 PID: 701631 Comm: python3 Not tainted 
5.9.0_for_upstream_min_debug_2020_10_19_16_22 #1

  [12288.320069] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), 
BIOS rel-1.13.0-0-gf21b5a4aeb02-prebuilt.qemu.org 04/01/2014

  [12288.322005] RIP: 0010:bond_update_slave_arr+0x498/0×560 [bonding]

  [12288.323079] Code: 25 fc ff ff 48 89 fe 4c 89 fa 48 c7 c7 e0 2c 73 
a0 48 89 04 24 e8 48 7b f1 e0 45 8b 04 24 48 8b 3b 48 8b 04 24 e9 a1 fc 
ff ff <0f> 0b e9 a0 fb ff ff 44 0f b7 74 24 12 e9 0f fc ff ff 31 d2 8d 46

  [12288.326199] RSP: 0018:ffff8881b13f7c48 EFLAGS: 00010202

  [12288.327152] RAX: 0000000000000001 RBX: ffff8881bb5a2b40 RCX: 
0000000000000000

  [12288.328389] RDX: 00000000fffffffe RSI: 00000000ffffffff RDI: 
ffff8881bb5a2b98

  [12288.329676] RBP: ffff8881bb5a2000 R08: 0000000000000000 R09: 
0000000000000000

  [12288.330986] R10: 0000000000000000 R11: ffffffff8237e060 R12: 
0000000000000001

  [12288.332228] R13: 0000000000000000 R14: ffff8881bb5a2b40 R15: 
0000000000000000

  [12288.333505] FS:  00007f84faffd700(0000) GS:ffff8882f5c00000(0000) 
knlGS:0000000000000000

  [12288.334844] mlx4_en: eth2: Link Up

  [12288.334989] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033

  [12288.336959] CR2: 00007f850e19ddb0 CR3: 00000001bc654004 CR4: 
0000000000370ea0

  [12288.338256] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 
0000000000000000

  [12288.339607] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 
0000000000000400

  [12288.340910] Call Trace:

  [12288.341451]  bond_enslave+0x1038/0×13e0 [bonding]

  [12288.342355]  ? __kernel_text_address+0xe/0×30

  [12288.343194]  ? unwind_get_return_address+0x1b/0×30

  [12288.344097]  ? sscanf+0x49/0×70

  [12288.344745]  bond_option_slaves_set+0xf3/0×1a0 [bonding]

  [12288.345773]  __bond_opt_set+0xe8/0×380 [bonding]

  [12288.346646]  __bond_opt_set_notify+0x27/0×80 [bonding]

  [12288.347606]  bond_opt_tryset_rtnl+0x51/0×90 [bonding]

  [12288.348553]  bonding_sysfs_store_option+0x4f/0×90 [bonding]

  [12288.349609]  kernfs_fop_write+0x114/0×1b0

  [12288.350385]  vfs_write+0xc1/0×1f0

  [12288.351058]  ksys_write+0xa7/0xe0

  [12288.351729]  do_syscall_64+0x2d/0×40

  [12288.352438]  entry_SYSCALL_64_after_hwframe+0x44/0xa9

  [12288.353408] RIP: 0033:0×7f851b74456f

  [12288.354117] Code: 89 54 24 18 48 89 74 24 10 89 7c 24 08 e8 09 4b 
f9 ff 48 8b 54 24 18 48 8b 74 24 10 41 89 c0 8b 7c 24 08 b8 01 00 00 00 
0f 05 <48> 3d 00 f0 ff ff 77 31 44 89 c7 48 89 44 24 08 e8 3c 4b f9 ff 48

  [12288.357411] RSP: 002b:00007f84faffb310 EFLAGS: 00000293 ORIG_RAX: 
0000000000000001

  [12288.358834] RAX: ffffffffffffffda RBX: 00007f84faffd680 RCX: 
00007f851b74456f

  [12288.360134] RDX: 0000000000000006 RSI: 00007f84ec006670 RDI: 
0000000000000007

  [12288.361463] RBP: 0000000000000006 R08: 0000000000000000 R09: 
00007f851b631960

  [12288.362729] R10: 0000000000000002 R11: 0000000000000293 R12: 
00007f8504234400

  [12288.364000] R13: 0000000000000007 R14: 00007f84ec006670 R15: 
00007f85004c15e0

  [12288.365358] CPU: 4 PID: 701631 Comm: python3 Not tainted 
5.9.0_for_upstream_min_debug_2020_10_19_16_22 #1

  [12288.367126] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), 
BIOS rel-1.13.0-0-gf21b5a4aeb02-prebuilt.qemu.org 04/01/2014

  [12288.369127] Call Trace:

  [12288.369659]  dump_stack+0x77/0×97

  [12288.370321]  __warn+0x8c/0xf0

  [12288.370932]  ? bond_update_slave_arr+0x498/0×560 [bonding]

  [12288.371947]  report_bug+0xbb/0×130

  [12288.372621]  handle_bug+0x3f/0×70

  [12288.373276]  exc_invalid_op+0x13/0×60

  [12288.383632]  asm_exc_invalid_op+0x12/0×20

  [12288.384429] RIP: 0010:bond_update_slave_arr+0x498/0×560 [bonding]

  [12288.385526] Code: 25 fc ff ff 48 89 fe 4c 89 fa 48 c7 c7 e0 2c 73 
a0 48 89 04 24 e8 48 7b f1 e0 45 8b 04 24 48 8b 3b 48 8b 04 24 e9 a1 fc 
ff ff <0f> 0b e9 a0 fb ff ff 44 0f b7 74 24 12 e9 0f fc ff ff 31 d2 8d 46

  [12288.388672] RSP: 0018:ffff8881b13f7c48 EFLAGS: 00010202

  [12288.389579] RAX: 0000000000000001 RBX: ffff8881bb5a2b40 RCX: 
0000000000000000

  [12288.389725] mlx4_en: eth3: Link Down

  [12288.390776] RDX: 00000000fffffffe RSI: 00000000ffffffff RDI: 
ffff8881bb5a2b98

  [12288.390778] RBP: ffff8881bb5a2000 R08: 0000000000000000 R09: 
0000000000000000

  [12288.394137] R10: 0000000000000000 R11: ffffffff8237e060 R12: 
0000000000000001

  [12288.395318] R13: 0000000000000000 R14: ffff8881bb5a2b40 R15: 
0000000000000000

  [12288.396502]  ? bond_update_slave_arr+0x37/0×560 [bonding]

  [12288.397477]  bond_enslave+0x1038/0×13e0 [bonding]

  [12288.398371]  ? __kernel_text_address+0xe/0×30

  [12288.399200]  ? unwind_get_return_address+0x1b/0×30

  [12288.400092]  ? sscanf+0x49/0×70

  [12288.400747]  bond_option_slaves_set+0xf3/0×1a0 [bonding]

  [12288.401722]  __bond_opt_set+0xe8/0×380 [bonding]

  [12288.402608]  __bond_opt_set_notify+0x27/0×80 [bonding]

  [12288.403561]  bond_opt_tryset_rtnl+0x51/0×90 [bonding]

  [12288.404525]  bonding_sysfs_store_option+0x4f/0×90 [bonding]

  [12288.405538]  kernfs_fop_write+0x114/0×1b0

  [12288.406300]  vfs_write+0xc1/0×1f0

  [12288.406972]  ksys_write+0xa7/0xe0

  [12288.407640]  do_syscall_64+0x2d/0×40

  [12288.408339]  entry_SYSCALL_64_after_hwframe+0x44/0xa9

  [12288.409272] RIP: 0033:0×7f851b74456f

  [12288.409977] Code: 89 54 24 18 48 89 74 24 10 89 7c 24 08 e8 09 4b 
f9 ff 48 8b 54 24 18 48 8b 74 24 10 41 89 c0 8b 7c 24 08 b8 01 00 00 00 
0f 05 <48> 3d 00 f0 ff ff 77 31 44 89 c7 48 89 44 24 08 e8 3c 4b f9 ff 48

  [12288.413250] RSP: 002b:00007f84faffb310 EFLAGS: 00000293 ORIG_RAX: 
0000000000000001

  [12288.414652] RAX: ffffffffffffffda RBX: 00007f84faffd680 RCX: 
00007f851b74456f

  [12288.415923] RDX: 0000000000000006 RSI: 00007f84ec006670 RDI: 
0000000000000007

  [12288.417202] RBP: 0000000000000006 R08: 0000000000000000 R09: 
00007f851b631960

  [12288.418477] R10: 0000000000000002 R11: 0000000000000293 R12: 
00007f8504234400

  [12288.419758] R13: 0000000000000007 R14: 00007f84ec006670 R15: 
00007f85004c15e0

  [12288.421029] irq event stamp: 0

  [12288.421654] hardirqs last  enabled at (0): [<0000000000000000>] 0×0

  [12288.422837] hardirqs last disabled at (0): [] copy_process+0x4c2/0×1c00

  [12288.424359] softirqs last  enabled at (0): [] copy_process+0x4c2/0×1c00

  [12288.425904] softirqs last disabled at (0): [<0000000000000000>] 0×0

  [12288.427075] -[ end trace 5c51515ebbf2daa8 ]—-

  [12288.427974] eth3bond13: (slave eth3): Enslaving as an active 
interface with a down link

  [12291.019456] mlx4_en: eth3: Link Up

  [12291.022221] -————-[ cut here ]——————

  [12291.025000] WARNING: CPU: 4 PID: 577432 at 
drivers/net/bonding/bond_main.c:4310 bond_update_slave_arr+0x498/0×560 
[bonding]

  [12291.028671] Modules linked in: bonding nf_tables ipip tunnel4 
geneve ip6_gre ip6_tunnel tunnel6 ip_gre gre ip_tunnel mlx4_en ptp 
pps_core mlx4_ib mlx4_core rdma_ucm ib_uverbs ib_ipoib ib_umad macvlan 
vxlan ip6_udp_tunnel udp_tunnel 8021q garp mrp openvswitch nsh rpcrdma 
ib_iser libiscsi scsi_transport_iscsi rdma_cm iw_cm ib_cm ib_core 
xt_conntrack xt_MASQUERADE nf_conntrack_netlink nfnetlink xt_addrtype 
iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 
br_netfilter overlay [last unloaded: nf_tables]

  [12291.038684] CPU: 4 PID: 577432 Comm: kworker/4:0 Tainted: G 
W         5.9.0_for_upstream_min_debug_2020_10_19_16_22 #1

  [12291.040625] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), 
BIOS rel-1.13.0-0-gf21b5a4aeb02-prebuilt.qemu.org 04/01/2014

  [12291.042458] Workqueue: events linkwatch_event

  [12291.043269] RIP: 0010:bond_update_slave_arr+0x498/0×560 [bonding]

  [12291.044293] Code: 25 fc ff ff 48 89 fe 4c 89 fa 48 c7 c7 e0 2c 73 
a0 48 89 04 24 e8 48 7b f1 e0 45 8b 04 24 48 8b 3b 48 8b 04 24 e9 a1 fc 
ff ff <0f> 0b e9 a0 fb ff ff 44 0f b7 74 24 12 e9 0f fc ff ff 31 d2 8d 46

  [12291.047286] RSP: 0018:ffff8881c1c6fd00 EFLAGS: 00010202

  [12291.048184] RAX: 0000000000000001 RBX: ffff8881bb5a2b40 RCX: 
0000000000000001

  [12291.049363] RDX: 00000000fffffffe RSI: 00000000ffffffff RDI: 
ffff8881bb5a2b98

  [12291.050561] RBP: 0000000000000004 R08: 0000000000000000 R09: 
0000000000000000

  [12291.051758] R10: ffff888163495870 R11: 0000000000000000 R12: 
ffff88811a38fc00

  [12291.052953] R13: 0000000000000000 R14: ffff8881bb5a2000 R15: 
0000000000000000

  [12291.054148] FS:  0000000000000000(0000) GS:ffff8882f5c00000(0000) 
knlGS:0000000000000000

  [12291.055584] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033

  [12291.056557] CR2: 000055b13935e010 CR3: 0000000002412003 CR4: 
0000000000370ea0

  [12291.057762] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 
0000000000000000

  [12291.058987] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 
0000000000000400

  [12291.060186] Call Trace:

  [12291.060699]  bond_netdev_event+0x1d1/0×3d0 [bonding]

  [12291.061562]  raw_notifier_call_chain+0x3e/0×50

  [12291.062357]  netdev_state_change+0x5a/0×90

  [12291.063191]  ? linkwatch_do_dev+0x3c/0×50

  [12291.063934]  linkwatch_do_dev+0x3c/0×50

  [12291.064613]  __linkwatch_run_queue+0x10f/0×1f0

  [12291.065407]  linkwatch_event+0x21/0×30

  [12291.066153]  process_one_work+0x27c/0×610

  [12291.066897]  ? process_one_work+0x610/0×610

  [12291.067652]  worker_thread+0x2d/0×3c0

  [12291.068332]  ? process_one_work+0x610/0×610

  [12291.069072]  kthread+0x128/0×140

  [12291.069681]  ? kthread_insert_work_sanity_check+0x60/0×60

  [12291.070615]  ret_from_fork+0x1f/0×30

  [12291.071293] CPU: 4 PID: 577432 Comm: kworker/4:0 Tainted: G 
W         5.9.0_for_upstream_min_debug_2020_10_19_16_22 #1

  [12291.073130] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), 
BIOS rel-1.13.0-0-gf21b5a4aeb02-prebuilt.qemu.org 04/01/2014

  [12291.075064] Workqueue: events linkwatch_event

  [12291.075844] Call Trace:

  [12291.076334]  dump_stack+0x77/0×97

  [12291.076947]  __warn+0x8c/0xf0

  [12291.077518]  ? bond_update_slave_arr+0x498/0×560 [bonding]

  [12291.078466]  report_bug+0xbb/0×130

  [12291.079118]  handle_bug+0x3f/0×70

  [12291.079746]  exc_invalid_op+0x13/0×60

  [12291.080423]  asm_exc_invalid_op+0x12/0×20

  [12291.081145] RIP: 0010:bond_update_slave_arr+0x498/0×560 [bonding]

  [12291.082162] Code: 25 fc ff ff 48 89 fe 4c 89 fa 48 c7 c7 e0 2c 73 
a0 48 89 04 24 e8 48 7b f1 e0 45 8b 04 24 48 8b 3b 48 8b 04 24 e9 a1 fc 
ff ff <0f> 0b e9 a0 fb ff ff 44 0f b7 74 24 12 e9 0f fc ff ff 31 d2 8d 46

  [12291.085107] RSP: 0018:ffff8881c1c6fd00 EFLAGS: 00010202

  [12291.085991] RAX: 0000000000000001 RBX: ffff8881bb5a2b40 RCX: 
0000000000000001

  [12291.087169] RDX: 00000000fffffffe RSI: 00000000ffffffff RDI: 
ffff8881bb5a2b98

  [12291.088361] RBP: 0000000000000004 R08: 0000000000000000 R09: 
0000000000000000

  [12291.089539] R10: ffff888163495870 R11: 0000000000000000 R12: 
ffff88811a38fc00

  [12291.090745] R13: 0000000000000000 R14: ffff8881bb5a2000 R15: 
0000000000000000

  [12291.091978]  bond_netdev_event+0x1d1/0×3d0 [bonding]

  [12291.092817]  raw_notifier_call_chain+0x3e/0×50

  [12291.093588]  netdev_state_change+0x5a/0×90

  [12291.094339]  ? linkwatch_do_dev+0x3c/0×50

  [12291.095094]  linkwatch_do_dev+0x3c/0×50

  [12291.095805]  __linkwatch_run_queue+0x10f/0×1f0

  [12291.096572]  linkwatch_event+0x21/0×30

  [12291.097269]  process_one_work+0x27c/0×610

  [12291.097996]  ? process_one_work+0x610/0×610

  [12291.098782]  worker_thread+0x2d/0×3c0

  [12291.099450]  ? process_one_work+0x610/0×610

  [12291.100212]  kthread+0x128/0×140

  [12291.100833]  ? kthread_insert_work_sanity_check+0x60/0×60

  [12291.101787]  ret_from_fork+0x1f/0×30

  [12291.102463] irq event stamp: 0

  [12291.103061] hardirqs last  enabled at (0): [<0000000000000000>] 0×0

  [12291.104143] hardirqs last disabled at (0): [] copy_process+0x4c2/0×1c00

  [12291.105547] softirqs last  enabled at (0): [] copy_process+0x4c2/0×1c00

  [12291.106979] softirqs last disabled at (0): [<0000000000000000>] 0×0

  [12291.108088] -[ end trace 5c51515ebbf2daa9 ]—-

  [12292.862376] eth3bond13: (slave eth3): link status up, enabling it 
in 0 ms

  [12292.862387] -————-[ cut here ]——————

  [12292.864501] WARNING: CPU: 5 PID: 701638 at 
drivers/net/bonding/bond_main.c:4310 bond_update_slave_arr+0x498/0×560 
[bonding]

  [12292.866324] Modules linked in: bonding nf_tables ipip tunnel4 
geneve ip6_gre ip6_tunnel tunnel6 ip_gre gre ip_tunnel mlx4_en ptp 
pps_core mlx4_ib mlx4_core rdma_ucm ib_uverbs ib_ipoib ib_umad macvlan 
vxlan ip6_udp_tunnel udp_tunnel 8021q garp mrp openvswitch nsh rpcrdma 
ib_iser libiscsi scsi_transport_iscsi rdma_cm iw_cm ib_cm ib_core 
xt_conntrack xt_MASQUERADE nf_conntrack_netlink nfnetlink xt_addrtype 
iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 
br_netfilter overlay [last unloaded: nf_tables]

  [12292.873158] eth3bond13: (slave eth3): link status up, enabling it 
in 0 ms

  [12292.876996] CPU: 5 PID: 701638 Comm: ip Tainted: G        W 
5.9.0_for_upstream_min_debug_2020_10_19_16_22 #1

  [12292.882361] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), 
BIOS rel-1.13.0-0-gf21b5a4aeb02-prebuilt.qemu.org 04/01/2014

  [12292.884251] RIP: 0010:bond_update_slave_arr+0x498/0×560 [bonding]

  [12292.885141] eth3bond13: (slave eth3): link status up, enabling it 
in 0 ms

  [12292.885321] Code: 25 fc ff ff 48 89 fe 4c 89 fa 48 c7 c7 e0 2c 73 
a0 48 89 04 24 e8 48 7b f1 e0 45 8b 04 24 48 8b 3b 48 8b 04 24 e9 a1 fc 
ff ff <0f> 0b e9 a0 fb ff ff 44 0f b7 74 24 12 e9 0f fc ff ff 31 d2 8d 46

  [12292.889803] RSP: 0018:ffff8881bb2eb4a0 EFLAGS: 00010202

  [12292.890778] RAX: 0000000000000001 RBX: ffff8881bb5a2b40 RCX: 
0000000000000000

  [12292.891983] RDX: 00000000fffffffe RSI: 00000000ffffffff RDI: 
ffff8881bb5a2b98

  [12292.893149] eth3bond13: (slave eth3): link status up, enabling it 
in 0 ms

  [12292.893176] RBP: ffff8881bb5a2000 R08: 0000000000000000 R09: 
0000000000000000

  [12292.898267] R10: 0000000000000000 R11: 0000000000000148 R12: 
ffff8881bb5a2b40

  [12292.899478] R13: 0000000000000000 R14: ffff8881bb2ebba8 R15: 
0000000000000001

  [12292.900687] FS:  00007f802af94800(0000) GS:ffff8882f5c80000(0000) 
knlGS:0000000000000000

  [12292.902047] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033

  [12292.903044] CR2: 00000000004d2780 CR3: 00000001c3242006 CR4: 
0000000000370ea0

  [12292.904313] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 
0000000000000000

  [12292.905113] eth3bond13: (slave eth3): link status up, enabling it 
in 0 ms

  [12292.905501] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 
0000000000000400

  [12292.909217] Call Trace:

  [12292.909732]  ? trace_hardirqs_on+0x33/0xd0

  [12292.910467]  bond_open+0x183/0×310 [bonding]

  [12292.911275]  __dev_open+0xed/0×180

  [12292.911932]  __dev_change_flags+0x174/0×1c0

  [12292.913138] eth3bond13: (slave eth3): link status up, enabling it 
in 0 ms

  [12292.922284]  dev_change_flags+0x23/0×60

  [12292.924414]  do_setlink+0x3af/0×1160

  [12292.925089]  ? lock_acquire+0x209/0×3b0

  [12292.925797]  ? lock_acquire+0x209/0×3b0

  [12292.926505]  ? lock_release+0x1d5/0×2a0

  [12292.927218]  ? __nla_validate_parse.part.7+0x57/0xac0

  [12292.928099]  ? is_bpf_text_address+0x86/0xf0

  [12292.928878]  ? kernel_text_address+0xb6/0xc0

  [12292.929041] eth3bond13: (slave eth3): link status up, enabling it 
in 0 ms

  [12292.929661]  ? __thaw_task+0x50/0×50

  [12292.931767]  __rtnl_newlink+0x53d/0×8d0

  [12292.932472]  ? lock_release+0x1d5/0×2a0

  [12292.933185]  ? lock_release+0x1d5/0×2a0

  [12292.933894]  ? lock_release+0x1d5/0×2a0

  [12292.934602]  ? trace_hardirqs_on+0x33/0xd0

  [12292.935347]  ? lock_acquire+0x209/0×3b0

  [12292.936056]  ? trace_hardirqs_on+0x33/0xd0

  [12292.936806]  ? lock_acquire+0x209/0×3b0

  [12292.937101] eth3bond13: (slave eth3): link status up, enabling it 
in 0 ms

  [12292.937526]  ? lock_acquire+0x209/0×3b0

  [12292.939752]  ? lock_release+0x1d5/0×2a0

  [12292.940462]  ? lock_acquire+0x209/0×3b0

  [12292.941187]  ? kmem_cache_alloc_trace+0x64e/0×890

  [12292.942018]  ? lock_acquire+0x209/0×3b0

  [12292.942743]  ? security_capable+0x32/0×50

  [12292.943481]  rtnl_newlink+0x47/0×70

  [12292.944146]  rtnetlink_rcv_msg+0x279/0×490

  [12292.944893]  ? lock_acquire+0x209/0×3b0

  [12292.945098] eth3bond13: (slave eth3): link status up, enabling it 
in 0 ms

  [12292.945609]  ? lock_release+0x1d5/0×2a0

  [12292.948412]  ? validate_linkmsg+0x370/0×370

  [12292.949201]  netlink_rcv_skb+0x4e/0×100

  [12292.949900]  netlink_unicast+0x1ac/0×270

  [12292.950641]  netlink_sendmsg+0x336/0×450

  [12292.951368]  sock_sendmsg+0x30/0×40

  [12292.952040]  ____sys_sendmsg+0x1dd/0×1f0

  [12292.952744]  ? copy_msghdr_from_user+0x5c/0×90

  [12292.953098] eth3bond13: (slave eth3): link status up, enabling it 
in 0 ms

  [12292.953537]  ? lock_acquire+0x209/0×3b0

  [12292.957067]  ___sys_sendmsg+0x87/0xd0

  [12292.957744]  ? lock_acquire+0x209/0×3b0

  [12292.958439]  ? lock_acquire+0x209/0×3b0

  [12292.959184]  ? lock_release+0x1d5/0×2a0

  [12292.959903]  ? lock_acquire+0x209/0×3b0

  [12292.960608]  ? lock_release+0x1d5/0×2a0

  [12292.961100] eth3bond13: (slave eth3): link status up, enabling it 
in 0 ms

  [12292.961301]  ? lock_acquire+0x209/0×3b0

  [12292.964795]  ? lock_release+0x1d5/0×2a0

  [12292.965506]  ? lock_acquire+0x209/0×3b0

  [12292.966217]  ? lock_release+0x1d5/0×2a0

  [12292.966945]  ? lock_release+0x1d5/0×2a0

  [12292.967695]  ? __sys_sendmsg+0x51/0×90

  [12292.968377]  __sys_sendmsg+0x51/0×90

  [12292.969056]  do_syscall_64+0x2d/0×40

  [12292.969115] eth3bond13: (slave eth3): link status up, enabling it 
in 0 ms

  [12292.969766]  entry_SYSCALL_64_after_hwframe+0x44/0xa9

  [12292.969771] RIP: 0033:0×7f802b170e57

  [12292.972837] Code: 0c 00 f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb b7 
0f 1f 00 f3 0f 1e fa 64 8b 04 25 18 00 00 00 85 c0 75 10 b8 2e 00 00 00 
0f 05 <48> 3d 00 f0 ff ff 77 51 c3 48 83 ec 28 89 54 24 1c 48 89 74 24 10

  [12292.975853] RSP: 002b:00007ffe5d2f7218 EFLAGS: 00000246 ORIG_RAX: 
000000000000002e

  [12292.977101] eth3bond13: (slave eth3): link status up, enabling it 
in 0 ms

  [12292.977148] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 
00007f802b170e57

  [12292.980651] RDX: 0000000000000000 RSI: 00007ffe5d2f7280 RDI: 
0000000000000003

  [12292.981819] RBP: 000000005f8f49a5 R08: 0000000000000001 R09: 
00007f802b231a40

  [12292.983026] R10: 0000000000405caf R11: 0000000000000246 R12: 
0000000000000001

  [12292.984223] R13: 00007ffe5d2f7920 R14: 00007ffe5d2f7d94 R15: 
0000000000488500

  [12292.985113] eth3bond13: (slave eth3): link status up, enabling it 
in 0 ms

  [12292.985411] CPU: 5 PID: 701638 Comm: ip Tainted: G        W 
5.9.0_for_upstream_min_debug_2020_10_19_16_22 #1

  [12292.989976] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), 
BIOS rel-1.13.0-0-gf21b5a4aeb02-prebuilt.qemu.org 04/01/2014

  [12292.991824] Call Trace:

  [12292.992340]  dump_stack+0x77/0×97

  [12292.992977]  __warn+0x8c/0xf0

  [12292.993109] eth3bond13: (slave eth3): link status up, enabling it 
in 0 ms

  [12292.993565]  ? bond_update_slave_arr+0x498/0×560 [bonding]

  [12292.993572]  report_bug+0xbb/0×130

  [12292.997995]  handle_bug+0x3f/0×70

  [12292.998634]  exc_invalid_op+0x13/0×60

  [12292.999326]  asm_exc_invalid_op+0x12/0×20

  [12293.000069] RIP: 0010:bond_update_slave_arr+0x498/0×560 [bonding]

  [12293.001108] eth3bond13: (slave eth3): link status up, enabling it 
in 0 ms

  [12293.001117] Code: 25 fc ff ff 48 89 fe 4c 89 fa 48 c7 c7 e0 2c 73 
a0 48 89 04 24 e8 48 7b f1 e0 45 8b 04 24 48 8b 3b 48 8b 04 24 e9 a1 fc 
ff ff <0f> 0b e9 a0 fb ff ff 44 0f b7 74 24 12 e9 0f fc ff ff 31 d2 8d 46

  [12293.001121] RSP: 0018:ffff8881bb2eb4a0 EFLAGS: 00010202

  [12293.006637] RAX: 0000000000000001 RBX: ffff8881bb5a2b40 RCX: 
0000000000000000

  [12293.007832] RDX: 00000000fffffffe RSI: 00000000ffffffff RDI: 
ffff8881bb5a2b98

  [12293.009013] RBP: ffff8881bb5a2000 R08: 0000000000000000 R09: 
0000000000000000

  [12293.009112] eth3bond13: (slave eth3): link status up, enabling it 
in 0 ms

  [12293.010226] R10: 0000000000000000 R11: 0000000000000148 R12: 
ffff8881bb5a2b40

  [12293.010230] R13: 0000000000000000 R14: ffff8881bb2ebba8 R15: 
0000000000000001

  [12293.014896]  ? trace_hardirqs_on+0x33/0xd0

  [12293.015634]  bond_open+0x183/0×310 [bonding]

  [12293.016400]  __dev_open+0xed/0×180

  [12293.017040]  __dev_change_flags+0x174/0×1c0

  [12293.017108] eth3bond13: (slave eth3): link status up, enabling it 
in 0 ms

  [12293.017792]  dev_change_flags+0x23/0×60

  [12293.020802]  do_setlink+0x3af/0×1160

  [12293.021491]  ? lock_acquire+0x209/0×3b0

  [12293.022193]  ? lock_acquire+0x209/0×3b0

  [12293.022897]  ? lock_release+0x1d5/0×2a0

  [12293.023598]  ? __nla_validate_parse.part.7+0x57/0xac0

  [12293.024486]  ? is_bpf_text_address+0x86/0xf0

  [12293.025111] eth3bond13: (slave eth3): link status up, enabling it 
in 0 ms

  [12293.025285]  ? kernel_text_address+0xb6/0xc0

  [12293.025293]  ? __thaw_task+0x50/0×50

  [12293.028247]  __rtnl_newlink+0x53d/0×8d0

  [12293.028944]  ? lock_release+0x1d5/0×2a0

  [12293.029657]  ? lock_release+0x1d5/0×2a0

  [12293.030356]  ? lock_release+0x1d5/0×2a0

  [12293.031084]  ? trace_hardirqs_on+0x33/0xd0

  [12293.031832]  ? lock_acquire+0x209/0×3b0

  [12293.032552]  ? trace_hardirqs_on+0x33/0xd0

  [12293.033102] eth3bond13: (slave eth3): link status up, enabling it 
in 0 ms

  [12293.033294]  ? lock_acquire+0x209/0×3b0

  [12293.033298]  ? lock_acquire+0x209/0×3b0

  [12293.037019]  ? lock_release+0x1d5/0×2a0

  [12293.037720]  ? lock_acquire+0x209/0×3b0

  [12293.038441]  ? kmem_cache_alloc_trace+0x64e/0×890

  [12293.039275]  ? lock_acquire+0x209/0×3b0

  [12293.039999]  ? security_capable+0x32/0×50

  [12293.040739]  rtnl_newlink+0x47/0×70

  [12293.041126] eth3bond13: (slave eth3): link status up, enabling it 
in 0 ms

  [12293.041407]  rtnetlink_rcv_msg+0x279/0×490

  [12293.041412]  ? lock_acquire+0x209/0×3b0

  [12293.045846]  ? lock_release+0x1d5/0×2a0

  [12293.046549]  ? validate_linkmsg+0x370/0×370

  [12293.047306]  netlink_rcv_skb+0x4e/0×100

  [12293.048013]  netlink_unicast+0x1ac/0×270

  [12293.048730]  netlink_sendmsg+0x336/0×450

  [12293.049108] eth3bond13: (slave eth3): link status up, enabling it 
in 0 ms

  [12293.049452]  sock_sendmsg+0x30/0×40

  [12293.053171]  ____sys_sendmsg+0x1dd/0×1f0

  [12293.053923]  ? copy_msghdr_from_user+0x5c/0×90

  [12293.054731]  ? lock_acquire+0x209/0×3b0

  [12293.055439]  ___sys_sendmsg+0x87/0xd0

  [12293.056122]  ? lock_acquire+0x209/0×3b0

  [12293.056839]  ? lock_acquire+0x209/0×3b0

  [12293.057108] eth3bond13: (slave eth3): link status up, enabling it 
in 0 ms

  [12293.057543]  ? lock_release+0x1d5/0×2a0

  [12293.057546]  ? lock_acquire+0x209/0×3b0

  [12293.060408]  ? lock_release+0x1d5/0×2a0

  [12293.061130]  ? lock_acquire+0x209/0×3b0

  [12293.061825]  ? lock_release+0x1d5/0×2a0

  [12293.062524]  ? lock_acquire+0x209/0×3b0

  [12293.063232]  ? lock_release+0x1d5/0×2a0

  [12293.063928]  ? lock_release+0x1d5/0×2a0

  [12293.064629]  ? __sys_sendmsg+0x51/0×90

  [12293.065110] eth3bond13: (slave eth3): link status up, enabling it 
in 0 ms

  [12293.065321]  __sys_sendmsg+0x51/0×90

  [12293.065325]  do_syscall_64+0x2d/0×40

  [12293.068968]  entry_SYSCALL_64_after_hwframe+0x44/0xa9

  [12293.069850] RIP: 0033:0×7f802b170e57

  [12293.070513] Code: 0c 00 f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb b7 
0f 1f 00 f3 0f 1e fa 64 8b 04 25 18 00 00 00 85 c0 75 10 b8 2e 00 00 00 
0f 05 <48> 3d 00 f0 ff ff 77 51 c3 48 83 ec 28 89 54 24 1c 48 89 74 24 10

  [12293.073043] eth3bond13: (slave eth3): link status up, enabling it 
in 0 ms

  [12293.073512] RSP: 002b:00007ffe5d2f7218 EFLAGS: 00000246 ORIG_RAX: 
000000000000002e

  [12293.077604] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 
00007f802b170e57

  [12293.078784] RDX: 0000000000000000 RSI: 00007ffe5d2f7280 RDI: 
0000000000000003

  [12293.079969] RBP: 000000005f8f49a5 R08: 0000000000000001 R09: 
00007f802b231a40

  [12293.081108] eth3bond13: (slave eth3): link status up, enabling it 
in 0 ms

  [12293.081156] R10: 0000000000405caf R11: 0000000000000246 R12: 
0000000000000001

  [12293.081161] R13: 00007ffe5d2f7920 R14: 00007ffe5d2f7d94 R15: 
0000000000488500

  [12293.086307] irq event stamp: 0

  [12293.086908] hardirqs last  enabled at (0): [<0000000000000000>] 0×0

  [12293.087972] hardirqs last disabled at (0): [] copy_process+0x4c2/0×1c00

  [12293.089097] eth3bond13: (slave eth3): link status up, enabling it 
in 0 ms

  [12293.089382] softirqs last  enabled at (0): [] copy_process+0x4c2/0×1c00

  [12293.092314] softirqs last disabled at (0): [<0000000000000000>] 0×0

  [12293.093395] -[ end trace 5c51515ebbf2daaa ]—-

  [12293.094387] 8021q: adding VLAN 0 to HW filter on device eth3bond13

  [12293.097064] eth3bond13: (slave eth3): link status up, enabling it 
in 0 ms

  [12293.113267] eth3bond13: (slave eth3): link status definitely up, 
56000 Mbps full duplex

  [12293.114709] -————-[ cut here ]——————

  [12293.115539] WARNING: CPU: 6 PID: 94250 at 
drivers/net/bonding/bond_main.c:4310 bond_update_slave_arr+0x498/0×560 
[bonding]

  [12293.117352] Modules linked in: bonding nf_tables ipip tunnel4 
geneve ip6_gre ip6_tunnel tunnel6 ip_gre gre ip_tunnel mlx4_en ptp 
pps_core mlx4_ib mlx4_core rdma_ucm ib_uverbs ib_ipoib ib_umad macvlan 
vxlan ip6_udp_tunnel udp_tunnel 8021q garp mrp openvswitch nsh rpcrdma 
ib_iser libiscsi scsi_transport_iscsi rdma_cm iw_cm ib_cm ib_core 
xt_conntrack xt_MASQUERADE nf_conntrack_netlink nfnetlink xt_addrtype 
iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 
br_netfilter overlay [last unloaded: nf_tables]

  [12293.124571] CPU: 6 PID: 94250 Comm: kworker/u16:7 Tainted: G 
W         5.9.0_for_upstream_min_debug_2020_10_19_16_22 #1

  [12293.126440] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), 
BIOS rel-1.13.0-0-gf21b5a4aeb02-prebuilt.qemu.org 04/01/2014

  [12293.128327] Workqueue: eth3bond13 bond_mii_monitor [bonding]

  [12293.129326] RIP: 0010:bond_update_slave_arr+0x498/0×560 [bonding]

  [12293.130371] Code: 25 fc ff ff 48 89 fe 4c 89 fa 48 c7 c7 e0 2c 73 
a0 48 89 04 24 e8 48 7b f1 e0 45 8b 04 24 48 8b 3b 48 8b 04 24 e9 a1 fc 
ff ff <0f> 0b e9 a0 fb ff ff 44 0f b7 74 24 12 e9 0f fc ff ff 31 d2 8d 46

  [12293.133450] RSP: 0018:ffff88813749bda8 EFLAGS: 00010202

  [12293.134373] RAX: 0000000000000001 RBX: ffff8881bb5a2b40 RCX: 
ffff88811a38fc00

  [12293.135584] RDX: 0000000000000000 RSI: 00000000ffffffff RDI: 
ffff8881bb5a2b98

  [12293.136786] RBP: ffff88813749be60 R08: 0000000000000000 R09: 
0000000000000000

  [12293.137998] R10: ffff88813749bde8 R11: ffff88813749bba8 R12: 
ffffffffa072b642

  [12293.139249] R13: 0000000000000000 R14: 0000000000000000 R15: 
0000000000000019

  [12293.140454] FS:  0000000000000000(0000) GS:ffff8882f5d00000(0000) 
knlGS:0000000000000000

  [12293.141878] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033

  [12293.142874] CR2: 000055b13935e010 CR3: 0000000104440002 CR4: 
0000000000370ea0

  [12293.144079] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 
0000000000000000

  [12293.145323] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 
0000000000000400

  [12293.146532] Call Trace:

  [12293.147117]  bond_mii_monitor+0x574/0×900 [bonding]

  [12293.148023]  ? raw_spin_unlock_irq+0x24/0×30

  [12293.148811]  process_one_work+0x27c/0×610

  [12293.149574]  worker_thread+0x2d/0×3c0

  [12293.150310]  ? process_one_work+0x610/0×610

  [12293.151115]  kthread+0x128/0×140

  [12293.151793]  ? kthread_insert_work_sanity_check+0x60/0×60

  [12293.152745]  ret_from_fork+0x1f/0×30

  [12293.153436] CPU: 6 PID: 94250 Comm: kworker/u16:7 Tainted: G 
W         5.9.0_for_upstream_min_debug_2020_10_19_16_22 #1

  [12293.155350] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), 
BIOS rel-1.13.0-0-gf21b5a4aeb02-prebuilt.qemu.org 04/01/2014

  [12293.157234] Workqueue: eth3bond13 bond_mii_monitor [bonding]

  [12293.158316] Call Trace:

  [12293.158876]  dumpstack+0x77/0×97

  [12293.159557]  __warn+0x8c/0xf0

  [12293.160145]  ? bond_update_slave_arr+0x498/0×560 [bonding]

  [12293.161108]  report_bug+0xbb/0×130

  [12293.161767]  handle_bug+0x3f/0×70

  [12293.162406]  exc_invalid_op+0x13/0×60

  [12293.163092]  asm_exc_invalid_op+0x12/0×20

  [12293.163818] RIP: 0010:bond_update_slave_arr+0x498/0×560 [bonding]

  [12293.164843] Code: 25 fc ff ff 48 89 fe 4c 89 fa 48 c7 c7 e0 2c 73 
a0 48 89 04 24 e8 48 7b f1 e0 45 8b 04 24 48 8b 3b 48 8b 04 24 e9 a1 fc 
ff ff <0f> 0b e9 a0 fb ff ff 44 0f b7 74 24 12 e9 0f fc ff ff 31 d2 8d 46

  [12293.167960] RSP: 0018:ffff88813749bda8 EFLAGS: 00010202

  [12293.168869] RAX: 0000000000000001 RBX: ffff8881bb5a2b40 RCX: 
ffff88811a38fc00

  [12293.170073] RDX: 0000000000000000 RSI: 00000000ffffffff RDI: 
ffff8881bb5a2b98

  [12293.171290] RBP: ffff88813749be60 R08: 0000000000000000 R09: 
0000000000000000

  [12293.172470] R10: ffff88813749bde8 R11: ffff88813749bba8 R12: 
ffffffffa072b642

  [12293.173673] R13: 0000000000000000 R14: 0000000000000000 R15: 
0000000000000019

  [12293.174886]  ? bond_update_slave_arr+0x37/0×560 [bonding]

  [12293.175857]  bond_mii_monitor+0x574/0×900 [bonding]

  [12293.176727]  ? raw_spin_unlock_irq+0x24/0×30

  [12293.177519]  process_one_work+0x27c/0×610

  [12293.178262]  worker_thread+0x2d/0×3c0

  [12293.178953]  ? process_one_work+0x610/0×610

  [12293.179719]  kthread+0x128/0×140

  [12293.180339]  ? kthread_insert_work_sanity_check+0x60/0×60

  [12293.181320]  ret_fromfork+0x1f/0×30

  [12293.182022] irq event stamp: 9226282

  [12293.182713] hardirqs last  enabled at (9226281): [] 
_raw_spin_unlock_irq+0x24/0×30

  [12293.184322] hardirqs last disabled at (9226282): [] 
__schedule+0x454/0×8d0

  [12293.185798] softirqs last  enabled at (9226244): [] 
tcp_sendmsg+0x31/0×40

  [12293.187320] softirqs last disabled at (9226242): [] 
release_sock+0x19/0xa0

  [12293.188754] -[ end trace 5c51515ebbf2daab ]—-

  [12293.189621] eth3bond13: active interface up!

  [12293.190415] IPv6: ADDRCONF: eth3bond13: link becomes ready

Re: bug report: WARNING in bonding

[Ido Schimmel]

On Thu, Nov 12, 2020 at 05:38:44PM +0200, Tariq Toukan wrote:
> Hi all,
> 
> In the past ~2-3 weeks, we started seeing the following WARNING and traces
> in our regression testing systems, almost every day.
> 
> Reproduction is not stable, and not isolated to a specific test, so it's
> hard to bisect.
> 
> Any idea what could this be?
> Or what is the suspected offending patch?

Do you have commit f8e48a3dca06 ("lockdep: Fix preemption WARN for spurious
IRQ-enable")? I think it fixed the issue for me

Re: bug report: WARNING in bonding

[Tariq Toukan]

On 11/12/2020 5:46 PM, Ido Schimmel wrote:
> On Thu, Nov 12, 2020 at 05:38:44PM +0200, Tariq Toukan wrote:
>> Hi all,
>>
>> In the past ~2-3 weeks, we started seeing the following WARNING and traces
>> in our regression testing systems, almost every day.
>>
>> Reproduction is not stable, and not isolated to a specific test, so it's
>> hard to bisect.
>>
>> Any idea what could this be?
>> Or what is the suspected offending patch?
> 
> Do you have commit f8e48a3dca06 ("lockdep: Fix preemption WARN for spurious
> IRQ-enable")? I think it fixed the issue for me
> 

We do have it. Yet issue still exists.
Thanks.

Re: bug report: WARNING in bonding

[Ido Schimmel]

On Thu, Nov 12, 2020 at 05:54:30PM +0200, Tariq Toukan wrote:
> 
> 
> On 11/12/2020 5:46 PM, Ido Schimmel wrote:
> > On Thu, Nov 12, 2020 at 05:38:44PM +0200, Tariq Toukan wrote:
> > > Hi all,
> > > 
> > > In the past ~2-3 weeks, we started seeing the following WARNING and traces
> > > in our regression testing systems, almost every day.
> > > 
> > > Reproduction is not stable, and not isolated to a specific test, so it's
> > > hard to bisect.
> > > 
> > > Any idea what could this be?
> > > Or what is the suspected offending patch?
> > 
> > Do you have commit f8e48a3dca06 ("lockdep: Fix preemption WARN for spurious
> > IRQ-enable")? I think it fixed the issue for me
> > 
> 
> We do have it. Yet issue still exists.

I checked my mail and apparently we stopped seeing this warning after I
fixed a lockdep issue (spin_lock() vs spin_lock_bh()) in a yet to be
submitted patch. Do you see any other lockdep warnings in the log
besides this one? Maybe something in mlx4/5 which is why syzbot didn't
hit it?

Re: bug report: WARNING in bonding

[Tariq Toukan]

On 11/12/2020 6:33 PM, Ido Schimmel wrote:
> On Thu, Nov 12, 2020 at 05:54:30PM +0200, Tariq Toukan wrote:
>>
>>
>> On 11/12/2020 5:46 PM, Ido Schimmel wrote:
>>> On Thu, Nov 12, 2020 at 05:38:44PM +0200, Tariq Toukan wrote:
>>>> Hi all,
>>>>
>>>> In the past ~2-3 weeks, we started seeing the following WARNING and traces
>>>> in our regression testing systems, almost every day.
>>>>
>>>> Reproduction is not stable, and not isolated to a specific test, so it's
>>>> hard to bisect.
>>>>
>>>> Any idea what could this be?
>>>> Or what is the suspected offending patch?
>>>
>>> Do you have commit f8e48a3dca06 ("lockdep: Fix preemption WARN for spurious
>>> IRQ-enable")? I think it fixed the issue for me
>>>
>>
>> We do have it. Yet issue still exists.
> 
> I checked my mail and apparently we stopped seeing this warning after I
> fixed a lockdep issue (spin_lock() vs spin_lock_bh()) in a yet to be
> submitted patch. Do you see any other lockdep warnings in the log
> besides this one? Maybe something in mlx4/5 which is why syzbot didn't
> hit it?
> 

Hi,

Issue still reproduces. Even in GA kernel.
It is always preceded by some other lockdep warning.

So to get the reproduction:
- First, have any lockdep issue.
- Then, open bond interface.

Any idea what could it be?

We'll share any new info as soon as we have it.

Regards,
Tariq

Re: bug report: WARNING in bonding

[Tariq Toukan]

On 2/18/2021 7:10 PM, Tariq Toukan wrote:
> 
> 
> On 11/12/2020 6:33 PM, Ido Schimmel wrote:
>> On Thu, Nov 12, 2020 at 05:54:30PM +0200, Tariq Toukan wrote:
>>>
>>>
>>> On 11/12/2020 5:46 PM, Ido Schimmel wrote:
>>>> On Thu, Nov 12, 2020 at 05:38:44PM +0200, Tariq Toukan wrote:
>>>>> Hi all,
>>>>>
>>>>> In the past ~2-3 weeks, we started seeing the following WARNING and 
>>>>> traces
>>>>> in our regression testing systems, almost every day.
>>>>>
>>>>> Reproduction is not stable, and not isolated to a specific test, so 
>>>>> it's
>>>>> hard to bisect.
>>>>>
>>>>> Any idea what could this be?
>>>>> Or what is the suspected offending patch?
>>>>
>>>> Do you have commit f8e48a3dca06 ("lockdep: Fix preemption WARN for 
>>>> spurious
>>>> IRQ-enable")? I think it fixed the issue for me
>>>>
>>>
>>> We do have it. Yet issue still exists.
>>
>> I checked my mail and apparently we stopped seeing this warning after I
>> fixed a lockdep issue (spin_lock() vs spin_lock_bh()) in a yet to be
>> submitted patch. Do you see any other lockdep warnings in the log
>> besides this one? Maybe something in mlx4/5 which is why syzbot didn't
>> hit it?
>>
> 
> Hi,
> 
> Issue still reproduces. Even in GA kernel.
> It is always preceded by some other lockdep warning.
> 
> So to get the reproduction:
> - First, have any lockdep issue.
> - Then, open bond interface.
> 
> Any idea what could it be?
> 
> We'll share any new info as soon as we have it.
> 
> Regards,
> Tariq


Bisect shows this is the offending commit:

commit 4d004099a668c41522242aa146a38cc4eb59cb1e
Author: Peter Zijlstra <peterz@infradead.org>
Date:   Fri Oct 2 11:04:21 2020 +0200

     lockdep: Fix lockdep recursion

     Steve reported that lockdep_assert*irq*(), when nested inside lockdep
     itself, will trigger a false-positive.

     One example is the stack-trace code, as called from inside lockdep,
     triggering tracing, which in turn calls RCU, which then uses
    lockdep_assert_irqs_disabled().

     Fixes: a21ee6055c30 ("lockdep: Change hardirq{s_enabled,_context} 
to per-cpu variables")
     Reported-by: Steven Rostedt <rostedt@goodmis.org>
     Signed-off-by: Peter Zijlstra (Intel) <peterz@infradead.org>
     Signed-off-by: Ingo Molnar <mingo@kernel.org>

Re: bug report: WARNING in bonding

[Steven Rostedt]

On Thu, 25 Feb 2021 17:24:48 +0200
Tariq Toukan <ttoukan.linux@gmail.com> wrote:

> > Hi,
> > 
> > Issue still reproduces. Even in GA kernel.
> > It is always preceded by some other lockdep warning.
> > 
> > So to get the reproduction:
> > - First, have any lockdep issue.
> > - Then, open bond interface.
> > 
> > Any idea what could it be?
> > 
> > We'll share any new info as soon as we have it.

Looks like you are triggering:

int bond_update_slave_arr(struct bonding *bond, struct slave *skipslave)
{
	struct bond_up_slave *usable_slaves = NULL, *all_slaves = NULL;
	struct slave *slave;
	struct list_head *iter;
	int agg_id = 0;
	int ret = 0;

#ifdef CONFIG_LOCKDEP
	WARN_ON(lockdep_is_held(&bond->mode_lock));
#endif

And the below commit made lockdep_is_held() always return true if lockdep
has been previously triggered. That is, if you had a lockdep splat earlier,
then lockdep_is_held() will always return true, and this WARN_ON() will
always trigger.

Peter,

Perhaps we should not have this part of your patch:

@@ -5056,13 +5081,13 @@ noinstr int lock_is_held_type(const struct lockdep_map *lock, int read)
        unsigned long flags;
        int ret = 0;
 
-       if (unlikely(current->lockdep_recursion))
+       if (unlikely(!lockdep_enabled()))
                return 1; /* avoid false negative lockdep_assert_held() */
 
        raw_local_irq_save(flags);
        check_flags(flags);
 

Because that changes how lock_is_held_type() behaves, and it will return
true if there's been an earlier lockdep splat, and any code that has
something like the above is going to fail.

Although, checking if a lot is not held seems rather strange. If anything,
the above should be changed to WARN_ON_ONCE() so that it doesn't constantly
trigger when a lockdep trigger happens.

-- Steve


> > 
> > Regards,
> > Tariq  
> 
> 
> Bisect shows this is the offending commit:
> 
> commit 4d004099a668c41522242aa146a38cc4eb59cb1e
> Author: Peter Zijlstra <peterz@infradead.org>
> Date:   Fri Oct 2 11:04:21 2020 +0200
> 
>      lockdep: Fix lockdep recursion
> 
>      Steve reported that lockdep_assert*irq*(), when nested inside lockdep
>      itself, will trigger a false-positive.
> 
>      One example is the stack-trace code, as called from inside lockdep,
>      triggering tracing, which in turn calls RCU, which then uses
>     lockdep_assert_irqs_disabled().
> 
>      Fixes: a21ee6055c30 ("lockdep: Change hardirq{s_enabled,_context} 
> to per-cpu variables")
>      Reported-by: Steven Rostedt <rostedt@goodmis.org>
>      Signed-off-by: Peter Zijlstra (Intel) <peterz@infradead.org>
>      Signed-off-by: Ingo Molnar <mingo@kernel.org>