Crash during reconfiguration under high load

[vankoven]

The issue had appeared during #1077 tests (reconf.test_stress_sched_ratio.SchedRatioStaticImplDefaultSg.test_ratio_del_srvs test) , but it's not related to the issue. See build 247 on CI.

[ 1859.991922] Start test: reconf.test_stress_sched_ratio.SchedRatioStaticImplDefaultSg.test_ratio_del_srvs
[ 1862.531629] [tdb] Start Tempesta DB
[ 1862.546202] net_ratelimit: 207 callbacks suppressed
[ 1862.546202] [tempesta] Initializing Tempesta FW kernel module...
[ 1862.551622] [tempesta] Registering new classifier: frang
[ 1862.555330] [tempesta] Registering new scheduler: hash
[ 1862.557841] [tempesta] Registering new scheduler: ratio
[ 1862.598642] [tempesta] Prepearing for the configuration processing.
[ 1862.601523] [tempesta] Configuration processing is completed.
[ 1862.611169] [tdb] Opened table /opt/tempesta/db/filter.tdb: size=16777216 rec_size=20 base=ffff8e766ac00000
[ 1862.769106] [tdb] Opened table /opt/tempesta/db/cache.tdb: size=268435456 rec_size=0 base=ffff8e765ac00000
[ 1862.773374] [tempesta] Open listen socket on: 0.0.0.0
[ 1862.788777] [tempesta] modules are started
[ 1864.968620] [tempesta] Live reconfiguration of Tempesta.
[ 1864.972388] [tempesta] Prepearing for the configuration processing.
[ 1865.021637] general protection fault: 0000 [#1] SMP PTI
[ 1865.024274] Modules linked in: tempesta_fw(O) tempesta_db(O) tempesta_tls(O) tempesta_lib(O) iptable_mangle xt_mark tcp_diag inet_diag fuse sr_mod cdrom sg ata_generic intel_rapl sb_edac crct10dif_pclmul crc32_pclmul ata_piix ghash_clmulni_intel cirrus ttm drm_kms_helper xen_netfront intel_rapl_perf pcspkr joydev drm libata psmouse scsi_mod i2c_piix4 floppy button ip_tables x_tables autofs4 ext4 crc16 mbcache jbd2 crc32c_generic fscrypto ecb crc32c_intel aesni_intel xen_blkfront aes_x86_64 crypto_simd cryptd glue_helper evdev serio_raw [last unloaded: tempesta_lib]
[ 1865.044015] CPU: 0 PID: 4857 Comm: sysctl Tainted: G           O    4.14.0-tempesta-amd64 #1 Debian 4.14.32-tfw1-1~bpo9+1
[ 1865.048320] Hardware name: Xen HVM domU, BIOS 4.8.4-pre 06/22/2018
[ 1865.051156] task: ffff8e7633aa2d00 task.stack: ffffa47c80ca4000
[ 1865.053902] RIP: 0010:__list_del_entry_valid+0x25/0x90
[ 1865.056414] RSP: 0018:ffff8e768f403810 EFLAGS: 00010207
[ 1865.058990] RAX: ffff8e768f403918 RBX: ffff8e7681ab5020 RCX: dead000000000200
[ 1865.062408] RDX: 166137b75db61600 RSI: ffff8e768f4038b8 RDI: ffff8e768f4038c8
[ 1865.065501] RBP: ffff8e7682255b60 R08: ffff8e768f4038b8 R09: ffff8e763209ee60
[ 1865.068606] R10: 000000000000000f R11: 0000000000000000 R12: ffff8e768f4038b8
[ 1865.071682] R13: ffff8e7682255c00 R14: ffff8e76342145c0 R15: ffff8e768f4034c8
[ 1865.074755] FS:  0000000000000000(0000) GS:ffff8e768f400000(0000) knlGS:0000000000000000
[ 1865.078129] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 1865.080807] CR2: 00007f6c19397ab4 CR3: 000000002ea0a002 CR4: 00000000001606f0
[ 1865.083913] Call Trace:
[ 1865.085655]  <IRQ>
[ 1865.087264]  tfw_http_conn_fwd_unsent+0x470/0x600 [tempesta_fw]
[ 1865.090071]  ? tfw_http_msg_hdr_lookup+0x56/0x70 [tempesta_fw]
[ 1865.092803]  ? tfw_http_msg_hdr_close+0x109/0x1a0 [tempesta_fw]
[ 1865.095538]  tfw_http_popreq.isra.28+0x1e2/0x3b0 [tempesta_fw]
[ 1865.098234]  ? xen_clocksource_get_cycles+0x11/0x20
[ 1865.100771]  tfw_http_resp_cache+0x63/0x170 [tempesta_fw]
[ 1865.103352]  ? tfw_http_resp_gfsm+0x55/0xc0 [tempesta_fw]
[ 1865.105933]  tfw_http_msg_process+0x617/0xaf0 [tempesta_fw]
[ 1865.108571]  ? ip_output+0x71/0xe0
[ 1865.110567]  __gfsm_fsm_exec+0x56/0x90 [tempesta_fw]
[ 1865.113039]  tfw_connection_recv+0x4e/0x70 [tempesta_fw]
[ 1865.115582]  ? tfw_connection_send+0x30/0x30 [tempesta_fw]
[ 1865.118182]  ss_tcp_process_data+0x1db/0x440 [tempesta_fw]
[ 1865.120780]  ss_tcp_data_ready+0x43/0x90 [tempesta_fw]
[ 1865.123269]  tcp_data_queue+0x4f5/0xc50
[ 1865.125364]  tcp_rcv_established+0x27c/0x570
[ 1865.127587]  tcp_v4_do_rcv+0x129/0x1d0
[ 1865.129650]  tcp_v4_rcv+0x947/0xa50
[ 1865.131634]  ip_local_deliver_finish+0x9a/0x1c0
[ 1865.133914]  ip_local_deliver+0x6b/0xe0
[ 1865.135998]  ? ip_rcv_finish+0x400/0x400
[ 1865.138085]  ip_rcv+0x289/0x3c0
[ 1865.139934]  ? inet_del_offload+0x40/0x40
[ 1865.142024]  __netif_receive_skb_core+0x84f/0xb30
[ 1865.144363]  ? netif_receive_skb_internal+0x34/0xe0
[ 1865.146720]  netif_receive_skb_internal+0x34/0xe0
[ 1865.149027]  napi_gro_receive+0xb8/0xe0
[ 1865.151065]  xennet_poll+0xa28/0xbc0 [xen_netfront]
[ 1865.153388]  net_rx_action+0x28e/0x3f0
[ 1865.155356]  ? handle_irq_event+0x47/0x60
[ 1865.157393]  __do_softirq+0x10f/0x2a8
[ 1865.159299]  irq_exit+0xae/0xb0
[ 1865.161008]  xen_evtchn_do_upcall+0x2c/0x40
[ 1865.163007]  xen_hvm_callback_vector+0x7d/0x90
[ 1865.165061]  </IRQ>
[ 1865.166398] RIP: 0010:unmap_page_range+0x63a/0x9d0
[ 1865.168583] RSP: 0018:ffffa47c80ca7cb0 EFLAGS: 00000286 ORIG_RAX: ffffffffffffff0c
[ 1865.171888] RAX: ffffffffffffffff RBX: 00007f6c19cfb000 RCX: 00000000043d5500
[ 1865.174793] RDX: ffffeebbc43da620 RSI: 00007f6c19cfb000 RDI: 000000010f554025
[ 1865.177702] RBP: ffff8e76831327d8 R08: ffff8e762e0450d0 R09: 00007f6c19d1b000
[ 1865.180633] R10: 0000000000000000 R11: 0000000000000001 R12: ffffeebbc43d5500
[ 1865.183545] R13: 000000010f554025 R14: 00007f6c19cfc000 R15: ffffa47c80ca7dd8
[ 1865.186448]  unmap_vmas+0x4c/0xa0
[ 1865.188182]  exit_mmap+0xa1/0x1a0
[ 1865.189895]  mmput+0x54/0x130
[ 1865.191490]  do_exit+0x288/0xb30
[ 1865.193156]  ? handle_mm_fault+0xc6/0x1b0
[ 1865.195073]  do_group_exit+0x3a/0xa0
[ 1865.196855]  SyS_exit_group+0x10/0x10
[ 1865.198644]  do_syscall_64+0x8d/0x120
[ 1865.200428]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
[ 1865.202629] RIP: 0033:0x7f6c1a404618
[ 1865.204387] RSP: 002b:00007ffecf294e08 EFLAGS: 00000246 ORIG_RAX: 00000000000000e7
[ 1865.207365] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f6c1a404618
[ 1865.210419] RDX: 0000000000000000 RSI: 000000000000003c RDI: 0000000000000000
[ 1865.213263] RBP: 00007f6c1a6e18e0 R08: 00000000000000e7 R09: ffffffffffffff98
[ 1865.216143] R10: 00007f6c19343000 R11: 0000000000000246 R12: 00007f6c1a6e18e0
[ 1865.219135] R13: 00007f6c1a6e6c20 R14: 0000000000000000 R15: 0000000000000000
[ 1865.221991] Code: 84 00 00 00 00 00 48 8b 07 48 b9 00 01 00 00 00 00 ad de 48 8b 57 08 48 39 c8 74 26 48 b9 00 02 00 00 00 00 ad de 48 39 ca 74 2b <48> 8b 12 48 39 d7 75 34 48 8b 50 08 48 39 d7 75 3c b8 01 00 00 
[ 1865.229203] RIP: __list_del_entry_valid+0x25/0x90 RSP: ffff8e768f403810
[ 1865.232106] ---[ end trace 3c3b41b6a91d48d5 ]---
[ 1865.234990] Kernel panic - not syncing: Fatal exception in interrupt
[ 1865.238616] Kernel Offset: 0x29c00000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)

