sk->sk_destruct() is not being called when connection is closed #46

vdmit11 · 2015-02-09T17:28:51Z

Scenario:

start nginx
start Tempesta FW
wget http://localhost - should pass and give you index.html
stop nginx
wget http://locslhost - crashes

That happens because when the connection to nginx is closed, no sk->sk_destruct() is called.

We put tfw_destroy_server() to sk->sk_destruct(), so when the connection is closed, the server is not deleted from the load-balancing scheduler as it should be, and you get a NULL pointer dereference when you try to acess its connection.

Generally, the problem is wider than the fact that tfw_destroy_server() is not invoked.
Original socket destructor (usually inet_release()) is not invoked as well, so we likely have some memory leak here.

A notable thing that when you call sock_release(), the sk->sk_destruct() is invoked as it should be.
We need to understand why sk->sk_destruct() is not invoked when a TCP connection is closed, but is invoked when you do sock_release().

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

keshonok · 2015-02-25T20:44:58Z

With the way Synchronous Sockets are implemented now, we never reach TCP_CLOSE state. That is the root cause of this and some other problems.

Right now we do a forceful "non-sleeping" socket close at TCP_CLOSE_WAIT state by calling ss_do_close(). However that doesn't close the socket properly. This procedure breaks TCP protocol handshake on socket closing. It also breaks proper moves from one TCP state to another, and thus doesn't execute proper actions required at each state. That includes the final actions where the sk_destruct() function is called. By the end the socket must be clear of any write data, and that's the condition under which the sk_destruct() is called.

By the way, calling ss_do_close() at TCP_CLOSE_WAIT state loses the received FIN packet as it's not processed (it's discarded) but "assumed". If we don't call ss_do_close() at TCP_CLOSE_WAIT state, then we do catch the FIN packet in ss_tcp_data_ready() -> ss_tcp_process_data(). The latter then calls ss_do_close() as soon as it recognizes a FIN packet, and then it's all the same.

Related issues are: #52, and possibly #62, #63.

krizhanovsky · 2015-03-10T22:13:34Z

An attempt to fix the issue was done in #59

krizhanovsky · 2015-03-24T11:37:46Z

