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

A Connection could not be closed before it is scheduled #19

Closed
vdmit11 opened this issue Sep 18, 2014 · 5 comments
Closed

A Connection could not be closed before it is scheduled #19

vdmit11 opened this issue Sep 18, 2014 · 5 comments
Assignees

Comments

@vdmit11
Copy link
Contributor

vdmit11 commented Sep 18, 2014

A NULL pointer dereference occurs when you connect to the Tempesta FW and close the TCP connection (send FIN from client) when the HTTP request is not yet parsed.

Scenario:

  1. start Tempesta FW
  2. wget http://remote-machine-address
    Actually my wget hangs after this, so I'm just hitting Ctrl+C and it sends FIN to the Tempesta server.

Result:

[   43.851433] [tempesta]   New client socket ffff88003d704940 (state=1)
[   43.852547] [tempesta]   Link new msg ffff88003d564040 with connection ffff88003db99438
[   43.853760] [tempesta]   Add skb ffff88003db150c0 to message ffff88003d564040
[   43.854845] [tempesta]   Received 62 client data bytes (GET / HTTP/1.1
[   43.854845] User-Agent: Wget/1.13.4 (linux-gnu)
[   43.854845] Accept: *) on socket (conn=ffff88003db99438)
[   43.855206] [tempesta]   enter FSM at state 0
[   43.855206] [tempesta]   parser: Req_0(0:0): c=0x47(G), r=-2
[   43.855206] [tempesta]   parser: Req_Method(1:0): c=0x47(G), r=-2
[   43.855206] [tempesta]   parser: Req_MUSpace(2:0): c=0x2f(/), r=-2
[   43.855206] [tempesta]   parser: Req_UriAbsPath(6:0): c=0x20( ), r=-2
[   43.855206] [tempesta]   parser: Req_HttpVer(7:0): c=0x48(H), r=-2
[   43.855206] [tempesta]   parser: Req_EoL(15:0): c=0xd(.), r=-2
[   43.855206] [tempesta]   parser: Req_EoL(15:0): c=0xa(.), r=-2
[   43.855206] [tempesta]   parser: Req_Hdr(16:0): c=0x55(U), r=-2
[   43.855206] [tempesta]   parser: Req_HdrOther(76:0): c=0x55(U), r=-2
[   43.855206] [tempesta]   store header w/ ptr=ffff88003d738a92 len=34 flags=0
[   43.855206] [tempesta]   parser: Req_Hdr(16:0): c=0x41(A), r=-2
[   43.855206] [tempesta]   parser: Req_HdrOther(76:0): c=0x41(A), r=-2
[   43.855206] [tempesta]   store header w/ ptr=ffff88003d738ab7 len=62 flags=0
[   43.855206] [tempesta]   request parsed: len=62 parsed=116 res=-1
[   43.855206] [tempesta]   postpone skb ffff88003db150c0
[   43.855206] [tempesta]   Add skb ffff88003db150c0 to message ffff88003d564040
[   43.855206] [tempesta]   Received 51 client data bytes () on socket (conn=ffff88003db99438)
[   43.855206] [tempesta]   enter FSM at state 76
[   43.855206] [tempesta]   parser: Req_HdrOther(76:0): c=0x0(.), r=-2
[   43.855206] [tempesta]   store header w/ ptr=          (null) len=51 flags=0
[   43.855206] [tempesta]   request parsed: len=51 parsed=52 res=-1
[   43.855206] [tempesta]   postpone skb ffff88003db150c0
[   51.543472] [sync_socket]   Close socket ffff88003d704940 (account=1)
[   51.544509] [tempesta]   Close socket ffff88003d704940, conn=ffff88003db99438
[   51.545598] [tempesta]   free skb ffff88003db150c0: truesize=4864 sk=ffff88003d704940, destructor=ffffffff812e0f60 users=1
[   51.547410] BUG: unable to handle kernel NULL pointer dereference at 0000000000000008
[   51.547410] IP: [<ffffffffa000ab73>] tfw_connection_close+0xa3/0x100 [tempesta_fw]
[   51.547410] PGD 3d891067 PUD 3d890067 PMD 0 
[   51.547410] Oops: 0000 [#1] SMP 
[   51.547410] Modules linked in: tfw_sched_rr(O) tempesta_fw(O) tempesta_db(O) sync_socket(O)
[   51.547410] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G           O 3.10.10-tempesta #2
[   51.547410] task: ffffffff815674c0 ti: ffffffff81556000 task.ti: ffffffff81556000
[   51.547410] RIP: 0010:[<ffffffffa000ab73>]  [<ffffffffa000ab73>] tfw_connection_close+0xa3/0x100 [tempesta_fw]
[   51.547410] RSP: 0018:ffff88003fc03ae0  EFLAGS: 00010202
[   51.547410] RAX: 0000000000000000 RBX: ffff88003db99438 RCX: 0000000000000000
[   51.547410] RDX: 0000000000000000 RSI: ffffffff81567a78 RDI: 0000000000000282
[   51.547410] RBP: ffff88003fc03af0 R08: 0000000000000001 R09: 0000000000000000
[   51.547410] R10: 0000000000000000 R11: 0000000000000000 R12: ffff88003d704940
[   51.547410] R13: 0000000000000062 R14: ffff88003d738e00 R15: ffff88003d738e62
[   51.547410] FS:  0000000000000000(0000) GS:ffff88003fc00000(0000) knlGS:0000000000000000
[   51.547410] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[   51.547410] CR2: 0000000000000008 CR3: 000000003d88d000 CR4: 00000000000006b0
[   51.547410] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[   51.547410] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[   51.547410] Stack:
[   51.547410]  ffff88003d704940 ffff88003d705118 ffff88003fc03b28 ffffffffa000053c
[   51.547410]  ffffffff81577600 ffff88003d704940 ffff88003d705118 0000000000000062
[   51.547410]  ffff88003d738e00 ffff88003fc03b48 ffffffffa0000bd8 ffff88003d704940
[   51.547410] Call Trace:
[   51.547410]  <IRQ> 
[   51.547410]  [<ffffffffa000053c>] ss_do_close+0x6c/0x5f0 [sync_socket]
[   51.547410]  [<ffffffffa0000bd8>] ss_tcp_state_change+0xc8/0x160 [sync_socket]
[   51.547410]  [<ffffffff81340779>] tcp_fin+0x159/0x1d0
[   51.547410]  [<ffffffff81341bf8>] tcp_data_queue+0x568/0xd90
[   51.547410]  [<ffffffff81344ed7>] tcp_rcv_established+0x267/0x670
[   51.547410]  [<ffffffff813504ec>] tcp_v4_do_rcv+0x19c/0x660
[   51.547410]  [<ffffffff811f6eb3>] ? do_raw_spin_lock+0x53/0x160
[   51.547410]  [<ffffffff8135195a>] tcp_v4_rcv+0x6aa/0x840
[   51.547410]  [<ffffffff8132a726>] ip_local_deliver_finish+0x86/0x140
[   51.547410]  [<ffffffff8132a6bd>] ? ip_local_deliver_finish+0x1d/0x140
[   51.547410]  [<ffffffff8132af32>] ip_local_deliver+0x42/0x80
[   51.547410]  [<ffffffff8132a88b>] ip_rcv_finish+0xab/0x5e0
[   51.547410]  [<ffffffff8132b176>] ip_rcv+0x206/0x330
[   51.547410]  [<ffffffff812f3d13>] __netif_receive_skb_core+0x1b3/0x660
[   51.547410]  [<ffffffff812f3ba7>] ? __netif_receive_skb_core+0x47/0x660
[   51.547410]  [<ffffffff812f41d1>] __netif_receive_skb+0x11/0x70
[   51.547410]  [<ffffffff812f4c2e>] netif_receive_skb+0x1e/0x110
[   51.547410]  [<ffffffff812e8520>] ? __netdev_alloc_skb+0x80/0xd0
[   51.547410]  [<ffffffff8127c068>] virtnet_poll+0x538/0x7b0
[   51.547410]  [<ffffffff812f5f7a>] net_rx_action+0x15a/0x210
[   51.547410]  [<ffffffff81038c8a>] __do_softirq+0x12a/0x230
[   51.547410]  [<ffffffff81038fa5>] irq_exit+0xd5/0xf0
[   51.547410]  [<ffffffff81003ede>] do_IRQ+0x4e/0xb0
[   51.547410]  [<ffffffff813ce232>] common_interrupt+0x72/0x72
[   51.547410]  <EOI> 
[   51.547410]  [<ffffffff810240f6>] ? native_safe_halt+0x6/0x10
[   51.547410]  [<ffffffff8107646d>] ? trace_hardirqs_on+0xd/0x10
[   51.547410]  [<ffffffff8100ae98>] default_idle+0x18/0x30
[   51.547410]  [<ffffffff8100b7aa>] arch_cpu_idle+0xa/0x10
[   51.547410]  [<ffffffff810698e0>] cpu_startup_entry+0x130/0x230
[   51.547410]  [<ffffffff813c3d3a>] rest_init+0xca/0xd0
[   51.547410]  [<ffffffff815dfc8a>] start_kernel+0x356/0x363
[   51.547410]  [<ffffffff815df120>] ? early_idt_handlers+0x120/0x120
[   51.547410]  [<ffffffff815df444>] x86_64_start_reservations+0x2a/0x2c
[   51.547410]  [<ffffffff815df535>] x86_64_start_kernel+0xef/0xfc
[   51.547410] Code: 00 48 8b 3d b0 4e 02 00 48 89 de e8 78 2e 0d e1 31 c0 49 c7 84 24 90 03 00 00 00 00 00 00 5b 41 5c 5d c3 0f 1f 44 00 00 48 8b 00 <48> 8b 40 08 48 8b 80 90 03 00 00 eb b8 48 89 fa 48 89 d9 48 c7 
[   51.547410] RIP  [<ffffffffa000ab73>] tfw_connection_close+0xa3/0x100 [tempesta_fw]
[   51.547410]  RSP <ffff88003fc03ae0>
[   51.547410] CR2: 0000000000000008
[   51.547410] ---[ end trace 2e62b0630e43dc00 ]---
[   51.547410] Kernel panic - not syncing: Fatal exception in interrupt

Actually the NULL pointer happens in an inlined function, so the full stack trace would look like:

tfw_sess_conn()
tfw_connection_peer()
tfw_connection_free()
tfw_connection_close()
ss_do_close()
ss_tcp_state_change()
tcp_fin()
...

The tfw_connection_peer() tries to find a server connection for the given client connection. But the problem is there is no server yet associated with the client because the message is not scheduled yet at this point (HTTP parser is not finished yet). So the sess->srv is NULL.

The server is obtained only to make peer_conn->sess = NULL; in tfw_connection_free(). If no session is yet established, then the field should already be NULL, so I think it may be fixed by simple NULL checks here.

@krizhanovsky krizhanovsky self-assigned this Sep 18, 2014
@krizhanovsky
Copy link
Contributor

Actually the problem is with the parser.

Firstly,

    [   43.854845] [tempesta]   Received 62 client data bytes (GET / HTTP/1.1
    [   43.854845] User-Agent: Wget/1.13.4 (linux-gnu)
    [   43.854845] Accept: *) on socket (conn=ffff88003db99438)

Means that there are no trailing CRLF at the end of Accept header and the whole request. Need to check with tcpdump whether wget sends the reuest and two CRLF trailers in separate TCP segments.

Next suspicious part is

    [   43.855206] [tempesta]   parser: Req_Hdr(16:0): c=0x41(A), r=-2
    [   43.855206] [tempesta]   parser: Req_HdrOther(76:0): c=0x41(A), r=-2
    [   43.855206] [tempesta]   store header w/ ptr=ffff88003d738ab7 len=62 flags=0

When the parser is at begin of Accept header it goes to Req_HdrOther state which parses headers which we don't process in special maner (like we do this for Conten-Length for example). The problem is considers that the header has 62 charactes and that's not correct.

Lastly,

    [   43.855206] [tempesta]   request parsed: len=51 parsed=52 res=-1

len should be equal to parsed (length of current packet must be the same as data size which the parser processed). In commit 021e6a8 I fixed the issue, but it seems it appears in some other place...

@vdmit11
Copy link
Contributor Author

vdmit11 commented Sep 18, 2014

I didn't pull the commit to my current branch, I'll test it later on master.
But I think the issue is not about the parser (althouth there is a problem with the parser as well).
The problem is the destructor callback tries to modify a server at a point where there is no server bound with the session yet.

@krizhanovsky
Copy link
Contributor

Yes, agree. Please fix the parser (because it's easy for you to reproduce the issue) and assign the issue with updated Oops message to me. Or you always can debug the connection bug as well ;)

vdmit11 added a commit that referenced this issue Sep 22, 2014
The commit fixes closing a connection at a point when no TfwSession is
yet established.

Changes:

1. tfw_connection_free() now releases a TfwSession and a peer
TfwConnection only if they exist.

2. tfw_connection_send_srv() doesn't close the connection by itself.
Instead, it returns an error code which is propagated up to Synchronous
Sockets, and the connection is closed from ss_do_close().
That is done to avoid a condition where the connection is referenced by
SS after it is closed (and free()'d) in tfw_connection_send_srv().

3. tfw_sess_conn() and tfw_connection_peer() now check for existence of
session and connection objects and return NULL if they don't exist.

4. tfw_http_conn_destruct() frees a HTTP request attached to the
message only if it exists. That is done to avoid another NULL pointer
dereference that occurs because the requests are pipelined now, and
this "current" request may be already pipelined and set to NULL when
the destructor is called.

5. tfw_http_req_process() doesn't free a HTTP request anymore.
It is done from a destructor called by ss_do_close() when
tfw_http_req_process() returns TFW_BLOCK.

6. tfw_session_free() now releases all pipelined HTTP requests stored
in the session's queue.
@vdmit11 vdmit11 assigned krizhanovsky and unassigned vdmit11 Sep 25, 2014
@vdmit11
Copy link
Contributor Author

vdmit11 commented Sep 25, 2014

Alexander, please review.
I've fixed free'ing a connection at a point where no session is established yet.

The HTTP parser seems to be fine now. The original Oops message was obtained on a version branched before 021e6a8.
Check it out:

Starting Tempesta...
[    7.014142] [tempesta] Start Tempesta
[    7.014666] [tempesta]   Starting thread: tfw_bconnd
[    7.015305] [tempesta] Open 1 listening sockets
[    7.015949] [tempesta]   Created listening socket ffff88003d53e940
[    7.016833] [tempesta]   Adding new backend: 127.0.0.1:8080
done
[  100.285562] [tempesta]   New client socket ffff88003dbe8980 (state=1)
[  100.287106] [tempesta]   Link new msg ffff88003d583040 with connection ffff88003d9ce438
[  100.288618] [tempesta]   Add skb ffff88003a8b9ba8 to message ffff88003d583040
[  100.289943] [tempesta]   Received 109 client data bytes (GET / HTTP/1.1
[  100.289943] User-Agent: Wget/1.13.4 (linux-gnu)
[  100.289943] Accept: */*
[  100.289943] Host: localhost
[  100.289943] Connection: Keep-Alive
[  100.289943] 
[  100.289943] ) on socket (conn=ffff88003d9ce438)
[  100.294539] [tempesta]   enter FSM at state 0
[  100.295307] [tempesta]   parser: Req_0(0:0): c=0x47(G), r=-2
[  100.296323] [tempesta]   parser: Req_Method(1:0): c=0x47(G), r=-2
[  100.297386] [tempesta]   parser: Req_MUSpace(2:0): c=0x2f(/), r=-2
[  100.298506] [tempesta]   parser: Req_UriAbsPath(6:0): c=0x20( ), r=-2
[  100.299641] [tempesta]   parser: Req_HttpVer(7:0): c=0x48(H), r=-2
[  100.300749] [tempesta]   parser: Req_EoL(15:0): c=0xd(.), r=-2
[  100.301776] [tempesta]   parser: Req_EoL(15:0): c=0xa(.), r=-2
[  100.302804] [tempesta]   parser: Req_Hdr(16:0): c=0x55(U), r=-2
[  100.303848] [tempesta]   parser: Req_HdrOther(76:0): c=0x55(U), r=-2
[  100.304980] [tempesta]   store header w/ ptr=ffff88003d9140b0 len=34 flags=0
[  100.306216] [tempesta]   parser: Req_Hdr(16:0): c=0x41(A), r=-2
[  100.307255] [tempesta]   parser: Req_HdrOther(76:0): c=0x41(A), r=-2
[  100.308344] [tempesta]   store header w/ ptr=ffff88003d9140d5 len=10 flags=0
[  100.309499] [tempesta]   parser: Req_Hdr(16:0): c=0x48(H), r=-2
[  100.310423] [tempesta]   parser: RGen_LWS(10000:21): c=0x20( ), r=-2
[  100.311255] [tempesta]   parser: RGen_LWS(10000:21): c=0x6c(l), r=-2
[  100.312179] [tempesta]   enter FSM at state 21
[  100.312915] [tempesta]   parser: Req_HdrHostV(21:0): c=0x6c(l), r=-2
[  100.313967] [tempesta]   enter FSM at state 1
[  100.314694] [tempesta]   parser: Req_I_H(1:1): c=0x6c(l), r=-2
[  100.315657] [tempesta]   parser: Req_I_H(1:1): c=0x6f(o), r=-2
[  100.316635] [tempesta]   parser: Req_I_H(1:1): c=0x63(c), r=-2
[  100.317602] [tempesta]   parser: Req_I_H(1:1): c=0x61(a), r=-2
[  100.318575] [tempesta]   parser: Req_I_H(1:1): c=0x6c(l), r=-2
[  100.319538] [tempesta]   parser: Req_I_H(1:1): c=0x68(h), r=-2
[  100.320501] [tempesta]   parser: Req_I_H(1:1): c=0x6f(o), r=-2
[  100.321423] [tempesta]   parser: Req_I_H(1:1): c=0x73(s), r=-2
[  100.322346] [tempesta]   parser: Req_I_H(1:1): c=0x74(t), r=-2
[  100.323256] [tempesta]   parser: Req_I_H(1:1): c=0xd(.), r=-2
[  100.324176] [tempesta]   parser: Req_I_H_EoL(3:1): c=0xd(.), r=-2
[  100.325144] [tempesta]   parser: Req_I_H_EoL(3:1): c=0xa(.), r=-2
[  100.326109] [tempesta]   parse header __req_parse_host: return 11
[  100.327075] [tempesta]   store header w/ ptr=ffff88003d9140e2 len=9 flags=0
[  100.328191] [tempesta]   parser: Req_Hdr(16:0): c=0x43(C), r=-2
[  100.329127] [tempesta]   parser: Req_HdrC(22:0): c=0x6f(o), r=-2
[  100.330086] [tempesta]   parser: Req_HdrConnection(44:0): c=0x3a(:), r=-2
[  100.331147] [tempesta]   parser: RGen_LWS(10000:45): c=0x20( ), r=-2
[  100.332155] [tempesta]   parser: RGen_LWS(10000:45): c=0x4b(K), r=-2
[  100.333111] [tempesta]   enter FSM at state 45
[  100.333779] [tempesta]   parser: Req_HdrConnectionV(45:0): c=0x4b(K), r=-2
[  100.334809] [tempesta]   enter FSM at state 1
[  100.335471] [tempesta]   parser: I_Conn(1:1): c=0x4b(K), r=-2
[  100.336346] [tempesta]   parser: I_EoL(6:1): c=0xd(.), r=0
[  100.337175] [tempesta]   parser: I_EoL(6:1): c=0xa(.), r=0
[  100.338006] [tempesta]   parser: Connection parsed: flags 0x2
[  100.338872] [tempesta]   parse header __parse_connection: return 12
[  100.339806] [tempesta]   store header w/ ptr=ffff88003d9140f3 len=10 flags=0
[  100.340860] [tempesta]   parser: Req_Hdr(16:0): c=0xd(.), r=-2
[  100.341634] [tempesta]   parser: Req_HdrDone(77:0): c=0xa(.), r=-2
[  100.342320] [tempesta]   parse msg body: flags=0x2 content_length=0
[  100.343254] [tempesta]   request parsed: len=109 parsed=109 res=0
[  100.344185] [tempesta]   GFSM return code 0
[  100.344787] [tempesta] ERROR: Can't get an appropriate server for a session
[  100.345763] [tempesta] ERROR: Cannot schedule message, msg=ffff88003d583040 clnt=ffff88003d5a75f0
[  100.347057] [sync_socket] Warning: can't process app data on socket ffff88003dbe8980
[  100.348176] [sync_socket]   Close socket ffff88003dbe8980 (account=1)
[  100.349090] [tempesta]   Close socket ffff88003dbe8980, conn=ffff88003d9ce438
[  100.350103] [tempesta]   Free connection: ffff88003d9ce438
[  100.350893] [tempesta]   Free session: ffff88003db763d0
[  100.351649] [tempesta]   Free msg: ffff88003d583040
[  100.352342] [tempesta]   free skb ffff88003a8b9ba8: truesize=2304 sk=ffff88003dbe8980, destructor=ffffffff812e0f60 users=1

@vdmit11
Copy link
Contributor Author

vdmit11 commented Mar 7, 2015

Fixed long time ago, see: 1cd52cf.

@vdmit11 vdmit11 closed this as completed Mar 7, 2015
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