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.

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

Kernel panic when freeing a Tempesta message #56

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

Kernel panic when freeing a Tempesta message #56

keshonok opened this issue Feb 19, 2015 · 5 comments
Assignees

Comments

@keshonok
Copy link
Contributor

This appears to be a case of SKB's double-free - freeing an SKB that had been freed already.

Loading Tempesta kernel modules...
[    8.219962] [tempesta] Initializing Tempesta FW kernel module...
[    8.220504] [tempesta] init: cfg_if
[    8.220800] [tempesta] init: http
[    8.221066] [tempesta] init: server
[    8.221363] [tempesta] init: client
[    8.221650] [tempesta] init: session
[    8.221944] [tempesta] init: connection
[    8.222268] [tempesta]   register cfg: cache
[    8.222613] [tempesta]   register cfg: sock_backend
[    8.223006] [tempesta]   register cfg: sock_frontend
[    8.238490] [tempesta] Registering new scheduler: dummy
Starting Tempesta...
[    8.240987] [tempesta] got state via sysctl: start
[    8.241387] [tempesta]   reading configuration file...
[    8.241800] [tempesta]   reading file: /home/natsys-lab/tfw-run/tempesta/etc/tempesta_fw.conf
[    8.242864] [tempesta]   file size: 2224 bytes
[    8.243236] [tempesta]   read by offset: 0
[    8.243717] [tempesta]   read by offset: 2224
[    8.244194] [tempesta] starting all modules...
[    8.244559] [tempesta]   parsing configuration and pushing it to modules...
[    8.245134] [tempesta]   spec handle: 'listen'
[    8.245616] [tempesta]   created front-end socket: sk=ffff88003cc2e040
[    8.246197] [tempesta]   use default entry: 'cache off;'
[    8.246758] [tempesta]   spec handle: 'cache'
[    8.247231] [tempesta]   use default entry: 'cache_size 262144;'
[    8.247975] [tempesta]   spec handle: 'cache_size'
[    8.248682] [tempesta]   use default entry: 'cache_dir /opt/tempesta/cache;'
[    8.249596] [tempesta]   spec handle: 'cache_dir'
[    8.250104] [tempesta]   use default entry: 'backend 127.0.0.1:8080;'
[    8.250533] [tempesta]   spec handle: 'backend'
[    8.250833] [tempesta]   starting modules...
[    8.251111] [tempesta]   mod_start(): cache
[    8.251383] [tempesta]   mod_start(): sock_backend
[    8.251695] [tempesta]   Starting thread: tfw_bconnd
[    8.252101] [tempesta]   mod_start(): sock_frontend
[    8.252432] [tempesta]   start listening on socket: sk=ffff88003cc2e040
[    8.252886] [tempesta] modules are started
net.tempesta.state = start
done
done
Starting nginx: nginx.
[   12.253724] [tempesta] Connected to backend: 127.0.0.1:8080
[   25.326849] [tempesta]   New client socket ffff88003d4af2c0 (state=1)
[   25.327669] [tempesta]   Link new msg ffff88003d411040 with connection ffff88003d660590
[   25.328621] [tempesta]   Add skb ffff88003d6b7da8 to message ffff88003d411040
[   25.329299] [tempesta]   Received 109 client data bytes (GET / HTTP/1.1
[   25.329299] User-Agent: Wget/1.13.4 (linux-gnu)
[   25.329299] Accept: */*
[   25.329299] Host: 127.0.0.1
[   25.329299] Connection: Keep-Alive
[   25.329299] 
[   25.329299] ) on socket (conn=ffff88003d660590)
[   25.331721] [tempesta]   enter FSM at state 0
[   25.332140] [tempesta]   parser: Req_0(0:0): c=0x47(G), r=-2
[   25.332666] [tempesta]   parser: Req_Method(1:0): c=0x47(G), r=-2
[   25.333231] [tempesta]   parser: Req_MUSpace(2:0): c=0x2f(/), r=-2
[   25.333804] [tempesta]   parser: Req_UriAbsPath(6:0): c=0x20( ), r=-2
[   25.334404] [tempesta]   parser: Req_HttpVer(7:0): c=0x48(H), r=-2
[   25.334976] [tempesta]   parser: Req_EoL(15:0): c=0xd(.), r=-2
[   25.335526] [tempesta]   parser: Req_EoL(15:0): c=0xa(.), r=-2
[   25.336075] [tempesta]   parser: Req_Hdr(16:0): c=0x55(U), r=-2
[   25.336626] [tempesta]   parser: Req_HdrOther(92:0): c=0x55(U), r=-2
[   25.337213] [tempesta]   store header w/ ptr=ffff88003dbdb0b0 len=35 flags=0 id=3
[   25.337900] [tempesta]   parser: Req_Hdr(16:0): c=0x41(A), r=-2
[   25.338351] [tempesta]   parser: Req_HdrOther(92:0): c=0x41(A), r=-2
[   25.338768] [tempesta]   store header w/ ptr=ffff88003dbdb0d5 len=11 flags=0 id=4
[   25.339256] [tempesta]   parser: Req_Hdr(16:0): c=0x48(H), r=-2
[   25.339644] [tempesta]   parser: RGen_LWS(10000:21): c=0x20( ), r=-2
[   25.340067] [tempesta]   parser: RGen_LWS(10000:21): c=0x31(1), r=-2
[   25.340486] [tempesta]   enter FSM at state 21
[   25.340780] [tempesta]   parser: Req_HdrHostV(21:0): c=0x31(1), r=-2
[   25.341196] [tempesta]   enter FSM at state 1
[   25.341484] [tempesta]   parser: Req_I_H(1:1): c=0x31(1), r=-2
[   25.341867] [tempesta]   parser: Req_I_H(1:1): c=0x32(2), r=-2
[   25.342253] [tempesta]   parser: Req_I_H(1:1): c=0x37(7), r=-2
[   25.342636] [tempesta]   parser: Req_I_H(1:1): c=0x2e(.), r=-2
[   25.343020] [tempesta]   parser: Req_I_H(1:1): c=0x30(0), r=-2
[   25.343402] [tempesta]   parser: Req_I_H(1:1): c=0x2e(.), r=-2
[   25.343783] [tempesta]   parser: Req_I_H(1:1): c=0x30(0), r=-2
[   25.344176] [tempesta]   parser: Req_I_H(1:1): c=0x2e(.), r=-2
[   25.344561] [tempesta]   parser: Req_I_H(1:1): c=0x31(1), r=-2
[   25.344944] [tempesta]   parser: Req_I_H(1:1): c=0xd(.), r=-2
[   25.345322] [tempesta]   parser: Req_I_H_EoL(3:1): c=0xd(.), r=-2
[   25.345722] [tempesta]   parser: Req_I_H_EoL(3:1): c=0xa(.), r=-2
[   25.346124] [tempesta]   parse header __req_parse_host: ret=11 plen=9 id=1
[   25.346573] [tempesta]   store header w/ ptr=ffff88003dbdb0e2 len=15 flags=0 id=1
[   25.347059] [tempesta]   parser: Req_Hdr(16:0): c=0x43(C), r=-2
[   25.347447] [tempesta]   parser: Req_HdrC(22:0): c=0x6f(o), r=-2
[   25.347841] [tempesta]   parser: Req_HdrConnection(44:0): c=0x3a(:), r=-2
[   25.348292] [tempesta]   parser: RGen_LWS(10000:45): c=0x20( ), r=-2
[   25.348709] [tempesta]   parser: RGen_LWS(10000:45): c=0x4b(K), r=-2
[   25.349126] [tempesta]   enter FSM at state 45
[   25.349420] [tempesta]   parser: Req_HdrConnectionV(45:0): c=0x4b(K), r=-2
[   25.349869] [tempesta]   enter FSM at state 1
[   25.350160] [tempesta]   parser: I_Conn(1:1): c=0x4b(K), r=-2
[   25.350538] [tempesta]   parser: I_EoT(6:1): c=0xd(.), r=0
[   25.350898] [tempesta]   parser: I_EoL(7:1): c=0xd(.), r=0
[   25.351259] [tempesta]   parser: I_EoL(7:1): c=0xa(.), r=0
[   25.351619] [tempesta]   parser: Connection parsed: flags 0x2
[   25.351997] [tempesta]   parse header __parse_connection: ret=12 plen=10 id=0
[   25.352474] [tempesta]   store header w/ ptr=ffff88003dbdb0f3 len=22 flags=0 id=0
[   25.352965] [tempesta]   parser: Req_Hdr(16:0): c=0xd(.), r=-2
[   25.353349] [tempesta]   parser: Req_HdrDone(93:0): c=0xa(.), r=-2
[   25.353755] [tempesta]   parse msg body: flags=0x2 content_length=0
[   25.354167] [tempesta]   request parsed: len=109 parsed=109 msg_len=109 res=0
[   25.354632] [tempesta]   GFSM return code 0
[   25.354910] [tempesta]   added X-Forwarded-For header: X-Forwarded-For: 127.0.0.1
[   25.354910] 
[   25.355497] 
[   25.355602] =============================================
[   25.355955] [ INFO: possible recursive locking detected ]
[   25.356312] 3.10.10-tempesta #7 Tainted: G           O
[   25.356470] ---------------------------------------------
[   25.356470] wget/1954 is trying to acquire lock:
[   25.356470]  (slock-AF_INET/1){+.-...}, at: [<ffffffffa00002c8>] ss_send+0x28/0x160 [sync_socket]
[   25.356470] 
[   25.356470] but task is already holding lock:
[   25.356470]  (slock-AF_INET/1){+.-...}, at: [<ffffffff813433bc>] tcp_v4_rcv+0x40c/0x8b0
[   25.356470] 
[   25.356470] other info that might help us debug this:
[   25.356470]  Possible unsafe locking scenario:
[   25.356470] 
[   25.356470]        CPU0
[   25.356470]        ----
[   25.356470]   lock(slock-AF_INET/1);
[   25.356470]   lock(slock-AF_INET/1);
[   25.356470] 
[   25.356470]  *** DEADLOCK ***
[   25.356470] 
[   25.356470]  May be due to missing lock nesting notation
[   25.356470] 
[   25.356470] 5 locks held by wget/1954:
[   25.356470]  #0:  (sk_lock-AF_INET){+.+.+.}, at: [<ffffffff8132f107>] tcp_sendmsg+0x27/0xc00
[   25.356470]  #1:  (rcu_read_lock){.+.+..}, at: [<ffffffff81323670>] ip_queue_xmit+0x0/0x4a0
[   25.356470]  #2:  (rcu_read_lock){.+.+..}, at: [<ffffffff812e6463>] __netif_receive_skb_core+0x63/0x590
[   25.356470]  #3:  (rcu_read_lock){.+.+..}, at: [<ffffffff8131d750>] ip_local_deliver_finish+0x40/0x150
[   25.356470]  #4:  (slock-AF_INET/1){+.-...}, at: [<ffffffff813433bc>] tcp_v4_rcv+0x40c/0x8b0
[   25.356470] 
[   25.356470] stack backtrace:
[   25.356470] CPU: 0 PID: 1954 Comm: wget Tainted: G           O 3.10.10-tempesta #7
[   25.356470]  ffff88003d645080 ffff88003fc038c0 ffffffff813bf35d ffff88003fc03930
[   25.356470]  ffffffff81073b96 ffff88003d6b7da8 ffff88003fc03938 ffffffffa0014169
[   25.356470]  ffff880000000000 00000b00584a0250 ffffffff00000000 ffffffff816f5cc0
[   25.356470] Call Trace:
[   25.356470]  <IRQ>  [<ffffffff813bf35d>] dump_stack+0x19/0x1b
[   25.356470]  [<ffffffff81073b96>] __lock_acquire+0xfa6/0x1240
[   25.356470]  [<ffffffffa0014169>] ? __hdr_add+0x96/0x17a [tempesta_fw]
[   25.356470]  [<ffffffff81074658>] lock_acquire+0x98/0xd0
[   25.356470]  [<ffffffffa00002c8>] ? ss_send+0x28/0x160 [sync_socket]
[   25.356470]  [<ffffffff813c30ca>] _raw_spin_lock_nested+0x3a/0x50
[   25.356470]  [<ffffffffa00002c8>] ? ss_send+0x28/0x160 [sync_socket]
[   25.356470]  [<ffffffffa00002c8>] ss_send+0x28/0x160 [sync_socket]
[   25.356470]  [<ffffffffa00493d1>] ? tfw_sched_get_srv+0x49/0x4b [tempesta_fw]
[   25.356470]  [<ffffffffa0011c50>] tfw_connection_send_srv+0xbf/0xc6 [tempesta_fw]
[   25.356470]  [<ffffffffa0015360>] tfw_http_req_cache_cb+0x5d/0x5f [tempesta_fw]
[   25.356470]  [<ffffffffa000ddec>] tfw_cache_req_process+0x39/0x163 [tempesta_fw]
[   25.356470]  [<ffffffffa0015303>] ? tfw_http_adjust_resp+0x13/0x13 [tempesta_fw]
[   25.356470]  [<ffffffffa001561e>] tfw_http_req_process+0x2bc/0x32b [tempesta_fw]
[   25.356470]  [<ffffffffa00159f9>] tfw_http_msg_process+0x43/0x5e [tempesta_fw]
[   25.356470]  [<ffffffffa0012d0b>] tfw_gfsm_dispatch+0x41/0x43 [tempesta_fw]
[   25.356470]  [<ffffffffa0011e11>] tfw_connection_recv+0x88/0x8a [tempesta_fw]
[   25.356470]  [<ffffffffa000005b>] ss_tcp_process_proto_skb+0x5b/0x90 [sync_socket]
[   25.356470]  [<ffffffffa000020f>] ss_tcp_process_skb+0x17f/0x190 [sync_socket]
[   25.356470]  [<ffffffffa0000d8e>] ss_tcp_data_ready+0x10e/0x25e [sync_socket]
[   25.356470]  [<ffffffff8133425d>] tcp_data_queue+0x4dd/0xd10
[   25.356470]  [<ffffffff81337660>] tcp_rcv_established+0x560/0x620
[   25.356470]  [<ffffffff8134183c>] tcp_v4_do_rcv+0x1dc/0x4e0
[   25.356470]  [<ffffffff811eea42>] ? do_raw_spin_lock+0x82/0x140
[   25.356470]  [<ffffffff813433e7>] tcp_v4_rcv+0x437/0x8b0
[   25.356470]  [<ffffffff8131d7c5>] ip_local_deliver_finish+0xb5/0x150
[   25.356470]  [<ffffffff8131d750>] ? ip_local_deliver_finish+0x40/0x150
[   25.356470]  [<ffffffff8131df70>] ip_local_deliver+0x50/0x90
[   25.356470]  [<ffffffff8131dcde>] ip_rcv_finish+0x47e/0x580
[   25.356470]  [<ffffffff8131e26c>] ip_rcv+0x2bc/0x340
[   25.356470]  [<ffffffff812e6869>] __netif_receive_skb_core+0x469/0x590
[   25.356470]  [<ffffffff812e6463>] ? __netif_receive_skb_core+0x63/0x590
[   25.356470]  [<ffffffff8107258e>] ? mark_held_locks+0x10e/0x130
[   25.356470]  [<ffffffff812e69df>] __netif_receive_skb+0x4f/0x70
[   25.356470]  [<ffffffff812e855f>] process_backlog+0x7f/0x200
[   25.356470]  [<ffffffff812e8783>] net_rx_action+0xa3/0x1f0
[   25.356470]  [<ffffffff81036550>] __do_softirq+0xe0/0x1d0
[   25.356470]  [<ffffffff813c5afc>] call_softirq+0x1c/0x26
[   25.356470]  <EOI>  [<ffffffff81003ef5>] do_softirq+0x65/0x100
[   25.356470]  [<ffffffff81322db4>] ? ip_finish_output+0x3f4/0x500
[   25.356470]  [<ffffffff81035dc0>] local_bh_enable+0xd0/0x120
[   25.356470]  [<ffffffff81322db4>] ip_finish_output+0x3f4/0x500
[   25.356470]  [<ffffffff81322c10>] ? ip_finish_output+0x250/0x500
[   25.356470]  [<ffffffff81323e35>] ip_output+0x95/0x110
[   25.356470]  [<ffffffff813233ee>] ip_local_out+0x5e/0x90
[   25.356470]  [<ffffffff813239ff>] ip_queue_xmit+0x38f/0x4a0
[   25.356470]  [<ffffffff81323670>] ? ip_build_and_send_pkt+0x250/0x250
[   25.356470]  [<ffffffff8133a7e2>] tcp_transmit_skb+0x792/0x820
[   25.356470]  [<ffffffff8133b1dd>] tcp_write_xmit+0x96d/0xb40
[   25.356470]  [<ffffffff8133b61d>] __tcp_push_pending_frames+0x2d/0xd0
[   25.356470]  [<ffffffff8132b171>] tcp_push+0x81/0x90
[   25.356470]  [<ffffffff8132fb03>] tcp_sendmsg+0xa23/0xc00
[   25.356470]  [<ffffffff813563ff>] inet_sendmsg+0xdf/0x100
[   25.356470]  [<ffffffff81356320>] ? inet_sendpage+0x130/0x130
[   25.356470]  [<ffffffff812d1232>] sock_aio_write+0x142/0x160
[   25.356470]  [<ffffffff810f9cc4>] ? core_sys_select+0x34/0x3c0
[   25.356470]  [<ffffffff810e6d61>] do_sync_write+0x81/0xa0
[   25.356470]  [<ffffffff810e75c5>] vfs_write+0xe5/0x1b0
[   25.356470]  [<ffffffff810e7b87>] SyS_write+0x47/0x90
[   25.356470]  [<ffffffff813c4729>] system_call_fastpath+0x16/0x1b
[   25.391764] [sync_socket]   ss_send:89 entail skb=ffff88003d6b7da8 data_len=0 len=137
[   25.392290] [sync_socket]   ss_send:99 sk=ffff88003d71b280 is_queue_empty=0 tcp_send_head(sk)=ffff88003d6b7da8 sk->sk_state=1
[   25.393662] [tempesta]   Link new msg ffff88003cc69040 with connection ffff88003d660548
[   25.394205] [tempesta]   Add skb ffff88003d6b7ba8 to message ffff88003cc69040
[   25.394677] [tempesta]   received 215 server data bytes (HTTP/1.1 200 OK
[   25.394677] Server: nginx/1.2.1
[   25.394677] Date: Thu, 19 Feb 2015 11:24:07 GMT
[   25.394677] Content-Type: text/html
[   25.394677] Content-Length: 151
[   25.394677] Last-Modified: Mon, 04 Oct 2004 15:04:06 GMT
[   25.394677] Connection: keep-alive
[   25.394677] Accept-Ranges: bytes
[   25.394677] 
[   25.394677] ) on socket (conn=ffff88003d660548)
[   25.397258] [tempesta]   enter FSM at state 0
[   25.397552] [tempesta]   parser: Resp_0(0:0): c=0x48(H), r=-2
[   25.397932] [tempesta]   parser: Resp_HttpVer(2:0): c=0x48(H), r=-2
[   25.398351] [tempesta]   parser: Resp_StatusCode(11:0): c=0x32(2), r=-2
[   25.398784] [tempesta]   parser: Resp_ReasonPhrase(12:1): c=0x20( ), r=-2
[   25.399231] [tempesta]   parser: Resp_Hdr(13:1): c=0x53(S), r=-2
[   25.399625] [tempesta]   parser: Resp_HdrOther(87:1): c=0x65(e), r=-2
[   25.400055] [tempesta]   parser: Resp_Hdr(13:1): c=0x44(D), r=-2
[   25.400452] [tempesta]   parser: Resp_HdrOther(87:1): c=0x61(a), r=-2
[   25.400878] [tempesta]   parser: Resp_Hdr(13:1): c=0x43(C), r=-2
[   25.401275] [tempesta]   parser: Resp_HdrC(14:1): c=0x6f(o), r=-2
[   25.401676] [tempesta]   parser: Resp_HdrCo(28:1): c=0x6e(n), r=-2
[   25.402087] [tempesta]   parser: Resp_HdrCon(29:1): c=0x74(t), r=-2
[   25.402501] [tempesta]   parser: Resp_HdrCont(38:1): c=0x65(e), r=-2
[   25.402920] [tempesta]   parser: Resp_HdrConte(39:1): c=0x6e(n), r=-2
[   25.403344] [tempesta]   parser: Resp_HdrConten(40:1): c=0x74(t), r=-2
[   25.403774] [tempesta]   parser: Resp_HdrContent(41:1): c=0x2d(-), r=-2
[   25.404219] [tempesta]   parser: Resp_HdrContent_(42:1): c=0x54(T), r=-2
[   25.404662] [tempesta]   parser: Resp_HdrOther(87:1): c=0x79(y), r=-2
[   25.405087] [tempesta]   parser: Resp_Hdr(13:1): c=0x43(C), r=-2
[   25.405483] [tempesta]   parser: Resp_HdrC(14:1): c=0x6f(o), r=-2
[   25.405886] [tempesta]   parser: RGen_LWS(10000:49): c=0x20( ), r=-2
[   25.406307] [tempesta]   parser: RGen_LWS(10000:49): c=0x31(1), r=-2
[   25.406724] [tempesta]   enter FSM at state 49
[   25.407019] [tempesta]   parser: Resp_HdrContent_LengthV(49:0): c=0x31(1), r=-2
[   25.407498] [tempesta]   enter FSM at state 3
[   25.407789] [tempesta]   parser: I_ContLen(3:3): c=0x31(1), r=-2
[   25.408192] [tempesta]   parser: I_EoL(7:3): c=0xd(.), r=-2
[   25.408563] [tempesta]   parser: I_EoL(7:3): c=0xa(.), r=-2
[   25.408932] [tempesta]   parse header __parse_content_length: ret=5 plen=3 id=3
[   25.409413] [tempesta]   store header w/ ptr=ffff88003cc69548 len=19 flags=1 id=3
[   25.409906] [tempesta]   parser: Resp_Hdr(13:0): c=0x4c(L), r=-2
[   25.410305] [tempesta]   parser: Resp_HdrOther(87:0): c=0x61(a), r=-2
[   25.410726] [tempesta]   parser: Resp_Hdr(13:0): c=0x43(C), r=-2
[   25.411116] [tempesta]   parser: Resp_HdrC(14:0): c=0x6f(o), r=-2
[   25.411511] [tempesta]   parser: Resp_HdrConnection(36:0): c=0x3a(:), r=-2
[   25.411949] [tempesta]   parser: RGen_LWS(10000:37): c=0x20( ), r=-2
[   25.412363] [tempesta]   parser: RGen_LWS(10000:37): c=0x6b(k), r=-2
[   25.412770] [tempesta]   enter FSM at state 37
[   25.413057] [tempesta]   parser: Resp_HdrConnectionV(37:0): c=0x6b(k), r=-2
[   25.413501] [tempesta]   enter FSM at state 1
[   25.413782] [tempesta]   parser: I_Conn(1:1): c=0x6b(k), r=-2
[   25.414154] [tempesta]   parser: I_EoT(6:1): c=0xd(.), r=0
[   25.414506] [tempesta]   parser: I_EoL(7:1): c=0xd(.), r=0
[   25.414858] [tempesta]   parser: I_EoL(7:1): c=0xa(.), r=0
[   25.415209] [tempesta]   parser: Connection parsed: flags 0x2
[   25.415577] [tempesta]   parse header __parse_connection: ret=12 plen=10 id=0
[   25.416038] [tempesta]   store header w/ ptr=ffff88003cc69588 len=22 flags=1 id=0
[   25.416533] [tempesta]   parser: Resp_Hdr(13:0): c=0x41(A), r=-2
[   25.416948] [tempesta]   parser: Resp_HdrOther(87:0): c=0x63(c), r=-2
[   25.417377] [tempesta]   parser: Resp_Hdr(13:0): c=0xd(.), r=-2
[   25.417770] [tempesta]   parser: Resp_HdrDone(88:0): c=0xa(.), r=-2
[   25.418188] [tempesta]   parse msg body: flags=0x2 content_length=151
[   25.418614] [tempesta]   response parsed: len=215 parsed=215 res=-1
[   25.419029] [tempesta]   postpone skb ffff88003d6b7ba8
[   25.419369] [tempesta]   Add skb ffff88003d6b7ba8 to message ffff88003cc69040
[   25.419840] [tempesta]   received 151 server data bytes (<html>
[   25.419840] <head>
[   25.419840] <title>Welcome to nginx!</title>
[   25.419840] </head>
[   25.419840] <body bgcolor="white" text="black">
[   25.419840] <center><h1>Welcome to nginx!</h1></center>
[   25.419840] </body>
[   25.419840] </html>
[   25.419840] ) on socket (conn=ffff88003d660548)
[   25.421971] [tempesta]   enter FSM at state 89
[   25.422272] [tempesta]   parser: Resp_Body(89:0): c=0x3c(<), r=-2
[   25.422677] [tempesta]   read body: to_read=151
[   25.422979] [tempesta]   parser: Resp_BodyReadChunk(92:0): c=0x3c(<), r=-2
[   25.423431] [tempesta]   response parsed: len=151 parsed=151 res=0
[   25.423842] [sync_socket]   ss_send:89 entail skb=ffff88003d6b7ba8 data_len=151 len=366
[   25.424372] [sync_socket]   ss_send:99 sk=ffff88003d4af2c0 is_queue_empty=0 tcp_send_head(sk)=ffff88003d6b7ba8 sk->sk_state=1
[   25.425121] [tempesta]   Free msg: ffff88003d411040
[   25.425436] [tempesta]   free skb ffff88003d6b7da8: truesize=2304 sk=ffff88003d4af2c0, destructor=ffffffff812d2ea0 users=1
[   25.426182] [tempesta]   Free msg: ffff88003cc69040
[   25.426493] [tempesta]   free skb ffff88003d6b7ba8: truesize=2455 sk=ffff88003d71b280, destructor=ffffffff812d2ea0 users=1
[   25.428753] general protection fault: 0000 [#1] SMP 
[   25.429189] Modules linked in: tfw_sched_dummy(O) tempesta_fw(O) tempesta_db(O) sync_socket(O)
[   25.429800] CPU: 0 PID: 1854 Comm: nginx Tainted: G           O 3.10.10-tempesta #7
[   25.430309] task: ffff88003d53b100 ti: ffff88003cc8e000 task.ti: ffff88003cc8e000
[   25.430802] RIP: 0010:[<ffffffff81336257>]  [<ffffffff81336257>] tcp_ack+0x3f7/0xf10
[   25.431322] RSP: 0018:ffff88003fc03bd8  EFLAGS: 00010296
[   25.431675] RAX: 000000006b6b6b6b RBX: ffff88003d4af2c0 RCX: 000000000000006b
[   25.432154] RDX: 00000000f166e383 RSI: 6b6b6b6b6b6b6b6b RDI: 0000000000000001
[   25.432628] RBP: ffff88003fc03c58 R08: 00000000ffffffff R09: 0000000000000000
[   25.433099] R10: 0000000000000000 R11: 0000000000000000 R12: ffff88003d6b7ba8
[   25.433569] R13: 00000000f166e383 R14: 0000000000004502 R15: 00000000f166e215
[   25.434040] FS:  00007fdd100e0700(0000) GS:ffff88003fc00000(0000) knlGS:0000000000000000
[   25.434578] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[   25.434958] CR2: 00007faf7f1a2d2c CR3: 000000003d51e000 CR4: 00000000000006b0
[   25.435432] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[   25.435904] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[   25.436381] Stack:
[   25.436521]  ffff88003fc03cf8 0000000081366a59 fffef3dc00000001 0000000000000000
[   25.437043]  ffffffff81366a59 00000001810727cd ffff88003d4af4a0 00000000ffffffff
[   25.437567]  0000000000000000 0000000000000001 0000000100000000 ffff88003d4af2c0
[   25.438093] Call Trace:
[   25.438259]  <IRQ> 
[   25.438392]  [<ffffffff81366a59>] ? ipt_do_table+0x689/0x6b0
[   25.438800]  [<ffffffff813375e5>] tcp_rcv_established+0x4e5/0x620
[   25.439203]  [<ffffffff8134183c>] tcp_v4_do_rcv+0x1dc/0x4e0
[   25.439577]  [<ffffffff811eea42>] ? do_raw_spin_lock+0x82/0x140
[   25.439969]  [<ffffffff813433e7>] tcp_v4_rcv+0x437/0x8b0
[   25.440330]  [<ffffffff8131d7c5>] ip_local_deliver_finish+0xb5/0x150
[   25.440751]  [<ffffffff8131d750>] ? ip_local_deliver_finish+0x40/0x150
[   25.441180]  [<ffffffff8131df70>] ip_local_deliver+0x50/0x90
[   25.441558]  [<ffffffff8131dcde>] ip_rcv_finish+0x47e/0x580
[   25.441928]  [<ffffffff8131e26c>] ip_rcv+0x2bc/0x340
[   25.442260]  [<ffffffff812e6869>] __netif_receive_skb_core+0x469/0x590
[   25.442692]  [<ffffffff812e6463>] ? __netif_receive_skb_core+0x63/0x590
[   25.443129]  [<ffffffff812e69df>] __netif_receive_skb+0x4f/0x70
[   25.443522]  [<ffffffff812e855f>] process_backlog+0x7f/0x200
[   25.443899]  [<ffffffff812e8783>] net_rx_action+0xa3/0x1f0
[   25.444269]  [<ffffffff81036550>] __do_softirq+0xe0/0x1d0
[   25.444631]  [<ffffffff813c5afc>] call_softirq+0x1c/0x26
[   25.444985]  <EOI> 
[   25.445118]  [<ffffffff81003ef5>] do_softirq+0x65/0x100
[   25.445497]  [<ffffffff812d54f8>] ? release_sock+0x1b8/0x210
[   25.445873]  [<ffffffff810362d0>] local_bh_enable_ip+0xd0/0x120
[   25.446270]  [<ffffffff813c31ab>] _raw_spin_unlock_bh+0x3b/0x40
[   25.446664]  [<ffffffff812d54f8>] release_sock+0x1b8/0x210
[   25.447028]  [<ffffffff8132ea38>] tcp_setsockopt+0x7b8/0x800
[   25.447404]  [<ffffffff812d329f>] sock_common_setsockopt+0xf/0x20
[   25.447808]  [<ffffffff812d254e>] SyS_setsockopt+0x8e/0xd0
[   25.448179]  [<ffffffff813c4729>] system_call_fastpath+0x16/0x1b
[   25.448581] Code: 1f 44 00 00 8b 93 80 06 00 00 41 0f b6 4c 24 4d 41 8b 84 24 c8 00 00 00 41 3b 54 24 44 0f 89 b1 00 00 00 49 8b b4 24 d0 00 00 00 <44> 0f b7 5c 06 04 66 41 83 fb 01 0f 84 76 02 00 00 41 8b 44 24 
[   25.450396] RIP  [<ffffffff81336257>] tcp_ack+0x3f7/0xf10
[   25.450767]  RSP <ffff88003fc03bd8>
[   25.451002] ---[ end trace 05a09eb893958b3b ]---
[   25.451311] Kernel panic - not syncing: Fatal exception in interrupt
@keshonok
Copy link
Contributor Author

This issue is very convoluted and difficult to comprehend. Here's my analysis.

All data SKBs that come to Tempesta are organazied into messages that make up either an HTTP request message, or an HTTP response message. Incoming HTTP message is parsed, processed and then passed over to the other end - a backend server if it's a request, or a client if it's a response. It's important to note that the messages are passed in a zero-copy fashion in the same SKBs they have come to Tempesta.

The SKBs that are not longer needed in Tempesta need to be deleted and returned to the kernel's memory pool. The issue is where and how that needs to be done.

Few exceptions aside, Tempesta doesn't create or own SKBs it keeps in the messages. These SKBs come from the Linux kernel. Socket and TCP layers are the real owners. Moreover, these layers consider themselves the sole owners of these SKBs, and so they use a __kfree_skb() when they need to free an SKB, instead of using the generic and smarter kfree_skb() that watches for the number of users of an SKB. That means we can't use the usual protocol of skb_get()/skb_put() to increment or decrement the number of SKB users and prevent freeing an SKB from under us. That lead to inclusion of a special case in __kfree_skb() in the Linux kernel with Tempesta that prevents freeing an SKB when it's part of a Tempesta's message:

/* Don't free Tempesta owned socket buffers. */
if (unlikely(ss_skb_passed(skb)))
    return;

It's important to note that Synchronous Sockets that is part of Tempesta uses only __kfree_skb() as well.

In the current logic, Tempesta keeps a request message until the response comes, then uses part of the request with the response and caches the data. Before it caches the data it passes the response over to the client by passing the SKBs to the Linux stack. After the data is cached Tempesta deletes both request and response message with all associated data (read - SKBs).

A crucial piece of knowledge to mention here is that the Linux stack deletes SKBs after it has sent them out (it's not that simple, the stack keeps some for possible retransmissions, etc).

That means that the SKBs in the request message had been most probably freed by the stack and from the stack's point of view. They had not been actually freed due to the special case in __kfree_skb() described above, as they were part of the request message in Tempesta. As for the response message, it turns out that the SKBs are still in use by the Linux stack when Tempesta removes them from the message and frees them, meaning that those SKBs are still in the process of being sent out.

NOTE: Depending on the circumstances that's not true at all times for response SKBs, so it could be even more complicated. Even for request's SKBs I can't exclude a chance that the SKBs had not been freed yet by the Linux stack when Tempesta wanted to destroy the pair of request/response messages Basically, it's a matter of timing.

All in all, generally, we don't know whether the Linux stack considers the SKBs freed or not. So we don't know if Tempesta can remove a particular SKB.

If we assume that the Linux stack frees all SKBs when they have been sent out, then a solution could be to free request's SKBs and do not free response SKBs when Tempesta destroys the request/response messages. We can strengthen the case by caching the response before it's passed over to the Linux stack. Then under the assumption the response message's SKBs are freed by the stack.

Again, the solution within current logic would be to destroy messages differently in Tempesta. Free request's SKBs as they had been freed by the Linux stack when they were sent out. Do not free the response SKBs are the Linux stack still processes them. I tried this solution, and it works on simple tests.

However, considering the above note that might not always be true. We're still not sure about the request SKBs. To "guarantee" freeing the request's SKBs under the same assumption, we need to store the needed request data in cache right after we have processed the request and before we pass it over to a backend server. Then we can be sure that the request's SKBs are eventually freed by the Linux stack.

@keshonok
Copy link
Contributor Author

After further analysis the following has became clear. The major issue here is whether an SKB is in Tempesta's full possession or not. And it is from the moment an SKB is taken out of a socket's receive queue, and until that SKB is sent out (that is, put into a socket's send queue).

While an SKB is in Temepsta's full possession, it's Tempesta's responsibility to free an SKB should it decide not to send it out for any reason. As soon as an SKB is sent out the Linux networking stack takes possession of that SKBs, and it will take care of freeing it later.

keshonok added a commit that referenced this issue Apr 17, 2015
This is a solution to #56. The key is knowing whether an SKB is in
Tempesta's full possession or not. It is from the moment it's been
taken out of a socket's receive queue, and until it's sent out, i.e.
put in a socket's send queue. If a message is freed during that time
frame, Tempesta is responsible of freeing SKBs that make the message.
Otherwise, the Linux networking stack will take care of that when it
finishes sending those SKBs out.
@keshonok
Copy link
Contributor Author

keshonok commented May 2, 2015

The proposed patch above is only half of the solution. Yes, while an SKB is completely in Tempesta's possession, Tempesta can and must delete it when it deletes a message that contains it. So, the above patch is an easy and cheap solution that covers the described case.

The problem, however, is what to do when Tempesta sends a message out, either to a backend server, or to a client.

In many cases Tempesta deletes the message immediately after it sends it out. Does it need to delete the SKBs as well? Well, the kernel deletes SKBs after it has finished with sending. So, generally speaking, the case we have here is that both Tempesta and the kernel attempt to free SKBs that make the message at nearly the same time. If the kernel is faster, then it's okay, an SKB is still in Tempesta's message queue, and so it doesn't get freed, Tempesta will free it in a moment. If Tempesta is faster, though, then an attempt by the kernel will lead to a crash.

There's also a request message that Tempesta keeps around until it receives the response to it. Even though it may appear that the kernel must have attempted to free the request's SKBs by that time, that's not a guarantee. So, essentially, it's still the same case.

It appears that the solution requires a reference counter in SKB, like the one that kfree_skb() has in form of skb->users, and __kfree_skb() doesn't. Is there another, better solution?

@krizhanovsky krizhanovsky modified the milestones: 0.4.0 Web Server, 0.3.0 Proxy Filter May 24, 2015
@krizhanovsky
Copy link
Contributor

The concept behind skb management is very simple:

  1. Linux TCP/IP stack can free skb at any time if it's not passed to Tempesta;
  2. If skb is passed to Tempesta ownership, then Tempesta only can free it;
  3. If Tempesta is not interested in skb and for example sends it to a socket, then it should pass the skb to Linux, i.e. remove from its lists so that ss_skb_passed(skb) is false;
  4. If Tempesta is not interested in skb and Linux also won't free the skb in some of its internal functions, then Tempesta must free the skb since it own it.

The concept must be obeyed, so we wouldn't need extra reference counting or other complex things.

keshonok added a commit that referenced this issue Jul 28, 2015
This part of a series of changes to implement #56.
The kernel is modified to not free SKBs that are still in Tempesta
queues. That gives Tempesta control over SKBs. Request SKBs are kept
until a corresponging response it received. However. when response
is sent to a client, its SKBs are no longer needed. The new argument
tells ss_send() if it needs to remove SKBs from a Tempesta queue.
@keshonok
Copy link
Contributor Author

keshonok commented Aug 4, 2015

Fixed with 6ea9bfb and krizhanovsky/linux-3.10.10-sync_sockets@06f1b61

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

2 participants