It seems we ever have the problem in simple scenario on normal connection closing after successful data transfer in proxy mode:

    .....................
    [tempesta]   parser: Resp_BodyReadChunk(92:0): c=0x3c(<), r=-2
    [tempesta]   response parsed: len=460 parsed=460 res=0
    [sync_socket]   ss_send:155 entail skb=ffff88002c027e88 data_len=0 len=460
    [sync_socket]   ss_send:173 sk=ffff88007bb52140 is_queue_empty=0 tcp_send_head(sk)=ffff88002c027e88 sk->sk_state=1
    [tempesta]   Free msg: ffff88007bf82040
    [tempesta]   free skb ffff88007b263080: truesize=2240 sk=ffff88007bb52140, destructor=ffffffff813eee10 users=1
    [tempesta]   Free msg: ffff88007a55f040
    [tempesta]   free skb ffff88002c027e88: truesize=2368 sk=ffff88007bb52840, destructor=ffffffff813eee10 users=1
    [sync_socket]   Peer connection closing
    [sync_socket]   Close socket ffff88007bb52840 (account=1)
    [tempesta]   Close socket ffff88007bb52840, conn=ffff88002c025488
    [tempesta]   Free msg:           (null)
    [tempesta]   Free connection: ffff88002c025488
    [sync_socket]   free rcv skb ffff88002c0277c8
    ------------[ cut here ]------------
    WARNING: at net/core/stream.c:201 sk_stream_kill_queues+0x12c/0x130()
    Modules linked in: tfw_sched_dummy(O) tempesta_fw(O) tempesta_db(O) sync_socket(O) 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 dm_mirror parport_pc serio_raw microcode dm_region_hash pcspkr parport i2c_piix4 i2c_core dm_log dm_mod uinput btrfs xor zlib_deflate raid6_pq libcrc32c ata_generic pata_acpi e1000 ata_piix floppy ipv6 autofs4
    CPU: 0 PID: 1025 Comm: httpd Tainted: G           O 3.10.10+ #29
    Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.7.5-0-ge51488c-20140602_164612-nilsson.home.kraxel.org 04/01/2014
     0000000000000009 ffff88007fc03b80 ffffffff814cbf7f ffff88007fc03bb8
     ffffffff8103c091 ffff88007bb52840 ffff88007bb529a0 ffff880078a88cb0
     0000000000000000 ffff880078a88ca8 ffff88007fc03bc8 ffffffff8103c16a
    Call Trace:
     <IRQ>  [<ffffffff814cbf7f>] dump_stack+0x19/0x1b
     [<ffffffff8103c091>] warn_slowpath_common+0x61/0x80
     [<ffffffff8103c16a>] warn_slowpath_null+0x1a/0x20
     [<ffffffff813fb63c>] sk_stream_kill_queues+0x12c/0x130
     [<ffffffff814468c6>] inet_csk_destroy_sock+0x56/0x140
     [<ffffffff814480b7>] tcp_done+0x67/0xa0
     [<ffffffff81454f4a>] tcp_rcv_state_process+0x95a/0xca0
     [<ffffffff8145e9da>] tcp_v4_do_rcv+0x26a/0x470
     [<ffffffff8145ff5e>] tcp_v4_rcv+0x68e/0x7e0
     [<ffffffff8143a4e0>] ? ip_rcv_finish+0x320/0x320
     [<ffffffff8143a5b0>] ip_local_deliver_finish+0xd0/0x210
     [<ffffffff8143a8c8>] ip_local_deliver+0x88/0x90
     [<ffffffff8143a238>] ip_rcv_finish+0x78/0x320
     [<ffffffff8143ab3d>] ip_rcv+0x26d/0x390
     [<ffffffff81403996>] __netif_receive_skb_core+0x5e6/0x820
     [<ffffffff81403bed>] __netif_receive_skb+0x1d/0x60
     [<ffffffff814046d0>] process_backlog+0xa0/0x160
     [<ffffffff81403f99>] net_rx_action+0x139/0x220
     [<ffffffff81044480>] __do_softirq+0x100/0x250
     [<ffffffff814da67c>] call_softirq+0x1c/0x30
     <EOI>  [<ffffffff810041ed>] do_softirq+0x3d/0x80
     [<ffffffff81043fb4>] local_bh_enable_ip+0x94/0xa0
     [<ffffffff814d11b6>] _raw_spin_unlock_bh+0x16/0x20
     [<ffffffff813f1773>] release_sock+0x113/0x160
     [<ffffffff81470b5a>] inet_shutdown+0x9a/0x120
     [<ffffffff813ee3fd>] SyS_shutdown+0x7d/0x90
     [<ffffffff814d9442>] system_call_fastpath+0x16/0x1b
    ---[ end trace fa86b131a787e051 ]---
    ------------[ cut here ]------------
    WARNING: at net/core/stream.c:201 sk_stream_kill_queues+0x12c/0x130()
    Modules linked in: tfw_sched_dummy(O) tempesta_fw(O) tempesta_db(O) sync_socket(O) 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 dm_mirror parport_pc serio_raw microcode dm_region_hash pcspkr parport i2c_piix4 i2c_core dm_log dm_mod uinput btrfs xor zlib_deflate raid6_pq libcrc32c ata_generic pata_acpi e1000 ata_piix floppy ipv6 autofs4
    CPU: 1 PID: 1025 Comm: httpd Tainted: G        W  O 3.10.10+ #29
    Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.7.5-0-ge51488c-20140602_164612-nilsson.home.kraxel.org 04/01/2014
     0000000000000009 ffff880078b17d80 ffffffff814cbf7f ffff880078b17db8
     ffffffff8103c091 ffff880078a76040 ffff880078a761a0 0000000000000007
     ffff880078a760b0 ffff8800783569a0 ffff880078b17dc8 ffffffff8103c16a
    Call Trace:
     [<ffffffff814cbf7f>] dump_stack+0x19/0x1b
     [<ffffffff8103c091>] warn_slowpath_common+0x61/0x80
     [<ffffffff8103c16a>] warn_slowpath_null+0x1a/0x20
     [<ffffffff813fb63c>] sk_stream_kill_queues+0x12c/0x130
     [<ffffffff814468c6>] inet_csk_destroy_sock+0x56/0x140
     [<ffffffff814492ce>] tcp_close+0x16e/0x3f0
     [<ffffffff81470c57>] inet_release+0x77/0x80
     [<ffffffffa000d560>] inet6_release+0x30/0x40 [ipv6]
     [<ffffffff813eb81f>] sock_release+0x1f/0x80
     [<ffffffff813eb892>] sock_close+0x12/0x20
     [<ffffffff81155be9>] __fput+0xe9/0x270
     [<ffffffff81155e2e>] ____fput+0xe/0x10
     [<ffffffff8105cfc7>] task_work_run+0xa7/0xe0
     [<ffffffff810028f9>] do_notify_resume+0x59/0x80
     [<ffffffff814d96ca>] int_signal+0x12/0x17
    ---[ end trace fa86b131a787e052 ]---
    ------------[ cut here ]------------
    WARNING: at net/ipv4/af_inet.c:153 inet_sock_destruct+0x197/0x1e0()
    Modules linked in: tfw_sched_dummy(O) tempesta_fw(O) tempesta_db(O) sync_socket(O) 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 dm_mirror parport_pc serio_raw microcode dm_region_hash pcspkr parport i2c_piix4 i2c_core dm_log dm_mod uinput btrfs xor zlib_deflate raid6_pq libcrc32c ata_generic pata_acpi e1000 ata_piix floppy ipv6 autofs4
    CPU: 1 PID: 1025 Comm: httpd Tainted: G        W  O 3.10.10+ #29
    Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.7.5-0-ge51488c-20140602_164612-nilsson.home.kraxel.org 04/01/2014
     0000000000000009 ffff880078b17d60 ffffffff814cbf7f ffff880078b17d98
     ffffffff8103c091 ffff880078a76040 ffff880078a761a0 0000000000000007
     ffff880078a760b0 ffff8800783569a0 ffff880078b17da8 ffffffff8103c16a
    Call Trace:
     [<ffffffff814cbf7f>] dump_stack+0x19/0x1b
     [<ffffffff8103c091>] warn_slowpath_common+0x61/0x80
     [<ffffffff8103c16a>] warn_slowpath_null+0x1a/0x20
     [<ffffffff814721d7>] inet_sock_destruct+0x197/0x1e0
     [<ffffffff813f0f8f>] __sk_free+0x1f/0x170
     [<ffffffff813f1101>] sk_free+0x21/0x30
     [<ffffffff814492a1>] tcp_close+0x141/0x3f0
     [<ffffffff81470c57>] inet_release+0x77/0x80
     [<ffffffffa000d560>] inet6_release+0x30/0x40 [ipv6]
     [<ffffffff813eb81f>] sock_release+0x1f/0x80
     [<ffffffff813eb892>] sock_close+0x12/0x20
     [<ffffffff81155be9>] __fput+0xe9/0x270
     [<ffffffff81155e2e>] ____fput+0xe/0x10
     [<ffffffff8105cfc7>] task_work_run+0xa7/0xe0
     [<ffffffff810028f9>] do_notify_resume+0x59/0x80
     [<ffffffff814d96ca>] int_signal+0x12/0x17
    ---[ end trace fa86b131a787e053 ]---
    ------------[ cut here ]------------
    WARNING: at net/ipv4/af_inet.c:156 inet_sock_destruct+0x1d9/0x1e0()
    Modules linked in: tfw_sched_dummy(O) tempesta_fw(O) tempesta_db(O) sync_socket(O) 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 dm_mirror parport_pc serio_raw microcode dm_region_hash pcspkr parport i2c_piix4 i2c_core dm_log dm_mod uinput btrfs xor zlib_deflate raid6_pq libcrc32c ata_generic pata_acpi e1000 ata_piix floppy ipv6 autofs4
    CPU: 1 PID: 1025 Comm: httpd Tainted: G        W  O 3.10.10+ #29
    Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.7.5-0-ge51488c-20140602_164612-nilsson.home.kraxel.org 04/01/2014
     0000000000000009 ffff880078b17d60 ffffffff814cbf7f ffff880078b17d98
     ffffffff8103c091 ffff880078a76040 ffff880078a761a0 0000000000000007
     ffff880078a760b0 ffff8800783569a0 ffff880078b17da8 ffffffff8103c16a
    Call Trace:
     [<ffffffff814cbf7f>] dump_stack+0x19/0x1b
     [<ffffffff8103c091>] warn_slowpath_common+0x61/0x80
     [<ffffffff8103c16a>] warn_slowpath_null+0x1a/0x20
     [<ffffffff81472219>] inet_sock_destruct+0x1d9/0x1e0
     [<ffffffff813f0f8f>] __sk_free+0x1f/0x170
     [<ffffffff813f1101>] sk_free+0x21/0x30
     [<ffffffff814492a1>] tcp_close+0x141/0x3f0
     [<ffffffff81470c57>] inet_release+0x77/0x80
     [<ffffffffa000d560>] inet6_release+0x30/0x40 [ipv6]
     [<ffffffff813eb81f>] sock_release+0x1f/0x80
     [<ffffffff813eb892>] sock_close+0x12/0x20
     [<ffffffff81155be9>] __fput+0xe9/0x270
     [<ffffffff81155e2e>] ____fput+0xe/0x10
     [<ffffffff8105cfc7>] task_work_run+0xa7/0xe0
     [<ffffffff810028f9>] do_notify_resume+0x59/0x80
     [<ffffffff814d96ca>] int_signal+0x12/0x17
    ---[ end trace fa86b131a787e054 ]---
    [sync_socket]   Peer connection closing
    [sync_socket]   Close socket ffff88007a405180 (account=1)
    [tempesta]   Close socket ffff88007a405180, conn=ffff88002c0255d8
    [tempesta]   Free msg:           (null)
    [tempesta]   Free connection: ffff88002c0255d8
    [sync_socket]   free rcv skb ffff88007b263580
    [sync_socket]   Peer connection closing
    [sync_socket]   Close socket ffff88007a405880 (account=1)
    [tempesta]   Close socket ffff88007a405880, conn=ffff88002c025610
    [tempesta]   Free msg:           (null)
    [tempesta]   Free connection: ffff88002c025610
    [sync_socket]   free rcv skb ffff88007b263580
    [sync_socket]   Peer connection closing
    [sync_socket]   Close socket ffff88007bb52140 (account=1)
    [tempesta]   Close socket ffff88007bb52140, conn=ffff88002c025648
    [tempesta]   Free msg:           (null)
    [tempesta]   Free connection: ffff88002c025648
    [sync_socket]   free rcv skb ffff88007b263580
    fuse init (API version 7.22)
    end_request: I/O error, dev fd0, sector 0
    device label centos devid 1 transid 3541 /dev/sda3
    nr_pdflush_threads exported in /proc is scheduled for removal
    sysctl: The scan_unevictable_pages sysctl/node-interface has been disabled for lack of a legitimate use case.  If you have one, please send an email to linux-mm@kvack.org.
    end_request: I/O error, dev fd0, sector 0
    device label centos devid 1 transid 3542 /dev/sda3
    end_request: I/O error, dev fd0, sector 0
    device label centos devid 1 transid 3542 /dev/sda3
    end_request: I/O error, dev fd0, sector 0
    device label centos devid 1 transid 3543 /dev/sda3

keshonok · 2015-03-24T12:36:48Z

This is probably wrong place for this trace. I believe it belongs to #60. The fix to the problem is presented there as well.

krizhanovsky · 2015-06-19T21:34:13Z

Alexey, please check whether we still have the issue with recent changes in TCP_CLOSE handling,

krizhanovsky · 2015-06-28T21:43:34Z

