Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
keshonok opened this issue Feb 19, 2015 · 2 comments
Closed

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

keshonok opened this issue Feb 19, 2015 · 2 comments
Assignees
@krizhanovsky
Labels
bug crucial
Milestone
0.3.0 Proxy Filter

Comments

@keshonok
Copy link
Contributor

After a period of inactivity the socket that serves the server backend connection is closed. However the related Tempesta connection data is not cleared. That leads to a stale pointer to the connection data that no longer exists. Consequently, we get a kernel crash on first attempt to use that connection data, which happens on the very next http request.

Loading Tempesta kernel modules...
[   71.978352] [tempesta] Initializing Tempesta FW kernel module...
[   71.978949] [tempesta] init: cfg_if
[   71.979298] [tempesta] init: http
[   71.979616] [tempesta] init: server
[   71.979985] [tempesta] init: client
[   71.980347] [tempesta] init: session
[   71.980686] [tempesta] init: connection
[   71.981044] [tempesta]   register cfg: cache
[   71.981434] [tempesta]   register cfg: sock_backend
[   71.981877] [tempesta]   register cfg: sock_frontend
[   71.999827] [tempesta] Registering new scheduler: dummy
Starting Tempesta...
[   72.002657] [tempesta] got state via sysctl: start
[   72.003130] [tempesta]   reading configuration file...
[   72.003621] [tempesta]   reading file: /home/natsys-lab/tfw-run/tempesta/etc/tempesta_fw.conf
[   72.005235] [tempesta]   file size: 2204 bytes
[   72.005675] [tempesta]   read by offset: 0
[   72.006181] [tempesta]   read by offset: 2204
[   72.006668] [tempesta] starting all modules...
[   72.007093] [tempesta]   parsing configuration and pushing it to modules...
[   72.007762] [tempesta]   use default entry: 'cache off;'
[   72.008312] [tempesta]   spec handle: 'cache'
[   72.008739] [tempesta]   use default entry: 'cache_size 262144;'
[   72.009378] [tempesta]   spec handle: 'cache_size'
[   72.009983] [tempesta]   use default entry: 'cache_dir /opt/tempesta/cache;'
[   72.010878] [tempesta]   spec handle: 'cache_dir'
[   72.011444] [tempesta]   use default entry: 'backend 127.0.0.1:8080;'
[   72.012077] [tempesta]   spec handle: 'backend'
[   72.012509] [tempesta]   use default entry: 'listen 127.0.0.1:80;'
[   72.013088] [tempesta]   spec handle: 'listen'
[   72.013633] [tempesta]   created front-end socket: sk=ffff88003d7a0040
[   72.014246] [tempesta]   starting modules...
[   72.014653] [tempesta]   mod_start(): cache
[   72.015050] [tempesta]   mod_start(): sock_backend
[   72.015501] [tempesta]   Starting thread: tfw_bconnd
[   72.016035] [tempesta]   mod_start(): sock_frontend
[   72.016366] [tempesta]   start listening on socket: sk=ffff88003d7a0040
[   72.016817] [tempesta] modules are started
net.tempesta.state = start
done
done
Starting nginx: nginx.
[   76.016515] [tempesta] Connected to backend: 127.0.0.1:8080
[  136.077004] [sync_socket]   Close socket ffff88003c813280 (account=1)
[  136.079175] [tempesta]   Close socket ffff88003c813280, conn=ffff88003d55e548
[  136.081542] [tempesta]   Free msg:           (null)
[  136.083030] [tempesta]   Free connection: ffff88003d55e548
[  136.084197] [sync_socket]   free rcv skb ffff88003d638da8
[  275.983382] [tempesta]   New client socket ffff88003c812980 (state=1)
[  275.984126] [tempesta]   Link new msg ffff88003d5e8040 with connection ffff88003c881548
[  275.984758] [tempesta]   Add skb ffff88003d4e0de8 to message ffff88003d5e8040
[  275.985324] [tempesta]   Received 109 client data bytes (GET / HTTP/1.1
[  275.985324] User-Agent: Wget/1.13.4 (linux-gnu)
[  275.985324] Accept: */*
[  275.985324] Host: 127.0.0.1
[  275.985324] Connection: Keep-Alive
[  275.985324] 
[  275.985324] ) on socket (conn=ffff88003c881548)
[  275.987351] [tempesta]   enter FSM at state 0
[  275.987696] [tempesta]   parser: Req_0(0:0): c=0x47(G), r=-2
[  275.988163] [tempesta]   parser: Req_Method(1:0): c=0x47(G), r=-2
[  275.988643] [tempesta]   parser: Req_MUSpace(2:0): c=0x2f(/), r=-2
[  275.989130] [tempesta]   parser: Req_UriAbsPath(6:0): c=0x20( ), r=-2
[  275.989633] [tempesta]   parser: Req_HttpVer(7:0): c=0x48(H), r=-2
[  275.990116] [tempesta]   parser: Req_EoL(15:0): c=0xd(.), r=-2
[  275.990574] [tempesta]   parser: Req_EoL(15:0): c=0xa(.), r=-2
[  275.991030] [tempesta]   parser: Req_Hdr(16:0): c=0x55(U), r=-2
[  275.991497] [tempesta]   parser: Req_HdrOther(92:0): c=0x55(U), r=-2
[  275.992019] [tempesta]   store header w/ ptr=ffff88003d51b8b0 len=35 flags=0 id=3
[  275.992513] [tempesta]   parser: Req_Hdr(16:0): c=0x41(A), r=-2
[  275.992905] [tempesta]   parser: Req_HdrOther(92:0): c=0x41(A), r=-2
[  275.993324] [tempesta]   store header w/ ptr=ffff88003d51b8d5 len=11 flags=0 id=4
[  275.993817] [tempesta]   parser: Req_Hdr(16:0): c=0x48(H), r=-2
[  275.994211] [tempesta]   parser: RGen_LWS(10000:21): c=0x20( ), r=-2
[  275.994630] [tempesta]   parser: RGen_LWS(10000:21): c=0x31(1), r=-2
[  275.995049] [tempesta]   enter FSM at state 21
[  275.995346] [tempesta]   parser: Req_HdrHostV(21:0): c=0x31(1), r=-2
[  275.995765] [tempesta]   enter FSM at state 1
[  275.996064] [tempesta]   parser: Req_I_H(1:1): c=0x31(1), r=-2
[  275.996450] [tempesta]   parser: Req_I_H(1:1): c=0x32(2), r=-2
[  275.996836] [tempesta]   parser: Req_I_H(1:1): c=0x37(7), r=-2
[  275.997224] [tempesta]   parser: Req_I_H(1:1): c=0x2e(.), r=-2
[  275.997610] [tempesta]   parser: Req_I_H(1:1): c=0x30(0), r=-2
[  275.997996] [tempesta]   parser: Req_I_H(1:1): c=0x2e(.), r=-2
[  275.998383] [tempesta]   parser: Req_I_H(1:1): c=0x30(0), r=-2
[  275.998768] [tempesta]   parser: Req_I_H(1:1): c=0x2e(.), r=-2
[  275.999154] [tempesta]   parser: Req_I_H(1:1): c=0x31(1), r=-2
[  275.999542] [tempesta]   parser: Req_I_H(1:1): c=0xd(.), r=-2
[  275.999922] [tempesta]   parser: Req_I_H_EoL(3:1): c=0xd(.), r=-2
[  276.000337] [tempesta]   parser: Req_I_H_EoL(3:1): c=0xa(.), r=-2
[  276.000740] [tempesta]   parse header __req_parse_host: ret=11 plen=9 id=1
[  276.001193] [tempesta]   store header w/ ptr=ffff88003d51b8e2 len=15 flags=0 id=1
[  276.001684] [tempesta]   parser: Req_Hdr(16:0): c=0x43(C), r=-2
[  276.002074] [tempesta]   parser: Req_HdrC(22:0): c=0x6f(o), r=-2
[  276.002474] [tempesta]   parser: Req_HdrConnection(44:0): c=0x3a(:), r=-2
[  276.002923] [tempesta]   parser: RGen_LWS(10000:45): c=0x20( ), r=-2
[  276.003344] [tempesta]   parser: RGen_LWS(10000:45): c=0x4b(K), r=-2
[  276.003763] [tempesta]   enter FSM at state 45
[  276.004070] [tempesta]   parser: Req_HdrConnectionV(45:0): c=0x4b(K), r=-2
[  276.004523] [tempesta]   enter FSM at state 1
[  276.004813] [tempesta]   parser: I_Conn(1:1): c=0x4b(K), r=-2
[  276.005275] [tempesta]   parser: I_EoT(6:1): c=0xd(.), r=0
[  276.005692] [tempesta]   parser: I_EoL(7:1): c=0xd(.), r=0
[  276.006058] [tempesta]   parser: I_EoL(7:1): c=0xa(.), r=0
[  276.006422] [tempesta]   parser: Connection parsed: flags 0x2
[  276.006805] [tempesta]   parse header __parse_connection: ret=12 plen=10 id=0
[  276.007301] [tempesta]   store header w/ ptr=ffff88003d51b8f3 len=22 flags=0 id=0
[  276.007799] [tempesta]   parser: Req_Hdr(16:0): c=0xd(.), r=-2
[  276.008206] [tempesta]   parser: Req_HdrDone(93:0): c=0xa(.), r=-2
[  276.008617] [tempesta]   parse msg body: flags=0x2 content_length=0
[  276.009035] [tempesta]   request parsed: len=109 parsed=109 msg_len=109 res=0
[  276.009507] [tempesta]   GFSM return code 0
[  276.009791] [tempesta]   added X-Forwarded-For header: X-Forwarded-For: 127.0.0.1
[  276.009791] 
[  276.010393] BUG: unable to handle kernel NULL pointer dereference at 0000000000000020
[  276.010929] IP: [<ffffffffa0011bf8>] tfw_connection_send_srv+0x67/0xc6 [tempesta_fw]
[  276.011460] PGD 3dbaf067 PUD 3dbe8067 PMD 0 
[  276.011775] Oops: 0000 [#1] SMP 
[  276.012030] Modules linked in: tfw_sched_dummy(O) tempesta_fw(O) tempesta_db(O) sync_socket(O)
[  276.012200] CPU: 0 PID: 2287 Comm: wget Tainted: G           O 3.10.10-tempesta #7
[  276.012200] task: ffff88003d5890c0 ti: ffff88003c8de000 task.ti: ffff88003c8de000
[  276.012200] RIP: 0010:[<ffffffffa0011bf8>]  [<ffffffffa0011bf8>] tfw_connection_send_srv+0x67/0xc6 [tempesta_fw]
[  276.012200] RSP: 0018:ffff88003fc039e8  EFLAGS: 00010286
[  276.012200] RAX: 0000000000000000 RBX: ffff88003d4e0de8 RCX: 0000000000000000
[  276.012200] RDX: ffff88003c880400 RSI: 0000000000000200 RDI: ffff88003d58a490
[  276.012200] RBP: ffff88003fc03a00 R08: 0000000000000000 R09: 0000000000000000
[  276.012200] R10: 0000000000000001 R11: ffff88003fc035c6 R12: ffff88003d51b8a0
[  276.012200] R13: 000000000000006d R14: ffff88003c812980 R15: 0000000000000000
[  276.012200] FS:  00007f239b86f700(0000) GS:ffff88003fc00000(0000) knlGS:0000000000000000
[  276.012200] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  276.012200] CR2: 0000000000000020 CR3: 000000003d75a000 CR4: 00000000000006b0
[  276.012200] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  276.012200] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[  276.012200] Stack:
[  276.012200]  ffff88003d5e8040 ffff88003d58a490 0000000000000000 ffff88003fc03a30
[  276.012200]  ffffffffa0015360 ffff88003d58a490 0000000000000000 ffff88003d5e8040
[  276.012200]  ffff88003d58a490 ffff88003fc03a78 ffffffffa000ddec ffff88003d58a490
[  276.012200] Call Trace:
[  276.012200]  <IRQ> 
[  276.012200]  [<ffffffffa0015360>] tfw_http_req_cache_cb+0x5d/0x5f [tempesta_fw]
[  276.012200]  [<ffffffffa000ddec>] tfw_cache_req_process+0x39/0x163 [tempesta_fw]
[  276.012200]  [<ffffffffa0015303>] ? tfw_http_adjust_resp+0x13/0x13 [tempesta_fw]
[  276.012200]  [<ffffffffa001561e>] tfw_http_req_process+0x2bc/0x32b [tempesta_fw]
[  276.012200]  [<ffffffffa00159f9>] tfw_http_msg_process+0x43/0x5e [tempesta_fw]
[  276.012200]  [<ffffffffa0012d0b>] tfw_gfsm_dispatch+0x41/0x43 [tempesta_fw]
[  276.012200]  [<ffffffffa0011e11>] tfw_connection_recv+0x88/0x8a [tempesta_fw]
[  276.012200]  [<ffffffffa000005b>] ss_tcp_process_proto_skb+0x5b/0x90 [sync_socket]
[  276.012200]  [<ffffffffa000020f>] ss_tcp_process_skb+0x17f/0x190 [sync_socket]
[  276.012200]  [<ffffffffa0000d8e>] ss_tcp_data_ready+0x10e/0x25e [sync_socket]
[  276.012200]  [<ffffffff8133425d>] tcp_data_queue+0x4dd/0xd10
[  276.012200]  [<ffffffff81337660>] tcp_rcv_established+0x560/0x620
[  276.012200]  [<ffffffff8134183c>] tcp_v4_do_rcv+0x1dc/0x4e0
[  276.012200]  [<ffffffff811eea42>] ? do_raw_spin_lock+0x82/0x140
[  276.012200]  [<ffffffff813433e7>] tcp_v4_rcv+0x437/0x8b0
[  276.012200]  [<ffffffff8131d7c5>] ip_local_deliver_finish+0xb5/0x150
[  276.012200]  [<ffffffff8131d750>] ? ip_local_deliver_finish+0x40/0x150
[  276.012200]  [<ffffffff8131df70>] ip_local_deliver+0x50/0x90
[  276.012200]  [<ffffffff8131dcde>] ip_rcv_finish+0x47e/0x580
[  276.012200]  [<ffffffff8131e26c>] ip_rcv+0x2bc/0x340
[  276.012200]  [<ffffffff812e6869>] __netif_receive_skb_core+0x469/0x590
[  276.012200]  [<ffffffff812e6463>] ? __netif_receive_skb_core+0x63/0x590
[  276.012200]  [<ffffffff8107258e>] ? mark_held_locks+0x10e/0x130
[  276.012200]  [<ffffffff812e69df>] __netif_receive_skb+0x4f/0x70
[  276.012200]  [<ffffffff812e855f>] process_backlog+0x7f/0x200
[  276.012200]  [<ffffffff812e8783>] net_rx_action+0xa3/0x1f0
[  276.012200]  [<ffffffff81036550>] __do_softirq+0xe0/0x1d0
[  276.012200]  [<ffffffff813c5afc>] call_softirq+0x1c/0x26
[  276.012200]  <EOI> 
[  276.012200]  [<ffffffff81003ef5>] do_softirq+0x65/0x100
[  276.012200]  [<ffffffff81322db4>] ? ip_finish_output+0x3f4/0x500
[  276.012200]  [<ffffffff81035dc0>] local_bh_enable+0xd0/0x120
[  276.012200]  [<ffffffff81322db4>] ip_finish_output+0x3f4/0x500
[  276.012200]  [<ffffffff81322c10>] ? ip_finish_output+0x250/0x500
[  276.012200]  [<ffffffff81323e35>] ip_output+0x95/0x110
[  276.012200]  [<ffffffff813233ee>] ip_local_out+0x5e/0x90
[  276.012200]  [<ffffffff813239ff>] ip_queue_xmit+0x38f/0x4a0
[  276.012200]  [<ffffffff81323670>] ? ip_build_and_send_pkt+0x250/0x250
[  276.012200]  [<ffffffff8133a7e2>] tcp_transmit_skb+0x792/0x820
[  276.012200]  [<ffffffff8133b1dd>] tcp_write_xmit+0x96d/0xb40
[  276.012200]  [<ffffffff8133b61d>] __tcp_push_pending_frames+0x2d/0xd0
[  276.012200]  [<ffffffff8132b171>] tcp_push+0x81/0x90
[  276.012200]  [<ffffffff8132fb03>] tcp_sendmsg+0xa23/0xc00
[  276.012200]  [<ffffffff813563ff>] inet_sendmsg+0xdf/0x100
[  276.012200]  [<ffffffff81356320>] ? inet_sendpage+0x130/0x130
[  276.012200]  [<ffffffff812d1232>] sock_aio_write+0x142/0x160
[  276.012200]  [<ffffffff810f9cc4>] ? core_sys_select+0x34/0x3c0
[  276.012200]  [<ffffffff810e6d61>] do_sync_write+0x81/0xa0
[  276.012200]  [<ffffffff810e75c5>] vfs_write+0xe5/0x1b0
[  276.012200]  [<ffffffff810e7b87>] SyS_write+0x47/0x90
[  276.012200]  [<ffffffff813c4729>] system_call_fastpath+0x16/0x1b
[  276.012200] Code: a0 b8 00 00 00 00 e8 36 a1 3a e1 b8 ff ff ff ff eb 76 48 8b 45 f0 be 00 02 00 00 48 89 c7 e8 73 fb ff ff 48 89 45 f8 48 8b 45 f8 <48> 8b 40 20 48 85 c0 0f 95 c0 0f b6 c0 48 85 c0 74 19 48 8b 45 
[  276.012200] RIP  [<ffffffffa0011bf8>] tfw_connection_send_srv+0x67/0xc6 [tempesta_fw]
[  276.012200]  RSP <ffff88003fc039e8>
[  276.012200] CR2: 0000000000000020
[  276.044634] ---[ end trace ccbde25cbefb1ae1 ]---
[  276.044946] Kernel panic - not syncing: Fatal exception in interrupt
@keshonok keshonok mentioned this issue Feb 19, 2015
Closed
@keshonok
Copy link
Contributor Author

This issue is closely related to #46 - sk->sk_destruct() is not being called when connection is closed

@keshonok keshonok mentioned this issue Feb 25, 2015
Closed
@krizhanovsky krizhanovsky self-assigned this Mar 10, 2015
@krizhanovsky krizhanovsky added this to the 0.3.0 Proxy Filter milestone Mar 15, 2015
@krizhanovsky
Copy link
Contributor

The log bit outdated. The function offsets pints somewhere just after tfw_sess_conn() call (now the addresses are different):

5d8e:       e8 55 fb ff ff          callq  58e8 <tfw_sess_conn>
5d93:       48 89 45 f8             mov    %rax,-0x8(%rbp)
5d97:       48 8b 45 f8             mov    -0x8(%rbp),%rax
5d9b:       48 8b 40 20             mov    0x20(%rax),%rax
5d9f:       48 85 c0                test   %rax,%rax

And now the Oops looks as following

    [tempesta]   parser: Req_HdrDone(93:0): c=0xa(.), r=-2
    [tempesta]   parse msg body: flags=0x2 content_length=0
    [tempesta]   request parsed: len=273 parsed=273 msg_len=273 res=0
    [tempesta]   GFSM return code 0
    [tempesta]   added X-Forwarded-For header: X-Forwarded-For: 172.16.0.1^M

    ------------[ cut here ]------------
    kernel BUG at /root/tempesta/tempesta_fw/connection.c:180!
    invalid opcode: 0000 [#1] SMP
    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 pcspkr microcode serio_raw i2c_piix4 i2c_core parport_pc parport 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           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
    task: ffff8800783b2000 ti: ffff88007842e000 task.ti: ffff88007842e000
    RIP: 0010:[<ffffffffa044fdc4>]  [<ffffffffa044fdc4>] tfw_connection_send_srv+0x95/0xcb [tempesta_fw]
    RSP: 0018:ffff88007842f740  EFLAGS: 00010202
    RAX: 0000000000000001 RBX: ffff88002c141040 RCX: 0000000000000000
    RDX: ffff88002c2e4448 RSI: 0000000000000200 RDI: ffff88002c13c3b0
    RBP: ffff88007842f758 R08: 0000000000000000 R09: 0000000000000383
    R10: 0000000000000050 R11: 0000000000000006 R12: ffff88007b2351c0
    R13: 0000000000000000 R14: ffff88007b2351c0 R15: 0000000000000111
    FS:  0000000000000000(0000) GS:ffff88007fd00000(0000) knlGS:0000000000000000
    CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
    CR2: 00007f1e139d3000 CR3: 0000000001a0b000 CR4: 00000000000006e0
    DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
    DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
    Stack:
     ffff88007be44040 ffff88002c13c3b0 ffff88002c149438 ffff88007842f788
     ffffffffa04536bf ffff88002c13c3b0 0000000000000000 ffff88007be44040
     ffff88002c13c3b0 ffff88007842f7d0 ffffffffa044be9d ffff88002c13c3b0
    Call Trace:
     [<ffffffffa04536bf>] tfw_http_req_cache_cb+0x62/0x64 [tempesta_fw]
     [<ffffffffa044be9d>] tfw_cache_req_process+0x3e/0x140 [tempesta_fw]
     [<ffffffffa045365d>] ? tfw_http_adjust_resp+0x18/0x18 [tempesta_fw]
     [<ffffffffa0453982>] tfw_http_req_process+0x2c1/0x330 [tempesta_fw]
     [<ffffffffa0453d67>] tfw_http_msg_process+0x48/0x63 [tempesta_fw]
     [<ffffffffa0450f7b>] tfw_gfsm_dispatch+0x46/0x48 [tempesta_fw]
     [<ffffffffa044ffc3>] tfw_connection_recv+0x8d/0x8f [tempesta_fw]
     [<ffffffffa04380f4>] ss_tcp_process_proto_skb+0x24/0x60 [sync_socket]
     [<ffffffffa04382ed>] ss_tcp_process_skb+0x1bd/0x1d0 [sync_socket]
     [<ffffffffa0438b75>] ss_tcp_data_ready+0x115/0x260 [sync_socket]

@krizhanovsky krizhanovsky mentioned this issue Mar 20, 2015
Closed
krizhanovsky added a commit that referenced this issue Mar 24, 2015
@krizhanovsky
1. Rework session management: remove session.[ch] at all which fixed #23
30f0e6d 
 and #52;

2. Introduce TLS/SSL support in tls.c;
3. Rename backend/frontend sockets server/client correspondingly with forward proxy in mind;
4. Many code cleanups and and some small fixes.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@krizhanovsky krizhanovsky

Labels
bug crucial
Projects
None yet
Milestone
0.3.0 Proxy Filter
Development

No branches or pull requests
2 participants
@krizhanovsky @keshonok