search

tempesta-tech / tempesta

All-in-one solution for high performance web content delivery and advanced protection against DDoS and web attacks
https://tempesta-tech.com/
GNU General Public License v2.0
616 stars 103 forks source link

Server failovering may cause crashes under load or during getting of perfstat #692

Closed vankoven closed 6 years ago

vankoven commented 7 years ago

Hard to reproduce.

Ways to reproduce:

  1. start nginx on host 1, Keep-alive requests limit = 100;
  2. start tempesta on host 1;
  3. run wrk on host 2;
  4. read performance stats.

In this case i have 80-95% probability of crash during wrk job or when reading statistics. Running all the programs on same host does not cause crash. If nginx's keep-alive requests limit will be set to some big value (e.g. 1M, nginx does not allow to switch off the limitation) crash does not happen.

Here are my configs: Nginx:


pid /home/user/nginx/nginx_8000.pid ;
worker_processes 1 ;

events {
    worker_connections   1024;
    use epoll;
}

http {
    keepalive_timeout 65;
    keepalive_requests 100;
    sendfile         on;
    tcp_nopush       on;
    tcp_nodelay      on;

    open_file_cache max=1000;
    open_file_cache_valid 30s;
    open_file_cache_min_uses 2;
    open_file_cache_errors off;

    # [ debug | info | notice | warn | error | crit | alert | emerg ]
    # Fully disable log errors.
    error_log /dev/null emerg;

    # Disable access log altogether.
    access_log off;

    server {
        listen 8000 ;

        location / {
            root /srv/http ;
        }
        location /nginx_status {
            stub_status on;
        }
    }
}

Tempesta:

cache 0;
sched round-robin;
server 10.0.10.2:8000;

Script to reproduce, run it on host 2.

#!/bin/bash

TEMPESTA_HOST="root@10.0.10.2"
TEMPESTA_DIR="/home/user/tempesta"
NGINX_CONFIG="/home/user/nginx/nginx_8000.conf"
NGINX_PIDFILE="/home/user/nginx/nginx_8000.pid"
WRK="wrk"

REMOTE='true'
if [ ${REMOTE} != 'true' ]; then
        RUN='eval '
else
        RUN="ssh ${TEMPESTA_HOST} "
fi

echo Start nginx...
${RUN} "nginx -c ${NGINX_CONFIG}"
echo Start Tempesta...
${RUN} "${TEMPESTA_DIR}/scripts/tempesta.sh --start"
sleep 2
echo "Run Wrk for 5 secondss..."
${WRK} -d 5 -t 4 -c 10 http://10.0.10.2/
echo Get Tempesta perfstats...
${RUN} "cat /proc/tempesta/perfstat"
echo Stop Tempesta....
${RUN} "${TEMPESTA_DIR}/scripts/tempesta.sh --stop"
echo stop nginx...
${RUN} "xargs -a ${NGINX_PIDFILE} kill -s TERM"

Crash dump:

