Dirty shutdown #254

krizhanovsky · 2015-09-10T21:07:47Z

Test case:

start Tempesta with enabled Frang
send some request
shutdown Tempesta

Tempesta doesn't clean data structures on shutdown, so following trace is produced and the system hangs:

    .......
    [sync_sockets]   ss_send: sk ffff8800382ce740, sk->sk_socket           (null), state (Established)
    [sync_sockets]   ss_send:213 entail skb=ffff88005bc61440 data_len=0 len=467
    [sync_sockets]   ss_send:231 sk=ffff8800382ce740 is_queue_empty=0 tcp_send_head(sk)=ffff88005bc61440 sk->sk_state=1
    [tempesta]   Free msg: ffff8800382cd040
    [tempesta]   free skb ffff880059feb800: truesize=2271 sk=          (null), destructor=          (null) users=1 type=Conn_Clnt
    [tempesta]   Free msg: ffff88004634b040
    [tempesta]   free skb ffff88003c937c48: truesize=2368 sk=          (null), destructor=          (null) users=1 type=Conn_Srv
    [tempesta] got state via sysctl: stop
    [tempesta] stopping all modules...
    [tempesta]   stopping modules...
    [tempesta]   mod_stop(): frang
    [tempesta]   spec cleanup: 'frang_limits'
    [tempesta]   spec cleanup: 'http_methods'
    [tempesta]   spec cleanup: 'http_ct_vals'
    [tempesta]   mod_stop(): tfw_sched_http
    [tempesta]   spec cleanup: 'sched_http_rules'
    [tempesta]   spec cleanup: 'match'
    [tempesta]   mod_stop(): sock_clnt
    [tempesta]   spec cleanup: 'listen'
    [tempesta]   mod_stop(): sock_srv
    [sync_sockets]   Close socket ffff880046388840 (account=1)
    [sync_sockets]   __ss_do_close: sk ffff880046388840, sk->sk_socket           (null), state (Established)
    [tempesta]   Free msg:           (null)
    [sync_sockets]   Close socket ffff880046388140 (account=1)
    [sync_sockets]   __ss_do_close: sk ffff880046388140, sk->sk_socket           (null), state (Established)
    [tempesta]   Free msg:           (null)
    [sync_sockets]   Close socket ffff880038310880 (account=1)
    [sync_sockets]   __ss_do_close: sk ffff880038310880, sk->sk_socket           (null), state (Established)
    [tempesta]   Free msg:           (null)
    [sync_sockets]   Close socket ffff880038310180 (account=1)
    [sync_sockets]   __ss_do_close: sk ffff880038310180, sk->sk_socket           (null), state (Established)
    [tempesta]   Free msg:           (null)
    [tempesta]   spec cleanup: 'server'
    [tempesta]   mod_stop(): http_sticky
    [tempesta]   mod_stop(): cache
    [tempesta]   spec cleanup: 'cache_db'
    [tempesta]   mod_stop(): filter
    [tdb] Close table filter
    [tempesta]   spec cleanup: 'filter_db'
    [tempesta] Un-registering scheduler: dummy
    [tempesta]   tfw_sched_hash: exit
    [tempesta] Un-registering scheduler: hash
    [tempesta]   tfw_sched_http: exit
    [tempesta] Un-registering scheduler: http
    [tempesta]   unregister cfg: tfw_sched_http
    [tempesta]   tfw_sched_rr: exit
    [tempesta] Un-registering scheduler: round-robin
    [tempesta]   unregister cfg: frang
    [tempesta] exiting...
    kmem_cache_destroy tfw_cli_conn_cache: Slab cache still has objects
    CPU: 0 PID: 3826 Comm: rmmod Tainted: G           O 3.10.10+ #8
    Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.8.1-20150318_183358- 04/01/2014
     ffff88005a65c118 ffff880046383ea8 ffffffff814cdd12 ffff880046383ec8
     ffffffff8111e73f fffffffffffffff5 ffffffffa0487080 ffff880046383ed8
     ffffffffa0470bdd ffff880046383ef0 ffffffffa046c580 0000000700000000
    Call Trace:
     [<ffffffff814cdd12>] dump_stack+0x19/0x1b
     [<ffffffff8111e73f>] kmem_cache_destroy+0xcf/0xe0
     [<ffffffffa0470bdd>] tfw_sock_clnt_exit+0x18/0x1b [tempesta_fw]
     [<ffffffffa046c580>] tfw_exit+0x3c/0x48 [tempesta_fw]
     [<ffffffff8109ffbb>] SyS_delete_module+0x16b/0x2d0
     [<ffffffff810028f9>] ? do_notify_resume+0x59/0x80
     [<ffffffff814db202>] system_call_fastpath+0x16/0x1b
    kmem_cache_destroy tfw_cli_cache: Slab cache still has objects
    CPU: 0 PID: 3826 Comm: rmmod Tainted: G           O 3.10.10+ #8
    Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.8.1-20150318_183358- 04/01/2014
     ffff880001c0fa18 ffff880046383ea8 ffffffff814cdd12 ffff880046383ec8
     ffffffff8111e73f fffffffffffffff5 ffffffffa0487080 ffff880046383ed8
     ffffffffa0449c89 ffff880046383ef0 ffffffffa046c580 0000000500000000
    Call Trace:
     [<ffffffff814cdd12>] dump_stack+0x19/0x1b
     [<ffffffff8111e73f>] kmem_cache_destroy+0xcf/0xe0
     [<ffffffffa0449c89>] tfw_client_exit+0x18/0x1b [tempesta_fw]
     [<ffffffffa046c580>] tfw_exit+0x3c/0x48 [tempesta_fw]
     [<ffffffff8109ffbb>] SyS_delete_module+0x16b/0x2d0
     [<ffffffff810028f9>] ? do_notify_resume+0x59/0x80
     [<ffffffff814db202>] system_call_fastpath+0x16/0x1b
    [tempesta]   stopping and unregistering all cfg modules
    [tempesta]   unregister cfg: sock_clnt
    [tempesta]   unregister cfg: sock_srv
    [tempesta]   unregister cfg: http_sticky
    [tempesta]   unregister cfg: cache
    [tempesta]   unregister cfg: filter
    [tdb] Shutdown Tempesta DB
    BUG: unable to handle kernel paging request at ffffffffa046f490
    IP: [<ffffffffa046f490>] 0xffffffffa046f48f
    PGD 1a0c067 PUD 1a0d063 PMD 5c7fb067 PTE 0
    Oops: 0010 [#1] SMP 
    Modules linked in: nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack ipt_REJECT xt_CHECKSUM iptable_mangle bridge stp llc ip6table_filter ip6_tables iptable_filter ip_tables ebtable_nat ebtables xfs exportfs ppdev microcode pcspkr serio_raw parport_pc parport i2c_piix4 i2c_core dm_mirror dm_region_hash dm_log dm_mod uinput btrfs xor zlib_deflate raid6_pq libcrc32c ata_generic pata_acpi e1000 ata_piix floppy ipv6 autofs4 [last unloaded: tempesta_db]
    CPU: 1 PID: 0 Comm: swapper/1 Tainted: G           O 3.10.10+ #8
    Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.8.1-20150318_183358- 04/01/2014
    task: ffff88005d3ae7f0 ti: ffff88005c826000 task.ti: ffff88005c826000
    RIP: 0010:[<ffffffffa046f490>]  [<ffffffffa046f490>] 0xffffffffa046f48f
    RSP: 0018:ffff88007fd03a38  EFLAGS: 00010246
    RAX: 0000000000000302 RBX: ffff8800382ce040 RCX: 0000000000000000
    RDX: 0000000000000003 RSI: 0000000000000008 RDI: ffff8800382ce040
    RBP: ffff88007fd03a50 R08: 0000000000000062 R09: 0000000000000000
    R10: 0000000000000062 R11: ffffffffa03bbf18 R12: ffff8800382ce648
    R13: ffff88003c9e9200 R14: ffff88003c9e9262 R15: ffff88003c9e925a
    FS:  0000000000000000(0000) GS:ffff88007fd00000(0000) knlGS:0000000000000000
    CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
    CR2: ffffffffa046f490 CR3: 000000005bf2c000 CR4: 00000000000006e0
    DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
    DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
    Stack:
     ffffffff814501a9 ffff8800382ce040 ffff88005bc61580 ffff88007fd03aa0
     ffffffff81452aa8 0000000000000000 0000000000000000 0000000000000000
     ffff8800382ce040 ffff88003c9e9262 ffff88005bc61580 ffff88003c9e924e
    Call Trace:
     <IRQ> 
     [<ffffffff814501a9>] ? tcp_fin+0x169/0x1e0
     [<ffffffff81452aa8>] tcp_data_queue+0x6c8/0xc90
     [<ffffffff8145595f>] tcp_rcv_established+0x1bf/0x8a0
     [<ffffffff814606b4>] tcp_v4_do_rcv+0x1b4/0x470
     [<ffffffff81461cee>] tcp_v4_rcv+0x68e/0x7e0
     [<ffffffff8143c270>] ? ip_rcv_finish+0x320/0x320
     [<ffffffff81433654>] ? nf_hook_slow+0x74/0x130
     [<ffffffff8143c270>] ? ip_rcv_finish+0x320/0x320
     [<ffffffff8143c340>] ip_local_deliver_finish+0xd0/0x210
     [<ffffffff8143c658>] ip_local_deliver+0x88/0x90
     [<ffffffff8143bfc8>] ip_rcv_finish+0x78/0x320
     [<ffffffff8143c8cd>] ip_rcv+0x26d/0x390
     [<ffffffff81405726>] __netif_receive_skb_core+0x5e6/0x820
     [<ffffffff81461f00>] ? tcp4_gro_receive+0xa0/0x130
     [<ffffffff8140597d>] __netif_receive_skb+0x1d/0x60
     [<ffffffff814059ed>] netif_receive_skb+0x2d/0x90
     [<ffffffff81406390>] napi_gro_receive+0x80/0xb0
     [<ffffffffa009c4c3>] e1000_clean_rx_irq+0x2b3/0x580 [e1000]
     [<ffffffffa009e9d5>] e1000_clean+0x255/0x8c0 [e1000]
     [<ffffffff8135455e>] ? scsi_io_completion+0x1ee/0x6e0
     [<ffffffff81405d29>] net_rx_action+0x139/0x220
     [<ffffffff810461f0>] __do_softirq+0x100/0x250
     [<ffffffff81046495>] irq_exit+0x95/0xa0
     [<ffffffff814dcab6>] do_IRQ+0x56/0xc0
     [<ffffffff814d336a>] common_interrupt+0x6a/0x6a
     <EOI> 
     [<ffffffff8100a101>] ? default_idle+0x21/0xb0
     [<ffffffff8100a92e>] arch_cpu_idle+0x1e/0x30
     [<ffffffff8108cf6e>] cpu_startup_entry+0xce/0x270
     [<ffffffff81094915>] ? clockevents_register_device+0xb5/0x120
     [<ffffffff814c0b32>] start_secondary+0x247/0x249
    Code:  Bad RIP value.
    RIP  [<ffffffffa046f490>] 0xffffffffa046f48f
     RSP <ffff88007fd03a38>
    CR2: ffffffffa046f490
    ---[ end trace 52527555cdcd0973 ]---
    Kernel panic - not syncing: Fatal exception in interrupt

The text was updated successfully, but these errors were encountered:

keshonok · 2015-09-10T22:27:21Z

The kernel panic above, as well as the warnings about Slab cache still having objects is also described is #116.

krizhanovsky · 2015-09-12T18:53:07Z

Probably there are also other issues on shutdown, so the issues should be verified again after closing #116.

krizhanovsky · 2015-10-10T19:07:59Z

TODO from #228:

Connection establishing is asynchronous and we should close half-open socket on Tempesta shutdown. The problem could be solved by two phase shutdown process:

stop all services, unregister any callbacks and wait for all sortirq running Tempesta code stop. If ss_tcp_state_change() is called in softirq for ESTABLISHED connection, then the socket should be closed immediately in the same function. Since there are many sockets referencing to Tempesta's hooks, we can't unregister the callbacks. Rather there should be wrapping functions which check __read_mostly boolean variable for current shutdown status and call or bypass actual Tempesta call;
now all sockets for server connection pool are fully open or closed, so we can free all resources and close the sockets.

As the consequence of 2-phase shutdown is that we should not synchronized sockets and skbs between softirqs and shutdown (process) contexts. This removes one case of concurrent skb usage in #173.

UPD Actually we already have 2-phase shutdown: firstly we do sysctl -w net.tempesta.state=stop which must stop all services and wait for softirq completion and secondly we do modules unloading.

…d in #254 instead of checking the socket state

keshonok · 2016-02-17T16:39:12Z

When Tempesta stops on encountering an error in configuration file, there's this piece of code that it executes in tfw_listen_sock_stop_all() at https://github.com/natsys/tempesta/blob/master/tempesta_fw/sock_clnt.c#L380:

    list_for_each_entry(ls, &tfw_listen_socks, list) {
        BUG_ON(!ls->sk);
        ss_release(ls->sk);
        ls->sk = NULL;
    }

It may easily happen that listening sockets had not been established. In that case this code leads to an unnecessary kernel panic.

krizhanovsky · 2016-08-30T18:36:49Z

One more problem with shutdown is unloading with no connection to the backend. An attempt to fix the issue was made in #609 .

Fix #116, #254 and #418: clean restart

krizhanovsky · 2017-02-02T18:06:35Z

Fixed in 2027734

krizhanovsky added the bug label Sep 10, 2015

krizhanovsky added this to the 0.5.0 Web Server milestone Sep 10, 2015

krizhanovsky added a commit that referenced this issue Sep 12, 2015

#228: TODO for #116 and #254; several cleanups

f3fc64d

krizhanovsky mentioned this issue Sep 12, 2015

Soft lockup on Tempesta start #228

Closed

keshonok mentioned this issue Sep 24, 2015

Oops in tcp_set_state() #281

Closed

krizhanovsky added a commit that referenced this issue Oct 10, 2015

Undo commit 9ab1e68: we should use 2-phase socket closing as describe…

e4a41eb

…d in #254 instead of checking the socket state

krizhanovsky mentioned this issue Dec 9, 2015

Synchronous Socket: deadlock betweed __ss_do_close() and ss_tcp_process_data() #367

Closed

krizhanovsky self-assigned this Dec 18, 2015

keshonok mentioned this issue Feb 17, 2016

Kernel panic when Tempesta starts with an error in the config file #418

Closed

krizhanovsky mentioned this issue Mar 15, 2016

[TfwBomber] SS: proper errors handling #428

Closed

krizhanovsky mentioned this issue Aug 30, 2016

Fix a bug while unloading with no connection to the backend #609

Closed

vankoven mentioned this issue Nov 3, 2016

Stoping Tempesta during open sessions cause kernel panic #631

Closed

krizhanovsky added the crucial label Nov 29, 2016

krizhanovsky added a commit that referenced this issue Jan 8, 2017

Fix #116 & #254; remove some noisy debug printing; several cleanups

41f1d8e

This was referenced Jan 13, 2017

Enforce the correct order of responses. Handle non-idempotent requests. #660

Merged

Functional test for Frang #673

Closed

This was referenced Feb 1, 2017

Bad socket cpu locality on new Linux 4.8.15 #668

Closed

SS: properly implement ss_drain_accept_queue() #145

Closed

krizhanovsky added a commit that referenced this issue Feb 2, 2017

Merge pull request #676 from tempesta-tech/ak-shutdown

2027734

Fix #116, #254 and #418: clean restart

krizhanovsky closed this as completed Feb 2, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Dirty shutdown #254

Dirty shutdown #254

krizhanovsky commented Sep 10, 2015

keshonok commented Sep 10, 2015

krizhanovsky commented Sep 12, 2015

krizhanovsky commented Oct 10, 2015 •

edited

Loading

keshonok commented Feb 17, 2016

krizhanovsky commented Aug 30, 2016

krizhanovsky commented Feb 2, 2017

Dirty shutdown #254

Dirty shutdown #254

Comments

krizhanovsky commented Sep 10, 2015

keshonok commented Sep 10, 2015

krizhanovsky commented Sep 12, 2015

krizhanovsky commented Oct 10, 2015 • edited Loading

keshonok commented Feb 17, 2016

krizhanovsky commented Aug 30, 2016

krizhanovsky commented Feb 2, 2017

krizhanovsky commented Oct 10, 2015 •

edited

Loading