Skip to content

kernel BUG at include/linux/skbuff.h:970! #1855

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Closed
s0nx opened this issue Apr 5, 2023 · 1 comment
Closed

kernel BUG at include/linux/skbuff.h:970! #1855

s0nx opened this issue Apr 5, 2023 · 1 comment
Assignees
@dmpetroff
Labels
bug crucial h2
Milestone
0.7 - HTTP/2

Comments

@s0nx
Copy link
Contributor

s0nx commented Apr 5, 2023

Motivation

Tempesta crashes when running Wordpress test (see below).

Scope

The issue was reproduced on master branch (94f8383) + all the commits from #1820 and from #1837.

Got the following errors in dmesg:

[  758.283631] [tdb] Start Tempesta DB
[  758.309253] [tempesta fw] Initializing Tempesta FW kernel module...
[  758.375542] [tempesta fw] Configuration processing is completed.
[  758.391519] [tdb] Opened table /opt/tempesta/db/filter0.tdb: size=16777216 rec_size=20 base=00000000b68868d2
[  758.398570] [tdb] Opened table /opt/tempesta/db/sessions0.tdb: size=16777216 rec_size=312 base=0000000044b0da2f
[  758.404982] [tdb] Opened table /opt/tempesta/db/client0.tdb: size=16777216 rec_size=624 base=00000000fa708a86
[  758.423777] [tempesta fw] Open listen socket on: 0.0.0.0:443
[  758.437471] [tempesta fw] Tempesta FW is ready
[  764.987328] curl: page allocation failure: order:2, mode:0xa20(GFP_ATOMIC), nodemask=(null),cpuset=user.slice,mems_allowed=0
[  764.987339] CPU: 3 PID: 13128 Comm: curl Tainted: G           OE     5.10.35perf+ #13
[  764.987342] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 0.0.0 02/06/2015
[  764.987343] Call Trace:
[  764.987346]  <IRQ>
[  764.987353]  dump_stack+0x6b/0x83
[  764.987356]  warn_alloc.cold+0x72/0xd6
[  764.987359]  __alloc_pages_slowpath.constprop.0+0xc40/0xc70
[  764.987363]  __alloc_pages_nodemask+0x2e3/0x310
[  764.987379]  ss_skb_to_sgvec_with_new_pages+0x8d/0x280 [tempesta_fw]
[  764.987389]  tfw_tls_encrypt+0x31b/0x720 [tempesta_fw]
[  764.987392]  ? netif_rx+0x17/0x90
[  764.987395]  ? loopback_xmit+0x9d/0xe0
[  764.987398]  ? __ip_finish_output+0xf2/0x1f0
[  764.987401]  ? pg_skb_alloc+0x451/0x4c0
[  764.987409]  tfw_sc_write_xmit+0xeb/0x290 [tempesta_fw]
[  764.987412]  ? skb_split+0x62/0x2c0
[  764.987414]  tcp_write_xmit+0x3bb/0x12d0
[  764.987416]  __tcp_push_pending_frames+0x32/0xf0
[  764.987417]  tcp_rcv_established+0x255/0x630
[  764.987419]  ? tcp_v4_inbound_md5_hash+0x55/0x160
[  764.987421]  tcp_v4_do_rcv+0x131/0x1f0
[  764.987423]  tcp_v4_rcv+0xbef/0xd40
[  764.987425]  ip_protocol_deliver_rcu+0x2b/0x1b0
[  764.987427]  ip_local_deliver_finish+0x44/0x50
[  764.987429]  __netif_receive_skb_one_core+0x67/0x70
[  764.987430]  process_backlog+0x98/0x170
[  764.987432]  net_rx_action+0x135/0x3b0
[  764.987435]  ? psi_task_change+0x84/0xc0
[  764.987437]  __do_softirq+0xd5/0x297
[  764.987439]  asm_call_irq_on_stack+0xf/0x20
[  764.987440]  </IRQ>
[  764.987443]  do_softirq_own_stack+0x37/0x40
[  764.987445]  do_softirq+0x5e/0x70
[  764.987447]  __local_bh_enable_ip+0x4b/0x50
[  764.987449]  ip_finish_output2+0x198/0x550
[  764.987451]  __ip_queue_xmit+0x180/0x410
[  764.987453]  __tcp_transmit_skb+0xa1b/0xbe0
[  764.987455]  ? __check_object_size+0x56/0x150
[  764.987457]  tcp_recvmsg+0x25f/0xa90
[  764.987460]  inet_recvmsg+0x4e/0xf0
[  764.987463]  ? sock_recvmsg+0x1d/0x70
[  764.987464]  sock_read_iter+0x84/0xd0
[  764.987466]  new_sync_read+0x167/0x180
[  764.987468]  vfs_read+0x147/0x1a0
[  764.987470]  ksys_read+0x87/0xc0
[  764.987473]  do_syscall_64+0x33/0x80
[  764.987475]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[  764.987478] RIP: 0033:0x7f920f02a762
[  764.987479] Code: c0 e9 b2 fe ff ff 50 48 8d 3d 3a 10 08 00 e8 e5 e9 01 00 0f 1f 44 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
[  764.987482] RSP: 002b:00007ffc53e1e458 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
[  764.987484] RAX: ffffffffffffffda RBX: 0000000000004015 RCX: 00007f920f02a762
[  764.987485] RDX: 0000000000004015 RSI: 0000558c60815fa8 RDI: 0000000000000010
[  764.987486] RBP: 0000558c60815fa8 R08: 0000000000000001 R09: 00007ffc53e1e5c8
[  764.987487] R10: 0000000000000002 R11: 0000000000000246 R12: 0000558c607f1100
[  764.987488] R13: 0000000000000000 R14: 0000000000004015 R15: 0000558c607f61a0
[  764.987490] Mem-Info:
[  764.987493] active_anon:273 inactive_anon:67537 isolated_anon:0
[  764.987493]  active_file:21723 inactive_file:17500 isolated_file:0
[  764.987493]  unevictable:0 dirty:164 writeback:3
[  764.987493]  slab_reclaimable:12225 slab_unreclaimable:14830
[  764.987493]  mapped:25277 shmem:5224 pagetables:3189 bounce:0
[  764.987493]  free:294038 free_pcp:150 free_cma:0
[  764.987497] Node 0 active_anon:1092kB inactive_anon:270148kB active_file:86892kB inactive_file:70000kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:101108kB dirty:656kB writeback:12kB shmem:20896kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 0kB writeback_tmp:0kB kernel_stack:4576kB all_unreclaimable? yes
[  764.987500] Node 0 DMA free:14884kB min:204kB low:252kB high:300kB reserved_highatomic:0KB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15996kB managed:15908kB mlocked:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[  764.987504] lowmem_reserve[]: 0 1769 5116 5116 5116
[  764.987507] Node 0 DMA32 free:506508kB min:49920kB low:55744kB high:61568kB reserved_highatomic:0KB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:1938956kB managed:1827584kB mlocked:0kB pagetables:0kB bounce:0kB free_pcp:52kB local_pcp:52kB free_cma:0kB
[  764.987511] lowmem_reserve[]: 0 0 3347 3347 3347
[  764.987513] Node 0 Normal free:654760kB min:143260kB low:154280kB high:165300kB reserved_highatomic:0KB active_anon:1092kB inactive_anon:270116kB active_file:86664kB inactive_file:70228kB unevictable:0kB writepending:668kB present:4194304kB managed:3492384kB mlocked:0kB pagetables:12756kB bounce:0kB free_pcp:496kB local_pcp:136kB free_cma:0kB
[  764.987517] lowmem_reserve[]: 0 0 0 0 0
[  764.987520] Node 0 DMA: 1*4kB (U) 0*8kB 0*16kB 1*32kB (U) 2*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 0*1024kB 1*2048kB (M) 3*4096kB (M) = 14884kB
[  764.987529] Node 0 DMA32: 126531*4kB (U) 41*8kB (UM) 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 506452kB
[  764.987535] Node 0 Normal: 152187*4kB (UME) 5750*8kB (UM) 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 654748kB
[  764.987543] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
[  764.987544] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
[  764.987545] 44459 total pagecache pages
[  764.987548] 0 pages in swap cache
[  764.987549] Swap cache stats: add 0, delete 0, find 0/0
[  764.987550] Free swap  = 5335036kB
[  764.987551] Total swap = 5335036kB
[  764.987552] 1537314 pages RAM
[  764.987552] 0 pages HighMem/MovableOnly
[  764.987553] 203345 pages reserved
[  764.987554] 0 pages cma reserved
[  764.987555] 0 pages hwpoisoned
[  764.987557] [tempesta fw] Warning: tfw_tls_encrypt: cannot encrypt data (-12), only partial data was sent
[  764.987581] ------------[ cut here ]------------
[  764.987582] kernel BUG at include/linux/skbuff.h:970!
[  764.987587] invalid opcode: 0000 [#1] SMP NOPTI
[  764.987589] CPU: 3 PID: 13128 Comm: curl Tainted: G           OE     5.10.35perf+ #13
[  764.987590] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 0.0.0 02/06/2015
[  764.987598] RIP: 0010:tfw_sc_write_xmit+0x20f/0x290 [tempesta_fw]
[  764.987600] Code: 48 89 ef e8 03 f1 ff ff 48 8b 43 10 4d 85 e4 74 19 48 85 c0 75 67 49 c1 e4 08 4c 09 e0 48 83 c8 01 48 89 43 10 e9 18 ff ff ff <0f> 0b 0f 0b e9 57 ff ff ff 31 d2 44 89 fe 48 89 ef e8 5b 83 21 c1
[  764.987602] RSP: 0018:ffffc90000130d20 EFLAGS: 00010246
[  764.987603] RAX: 000000000000002f RBX: ffff888159a00480 RCX: 0000000000000000
[  764.987604] RDX: ffff8881d1f98a88 RSI: 0000000000000001 RDI: ffff8881d1f98a80
[  764.987606] RBP: ffff88819f992600 R08: 0000000000000000 R09: ffffc90000130888
[  764.987607] R10: ffffc90000130880 R11: 00000000fffffff4 R12: 0000000000000000
[  764.987608] R13: 0000000000000003 R14: 0000000000004000 R15: 00000000fffffff4
[  764.987609] FS:  00007f920e593840(0000) GS:ffff8881d1f80000(0000) knlGS:0000000000000000
[  764.987611] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  764.987612] CR2: 00007f4883c77a20 CR3: 000000014b86c006 CR4: 0000000000770ee0
[  764.987615] PKRU: 55555554
[  764.987616] Call Trace:
[  764.987617]  <IRQ>
[  764.987619]  ? skb_split+0x62/0x2c0
[  764.987621]  tcp_write_xmit+0x3bb/0x12d0
[  764.987623]  __tcp_push_pending_frames+0x32/0xf0
[  764.987624]  tcp_rcv_established+0x255/0x630
[  764.987626]  ? tcp_v4_inbound_md5_hash+0x55/0x160
[  764.987628]  tcp_v4_do_rcv+0x131/0x1f0
[  764.987630]  tcp_v4_rcv+0xbef/0xd40
[  764.987632]  ip_protocol_deliver_rcu+0x2b/0x1b0
[  764.987634]  ip_local_deliver_finish+0x44/0x50
[  764.987635]  __netif_receive_skb_one_core+0x67/0x70
[  764.987637]  process_backlog+0x98/0x170
[  764.987639]  net_rx_action+0x135/0x3b0
[  764.987640]  ? psi_task_change+0x84/0xc0
[  764.987642]  __do_softirq+0xd5/0x297
[  764.987644]  asm_call_irq_on_stack+0xf/0x20
[  764.987645]  </IRQ>
[  764.987647]  do_softirq_own_stack+0x37/0x40
[  764.987649]  do_softirq+0x5e/0x70
[  764.987651]  __local_bh_enable_ip+0x4b/0x50
[  764.987653]  ip_finish_output2+0x198/0x550
[  764.987654]  __ip_queue_xmit+0x180/0x410
[  764.987656]  __tcp_transmit_skb+0xa1b/0xbe0
[  764.987658]  ? __check_object_size+0x56/0x150
[  764.987660]  tcp_recvmsg+0x25f/0xa90
[  764.987663]  inet_recvmsg+0x4e/0xf0
[  764.987664]  ? sock_recvmsg+0x1d/0x70
[  764.987666]  sock_read_iter+0x84/0xd0
[  764.987668]  new_sync_read+0x167/0x180
[  764.987670]  vfs_read+0x147/0x1a0
[  764.987672]  ksys_read+0x87/0xc0
[  764.987674]  do_syscall_64+0x33/0x80
[  764.987675]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[  764.987677] RIP: 0033:0x7f920f02a762
[  764.987678] Code: c0 e9 b2 fe ff ff 50 48 8d 3d 3a 10 08 00 e8 e5 e9 01 00 0f 1f 44 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
[  764.987681] RSP: 002b:00007ffc53e1e458 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
[  764.987683] RAX: ffffffffffffffda RBX: 0000000000004015 RCX: 00007f920f02a762
[  764.987684] RDX: 0000000000004015 RSI: 0000558c60815fa8 RDI: 0000000000000010
[  764.987685] RBP: 0000558c60815fa8 R08: 0000000000000001 R09: 00007ffc53e1e5c8
[  764.987687] R10: 0000000000000002 R11: 0000000000000246 R12: 0000558c607f1100
[  764.987688] R13: 0000000000000000 R14: 0000000000004015 R15: 0000558c607f61a0
[  764.987690] Modules linked in: tempesta_fw(OE) tempesta_db(OE) tempesta_tls(OE) tempesta_lib(OE) sha256_ssse3 sha512_ssse3 veth xt_nat nf_conntrack_netlink nfnetlink xt_addrtype br_netfilter overlay xt_CHECKSUM xt_MASQUERADE xt_conntrack ipt_REJECT nf_reject_ipv4 ip6table_mangle ip6table_nat ip6table_filter ip6_tables iptable_mangle iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 iptable_filter bpfilter bridge stp llc qrtr ns sunrpc vfat fat kvm_intel kvm iTCO_wdt intel_pmc_bxt iTCO_vendor_support input_leds irqbypass i2c_i801 pcspkr i2c_smbus virtio_balloon lpc_ich virtiofs fuse zram ip_tables crct10dif_pclmul crc32_pclmul crc32c_intel virtio_net ghash_clmulni_intel serio_raw virtio_scsi virtio_console net_failover virtio_blk failover qemu_fw_cfg ipmi_devintf ipmi_msghandler [last unloaded: tempesta_lib]
[  764.987741] ---[ end trace 609ff893886ab75d ]---
[  764.987748] RIP: 0010:tfw_sc_write_xmit+0x20f/0x290 [tempesta_fw]
[  764.987749] Code: 48 89 ef e8 03 f1 ff ff 48 8b 43 10 4d 85 e4 74 19 48 85 c0 75 67 49 c1 e4 08 4c 09 e0 48 83 c8 01 48 89 43 10 e9 18 ff ff ff <0f> 0b 0f 0b e9 57 ff ff ff 31 d2 44 89 fe 48 89 ef e8 5b 83 21 c1
[  764.987751] RSP: 0018:ffffc90000130d20 EFLAGS: 00010246
[  764.987752] RAX: 000000000000002f RBX: ffff888159a00480 RCX: 0000000000000000
[  764.987753] RDX: ffff8881d1f98a88 RSI: 0000000000000001 RDI: ffff8881d1f98a80
[  764.987755] RBP: ffff88819f992600 R08: 0000000000000000 R09: ffffc90000130888
[  764.987756] R10: ffffc90000130880 R11: 00000000fffffff4 R12: 0000000000000000
[  764.987757] R13: 0000000000000003 R14: 0000000000004000 R15: 00000000fffffff4
[  764.987758] FS:  00007f920e593840(0000) GS:ffff8881d1f80000(0000) knlGS:0000000000000000
[  764.987759] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  764.987761] CR2: 00007f4883c77a20 CR3: 000000014b86c006 CR4: 0000000000770ee0
[  764.987762] PKRU: 55555554
[  764.987763] Kernel panic - not syncing: Fatal exception in interrupt
[  764.988020] Kernel Offset: disabled
[  764.988022] ---[ end Kernel panic - not syncing: Fatal exception in interrupt ]---

The issue seems to be a BUG() in tempesta_skb_set_cb_val():

static inline void
tempesta_skb_set_cb_val(struct sk_buff *skb, unsigned long val, unsigned char off)
{
	unsigned long d = (unsigned long)skb->dev;

	BUG_ON(off + 1 >= sizeof(skb->dev) * BITS_PER_BYTE);
	BUG_ON(!val || __builtin_clzl(val) < off + 1);                             <=====
	BUG_ON(skb->dev && !((unsigned long)skb->dev & 1UL));

	d |= ((val << (off + 1)) | 1UL);
	skb->dev = (void *)d;
}

Testing

Run the following test multiple times:
./run_tests.py -n -v -D t_stress.test_wordpress.H2WordpressStress.test_get_large_images
@krizhanovsky krizhanovsky added this to the 0.7 - Beta milestone Apr 5, 2023
@dmpetroff
Copy link
Contributor

Fixed in tempesta-tech/linux-5.10.35-tfw#10

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@dmpetroff dmpetroff

Labels
bug crucial h2
Projects
None yet
Milestone
0.7 - HTTP/2
Development

No branches or pull requests
3 participants
@krizhanovsky @s0nx @dmpetroff