[aleksostapenko]

Very likely that the problem is a consequence of #1175 issue.
In particular, very similar BUG_ON can be caught with instrumentation for conditions described in #1175 (comment), in tfw_http_popreq()->tfw_http_conn_fwd_repair()->tfw_srv_conn_reenable_if_done() call chain:

[ 4791.520318] ------------[ cut here ]------------
[ 4791.520319] kernel BUG at /home/test_user/nfs_client/tempesta/tempesta_fw/http.c:1309!
[ 4791.520340] invalid opcode: 0000 [#1] SMP KASAN PTI
[ 4791.520340] Modules linked in: tempesta_fw(O) tempesta_db(O) tempesta_tls(O) tempesta_lib(O) rpcsec_gss_krb5 auth_rpcgss oid_registry nfsv4 dns_resolver nfs lockd grace fscache kvm_intel kvm irqbypass crct10dif_pclmul cirrus ttm ghash_clmulni_intel pcbc drm_kms_helper snd_pcm aesni_intel aes_x86_64 snd_timer joydev drm crypto_simd glue_helper sg evdev cryptd snd serio_raw soundcore pcspkr button sunrpc ip_tables x_tables autofs4 ext4 crc16 mbcache jbd2 fscrypto libcrc32c crc32c_generic sd_mod ata_generic ata_piix libata uhci_hcd ehci_hcd crc32_pclmul i2c_piix4 crc32c_intel e1000 psmouse scsi_mod usbcore floppy
[ 4791.520374] CPU: 3 PID: 1997 Comm: nginx Tainted: G           O    4.14.32-5+ #1
[ 4791.520375] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
[ 4791.520376] task: ffff880081e7d500 task.stack: ffff880080a40000
[ 4791.520389] RIP: 0010:tfw_http_popreq+0xbf6/0x1000 [tempesta_fw]
[ 4791.520390] RSP: 0018:ffff88011a987050 EFLAGS: 00010286
[ 4791.520391] RAX: ffff88009999a930 RBX: ffff88009999a930 RCX: ffff88009999a760
[ 4791.520392] RDX: 00000000ffffffff RSI: ffff88009999a950 RDI: 1ffff1001261ea3e
[ 4791.520393] RBP: ffff88011a987140 R08: fffffbfff3b49011 R09: 1ffff1001261ea3f
[ 4791.520394] R10: ffff88009999a958 R11: fffffbfff3b49011 R12: ffff88009999a958
[ 4791.520395] R13: ffff88009999a620 R14: ffff88009999a940 R15: dffffc0000000000
[ 4791.520396] FS:  00007fa09cb0bb40(0000) GS:ffff88011a980000(0000) knlGS:0000000000000000
[ 4791.520397] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 4791.520398] CR2: 000055625818d000 CR3: 0000000026cd8004 CR4: 00000000003606e0
[ 4791.520401] Call Trace:
[ 4791.520402]  <IRQ>
[ 4791.520406]  ? vprintk_default+0x1f/0x30
[ 4791.520408]  ? vprintk_func+0x27/0x60
[ 4791.520418]  ? tfw_http_req_zap_error+0x330/0x330 [tempesta_fw]
[ 4791.520420]  ? __getnstimeofday64+0x74/0x1a0
[ 4791.520429]  tfw_http_resp_cache+0x1dc/0xd60 [tempesta_fw]
[ 4791.520439]  ? tfw_http_resp_gfsm+0x130/0x130 [tempesta_fw]
[ 4791.520448]  ? tfw_http_init_parser_resp+0x130/0x130 [tempesta_fw]
[ 4791.520456]  ? tfw_pool_exit+0x170/0x170 [tempesta_fw]
[ 4791.520465]  tfw_http_msg_process+0x1593/0x3660 [tempesta_fw]
[ 4791.520475]  ? tfw_http_conn_repair+0x3ea0/0x3ea0 [tempesta_fw]
[ 4791.520476]  ? log_store+0x268/0x450
[ 4791.520479]  ? ip_finish_output+0x4bb/0x680
[ 4791.520481]  ? pg_skb_alloc+0x53a/0xd60
[ 4791.520483]  ? ip_output+0x1b5/0x410
[ 4791.520485]  ? ip_mc_output+0x960/0x960
[ 4791.520487]  ? memset+0x31/0x40
[ 4791.520489]  ? __alloc_skb+0x39b/0x6c0
[ 4791.520498]  ? tfw_http_conn_repair+0x3ea0/0x3ea0 [tempesta_fw]
[ 4791.520506]  __gfsm_fsm_exec+0x145/0x2d0 [tempesta_fw]
[ 4791.520514]  tfw_gfsm_dispatch+0x40/0x60 [tempesta_fw]
[ 4791.520521]  tfw_connection_recv+0x95/0xc0 [tempesta_fw]
[ 4791.520529]  ? tfw_connection_send+0xd0/0xd0 [tempesta_fw]
[ 4791.520538]  ss_tcp_process_data+0x65c/0x1340 [tempesta_fw]
[ 4791.520547]  ? ss_wq_push+0xf0/0xf0 [tempesta_fw]
[ 4791.520549]  ? tcp_send_ack+0x3a2/0x670
[ 4791.520557]  ss_tcp_data_ready+0xbe/0x1d0 [tempesta_fw]
[ 4791.520560]  tcp_rcv_established+0x1074/0x1d30
[ 4791.520561]  ? inet_hashinfo_init+0x80/0x80
[ 4791.520563]  ? tcp_data_queue+0x3f70/0x3f70
[ 4791.520564]  ? tcp_filter+0x160/0x160
[ 4791.520566]  tcp_v4_do_rcv+0x4f9/0x760
[ 4791.520567]  tcp_v4_rcv+0x1ff0/0x2ca0
[ 4791.520570]  ip_local_deliver_finish+0x25c/0x6e0
[ 4791.520572]  ? __update_load_avg_se.isra.34+0x3c2/0x550
[ 4791.520574]  ip_local_deliver+0x1a5/0x340
[ 4791.520576]  ? ip_call_ra_chain+0x5c0/0x5c0
[ 4791.520578]  ? __enqueue_entity+0x10e/0x1f0
[ 4791.520586]  ? tfw_filter_start+0x90/0x90 [tempesta_fw]
[ 4791.520588]  ? enqueue_entity+0x2b7/0x1f40
[ 4791.520590]  ip_rcv_finish+0x403/0x1320
[ 4791.520591]  ? nf_hook_slow+0xb3/0x180
[ 4791.520593]  ip_rcv+0x83b/0x11e0
[ 4791.520595]  ? sched_clock_local+0x43/0x130
[ 4791.520597]  ? ip_local_deliver+0x340/0x340
[ 4791.520598]  ? inet_del_offload+0x40/0x40
[ 4791.520600]  ? attach_task+0xd7/0x100
[ 4791.520602]  ? ip_local_deliver+0x340/0x340
[ 4791.520604]  __netif_receive_skb_core+0x171f/0x2c80
[ 4791.520606]  ? netdev_info+0x100/0x100
[ 4791.520608]  ? cpu_load_update+0x1bd/0x350
[ 4791.520609]  ? task_tick_fair+0xeb2/0x1a00
[ 4791.520611]  __netif_receive_skb+0x26/0x190
[ 4791.520613]  ? __netif_receive_skb+0x26/0x190
[ 4791.520615]  process_backlog+0x1a2/0x600
[ 4791.520618]  ? timerqueue_add+0x12d/0x2b0
[ 4791.520620]  net_rx_action+0x777/0xd30
[ 4791.520621]  ? napi_complete_done+0x350/0x350
[ 4791.520625]  ? clockevents_program_event+0x1af/0x2c0
[ 4791.520627]  ? hrtimer_interrupt+0x282/0x5b0
[ 4791.520630]  __do_softirq+0x1c8/0x5ab
[ 4791.520632]  do_softirq_own_stack+0x2a/0x40
[ 4791.520633]  </IRQ>
[ 4791.520637]  do_softirq.part.17+0x60/0x80
[ 4791.520639]  __local_bh_enable_ip+0x5a/0x60
[ 4791.520641]  ip_finish_output2+0x67f/0xeb0
[ 4791.520645]  ? touch_atime+0xd7/0x250
[ 4791.520647]  ? ip_fragment.constprop.51+0x220/0x220
[ 4791.520655]  ? pagecache_get_page+0x4a/0x430
[ 4791.520657]  ip_finish_output+0x4bb/0x680
[ 4791.520659]  ? ip_finish_output+0x4bb/0x680
[ 4791.520660]  ip_output+0x1b5/0x410
[ 4791.520662]  ? ip_mc_output+0x960/0x960
[ 4791.520665]  ? kernel_sendpage+0xd0/0xd0
[ 4791.520666]  ? kernel_sendpage+0x65/0xd0
[ 4791.520668]  ip_local_out+0x70/0x90
[ 4791.520670]  ip_queue_xmit+0x778/0x17d0
[ 4791.520672]  tcp_transmit_skb+0x17e6/0x3780
[ 4791.520675]  ? __tcp_select_window+0x6b0/0x6b0
[ 4791.520677]  ? kvm_clock_read+0x1e/0x20
[ 4791.520679]  ? sched_clock+0x9/0x10
[ 4791.520680]  ? sched_clock_local+0x43/0x130
[ 4791.520682]  ? sched_clock_cpu+0x10c/0x180
[ 4791.520684]  tcp_write_xmit+0x531/0x5c70
[ 4791.520686]  ? tcp_current_mss+0x189/0x280
[ 4791.520688]  ? splice_direct_to_actor+0x501/0x790
[ 4791.520690]  ? tcp_sync_mss+0x5b0/0x5b0
[ 4791.520693]  __tcp_push_pending_frames+0x8d/0x2a0
[ 4791.520694]  do_tcp_setsockopt.isra.35+0x1236/0x1b20
[ 4791.520696]  ? tcp_disconnect+0x1470/0x1470
[ 4791.520698]  ? rw_verify_area+0xbd/0x2b0
[ 4791.520700]  ? do_sendfile+0x856/0xe50
[ 4791.520701]  tcp_setsockopt+0x83/0xd0
[ 4791.520704]  sock_common_setsockopt+0x78/0xf0
[ 4791.520705]  SyS_setsockopt+0x145/0x210
[ 4791.520707]  ? SyS_recv+0x20/0x20
[ 4791.520709]  ? SyS_sendfile64+0xaf/0x110
[ 4791.520710]  ? SyS_sendfile+0xf0/0xf0
[ 4791.520712]  ? SyS_recv+0x20/0x20
[ 4791.520714]  do_syscall_64+0x194/0x440
[ 4791.520716]  ? async_page_fault+0x2f/0x50
[ 4791.520717]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
[ 4791.520719] RIP: 0033:0x7fa09b467c7a
[ 4791.520720] RSP: 002b:00007ffe297a2868 EFLAGS: 00000246 ORIG_RAX: 0000000000000036
[ 4791.520721] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007fa09b467c7a
[ 4791.520722] RDX: 0000000000000003 RSI: 0000000000000006 RDI: 0000000000000003
[ 4791.520723] RBP: 000055625815d090 R08: 0000000000000004 R09: 0000000000000003
[ 4791.520724] R10: 00007ffe297a2874 R11: 0000000000000246 R12: 00005562581503f0
[ 4791.520725] R13: 00007fa09cad01e0 R14: 0000556258148400 R15: 0000556258148460
[ 4791.520726] Code: 00 00 00 fc ff df 48 c1 ea 03 80 3c 02 00 0f 85 15 01 00 00 49 8b 85 10 03 00 00 48 39 c3 0f 84 e4 fd ff ff e9 d0 fd ff ff 0f 0b <0f> 0b 48 89 da 48 b8 00 00 00 00 00 fc ff df 48 c1 ea 03 80 3c
[ 4791.520755] RIP: tfw_http_popreq+0xbf6/0x1000 [tempesta_fw] RSP: ffff88011a987050

