Open b3b opened 2 years ago
I received this bug for h2 request with 500+ MB in body. Test to reproduce.
tls.test_tls_integrity.ProxyH2
with TCP segmentation 1 byte. Tempesta - f6d4355dfb9040473fa0c5e84891d207441babf6
[ 148.472087] ------------[ cut here ]------------
[ 148.472944] WARNING: CPU: 2 PID: 2447 at mm/page_alloc.c:4935 __alloc_pages_nodemask+0x291/0x310
[ 148.475965] Modules linked in: tempesta_fw(OE) tempesta_db(OE) sha256_ssse3(E) sha512_ssse3(E) sha512_generic(E) tempesta_tls(OE) tempesta_lib(OE) uinput(E) xt_conntrack(E) nft_chain_nat(E) xt_MASQUERADE(E) nf_nat(E) nf_conntrack_netlink(E) nf_conntrack(E) nf_defrag_ipv6(E) nf_defrag_ipv4(E) xfrm_user(E) xfrm_algo(E) nft_counter(E) xt_addrtype(E) nft_compat(E) nf_tables(E) libcrc32c(E) nfnetlink(E) br_netfilter(E) bridge(E) stp(E) llc(E) overlay(E) hid_generic(E) usbhid(E) hid(E) rfkill(E) intel_rapl_msr(E) intel_rapl_common(E) intel_pmc_core(E) crc32_pclmul(E) ghash_clmulni_intel(E) sr_mod(E) snd_ens1371(E) cdrom(E) snd_ac97_codec(E) aesni_intel(E) libaes(E) ata_generic(E) crypto_simd(E) ac97_bus(E) cryptd(E) gameport(E) glue_helper(E) vsock_loopback(E) snd_rawmidi(E) vmw_vsock_virtio_transport_common(E) snd_seq_device(E) ehci_pci(E) uhci_hcd(E) snd_pcm(E) ehci_hcd(E) vmw_balloon(E) ata_piix(E) snd_timer(E) snd(E) usbcore(E) joydev(E) pcspkr(E) libata(E) e1000(E)
[ 148.476005] vmw_vsock_vmci_transport(E) soundcore(E) i2c_piix4(E) vsock(E) sg(E) vmw_vmci(E) button(E) ac(E) msr(E) parport_pc(E) ppdev(E) lp(E) parport(E) fuse(E) configfs(E) ip_tables(E) x_tables(E) autofs4(E) ext4(E) crc32c_generic(E) crc16(E) mbcache(E) jbd2(E) sd_mod(E) t10_pi(E) crc_t10dif(E) crct10dif_generic(E) vmwgfx(E) drm_kms_helper(E) cec(E) ttm(E) drm(E) mptspi(E) scsi_transport_spi(E) mptscsih(E) mptbase(E) scsi_mod(E) psmouse(E) crct10dif_pclmul(E) crct10dif_common(E) evdev(E) crc32c_intel(E) serio_raw(E)
[ 148.499405] CPU: 2 PID: 2447 Comm: python3 Tainted: G OE 5.10.35+ #16
[ 148.500864] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 11/12/2020
[ 148.502789] RIP: 0010:__alloc_pages_nodemask+0x291/0x310
[ 148.503852] Code: 48 8b 04 25 c0 7b 01 00 48 05 48 0c 00 00 41 bd 01 00 00 00 48 89 44 24 08 e9 47 fe ff ff 81 e5 00 20 00 00 0f 85 60 ff ff ff <0f> 0b e9 59 ff ff ff 31 c0 e9 1b fe ff ff e8 4c 41 fc ff 48 89 c7
[ 148.507173] RSP: 0018:ffffb85fc04eca50 EFLAGS: 00010246
[ 148.508360] RAX: 0000000000000000 RBX: ffff9c2925286010 RCX: 0000000000000000
[ 148.510285] RDX: 0000000000000000 RSI: 000000000000000b RDI: 0000000000040a20
[ 148.512192] RBP: 0000000000000000 R08: 0000000000000001 R09: 00000000007ffff0
[ 148.513804] R10: 0000000000000020 R11: 0000000000000001 R12: 0000000000400010
[ 148.515284] R13: 000000000000000b R14: ffffb85fc04ecbe4 R15: ffff9c270db3e6c0
[ 148.516598] FS: 00007fe46910d700(0000) GS:ffff9c295a080000(0000) knlGS:0000000000000000
[ 148.518163] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 148.519440] CR2: 00007fd854646ccc CR3: 00000001901ee002 CR4: 0000000000370ee0
[ 148.520741] Call Trace:
[ 148.521257] <IRQ>
[ 148.521654] __get_free_pages+0xd/0x30
[ 148.522372] __tfw_pool_realloc+0xd3/0x120 [tempesta_fw]
[ 148.523425] __str_grow_tree+0x45/0x140 [tempesta_fw]
[ 148.524340] __tfw_http_msg_add_str_data+0x38/0xd0 [tempesta_fw]
[ 148.525435] tfw_h2_parse_req+0x138/0x200 [tempesta_fw]
[ 148.526374] ss_skb_process+0xed/0x130 [tempesta_fw]
[ 148.527303] ? h2_set_hdr_if_mod_since+0x40/0x40 [tempesta_fw]
[ 148.528431] tfw_http_req_process+0x7c/0x870 [tempesta_fw]
[ 148.529439] ? ttls_decrypt+0x28e/0x510 [tempesta_tls]
[ 148.530424] ? ss_skb_process+0xed/0x130 [tempesta_fw]
[ 148.531359] ? tfw_h2_conn_terminate_close+0x30/0x30 [tempesta_fw]
[ 148.532947] tfw_h2_frame_process+0x26b/0x4b0 [tempesta_fw]
[ 148.534036] tfw_connection_recv+0x52/0xa0 [tempesta_fw]
[ 148.535215] tfw_tls_connection_recv+0x281/0x3a0 [tempesta_fw]
[ 148.537516] ss_tcp_process_data+0x1f1/0x400 [tempesta_fw]
[ 148.538632] ss_tcp_data_ready+0x3f/0xc0 [tempesta_fw]
[ 148.539933] tcp_rcv_established+0x5d8/0x680
[ 148.540933] tcp_v4_do_rcv+0x131/0x1f0
[ 148.541662] tcp_v4_rcv+0xc2f/0xd80
[ 148.542292] ip_protocol_deliver_rcu+0x2b/0x1b0
[ 148.543269] ip_local_deliver_finish+0x44/0x50
[ 148.544085] __netif_receive_skb_one_core+0x87/0xa0
[ 148.544958] process_backlog+0x96/0x160
[ 148.545668] net_rx_action+0x145/0x3e0
[ 148.546344] __do_softirq+0xcf/0x284
[ 148.546987] asm_call_irq_on_stack+0x12/0x20
[ 148.547879] </IRQ>
[ 148.548328] do_softirq_own_stack+0x37/0x40
[ 148.549087] do_softirq+0x5e/0x70
[ 148.549701] __local_bh_enable_ip+0x4b/0x50
[ 148.550527] ip_finish_output2+0x1ab/0x590
[ 148.551284] ? ipv4_link_failure+0x1b0/0x1b0
[ 148.552145] __ip_queue_xmit+0x180/0x410
[ 148.552911] __tcp_transmit_skb+0xa0e/0xbc0
[ 148.553661] tcp_write_xmit+0x401/0x1280
[ 148.554376] __tcp_push_pending_frames+0x32/0xf0
[ 148.555203] tcp_sendmsg_locked+0xa32/0xb50
[ 148.556040] tcp_sendmsg+0x28/0x40
[ 148.556697] sock_sendmsg+0x57/0x60
[ 148.557353] sock_write_iter+0x97/0x100
[ 148.558063] new_sync_write+0x199/0x1b0
[ 148.558756] vfs_write+0x1c2/0x260
[ 148.559536] ksys_write+0xa7/0xe0
[ 148.560242] ? exit_to_user_mode_prepare+0x6e/0x120
[ 148.561277] do_syscall_64+0x33/0x80
[ 148.562051] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 148.563334] RIP: 0033:0x7fe46dcfffef
[ 148.564021] Code: 89 54 24 18 48 89 74 24 10 89 7c 24 08 e8 29 fd ff 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 5c fd ff ff 48
[ 148.567729] RSP: 002b:00007fe46910a730 EFLAGS: 00000293 ORIG_RAX: 0000000000000001
[ 148.569246] RAX: ffffffffffffffda RBX: 000000000000001e RCX: 00007fe46dcfffef
[ 148.570624] RDX: 000000000000001e RSI: 00007fe46406eb73 RDI: 0000000000000005
[ 148.572108] RBP: 00007fe464003cd0 R08: 0000000000000000 R09: 00007fe46910a8b0
[ 148.573656] R10: 00007fe46cfb1d50 R11: 0000000000000293 R12: 00007fe46406eb73
[ 148.574995] R13: 000000000000001e R14: 00007fe464002808 R15: 00007fe464001f80
[ 148.576443] ---[ end trace 4c9ceb94de080a36 ]---
[ 148.577358] [tempesta fw] Warning: Cannot grow HTTP data string
[ 148.578784] [tempesta fw] Warning: failed to parse request: 127.0.0.1
TCP segmentation 1 for tests:
[ 1281.638924] ------------[ cut here ]------------
[ 1281.639298] WARNING: CPU: 2 PID: 0 at mm/page_alloc.c:4935 __alloc_pages_nodemask+0x298/0x310
[ 1281.639838] Modules linked in: tempesta_fw(OE) tempesta_db(OE) tempesta_tls(OE) tempesta_lib(OE) tls sha256_ssse3 sha512_ssse3 xt_conntrack nft_chain_nat xt_MASQUERADE nf_nat nf_conntrack_netlink nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 xfrm_user xfrm_algo nft_counter xt_addrtype nft_compat br_netfilter bridge stp llc overlay binfmt_misc snd_hda_codec_generic ledtrig_audio snd_hda_intel snd_intel_dspcfg snd_hda_codec intel_rapl_msr intel_rapl_common snd_hda_core snd_hwdep kvm_intel snd_pcm snd_seq_midi snd_seq_midi_event kvm qxl snd_rawmidi drm_ttm_helper nls_iso8859_1 ttm snd_seq crct10dif_pclmul ghash_clmulni_intel aesni_intel snd_seq_device snd_timer crypto_simd cryptd glue_helper drm_kms_helper snd cec input_leds serio_raw rc_core soundcore joydev fb_sys_fops syscopyarea sysfillrect sysimgblt mac_hid qemu_fw_cfg sch_fq_codel msr parport_pc ppdev drm lp parport ramoops pstore_blk pstore_zone efi_pstore reed_solomon virtio_rng ip_tables x_tables autofs4 hid_generic usbhid hid psmouse
[ 1281.639937] xhci_pci virtio_net lpc_ich virtio_blk i2c_i801 i2c_smbus net_failover crc32_pclmul ahci libahci failover xhci_pci_renesas [last unloaded: tempesta_lib]
[ 1281.646155] CPU: 2 PID: 0 Comm: swapper/2 Tainted: G OE 5.10.35+ #3
[ 1281.646626] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.15.0-1 04/01/2014
[ 1281.647135] RIP: 0010:__alloc_pages_nodemask+0x298/0x310
[ 1281.647476] Code: 48 8b 04 25 c0 7b 01 00 48 05 60 0c 00 00 41 be 01 00 00 00 48 89 45 b0 e9 43 fe ff ff 41 81 e4 00 20 00 00 0f 85 60 ff ff ff <0f> 0b e9 59 ff ff ff 31 c0 e9 17 fe ff ff e8 25 bc fb ff 48 89 c7
[ 1281.648662] RSP: 0018:ffffad4fc011c7b0 EFLAGS: 00010246
[ 1281.649003] RAX: 0000000000000000 RBX: ffff9a98bb419010 RCX: 0000000000000000
[ 1281.649455] RDX: 0000000000000000 RSI: 000000000000000b RDI: 0000000000040a20
[ 1281.649906] RBP: ffffad4fc011c808 R08: 0000000000000001 R09: ffff9a988a7d2482
[ 1281.650360] R10: ffff9a986e8fb4d8 R11: 0000000086d88000 R12: 0000000000000000
[ 1281.650810] R13: ffffffff8ee43a80 R14: 000000000000000b R15: 0000000000000000
[ 1281.651261] FS: 0000000000000000(0000) GS:ffff9a99b7c80000(0000) knlGS:0000000000000000
[ 1281.651769] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 1281.652134] CR2: 00007fe5f4f77ae0 CR3: 0000000121a94006 CR4: 0000000000770ee0
[ 1281.652587] PKRU: 55555554
[ 1281.652765] Call Trace:
[ 1281.652930] <IRQ>
[ 1281.653073] alloc_pages_current+0x84/0x140
[ 1281.653345] __get_free_pages+0x11/0x40
[ 1281.653606] tfw_pool_alloc_pages+0x53/0x60 [tempesta_fw]
[ 1281.653963] __tfw_pool_realloc+0x117/0x160 [tempesta_fw]
[ 1281.654316] __str_grow_tree+0x56/0x160 [tempesta_fw]
[ 1281.654652] ? ip_output+0x78/0x100
[ 1281.654885] tfw_str_add_compound+0x1b/0x30 [tempesta_fw]
[ 1281.655243] __tfw_http_msg_add_str_data+0x3d/0x100 [tempesta_fw]
[ 1281.655639] tfw_http_parse_resp+0xc8a8/0x151b0 [tempesta_fw]
[ 1281.656013] ss_skb_process+0xf3/0x140 [tempesta_fw]
[ 1281.656338] ? tfw_h2_parse_req_hdr+0x10510/0x10510 [tempesta_fw]
[ 1281.656732] tfw_http_msg_process_generic+0xda/0x740 [tempesta_fw]
[ 1281.657131] ? kmem_cache_free+0x105/0x470
[ 1281.657407] ? kfree_skbmem+0x1a7/0x1e0
[ 1281.657661] tfw_http_msg_process+0x38/0x50 [tempesta_fw]
[ 1281.658015] tfw_connection_recv+0x56/0xa0 [tempesta_fw]
[ 1281.658362] ss_tcp_process_data+0x1e0/0x430 [tempesta_fw]
[ 1281.658718] ss_tcp_data_ready+0x44/0xf0 [tempesta_fw]
[ 1281.659053] tcp_data_ready+0x2b/0xd0
[ 1281.659291] tcp_rcv_established+0x530/0x6b0
[ 1281.659568] tcp_v4_do_rcv+0x140/0x200
[ 1281.659812] tcp_v4_rcv+0xcd0/0xe20
[ 1281.660040] ip_protocol_deliver_rcu+0x44/0x230
[ 1281.660337] ip_local_deliver_finish+0x48/0x60
[ 1281.660625] ip_local_deliver+0xf8/0x110
[ 1281.660880] ? ip_protocol_deliver_rcu+0x230/0x230
[ 1281.661190] ip_rcv_finish+0x87/0xa0
[ 1281.661424] ip_rcv+0xce/0xe0
[ 1281.661619] ? ip_rcv_finish_core.constprop.0+0x470/0x470
[ 1281.661971] __netif_receive_skb_core+0x4ed/0x1030
[ 1281.662280] ? consume_skb+0x46/0xb0
[ 1281.662516] ? packet_rcv+0x54/0x490
[ 1281.662750] __netif_receive_skb_one_core+0x3f/0xa0
[ 1281.663064] __netif_receive_skb+0x18/0x60
[ 1281.663329] process_backlog+0x9e/0x170
[ 1281.663580] net_rx_action+0x13b/0x430
[ 1281.663831] ? try_to_wake_up+0x218/0x6c0
[ 1281.664101] __do_softirq+0xe3/0x340
[ 1281.664336] asm_call_irq_on_stack+0xf/0x20
[ 1281.664606] </IRQ>
[ 1281.664753] do_softirq_own_stack+0x3d/0x50
[ 1281.665035] irq_exit_rcu+0xa2/0xe0
[ 1281.665271] sysvec_call_function_single+0x3d/0x90
[ 1281.665592] asm_sysvec_call_function_single+0x12/0x20
[ 1281.665933] RIP: 0010:native_safe_halt+0xe/0x10
[ 1281.666235] Code: 39 ff ff ff 4c 89 ee 48 c7 c7 a0 ba c5 8e e8 19 7b 8e ff e9 01 ff ff ff cc cc cc cc e9 07 00 00 00 0f 00 2d 66 a8 44 00 fb f4 <c3> 90 e9 07 00 00 00 0f 00 2d 56 a8 44 00 f4 c3 cc cc 0f 1f 44 00
[ 1281.667449] RSP: 0018:ffffad4fc0093e88 EFLAGS: 00000216
[ 1281.667805] RAX: ffffffff8ddc02c0 RBX: 0000000000000002 RCX: ffff9a99b7cace40
[ 1281.668269] RDX: 000000000018dafe RSI: 0000000000000082 RDI: 0000000000000082
[ 1281.668732] RBP: ffffad4fc0093e90 R08: 000000cd42e4dffb R09: 0000000000000000
[ 1281.669196] R10: 0000012a6a2c1b56 R11: 0000000000000014 R12: ffff9a98602e0000
[ 1281.669661] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[ 1281.670130] ? __sched_text_end+0x4/0x4
[ 1281.670385] ? default_idle+0xe/0x20
[ 1281.670627] arch_cpu_idle+0x15/0x20
[ 1281.670865] default_idle_call+0x3d/0xc0
[ 1281.671124] do_idle+0x215/0x2a0
[ 1281.671340] cpu_startup_entry+0x20/0x30
[ 1281.671603] start_secondary+0x145/0x1b0
[ 1281.671867] secondary_startup_64_no_verify+0xc2/0xcb
[ 1281.672201] ---[ end trace c4d8ec3bde4a7920 ]---
My config (Tempesta on separate VM) :
[General]
ip = 192.168.122.1
ipv6 = ::1
verbose = 6
workdir = /tmp/host
duration = 10
concurrent_connections = 10
log_file = tests_log.log
stress_threads = 2
stress_large_content_length = 65536
stress_requests_count = 100
stress_mtu = 1500
long_body_size = 500
[Client] ip = 192.168.122.1 ipv6 = ::1 hostname = localhost ab = ab wrk = wrk h2load = h2load tls-perf = tls-perf workdir = /tmp/client unavaliable_timeout = 300
[Tempesta] ip = 192.168.122.116 ipv6 = ::1 hostname = 192.168.122.116 user = root port = 22 srcdir = /root/tempesta workdir = /tmp/host config = tempesta.conf tmp_config = tempesta_tmp.conf unavaliable_timeout = 300
[Server] ip = 192.168.122.1 ipv6 = ::1 hostname = localhost user = root port = 22 nginx = nginx workdir = /tmp/nginx resources = /var/www/html/ aliases_interface = virbr0 aliases_base_ip = 192.168.122.1 max_workers = 16 keepalive_timeout = 60 keepalive_requests = 100 unavaliable_timeout = 300
Motivation
Currently, it is not possible to serve big responses (files) from backend, because of memory allocation error.
DMESG WARNING mm/page_alloc.c:4935
Related issue: https://github.com/tempesta-tech/tempesta/issues/498
Testing
To reproduce, backend on port 8000 should return a large response (tested on 1GB).
tempesta.cfg
curl -v http://127.0.0.1/test