After commit 2cf2333 Tempesta throws many WARNING: at net/core/stream.c:201 sk_stream_kill_queues+0x12c/0x130() and crashes with:

    [sync_sockets]   ss_tcp_state_change: sk ffff8800382fd180, sk->sk_socket           (null), state (Close Wait)
    [sync_sockets]   Peer connection closing
    [tempesta]   connection lost: 127.0.0.1:8080
    [tempesta]   Free msg:           (null)
    [sync_sockets]   Close socket ffff8800382fd180 (account=1)
    [sync_sockets]   ss_do_close: sk ffff8800382fd180, sk->sk_socket           (null), state (Close Wait)
    [sync_sockets]   free rcv skb ffff88003948da08
    [sync_sockets]   ss_tcp_state_change: sk ffff88003816b800, sk->sk_socket           (null), state (Established)
    [tempesta]   connected: 127.0.0.1:8080
    BUG: unable to handle kernel NULL pointer dereference at 0000000000000008
    IP: [<ffffffff81406463>] process_backlog+0x93/0x160
    PGD 0 
    Oops: 0002 [#1] SMP 
    Modules linked in: tfw_sched_rr(O) tfw_sched_http(O) tfw_sched_hash(O) tfw_sched_dummy(O) tempesta_fw(O) tempesta_db(O) 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 parport_pc parport microcode serio_raw pcspkr 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
    CPU: 1 PID: 13 Comm: ksoftirqd/1 Tainted: G        W  O 3.10.10+ #3
    Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.8.1-20150318_183358- 04/01/2014
    task: ffff8800783b2000 ti: ffff88007842e000 task.ti: ffff88007842e000
    RIP: 0010:[<ffffffff81406463>]  [<ffffffff81406463>] process_backlog+0x93/0x160
    RSP: 0018:ffff88007842fd60  EFLAGS: 00010097
    RAX: 0000000000000000 RBX: ffff88007fd138e8 RCX: ffff88007fd138d0
    RDX: 0000000000000001 RSI: 0000000000000000 RDI: ffff88003948de88
    RBP: ffff88007842fd98 R08: ffff88007842e000 R09: 0000000000000000
    R10: 000000000000b73b R11: 0000000000000001 R12: 0000000000000040
    R13: ffff88007fd13994 R14: 0000000000000000 R15: ffff88007fd13998
    FS:  0000000000000000(0000) GS:ffff88007fd00000(0000) knlGS:0000000000000000
    CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
    CR2: 0000000000000008 CR3: 00000000382eb000 CR4: 00000000000006e0
    DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
    DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
    Stack:
     ffff88007fd12d00 ffff88007fd13980 0000000000000040 0000000000000000
     ffff88007fd13998 0000000000000000 00000000fffebc16 ffff88007842fdf0
     ffffffff81405d39 00000000fffebc18 ffff88007fd138d0 0000012c7842fdb8
    Call Trace:
     [<ffffffff81405d39>] net_rx_action+0x139/0x220
     [<ffffffff810461f0>] __do_softirq+0x100/0x250
     [<ffffffff81046368>] run_ksoftirqd+0x28/0x40
     [<ffffffff81069c4f>] smpboot_thread_fn+0xff/0x1a0
     [<ffffffff81069b50>] ? lg_local_lock_cpu+0x40/0x40
     [<ffffffff810620c0>] kthread+0xc0/0xd0
     [<ffffffff81062000>] ? insert_kthread_work+0x40/0x40
     [<ffffffff814db15c>] ret_from_fork+0x7c/0xb0
     [<ffffffff81062000>] ? insert_kthread_work+0x40/0x40
    Code: 0f 1f 84 00 00 00 00 00 48 85 ff 74 46 41 83 af 60 ff ff ff 01 48 8b 37 48 8b 47 08 48 c7 07 00 00 00 00 48 c7 47 08 00 00 00 00 <48> 89 46 08 48 89 30 fb e8 00 f5 ff ff fa 41 83 c6 01 41 83 47 
    RIP  [<ffffffff81406463>] process_backlog+0x93/0x160
     RSP <ffff88007842fd60>
    CR2: 0000000000000008
    ---[ end trace b5f354ff85aa0368 ]---
    Kernel panic - not syncing: Fatal exception in interrupt

keshonok · 2015-06-29T12:36:22Z

The core issue here is a missing sock_put() call when client sockets are released via direct call to ss_do_close(). This is completely unrelated to socket accounting warnings mentioned above.

In some cases sock_put() was not called. Because of that, some sockets were not closed properly: sk->sk_destruct() was not called.

Release a hold on a socket when closing it. (#46)

keshonok · 2015-07-01T07:17:56Z

Fixed with pull request 6a97572

krizhanovsky · 2015-07-06T22:55:24Z

It seems the issue is still not fixed and was just masked by 6a97572 . Issues #119 and #60 are relating.

After the last commit (47d82a1) I got exactly the same warnings under the same test:

Run Apache HTTPD as backend with default index page;
Run Tempesta with fillowing configuration:
```
server 127.0.0.1:8080;
cache off;
```
Request index page by Firefox.

In dmesg:

[tdb] Start Tempesta DB
[tempesta] Initializing Tempesta FW kernel module...
[tempesta] init: cfg_if
[tempesta] init: tls
[tempesta] init: http
[tempesta] init: http_sticky
[tempesta] init: server
[tempesta] init: client
[tempesta] init: sock_srv
[tempesta] init: sock_clnt
[tempesta]   register cfg: filter
[tempesta]   register cfg: cache
[tempesta]   register cfg: http_sticky
[tempesta]   register cfg: sock_srv
[tempesta]   register cfg: sock_clnt
[tempesta] Registering new scheduler: dummy
[tempesta]   tfw_sched_hash: init
[tempesta] Registering new scheduler: hash
[tempesta]   tfw_sched_http: init
[tempesta]   register cfg: tfw_sched_http
[tempesta] Registering new scheduler: http
[tempesta]   tfw_sched_rr: init
[tempesta] Registering new scheduler: round-robin
[tempesta] got state via sysctl: start
[tempesta]   reading configuration file...
[tempesta]   reading file: /root/tempesta/etc/tempesta_fw.conf
[tempesta]   file size: 5780 bytes
[tempesta]   read by offset: 0
[tempesta]   read by offset: 4096
[tempesta]   read by offset: 5780
[tempesta] starting all modules...
[tempesta]   parsing configuration and pushing it to modules...
[tempesta]   spec handle: 'server'
[tempesta]   new server group: 'default'
[tempesta]   spec handle: 'cache'
[tempesta]   use default entry: 'filter_tbl_size 16777216;'
[tempesta]   spec handle: 'filter_tbl_size'
[tempesta]   use default entry: 'filter_db /opt/tempesta/db/filter.tdb;'
[tempesta]   spec handle: 'filter_db'
[tempesta]   use default entry: 'cache_size 268435456;'
[tempesta]   spec handle: 'cache_size'
[tempesta]   use default entry: 'cache_db /opt/tempesta/db/cache.tdb;'
[tempesta]   spec handle: 'cache_db'
[tempesta]   use default entry: 'listen 80;'
[tempesta]   spec handle: 'listen'
[tempesta]   starting modules...
[tempesta]   mod_start(): filter
[tdb] Opened table /opt/tempesta/db/filter.tdb: size=16777216 rec_size=20 base=ffff880073000000
[tempesta]   mod_start(): cache
[tempesta]   mod_start(): http_sticky
[tempesta]   mod_start(): sock_srv
[sync_sockets]   ss_tcp_state_change: sk ffff88007a5ef140, sk->sk_socket           (null), state (Established)
[tempesta]   connected: 127.0.0.1:8080
[sync_sockets]   ss_tcp_state_change: sk ffff88007a1d17c0, sk->sk_socket           (null), state (Established)
[tempesta]   connected: 127.0.0.1:8080
[sync_sockets]   ss_tcp_state_change: sk ffff88007a1d10c0, sk->sk_socket           (null), state (Established)
[tempesta]   connected: 127.0.0.1:8080
[sync_sockets]   ss_tcp_state_change: sk ffff8800793da800, sk->sk_socket           (null), state (Established)
[tempesta]   connected: 127.0.0.1:8080
[tempesta]   mod_start(): sock_clnt
[tempesta] Open listen socket on: 0.0.0.0
[tempesta]   start listening on socket: sk=ffff8800793da100
[tempesta]   mod_start(): tfw_sched_http
[tempesta]   spec handle: 'sched_http_rules'
[tempesta]   tfw_sched_http: begin sched_http_rules
[tempesta]   spec handle: 'match'
[tempesta]   tfw_sched_http: parsed rule: match  'default'=ffff88003dff0a40  '*'=1  '*'=1  '*'
[tempesta]   tfw_sched_http: finish sched_http_rules
[tempesta] modules are started
[sync_sockets]   ss_tcp_state_change: sk ffff880079816840, sk->sk_socket           (null), state (Established)
[tempesta]   new client socket: sk=ffff880079816840, state=1
[tempesta]   new client: cli=ffff88003c461670
[tempesta]   new client socket is accepted: sk=ffff880079816840, conn=ffff88003cb935a0, cli=ffff88003c461670
[sync_sockets]   ss_drain_accept_queue: sk ffff8800793da100, sk->sk_socket           (null), state (Listen)
[sync_sockets]   ss_tcp_data_ready: sk ffff880079816840, sk->sk_socket           (null), state (Established)
[tempesta]   Link new msg ffff88003e1a5040 with connection ffff88003cb935a0
[tempesta]   Add skb ffff88007b1fae40 to message ffff88003e1a5040
[tempesta]   Received 288 client data bytes (GET / HTTP/1.1
Host: 172.16.0.5
User-Agent: Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:38.0) Gecko/20100101 Firefox/38.0
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Accept-Language: en-US,en;q=0.5
Accept-Encoding: gzip, deflate
Connection: keep-alive

) on socket (conn=ffff88003cb935a0)
[tempesta]   enter FSM at state 0
[tempesta]   parser: Req_0(0:0): c=0x47(G), r=-2
[tempesta]   parser: Req_Method(1:0): c=0x47(G), r=-2
[tempesta]   parser: Req_MUSpace(2:0): c=0x2f(/), r=-2
[tempesta]   parser: Req_UriAbsPath(6:0): c=0x20( ), r=-2
[tempesta]   parser: Req_HttpVer(7:0): c=0x48(H), r=-2
[tempesta]   parser: Req_EoL(15:0): c=0xd(.), r=-2
[tempesta]   parser: Req_EoL(15:0): c=0xa(.), r=-2
[tempesta]   parser: Req_Hdr(16:0): c=0x48(H), r=-2
[tempesta]   parser: RGen_LWS(10000:21): c=0x20( ), r=-2
[tempesta]   parser: RGen_LWS(10000:21): c=0x31(1), r=-2
[tempesta]   enter FSM at state 21
[tempesta]   parser: Req_HdrHostV(21:0): c=0x31(1), r=-2
[tempesta]   enter FSM at state 1
[tempesta]   parser: Req_I_H(1:1): c=0x31(1), r=-2
[tempesta]   parser: Req_I_H(1:1): c=0x37(7), r=-2
[tempesta]   parser: Req_I_H(1:1): c=0x32(2), r=-2
[tempesta]   parser: Req_I_H(1:1): c=0x2e(.), r=-2
[tempesta]   parser: Req_I_H(1:1): c=0x31(1), r=-2
[tempesta]   parser: Req_I_H(1:1): c=0x36(6), r=-2
[tempesta]   parser: Req_I_H(1:1): c=0x2e(.), r=-2
[tempesta]   parser: Req_I_H(1:1): c=0x30(0), r=-2
[tempesta]   parser: Req_I_H(1:1): c=0x2e(.), r=-2
[tempesta]   parser: Req_I_H(1:1): c=0x35(5), r=-2
[tempesta]   parser: Req_I_H(1:1): c=0xd(.), r=-2
[tempesta]   parser: Req_I_H_EoL(3:1): c=0xd(.), r=-2
[tempesta]   parser: Req_I_H_EoL(3:1): c=0xa(.), r=-2
[tempesta]   parse header __req_parse_host: ret=12 len=10 id=0
[tempesta]   store header w/ ptr=ffff88003e0ef718 len=10 flags=2 id=0
[tempesta]   parser: Req_Hdr(16:0): c=0x55(U), r=-2
[tempesta]   parser: Req_HdrOther(92:0): c=0x55(U), r=-2
[tempesta]   store header w/ ptr=ffff88003e0ef724 len=88 flags=2 id=4
[tempesta]   parser: Req_Hdr(16:0): c=0x41(A), r=-2
[tempesta]   parser: Req_HdrOther(92:0): c=0x41(A), r=-2
[tempesta]   store header w/ ptr=ffff88003e0ef77e len=71 flags=2 id=5
[tempesta]   parser: Req_Hdr(16:0): c=0x41(A), r=-2
[tempesta]   parser: Req_HdrOther(92:0): c=0x41(A), r=-2
[tempesta]   store header w/ ptr=ffff88003e0ef7c7 len=31 flags=2 id=6
[tempesta]   parser: Req_Hdr(16:0): c=0x41(A), r=-2
[tempesta]   parser: Req_HdrOther(92:0): c=0x41(A), r=-2
[tempesta]   store header w/ ptr=ffff88003e0ef7e8 len=30 flags=2 id=7
[tempesta]   parser: Req_Hdr(16:0): c=0x43(C), r=-2
[tempesta]   parser: Req_HdrC(22:0): c=0x6f(o), r=-2
[tempesta]   parser: Req_HdrConnection(44:0): c=0x3a(:), r=-2
[tempesta]   parser: RGen_LWS(10000:45): c=0x20( ), r=-2
[tempesta]   parser: RGen_LWS(10000:45): c=0x6b(k), r=-2
[tempesta]   enter FSM at state 45
[tempesta]   parser: Req_HdrConnectionV(45:0): c=0x6b(k), r=-2
[tempesta]   enter FSM at state 1
[tempesta]   parser: I_Conn(1:1): c=0x6b(k), r=-2
[tempesta]   parser: I_EoT(6:1): c=0xd(.), r=0
[tempesta]   parser: I_EoL(7:1): c=0xd(.), r=0
[tempesta]   parser: I_EoL(7:1): c=0xa(.), r=0
[tempesta]   parser: Connection parsed: flags 0x2
[tempesta]   parse header __parse_connection: ret=12 len=10 id=2
[tempesta]   store header w/ ptr=ffff88003e0ef814 len=10 flags=2 id=2
[tempesta]   parser: Req_Hdr(16:0): c=0xd(.), r=-2
[tempesta]   parser: Req_HdrDone(93:0): c=0xa(.), r=-2
[tempesta]   parse msg body: flags=0x2 content_length=0
[tempesta]   request parsed: len=288 parsed=288 msg_len=288 res=0
[tempesta]   GFSM return code 0
[tempesta]   Matching request: ffff88003e1a5040, list: ffff88003e9f9040
[tempesta]   tfw_sched_http: use server group: 'default'
[tempesta]   added X-Forwarded-For header: X-Forwarded-For: 172.16.0.1

[sync_sockets]   ss_send: sk ffff88007a1d17c0, sk->sk_socket           (null), state (Established)
[sync_sockets]   ss_send:167 entail skb=ffff88007b1fae40 data_len=0 len=317
[sync_sockets]   ss_send:185 sk=ffff88007a1d17c0 is_queue_empty=0 tcp_send_head(sk)=ffff88007b1fae40 sk->sk_state=1
[sync_sockets]   ss_tcp_data_ready: sk ffff88007a1d17c0, sk->sk_socket           (null), state (Established)
[tempesta]   Link new msg ffff880078974040 with connection ffff88007898e978
[tempesta]   Add skb ffff8800798d3c48 to message ffff880078974040
[tempesta]   received 344 server data bytes (HTTP/1.1 403 Forbidden
Date: Mon, 06 Jul 2015 22:29:19 GMT
Server: Apache/2.4.6 (CentOS) OpenSSL/1.0.1e-fips mod_fcgid/2.3.9
Last-Modified: Tue, 17 Jun 2014 16:00:47 GMT
ETag: "1310-4fc0a3f32a9c0"
Accept-Ranges: bytes
Content-Length: 4880
Keep-Alive: timeout=5, max=100
Connection: Keep-Alive
Content-Type: text/html; charset=UTF-8

) on socket (conn=ffff88007898e978)
[tempesta]   enter FSM at state 0
[tempesta]   parser: Resp_0(0:0): c=0x48(H), r=-2
[tempesta]   parser: Resp_HttpVer(2:0): c=0x48(H), r=-2
[tempesta]   parser: Resp_StatusCode(11:0): c=0x34(4), r=-2
[tempesta]   parser: Resp_ReasonPhrase(12:1): c=0x20( ), r=-2
[tempesta]   parser: Resp_Hdr(13:1): c=0x44(D), r=-2
[tempesta]   parser: Resp_HdrOther(87:1): c=0x61(a), r=-2
[tempesta]   store header w/ ptr=ffff88007b4410e8 len=34 flags=2 id=4
[tempesta]   parser: Resp_Hdr(13:1): c=0x53(S), r=-2
[tempesta]   parser: Resp_HdrOther(87:1): c=0x65(e), r=-2
[tempesta]   store header w/ ptr=ffff88007b44110d len=64 flags=2 id=5
[tempesta]   parser: Resp_Hdr(13:1): c=0x4c(L), r=-2
[tempesta]   parser: Resp_HdrOther(87:1): c=0x61(a), r=-2
[tempesta]   store header w/ ptr=ffff88007b441150 len=43 flags=2 id=6
[tempesta]   parser: Resp_Hdr(13:1): c=0x45(E), r=-2
[tempesta]   parser: Resp_HdrE(50:1): c=0x54(T), r=-2
[tempesta]   parser: Resp_HdrOther(87:1): c=0x61(a), r=-2
[tempesta]   store header w/ ptr=ffff88007b44117e len=24 flags=2 id=7
[tempesta]   parser: Resp_Hdr(13:1): c=0x41(A), r=-2
[tempesta]   parser: Resp_HdrOther(87:1): c=0x63(c), r=-2
[tempesta]   store header w/ ptr=ffff88007b44119a len=19 flags=2 id=8
[tempesta]   parser: Resp_Hdr(13:1): c=0x43(C), r=-2
[tempesta]   parser: Resp_HdrC(14:1): c=0x6f(o), r=-2
[tempesta]   parser: RGen_LWS(10000:49): c=0x20( ), r=-2
[tempesta]   parser: RGen_LWS(10000:49): c=0x34(4), r=-2
[tempesta]   enter FSM at state 49
[tempesta]   parser: Resp_HdrContent_LengthV(49:0): c=0x34(4), r=-2
[tempesta]   enter FSM at state 3
[tempesta]   parser: I_ContLen(3:3): c=0x34(4), r=-2
[tempesta]   parser: I_EoL(7:3): c=0xd(.), r=-2
[tempesta]   parser: I_EoL(7:3): c=0xa(.), r=-2
[tempesta]   parse header __parse_content_length: ret=6 len=4 id=1
[tempesta]   store header w/ ptr=ffff88007b4411c0 len=4 flags=2 id=1
[tempesta]   parser: Resp_Hdr(13:0): c=0x4b(K), r=-2
[tempesta]   parser: Resp_HdrK(58:0): c=0x65(e), r=-2
[tempesta]   parser: Resp_HdrKe(59:0): c=0x65(e), r=-2
[tempesta]   parser: Resp_HdrKee(60:0): c=0x70(p), r=-2
[tempesta]   parser: Resp_HdrKeep(61:0): c=0x2d(-), r=-2
[tempesta]   parser: Resp_HdrKeep_(62:0): c=0x41(A), r=-2
[tempesta]   parser: Resp_HdrKeep_A(63:0): c=0x6c(l), r=-2
[tempesta]   parser: Resp_HdrKeep_Al(64:0): c=0x69(i), r=-2
[tempesta]   parser: Resp_HdrKeep_Ali(65:0): c=0x76(v), r=-2
[tempesta]   parser: Resp_HdrKeep_Aliv(66:0): c=0x65(e), r=-2
[tempesta]   parser: Resp_HdrKeep_Alive(67:0): c=0x3a(:), r=-2
[tempesta]   parser: RGen_LWS(10000:68): c=0x20( ), r=-2
[tempesta]   parser: RGen_LWS(10000:68): c=0x74(t), r=-2
[tempesta]   enter FSM at state 68
[tempesta]   parser: Resp_HdrKeep_AliveV(68:0): c=0x74(t), r=-2
[tempesta]   response parsed: len=344 parsed=0 res=-2
[tempesta]   Block bad HTTP response
[tempesta]   Free msg: ffff880078974040
[tempesta]   free skb ffff8800798d3c48: truesize=7248 sk=ffff88007a1d17c0, destructor=ffffffff813f0bb0 users=1 type=Conn_Srv
[sync_sockets] Warning: can't process app data on socket ffff88007a1d17c0
[tempesta]   connection lost: 127.0.0.1:8080
[tempesta]   Free msg:           (null)
[tempesta]   Free msg: ffff88003e1a5040
[tempesta]   free skb ffff88007b1fae40: truesize=2240 sk=ffff880079816840, destructor=ffffffff813f0bb0 users=1 type=Conn_Clnt
[sync_sockets]   Close socket ffff88007a1d17c0 (account=1)
[sync_sockets]   __ss_do_close: sk ffff88007a1d17c0, sk->sk_socket           (null), state (Established)
[sync_sockets]   ss_tcp_state_change: sk ffff880079816140, sk->sk_socket           (null), state (Established)
[tempesta]   connected: 127.0.0.1:8080
------------[ cut here ]------------
WARNING: at net/core/stream.c:201 sk_stream_kill_queues+0x12c/0x130()
Modules linked in: tfw_sched_rr(O) tfw_sched_http(O) tfw_sched_hash(O) tfw_sched_dummy(O) tempesta_fw(O) tempesta_db(O) fuse ext3 jbd ext2 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 dm_mirror pcspkr microcode i2c_piix4 i2c_core serio_raw parport_pc parport 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
CPU: 1 PID: 952 Comm: httpd Tainted: G           O 3.10.10+ #3
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.8.1-20150318_183358- 04/01/2014
 0000000000000009 ffff88007fd03ad0 ffffffff814cdd1f ffff88007fd03b08
 ffffffff8103de01 ffff88007a1d17c0 ffff88007a1d1920 0000000000000000
 ffff88003e1a5bc0 ffff88007a1d17c0 ffff88007fd03b18 ffffffff8103deda
Call Trace:
 <IRQ>  [<ffffffff814cdd1f>] dump_stack+0x19/0x1b
 [<ffffffff8103de01>] warn_slowpath_common+0x61/0x80
 [<ffffffff8103deda>] warn_slowpath_null+0x1a/0x20
 [<ffffffff813fd3dc>] sk_stream_kill_queues+0x12c/0x130
 [<ffffffff81448666>] inet_csk_destroy_sock+0x56/0x140
 [<ffffffff81449e57>] tcp_done+0x67/0xa0
 [<ffffffff8146209c>] tcp_time_wait+0x6c/0x280
 [<ffffffff81450164>] tcp_fin+0x114/0x1e0
 [<ffffffff81452ab8>] tcp_data_queue+0x6c8/0xc90
 [<ffffffff814566cd>] tcp_rcv_state_process+0x33d/0xca0
 [<ffffffff8146077a>] tcp_v4_do_rcv+0x26a/0x470
 [<ffffffff8123a2a6>] ? tempesta_sock_tcp_rcv+0x26/0x30
 [<ffffffff81461cfe>] tcp_v4_rcv+0x68e/0x7e0
 [<ffffffff8143c280>] ? ip_rcv_finish+0x320/0x320
 [<ffffffff8143c350>] ip_local_deliver_finish+0xd0/0x210
 [<ffffffff8143c668>] ip_local_deliver+0x88/0x90
 [<ffffffff8143bfd8>] ip_rcv_finish+0x78/0x320
 [<ffffffff8143c8dd>] ip_rcv+0x26d/0x390
 [<ffffffff81405736>] __netif_receive_skb_core+0x5e6/0x820
 [<ffffffff8140598d>] __netif_receive_skb+0x1d/0x60
 [<ffffffff81406470>] process_backlog+0xa0/0x160
 [<ffffffff81405d39>] net_rx_action+0x139/0x220
 [<ffffffff810461f0>] __do_softirq+0x100/0x250
 [<ffffffff814dc43c>] call_softirq+0x1c/0x30
 <EOI>  [<ffffffff810041ed>] do_softirq+0x3d/0x80
 [<ffffffff81045814>] local_bh_enable+0x94/0xa0
 [<ffffffff814407e8>] ip_finish_output+0x1b8/0x3b0
 [<ffffffff81441d30>] ip_output+0x90/0xa0
 [<ffffffff81441455>] ip_local_out+0x25/0x30
 [<ffffffff814417ab>] ip_queue_xmit+0x14b/0x3f0
 [<ffffffff81458eed>] tcp_transmit_skb+0x45d/0x8c0
 [<ffffffff814594e4>] tcp_write_xmit+0x194/0xb90
 [<ffffffff8145a0fe>] __tcp_push_pending_frames+0x2e/0xc0
 [<ffffffff8145afd4>] tcp_send_fin+0x64/0xe0
 [<ffffffff81449de4>] tcp_shutdown+0x54/0x60
 [<ffffffff814728e9>] inet_shutdown+0x89/0x120
 [<ffffffff813f019d>] SyS_shutdown+0x7d/0x90
 [<ffffffff814db202>] system_call_fastpath+0x16/0x1b
---[ end trace 590780289564f5fe ]---
------------[ cut here ]------------
WARNING: at net/ipv4/af_inet.c:153 inet_sock_destruct+0x197/0x1e0()
Modules linked in: tfw_sched_rr(O) tfw_sched_http(O) tfw_sched_hash(O) tfw_sched_dummy(O) tempesta_fw(O) tempesta_db(O) fuse ext3 jbd ext2 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 dm_mirror pcspkr microcode i2c_piix4 i2c_core serio_raw parport_pc parport 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
CPU: 1 PID: 952 Comm: httpd Tainted: G        W  O 3.10.10+ #3
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.8.1-20150318_183358- 04/01/2014
 0000000000000009 ffff88007fd03c58 ffffffff814cdd1f ffff88007fd03c90
 ffffffff8103de01 ffff88007a1d17c0 ffff88007a1d1920 ffff88007a1d17c0
 ffff88007a1d1810 ffff88007a07f8b0 ffff88007fd03ca0 ffffffff8103deda
Call Trace:
 <IRQ>  [<ffffffff814cdd1f>] dump_stack+0x19/0x1b
 [<ffffffff8103de01>] warn_slowpath_common+0x61/0x80
 [<ffffffff8103deda>] warn_slowpath_null+0x1a/0x20
 [<ffffffff81473f77>] inet_sock_destruct+0x197/0x1e0
 [<ffffffff813f2d2f>] __sk_free+0x1f/0x170
 [<ffffffff813f2ea1>] sk_free+0x21/0x30
 [<ffffffff8145d049>] sock_put+0x19/0x20
 [<ffffffff81461d0e>] tcp_v4_rcv+0x69e/0x7e0
 [<ffffffff8143c280>] ? ip_rcv_finish+0x320/0x320
 [<ffffffff8143c350>] ip_local_deliver_finish+0xd0/0x210
 [<ffffffff8143c668>] ip_local_deliver+0x88/0x90
 [<ffffffff8143bfd8>] ip_rcv_finish+0x78/0x320
 [<ffffffff8143c8dd>] ip_rcv+0x26d/0x390
 [<ffffffff81405736>] __netif_receive_skb_core+0x5e6/0x820
 [<ffffffff8140598d>] __netif_receive_skb+0x1d/0x60
 [<ffffffff81406470>] process_backlog+0xa0/0x160
 [<ffffffff81405d39>] net_rx_action+0x139/0x220
 [<ffffffff810461f0>] __do_softirq+0x100/0x250
 [<ffffffff814dc43c>] call_softirq+0x1c/0x30
 <EOI>  [<ffffffff810041ed>] do_softirq+0x3d/0x80
 [<ffffffff81045814>] local_bh_enable+0x94/0xa0
 [<ffffffff814407e8>] ip_finish_output+0x1b8/0x3b0
 [<ffffffff81441d30>] ip_output+0x90/0xa0
 [<ffffffff81441455>] ip_local_out+0x25/0x30
 [<ffffffff814417ab>] ip_queue_xmit+0x14b/0x3f0
 [<ffffffff81458eed>] tcp_transmit_skb+0x45d/0x8c0
 [<ffffffff814594e4>] tcp_write_xmit+0x194/0xb90
 [<ffffffff8145a0fe>] __tcp_push_pending_frames+0x2e/0xc0
 [<ffffffff8145afd4>] tcp_send_fin+0x64/0xe0
 [<ffffffff81449de4>] tcp_shutdown+0x54/0x60
 [<ffffffff814728e9>] inet_shutdown+0x89/0x120
 [<ffffffff813f019d>] SyS_shutdown+0x7d/0x90
 [<ffffffff814db202>] system_call_fastpath+0x16/0x1b
---[ end trace 590780289564f5ff ]---
------------[ cut here ]------------
WARNING: at net/ipv4/af_inet.c:156 inet_sock_destruct+0x1d9/0x1e0()
Modules linked in: tfw_sched_rr(O) tfw_sched_http(O) tfw_sched_hash(O) tfw_sched_dummy(O) tempesta_fw(O) tempesta_db(O) fuse ext3 jbd ext2 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 dm_mirror pcspkr microcode i2c_piix4 i2c_core serio_raw parport_pc parport 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
CPU: 1 PID: 952 Comm: httpd Tainted: G        W  O 3.10.10+ #3
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.8.1-20150318_183358- 04/01/2014
 0000000000000009 ffff88007fd03c58 ffffffff814cdd1f ffff88007fd03c90
 ffffffff8103de01 ffff88007a1d17c0 ffff88007a1d1920 ffff88007a1d17c0
 ffff88007a1d1810 ffff88007a07f8b0 ffff88007fd03ca0 ffffffff8103deda
Call Trace:
 <IRQ>  [<ffffffff814cdd1f>] dump_stack+0x19/0x1b
 [<ffffffff8103de01>] warn_slowpath_common+0x61/0x80
 [<ffffffff8103deda>] warn_slowpath_null+0x1a/0x20
 [<ffffffff81473fb9>] inet_sock_destruct+0x1d9/0x1e0
 [<ffffffff813f2d2f>] __sk_free+0x1f/0x170
 [<ffffffff813f2ea1>] sk_free+0x21/0x30
 [<ffffffff8145d049>] sock_put+0x19/0x20
 [<ffffffff81461d0e>] tcp_v4_rcv+0x69e/0x7e0
 [<ffffffff8143c280>] ? ip_rcv_finish+0x320/0x320
 [<ffffffff8143c350>] ip_local_deliver_finish+0xd0/0x210
 [<ffffffff8143c668>] ip_local_deliver+0x88/0x90
 [<ffffffff8143bfd8>] ip_rcv_finish+0x78/0x320
 [<ffffffff8143c8dd>] ip_rcv+0x26d/0x390
 [<ffffffff81405736>] __netif_receive_skb_core+0x5e6/0x820
 [<ffffffff8140598d>] __netif_receive_skb+0x1d/0x60
 [<ffffffff81406470>] process_backlog+0xa0/0x160
 [<ffffffff81405d39>] net_rx_action+0x139/0x220
 [<ffffffff810461f0>] __do_softirq+0x100/0x250
 [<ffffffff814dc43c>] call_softirq+0x1c/0x30
 <EOI>  [<ffffffff810041ed>] do_softirq+0x3d/0x80
 [<ffffffff81045814>] local_bh_enable+0x94/0xa0
 [<ffffffff814407e8>] ip_finish_output+0x1b8/0x3b0
 [<ffffffff81441d30>] ip_output+0x90/0xa0
 [<ffffffff81441455>] ip_local_out+0x25/0x30
 [<ffffffff814417ab>] ip_queue_xmit+0x14b/0x3f0
 [<ffffffff81458eed>] tcp_transmit_skb+0x45d/0x8c0
 [<ffffffff814594e4>] tcp_write_xmit+0x194/0xb90
 [<ffffffff8145a0fe>] __tcp_push_pending_frames+0x2e/0xc0
 [<ffffffff8145afd4>] tcp_send_fin+0x64/0xe0
 [<ffffffff81449de4>] tcp_shutdown+0x54/0x60
 [<ffffffff814728e9>] inet_shutdown+0x89/0x120
 [<ffffffff813f019d>] SyS_shutdown+0x7d/0x90
 [<ffffffff814db202>] system_call_fastpath+0x16/0x1b
---[ end trace 590780289564f600 ]---
------------[ cut here ]------------
WARNING: at net/core/stream.c:201 sk_stream_kill_queues+0x12c/0x130()
Modules linked in: tfw_sched_rr(O) tfw_sched_http(O) tfw_sched_hash(O) tfw_sched_dummy(O) tempesta_fw(O) tempesta_db(O) fuse ext3 jbd ext2 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 dm_mirror pcspkr microcode i2c_piix4 i2c_core serio_raw parport_pc parport 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
CPU: 1 PID: 952 Comm: httpd Tainted: G        W  O 3.10.10+ #3
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.8.1-20150318_183358- 04/01/2014
 0000000000000009 ffff88007967bd80 ffffffff814cdd1f ffff88007967bdb8
 ffffffff8103de01 ffff880079750800 ffff880079750960 0000000000000007
 ffff880079750870 ffff8800783569a0 ffff88007967bdc8 ffffffff8103deda
Call Trace:
 [<ffffffff814cdd1f>] dump_stack+0x19/0x1b
 [<ffffffff8103de01>] warn_slowpath_common+0x61/0x80
 [<ffffffff8103deda>] warn_slowpath_null+0x1a/0x20
 [<ffffffff813fd3dc>] sk_stream_kill_queues+0x12c/0x130
 [<ffffffff81448666>] inet_csk_destroy_sock+0x56/0x140
 [<ffffffff8144b06e>] tcp_close+0x16e/0x3f0
 [<ffffffff814729f7>] inet_release+0x77/0x80
 [<ffffffffa000d560>] inet6_release+0x30/0x40 [ipv6]
 [<ffffffff813ed5bf>] sock_release+0x1f/0x80
 [<ffffffff813ed632>] sock_close+0x12/0x20
 [<ffffffff81157959>] __fput+0xe9/0x270
 [<ffffffff81157b9e>] ____fput+0xe/0x10
 [<ffffffff8105ed37>] task_work_run+0xa7/0xe0
 [<ffffffff810028f9>] do_notify_resume+0x59/0x80
 [<ffffffff814db48a>] int_signal+0x12/0x17
---[ end trace 590780289564f601 ]---
------------[ cut here ]------------
WARNING: at net/ipv4/af_inet.c:153 inet_sock_destruct+0x197/0x1e0()
Modules linked in: tfw_sched_rr(O) tfw_sched_http(O) tfw_sched_hash(O) tfw_sched_dummy(O) tempesta_fw(O) tempesta_db(O) fuse ext3 jbd ext2 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 dm_mirror pcspkr microcode i2c_piix4 i2c_core serio_raw parport_pc parport 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
CPU: 1 PID: 952 Comm: httpd Tainted: G        W  O 3.10.10+ #3
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.8.1-20150318_183358- 04/01/2014
 0000000000000009 ffff88007967bd60 ffffffff814cdd1f ffff88007967bd98
 ffffffff8103de01 ffff880079750800 ffff880079750960 0000000000000007
 ffff880079750870 ffff8800783569a0 ffff88007967bda8 ffffffff8103deda
Call Trace:
 [<ffffffff814cdd1f>] dump_stack+0x19/0x1b
 [<ffffffff8103de01>] warn_slowpath_common+0x61/0x80
 [<ffffffff8103deda>] warn_slowpath_null+0x1a/0x20
 [<ffffffff81473f77>] inet_sock_destruct+0x197/0x1e0
 [<ffffffff813f2d2f>] __sk_free+0x1f/0x170
 [<ffffffff813f2ea1>] sk_free+0x21/0x30
 [<ffffffff8144b041>] tcp_close+0x141/0x3f0
 [<ffffffff814729f7>] inet_release+0x77/0x80
 [<ffffffffa000d560>] inet6_release+0x30/0x40 [ipv6]
 [<ffffffff813ed5bf>] sock_release+0x1f/0x80
 [<ffffffff813ed632>] sock_close+0x12/0x20
 [<ffffffff81157959>] __fput+0xe9/0x270
 [<ffffffff81157b9e>] ____fput+0xe/0x10
 [<ffffffff8105ed37>] task_work_run+0xa7/0xe0
 [<ffffffff810028f9>] do_notify_resume+0x59/0x80
 [<ffffffff814db48a>] int_signal+0x12/0x17
---[ end trace 590780289564f602 ]---
------------[ cut here ]------------
WARNING: at net/ipv4/af_inet.c:156 inet_sock_destruct+0x1d9/0x1e0()
Modules linked in: tfw_sched_rr(O) tfw_sched_http(O) tfw_sched_hash(O) tfw_sched_dummy(O) tempesta_fw(O) tempesta_db(O) fuse ext3 jbd ext2 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 dm_mirror pcspkr microcode i2c_piix4 i2c_core serio_raw parport_pc parport 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
CPU: 1 PID: 952 Comm: httpd Tainted: G        W  O 3.10.10+ #3
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.8.1-20150318_183358- 04/01/2014
 0000000000000009 ffff88007967bd60 ffffffff814cdd1f ffff88007967bd98
 ffffffff8103de01 ffff880079750800 ffff880079750960 0000000000000007
 ffff880079750870 ffff8800783569a0 ffff88007967bda8 ffffffff8103deda
Call Trace:
 [<ffffffff814cdd1f>] dump_stack+0x19/0x1b
 [<ffffffff8103de01>] warn_slowpath_common+0x61/0x80
 [<ffffffff8103deda>] warn_slowpath_null+0x1a/0x20
 [<ffffffff81473fb9>] inet_sock_destruct+0x1d9/0x1e0
 [<ffffffff813f2d2f>] __sk_free+0x1f/0x170
 [<ffffffff813f2ea1>] sk_free+0x21/0x30
 [<ffffffff8144b041>] tcp_close+0x141/0x3f0
 [<ffffffff814729f7>] inet_release+0x77/0x80
 [<ffffffffa000d560>] inet6_release+0x30/0x40 [ipv6]
 [<ffffffff813ed5bf>] sock_release+0x1f/0x80
 [<ffffffff813ed632>] sock_close+0x12/0x20
 [<ffffffff81157959>] __fput+0xe9/0x270
 [<ffffffff81157b9e>] ____fput+0xe/0x10
 [<ffffffff8105ed37>] task_work_run+0xa7/0xe0
 [<ffffffff810028f9>] do_notify_resume+0x59/0x80
 [<ffffffff814db48a>] int_signal+0x12/0x17
---[ end trace 590780289564f603 ]---
BUG: unable to handle kernel paging request at ffffea00025958ac
IP: [<ffffffff81148e2e>] free_block+0xee/0x170
PGD 7f7da067 PUD 7f7d9067 PMD 0 
Oops: 0002 [#1] SMP 
Modules linked in: tfw_sched_rr(O) tfw_sched_http(O) tfw_sched_hash(O) tfw_sched_dummy(O) tempesta_fw(O) tempesta_db(O) fuse ext3 jbd ext2 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 dm_mirror pcspkr microcode i2c_piix4 i2c_core serio_raw parport_pc parport 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
CPU: 0 PID: 120 Comm: kworker/0:2 Tainted: G        W  O 3.10.10+ #3
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.8.1-20150318_183358- 04/01/2014
Workqueue: events cache_reap
task: ffff88007afa3000 ti: ffff88007af8e000 task.ti: ffff88007af8e000
RIP: 0010:[<ffffffff81148e2e>]  [<ffffffff81148e2e>] free_block+0xee/0x170
RSP: 0018:ffff88007af8fd60  EFLAGS: 00010007
RAX: dead000000200200 RBX: ffff88007837f8c0 RCX: dead000000200200
RDX: 0000000000613dc9 RSI: 0000000000000000 RDI: ffffea0000d46158
RBP: ffff88007af8fd98 R08: ffffea0000d46158 R09: ffff88007fbdbfe0
R10: 0000000000000030 R11: ffffffffffffffec R12: ffff8800784a2618
R13: ffff8800798d3c48 R14: ffffea0000d46158 R15: ffff88007849e5c0
FS:  0000000000000000(0000) GS:ffff88007fc00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: ffffea00025958ac CR3: 0000000078f0e000 CR4: 00000000000006f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Stack:
 0000000000000000 ffff8800784a2620 ffff8800784a2600 ffff88007849e5c0
 0000000000000001 ffff88007837f8c0 0000000000000001 ffff88007af8fdd8
 ffffffff8114909c ffff8800784a2618 ffff88007849e5c0 ffff88007837f8c0
Call Trace:
 [<ffffffff8114909c>] drain_array+0xbc/0x120
 [<ffffffff81149c52>] cache_reap+0x82/0x230
 [<ffffffff8105b409>] process_one_work+0x179/0x440
 [<ffffffff8105c04b>] worker_thread+0x11b/0x390
 [<ffffffff8105bf30>] ? manage_workers.isra.25+0x2a0/0x2a0
 [<ffffffff810620c0>] kthread+0xc0/0xd0
 [<ffffffff81062000>] ? insert_kthread_work+0x40/0x40
 [<ffffffff814db15c>] ret_from_fork+0x7c/0xb0
 [<ffffffff81062000>] ? insert_kthread_work+0x40/0x40
Code: 20 48 8b 4b 78 48 8b 45 c8 4c 89 f7 4c 8b 3c 01 e8 b8 9c 13 00 8b 73 10 44 89 ea 41 2b 56 18 48 0f af d6 41 8b 76 24 48 c1 ea 20 <41> 89 74 96 30 41 83 6e 20 01 41 89 56 24 49 8b 47 38 48 8d 50 
RIP  [<ffffffff81148e2e>] free_block+0xee/0x170
 RSP <ffff88007af8fd60>
CR2: ffffea00025958ac
---[ end trace 590780289564f604 ]---
BUG: unable to handle kernel paging request at ffffffffffffffd8
IP: [<ffffffff81062630>] kthread_data+0x10/0x20
PGD 1a0c067 PUD 1a0e067 PMD 0 
Oops: 0000 [#2] SMP 
Modules linked in: tfw_sched_rr(O) tfw_sched_http(O) tfw_sched_hash(O) tfw_sched_dummy(O) tempesta_fw(O) tempesta_db(O) fuse ext3 jbd ext2 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 dm_mirror pcspkr microcode i2c_piix4 i2c_core serio_raw parport_pc parport 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
CPU: 0 PID: 120 Comm: kworker/0:2 Tainted: G      D W  O 3.10.10+ #3
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.8.1-20150318_183358- 04/01/2014
task: ffff88007afa3000 ti: ffff88007af8e000 task.ti: ffff88007af8e000
RIP: 0010:[<ffffffff81062630>]  [<ffffffff81062630>] kthread_data+0x10/0x20
RSP: 0018:ffff88007af8f9c0  EFLAGS: 00010002
RAX: 0000000000000000 RBX: 0000000000000000 RCX: 000000000000000d
RDX: 0000000000000005 RSI: 0000000000000000 RDI: ffff88007afa3000
RBP: ffff88007af8f9c0 R08: ffff88007afa3070 R09: 0000003c7d89cf28
R10: 0000000000000000 R11: 0000000000000000 R12: ffff88007fc12d00
R13: 0000000000000000 R14: ffff88007afa2ff0 R15: ffff88007afa3000
FS:  0000000000000000(0000) GS:ffff88007fc00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 0000000000000028 CR3: 000000007981b000 CR4: 00000000000006f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Stack:
 ffff88007af8f9d8 ffffffff8105c341 ffff88007afa3000 ffff88007af8fa40
 ffffffff814d144a ffff88007af8ffd8 0000000000000000 0000000000012d00
 ffff88007af8ffd8 0000000000012d00 ffff88007afa3000 ffff88007afa3600
Call Trace:
 [<ffffffff8105c341>] wq_worker_sleeping+0x11/0x90
 [<ffffffff814d144a>] __schedule+0x53a/0x7c0
 [<ffffffff814d16f9>] schedule+0x29/0x70
 [<ffffffff81042aa7>] do_exit+0x6e7/0xa50
 [<ffffffff8103fcd8>] ? console_unlock+0x1e8/0x3e0
 [<ffffffff814d4011>] oops_end+0x91/0xd0
 [<ffffffff814c9807>] no_context+0x263/0x270
 [<ffffffff8126e7de>] ? cpumask_next_and+0x2e/0x40
 [<ffffffff814c9881>] __bad_area_nosemaphore+0x6d/0x1c4
 [<ffffffff814c99eb>] bad_area_nosemaphore+0x13/0x15
 [<ffffffff814d67c4>] __do_page_fault+0xa4/0x4d0
 [<ffffffff8107ad06>] ? find_busiest_group+0x36/0x4a0
 [<ffffffff814d6bfe>] do_page_fault+0xe/0x10
 [<ffffffff814d3572>] page_fault+0x22/0x30
 [<ffffffff81148e2e>] ? free_block+0xee/0x170
 [<ffffffff8114909c>] drain_array+0xbc/0x120
 [<ffffffff81149c52>] cache_reap+0x82/0x230
 [<ffffffff8105b409>] process_one_work+0x179/0x440
 [<ffffffff8105c04b>] worker_thread+0x11b/0x390
 [<ffffffff8105bf30>] ? manage_workers.isra.25+0x2a0/0x2a0
 [<ffffffff810620c0>] kthread+0xc0/0xd0
 [<ffffffff81062000>] ? insert_kthread_work+0x40/0x40
 [<ffffffff814db15c>] ret_from_fork+0x7c/0xb0
 [<ffffffff81062000>] ? insert_kthread_work+0x40/0x40
Code: 00 48 89 e5 5d 48 8b 40 c8 48 c1 e8 02 83 e0 01 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 48 8b 87 98 03 00 00 55 48 89 e5 <48> 8b 40 d8 5d c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 
RIP  [<ffffffff81062630>] kthread_data+0x10/0x20
 RSP <ffff88007af8f9c0>
CR2: ffffffffffffffd8
---[ end trace 590780289564f605 ]---
Fixing recursive fault but reboot is needed!

krizhanovsky · 2015-07-08T12:08:56Z

#8 relates to the issue.
Duplicate of #60 (comment).

vdmit11 assigned krizhanovsky Feb 9, 2015

vdmit11 added the bug label Feb 9, 2015

keshonok mentioned this issue Feb 24, 2015

Server backend connection data is not cleared when the connection socket is closed #52

Closed

krizhanovsky mentioned this issue Mar 10, 2015

lb: backend connections hang in TIME_WAIT state after closing #62

Closed

krizhanovsky added this to the 0.3.0 Proxy Filter milestone Mar 15, 2015

krizhanovsky modified the milestones: 0.4.0 Web Server, 0.3.0 Proxy Filter May 24, 2015

krizhanovsky assigned keshonok and unassigned krizhanovsky Jun 19, 2015

krizhanovsky added the crucial label Jun 28, 2015

keshonok added a commit that referenced this issue Jun 29, 2015

Release a hold on a socket when closing it. (#46)

f9c51a6

In some cases sock_put() was not called. Because of that, some sockets were not closed properly: sk->sk_destruct() was not called.

keshonok added a commit that referenced this issue Jul 1, 2015

Few comments regarding the variants of socket close functions (#46).

b4e2d9a

keshonok added a commit that referenced this issue Jul 1, 2015

Merge pull request #133 from natsys/ab-sk-destruct

6a97572

Release a hold on a socket when closing it. (#46)

keshonok closed this as completed Jul 1, 2015

krizhanovsky reopened this Jul 6, 2015

krizhanovsky mentioned this issue Jul 6, 2015

Regression on HTTP request and response parsing #139

Closed

krizhanovsky assigned krizhanovsky and unassigned keshonok Jul 7, 2015

krizhanovsky closed this as completed Jul 8, 2015

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

sk->sk_destruct() is not being called when connection is closed #46

sk->sk_destruct() is not being called when connection is closed #46

vdmit11 commented Feb 9, 2015

keshonok commented Feb 25, 2015

krizhanovsky commented Mar 10, 2015

krizhanovsky commented Mar 24, 2015

keshonok commented Mar 24, 2015

krizhanovsky commented Jun 19, 2015

krizhanovsky commented Jun 28, 2015

keshonok commented Jun 29, 2015

keshonok commented Jul 1, 2015

krizhanovsky commented Jul 6, 2015

krizhanovsky commented Jul 8, 2015

sk->sk_destruct() is not being called when connection is closed #46

sk->sk_destruct() is not being called when connection is closed #46

Comments

vdmit11 commented Feb 9, 2015

keshonok commented Feb 25, 2015

krizhanovsky commented Mar 10, 2015

krizhanovsky commented Mar 24, 2015

keshonok commented Mar 24, 2015

krizhanovsky commented Jun 19, 2015

krizhanovsky commented Jun 28, 2015

keshonok commented Jun 29, 2015

keshonok commented Jul 1, 2015

krizhanovsky commented Jul 6, 2015

krizhanovsky commented Jul 8, 2015