[aleksostapenko]

With additional instrumentation and logging during reproducing above crash - it has been confirmed that the issue is a consequence of #1175: after the scenario described in #1175 (comment), server connection can continue processing responses/requests in the same time as connection's destructor is executing in other thread; as a result, the following sequence may take place (as a continuation of mentioned in #1175 (comment) scenario):
Thr.2: responses from the server arrive and link with requests from connection's fwd_queue - intfw_http_resp_process();
Thr.1: all requests are evicted from connection's fwd_queue - in tfw_http_conn_shrink_fwdq_resched(), called from connection's destructor;
Thr.1: requests can be redistributed further among other connections or moved to eq (due to timeout/retries expiration) or just dropped and deleted (if this is health monitoring request, or in case of client connection closing); all these actions take place without any locking for fwd_queue of initial connection;
Thr.2: but links to those requests (one or more) remain in tfw_http_resp_process () of the response processing SoftIRQ, and in tfw_http_popreq() -> list_del_init (&req-> fwd_list) we get various crashes, e.g:

1. If request is caught by list_del_init() while it is added on rescheduling in eq, or while it is added to fwd_queue of another connection, or removed from fwd_queue of other connection etc., there will be the crash in list_debug (i.e. __list_del_entry_valid() - due to list structure violation), since, as mentioned above, there is no any synchronization for list access in this case;
2. If request had been deleted during rescheduling, and new request is allocated and initialized by zeros to its memory area, then we will also get crash in list_debug - not on BUG_ON this time, but with "unable to handle kernel NULL pointer dereference".

These scenarios can arise not only during reconfiguration - on shutdown they are also possible, though less likely.

[aleksostapenko]

Fixed in context of #1179.