[   77.480951] [tdb] Start Tempesta DB
[   77.485841] [tempesta] Initializing Tempesta FW kernel module...
[   77.492390] [tempesta] Registering new scheduler: hash
[   77.494745] [tempesta] Registering new scheduler: http
[   77.497258] [tempesta] Registering new scheduler: round-robin
[   77.500871] [tempesta] Starting all modules...
[   77.511487] [tdb] Opened table /opt/tempesta/db/filter.tdb: size=16777216 rec_size=20 base=ffff88007c400000
[   77.513919] [tempesta] Open listen socket on: 0.0.0.0
[   77.515172] [tempesta] modules are started
[   83.199119] [tempesta] Warning: Unable to find a backend server
[   83.200107] [tempesta] Warning: Unable to find a backend server
[   83.200472] [tempesta] Warning: Unable to find a backend server
[   83.200490] [tempesta] Warning: Unable to find a backend server
[   83.200504] [tempesta] Warning: Unable to find a backend server
[   83.248867] [tempesta] Warning: Unable to find a backend server
[   83.248900] [tempesta] Warning: Unable to find a backend server
[   83.248906] [tempesta] Warning: Unable to find a backend server
[   83.248910] [tempesta] Warning: Unable to find a backend server
[   83.248913] [tempesta] Warning: Unable to find a backend server
[   84.507090] ------------[ cut here ]------------
[   84.507992] kernel BUG at net/core/skbuff.c:1667!
[   84.508440] invalid opcode: 0000 [#1] PREEMPT SMP
[   84.508961] Modules linked in: tfw_sched_rr(O) tfw_sched_http(O) tfw_sched_hash(O) tempesta_fw(O) tempesta_db(O) tempesta_tls(O) mousedev crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel snd_hda_codec_generic bochs_drm snd_hda_intel aesni_intel ttm aes_x86_64 lrw snd_hda_codec ppdev gf128mul glue_helper iTCO_wdt ablk_helper iTCO_vendor_support drm_kms_helper cryptd snd_hda_core evdev input_leds led_class mac_hid snd_hwdep psmouse pcspkr snd_pcm snd_timer snd drm acpi_cpufreq soundcore parport_pc syscopyarea sysfillrect sysimgblt fb_sys_fops lpc_ich tpm_tis intel_agp i2c_i801 shpchp i2c_smbus tpm_tis_core intel_gtt tpm parport qemu_fw_cfg button sch_fq_codel ip_tables x_tables ext4 crc16 jbd2 fscrypto mbcache sr_mod cdrom virtio_console virtio_net virtio_blk virtio_balloon serio_raw atkbd libps2 uhci_hcd ahci libahci virtio_pci virtio_ring virtio libata scsi_mod ehci_pci ehci_hcd usbcore usb_common i8042 serio
[   84.519036] CPU: 1 PID: 0 Comm: swapper/1 Tainted: G           O    4.8.15-3-tempesta #3
[   84.520845] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.10.1-20161122_114906-anatol 04/01/2014
[   84.522157] task: ffff88005c8ce3c0 task.stack: ffff88005c8e0000
[   84.523535] RIP: 0010:[<ffffffff814d77e0>]  [<ffffffff814d77e0>] skb_put+0x40/0x60
[   84.525864] RSP: 0018:ffff88007fd03878  EFLAGS: 00010202
[   84.526914] RAX: ffff88005b948c30 RBX: ffff88005b948a00 RCX: ffff88005b948cf0
[   84.528218] RDX: 0000000000000130 RSI: 0000000000000011 RDI: ffff88005b948a00
[   84.529528] RBP: ffff88007fd03960 R08: 0000000000000130 R09: ffff88005b948a00
[   84.530762] R10: 0000000000000000 R11: 0000000000000053 R12: 0000000000000011
[   84.531785] R13: 00000000000005a8 R14: ffff88005938a8f0 R15: 0000000000000000
[   84.533032] FS:  0000000000000000(0000) GS:ffff88007fd00000(0000) knlGS:0000000000000000
[   84.534040] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   84.535282] CR2: 000055e1b81ba588 CR3: 000000005b909000 CR4: 00000000003406e0
[   84.537277] Stack:
[   84.537722]  ffffffff814d8f4e ffff88007fd038c0 ffffffffffffffbe 000000000000000a
[   84.539097]  ffff880002026600 00000053fffffff4 0000000000000000 0000000000000042
[   84.540472]  00000000000000ee 0000000000000001 ffff88005b948a00 0000000000000042
[   84.541713] Call Trace:
[   84.542021]  <IRQ> 
[   84.542392]  [<ffffffff814d8f4e>] ? skb_segment+0x50e/0xc30
[   84.543438]  [<ffffffffa04e7e1c>] ? tfw_http_conn_send+0x1c/0x20 [tempesta_fw]
[   84.544692]  [<ffffffff815575f3>] tcp_gso_segment+0xf3/0x4d0
[   84.545686]  [<ffffffffa04e8c40>] ? tfw_http_send_502+0xf0/0xf0 [tempesta_fw]
[   84.546960]  [<ffffffff81548430>] ? tcp_event_new_data_sent+0x90/0x90
[   84.548091]  [<ffffffff81557a0e>] tcp4_gso_segment+0x3e/0xa0
[   84.548994]  [<ffffffff815688de>] inet_gso_segment+0x13e/0x3a0
[   84.549737]  [<ffffffff814ebf7a>] skb_mac_gso_segment+0xba/0x130
[   84.550256]  [<ffffffff814ec0ad>] __skb_gso_segment+0xbd/0x150
[   84.551412]  [<ffffffff814ec533>] validate_xmit_skb+0x153/0x2d0
[   84.552736]  [<ffffffff814ec6f3>] validate_xmit_skb_list+0x43/0x70
[   84.554278]  [<ffffffff81514d49>] sch_direct_xmit+0x169/0x1b0
[   84.555453]  [<ffffffff814ecdd0>] __dev_queue_xmit+0x3b0/0x670
[   84.556098]  [<ffffffff814ed0a0>] dev_queue_xmit+0x10/0x20
[   84.556624]  [<ffffffff8152edc7>] ip_finish_output2+0x1a7/0x370
[   84.557154]  [<ffffffff81552c00>] ? tcp_v4_rcv+0xbd0/0xdc0
[   84.557649]  [<ffffffff815309a8>] ip_finish_output+0x128/0x1c0
[   84.558179]  [<ffffffff8153146e>] ip_output+0x6e/0xf0
[   84.558634]  [<ffffffff814d2dbc>] ? __pg_skb_alloc+0x25c/0x500
[   84.559164]  [<ffffffff81530be5>] ip_local_out+0x35/0x40
[   84.559644]  [<ffffffff81530f10>] ip_queue_xmit+0x160/0x3b0
[   84.560165]  [<ffffffff81549b8e>] tcp_transmit_skb+0x48e/0x910
[   84.560705]  [<ffffffff8154a1ed>] tcp_write_xmit+0x1dd/0xf00
[   84.561221]  [<ffffffff8154b1a5>] __tcp_push_pending_frames+0x35/0xd0
[   84.561810]  [<ffffffff81538c7e>] tcp_push+0xee/0x110
[   84.562278]  [<ffffffffa0500780>] ss_tx_action+0x330/0x3a0 [tempesta_fw]
[   84.563062]  [<ffffffff810aa8b9>] ? try_to_wake_up+0x189/0x3b0
[   84.563942]  [<ffffffff814e89f4>] net_tx_action+0xa4/0x210
[   84.564453]  [<ffffffff81602552>] __do_softirq+0x112/0x2d7
[   84.565035]  [<ffffffff81085e03>] irq_exit+0xa3/0xb0
[   84.565487]  [<ffffffff81050543>] smp_call_function_single_interrupt+0x33/0x40
[   84.566184]  [<ffffffff81601bd2>] call_function_single_interrupt+0x82/0x90
[   84.567590]  <EOI> 
[   84.567785]  [<ffffffff810605f6>] ? native_safe_halt+0x6/0x10
[   84.568375]  [<ffffffff81037c70>] default_idle+0x20/0x110
[   84.569049]  [<ffffffff8103843f>] arch_cpu_idle+0xf/0x20
[   84.569784]  [<ffffffff810c4aca>] default_idle_call+0x2a/0x40
[   84.570725]  [<ffffffff810c4df1>] cpu_startup_entry+0x311/0x380
[   84.571410]  [<ffffffff81050f18>] start_secondary+0x158/0x1a0
[   84.571931] Code: f6 87 a3 00 00 00 20 75 22 8b 8f 94 00 00 00 85 c9 75 18 01 f2 01 b7 90 00 00 00 3b 97 dc 00 00 00 89 97 d8 00 00 00 77 04 f3 c3 <0f> 0b 55 48 c7 c1 d0 13 88 81 48 89 e5 48 8b 55 08 e8 8a eb ff 
[   84.575094] RIP  [<ffffffff814d77e0>] skb_put+0x40/0x60
[   84.575589]  RSP <ffff88007fd03878>
[   84.575946] ---[ end trace 4688883cc6ef63c0 ]---
[   84.576468] Kernel panic - not syncing: Fatal exception in interrupt
[   84.577228] Kernel Offset: disabled
[   84.577565] ---[ end Kernel panic - not syncing: Fatal exception in interrupt

Tempesta rev: 7672713c5b928a7d1421ce65d8df24d4d1dd9d38

keshonok commented 7 years ago

Please note that this crash occurred in Tempesta with code base at the state before #670 was merged into master.

vankoven commented 7 years ago

I use to have the issue during every other run, but since some moment everything is ok. I can't reproduce the issue for a long time. I have tried a lot of different kernels and TempestaFW revisions and configurations. The issue never happen to me again.

Nobody had the same issue and the issue happened only in my virtual machines. May be there was some side effect from the host machine, I'm not sure.

krizhanovsky commented 7 years ago

I got a different Oops on the same test scenario except that I ran

    # while :; do cat /proc/tempesta/perfstat; sleep 1; done

at host 1 through SSH session. Also I ran wrk with higher concurrency

    # ./wrk -t 8 -c 1024 -d 600s http://centos/

and used Apache HTTPD with MaxKeepAliveRequests 100. Interesting that my Oopes are at RX path while the original is at TX path... The kernel version is the latest one, just with https://github.com/tempesta-tech/linux-4.8.15-tfw/commit/0bf3cf888a6bc61da0919c5c989bec938bda6e4b patch.

    [ 1416.852466] BUG: unable to handle kernel NULL pointer dereference at 0000000000000008
    [ 1416.853101] IP: [<ffffffff815c4331>] tcp_clean_rtx_queue+0x161/0xe60
    [ 1416.853101] PGD 0 
    [ 1416.853101] Oops: 0002 [#1] SMP
    [ 1416.853101] Modules linked in: tfw_sched_rr(O) tfw_sched_http(O) tfw_sched_hash(O) tempesta_fw(O) tempesta_db(O) tempesta_tls(O) nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack ipt_REJECT nf_reject_ipv4 tun bridge stp llc ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter ip_vs nf_conntrack dm_mirror dm_region_hash dm_log dm_mod ghash_clmulni_intel xfs aesni_intel libcrc32c ppdev aes_x86_64 glue_helper lrw gf128mul ablk_helper cryptd input_leds led_class pcspkr parport_pc parport i2c_piix4 acpi_cpufreq i2c_core uinput ip_tables btrfs xor raid6_pq ata_generic pata_acpi crc32c_intel serio_raw e1000 ata_piix floppy ipv6 crc_ccitt autofs4
    [ 1416.853101] CPU: 1 PID: 16 Comm: ksoftirqd/1 Tainted: G           O    4.8.15-tfw #20
    [ 1416.853101] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.1-1.fc24 04/01/2014
    [ 1416.853101] task: ffff88005c909700 task.stack: ffff88005c910000
    [ 1416.853101] RIP: 0010:[<ffffffff815c4331>]  [<ffffffff815c4331>] tcp_clean_rtx_queue+0x161/0xe60
    [ 1416.853101] RSP: 0018:ffff88005c9138e8  EFLAGS: 00010206
    [ 1416.853101] RAX: 0000000000000000 RBX: 000000000000000c RCX: 0000000000000001
    [ 1416.853101] RDX: 0000000000000000 RSI: ffff880018e46a10 RDI: ffff88001817e680
    [ 1416.853101] RBP: ffff88005c913970 R08: 0000000000000000 R09: 0000000000000000
    [ 1416.853101] R10: ffff88005c913928 R11: ffff88001817e870 R12: 0000000000000002
    [ 1416.853101] R13: 0000000000000000 R14: ffff880018e46a00 R15: ffff88001817e680
    [ 1416.853101] FS:  0000000000000000(0000) GS:ffff88007fd00000(0000) knlGS:0000000000000000
    [ 1416.853101] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
    [ 1416.853101] CR2: 0000000000000008 CR3: 00000000199f5000 CR4: 00000000003406e0
    [ 1416.853101] Stack:
    [ 1416.853101]  ffff880000000001 0000000000000001 ffff880000000080 0000000000000000
    [ 1416.853101]  000000015c913990 ffff88005c9139a0 ffff88004b1765ca 0000000700000000
    [ 1416.853101]  ffff88005c9139a8 ffff88001817e870 ffff88005c909700 0000000000000246
    [ 1416.853101] Call Trace:
    [ 1416.853101]  [<ffffffff815c559e>] tcp_ack+0x56e/0x990
    [ 1416.853101]  [<ffffffff815c70bc>] tcp_rcv_established+0x19c/0x710
    [ 1416.853101]  [<ffffffff815d2bdc>] tcp_v4_do_rcv+0x10c/0x210
    [ 1416.853101]  [<ffffffff815d41bb>] tcp_v4_rcv+0xadb/0xcd0
    [ 1416.853101]  [<ffffffff815aa6b1>] ? ip_local_deliver_finish+0x41/0x3b0
    [ 1416.853101]  [<ffffffff815aa7a3>] ip_local_deliver_finish+0x133/0x3b0
    [ 1416.853101]  [<ffffffff815aa6b1>] ? ip_local_deliver_finish+0x41/0x3b0
    [ 1416.853101]  [<ffffffff815ab2d0>] ip_local_deliver+0xc0/0xd0
    [ 1416.853101]  [<ffffffff815aa670>] ? inet_del_offload+0x40/0x40
    [ 1416.853101]  [<ffffffff815aabcf>] ip_rcv_finish+0x1af/0x610
    [ 1416.853101]  [<ffffffff815ab5c9>] ip_rcv+0x2e9/0x410
    [ 1416.853101]  [<ffffffff815aaa20>] ? ip_local_deliver_finish+0x3b0/0x3b0
    [ 1416.853101]  [<ffffffff8155dd85>] __netif_receive_skb_core+0x3a5/0xb40
    [ 1416.853101]  [<ffffffff8155e660>] ? process_backlog+0xe0/0x230
    [ 1416.853101]  [<ffffffff8155e53d>] __netif_receive_skb+0x1d/0x60
    [ 1416.853101]  [<ffffffff8155e5f8>] process_backlog+0x78/0x230
    [ 1416.853101]  [<ffffffff8155e660>] ? process_backlog+0xe0/0x230
    [ 1416.853101]  [<ffffffff815607ce>] net_rx_action+0x14e/0x440
    [ 1416.853101]  [<ffffffff81653ca8>] __do_softirq+0xc8/0x473
    [ 1416.853101]  [<ffffffff810705cf>] run_ksoftirqd+0x1f/0x60
    [ 1416.853101]  [<ffffffff81091819>] smpboot_thread_fn+0x139/0x200
    [ 1416.853101]  [<ffffffff810916e0>] ? sort_range+0x30/0x30
    [ 1416.853101]  [<ffffffff8108dc48>] kthread+0xf8/0x110
    [ 1416.853101]  [<ffffffff8165153f>] ret_from_fork+0x1f/0x40
    [ 1416.853101]  [<ffffffff8108db50>] ? kthread_create_on_node+0x200/0x200
    [ 1416.853101] Code: 00 00 83 cb 04 84 c9 0f 84 7d 01 00 00 41 83 af 00 02 00 00 01 49 8b 16 49 8b 46 08 49 c7 06 00 00 00 00 49 c7 46 08 00 00 00 00 <48> 89 42 08 48 89 10 41 0f ba 6f 60 0e 49 8b 57 28 41 8b 86 f0 
    [ 1416.853101] RIP  [<ffffffff815c4331>] tcp_clean_rtx_queue+0x161/0xe60
    [ 1416.853101]  RSP <ffff88005c9138e8>
    [ 1416.853101] CR2: 0000000000000008
    [ 1416.853101] ---[ end trace 5683a364e3c2d102 ]---
    [ 1416.888020] BUG: unable to handle kernel paging request at ffff880100000127
    [ 1416.888020] IP: [<ffffffff8155da8a>] __netif_receive_skb_core+0xaa/0xb40
    [ 1416.888020] PGD 3bc7067 PUD 0 
    [ 1416.888020] Oops: 0000 [#2] SMP
    [ 1416.888020] Modules linked in: tfw_sched_rr(O) tfw_sched_http(O) tfw_sched_hash(O) tempesta_fw(O) tempesta_db(O) tempesta_tls(O) nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack ipt_REJECT nf_reject_ipv4 tun bridge stp llc ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter ip_vs nf_conntrack dm_mirror dm_region_hash dm_log dm_mod ghash_clmulni_intel xfs aesni_intel libcrc32c ppdev aes_x86_64 glue_helper lrw gf128mul ablk_helper cryptd input_leds led_class pcspkr parport_pc parport i2c_piix4 acpi_cpufreq i2c_core uinput ip_tables btrfs xor raid6_pq ata_generic pata_acpi crc32c_intel serio_raw e1000 ata_piix floppy ipv6 crc_ccitt autofs4
    [ 1416.888020] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G      D    O    4.8.15-tfw #20
    [ 1416.888020] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.1-1.fc24 04/01/2014
    [ 1416.888020] task: ffffffff81c0b540 task.stack: ffffffff81c00000
    [ 1416.888020] RIP: 0010:[<ffffffff8155da8a>]  [<ffffffff8155da8a>] __netif_receive_skb_core+0xaa/0xb40
    [ 1416.888020] RSP: 0018:ffff88007fc03db0  EFLAGS: 00010212
    [ 1416.888020] RAX: ffff8800ffffffff RBX: ffff88007fc19488 RCX: 0000000000000001
    [ 1416.888020] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff88007fd19438
    [ 1416.888020] RBP: ffff88007fc03e38 R08: 0000000000000000 R09: 0000000000000001
    [ 1416.888020] R10: 0000000000000000 R11: 0000000000000000 R12: ffff88007fd19438
    [ 1416.888020] R13: ffff8800ffffffff R14: 0000000000000001 R15: ffff88007fd19438
    [ 1416.888020] FS:  0000000000000000(0000) GS:ffff88007fc00000(0000) knlGS:0000000000000000
    [ 1416.888020] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
    [ 1416.888020] CR2: ffff880100000127 CR3: 000000001816b000 CR4: 00000000003406f0
    [ 1416.888020] Stack:
    [ 1416.888020]  0000000000000000 ffff88007fc03e40 0000000000000000 ffff88007fd19438
    [ 1416.888020]  0000000000000002 0000000000000000 0000000000000000 ffff88007fc03e58
    [ 1416.888020]  0000000000000046 0000000000000000 ffffffff8155e660 ffff880000000000
    [ 1416.888020] Call Trace:
    [ 1416.888020]  <IRQ> 
    [ 1416.888020]  [<ffffffff8155e660>] ? process_backlog+0xe0/0x230
    [ 1416.888020]  [<ffffffff8155e53d>] __netif_receive_skb+0x1d/0x60
    [ 1416.888020]  [<ffffffff8155e5f8>] process_backlog+0x78/0x230
    [ 1416.888020]  [<ffffffff8155e660>] ? process_backlog+0xe0/0x230
    [ 1416.888020]  [<ffffffff815607ce>] net_rx_action+0x14e/0x440
    [ 1416.888020]  [<ffffffff810f07a6>] ? ktime_get+0x96/0x120
    [ 1416.888020]  [<ffffffff81653ca8>] __do_softirq+0xc8/0x473
    [ 1416.888020]  [<ffffffff81070828>] irq_exit+0x98/0xb0
    [ 1416.888020]  [<ffffffff81653962>] smp_apic_timer_interrupt+0x42/0x50
    [ 1416.888020]  [<ffffffff81652c29>] apic_timer_interrupt+0x89/0x90
    [ 1416.888020]  <EOI> 
    [ 1416.888020]  [<ffffffff81028083>] ? default_idle+0x23/0x180
    [ 1416.888020]  [<ffffffff81028085>] ? default_idle+0x25/0x180
    [ 1416.888020]  [<ffffffff810289ef>] arch_cpu_idle+0xf/0x20
    [ 1416.888020]  [<ffffffff810b5563>] default_idle_call+0x33/0x50
    [ 1416.888020]  [<ffffffff810b57ba>] cpu_startup_entry+0x23a/0x420
    [ 1416.888020]  [<ffffffff81643c78>] rest_init+0x138/0x140
    [ 1416.888020]  [<ffffffff81643b45>] ? rest_init+0x5/0x140
    [ 1416.888020]  [<ffffffff81d34059>] start_kernel+0x45a/0x467
    [ 1416.888020]  [<ffffffff81d339ed>] ? set_init_arg+0x55/0x55
    [ 1416.888020]  [<ffffffff81d3358c>] x86_64_start_reservations+0x2a/0x2c
    [ 1416.888020]  [<ffffffff81d33678>] x86_64_start_kernel+0xea/0xed
    [ 1416.888020] Code: 20 66 41 89 84 24 d4 00 00 00 0f 84 43 05 00 00 66 41 2b 84 24 d6 00 00 00 41 be 01 00 00 00 66 41 89 84 24 98 00 00 00 4c 89 e8 <8b> 80 28 01 00 00 65 ff 05 c9 b8 ab 7e 41 89 84 24 b0 00 00 00 
    [ 1416.888020] RIP  [<ffffffff8155da8a>] __netif_receive_skb_core+0xaa/0xb40
    [ 1416.888020]  RSP <ffff88007fc03db0>
    [ 1416.888020] CR2: ffff880100000127
    [ 1416.888020] ---[ end trace 5683a364e3c2d103 ]---
    [ 1416.888020] Kernel panic - not syncing: Fatal exception in interrupt
    [ 1416.888020] Shutting down cpus with NMI
    [ 1416.888020] Kernel Offset: disabled
    [ 1416.888020] Rebooting in 5 seconds..[    0.000000] Linux version 4.8.15-tfw (root@localhost.localdomain) (gcc version 4.8.2 20140120 (Red Hat 4.8.2-16) (GCC) ) #20 SMP Tue May 9 21:53:48 MSK 2017
krizhanovsky commented 7 years ago

The issue is basically hard to reproduce. Linux 4.8.15-tfw works smoothly under 1h workload, however I got several Oopses when Tempesta is loaded, so I assume that original issue was caused by #697, while now the problem is in Tempesta's code.

I received following Oopses, which are different from the above and which basically mean dirty socket destruction.

    [ 1529.097102] [tempesta] Warning: Unable to find a back end server
    [ 1532.928424] ------------[ cut here ]------------
    [ 1532.929472] WARNING: CPU: 0 PID: 12503 at net/core/stream.c:204 sk_stream_kill_queues+0x11a/0x130
    [ 1532.931221] Modules linked in: tfw_sched_rr(O) tfw_sched_http(O) tfw_sched_hash(O) tempesta_fw(O) tempesta_db(O) tempesta_tls(O) nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack ipt_REJECT nf_reject_ipv4 tun bridge stp llc ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter ip_vs nf_conntrack dm_mirror dm_region_hash dm_log dm_mod xfs libcrc32c ppdev ghash_clmulni_intel aesni_intel aes_x86_64 glue_helper lrw gf128mul ablk_helper cryptd input_leds led_class pcspkr parport_pc parport acpi_cpufreq i2c_piix4 i2c_core uinput ip_tables btrfs xor raid6_pq ata_generic pata_acpi crc32c_intel serio_raw e1000 ata_piix floppy ipv6 crc_ccitt autofs4
    [ 1532.952559] CPU: 0 PID: 12503 Comm: httpd Tainted: G        W  O    4.8.15-tfw #21
    [ 1532.953106] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.1-1.fc24 04/01/2014
    [ 1532.954886]  0000000000000000 ffff88007fc03a88 ffffffff8135ecbe 0000000000000000
    [ 1532.954886]  0000000000000000 ffff88007fc03ac8 ffffffff810697c1 000000cc811dd0d7
    [ 1532.954886]  ffff880023e4b340 ffff880023e4b5c0 ffff88003ff165b0 0000000000000000
    [ 1532.954886] Call Trace:
    [ 1532.954886]  <IRQ>  [<ffffffff8135ecbe>] dump_stack+0x67/0x99
    [ 1532.954886]  [<ffffffff810697c1>] __warn+0xd1/0xf0
    [ 1532.954886]  [<ffffffff810698ad>] warn_slowpath_null+0x1d/0x20
    [ 1532.954886]  [<ffffffff815501aa>] sk_stream_kill_queues+0x11a/0x130
    [ 1532.954886]  [<ffffffff815b7dd7>] inet_csk_destroy_sock+0x57/0x170
    [ 1532.954886]  [<ffffffff815ba4e4>] tcp_done+0x64/0x90
    [ 1532.954886]  [<ffffffff815c8396>] tcp_rcv_state_process+0x956/0xe00
    [ 1532.954886]  [<ffffffff815d4189>] ? tcp_v4_rcv+0xa39/0xcd0
    [ 1532.954886]  [<ffffffff815d2bb9>] tcp_v4_do_rcv+0x79/0x210
    [ 1532.954886]  [<ffffffff815d422b>] tcp_v4_rcv+0xadb/0xcd0
    [ 1532.954886]  [<ffffffff815aa6b1>] ? ip_local_deliver_finish+0x41/0x3b0
    [ 1532.954886]  [<ffffffff815aa7a3>] ip_local_deliver_finish+0x133/0x3b0
    [ 1532.954886]  [<ffffffff815aa6b1>] ? ip_local_deliver_finish+0x41/0x3b0
    [ 1532.954886]  [<ffffffff815ab2d0>] ip_local_deliver+0xc0/0xd0
    [ 1532.954886]  [<ffffffff815aa670>] ? inet_del_offload+0x40/0x40
    [ 1532.954886]  [<ffffffff815aabcf>] ip_rcv_finish+0x1af/0x610
    [ 1532.954886]  [<ffffffff815ab5c9>] ip_rcv+0x2e9/0x410
    [ 1532.954886]  [<ffffffff815aaa20>] ? ip_local_deliver_finish+0x3b0/0x3b0
    [ 1532.954886]  [<ffffffff8155dd85>] __netif_receive_skb_core+0x3a5/0xb40
    [ 1532.954886]  [<ffffffff8155e660>] ? process_backlog+0xe0/0x230
    [ 1532.954886]  [<ffffffff8155e53d>] __netif_receive_skb+0x1d/0x60
    [ 1532.954886]  [<ffffffff8155e5f8>] process_backlog+0x78/0x230
    [ 1532.954886]  [<ffffffff8155e660>] ? process_backlog+0xe0/0x230
    [ 1532.954886]  [<ffffffff815607ce>] net_rx_action+0x14e/0x440
    [ 1532.954886]  [<ffffffff810f07a6>] ? ktime_get+0x96/0x120
    [ 1532.954886]  [<ffffffff81653d28>] __do_softirq+0xc8/0x473
    [ 1532.954886]  [<ffffffff81070828>] irq_exit+0x98/0xb0
    [ 1532.954886]  [<ffffffff816539e2>] smp_apic_timer_interrupt+0x42/0x50
    [ 1532.954886]  [<ffffffff81652ca9>] apic_timer_interrupt+0x89/0x90
    [ 1532.955046]  <EOI> 
    [ 1532.955046] ---[ end trace 6b58dfc0fb15f473 ]---
    [ 1532.955047] ------------[ cut here ]------------
    [ 1532.955050] WARNING: CPU: 0 PID: 12503 at net/core/stream.c:205 sk_stream_kill_queues+0x12d/0x130
    [ 1532.955074] Modules linked in: tfw_sched_rr(O) tfw_sched_http(O) tfw_sched_hash(O) tempesta_fw(O) tempesta_db(O) tempesta_tls(O) nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack ipt_REJECT nf_reject_ipv4 tun bridge stp llc ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter ip_vs nf_conntrack dm_mirror dm_region_hash dm_log dm_mod xfs libcrc32c ppdev ghash_clmulni_intel aesni_intel aes_x86_64 glue_helper lrw gf128mul ablk_helper cryptd input_leds led_class pcspkr parport_pc parport acpi_cpufreq i2c_piix4 i2c_core uinput ip_tables btrfs xor raid6_pq ata_generic pata_acpi crc32c_intel serio_raw e1000 ata_piix floppy ipv6 crc_ccitt autofs4
    [ 1532.955076] CPU: 0 PID: 12503 Comm: httpd Tainted: G        W  O    4.8.15-tfw #21
    [ 1532.955077] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.1-1.fc24 04/01/2014
    [ 1532.955079]  0000000000000000 ffff88007fc03a88 ffffffff8135ecbe 0000000000000000
    [ 1532.955081]  0000000000000000 ffff88007fc03ac8 ffffffff810697c1 000000cd811dd0d7
    [ 1532.955083]  ffff880023e4b340 ffff880023e4b5c0 ffff88003ff165b0 0000000000000000
    [ 1532.955083] Call Trace:
    [ 1532.955086]  <IRQ>  [<ffffffff8135ecbe>] dump_stack+0x67/0x99
    [ 1532.955088]  [<ffffffff810697c1>] __warn+0xd1/0xf0
    [ 1532.955090]  [<ffffffff810698ad>] warn_slowpath_null+0x1d/0x20
    [ 1532.955092]  [<ffffffff815501bd>] sk_stream_kill_queues+0x12d/0x130
    [ 1532.955094]  [<ffffffff815b7dd7>] inet_csk_destroy_sock+0x57/0x170
    [ 1532.955096]  [<ffffffff815ba4e4>] tcp_done+0x64/0x90
    [ 1532.955097]  [<ffffffff815c8396>] tcp_rcv_state_process+0x956/0xe00
    [ 1532.955099]  [<ffffffff815d4189>] ? tcp_v4_rcv+0xa39/0xcd0
    [ 1532.955101]  [<ffffffff815d2bb9>] tcp_v4_do_rcv+0x79/0x210
    [ 1532.955102]  [<ffffffff815d422b>] tcp_v4_rcv+0xadb/0xcd0
    [ 1532.955104]  [<ffffffff815aa6b1>] ? ip_local_deliver_finish+0x41/0x3b0
    [ 1532.955105]  [<ffffffff815aa7a3>] ip_local_deliver_finish+0x133/0x3b0
    [ 1532.955107]  [<ffffffff815aa6b1>] ? ip_local_deliver_finish+0x41/0x3b0
    [ 1532.955108]  [<ffffffff815ab2d0>] ip_local_deliver+0xc0/0xd0
    [ 1532.955110]  [<ffffffff815aa670>] ? inet_del_offload+0x40/0x40
    [ 1532.955111]  [<ffffffff815aabcf>] ip_rcv_finish+0x1af/0x610
    [ 1532.955112]  [<ffffffff815ab5c9>] ip_rcv+0x2e9/0x410
    [ 1532.955114]  [<ffffffff815aaa20>] ? ip_local_deliver_finish+0x3b0/0x3b0
    [ 1532.955116]  [<ffffffff8155dd85>] __netif_receive_skb_core+0x3a5/0xb40
    [ 1532.955118]  [<ffffffff8155e660>] ? process_backlog+0xe0/0x230
    [ 1532.955120]  [<ffffffff8155e53d>] __netif_receive_skb+0x1d/0x60
    [ 1532.955121]  [<ffffffff8155e5f8>] process_backlog+0x78/0x230
    [ 1532.955123]  [<ffffffff8155e660>] ? process_backlog+0xe0/0x230
    [ 1532.955125]  [<ffffffff815607ce>] net_rx_action+0x14e/0x440
    [ 1532.955127]  [<ffffffff810f07a6>] ? ktime_get+0x96/0x120
    [ 1532.955128]  [<ffffffff81653d28>] __do_softirq+0xc8/0x473
    [ 1532.955130]  [<ffffffff81070828>] irq_exit+0x98/0xb0
    [ 1532.955131]  [<ffffffff816539e2>] smp_apic_timer_interrupt+0x42/0x50
    [ 1532.955133]  [<ffffffff81652ca9>] apic_timer_interrupt+0x89/0x90
    [ 1532.955135]  <EOI> 
    [ 1532.955135] ---[ end trace 6b58dfc0fb15f474 ]---
    [ 1532.955138] ------------[ cut here ]------------
    [ 1532.955141] WARNING: CPU: 0 PID: 12503 at net/ipv4/af_inet.c:154 inet_sock_destruct+0x1c4/0x1e0
    [ 1532.955196] Modules linked in: tfw_sched_rr(O) tfw_sched_http(O) tfw_sched_hash(O) tempesta_fw(O) tempesta_db(O) tempesta_tls(O) nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack ipt_REJECT nf_reject_ipv4 tun bridge stp llc ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter ip_vs nf_conntrack dm_mirror dm_region_hash dm_log dm_mod xfs libcrc32c ppdev ghash_clmulni_intel aesni_intel aes_x86_64 glue_helper lrw gf128mul ablk_helper cryptd input_leds led_class pcspkr parport_pc parport acpi_cpufreq i2c_piix4 i2c_core uinput ip_tables btrfs xor raid6_pq ata_generic pata_acpi crc32c_intel serio_raw e1000 ata_piix floppy ipv6 crc_ccitt autofs4
    [ 1532.955198] CPU: 0 PID: 12503 Comm: httpd Tainted: G        W  O    4.8.15-tfw #21
    [ 1532.955199] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.1-1.fc24 04/01/2014
    [ 1532.955202]  0000000000000000 ffff88007fc03af0 ffffffff8135ecbe 0000000000000000
    [ 1532.955204]  0000000000000000 ffff88007fc03b30 ffffffff810697c1 0000009a00000246
    [ 1532.955206]  ffff880023e4b340 ffff880023e4b5c0 ffff880023e4b3c8 ffff88003ff1659c
    [ 1532.955207] Call Trace:
    [ 1532.955210]  <IRQ>  [<ffffffff8135ecbe>] dump_stack+0x67/0x99
    [ 1532.955212]  [<ffffffff810697c1>] __warn+0xd1/0xf0
    [ 1532.955215]  [<ffffffff810698ad>] warn_slowpath_null+0x1d/0x20
    [ 1532.955217]  [<ffffffff815ed5c4>] inet_sock_destruct+0x1c4/0x1e0
    [ 1532.955220]  [<ffffffff815411c6>] __sk_destruct+0x26/0x1a0
    [ 1532.955222]  [<ffffffff81544580>] sk_destruct+0x20/0x30
    [ 1532.955223]  [<ffffffff81544612>] __sk_free+0x82/0xa0
    [ 1532.955225]  [<ffffffff81544648>] sk_free+0x18/0x20
    [ 1532.955227]  [<ffffffff815cf6c3>] sock_put+0x13/0x20
    [ 1532.955229]  [<ffffffff815d4262>] tcp_v4_rcv+0xb12/0xcd0
    [ 1532.955232]  [<ffffffff815aa6b1>] ? ip_local_deliver_finish+0x41/0x3b0
    [ 1532.955234]  [<ffffffff815aa7a3>] ip_local_deliver_finish+0x133/0x3b0
    [ 1532.955236]  [<ffffffff815aa6b1>] ? ip_local_deliver_finish+0x41/0x3b0
    [ 1532.955238]  [<ffffffff815ab2d0>] ip_local_deliver+0xc0/0xd0
    [ 1532.955239]  [<ffffffff815aa670>] ? inet_del_offload+0x40/0x40
    [ 1532.955241]  [<ffffffff815aabcf>] ip_rcv_finish+0x1af/0x610
    [ 1532.955242]  [<ffffffff815ab5c9>] ip_rcv+0x2e9/0x410
    [ 1532.955243]  [<ffffffff815aaa20>] ? ip_local_deliver_finish+0x3b0/0x3b0
    [ 1532.955245]  [<ffffffff8155dd85>] __netif_receive_skb_core+0x3a5/0xb40
    [ 1532.955247]  [<ffffffff8155e660>] ? process_backlog+0xe0/0x230
    [ 1532.955249]  [<ffffffff8155e53d>] __netif_receive_skb+0x1d/0x60
    [ 1532.955251]  [<ffffffff8155e5f8>] process_backlog+0x78/0x230
    [ 1532.955252]  [<ffffffff8155e660>] ? process_backlog+0xe0/0x230
    [ 1532.955254]  [<ffffffff815607ce>] net_rx_action+0x14e/0x440
    [ 1532.955256]  [<ffffffff810f07a6>] ? ktime_get+0x96/0x120
    [ 1532.955258]  [<ffffffff81653d28>] __do_softirq+0xc8/0x473
    [ 1532.955259]  [<ffffffff81070828>] irq_exit+0x98/0xb0
    [ 1532.955261]  [<ffffffff816539e2>] smp_apic_timer_interrupt+0x42/0x50
    [ 1532.955262]  [<ffffffff81652ca9>] apic_timer_interrupt+0x89/0x90
    [ 1532.955264]  <EOI> 
    [ 1532.955264] ---[ end trace 6b58dfc0fb15f475 ]---
    [ 1532.955265] ------------[ cut here ]------------
    [ 1532.955267] WARNING: CPU: 0 PID: 12503 at net/ipv4/af_inet.c:155 inet_sock_destruct+0x1da/0x1e0
    [ 1532.955284] Modules linked in: tfw_sched_rr(O) tfw_sched_http(O) tfw_sched_hash(O) tempesta_fw(O) tempesta_db(O) tempesta_tls(O) nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack ipt_REJECT nf_reject_ipv4 tun bridge stp llc ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter ip_vs nf_conntrack dm_mirror dm_region_hash dm_log dm_mod xfs libcrc32c ppdev ghash_clmulni_intel aesni_intel aes_x86_64 glue_helper lrw gf128mul ablk_helper cryptd input_leds led_class pcspkr parport_pc parport acpi_cpufreq i2c_piix4 i2c_core uinput ip_tables btrfs xor raid6_pq ata_generic pata_acpi crc32c_intel serio_raw e1000 ata_piix floppy ipv6 crc_ccitt autofs4
    [ 1532.955285] CPU: 0 PID: 12503 Comm: httpd Tainted: G        W  O    4.8.15-tfw #21
    [ 1532.955285] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.1-1.fc24 04/01/2014
    [ 1532.955287]  0000000000000000 ffff88007fc03af0 ffffffff8135ecbe 0000000000000000
    [ 1532.955288]  0000000000000000 ffff88007fc03b30 ffffffff810697c1 0000009b00000246
    [ 1532.955290]  ffff880023e4b340 ffff880023e4b5c0 ffff880023e4b3c8 ffff88003ff1659c
    [ 1532.955290] Call Trace:
    [ 1532.955292]  <IRQ>  [<ffffffff8135ecbe>] dump_stack+0x67/0x99
    [ 1532.955295]  [<ffffffff810697c1>] __warn+0xd1/0xf0
    [ 1532.955296]  [<ffffffff810698ad>] warn_slowpath_null+0x1d/0x20
    [ 1532.955327]  [<ffffffff815ed5da>] inet_sock_destruct+0x1da/0x1e0
    [ 1532.955329]  [<ffffffff815411c6>] __sk_destruct+0x26/0x1a0
    [ 1532.955330]  [<ffffffff81544580>] sk_destruct+0x20/0x30
    [ 1532.955331]  [<ffffffff81544612>] __sk_free+0x82/0xa0
    [ 1532.955332]  [<ffffffff81544648>] sk_free+0x18/0x20
    [ 1532.955334]  [<ffffffff815cf6c3>] sock_put+0x13/0x20
    [ 1532.955335]  [<ffffffff815d4262>] tcp_v4_rcv+0xb12/0xcd0
    [ 1532.955337]  [<ffffffff815aa6b1>] ? ip_local_deliver_finish+0x41/0x3b0
    [ 1532.955338]  [<ffffffff815aa7a3>] ip_local_deliver_finish+0x133/0x3b0
    [ 1532.955339]  [<ffffffff815aa6b1>] ? ip_local_deliver_finish+0x41/0x3b0
    [ 1532.955341]  [<ffffffff815ab2d0>] ip_local_deliver+0xc0/0xd0
    [ 1532.955342]  [<ffffffff815aa670>] ? inet_del_offload+0x40/0x40
    [ 1532.955344]  [<ffffffff815aabcf>] ip_rcv_finish+0x1af/0x610
    [ 1532.955345]  [<ffffffff815ab5c9>] ip_rcv+0x2e9/0x410
    [ 1532.955347]  [<ffffffff815aaa20>] ? ip_local_deliver_finish+0x3b0/0x3b0
    [ 1532.955348]  [<ffffffff8155dd85>] __netif_receive_skb_core+0x3a5/0xb40
    [ 1532.955350]  [<ffffffff8155e660>] ? process_backlog+0xe0/0x230
    [ 1532.955352]  [<ffffffff8155e53d>] __netif_receive_skb+0x1d/0x60
    [ 1532.955354]  [<ffffffff8155e5f8>] process_backlog+0x78/0x230
    [ 1532.955355]  [<ffffffff8155e660>] ? process_backlog+0xe0/0x230
    [ 1532.955357]  [<ffffffff815607ce>] net_rx_action+0x14e/0x440
    [ 1532.955359]  [<ffffffff810f07a6>] ? ktime_get+0x96/0x120
    [ 1532.955361]  [<ffffffff81653d28>] __do_softirq+0xc8/0x473
    [ 1532.955362]  [<ffffffff81070828>] irq_exit+0x98/0xb0
    [ 1532.955364]  [<ffffffff816539e2>] smp_apic_timer_interrupt+0x42/0x50
    [ 1532.955365]  [<ffffffff81652ca9>] apic_timer_interrupt+0x89/0x90
    [ 1532.955367]  <EOI> 
    [ 1532.955367] ---[ end trace 6b58dfc0fb15f476 ]---

Also there is deplock issue on socket work queue overrun (UPD this one is fixed in https://github.com/tempesta-tech/tempesta/commit/649eca95420319029c6aa3d009f5d5c73d13e2e6):

    [ 1016.627697] [tempesta] Warning: Socket work queue overrun: [0]
    [ 1016.629900] [sync_sockets] Warning: Cannot schedule socket ffff880027d3e680 for transmission
    [ 1016.632491] [tempesta] Warning: Socket work queue overrun: [0]
    [ 1016.634287] [sync_sockets] Warning: Cannot schedule socket ffff880027d3e680 for transmission
    [ 1016.637260] [tempesta] Warning: Socket work queue overrun: [0]
    [ 1016.639270] [sync_sockets] Warning: Cannot schedule socket ffff880027d3e680 for transmission
    [ 1016.642197] [tempesta] Warning: Socket work queue overrun: [0]
    [ 1016.644073] [sync_sockets] Warning: Cannot schedule socket ffff880027d3e680 for transmission
    [ 1016.658536] [tempesta] Warning: Socket work queue overrun: [0]
    [ 1016.659869] [sync_sockets] Warning: Cannot schedule socket ffff880027d3e680 for transmission
    [ 1016.662243] 
    [ 1016.663051] ======================================================
    [ 1016.663051] [ INFO: possible circular locking dependency detected ]
    [ 1016.663051] 4.8.15-tfw #21 Tainted: G        W  O   
    [ 1016.663051] -------------------------------------------------------
    [ 1016.663051] ksoftirqd/0/3 is trying to acquire lock:
    [ 1016.663051]  (slock-AF_INET){+.-...}, at: [<ffffffffa06a2828>] __ss_close+0x98/0x120 [tempesta_fw]
    [ 1016.663051] 
    [ 1016.663051] but task is already holding lock:
    [ 1016.663051]  (&(&cli_conn->ret_qlock)->rlock){+.-...}, at: [<ffffffffa068d2ca>] tfw_http_resp_fwd+0xea/0x2b0 [tempesta_fw]
    [ 1016.663051] 
    [ 1016.663051] which lock already depends on the new lock.
    [ 1016.663051] 
    [ 1016.663051] 
    [ 1016.663051] the existing dependency chain (in reverse order) is:
    [ 1016.663051] 
    -> #2 (&(&cli_conn->ret_qlock)->rlock){+.-...}:
    [ 1016.663051]        [<ffffffff810c1ebe>] lock_acquire+0xbe/0x1f0
    [ 1016.663051]        [<ffffffff81650a08>] _raw_spin_lock+0x38/0x50
    [ 1016.663051]        [<ffffffffa068d2ca>] tfw_http_resp_fwd+0xea/0x2b0 [tempesta_fw]
    [ 1016.663051]        [<ffffffffa068d6bd>] tfw_http_resp_cache_cb+0x5d/0x80 [tempesta_fw]
    [ 1016.663051]        [<ffffffffa0688157>] tfw_cache_process+0x117/0x2a0 [tempesta_fw]
    [ 1016.663051]        [<ffffffffa068de8d>] tfw_http_resp_cache+0x7d/0xc0 [tempesta_fw]
    [ 1016.663051]        [<ffffffffa068e2bc>] tfw_http_msg_process+0x1fc/0x750 [tempesta_fw]
    [ 1016.663051]        [<ffffffffa068b61c>] __gfsm_fsm_exec+0x5c/0x90 [tempesta_fw]
    [ 1016.663051]        [<ffffffffa068b844>] tfw_gfsm_dispatch+0x14/0x20 [tempesta_fw]
    [ 1016.663051]        [<ffffffffa068ae3d>] tfw_connection_recv+0x1d/0x20 [tempesta_fw]
    [ 1016.663051]        [<ffffffffa06a251c>] ss_tcp_process_data+0x17c/0x360 [tempesta_fw]
    [ 1016.663051]        [<ffffffffa06a2750>] ss_tcp_data_ready+0x50/0x90 [tempesta_fw]
    [ 1016.663051]        [<ffffffff815c6916>] tcp_data_queue+0x6e6/0xd60
    [ 1016.663051]        [<ffffffff815c716e>] tcp_rcv_established+0x1de/0x710
    [ 1016.663051]        [<ffffffff815d2c4c>] tcp_v4_do_rcv+0x10c/0x210
    [ 1016.663051]        [<ffffffff815d422b>] tcp_v4_rcv+0xadb/0xcd0
    [ 1016.663051]        [<ffffffff815aa7a3>] ip_local_deliver_finish+0x133/0x3b0
    [ 1016.663051]        [<ffffffff815ab2d0>] ip_local_deliver+0xc0/0xd0
    [ 1016.663051]        [<ffffffff815aabcf>] ip_rcv_finish+0x1af/0x610
    [ 1016.663051]        [<ffffffff815ab5c9>] ip_rcv+0x2e9/0x410
    [ 1016.663051]        [<ffffffff8155dd85>] __netif_receive_skb_core+0x3a5/0xb40
    [ 1016.663051]        [<ffffffff8155e53d>] __netif_receive_skb+0x1d/0x60
    [ 1016.663051]        [<ffffffff8155e5f8>] process_backlog+0x78/0x230
    [ 1016.663051]        [<ffffffff815607ce>] net_rx_action+0x14e/0x440
    [ 1016.663051]        [<ffffffff81653d28>] __do_softirq+0xc8/0x473
    [ 1016.663051]        [<ffffffff8102066e>] __tempesta_do_softirq_fpusafe+0xe/0x10
    [ 1016.663051]        [<ffffffff8165226c>] do_softirq_own_stack+0x1c/0x30
    [ 1016.663051]        [<ffffffff8107065e>] do_softirq+0x4e/0x60
    [ 1016.663051]        [<ffffffff81070718>] __local_bh_enable_ip+0xa8/0xb0
    [ 1016.663051]        [<ffffffff815aef00>] ip_finish_output2+0x240/0x5c0
    [ 1016.663051]        [<ffffffff815afd46>] ip_finish_output+0x1c6/0x320
    [ 1016.663051]        [<ffffffff815afea9>] NF_HOOK_COND.part.33.constprop.47+0x9/0x10
    [ 1016.663051]        [<ffffffff815b1563>] ip_output+0xc3/0x110
    [ 1016.663051]        [<ffffffff815b0a19>] ip_local_out+0x39/0x70
    [ 1016.663051]        [<ffffffff815b0e4b>] ip_queue_xmit+0x1eb/0x5a0
    [ 1016.663051]        [<ffffffff815caa64>] tcp_transmit_skb+0x4a4/0x8b0
    [ 1016.663051]        [<ffffffff815cafd1>] tcp_write_xmit+0x161/0xef0
    [ 1016.663051]        [<ffffffff815cc041>] __tcp_push_pending_frames+0x31/0xd0
    [ 1016.663051]        [<ffffffff815bd16b>] do_tcp_setsockopt.isra.37+0x6ab/0x860
    [ 1016.663051]        [<ffffffff815bd34c>] tcp_setsockopt+0x2c/0x30
    [ 1016.663051]        [<ffffffff815401a4>] sock_common_setsockopt+0x14/0x20
    [ 1016.663051]        [<ffffffff8153ef11>] SyS_setsockopt+0x71/0xc0
    [ 1016.663051]        [<ffffffff810029c8>] do_syscall_64+0x58/0x110
    [ 1016.663051]        [<ffffffff8165145a>] return_from_SYSCALL_64+0x0/0x7a
    [ 1016.663051] 
    -> #1 (&(&cli_conn->seq_qlock)->rlock){+.-...}:
    [ 1016.663051]        [<ffffffff810c1ebe>] lock_acquire+0xbe/0x1f0
    [ 1016.663051]        [<ffffffff81650a08>] _raw_spin_lock+0x38/0x50
    [ 1016.663051]        [<ffffffffa068e4c0>] tfw_http_msg_process+0x400/0x750 [tempesta_fw]
    [ 1016.663051]        [<ffffffffa068b61c>] __gfsm_fsm_exec+0x5c/0x90 [tempesta_fw]
    [ 1016.663051]        [<ffffffffa068b844>] tfw_gfsm_dispatch+0x14/0x20 [tempesta_fw]
    [ 1016.663051]        [<ffffffffa068ae3d>] tfw_connection_recv+0x1d/0x20 [tempesta_fw]
    [ 1016.663051]        [<ffffffffa06a251c>] ss_tcp_process_data+0x17c/0x360 [tempesta_fw]
    [ 1016.663051]        [<ffffffffa06a2750>] ss_tcp_data_ready+0x50/0x90 [tempesta_fw]
    [ 1016.663051]        [<ffffffff815c6916>] tcp_data_queue+0x6e6/0xd60
    [ 1016.663051]        [<ffffffff815c7d6d>] tcp_rcv_state_process+0x32d/0xe00
    [ 1016.663051]        [<ffffffff815d57ae>] tcp_child_process+0x9e/0x280
    [ 1016.663051]        [<ffffffff815d3f3f>] tcp_v4_rcv+0x7ef/0xcd0
    [ 1016.663051]        [<ffffffff815aa7a3>] ip_local_deliver_finish+0x133/0x3b0
    [ 1016.663051]        [<ffffffff815ab2d0>] ip_local_deliver+0xc0/0xd0
    [ 1016.663051]        [<ffffffff815aabcf>] ip_rcv_finish+0x1af/0x610
    [ 1016.663051]        [<ffffffff815ab5c9>] ip_rcv+0x2e9/0x410
    [ 1016.663051]        [<ffffffff8155dd85>] __netif_receive_skb_core+0x3a5/0xb40
    [ 1016.663051]        [<ffffffff8155e53d>] __netif_receive_skb+0x1d/0x60
    [ 1016.663051]        [<ffffffff8155e5f8>] process_backlog+0x78/0x230
    [ 1016.663051]        [<ffffffff815607ce>] net_rx_action+0x14e/0x440
    [ 1016.663051]        [<ffffffff81653d28>] __do_softirq+0xc8/0x473
    [ 1016.663051]        [<ffffffff810705cf>] run_ksoftirqd+0x1f/0x60
    [ 1016.663051]        [<ffffffff81091819>] smpboot_thread_fn+0x139/0x200
    [ 1016.663051]        [<ffffffff8108dc48>] kthread+0xf8/0x110
    [ 1016.663051]        [<ffffffff816515bf>] ret_from_fork+0x1f/0x40
    [ 1016.663051] 
    -> #0 (slock-AF_INET){+.-...}:
    [ 1016.663051]        [<ffffffff810c1a8c>] __lock_acquire+0x15ec/0x1620
    [ 1016.663051]        [<ffffffff810c1ebe>] lock_acquire+0xbe/0x1f0
    [ 1016.663051]        [<ffffffff81650a08>] _raw_spin_lock+0x38/0x50
    [ 1016.663051]        [<ffffffffa06a2828>] __ss_close+0x98/0x120 [tempesta_fw]
    [ 1016.663051]        [<ffffffffa068d373>] tfw_http_resp_fwd+0x193/0x2b0 [tempesta_fw]
    [ 1016.663051]        [<ffffffffa068d540>] tfw_http_send_resp.isra.27.constprop.32+0xb0/0x100 [tempesta_fw]
    [ 1016.663051]        [<ffffffffa068d65b>] tfw_http_send_500.isra.28+0xcb/0xd0 [tempesta_fw]
    [ 1016.663051]        [<ffffffffa068da1f>] tfw_http_req_zap_error+0xcf/0xf0 [tempesta_fw]
    [ 1016.663051]        [<ffffffffa068dc2a>] tfw_http_popreq.isra.29+0x1ea/0x310 [tempesta_fw]
    [ 1016.663051]        [<ffffffffa068de61>] tfw_http_resp_cache+0x51/0xc0 [tempesta_fw]
    [ 1016.663051]        [<ffffffffa068e2bc>] tfw_http_msg_process+0x1fc/0x750 [tempesta_fw]
    [ 1016.663051]        [<ffffffffa068b61c>] __gfsm_fsm_exec+0x5c/0x90 [tempesta_fw]
    [ 1016.663051]        [<ffffffffa068b844>] tfw_gfsm_dispatch+0x14/0x20 [tempesta_fw]
    [ 1016.663051]        [<ffffffffa068ae3d>] tfw_connection_recv+0x1d/0x20 [tempesta_fw]
    [ 1016.663051]        [<ffffffffa06a251c>] ss_tcp_process_data+0x17c/0x360 [tempesta_fw]
    [ 1016.663051]        [<ffffffffa06a2750>] ss_tcp_data_ready+0x50/0x90 [tempesta_fw]
    [ 1016.663051]        [<ffffffff815c6916>] tcp_data_queue+0x6e6/0xd60
    [ 1016.663051]        [<ffffffff815c716e>] tcp_rcv_established+0x1de/0x710
    [ 1016.663051]        [<ffffffff815d2c4c>] tcp_v4_do_rcv+0x10c/0x210
    [ 1016.663051]        [<ffffffff815d422b>] tcp_v4_rcv+0xadb/0xcd0
    [ 1016.663051]        [<ffffffff815aa7a3>] ip_local_deliver_finish+0x133/0x3b0
    [ 1016.663051]        [<ffffffff815ab2d0>] ip_local_deliver+0xc0/0xd0
    [ 1016.663051]        [<ffffffff815aabcf>] ip_rcv_finish+0x1af/0x610
    [ 1016.663051]        [<ffffffff815ab5c9>] ip_rcv+0x2e9/0x410
    [ 1016.663051]        [<ffffffff8155dd85>] __netif_receive_skb_core+0x3a5/0xb40
    [ 1016.663051]        [<ffffffff8155e53d>] __netif_receive_skb+0x1d/0x60
    [ 1016.663051]        [<ffffffff8155e5f8>] process_backlog+0x78/0x230
    [ 1016.663051]        [<ffffffff815607ce>] net_rx_action+0x14e/0x440
    [ 1016.663051]        [<ffffffff81653d28>] __do_softirq+0xc8/0x473
    [ 1016.663051]        [<ffffffff810705cf>] run_ksoftirqd+0x1f/0x60
    [ 1016.663051]        [<ffffffff81091819>] smpboot_thread_fn+0x139/0x200
    [ 1016.663051]        [<ffffffff8108dc48>] kthread+0xf8/0x110
    [ 1016.663051]        [<ffffffff816515bf>] ret_from_fork+0x1f/0x40
    [ 1016.663051] 
    [ 1016.663051] other info that might help us debug this:
    [ 1016.663051] 
    [ 1016.663051] Chain exists of:
      slock-AF_INET --> &(&cli_conn->seq_qlock)->rlock --> &(&cli_conn->ret_qlock)->rlock

    [ 1016.663051]  Possible unsafe locking scenario:
    [ 1016.663051] 
    [ 1016.663051]        CPU0                    CPU1
    [ 1016.663051]        ----                    ----
    [ 1016.663051]   lock(&(&cli_conn->ret_qlock)->rlock);
    [ 1016.663051]                                lock(&(&cli_conn->seq_qlock)->rlock);
    [ 1016.663051]                                lock(&(&cli_conn->ret_qlock)->rlock);
    [ 1016.663051]   lock(slock-AF_INET);
    [ 1016.663051] 
    [ 1016.663051]  *** DEADLOCK ***
    [ 1016.663051] 
    [ 1016.663051] 4 locks held by ksoftirqd/0/3:
    [ 1016.663051]  #0:  (rcu_read_lock){......}, at: [<ffffffff8155e660>] process_backlog+0xe0/0x230
    [ 1016.663051]  #1:  (rcu_read_lock){......}, at: [<ffffffff815aa6b1>] ip_local_deliver_finish+0x41/0x3b0
    [ 1016.663051]  #2:  (slock-AF_INET/1){+.-...}, at: [<ffffffff815d4189>] tcp_v4_rcv+0xa39/0xcd0
    [ 1016.663051]  #3:  (&(&cli_conn->ret_qlock)->rlock){+.-...}, at: [<ffffffffa068d2ca>] tfw_http_resp_fwd+0xea/0x2b0 [tempesta_fw]
    [ 1016.663051] 
    [ 1016.663051] stack backtrace:
    [ 1016.663051] CPU: 0 PID: 3 Comm: ksoftirqd/0 Tainted: G        W  O    4.8.15-tfw #21
    [ 1016.663051] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.1-1.fc24 04/01/2014
    [ 1016.663051]  0000000000000000 ffff88005c897410 ffffffff8135ecbe ffffffff82dc7910
    [ 1016.663051]  ffffffff82e05b00 ffff88005c897450 ffffffff81178761 ffff88005c897490
    [ 1016.663051]  ffff88005c8336c0 0000000000000003 0000000000000004 ffff88005c832e00
    [ 1016.663051] Call Trace:
    [ 1016.663051]  [<ffffffff8135ecbe>] dump_stack+0x67/0x99
    [ 1016.663051]  [<ffffffff81178761>] print_circular_bug+0x200/0x20e
    [ 1016.663051]  [<ffffffff810c1a8c>] __lock_acquire+0x15ec/0x1620
    [ 1016.663051]  [<ffffffff810c1ebe>] lock_acquire+0xbe/0x1f0
    [ 1016.663051]  [<ffffffffa06a2828>] ? __ss_close+0x98/0x120 [tempesta_fw]
    [ 1016.663051]  [<ffffffff81650a08>] _raw_spin_lock+0x38/0x50
    [ 1016.663051]  [<ffffffffa06a2828>] ? __ss_close+0x98/0x120 [tempesta_fw]
    [ 1016.663051]  [<ffffffffa06a2828>] __ss_close+0x98/0x120 [tempesta_fw]
    [ 1016.663051]  [<ffffffffa068d373>] tfw_http_resp_fwd+0x193/0x2b0 [tempesta_fw]
    [ 1016.663051]  [<ffffffffa068d540>] tfw_http_send_resp.isra.27.constprop.32+0xb0/0x100 [tempesta_fw]
    [ 1016.663051]  [<ffffffffa068d65b>] tfw_http_send_500.isra.28+0xcb/0xd0 [tempesta_fw]
    [ 1016.663051]  [<ffffffffa068da1f>] tfw_http_req_zap_error+0xcf/0xf0 [tempesta_fw]
    [ 1016.663051]  [<ffffffffa068dc2a>] tfw_http_popreq.isra.29+0x1ea/0x310 [tempesta_fw]
    [ 1016.663051]  [<ffffffff810c00bd>] ? trace_hardirqs_on_caller+0xad/0x1c0
    [ 1016.663051]  [<ffffffff810f0ce4>] ? __getnstimeofday64+0x94/0x140
    [ 1016.663051]  [<ffffffffa068de61>] tfw_http_resp_cache+0x51/0xc0 [tempesta_fw]
    [ 1016.663051]  [<ffffffffa068e2bc>] tfw_http_msg_process+0x1fc/0x750 [tempesta_fw]
    [ 1016.663051]  [<ffffffff8154ab4d>] ? __alloc_skb+0x4d/0x2a0
    [ 1016.663051]  [<ffffffffa068b61c>] __gfsm_fsm_exec+0x5c/0x90 [tempesta_fw]
    [ 1016.663051]  [<ffffffffa068b844>] tfw_gfsm_dispatch+0x14/0x20 [tempesta_fw]
    [ 1016.663051]  [<ffffffffa068ae3d>] tfw_connection_recv+0x1d/0x20 [tempesta_fw]
    [ 1016.663051]  [<ffffffffa06a251c>] ss_tcp_process_data+0x17c/0x360 [tempesta_fw]
    [ 1016.663051]  [<ffffffff810be849>] ? __lock_is_held+0x49/0x70
    [ 1016.663051]  [<ffffffffa06a2750>] ss_tcp_data_ready+0x50/0x90 [tempesta_fw]
    [ 1016.663051]  [<ffffffff815c6916>] tcp_data_queue+0x6e6/0xd60
    [ 1016.663051]  [<ffffffff815c716e>] tcp_rcv_established+0x1de/0x710
    [ 1016.663051]  [<ffffffff815d2c4c>] tcp_v4_do_rcv+0x10c/0x210
    [ 1016.663051]  [<ffffffff815d422b>] tcp_v4_rcv+0xadb/0xcd0
    [ 1016.663051]  [<ffffffff815aa7a3>] ip_local_deliver_finish+0x133/0x3b0
    [ 1016.663051]  [<ffffffff815aa6b1>] ? ip_local_deliver_finish+0x41/0x3b0
    [ 1016.663051]  [<ffffffff815ab2d0>] ip_local_deliver+0xc0/0xd0
    [ 1016.663051]  [<ffffffff815aa670>] ? inet_del_offload+0x40/0x40
    [ 1016.663051]  [<ffffffff815aabcf>] ip_rcv_finish+0x1af/0x610
    [ 1016.663051]  [<ffffffff815ab5c9>] ip_rcv+0x2e9/0x410
    [ 1016.663051]  [<ffffffff815aaa20>] ? ip_local_deliver_finish+0x3b0/0x3b0
    [ 1016.663051]  [<ffffffff8155dd85>] __netif_receive_skb_core+0x3a5/0xb40
    [ 1016.663051]  [<ffffffff8155e660>] ? process_backlog+0xe0/0x230
    [ 1016.663051]  [<ffffffff8155e53d>] __netif_receive_skb+0x1d/0x60
    [ 1016.663051]  [<ffffffff8155e5f8>] process_backlog+0x78/0x230
    [ 1016.663051]  [<ffffffff8155e660>] ? process_backlog+0xe0/0x230
    [ 1016.663051]  [<ffffffff815607ce>] net_rx_action+0x14e/0x440
    [ 1016.663051]  [<ffffffff81653d28>] __do_softirq+0xc8/0x473
    [ 1016.663051]  [<ffffffff810705cf>] run_ksoftirqd+0x1f/0x60
    [ 1016.663051]  [<ffffffff81091819>] smpboot_thread_fn+0x139/0x200
    [ 1016.663051]  [<ffffffff810916e0>] ? sort_range+0x30/0x30
    [ 1016.663051]  [<ffffffff8108dc48>] kthread+0xf8/0x110
    [ 1016.663051]  [<ffffffff816515bf>] ret_from_fork+0x1f/0x40
    [ 1016.663051]  [<ffffffff8108db50>] ? kthread_create_on_node+0x200/0x200
krizhanovsky commented 7 years ago

UPD Fixed in https://github.com/tempesta-tech/tempesta/commit/ed6ae06d307be4953d24ccd25fb535c3d595b2bc

I got one more oops for restarting Tempesta under heavy wrk workload. There is a deadliock on bh_lock_sock(sk) called from ss_close_sync() [seems] from __tfw_http_resp_fwd().

    [  685.386824] perf: interrupt took too long (21406 > 21233), lowering kernel.perf_event_max_sample_rate to 9000
    [  712.059040] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 23s! [sysctl:9968]
    [  712.059040] Modules linked in: tfw_sched_rr(O) tfw_sched_http(O) tfw_sched_hash(O) tempesta_fw(O) tempesta_db(O) tempesta_tls(O) nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack ipt_REJECT nf_reject_ipv4 tun bridge stp llc ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter ip_vs nf_conntrack dm_mirror dm_region_hash dm_log dm_mod xfs ppdev libcrc32c ghash_clmulni_intel aesni_intel aes_x86_64 glue_helper lrw gf128mul ablk_helper cryptd input_leds led_class pcspkr i2c_piix4 i2c_core parport_pc parport acpi_cpufreq uinput ip_tables btrfs xor raid6_pq ata_generic pata_acpi crc32c_intel serio_raw e1000 ata_piix floppy ipv6 crc_ccitt autofs4
    [  712.059040] irq event stamp: 0
    [  712.059040] hardirqs last  enabled at (0): [<          (null)>]           (null)
    [  712.059040] hardirqs last disabled at (0): [<ffffffff81066ebc>] copy_process.part.40+0x5bc/0x1d40
    [  712.059040] softirqs last  enabled at (0): [<ffffffff81066ebc>] copy_process.part.40+0x5bc/0x1d40
    [  712.059040] softirqs last disabled at (0): [<          (null)>]           (null)
    [  712.059040] CPU: 0 PID: 9968 Comm: sysctl Tainted: G           O    4.8.15-tfw #21
    [  712.059040] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.1-1.fc24 04/01/2014
    [  712.059040] task: ffff8800278c0000 task.stack: ffff88002810c000
    [  712.059040] RIP: 0010:[<ffffffff8136c71c>]  [<ffffffff8136c71c>] delay_tsc+0x1c/0x70
    [  712.059040] RSP: 0018:ffff88007fc03738  EFLAGS: 00000202
    [  712.059040] RAX: 000000003dd149d2 RBX: ffff88002a0b1f48 RCX: 000001b43dd1497c
    [  712.059040] RDX: 00000000000001b4 RSI: 0000000000000000 RDI: 0000000000000001
    [  712.059040] RBP: ffff88007fc03738 R08: 0000000000000001 R09: 0000000000000000
    [  712.059040] R10: ffff8800278c0000 R11: 0000000000000000 R12: 000000009ce50de8
    [  712.059040] R13: 00000000380146e2 R14: 0000000000000001 R15: ffff88007fc03808
    [  712.059040] FS:  00007f85a1aad840(0000) GS:ffff88007fc00000(0000) knlGS:0000000000000000
    [  712.059040] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
    [  712.059040] CR2: 00007f85a1af6000 CR3: 0000000027179000 CR4: 00000000003406f0
    [  712.059040] Stack:
    [  712.059040]  ffff88007fc03748 ffffffff8136c65f ffff88007fc03778 ffffffff810c4b66
    [  712.059040]  ffff88002a0b1f48 0000000000000005 ffff88002a0b1f48 ffff88002a057988
    [  712.059040]  ffff88007fc03798 ffffffff81650a10 ffffffffa069e828 ffff88002a0b1ec0
    [  712.059040] Call Trace:
    [  712.059040]  <IRQ> 
    [  712.059040]  [<ffffffff8136c65f>] __delay+0xf/0x20
    [  712.059040]  [<ffffffff810c4b66>] do_raw_spin_lock+0x86/0x130
    [  712.059040]  [<ffffffff81650a10>] _raw_spin_lock+0x40/0x50
    [  712.059040]  [<ffffffffa069e828>] ? __ss_close+0x98/0x120 [tempesta_fw]
    [  712.059040]  [<ffffffffa069e828>] __ss_close+0x98/0x120 [tempesta_fw]
    [  712.059040]  [<ffffffffa0689373>] tfw_http_resp_fwd+0x193/0x2b0 [tempesta_fw]
    [  712.059040]  [<ffffffffa0689540>] tfw_http_send_resp.isra.27.constprop.32+0xb0/0x100 [tempesta_fw]
    [  712.059040]  [<ffffffffa068987b>] tfw_http_send_502+0xcb/0xd0 [tempesta_fw]
    [  712.059040]  [<ffffffffa068adca>] tfw_http_req_cache_cb+0x19a/0x210 [tempesta_fw]
    [  712.059040]  [<ffffffffa068ac30>] ? tfw_http_conn_repair+0x420/0x420 [tempesta_fw]
    [  712.059040]  [<ffffffffa0684157>] tfw_cache_process+0x117/0x2a0 [tempesta_fw]
    [  712.059040]  [<ffffffffa068a520>] tfw_http_msg_process+0x460/0x750 [tempesta_fw]
    [  712.059040]  [<ffffffffa068761c>] __gfsm_fsm_exec+0x5c/0x90 [tempesta_fw]
    [  712.059040]  [<ffffffffa0687844>] tfw_gfsm_dispatch+0x14/0x20 [tempesta_fw]
    [  712.059040]  [<ffffffffa0686e3d>] tfw_connection_recv+0x1d/0x20 [tempesta_fw]
    [  712.059040]  [<ffffffffa069e51c>] ss_tcp_process_data+0x17c/0x360 [tempesta_fw]
    [  712.059040]  [<ffffffffa069e750>] ss_tcp_data_ready+0x50/0x90 [tempesta_fw]
    [  712.059040]  [<ffffffff815c7367>] tcp_rcv_established+0x3d7/0x710
    [  712.059040]  [<ffffffff815d2c4c>] tcp_v4_do_rcv+0x10c/0x210
    [  712.059040]  [<ffffffff815d422b>] tcp_v4_rcv+0xadb/0xcd0
    [  712.059040]  [<ffffffff815aa6b1>] ? ip_local_deliver_finish+0x41/0x3b0
    [  712.059040]  [<ffffffff815aa7a3>] ip_local_deliver_finish+0x133/0x3b0
    [  712.059040]  [<ffffffff815aa6b1>] ? ip_local_deliver_finish+0x41/0x3b0
    [  712.059040]  [<ffffffff815ab2d0>] ip_local_deliver+0xc0/0xd0
    [  712.059040]  [<ffffffff815aa670>] ? inet_del_offload+0x40/0x40
    [  712.059040]  [<ffffffff815aabcf>] ip_rcv_finish+0x1af/0x610
    [  712.059040]  [<ffffffff815ab5c9>] ip_rcv+0x2e9/0x410
    [  712.059040]  [<ffffffff815aaa20>] ? ip_local_deliver_finish+0x3b0/0x3b0
    [  712.059040]  [<ffffffff8155dd85>] __netif_receive_skb_core+0x3a5/0xb40
    [  712.059040]  [<ffffffff8155e660>] ? process_backlog+0xe0/0x230
    [  712.059040]  [<ffffffff8155e53d>] __netif_receive_skb+0x1d/0x60
    [  712.059040]  [<ffffffff8155e5f8>] process_backlog+0x78/0x230
    [  712.059040]  [<ffffffff8155e660>] ? process_backlog+0xe0/0x230
    [  712.059040]  [<ffffffff815607ce>] net_rx_action+0x14e/0x440
    [  712.059040]  [<ffffffff81653d28>] __do_softirq+0xc8/0x473
    [  712.059040]  [<ffffffffa069f757>] ? tfw_sock_clnt_stop_all+0x77/0xd0 [tempesta_fw]
    [  712.059040]  [<ffffffff8102066e>] __tempesta_do_softirq_fpusafe+0xe/0x10
    [  712.059040]  [<ffffffff8165226c>] do_softirq_own_stack+0x1c/0x30
    [  712.059040]  <EOI> 
    [  712.059040]  [<ffffffff8107065e>] do_softirq+0x4e/0x60
    [  712.059040]  [<ffffffff81070718>] __local_bh_enable_ip+0xa8/0xb0
    [  712.059040]  [<ffffffffa069f763>] tfw_sock_clnt_stop_all+0x83/0xd0 [tempesta_fw]
    [  712.059040]  [<ffffffffa0685d12>] tfw_cfg_stop+0x32/0x90 [tempesta_fw]
    [  712.059040]  [<ffffffffa069baf8>] handle_sysctl_state_io+0x188/0x1b0 [tempesta_fw]
    [  712.059040]  [<ffffffffa069b9a2>] ? handle_sysctl_state_io+0x32/0x1b0 [tempesta_fw]
    [  712.059040]  [<ffffffff81279055>] proc_sys_call_handler+0xc5/0xe0
    [  712.059040]  [<ffffffff81279084>] proc_sys_write+0x14/0x20
    [  712.059040]  [<ffffffff811f8c18>] __vfs_write+0x28/0x120
    [  712.059040]  [<ffffffff810bc9ec>] ? percpu_down_read+0x5c/0x90
    [  712.059040]  [<ffffffff811fc5e1>] ? __sb_start_write+0xd1/0xf0
    [  712.059040]  [<ffffffff811fc5e1>] ? __sb_start_write+0xd1/0xf0
    [  712.059040]  [<ffffffff811f9312>] vfs_write+0xb2/0x1b0
    [  712.059040]  [<ffffffff811fa669>] SyS_write+0x49/0xa0
    [  712.059040]  [<ffffffff810029c8>] do_syscall_64+0x58/0x110
    [  712.059040]  [<ffffffff8165145a>] entry_SYSCALL64_slow_path+0x25/0x25
    [  712.059040] Code: e2 48 8d 7a 01 ff 15 2c c3 93 00 5d c3 66 90 0f 1f 44 00 00 55 65 ff 05 8b fe c9 7e 48 89 e5 65 8b 35 79 da c9 7e 0f ae e8 0f 31 <48> 89 d1 48 c1 e1 20 48 09 c1 eb 1b 65 ff 0d 69 fe c9 7e f3 90
krizhanovsky commented 7 years ago

I reproduced the issue once with following kernel patch:

diff --git a/net/ipv4/tcp_input.c b/net/ipv4/tcp_input.c
index 1eade37..1d51186 100644
--- a/net/ipv4/tcp_input.c
+++ b/net/ipv4/tcp_input.c
@@ -3191,6 +3191,10 @@ static int tcp_clean_rtx_queue(struct sock *sk, int prior_fackets,
                if (!fully_acked)
                        break;

+               if (!skb->next) {
+                       pr_err("AK_DBG peer=%x:%x\n", sk->sk_daddr, sk->sk_dport);
+                       continue;
+               }
                tcp_unlink_write_queue(skb, sk);
                sk_wmem_free_skb(sk, skb);
                if (unlikely(skb == tp->retransmit_skb_hint))

The patch gave me many lines like

    [18438.752508] TCP: AK_DBG peer=100007f:901f
    [18438.754298] TCP: AK_DBG peer=100007f:901f
    [18438.755767] TCP: AK_DBG peer=100007f:901f

It means that the problem occurs in communications between Tempesta and local HTTPD (I use Apache HTTPD). During other runs I saw different crashes in different places, including earlier code in clean_rtx_queue(), traces mentioned in https://github.com/tempesta-tech/tempesta/issues/693#issuecomment-301731868, and several others: in short, we just use freed sockets and crash at various places.

Since all skb's sent from Tempesta to an upstream are copied by SS_F_KEEP_SKB flag, it's unlikely that they're freed at some point before using. I think the reason for the issues is using a socket after its freeing due to server connection reset. Recent changes in #660 could affect the issue.

Also # ./wrk -t 16 -c 4096 -d 3600s http://192.168.100.5:80/ gave me one more crash:

    [46560.054477] [tempesta] Warning: Parser error: state=Resp_HdrContent_TypeV input=0x74('text/htm„õ¶õiP') data_len=337 off=309
    [46560.058284] ------------[ cut here ]------------
    [46560.059202] kernel BUG at /root/tempesta/tempesta_fw/http.c:1125!
    [46560.059202] invalid opcode: 0000 [#1] SMP
    [46560.059202] Modules linked in: tfw_sched_rr(O) tfw_sched_http(O) tfw_sched_hash(O) tempesta_fw(O) tempesta_db(O) tempesta_tls(O) nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack ipt_REJECT nf_reject_ipv4 tun bridge stp llc ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter ip_vs nf_conntrack dm_mirror dm_region_hash dm_log dm_mod xfs libcrc32c ppdev ghash_clmulni_intel aesni_intel aes_x86_64 glue_helper lrw gf128mul ablk_helper cryptd input_leds led_class pcspkr i2c_piix4 i2c_core parport_pc parport acpi_cpufreq uinput ip_tables btrfs xor raid6_pq ata_generic pata_acpi crc32c_intel serio_raw e1000 ata_piix floppy ipv6 crc_ccitt autofs4 [last unloaded: tempesta_tls]
    [46560.059202] CPU: 0 PID: 10887 Comm: httpd Tainted: G        W  O    4.8.15-tfw #21
    [46560.059202] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.1-1.fc24 04/01/2014
    [46560.059202] task: ffff88004b6e8000 task.stack: ffff88004607c000
    [46560.059202] RIP: 0010:[<ffffffffa06821cb>]  [<ffffffffa06821cb>] tfw_http_req_destruct+0x4b/0x60 [tempesta_fw]
    [46560.059202] RSP: 0018:ffff88007fc039e0  EFLAGS: 00010293
    [46560.059202] RAX: ffff8800539fe8e8 RBX: ffff88002d16b020 RCX: 0000000000000001
    [46560.059202] RDX: 0000000000000000 RSI: ffffea0000493a80 RDI: ffff88002d16b020
    [46560.059202] RBP: ffff88007fc039f8 R08: ffff8800124ea200 R09: 000000010010000e
    [46560.059202] R10: 0000000000000000 R11: ffff8800124ea200 R12: ffff88004af33148
    [46560.059202] R13: 0000000000000000 R14: 00000000fffffffe R15: 0000000000000000
    [46560.059202] FS:  00007f04c4974880(0000) GS:ffff88007fc00000(0000) knlGS:0000000000000000
    [46560.059202] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
    [46560.059202] CR2: 000055687f09e090 CR3: 000000002a1b6000 CR4: 00000000003406f0
    [46560.059202] Stack:
    [46560.059202]  ffffffffa0684eb1 ffff88007fc03a18 ffff88002d16b020 ffff88007fc03a18
    [46560.059202]  ffffffffa068145c 00000000fffffffe ffff88001cfae020 ffff88007fc03aa8
    [46560.104438]  ffffffffa0683256 ffffffff8154ab4d ffff88004a7ba0f8 ffff88004a7ba0f8
    [46560.104521] Call Trace:
    [46560.104521]  <IRQ> 
    [46560.104521]  [<ffffffffa0684eb1>] ? tfw_http_msg_free+0x91/0xb0 [tempesta_fw]
    [46560.104521]  [<ffffffffa068145c>] tfw_http_conn_msg_free+0x5c/0x70 [tempesta_fw]
    [46560.104521]  [<ffffffffa0683256>] tfw_http_msg_process+0x196/0x750 [tempesta_fw]
    [46560.104521]  [<ffffffff8154ab4d>] ? __alloc_skb+0x4d/0x2a0
    [46560.104521]  [<ffffffffa068061c>] __gfsm_fsm_exec+0x5c/0x90 [tempesta_fw]
    [46560.104521]  [<ffffffffa0680844>] tfw_gfsm_dispatch+0x14/0x20 [tempesta_fw]
    [46560.104521]  [<ffffffffa067fe3d>] tfw_connection_recv+0x1d/0x20 [tempesta_fw]
    [46560.104521]  [<ffffffffa06974fc>] ss_tcp_process_data+0x17c/0x360 [tempesta_fw]
    [46560.104521]  [<ffffffffa0697730>] ss_tcp_data_ready+0x50/0x90 [tempesta_fw]
    [46560.104521]  [<ffffffff815c7367>] tcp_rcv_established+0x3d7/0x710
    [46560.104521]  [<ffffffff815d2c4c>] tcp_v4_do_rcv+0x10c/0x210
    [46560.104521]  [<ffffffff815d422b>] tcp_v4_rcv+0xadb/0xcd0
    [46560.104521]  [<ffffffff815aa6b1>] ? ip_local_deliver_finish+0x41/0x3b0
    [46560.104521]  [<ffffffff815aa7a3>] ip_local_deliver_finish+0x133/0x3b0
    [46560.104521]  [<ffffffff815aa6b1>] ? ip_local_deliver_finish+0x41/0x3b0
    [46560.104521]  [<ffffffff815ab2d0>] ip_local_deliver+0xc0/0xd0
    [46560.104521]  [<ffffffff815aa670>] ? inet_del_offload+0x40/0x40
    [46560.104521]  [<ffffffff815aabcf>] ip_rcv_finish+0x1af/0x610
    [46560.104521]  [<ffffffff815ab5c9>] ip_rcv+0x2e9/0x410
    [46560.104521]  [<ffffffff815aaa20>] ? ip_local_deliver_finish+0x3b0/0x3b0
    [46560.104521]  [<ffffffff8155dd85>] __netif_receive_skb_core+0x3a5/0xb40
    [46560.104521]  [<ffffffff8155e660>] ? process_backlog+0xe0/0x230
    [46560.104521]  [<ffffffff8155e53d>] __netif_receive_skb+0x1d/0x60
    [46560.104521]  [<ffffffff8155e5f8>] process_backlog+0x78/0x230
    [46560.104521]  [<ffffffff8155e660>] ? process_backlog+0xe0/0x230
    [46560.104521]  [<ffffffff815607ce>] net_rx_action+0x14e/0x440
    [46560.104521]  [<ffffffff81098b7c>] ? check_preempt_curr+0x8c/0xc0
    [46560.104521]  [<ffffffff81653d28>] __do_softirq+0xc8/0x473
    [46560.104521]  [<ffffffff815aeed7>] ? ip_finish_output2+0x217/0x5c0
    [46560.104521]  [<ffffffff8102066e>] __tempesta_do_softirq_fpusafe+0xe/0x10
    [46560.104521]  [<ffffffff8165226c>] do_softirq_own_stack+0x1c/0x30
    [46560.104521]  <EOI> 
    [46560.104521]  [<ffffffff8107065e>] do_softirq+0x4e/0x60
    [46560.104521]  [<ffffffff81070718>] __local_bh_enable_ip+0xa8/0xb0
    [46560.104521]  [<ffffffff815aef00>] ip_finish_output2+0x240/0x5c0
    [46560.104521]  [<ffffffff815afd46>] ? ip_finish_output+0x1c6/0x320
    [46560.104521]  [<ffffffff815afd46>] ip_finish_output+0x1c6/0x320
    [46560.104521]  [<ffffffff815afea9>] NF_HOOK_COND.part.33.constprop.47+0x9/0x10
    [46560.104521]  [<ffffffff815b1563>] ip_output+0xc3/0x110
    [46560.104521]  [<ffffffff815afb80>] ? ip_fragment.constprop.49+0x80/0x80
    [46560.104521]  [<ffffffff815b0a19>] ip_local_out+0x39/0x70
    [46560.104521]  [<ffffffff815b0e4b>] ip_queue_xmit+0x1eb/0x5a0
    [46560.104521]  [<ffffffff815b0c65>] ? ip_queue_xmit+0x5/0x5a0
    [46560.104521]  [<ffffffff815caa64>] tcp_transmit_skb+0x4a4/0x8b0
    [46560.104521]  [<ffffffff815cafd1>] tcp_write_xmit+0x161/0xef0
    [46560.104521]  [<ffffffff815cc041>] __tcp_push_pending_frames+0x31/0xd0
    [46560.104521]  [<ffffffff815bd16b>] do_tcp_setsockopt.isra.37+0x6ab/0x860
    [46560.104521]  [<ffffffff815bd34c>] tcp_setsockopt+0x2c/0x30
    [46560.104521]  [<ffffffff815401a4>] sock_common_setsockopt+0x14/0x20
    [46560.104521]  [<ffffffff8153ef11>] SyS_setsockopt+0x71/0xc0
    [46560.104521]  [<ffffffff810029c8>] do_syscall_64+0x58/0x110
    [46560.104521]  [<ffffffff8165145a>] entry_SYSCALL64_slow_path+0x25/0x25
    [46560.104521] Code: 48 8b 87 d0 03 00 00 48 8d 97 d0 03 00 00 48 39 c2 75 1a 48 8b bf 58 03 00 00 48 85 ff 74 0a 55 48 89 e5 e8 68 21 01 00 5d f3 c3 <0f> 0b 0f 0b 0f 0b 0f 1f 44 00 00 66 2e 0f 1f 84 00 00 00 00 00 
    [46560.104521] RIP  [<ffffffffa06821cb>] tfw_http_req_destruct+0x4b/0x60 [tempesta_fw]
    [46560.104521]  RSP <ffff88007fc039e0>
    [46560.219990] ---[ end trace b4b388391d62594f ]---
    [46560.221101] Kernel panic - not syncing: Fatal exception in interrupt
    [46560.222063] Kernel Offset: disabled
krizhanovsky commented 7 years ago

One more deplock warning on Tempesta restart under the wrk load (UDP fixed in https://github.com/tempesta-tech/tempesta/commit/805cca7208d20ef838b6147fd890b993d653aebd):

    [ 1485.704637] [tempesta] Stopping all modules...
    [ 1485.788264] [tempesta] Warning: Socket work queue overrun: [1]
    [ 1485.917482] 
    [ 1485.918033] =================================
    [ 1485.918033] [ INFO: inconsistent lock state ]
    [ 1485.918033] 4.8.15-tfw #21 Tainted: G           O   
    [ 1485.930398] ---------------------------------
    [ 1485.930398] inconsistent {IN-SOFTIRQ-W} -> {SOFTIRQ-ON-W} usage.
    [ 1485.930398] sysctl/11922 [HC0[0]:SC0[0]:HE1:SE1] takes:
    [ 1485.942278]  (&(&srv_conn->fwd_qlock)->rlock){+.?...}, at: [<ffffffffa1753d50>] tfw_http_conn_release+0x80/0x220 [tempesta_fw]
    [ 1485.952770] {IN-SOFTIRQ-W} state was registered at:
    [ 1485.952770]   [<ffffffff810c06e6>] __lock_acquire+0x246/0x1620
    [ 1485.952770]   [<ffffffff810c1ebe>] lock_acquire+0xbe/0x1f0
    [ 1485.952770]   [<ffffffff81650a08>] _raw_spin_lock+0x38/0x50
    [ 1485.952770]   [<ffffffffa17539d2>] tfw_http_req_fwd+0x32/0xe0 [tempesta_fw]
    [ 1485.952770]   [<ffffffffa1755dfa>] tfw_http_req_cache_cb+0x1ca/0x1f0 [tempesta_fw]
    [ 1485.952770]   [<ffffffffa174f157>] tfw_cache_process+0x117/0x2a0 [tempesta_fw]
    [ 1485.952770]   [<ffffffffa1755520>] tfw_http_msg_process+0x460/0x750 [tempesta_fw]
    [ 1485.952770]   [<ffffffffa175261c>] __gfsm_fsm_exec+0x5c/0x90 [tempesta_fw]
    [ 1485.952770]   [<ffffffffa1752844>] tfw_gfsm_dispatch+0x14/0x20 [tempesta_fw]
    [ 1485.952770]   [<ffffffffa1751e3d>] tfw_connection_recv+0x1d/0x20 [tempesta_fw]
    [ 1485.952770]   [<ffffffffa176956c>] ss_tcp_process_data+0x17c/0x360 [tempesta_fw]
    [ 1485.952770]   [<ffffffffa17697af>] ss_tcp_data_ready+0x5f/0xa0 [tempesta_fw]
    [ 1485.993583]   [<ffffffff815c6916>] tcp_data_queue+0x6e6/0xd60
    [ 1485.993583]   [<ffffffff815c716e>] tcp_rcv_established+0x1de/0x710
    [ 1485.993583]   [<ffffffff815d2c4c>] tcp_v4_do_rcv+0x10c/0x210
    [ 1485.993583]   [<ffffffff815d422b>] tcp_v4_rcv+0xadb/0xcd0
    [ 1485.993583]   [<ffffffff815aa7a3>] ip_local_deliver_finish+0x133/0x3b0
    [ 1485.993583]   [<ffffffff815ab2d0>] ip_local_deliver+0xc0/0xd0
    [ 1485.993583]   [<ffffffff815aabcf>] ip_rcv_finish+0x1af/0x610
    [ 1485.993583]   [<ffffffff815ab5c9>] ip_rcv+0x2e9/0x410
    [ 1485.993583]   [<ffffffff8155dd85>] __netif_receive_skb_core+0x3a5/0xb40
    [ 1485.993583]   [<ffffffff8155e53d>] __netif_receive_skb+0x1d/0x60
    [ 1485.993583]   [<ffffffff8155e5f8>] process_backlog+0x78/0x230
    [ 1485.993583]   [<ffffffff815607ce>] net_rx_action+0x14e/0x440
    [ 1485.993583]   [<ffffffff81653d28>] __do_softirq+0xc8/0x473
    [ 1485.993583]   [<ffffffff810705cf>] run_ksoftirqd+0x1f/0x60
    [ 1485.993583]   [<ffffffff81091819>] smpboot_thread_fn+0x139/0x200
    [ 1485.993583]   [<ffffffff8108dc48>] kthread+0xf8/0x110
    [ 1485.993583]   [<ffffffff816515bf>] ret_from_fork+0x1f/0x40
    [ 1485.993583] irq event stamp: 75771
    [ 1485.993583] hardirqs last  enabled at (75771): [<ffffffff81650d36>] _raw_spin_unlock_irqrestore+0x36/0x50
    [ 1485.993583] hardirqs last disabled at (75770): [<ffffffff81650b8c>] _raw_spin_lock_irqsave+0x1c/0x60
    [ 1485.993583] softirqs last  enabled at (75766): [<ffffffff81653ebc>] __do_softirq+0x25c/0x473
    [ 1485.993583] softirqs last disabled at (72235): [<ffffffff8102066e>] __tempesta_do_softirq_fpusafe+0xe/0x10
    [ 1485.993583] 
    [ 1485.993583] other info that might help us debug this:
    [ 1485.993583]  Possible unsafe locking scenario:
    [ 1485.993583] 
    [ 1485.993583]        CPU0
    [ 1485.993583]        ----
    [ 1485.993583]   lock(&(&srv_conn->fwd_qlock)->rlock);
    [ 1485.993583]   <Interrupt>
    [ 1485.993583]     lock(&(&srv_conn->fwd_qlock)->rlock);
    [ 1485.993583] 
    [ 1485.993583]  *** DEADLOCK ***
    [ 1485.993583] 
    [ 1486.128032] 5 locks held by sysctl/11922:
    [ 1486.128032]  #0:  (sb_writers#4){.+.+.+}, at: [<ffffffff811fc5e1>] __sb_start_write+0xd1/0xf0
    [ 1486.128032]  #1:  (tfw_sysctl_mtx){+.+.+.}, at: [<ffffffffa1766982>] handle_sysctl_state_io+0x32/0x1b0 [tempesta_fw]
    [ 1486.128032]  #2:  (sg_lock){++++..}, at: [<ffffffffa1768085>] tfw_sg_for_each_srv+0x25/0xc0 [tempesta_fw]
    [ 1486.128032]  #3:  (&sg->lock){+.+...}, at: [<ffffffffa17680a5>] tfw_sg_for_each_srv+0x45/0xc0 [tempesta_fw]
    [ 1486.128032]  #4:  (&(&p->conn_lock)->rlock){+.+...}, at: [<ffffffffa176b3e1>] tfw_sock_srv_disconnect_srv+0x21/0xa0 [tempesta_fw]
    [ 1486.128032] 
    [ 1486.128032] stack backtrace:
    [ 1486.128032] CPU: 1 PID: 11922 Comm: sysctl Tainted: G           O    4.8.15-tfw #21
    [ 1486.128032] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.1-1.fc24 04/01/2014
    [ 1486.128032]  0000000000000000 ffff8800192e3a38 ffffffff8135ecbe ffff8800188f5c00
    [ 1486.128032]  ffffffff82e0c1f0 ffff8800192e3a88 ffffffff81178b19 0000000000000000
    [ 1486.128032]  ffff880000000001 ffff880000000001 0000000000000004 ffff8800188f5c00
    [ 1486.128032] Call Trace:
    [ 1486.128032]  [<ffffffff8135ecbe>] dump_stack+0x67/0x99
    [ 1486.128032]  [<ffffffff81178b19>] print_usage_bug+0x1f2/0x203
    [ 1486.128032]  [<ffffffff810bf440>] ? print_shortest_lock_dependencies+0x1d0/0x1d0
    [ 1486.128032]  [<ffffffff810bfef2>] mark_lock+0x212/0x2a0
    [ 1486.128032]  [<ffffffff810c0741>] __lock_acquire+0x2a1/0x1620
    [ 1486.128032]  [<ffffffff810c1ebe>] lock_acquire+0xbe/0x1f0
    [ 1486.128032]  [<ffffffffa1753d50>] ? tfw_http_conn_release+0x80/0x220 [tempesta_fw]
    [ 1486.128032]  [<ffffffff81650a08>] _raw_spin_lock+0x38/0x50
    [ 1486.128032]  [<ffffffffa1753d50>] ? tfw_http_conn_release+0x80/0x220 [tempesta_fw]
    [ 1486.128032]  [<ffffffffa1753d50>] tfw_http_conn_release+0x80/0x220 [tempesta_fw]
    [ 1486.128032]  [<ffffffff810e6d1b>] ? try_to_del_timer_sync+0x4b/0x60
    [ 1486.128032]  [<ffffffffa1751dcc>] tfw_connection_release+0x2c/0x50 [tempesta_fw]
    [ 1486.128032]  [<ffffffffa176b42d>] tfw_sock_srv_disconnect_srv+0x6d/0xa0 [tempesta_fw]
    [ 1486.128032]  [<ffffffffa176b3c0>] ? tfw_sock_srv_del_conns+0x130/0x130 [tempesta_fw]
    [ 1486.128032]  [<ffffffffa17680c7>] tfw_sg_for_each_srv+0x67/0xc0 [tempesta_fw]
    [ 1486.128032]  [<ffffffff810c01dd>] ? trace_hardirqs_on+0xd/0x10
    [ 1486.128032]  [<ffffffffa176b285>] tfw_sock_srv_stop+0x15/0x20 [tempesta_fw]
    [ 1486.128032]  [<ffffffffa1750d12>] tfw_cfg_stop+0x32/0x90 [tempesta_fw]
    [ 1486.128032]  [<ffffffffa1766ad8>] handle_sysctl_state_io+0x188/0x1b0 [tempesta_fw]
    [ 1486.128032]  [<ffffffffa1766982>] ? handle_sysctl_state_io+0x32/0x1b0 [tempesta_fw]
    [ 1486.128032]  [<ffffffff81279055>] proc_sys_call_handler+0xc5/0xe0
    [ 1486.128032]  [<ffffffff81279084>] proc_sys_write+0x14/0x20
    [ 1486.128032]  [<ffffffff811f8c18>] __vfs_write+0x28/0x120
    [ 1486.128032]  [<ffffffff810bc9ec>] ? percpu_down_read+0x5c/0x90
    [ 1486.128032]  [<ffffffff811fc5e1>] ? __sb_start_write+0xd1/0xf0
    [ 1486.128032]  [<ffffffff811fc5e1>] ? __sb_start_write+0xd1/0xf0
    [ 1486.128032]  [<ffffffff811f9312>] vfs_write+0xb2/0x1b0
    [ 1486.128032]  [<ffffffff811fa669>] SyS_write+0x49/0xa0
    [ 1486.128032]  [<ffffffff810029c8>] do_syscall_64+0x58/0x110
    [ 1486.128032]  [<ffffffff8165145a>] entry_SYSCALL64_slow_path+0x25/0x25
    [ 1486.293360] [tdb] Close table 'filter0.tdb'
    [ 1486.300593] [tempesta] Un-registering scheduler: hash
    [ 1486.334654] [tempesta] Un-registering scheduler: http
    [ 1486.379439] [tempesta] Un-registering scheduler: round-robin
    [ 1486.405757] [tempesta] exiting...
    [ 1486.454160] [tdb] Shutdown Tempesta DB
krizhanovsky commented 7 years ago

One more interesting trace got by Tempesta restart under heavy wrk load (./wrk -t 16 -c 4096 -d 3600s http://centos:80/). While it happens on restart, which is different from original issue case, it still means that Tempesta can free socket from under tcp_v4_rcv(). Probably server connections closing is the issue, it can happen on Tempesta restart as well as on server connections reset & recovering.

   [  570.486011] =========================
    [  570.486011] [ BUG: held lock freed! ]
    [  570.486011] 4.8.15-tfw #21 Tainted: G           O   
    [  570.486011] -------------------------
    [  570.486011] ksoftirqd/1/16 is freeing memory ffff880023eabd80-ffff880023eac787, with a lock still held there!
    [  570.486011]  (slock-AF_INET/1){+.-...}, at: [<ffffffff815d4189>] tcp_v4_rcv+0xa39/0xcd0
    [  570.486011] 3 locks held by ksoftirqd/1/16:
    [  570.486011]  #0:  (rcu_read_lock){......}, at: [<ffffffff8155e660>] process_backlog+0xe0/0x230
    [  570.486011]  #1:  (rcu_read_lock){......}, at: [<ffffffff815aa6b1>] ip_local_deliver_finish+0x41/0x3b0
    [  570.486011]  #2:  (slock-AF_INET/1){+.-...}, at: [<ffffffff815d4189>] tcp_v4_rcv+0xa39/0xcd0
    [  570.486011] 
    [  570.486011] stack backtrace:
    [  570.486011] CPU: 1 PID: 16 Comm: ksoftirqd/1 Tainted: G           O    4.8.15-tfw #21
    [  570.486011] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.1-1.fc24 04/01/2014
    [  570.486011]  0000000000000000 ffff88005c913878 ffffffff8135ecbe ffff88005c909f70
    [  570.486011]  ffff880023eabd80 ffff88005c9138b0 ffffffff810c0491 ffff880023eabd80
    [  570.486011]  0000000000000246 ffff88005c98f600 ffffea00008faa00 ffffffff815412a0
    [  570.486011] Call Trace:
    [  570.486011]  [<ffffffff8135ecbe>] dump_stack+0x67/0x99
    [  570.486011]  [<ffffffff810c0491>] debug_check_no_locks_freed+0x141/0x150
    [  570.486011]  [<ffffffff815412a0>] ? __sk_destruct+0x100/0x1a0
    [  570.486011]  [<ffffffff811dca11>] kmem_cache_free+0x91/0x250
    [  570.486011]  [<ffffffff815412a0>] __sk_destruct+0x100/0x1a0
    [  570.486011]  [<ffffffff81544580>] sk_destruct+0x20/0x30
    [  570.486011]  [<ffffffff81544612>] __sk_free+0x82/0xa0
    [  570.486011]  [<ffffffff81544648>] sk_free+0x18/0x20
    [  570.486011]  [<ffffffff815b7e54>] inet_csk_destroy_sock+0xd4/0x170
    [  570.486011]  [<ffffffff815ba4e4>] tcp_done+0x64/0x90
    [  570.486011]  [<ffffffff815d4601>] tcp_time_wait+0x1c1/0x290
    [  570.486011]  [<ffffffff815c87df>] tcp_rcv_state_process+0xd9f/0xe00
    [  570.486011]  [<ffffffff815d4189>] ? tcp_v4_rcv+0xa39/0xcd0
    [  570.486011]  [<ffffffff810be849>] ? __lock_is_held+0x49/0x70
    [  570.486011]  [<ffffffff815d2bb9>] tcp_v4_do_rcv+0x79/0x210
    [  570.486011]  [<ffffffff815d422b>] tcp_v4_rcv+0xadb/0xcd0
    [  570.486011]  [<ffffffff810be849>] ? __lock_is_held+0x49/0x70
    [  570.486011]  [<ffffffff815aa7a3>] ip_local_deliver_finish+0x133/0x3b0
    [  570.486011]  [<ffffffff815aa6b1>] ? ip_local_deliver_finish+0x41/0x3b0
    [  570.486011]  [<ffffffff815ab2d0>] ip_local_deliver+0xc0/0xd0
    [  570.486011]  [<ffffffff815aa670>] ? inet_del_offload+0x40/0x40
    [  570.486011]  [<ffffffff815aabcf>] ip_rcv_finish+0x1af/0x610
    [  570.486011]  [<ffffffff815ab5c9>] ip_rcv+0x2e9/0x410
    [  570.486011]  [<ffffffff815aaa20>] ? ip_local_deliver_finish+0x3b0/0x3b0
    [  570.486011]  [<ffffffff8155dd85>] __netif_receive_skb_core+0x3a5/0xb40
    [  570.486011]  [<ffffffff8155e660>] ? process_backlog+0xe0/0x230
    [  570.486011]  [<ffffffff8155e53d>] __netif_receive_skb+0x1d/0x60
    [  570.486011]  [<ffffffff8155e5f8>] process_backlog+0x78/0x230
    [  570.486011]  [<ffffffff8155e660>] ? process_backlog+0xe0/0x230
    [  570.486011]  [<ffffffff815607ce>] net_rx_action+0x14e/0x440
    [  570.486011]  [<ffffffff81653d28>] __do_softirq+0xc8/0x473
    [  570.486011]  [<ffffffff810705cf>] run_ksoftirqd+0x1f/0x60
    [  570.486011]  [<ffffffff81091819>] smpboot_thread_fn+0x139/0x200
    [  570.486011]  [<ffffffff810916e0>] ? sort_range+0x30/0x30
    [  570.486011]  [<ffffffff8108dc48>] kthread+0xf8/0x110
    [  570.486011]  [<ffffffff816515bf>] ret_from_fork+0x1f/0x40
    [  570.486011]  [<ffffffff8108db50>] ? kthread_create_on_node+0x200/0x200
    [  570.609610] [tdb] Shutdown Tempesta DB
    [  570.786677] [tdb] Start Tempesta DB
    [  570.847929] [tdb] Opened table /opt/tempesta/db/filter.tdb: size=16777216 rec_size=20 base=ffff88007c400000
    [  571.287440] TCP: request_sock_TCP: Possible SYN flooding on port 80. Sending cookies.  Check SNMP counters.
    [  663.779920] net_ratelimit: 71 callbacks suppressed
    [  663.781248] [tempesta] Warning: Paired request missing, HTTP Response Splitting attack?
krizhanovsky commented 7 years ago

There were a bug in FPU context switch, fixed with https://github.com/tempesta-tech/linux-4.8.15-tfw/commit/9cea1ec0156145217ac6320c40189b40b8160780 . The problem is that in_softirq() checks softirq part of current_thread_info()->preempt_count, which is incremented on local_bh_disable() and doesn't mean that current context is softirq. The right check is in_serving_softirq() which checks the last bit for softirq context.

However, with the patch I got following oops on workload ./wrk -t 16 -c 4096 -d 3600s http://centos:80/

UPD Created #752 for the crash, so it's out of the issue.

    [ 4512.704257] divide error: 0000 [#1] SMP
    [ 4512.705113] Modules linked in: tfw_sched_rr(O) tfw_sched_http(O) tfw_sched_hash(O) tempesta_fw(O) tempesta_db(O) tempesta_tls(O) nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack ipt_REJECT nf_reject_ipv4 tun bridge stp llc ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter ip_vs nf_conntrack dm_mirror dm_region_hash dm_log dm_mod xfs libcrc32c ppdev ghash_clmulni_intel aesni_intel aes_x86_64 glue_helper lrw gf128mul ablk_helper cryptd input_leds led_class pcspkr i2c_piix4 i2c_core parport_pc parport acpi_cpufreq uinput ip_tables btrfs xor raid6_pq ata_generic pata_acpi crc32c_intel serio_raw e1000 ata_piix floppy ipv6 crc_ccitt autofs4
    [ 4512.711182] CPU: 0 PID: 12929 Comm: httpd Tainted: G           O    4.8.15-tfw #41
    [ 4512.711182] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.1-1.fc24 04/01/2014
    [ 4512.711182] task: ffff8800357cc500 task.stack: ffff880023b1c000
    [ 4512.711182] RIP: 0010:[<ffffffffa068aea7>]  [<ffffffffa068aea7>] __tfw_stats_adjust+0x67/0x250 [tempesta_fw]
    [ 4512.711182] RSP: 0018:ffff88007fc03898  EFLAGS: 00010246
    [ 4512.711182] RAX: 0000000000000000 RBX: 0000000000000040 RCX: ffff88005b964688
    [ 4512.711182] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff88005b964608
    [ 4512.735428] RBP: ffff88007fc038c8 R08: 0000000000000010 R09: 0000000000000000
    [ 4512.735428] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
    [ 4512.735428] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
    [ 4512.735428] FS:  00007f07c8d3e880(0000) GS:ffff88007fc00000(0000) knlGS:0000000000000000
    [ 4512.735428] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
    [ 4512.735428] CR2: 00007f9a699ee640 CR3: 0000000026e40000 CR4: 00000000003406f0
    [ 4512.735428] Stack:
    [ 4512.735428]  0000000000000000 ffff88005b964608 0000000000000625 ffff88005b964008
    [ 4512.735428]  0000000000000000 0000000000000000 ffff88007fc038f8 ffffffffa068bddf
    [ 4512.735428]  ffff88001f78c608 ffff8800216ce020 ffff8800265da020 ffffffffa0693660
    [ 4512.735428] Call Trace:
    [ 4512.735428]  <IRQ> 
    [ 4512.735428]  [<ffffffffa068bddf>] tfw_apm_update+0x2cf/0x3c0 [tempesta_fw]
    [ 4512.735428]  [<ffffffffa0693660>] ? tfw_http_send_500.isra.28+0xd0/0xd0 [tempesta_fw]
    [ 4512.735428]  [<ffffffffa06936b2>] tfw_http_resp_cache_cb+0x52/0x80 [tempesta_fw]
    [ 4512.735428]  [<ffffffffa068e157>] tfw_cache_process+0x117/0x2a0 [tempesta_fw]
    [ 4512.735428]  [<ffffffff810f0ce4>] ? __getnstimeofday64+0x94/0x140
    [ 4512.735428]  [<ffffffffa0693e8d>] tfw_http_resp_cache+0x7d/0xc0 [tempesta_fw]
    [ 4512.735428]  [<ffffffffa06942bc>] tfw_http_msg_process+0x1fc/0x750 [tempesta_fw]
    [ 4512.735428]  [<ffffffff8154ab4d>] ? __alloc_skb+0x4d/0x2a0
    [ 4512.735428]  [<ffffffffa069161c>] __gfsm_fsm_exec+0x5c/0x90 [tempesta_fw]
    [ 4512.735428]  [<ffffffffa0691844>] tfw_gfsm_dispatch+0x14/0x20 [tempesta_fw]
    [ 4512.735428]  [<ffffffffa0690e3d>] tfw_connection_recv+0x1d/0x20 [tempesta_fw]
    [ 4512.735428]  [<ffffffffa06a84fc>] ss_tcp_process_data+0x17c/0x360 [tempesta_fw]
    [ 4512.735428]  [<ffffffffa06a8730>] ss_tcp_data_ready+0x50/0x90 [tempesta_fw]
    [ 4512.735428]  [<ffffffff815c68a6>] tcp_data_queue+0x6e6/0xd60
    [ 4512.735428]  [<ffffffff815c70fe>] tcp_rcv_established+0x1de/0x710
    [ 4512.735428]  [<ffffffff815d2bdc>] tcp_v4_do_rcv+0x10c/0x210
    [ 4512.735428]  [<ffffffff815d41bb>] tcp_v4_rcv+0xadb/0xcd0
    [ 4512.735428]  [<ffffffff815aa6b1>] ? ip_local_deliver_finish+0x41/0x3b0
    [ 4512.735428]  [<ffffffff815aa7a3>] ip_local_deliver_finish+0x133/0x3b0
    [ 4512.735428]  [<ffffffff815aa6b1>] ? ip_local_deliver_finish+0x41/0x3b0
    [ 4512.735428]  [<ffffffff815ab2d0>] ip_local_deliver+0xc0/0xd0
    [ 4512.735428]  [<ffffffff815aa670>] ? inet_del_offload+0x40/0x40
    [ 4512.735428]  [<ffffffff815aabcf>] ip_rcv_finish+0x1af/0x610
    [ 4512.735428]  [<ffffffff815ab5c9>] ip_rcv+0x2e9/0x410
    [ 4512.735428]  [<ffffffff815aaa20>] ? ip_local_deliver_finish+0x3b0/0x3b0
    [ 4512.735428]  [<ffffffff8155dd85>] __netif_receive_skb_core+0x3a5/0xb40
    [ 4512.735428]  [<ffffffff8155e660>] ? process_backlog+0xe0/0x230
    [ 4512.735428]  [<ffffffff8155e53d>] __netif_receive_skb+0x1d/0x60
    [ 4512.735428]  [<ffffffff8155e5f8>] process_backlog+0x78/0x230
    [ 4512.735428]  [<ffffffff8155e660>] ? process_backlog+0xe0/0x230
    [ 4512.735428]  [<ffffffff815607ce>] net_rx_action+0x14e/0x440
    [ 4512.735428]  [<ffffffff81653ca8>] __do_softirq+0xc8/0x473
    [ 4512.735428]  [<ffffffff815aeed7>] ? ip_finish_output2+0x217/0x5c0
    [ 4512.735428]  [<ffffffff8102066e>] __tempesta_do_softirq_fpusafe+0xe/0x10
    [ 4512.735428]  [<ffffffff816521ec>] do_softirq_own_stack+0x1c/0x30
    [ 4512.735428]  <EOI> 
    [ 4512.735428]  [<ffffffff8107065e>] do_softirq+0x4e/0x60
    [ 4512.735428]  [<ffffffff81070718>] __local_bh_enable_ip+0xa8/0xb0
    [ 4512.735428]  [<ffffffff815aef00>] ip_finish_output2+0x240/0x5c0
    [ 4512.735428]  [<ffffffff815afd46>] ? ip_finish_output+0x1c6/0x320
    [ 4512.735428]  [<ffffffff815afd46>] ip_finish_output+0x1c6/0x320
    [ 4512.735428]  [<ffffffff815afea9>] NF_HOOK_COND.part.33.constprop.47+0x9/0x10
    [ 4512.735428]  [<ffffffff815b1563>] ip_output+0xc3/0x110
    [ 4512.735428]  [<ffffffff815afb80>] ? ip_fragment.constprop.49+0x80/0x80
    [ 4512.735428]  [<ffffffff815b0a19>] ip_local_out+0x39/0x70
    [ 4512.735428]  [<ffffffff815b0e4b>] ip_queue_xmit+0x1eb/0x5a0
    [ 4512.735428]  [<ffffffff815b0c65>] ? ip_queue_xmit+0x5/0x5a0
    [ 4512.735428]  [<ffffffff815ca9f4>] tcp_transmit_skb+0x4a4/0x8b0
    [ 4512.735428]  [<ffffffff815caf61>] tcp_write_xmit+0x161/0xef0
    [ 4512.735428]  [<ffffffff815cbfd1>] __tcp_push_pending_frames+0x31/0xd0
    [ 4512.735428]  [<ffffffff815bd16b>] do_tcp_setsockopt.isra.37+0x6ab/0x860
    [ 4512.735428]  [<ffffffff815bd34c>] tcp_setsockopt+0x2c/0x30
    [ 4512.735428]  [<ffffffff815401a4>] sock_common_setsockopt+0x14/0x20
    [ 4512.735428]  [<ffffffff8153ef11>] SyS_setsockopt+0x71/0xc0
    [ 4512.735428]  [<ffffffff810029c8>] do_syscall_64+0x58/0x110
    [ 4512.735428]  [<ffffffff816513da>] entry_SYSCALL64_slow_path+0x25/0x25
    [ 4512.735428] Code: 48 63 11 49 83 c3 01 48 01 d0 4c 63 09 4d 39 d1 76 06 4c 63 11 4d 89 c5 49 83 c0 01 48 83 c1 04 49 83 f8 10 75 d2 48 01 c0 31 d2 <49> f7 f3 4c 39 d0 72 0f 48 83 c4 08 5b 41 5c 41 5d 41 5e 41 5f 
    [ 4512.735428] RIP  [<ffffffffa068aea7>] __tfw_stats_adjust+0x67/0x250 [tempesta_fw]
    [ 4512.735428]  RSP <ffff88007fc03898>
    [ 4512.852777] ---[ end trace 630a16268dd4e293 ]---
    [ 4512.854608] Kernel panic - not syncing: Fatal exception in interrupt
keshonok commented 7 years ago

The crashes are gone in my tests in a VM after I replace pskb_copy_for_clone() with a simple pskb_copy(). All KASAN warnings are gone as well.

diff --git a/tempesta_fw/sock.c b/tempesta_fw/sock.c
index fca11c4..4e09d7e 100644
--- a/tempesta_fw/sock.c
+++ b/tempesta_fw/sock.c
@@ -324,7 +324,7 @@ ss_send(struct sock *sk, SsSkbList *skb_list, int flags)
                ss_skb_queue_head_init(&sw.skb_list);
                for (skb = ss_skb_peek(skb_list); skb; skb = ss_skb_next(skb)) {
                        /* tcp_transmit_skb() will clone the skb. */
-                       twin_skb = pskb_copy_for_clone(skb, GFP_ATOMIC);
+                       twin_skb = pskb_copy(skb, GFP_ATOMIC);
                        if (!twin_skb) {
                                SS_WARN("Unable to copy an egress SKB.\n");
                                r = -ENOMEM;

Both functions eventually call __alloc_skb() which has a special implementation in Tempesta kernel that is different from the standard kernel. The only difference between these two functions in the kernel is in the use of flag SKB_ALLOC_FCLONE:

static inline struct sk_buff *pskb_copy(struct sk_buff *skb,
                                        gfp_t gfp_mask)
{
        return __pskb_copy(skb, skb_headroom(skb), gfp_mask);
}

static inline struct sk_buff *__pskb_copy(struct sk_buff *skb, int headroom,
                                          gfp_t gfp_mask)
{
        return __pskb_copy_fclone(skb, headroom, gfp_mask, false);
}

static inline struct sk_buff *pskb_copy_for_clone(struct sk_buff *skb,
                                                  gfp_t gfp_mask)
{
        return __pskb_copy_fclone(skb, skb_headroom(skb), gfp_mask, true);
}

struct sk_buff *__pskb_copy_fclone(struct sk_buff *skb, int headroom,
                                   gfp_t gfp_mask, bool fclone)
{
        unsigned int size = skb_headlen(skb) + headroom;
        int flags = skb_alloc_rx_flag(skb) | (fclone ? SKB_ALLOC_FCLONE : 0);
        struct sk_buff *n = __alloc_skb(size, gfp_mask, flags, NUMA_NO_NODE);

        /* THE REST IS CUT OUT. */
}

This leads to a thought that something is not right in the implementation of Tempesta's __alloc_skb() in the kernel when SKB_ALLOC_FCLONE flag is specified. Is this just a coincidence?

krizhanovsky commented 7 years ago

One more Oops during debugging. It seems that all the crashes are occurred on receiving ACK from local HTTP server (Apache HTTPD in my case): sometimes the socket write queue is broken, sometimes we're freeing the socket with non-empty write queue.....

    [22742.143187] ------------[ cut here ]------------
    [22742.143187] WARNING: CPU: 1 PID: 0 at lib/list_debug.c:59 __list_del_entry+0xa1/0xd0
    [22742.143187] list_del corruption. prev->next should be ffffea0000d9b8c0, but was ffff88002f8e3100
    [22742.143187] Modules linked in: tfw_sched_ratio(O) tfw_sched_http(O) tfw_sched_hash(O) tempesta_fw(O) tempesta_db(O) tempesta_tls(O) nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack ipt_REJECT nf_reject_ipv4 tun bridge stp llc ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter ip_vs nf_conntrack dm_mirror dm_region_hash dm_log dm_mod xfs ppdev libcrc32c ghash_clmulni_intel aesni_intel aes_x86_64 glue_helper lrw gf128mul ablk_helper cryptd input_leds led_class pcspkr parport_pc parport acpi_cpufreq i2c_piix4 i2c_core uinput ip_tables btrfs xor raid6_pq ata_generic pata_acpi crc32c_intel serio_raw e1000 ata_piix floppy ipv6 crc_ccitt autofs4 [last unloaded: tempesta_tls]
    [22742.143187] CPU: 1 PID: 0 Comm: swapper/1 Tainted: G           O    4.8.15-tfw #45
    [22742.143187] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.1-1.fc24 04/01/2014
    [22742.143187]  0000000000000000 ffff88007fd03b88 ffffffff8135ecbe ffff88007fd03bd8
    [22742.143187]  0000000000000000 ffff88007fd03bc8 ffffffff810697c1 0000003b7fd03bd8
    [22742.143187]  ffffea0000d9b8c0 00000000ffffffff 0000000000000001 ffff88007fd153c0
    [22742.143187] Call Trace:
    [22742.143187]  <IRQ>  [<ffffffff8135ecbe>] dump_stack+0x67/0x99
    [22742.143187]  [<ffffffff810697c1>] __warn+0xd1/0xf0
    [22742.143187]  [<ffffffff8106982f>] warn_slowpath_fmt+0x4f/0x60
    [22742.143187]  [<ffffffff8137d4d1>] __list_del_entry+0xa1/0xd0
    [22742.143187]  [<ffffffff8137d50d>] list_del+0xd/0x30
    [22742.143187]  [<ffffffff8154a79f>] __pg_skb_alloc+0x13f/0x4a0
    [22742.143187]  [<ffffffff8154b4a7>] pskb_expand_head+0x67/0x290
    [22742.143187]  [<ffffffff815c9e8c>] tcp_fragment+0x30c/0x370
    [22742.143187]  [<ffffffff815ccf5d>] __tcp_retransmit_skb+0xed/0x660
    [22742.143187]  [<ffffffff810e84c1>] ? mod_timer+0x1a1/0x3e0
    [22742.143187]  [<ffffffff815cd6f9>] tcp_retransmit_skb+0x19/0xe0
    [22742.143187]  [<ffffffff815cec8b>] tcp_retransmit_timer+0x2bb/0x860
    [22742.143187]  [<ffffffff815cf420>] ? tcp_write_timer_handler+0x1f0/0x1f0
    [22742.143187]  [<ffffffff815cf2be>] tcp_write_timer_handler+0x8e/0x1f0
    [22742.143187]  [<ffffffff815cf4f4>] tcp_write_timer+0xd4/0xe0
    [22742.143187]  [<ffffffff810e677e>] call_timer_fn+0x9e/0x310
    [22742.143187]  [<ffffffff810e66e5>] ? call_timer_fn+0x5/0x310
    [22742.143187]  [<ffffffff815cf420>] ? tcp_write_timer_handler+0x1f0/0x1f0
    [22742.143187]  [<ffffffff810e76b9>] run_timer_softirq+0x1c9/0x620
    [22742.143187]  [<ffffffff810f07a6>] ? ktime_get+0x96/0x120
    [22742.143187]  [<ffffffff810f7454>] ? clockevents_program_event+0x44/0x110
    [22742.143187]  [<ffffffff810f7486>] ? clockevents_program_event+0x76/0x110
    [22742.143187]  [<ffffffff81653d68>] __do_softirq+0xc8/0x473
    [22742.143187]  [<ffffffff81070828>] irq_exit+0x98/0xb0
    [22742.143187]  [<ffffffff81653a22>] smp_apic_timer_interrupt+0x42/0x50
    [22742.143187]  [<ffffffff81652ce9>] apic_timer_interrupt+0x89/0x90
    [22742.143187]  <EOI>  [<ffffffff81028083>] ? default_idle+0x23/0x180
    [22742.143187]  [<ffffffff81028085>] ? default_idle+0x25/0x180
    [22742.143187]  [<ffffffff81028083>] ? default_idle+0x23/0x180
    [22742.143187]  [<ffffffff810289ef>] arch_cpu_idle+0xf/0x20
    [22742.143187]  [<ffffffff810b5563>] default_idle_call+0x33/0x50
    [22742.143187]  [<ffffffff810b57ba>] cpu_startup_entry+0x23a/0x420
    [22742.143187]  [<ffffffff8104311b>] start_secondary+0x10b/0x130
    [22742.143187] ---[ end trace ffe85316b88c56b2 ]---
    [22742.143187] BUG: unable to handle kernel paging request at ffffeb88000366e0
    [22742.143187] IP: [<ffffffff8154a7de>] __pg_skb_alloc+0x17e/0x4a0
    [22742.143187] PGD 0 
    [22742.143187] Oops: 0000 [#1] SMP
    [22742.143187] Modules linked in: tfw_sched_ratio(O) tfw_sched_http(O) tfw_sched_hash(O) tempesta_fw(O) tempesta_db(O) tempesta_tls(O) nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack ipt_REJECT nf_reject_ipv4 tun bridge stp llc ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter ip_vs nf_conntrack dm_mirror dm_region_hash dm_log dm_mod xfs ppdev libcrc32c ghash_clmulni_intel aesni_intel aes_x86_64 glue_helper lrw gf128mul ablk_helper cryptd input_leds led_class pcspkr parport_pc parport acpi_cpufreq i2c_piix4 i2c_core uinput ip_tables btrfs xor raid6_pq ata_generic pata_acpi crc32c_intel serio_raw e1000 ata_piix floppy ipv6 crc_ccitt autofs4 [last unloaded: tempesta_tls]
    [22742.143187] CPU: 1 PID: 0 Comm: swapper/1 Tainted: G        W  O    4.8.15-tfw #45
    [22742.143187] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.1-1.fc24 04/01/2014
    [22742.143187] task: ffff88005c8e1700 task.stack: ffff88005c8e8000
    [22742.143187] RIP: 0010:[<ffffffff8154a7de>]  [<ffffffff8154a7de>] __pg_skb_alloc+0x17e/0x4a0
    [22742.143187] RSP: 0018:ffff88007fd03c60  EFLAGS: 00010206
    [22742.143187] RAX: 00000188000366c0 RBX: ffffea0000d9b8c0 RCX: 0000000000000001
    [22742.143187] RDX: 000077ff80000000 RSI: 0000000000000000 RDI: 0000000000000009
    [22742.143187] RBP: ffff88007fd03ca8 R08: 0000000000000002 R09: 0000000000000001
    [22742.143187] R10: 0000000000000000 R11: ffffea0000000000 R12: 00000000ffffffff
    [22742.143187] R13: 0000000000000001 R14: ffffeb88000366c0 R15: 00000000000153a0
    [22742.143187] FS:  0000000000000000(0000) GS:ffff88007fd00000(0000) knlGS:0000000000000000
    [22742.143187] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
    [22742.143187] CR2: ffffeb88000366e0 CR3: 000000005a497000 CR4: 00000000003406e0
    [22742.143187] Stack:
    [22742.143187]  0000000000000002 ffffea0000d9b8c0 0000000101000086 ffff88007fd153a0
    [22742.143187]  0000000000000000 0000000002080020 0000000000000300 00000000000005a8
    [22742.143187]  ffff88001ea50800 ffff88007fd03ce8 ffffffff8154b4a7 02080020815c8c3d
    [22742.143187] Call Trace:
    [22742.143187]  <IRQ> 
    [22742.143187]  [<ffffffff8154b4a7>] pskb_expand_head+0x67/0x290
    [22742.143187]  [<ffffffff815c9e8c>] tcp_fragment+0x30c/0x370
    [22742.143187]  [<ffffffff815ccf5d>] __tcp_retransmit_skb+0xed/0x660
    [22742.143187]  [<ffffffff810e84c1>] ? mod_timer+0x1a1/0x3e0
    [22742.143187]  [<ffffffff815cd6f9>] tcp_retransmit_skb+0x19/0xe0
    [22742.143187]  [<ffffffff815cec8b>] tcp_retransmit_timer+0x2bb/0x860
    [22742.143187]  [<ffffffff815cf420>] ? tcp_write_timer_handler+0x1f0/0x1f0
    [22742.143187]  [<ffffffff815cf2be>] tcp_write_timer_handler+0x8e/0x1f0
    [22742.143187]  [<ffffffff815cf4f4>] tcp_write_timer+0xd4/0xe0
    [22742.143187]  [<ffffffff810e677e>] call_timer_fn+0x9e/0x310
    [22742.143187]  [<ffffffff810e66e5>] ? call_timer_fn+0x5/0x310
    [22742.143187]  [<ffffffff815cf420>] ? tcp_write_timer_handler+0x1f0/0x1f0
    [22742.143187]  [<ffffffff810e76b9>] run_timer_softirq+0x1c9/0x620
    [22742.143187]  [<ffffffff810f07a6>] ? ktime_get+0x96/0x120
    [22742.143187]  [<ffffffff810f7454>] ? clockevents_program_event+0x44/0x110
    [22742.143187]  [<ffffffff810f7486>] ? clockevents_program_event+0x76/0x110
    [22742.143187]  [<ffffffff81653d68>] __do_softirq+0xc8/0x473
    [22742.143187]  [<ffffffff81070828>] irq_exit+0x98/0xb0
    [22742.143187]  [<ffffffff81653a22>] smp_apic_timer_interrupt+0x42/0x50
    [22742.143187]  [<ffffffff81652ce9>] apic_timer_interrupt+0x89/0x90
    [22742.143187]  <EOI> 
    [22742.143187]  [<ffffffff81028083>] ? default_idle+0x23/0x180
    [22742.143187]  [<ffffffff81028085>] ? default_idle+0x25/0x180
    [22742.143187]  [<ffffffff81028083>] ? default_idle+0x23/0x180
    [22742.143187]  [<ffffffff810289ef>] arch_cpu_idle+0xf/0x20
    [22742.143187]  [<ffffffff810b5563>] default_idle_call+0x33/0x50
    [22742.143187]  [<ffffffff810b57ba>] cpu_startup_entry+0x23a/0x420
    [22742.143187]  [<ffffffff8104311b>] start_secondary+0x10b/0x130
    [22742.143187] Code: 48 01 d8 48 0f 42 15 52 08 6c 00 49 bb 00 00 00 00 00 ea ff ff 8b 4d cc 44 8b 45 b8 48 01 d0 48 c1 e8 0c 48 c1 e0 06 4e 8d 34 18 <49> 8b 46 20 a8 01 0f 85 50 02 00 00 41 bc 01 00 00 00 41 d3 e4 
    [22742.143187] RIP  [<ffffffff8154a7de>] __pg_skb_alloc+0x17e/0x4a0
    [22742.143187]  RSP <ffff88007fd03c60>
    [22742.143187] CR2: ffffeb88000366e0
    [22742.143187] ---[ end trace ffe85316b88c56b3 ]---
    [22742.143187] Kernel panic - not syncing: Fatal exception in interrupt
    [22742.143187] Kernel Offset: disabled
krizhanovsky commented 7 years ago

After the last changes in https://github.com/tempesta-tech/tempesta/pull/757 , I still get following crash. I noticed that Apache HTTPDs EnableSendfile Off with sending large responses (~18KB) reproduces the issue much faster. Such transmissions use only one 32KB skb fragment, while sendfile() works with page cache, so fills skb fragments with normal pages. Probably there is some issue with tcp_transmit_skb(), which processes the proxied response twise and calls skb_copy_ubufs() working with normal pages... Need more investigation.

     [ 4386.381556] general protection fault: 0000 [#1] SMP
     [ 4386.382036] Modules linked in: tfw_sched_ratio(O) tfw_sched_http(O) tfw_sched_hash(O) tempesta_fw(O) tempesta_db(O) tempesta_tls(O) nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack ipt_REJECT nf_reject_ipv4 tun bridge stp llc ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter ip_vs nf_conntrack dm_mirror dm_region_hash dm_log dm_mod xfs libcrc32c ghash_clmulni_intel aesni_intel ppdev aes_x86_64 glue_helper lrw gf128mul ablk_helper cryptd input_leds led_class pcspkr parport_pc parport i2c_piix4 acpi_cpufreq i2c_core uinput ip_tables btrfs xor raid6_pq ata_generic pata_acpi crc32c_intel serio_raw e1000 ata_piix floppy ipv6 crc_ccitt autofs4 [last unloaded: tempesta_tls]
     [ 4386.382036] CPU: 0 PID: 3 Comm: ksoftirqd/0 Tainted: G           O    4.8.15-tfw #58
     [ 4386.382036] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.1-1.fc24 04/01/2014
     [ 4386.382036] task: ffff88005c832e00 task.stack: ffff88005c8a0000
     [ 4386.382036] RIP: 0010:[<ffffffff815d1805>]  [<ffffffff815d1805>] tcp_v4_destroy_sock+0x65/0x2d0
     [ 4386.382036] RSP: 0018:ffff88005c8a3968  EFLAGS: 00010206
     [ 4386.382036] RAX: 70612f6f63692f67 RBX: ffff880010326680 RCX: 0000000000000000
     [ 4386.382036] RDX: 6d69223d66657268 RSI: ffff8800103269c8 RDI: 0000000000000000
     [ 4386.382036] RBP: ffff88005c8a3988 R08: 0000000000000000 R09: 0000000000000000
     [ 4386.382036] R10: 0000000000000001 R11: 0000000000000001 R12: ffff88001fe68800
     [ 4386.382036] R13: ffff880010326870 R14: ffff8800103266e0 R15: ffff880010326680
     [ 4386.382036] FS:  0000000000000000(0000) GS:ffff88007fc00000(0000) knlGS:0000000000000000
     [ 4386.382036] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
     [ 4386.382036] CR2: 00007fab0c895000 CR3: 0000000001c06000 CR4: 00000000003406f0
     [ 4386.382036] Stack:
     [ 4386.382036]  ffff880010326680 0000000000000000 ffff8800250a2bb0 0000000000000000
     [ 4386.382036]  ffff88005c8a39a0 ffffffff815b7d4f ffff880010326680 ffff88005c8a39c0
     [ 4386.382036]  ffffffff815ba464 ffff880010326680 ffff8800250a2a00 ffff88005c8a3a38
     [ 4386.382036] Call Trace:
     [ 4386.382036]  [<ffffffff815b7d4f>] inet_csk_destroy_sock+0x4f/0x170
     [ 4386.382036]  [<ffffffff815ba464>] tcp_done+0x64/0x90
     [ 4386.382036]  [<ffffffff815c82a6>] tcp_rcv_state_process+0x956/0xe00
     [ 4386.382036]  [<ffffffff815d408a>] ? tcp_v4_rcv+0xa2a/0xcc0
     [ 4386.382036]  [<ffffffff810be849>] ? __lock_is_held+0x49/0x70
     [ 4386.382036]  [<ffffffff815d2ac9>] tcp_v4_do_rcv+0x79/0x210
     [ 4386.382036]  [<ffffffff815d412c>] tcp_v4_rcv+0xacc/0xcc0
     [ 4386.382036]  [<ffffffff815aa723>] ip_local_deliver_finish+0x133/0x3b0
     [ 4386.382036]  [<ffffffff815aa631>] ? ip_local_deliver_finish+0x41/0x3b0
     [ 4386.382036]  [<ffffffff815ab250>] ip_local_deliver+0xc0/0xd0
     [ 4386.382036]  [<ffffffff815aa5f0>] ? inet_del_offload+0x40/0x40
     [ 4386.382036]  [<ffffffff815aab4f>] ip_rcv_finish+0x1af/0x610
     [ 4386.382036]  [<ffffffff815ab549>] ip_rcv+0x2e9/0x410
     [ 4386.382036]  [<ffffffff815aa9a0>] ? ip_local_deliver_finish+0x3b0/0x3b0
     [ 4386.382036]  [<ffffffff8155dd25>] __netif_receive_skb_core+0x3a5/0xb40
     [ 4386.382036]  [<ffffffff8155e600>] ? process_backlog+0xe0/0x230
     [ 4386.382036]  [<ffffffff8155e4dd>] __netif_receive_skb+0x1d/0x60
     [ 4386.457744]  [<ffffffff8155e598>] process_backlog+0x78/0x230
     [ 4386.457744]  [<ffffffff8155e600>] ? process_backlog+0xe0/0x230
     [ 4386.457744]  [<ffffffff8156076e>] net_rx_action+0x14e/0x440
     [ 4386.457744]  [<ffffffff81653c28>] __do_softirq+0xc8/0x473
     [ 4386.457744]  [<ffffffff810705cf>] run_ksoftirqd+0x1f/0x60
     [ 4386.457744]  [<ffffffff81091819>] smpboot_thread_fn+0x139/0x200
     [ 4386.457744]  [<ffffffff810916e0>] ? sort_range+0x30/0x30
     [ 4386.457744]  [<ffffffff8108dc48>] kthread+0xf8/0x110
     [ 4386.457744]  [<ffffffff816514bf>] ret_from_fork+0x1f/0x40
     [ 4386.457744]  [<ffffffff8108db50>] ? kthread_create_on_node+0x200/0x200
     [ 4386.457744] Code: 0f 84 89 00 00 00 4c 8d 73 60 83 ab 00 02 00 00 01 49 8b 14 24 49 8b 44 24 08 49 c7 04 24 00 00 00 00 49 c7 44 24 08 00 00 00 00 <48> 89 42 08 48 89 10 41 0f ba 2e 0e 48 8b 53 28 41 8b 84 24 f0 
     [ 4386.457744] RIP  [<ffffffff815d1805>] tcp_v4_destroy_sock+0x65/0x2d0
     [ 4386.457744]  RSP <ffff88005c8a3968>
     [ 4386.485314] ---[ end trace dc99f206f1e9e50f ]---
     [ 4386.486686] Kernel panic - not syncing: Fatal exception in interrupt
keshonok commented 7 years ago

For completeness, the issue is still present in the combination of the new kernel 4.9.35 at https://github.com/tempesta-tech/linux-4.9.35-tfw/commit/1d9fd7abef7457b64cbb200479c1b2c7b65d8f6a and the latest changes in ak-692 branch of Tempesta at https://github.com/tempesta-tech/tempesta/pull/757/commits/c2b5c53eb1eaec57c7a45a36142bb0e1da4b2fcb.

[ 1309.169838] tempesta_tls: loading out-of-tree module taints kernel.
[ 1309.587018] [tdb] Start Tempesta DB
[ 1309.600494] [tempesta] Initializing Tempesta FW kernel module...
[ 1309.651926] [tempesta] Registering new scheduler: hash
[ 1309.655576] [tempesta] Registering new scheduler: http
[ 1309.659270] [tempesta] Registering new scheduler: ratio
[ 1309.671160] [tempesta] Starting all modules...
[ 1309.688253] [tdb] Opened table /opt/tempesta/db/filter.tdb: size=16777216 rec_size=20 base=ffff880187c00000
[ 1309.689600] [tempesta] Open listen socket on: 0.0.0.0
[ 1309.690357] [tempesta] modules are started
[ 1343.829554] TCP: request_sock_TCP: Possible SYN flooding on port 8081. Sending cookies.  Check SNMP counters.
[ 1389.441586] TCP: request_sock_TCP: Possible SYN flooding on port 80. Sending cookies.  Check SNMP counters.
[ 1414.077563] perf: interrupt took too long (10068 > 10062), lowering kernel.perf_event_max_sample_rate to 19000
[ 1474.296678] perf: interrupt took too long (12594 > 12585), lowering kernel.perf_event_max_sample_rate to 15000
[ 1597.003008] perf: interrupt took too long (15994 > 15742), lowering kernel.perf_event_max_sample_rate to 12000
[ 1636.641009] perf: interrupt took too long (20424 > 19992), lowering kernel.perf_event_max_sample_rate to 9000
[ 1846.550394] kasan: CONFIG_KASAN_INLINE enabled
[ 1846.551172] kasan: GPF could be caused by NULL-ptr deref or user memory access
[ 1846.552660] general protection fault: 0000 [#1] SMP KASAN
[ 1846.553306] Modules linked in: tfw_sched_ratio(O) tfw_sched_http(O) tfw_sched_hash(O) tempesta_fw(O) tempesta_db(O) tempesta_tls(O) ghash_clmulni_intel aesni_intel aes_x86_64 glue_helper lrw gf128mul ppdev 9pnet_virtio ablk_helper cryptd 9pnet input_leds virtio_balloon i2c_piix4 i2c_core pcspkr led_class parport_pc parport ip_tables ata_generic pata_acpi crc32c_intel serio_raw virtio_pci virtio_ring e1000 virtio ata_piix floppy ipv6 crc_ccitt autofs4
[ 1846.553651] CPU: 3 PID: 28 Comm: ksoftirqd/3 Tainted: G           O    4.9.35-ab+ #1
[ 1846.553651] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
[ 1846.553651] task: ffff8801675d0040 task.stack: ffff8801675d8000
[ 1846.553651] RIP: 0010:[<ffffffff82144a5d>]  [<ffffffff82144a5d>] tcp_clean_rtx_queue+0x52d/0x3480
[ 1846.553651] RSP: 0018:ffff8801675df0a8  EFLAGS: 00010202
[ 1846.553651] RAX: 0000000000000000 RBX: ffff88015f96af40 RCX: 0000000000000000
[ 1846.553651] RDX: 0000000000000001 RSI: ffff880126abea00 RDI: 0000000000000008
[ 1846.553651] RBP: ffff8801675df1d0 R08: ffff880126abea35 R09: 0000000000000000
[ 1846.553651] R10: 0000000000000000 R11: 0000000000000000 R12: ffff880126abea00
[ 1846.553651] R13: dffffc0000000000 R14: ffff8801675df360 R15: 0000000000000000
[ 1846.553651] FS:  0000000000000000(0000) GS:ffff880188f80000(0000) knlGS:0000000000000000
[ 1846.553651] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 1846.553651] CR2: 00007fad6bb4fa08 CR3: 000000015ffb2000 CR4: 00000000001406e0
[ 1846.553651] Stack:
[ 1846.553651]  ffff8801675d0850 000000000000001d 3a1a3b0da300a05f 0000000000000000
[ 1846.553651]  ffff88015f96b320 0000000081261797 001799266e0fdc60 1ffff1002cebbe29
[ 1846.553651]  0349cd0000000000 ffff880115f1f601 0000000000000b50 ffffed002bf2d664
[ 1846.553651] Call Trace:
[ 1846.553651]  [<ffffffff82144530>] ? tcp_rtt_estimator+0x7f0/0x7f0
[ 1846.553651]  [<ffffffff821505e6>] tcp_ack+0x1016/0x32e0
[ 1846.553651]  [<ffffffff8214f5d0>] ? tcp_fastretrans_alert+0x3450/0x3450
[ 1846.553651]  [<ffffffff8121cfe6>] ? __lock_acquire+0xaa6/0x3a90
[ 1846.553651]  [<ffffffff8121c540>] ? debug_check_no_locks_freed+0x280/0x280
[ 1846.553651]  [<ffffffff81261797>] ? debug_lockdep_rcu_enabled+0x77/0x90
[ 1846.553651]  [<ffffffff8215ee2c>] tcp_rcv_state_process+0x8bc/0x4090
[ 1846.553651]  [<ffffffff8204df13>] ? sk_filter_trim_cap+0x283/0x700
[ 1846.553651]  [<ffffffff8215e570>] ? tcp_finish_connect+0x670/0x670
[ 1846.553651]  [<ffffffff8204df32>] ? sk_filter_trim_cap+0x2a2/0x700
[ 1846.553651]  [<ffffffff8204dd66>] ? sk_filter_trim_cap+0xd6/0x700
[ 1846.553651]  [<ffffffff8219472e>] ? tcp_v4_rcv+0x1f3e/0x2f80
[ 1846.553651]  [<ffffffff8218fcc8>] tcp_v4_do_rcv+0x2c8/0x8c0
[ 1846.553651]  [<ffffffff8219574d>] tcp_v4_rcv+0x2f5d/0x2f80
[ 1846.553651]  [<ffffffff820e370b>] ip_local_deliver_finish+0x2cb/0x9b0
[ 1846.553651]  [<ffffffff820e356a>] ? ip_local_deliver_finish+0x12a/0x9b0
[ 1846.553651]  [<ffffffff820e4680>] ip_local_deliver+0x380/0x450
[ 1846.553651]  [<ffffffff820e4495>] ? ip_local_deliver+0x195/0x450
[ 1846.553651]  [<ffffffff820e4300>] ? ip_call_ra_chain+0x510/0x510
[ 1846.553651]  [<ffffffff820bcbeb>] ? nf_iterate+0x1cb/0x2d0
[ 1846.553651]  [<ffffffff81261797>] ? debug_lockdep_rcu_enabled+0x77/0x90
[ 1846.553651]  [<ffffffff820bcdd3>] ? nf_hook_slow+0xe3/0x190
[ 1846.553651]  [<ffffffff820e2169>] ip_rcv_finish+0x599/0x1870
[ 1846.553651]  [<ffffffff820e504d>] ? ip_rcv+0x8fd/0x1300
[ 1846.553651]  [<ffffffff820e5088>] ip_rcv+0x938/0x1300
[ 1846.553651]  [<ffffffff820e4f58>] ? ip_rcv+0x808/0x1300
[ 1846.553651]  [<ffffffff820e4750>] ? ip_local_deliver+0x450/0x450
[ 1846.553651]  [<ffffffff820e1bd0>] ? inet_del_offload+0x40/0x40
[ 1846.553651]  [<ffffffff820e4750>] ? ip_local_deliver+0x450/0x450
[ 1846.553651]  [<ffffffff81ff7fd0>] __netif_receive_skb_core+0x1690/0x2cf0
[ 1846.553651]  [<ffffffff8121c540>] ? debug_check_no_locks_freed+0x280/0x280
[ 1846.553651]  [<ffffffff81ff6940>] ? net_tx_action+0x9d0/0x9d0
[ 1846.553651]  [<ffffffff8121c540>] ? debug_check_no_locks_freed+0x280/0x280
[ 1846.553651]  [<ffffffff8217efa0>] ? tcp_delack_timer+0x20/0x200
[ 1846.553651]  [<ffffffff81261797>] ? debug_lockdep_rcu_enabled+0x77/0x90
[ 1846.553651]  [<ffffffff81ff99be>] ? process_backlog+0x1fe/0x5f0
[ 1846.553651]  [<ffffffff81ff968a>] __netif_receive_skb+0x5a/0x190
[ 1846.553651]  [<ffffffff81ff9891>] process_backlog+0xd1/0x5f0
[ 1846.553651]  [<ffffffff81ff99be>] ? process_backlog+0x1fe/0x5f0
[ 1846.553651]  [<ffffffff81ffe925>] net_rx_action+0x655/0xde0
[ 1846.553651]  [<ffffffff81ffe2d0>] ? sk_busy_loop+0xba0/0xba0
[ 1846.553651]  [<ffffffff81ff6298>] ? net_tx_action+0x328/0x9d0
[ 1846.553651]  [<ffffffff810779b8>] ? __kernel_fpu_end_bh+0x98/0x170
[ 1846.553651]  [<ffffffff8232cae1>] __do_softirq+0x221/0x97d
[ 1846.553651]  [<ffffffff8112ea00>] ? takeover_tasklets+0x830/0x830
[ 1846.553651]  [<ffffffff8112ea1f>] run_ksoftirqd+0x1f/0x60
[ 1846.553651]  [<ffffffff81185ec4>] smpboot_thread_fn+0x3d4/0x840
[ 1846.553651]  [<ffffffff81185af0>] ? smpboot_update_cpumask_percpu_thread+0x590/0x590
[ 1846.553651]  [<ffffffff8231a454>] ? schedule+0x94/0x1b0
[ 1846.553651]  [<ffffffff8117abe2>] ? __kthread_parkme+0xe2/0x210
[ 1846.553651]  [<ffffffff81185af0>] ? smpboot_update_cpumask_percpu_thread+0x590/0x590
[ 1846.553651]  [<ffffffff8117b417>] kthread+0x247/0x310
[ 1846.553651]  [<ffffffff8117b1d0>] ? kthread_park+0x80/0x80
[ 1846.553651]  [<ffffffff8117b1d0>] ? kthread_park+0x80/0x80
[ 1846.553651]  [<ffffffff8117b1d0>] ? kthread_park+0x80/0x80
[ 1846.553651]  [<ffffffff82329e07>] ret_from_fork+0x27/0x40
[ 1846.553651] Code: 80 3c 2a 00 0f 85 e0 2c 00 00 48 8d 78 08 4d 8b 7c 24 08 49 c7 04 24 00 00 00 00 49 c7 44 24 08 00 00 00 00 48 89 fa 48 c1 ea 03 <42> 80 3c 2a 00 0f 85 9c 2c 00 00 4c 89 fa 4c 89 78 08 48 c1 ea
[ 1846.553651] RIP  [<ffffffff82144a5d>] tcp_clean_rtx_queue+0x52d/0x3480
[ 1846.553651]  RSP <ffff8801675df0a8>
krizhanovsky commented 7 years ago

After 1 hour test caught crash at the below, which is essentially #693. Master after merge https://github.com/tempesta-tech/tempesta/pull/771 was used.

    [50405.505617] BUG: unable to handle kernel paging request at ffff8c024a994a14
    [50405.505617] IP: [<ffffffffa6f19de5>] tcp_rearm_rto.part.63+0x75/0x80
    [50405.505617] PGD 2200b067 [50405.505617] PUD 2200f067 
    PMD 7fcb3067 [50405.505617] PTE 800000004a994163
    [50405.505617] 
    [50405.505617] Oops: 0000 [#1] SMP DEBUG_PAGEALLOC
    [50405.505617] Modules linked in: tcp_diag inet_diag tfw_sched_ratio(O) tfw_sched_http(O) tfw_sched_hash(O) tempesta_fw(O) tempesta_db(O) tempesta_tls(O) crct10dif_pclmul crc32_pclmul ghash_clmulni_intel aesni_intel bochs_drm ttm drm_kms_helper drm aes_x86_64 lrw gf128mul glue_helper ablk_helper cryptd fb_sys_fops syscopyarea sysfillrect ppdev sg sysimgblt input_leds led_class serio_raw pcspkr button parport_pc parport ip_tables x_tables autofs4 ext4 crc16 jbd2 fscrypto mbcache sr_mod cdrom sd_mod ata_generic psmouse ata_piix e1000 libata crc32c_intel scsi_mod i2c_piix4 floppy [last unloaded: tempesta_tls]
    [50405.505617] CPU: 3 PID: 28 Comm: ksoftirqd/3 Tainted: G           O    4.9.35 #11
    [50405.505617] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.1-1.fc24 04/01/2014
    [50405.505617] task: ffff8c025c9aa7c0 task.stack: ffffb22dc040c000
    [50405.505617] RIP: 0010:[<ffffffffa6f19de5>]  [<ffffffffa6f19de5>] tcp_rearm_rto.part.63+0x75/0x80
    [50405.505617] RSP: 0018:ffffb22dc040fc08  EFLAGS: 00010293
    [50405.505617] RAX: 00000000ff40dd0d RBX: ffff8c023e3a9480 RCX: ffff8c024a994a00
    [50405.505617] RDX: 0000000000000034 RSI: 00000000ff40dd0d RDI: ffff8c023e3a9480
    [50405.505617] RBP: ffffb22dc040fc08 R08: 000000000828e03e R09: 677409d400000000
    [50405.505617] R10: 0000000000000001 R11: 0000000000000001 R12: ffff8c0205308400
    [50405.505617] R13: 0000000000000000 R14: 000000000000000b R15: ffff8c023e3a9480
    [50405.505617] FS:  0000000000000000(0000) GS:ffff8c027f980000(0000) knlGS:0000000000000000
    [50405.505617] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
    [50405.505617] CR2: ffff8c024a994a14 CR3: 0000000049464000 CR4: 00000000003406e0
    [50405.505617] Stack:
    [50405.505617]  ffffb22dc040fc18 ffffffffa6f1fd9f ffffb22dc040fc38 ffffffffa6f2362d
    [50405.505617]  000000000000e3c0 ffff8c0205308400 ffffb22dc040fcb0 ffffffffa6f257d0
    [50405.505617]  000000000000e3c0 0000000000000040 0000000400000000 ffffb22d00000002
    [50405.505617] Call Trace:
    [50405.505617]  [<ffffffffa6f1fd9f>] tcp_rearm_rto+0x1f/0x30
    [50405.505617]  [<ffffffffa6f2362d>] tcp_event_new_data_sent+0x7d/0x80
    [50405.505617]  [<ffffffffa6f257d0>] tcp_write_xmit+0x370/0xef0
    [50405.505617]  [<ffffffffa6f2637c>] __tcp_push_pending_frames+0x2c/0xa0
    [50405.505617]  [<ffffffffa6f12ef9>] tcp_push+0xe9/0x110
    [50405.505617]  [<ffffffffc07b0361>] ss_tx_action+0x4f1/0x560 [tempesta_fw]
    [50405.505617]  [<ffffffffc07afe70>] ? ss_tcp_data_ready+0x90/0x90 [tempesta_fw]
    [50405.505617]  [<ffffffffa6eb799d>] net_tx_action+0xed/0x280
    [50405.505617]  [<ffffffffa6eb7940>] ? net_tx_action+0x90/0x280
    [50405.505617]  [<ffffffffa6a65b3e>] __do_softirq+0x11e/0x250
    [50405.505617]  [<ffffffffa6a86690>] ? sort_range+0x20/0x20
    [50405.505617]  [<ffffffffa6a65c8a>] run_ksoftirqd+0x1a/0x40
    [50405.505617]  [<ffffffffa6a86795>] smpboot_thread_fn+0x105/0x160
    [50405.505617]  [<ffffffffa6a8296c>] kthread+0xfc/0x120
    [50405.505617]  [<ffffffffa6a82870>] ? kthread_park+0x60/0x60
    [50405.505617]  [<ffffffffa6fe7437>] ret_from_fork+0x27/0x40
    [50405.505617] Code: f8 ff 5d c3 48 8b 8f f0 01 00 00 48 8d 87 f0 01 00 00 89 d6 48 39 c1 b8 00 00 00 00 48 0f 44 c8 48 8b 05 1f b2 4e 00 29 c6 89 f0 <03> 41 14 85 c0 48 0f 4f d0 eb 98 39 b7 34 08 00 00 55 48 89 e5 
    [50405.505617] RIP  [<ffffffffa6f19de5>] tcp_rearm_rto.part.63+0x75/0x80
    [50405.505617]  RSP <ffffb22dc040fc08>
    [50405.505617] CR2: ffff8c024a994a14
    [50405.505617] ---[ end trace f6179d8549ef2e56 ]---
keshonok commented 7 years ago

I can confirm that after the merge of #771 similar crashes still occur in the neighbourhood of tcp_ack(). It appears though that crashes are more likely to occur when a backend is in the same VM as Tempesta itself, but that's very subjective.

[  280.036456] kasan: CONFIG_KASAN_INLINE enabled
[  280.037688] kasan: GPF could be caused by NULL-ptr deref or user memory access
[  280.038717] general protection fault: 0000 [#1] SMP KASAN
[  280.039361] Modules linked in: tfw_sched_ratio(O) tfw_sched_http(O) tfw_sched_hash(O) tempesta_fw(O) tempesta_db(O) tempesta_tls(O) ghash_clmulni_intel aesni_intel aes_x86_64 ppdev 9pnet_virtio glue_helper 9pnet lrw gf128mul ablk_helper cryptd virtio_balloon parport_pc input_leds led_class i2c_piix4 i2c_core parport pcspkr ip_tables ata_generic pata_acpi crc32c_intel serio_raw virtio_pci virtio_ring virtio e1000 ata_piix floppy ipv6 crc_ccitt autofs4
[  280.039710] CPU: 3 PID: 28 Comm: ksoftirqd/3 Tainted: G           O    4.9.35-ab+ #2
[  280.039710] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
[  280.039710] task: ffff88038ca10040 task.stack: ffff88038ca18000
[  280.039710] RIP: 0010:[<ffffffff821a8db2>]  [<ffffffff821a8db2>] tcp_rack_mark_lost+0x1f2/0x8f0
[  280.039710] RSP: 0018:ffff88038ca1f110  EFLAGS: 00010206
[  280.039710] RAX: 0d0408aa0b2a886f RBX: 682045505954434f RCX: ffff880387cb7435
[  280.039710] RDX: ffff88037042d660 RSI: 0000000000000005 RDI: 682045505954437b
[  280.039710] RBP: ffff88038ca1f180 R08: ffff88037042daec R09: ffff88037042daa4
[  280.039710] R10: 00000000fffffe2b R11: 0000000000000000 R12: dffffc0000000000
[  280.039710] R13: ffff88037042d280 R14: ffff88037042d9f0 R15: ffff88037042d470
[  280.039710] FS:  0000000000000000(0000) GS:ffff8803aef80000(0000) knlGS:0000000000000000
[  280.039710] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  280.039710] CR2: 00007f5cccfee000 CR3: 0000000002a0e000 CR4: 00000000001406e0
[  280.039710] Stack:
[  280.039710]  1ffff10071943e2f fff3006d00000000 ffffffff82d80dc0 0000000b00000000
[  280.039710]  ffffed006e085acc ffff88038ca1f2d0 ffff88037042d9f0 000003e800000001
[  280.039710]  ffffed006e085b54 ffff88037042d280 0000000000004101 ffff88037042db84
[  280.039710] Call Trace:
[  280.039710]  [<ffffffff8214d851>] tcp_fastretrans_alert+0x16d1/0x3450
[  280.039710]  [<ffffffff8215062c>] tcp_ack+0x105c/0x32e0
[  280.039710]  [<ffffffff8214f5d0>] ? tcp_fastretrans_alert+0x3450/0x3450
[  280.039710]  [<ffffffff8121c540>] ? debug_check_no_locks_freed+0x280/0x280
[  280.039710]  [<ffffffff8121c540>] ? debug_check_no_locks_freed+0x280/0x280
[  280.039710]  [<ffffffff8215b2fd>] tcp_rcv_established+0x57d/0x2dc0
[  280.039710]  [<ffffffff8204df32>] ? sk_filter_trim_cap+0x2a2/0x700
[  280.039710]  [<ffffffff8204dd66>] ? sk_filter_trim_cap+0xd6/0x700
[  280.039710]  [<ffffffff8215ad80>] ? tcp_data_queue+0x4da0/0x4da0
[  280.039710]  [<ffffffff82194733>] ? tcp_v4_rcv+0x1f43/0x2f80
[  280.039710]  [<ffffffff8218ff29>] tcp_v4_do_rcv+0x529/0x8c0
[  280.039710]  [<ffffffff82195752>] tcp_v4_rcv+0x2f62/0x2f80
[  280.039710]  [<ffffffff820e370b>] ip_local_deliver_finish+0x2cb/0x9b0
[  280.039710]  [<ffffffff820e356a>] ? ip_local_deliver_finish+0x12a/0x9b0
[  280.039710]  [<ffffffff820e4680>] ip_local_deliver+0x380/0x450
[  280.039710]  [<ffffffff820e4495>] ? ip_local_deliver+0x195/0x450
[  280.039710]  [<ffffffff820e4300>] ? ip_call_ra_chain+0x510/0x510
[  280.039710]  [<ffffffff820bcbeb>] ? nf_iterate+0x1cb/0x2d0
[  280.039710]  [<ffffffff81261797>] ? debug_lockdep_rcu_enabled+0x77/0x90
[  280.039710]  [<ffffffff820bcdd3>] ? nf_hook_slow+0xe3/0x190
[  280.039710]  [<ffffffff820e2169>] ip_rcv_finish+0x599/0x1870
[  280.039710]  [<ffffffff820e504d>] ? ip_rcv+0x8fd/0x1300
[  280.039710]  [<ffffffff820e5088>] ip_rcv+0x938/0x1300
[  280.039710]  [<ffffffff820e4f58>] ? ip_rcv+0x808/0x1300
[  280.039710]  [<ffffffff820e4750>] ? ip_local_deliver+0x450/0x450
[  280.039710]  [<ffffffff820e1bd0>] ? inet_del_offload+0x40/0x40
[  280.039710]  [<ffffffff820e4750>] ? ip_local_deliver+0x450/0x450
[  280.039710]  [<ffffffff81ff7fd0>] __netif_receive_skb_core+0x1690/0x2cf0
[  280.039710]  [<ffffffff8121c540>] ? debug_check_no_locks_freed+0x280/0x280
[  280.039710]  [<ffffffff81ff6940>] ? net_tx_action+0x9d0/0x9d0
[  280.039710]  [<ffffffffa0201da0>] ? e1000_clean+0x9c0/0x26a0 [e1000]
[  280.039710]  [<ffffffff81261797>] ? debug_lockdep_rcu_enabled+0x77/0x90
[  280.039710]  [<ffffffff8143455e>] ? free_one_page+0x3e/0x9c0
[  280.039710]  [<ffffffff81ff99be>] ? process_backlog+0x1fe/0x5f0
[  280.039710]  [<ffffffff81ff968a>] __netif_receive_skb+0x5a/0x190
[  280.039710]  [<ffffffff81ff9891>] process_backlog+0xd1/0x5f0
[  280.039710]  [<ffffffff81ff99be>] ? process_backlog+0x1fe/0x5f0
[  280.039710]  [<ffffffffa02013e0>] ? e1000_unmap_and_free_tx_resource.isra.46+0x3e0/0x3e0 [e1000]
[  280.039710]  [<ffffffff81ffe925>] net_rx_action+0x655/0xde0
[  280.039710]  [<ffffffff812685af>] ? note_gp_changes+0xaf/0x1c0
[  280.039710]  [<ffffffff81ffe2d0>] ? sk_busy_loop+0xba0/0xba0
[  280.039710]  [<ffffffff8126f9d7>] ? rcu_process_callbacks+0xe37/0x1320
[  280.039710]  [<ffffffff810779b8>] ? __kernel_fpu_end_bh+0x98/0x170
[  280.039710]  [<ffffffff8232cae1>] __do_softirq+0x221/0x97d
[  280.039710]  [<ffffffff8112ea00>] ? takeover_tasklets+0x830/0x830
[  280.039710]  [<ffffffff8112ea1f>] run_ksoftirqd+0x1f/0x60
[  280.039710]  [<ffffffff81185ec4>] smpboot_thread_fn+0x3d4/0x840
[  280.039710]  [<ffffffff81185af0>] ? smpboot_update_cpumask_percpu_thread+0x590/0x590
[  280.039710]  [<ffffffff8231a454>] ? schedule+0x94/0x1b0
[  280.039710]  [<ffffffff8117abe2>] ? __kthread_parkme+0xe2/0x210
[  280.039710]  [<ffffffff81185af0>] ? smpboot_update_cpumask_percpu_thread+0x590/0x590
[  280.039710]  [<ffffffff8117b417>] kthread+0x247/0x310
[  280.039710]  [<ffffffff8117b1d0>] ? kthread_park+0x80/0x80
[  280.039710]  [<ffffffff8117b1d0>] ? kthread_park+0x80/0x80
[  280.039710]  [<ffffffff8117b1d0>] ? kthread_park+0x80/0x80
[  280.039710]  [<ffffffff8117b1d0>] ? kthread_park+0x80/0x80
[  280.039710]  [<ffffffff82329e07>] ret_from_fork+0x27/0x40
[  280.039710] Code: 00 48 89 d0 48 c1 e8 03 42 80 3c 20 00 0f 85 72 06 00 00 49 39 9d e0 03 00 00 0f 84 96 03 00 00 48 8d 7b 2c 48 89 f8 48 c1 e8 03 <42> 0f b6 0c 20 48 89 f8 83 e0 07 83 c0 03 38 c8 7c 08 84 c9 0f
[  280.039710] RIP  [<ffffffff821a8db2>] tcp_rack_mark_lost+0x1f2/0x8f0
[ 1364.025981] kasan: CONFIG_KASAN_INLINE enabled
[ 1364.031013] kasan: GPF could be caused by NULL-ptr deref or user memory access
[ 1364.033882] general protection fault: 0000 [#1] SMP KASAN
[ 1364.034528] Modules linked in: tfw_sched_ratio(O) tfw_sched_http(O) tfw_sched_hash(O) tempesta_fw(O) tempesta_db(O) tempesta_tls(O) ppdev ghash_clmulni_intel aesni_intel aes_x86_64 glue_helper lrw gf128mul ablk_helper cryptd input_leds pcspkr 9pnet_virtio virtio_balloon i2c_piix4 led_class 9pnet parport_pc parport i2c_core ip_tables ata_generic pata_acpi crc32c_intel serio_raw virtio_pci virtio_ring virtio e1000 ata_piix floppy ipv6 crc_ccitt autofs4
[ 1364.035792] CPU: 0 PID: 3 Comm: ksoftirqd/0 Tainted: G           O    4.9.35-ab+ #2
[ 1364.035792] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
[ 1364.035792] task: ffff88038c841840 task.stack: ffff88038c880000
[ 1364.035792] RIP: 0010:[<ffffffff82141667>]  [<ffffffff82141667>] tcp_sacktag_write_queue+0x10d7/0x37b0
[ 1364.035792] RSP: 0018:ffff88038c8870b8  EFLAGS: 00010206
[ 1364.035792] RAX: 0cae6dee0dadec72 RBX: 65736f706d6f6365 RCX: ffff880385a8e030
[ 1364.035792] RDX: 000000000000223e RSI: 0000000000000000 RDI: 65736f706d6f6391
[ 1364.035792] RBP: ffff88038c887200 R08: 0000000000000000 R09: 0000000000000001
[ 1364.035792] R10: ffff880385a8e7b8 R11: ffff88038c887390 R12: 000000008426baca
[ 1364.035792] R13: ffff880385a8e7b8 R14: ffff880385a8de40 R15: dffffc0000000000
[ 1364.035792] FS:  0000000000000000(0000) GS:ffff8803aee00000(0000) knlGS:0000000000000000
[ 1364.035792] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 1364.035792] CR2: 00007f280a109000 CR3: 0000000002a0e000 CR4: 00000000001406f0
[ 1364.035792] Stack:
[ 1364.035792]  0000000000000000 ffff88038c8870d0 ffffffff81261797 ffff88038c887188
[ 1364.035792]  ffff880385a8e220 0000000000000296 0000000000000003 1ffff10071910e2f
[ 1364.035792]  ffff88038c8873b0 ffff880385a8e6a8 ffff880385a8e748 ffffed0070b51c44
[ 1364.035792] Call Trace:
[ 1364.035792]  [<ffffffff81261797>] ? debug_lockdep_rcu_enabled+0x77/0x90
[ 1364.035792]  [<ffffffff820fe0d4>] ? ip_queue_xmit+0x804/0x1bc0
[ 1364.035792]  [<ffffffff82140590>] ? tcp_sacktag_walk+0x1570/0x1570
[ 1364.035792]  [<ffffffff82150853>] tcp_ack+0x1283/0x32e0
[ 1364.035792]  [<ffffffff8214f5d0>] ? tcp_fastretrans_alert+0x3450/0x3450
[ 1364.035792]  [<ffffffff8121c540>] ? debug_check_no_locks_freed+0x280/0x280
[ 1364.035792]  [<ffffffff8121c540>] ? debug_check_no_locks_freed+0x280/0x280
[ 1364.035792]  [<ffffffff8215b2fd>] tcp_rcv_established+0x57d/0x2dc0
[ 1364.035792]  [<ffffffff8204df32>] ? sk_filter_trim_cap+0x2a2/0x700
[ 1364.035792]  [<ffffffff8204dd66>] ? sk_filter_trim_cap+0xd6/0x700
[ 1364.035792]  [<ffffffff8215ad80>] ? tcp_data_queue+0x4da0/0x4da0
[ 1364.035792]  [<ffffffff82194733>] ? tcp_v4_rcv+0x1f43/0x2f80
[ 1364.035792]  [<ffffffff8218ff29>] tcp_v4_do_rcv+0x529/0x8c0
[ 1364.035792]  [<ffffffff82195752>] tcp_v4_rcv+0x2f62/0x2f80
[ 1364.035792]  [<ffffffff820e370b>] ip_local_deliver_finish+0x2cb/0x9b0
[ 1364.035792]  [<ffffffff820e356a>] ? ip_local_deliver_finish+0x12a/0x9b0
[ 1364.035792]  [<ffffffff820e4680>] ip_local_deliver+0x380/0x450
[ 1364.035792]  [<ffffffff820e4495>] ? ip_local_deliver+0x195/0x450
[ 1364.035792]  [<ffffffff820e4300>] ? ip_call_ra_chain+0x510/0x510
[ 1364.035792]  [<ffffffff820bcbeb>] ? nf_iterate+0x1cb/0x2d0
[ 1364.035792]  [<ffffffff81261797>] ? debug_lockdep_rcu_enabled+0x77/0x90
[ 1364.035792]  [<ffffffff820bcdd3>] ? nf_hook_slow+0xe3/0x190
[ 1364.035792]  [<ffffffff820e2169>] ip_rcv_finish+0x599/0x1870
[ 1364.035792]  [<ffffffff820e504d>] ? ip_rcv+0x8fd/0x1300
[ 1364.035792]  [<ffffffff820e5088>] ip_rcv+0x938/0x1300
[ 1364.035792]  [<ffffffff820e4f58>] ? ip_rcv+0x808/0x1300
[ 1364.035792]  [<ffffffff820e4750>] ? ip_local_deliver+0x450/0x450
[ 1364.035792]  [<ffffffff820e1bd0>] ? inet_del_offload+0x40/0x40
[ 1364.035792]  [<ffffffff820e4750>] ? ip_local_deliver+0x450/0x450
[ 1364.035792]  [<ffffffff81ff7fd0>] __netif_receive_skb_core+0x1690/0x2cf0
[ 1364.035792]  [<ffffffff8121c540>] ? debug_check_no_locks_freed+0x280/0x280
[ 1364.035792]  [<ffffffff81ff6940>] ? net_tx_action+0x9d0/0x9d0
[ 1364.035792]  [<ffffffff8112ca95>] ? __local_bh_enable_ip+0x65/0xb0
[ 1364.035792]  [<ffffffff81261797>] ? debug_lockdep_rcu_enabled+0x77/0x90
[ 1364.035792]  [<ffffffff81261797>] ? debug_lockdep_rcu_enabled+0x77/0x90
[ 1364.035792]  [<ffffffff81ff99be>] ? process_backlog+0x1fe/0x5f0
[ 1364.035792]  [<ffffffff81ff968a>] __netif_receive_skb+0x5a/0x190
[ 1364.035792]  [<ffffffff81ff9891>] process_backlog+0xd1/0x5f0
[ 1364.035792]  [<ffffffff81ff99be>] ? process_backlog+0x1fe/0x5f0
[ 1364.035792]  [<ffffffff8121c540>] ? debug_check_no_locks_freed+0x280/0x280
[ 1364.035792]  [<ffffffff81ffe925>] net_rx_action+0x655/0xde0
[ 1364.035792]  [<ffffffff812685af>] ? note_gp_changes+0xaf/0x1c0
[ 1364.035792]  [<ffffffff81ffe2d0>] ? sk_busy_loop+0xba0/0xba0
[ 1364.035792]  [<ffffffff8126f9d7>] ? rcu_process_callbacks+0xe37/0x1320
[ 1364.035792]  [<ffffffffa08e8220>] ? ss_tcp_data_ready+0x150/0x150 [tempesta_fw]
[ 1364.035792]  [<ffffffff8232cae1>] __do_softirq+0x221/0x97d
[ 1364.035792]  [<ffffffff8112ea00>] ? takeover_tasklets+0x830/0x830
[ 1364.035792]  [<ffffffff8112ea1f>] run_ksoftirqd+0x1f/0x60
[ 1364.035792]  [<ffffffff81185ec4>] smpboot_thread_fn+0x3d4/0x840
[ 1364.035792]  [<ffffffff81185af0>] ? smpboot_update_cpumask_percpu_thread+0x590/0x590
[ 1364.035792]  [<ffffffff8231a454>] ? schedule+0x94/0x1b0
[ 1364.035792]  [<ffffffff8117abe2>] ? __kthread_parkme+0xe2/0x210
[ 1364.035792]  [<ffffffff81185af0>] ? smpboot_update_cpumask_percpu_thread+0x590/0x590
[ 1364.035792]  [<ffffffff8117b417>] kthread+0x247/0x310
[ 1364.035792]  [<ffffffff8117b1d0>] ? kthread_park+0x80/0x80
[ 1364.035792]  [<ffffffff8117b1d0>] ? kthread_park+0x80/0x80
[ 1364.035792]  [<ffffffff8117b1d0>] ? kthread_park+0x80/0x80
[ 1364.035792]  [<ffffffff8117b1d0>] ? kthread_park+0x80/0x80
[ 1364.035792]  [<ffffffff82329e07>] ret_from_fork+0x27/0x40
[ 1364.035792] Code: 7c 08 84 d2 0f 85 b0 19 00 00 41 8b 53 04 48 8b 8d 50 ff ff ff eb 36 49 39 9e e0 03 00 00 74 6d 48 8d 7b 2c 48 89 f8 48 c1 e8 03 <42> 0f b6 34 38 48 89 f8 83 e0 07 83 c0 03 40 38 f0 7c 09 40 84
[ 1364.035792] RIP  [<ffffffff82141667>] tcp_sacktag_write_queue+0x10d7/0x37b0
[ 1364.035792]  RSP <ffff88038c8870b8>
vankoven commented 6 years ago

Last couple of days I have rather frequent crashes on latest kernel (https://github.com/tempesta-tech/linux-4.9.35-tfw/commit/5dd6e7d8bc48838763cf1c7fcdced1a4f8e17358) and latest TempestaFW a66752a165f4aac8a685aecc1b6014b5b61adec7

Steps to reproduce:

Crash log:

[  305.239620] ------------[ cut here ]------------
[  305.241196] kernel BUG at /home/user/tempesta/tempesta/tempesta_fw/ss_skb.h:79!
[  305.242787] invalid opcode: 0000 [#1] SMP
[  305.243672] Modules linked in: tfw_sched_ratio(O) tfw_sched_http(O) tfw_sched_hash(O) tempesta_fw(O) tempesta_db(O) tempesta_tls(O) crct10dif_pclmul crc32_pclmul snd_hda_codec_generic ghash_clmulni_intel ppdev aesni_intel iTCO_wdt aes_x86_64 iTCO_vendor_support lrw gf128mul glue_helper ablk_helper cryptd snd_hda_intel snd_hda_codec snd_hda_core snd_hwdep virtio_balloon sg virtio_console snd_pcm snd_timer snd soundcore evdev serio_raw pcspkr qxl ttm lpc_ich mfd_core shpchp drm_kms_helper drm binfmt_misc parport_pc parport button ip_tables x_tables autofs4 ext4 crc16 jbd2 fscrypto mbcache sr_mod cdrom virtio_blk virtio_net crc32c_intel psmouse ahci i2c_i801 i2c_smbus libahci libata ehci_pci uhci_hcd sym53c8xx ehci_hcd scsi_transport_spi usbcore scsi_mod virtio_pci virtio_ring virtio
[  305.272538] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G           O    4.9.35-fix-691+ #2
[  305.273675] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.10.3-20171021_125229-anatol 04/01/2014
[  305.278819] task: ffffffff99e0e500 task.stack: ffffffff99e00000
[  305.280993] RIP: 0010:[<ffffffffc06fec11>]  [<ffffffffc06fec11>] ss_skb_unroll+0x271/0x2c0 [tempesta_fw]
[  305.284703] RSP: 0018:ffff95f4bfc03b50  EFLAGS: 00010286
[  305.285590] RAX: ffff95f4b811da00 RBX: ffff95f4b3bb7c00 RCX: ffffffff99edd120
[  305.287156] RDX: 00000000000032e8 RSI: ffff95f4b3bb7c00 RDI: ffff95f4bfc03ba0
[  305.288695] RBP: 0000000000000000 R08: 000000000001c570 R09: 0000000000000000
[  305.290265] R10: 000000000000e380 R11: 0000000000000000 R12: ffff95f4b5591728
[  305.291630] R13: 0000000000000000 R14: ffff95f4b3bb7c00 R15: ffff95f4b5591680
[  305.294103] FS:  0000000000000000(0000) GS:ffff95f4bfc00000(0000) knlGS:0000000000000000
[  305.296570] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  305.297520] CR2: 00007f86dfc2dab4 CR3: 000000007738b000 CR4: 00000000003406f0
[  305.299497] Stack:
[  305.300184]  0000000000000001 ffff95f4b3bb7c00 0000000000000000 ffff95f4b5591728
[  305.301456]  0000000000000000 ffffffffc06f894c 0000000000000b97 ffff95f4b5591728
[  305.303116]  00000000b5498000 c7f439a900007120 ffff95f4b3bb7c00 ffff95f4b3bb7c00
[  305.304854] Call Trace:
[  305.305459]  <IRQ> [  305.305919]  [<ffffffffc06f894c>] ? ss_tcp_process_data+0xec/0x410 [tempesta_fw]
[  305.307867]  [<ffffffffc06f8ee3>] ? ss_tcp_data_ready+0x43/0x80 [tempesta_fw]
[  305.309326]  [<ffffffff99762282>] ? tcp_data_queue+0x4f2/0xce0
[  305.310980]  [<ffffffff99762c95>] ? tcp_rcv_established+0x225/0x6c0
[  305.313769]  [<ffffffff99720dcd>] ? sk_filter_trim_cap+0x2d/0x2c0
[  305.315265]  [<ffffffff9976d773>] ? tcp_v4_do_rcv+0x133/0x1f0
[  305.316243]  [<ffffffff9976ef17>] ? tcp_v4_rcv+0x8a7/0x9b0
[  305.317113]  [<ffffffff99748569>] ? ip_local_deliver_finish+0x99/0x1c0
[  305.318071]  [<ffffffff9974882b>] ? ip_local_deliver+0x6b/0xf0
[  305.319542]  [<ffffffff9976e660>] ? tcp_v4_early_demux+0x130/0x140
[  305.321287]  [<ffffffff99748251>] ? ip_rcv_finish+0x171/0x3f0
[  305.322737]  [<ffffffff99748b36>] ? ip_rcv+0x286/0x3d0
[  305.324012]  [<ffffffff997480e0>] ? inet_del_offload+0x40/0x40
[  305.325392]  [<ffffffff997076e9>] ? __netif_receive_skb_core+0x4f9/0xa00
[  305.326767]  [<ffffffffc0703203>] ? tfw_wq_pop_ticket+0x83/0xe80 [tempesta_fw]
[  305.327631]  [<ffffffff99708d88>] ? process_backlog+0x88/0x130
[  305.329560]  [<ffffffff997084a0>] ? net_rx_action+0x240/0x370
[  305.331972]  [<ffffffff99810dda>] ? __do_softirq+0x10a/0x29a
[  305.334070]  [<ffffffff99280e8e>] ? irq_exit+0xae/0xb0
[  305.335957]  [<ffffffff998104a2>] ? call_function_single_interrupt+0x82/0x90
[  305.336825]  <EOI> [  305.337325]  [<ffffffff9980db32>] ? native_safe_halt+0x2/0x10
[  305.338258]  [<ffffffff9980d87a>] ? default_idle+0x1a/0xd0
[  305.339045]  [<ffffffff992bd83a>] ? cpu_startup_entry+0x1ca/0x240
[  305.340000]  [<ffffffff99f38f61>] ? start_kernel+0x44d/0x46d
[  305.341047]  [<ffffffff99f38120>] ? early_idt_handler_array+0x120/0x120
[  305.342889]  [<ffffffff99f38408>] ? x86_64_start_kernel+0x14c/0x170
[  305.343923] Code: 00 00 00 48 c7 47 58 00 00 00 00 e8 7a 55 ff d8 48 8b 3b 48 85 ff 74 2a 48 8b 47 58 48 85 c0 75 c1 48 8b 47 60 48 89 43 08 eb bf <0f> 0b 0f 0b 0f 0b 48 89 07 e9 4a ff ff ff 48 8b 47 58 48 89 03 
[  305.350998] RIP  [<ffffffffc06fec11>] ss_skb_unroll+0x271/0x2c0 [tempesta_fw]
[  305.352485]  RSP <ffff95f4bfc03b50>
keshonok commented 6 years ago

The latest issue is caused by the recent addition to ss_skb_queue_tail(): https://github.com/tempesta-tech/tempesta/blob/a66752a165f4aac8a685aecc1b6014b5b61adec7/tempesta_fw/ss_skb.h#L79 In case of a GRO skb, such skb is dismantled into a set of individual skb. Individual skb in a GRO skb list are linked via skb->next pointer, and the list is attached to skb_shinfo(skb)->frag_list. In this process the skb->next pointer is not NULLed, hence the crash on the new BUG_ON().

Yes, it's possible to rework the code, not use the convenient skb_walk_frags() macro, and nullify skb->next pointer to satisfy the new BUG_ON(). That would fix the issue. However, I believe that it would be just excessive and unnecessary code.

When an skb gets into Tempesta, it is removed from the receive queue of a socket, and then orphaned from the socket. skb->next and skb->prev pointers are NULLed in the process. Only when an skb leaves Tempesta and is sent out through the kernel's TCP/IP stack, it is placed into an outgoing queue of another socket, and these pointers are assigned a value.

The only exception to this in regards to the value of skb->next pointer are skbs that were taken out of a GRO chain. Those skb do have a non-null skb->next pointer.

So, while an skb is inside Tempesta, skb->prev and skb->next pointers are never used. These pointers are explicitly assigned new values when an skb leaves Tempesta and is sent out through the kernel.

We can just remove the BUG_ON() mentioned above, and be as safe as before. That would remove the cause for the crash.

I must add a note that there's an skb dumping function ss_skb_dump() that prints the contents of an skb and used for debugging. The function also prints the values of skb->prev and skb->next pointers. Don't be confused when skb->next is not NULL. Again, these pointers ARE NOT used in Tempesta, and therefore their values are irrelevant. Perhaps, that information is excessive in the skb dumping function.

vankoven commented 6 years ago

@keshonok I can confirm that i have no crash described above in https://github.com/tempesta-tech/tempesta/issues/692#issuecomment-341629125 after removing of the BUG_ON statement. Thank you for investigation!

krizhanovsky commented 6 years ago

The reason for the bug is really the pskb_copy_for_clone() call in ss_send(). kfree_skb_partial() called from tcp_rcv_established() just puts an skb page . However, fclones, generated by ss_send() may go through the code, so the page containing 2 skbs, one of which is still alive, can be freed.

I spent incredibly much time to come to the instrumentation patch, in the attachment. The sense of the patch is to make all skbs in the kernel to be allocated in separate pages with the new PG_Tempesta flag. Next, on put_page() the patch verifies the page counter and guesses that the page contains skb(s) using a magic (I use page pointer for it). And finally, the patch check fclones->fclone_ref to crash if we free a page with an alive fclone. The patch also contains several bugfixes and isn't clean - sorry for that.

692_instr.txt (This is .gz file renamed to .txt to make Github attach it).