Many HTTP requests are blocked by Tempesta

[keshonok]

When an SKB consists of multiple parts/fragments Tempesta processes it fragment by fragment, passing each fragment separately to the HTTP parser. The HTTP parser keeps track of the current state of HTTP message parsing. However the code that passes the fragments to the parser is broken. The parser does not receive the complete HTTP message and reports a parsing error, which leads to be message being blocked.

Loading Tempesta kernel modules...
[   13.930348] [tempesta] Initializing Tempesta FW kernel module...
[   13.930891] [tempesta] init: cfg_if
[   13.931200] [tempesta] init: http
[   13.931484] [tempesta] init: server
[   13.931797] [tempesta] init: client
[   13.932138] [tempesta] init: session
[   13.932437] [tempesta] init: connection
[   13.932762] [tempesta]   register cfg: cache
[   13.933103] [tempesta]   register cfg: sock_backend
[   13.933496] [tempesta]   register cfg: sock_frontend
[   13.951327] [tempesta] Registering new scheduler: dummy
Starting Tempesta...
[   13.954693] [tempesta] got state via sysctl: start
[   13.955261] [tempesta]   reading configuration file...
[   13.955846] [tempesta]   reading file: /home/natsys-lab/tfw-run/tempesta/etc/tempesta_fw.conf
[   13.957494] [tempesta]   file size: 2204 bytes
[   13.958008] [tempesta]   read by offset: 0
[   13.960110] [tempesta]   read by offset: 2204
[   13.960690] [tempesta] starting all modules...
[   13.961180] [tempesta]   parsing configuration and pushing it to modules...
[   13.961993] [tempesta]   use default entry: 'cache off;'
[   13.962671] [tempesta]   spec handle: 'cache'
[   13.963279] [tempesta]   use default entry: 'cache_size 262144;'
[   13.964238] [tempesta]   spec handle: 'cache_size'
[   13.964785] [tempesta]   use default entry: 'cache_dir /opt/tempesta/cache;'
[   13.965509] [tempesta]   spec handle: 'cache_dir'
[   13.965986] [tempesta]   use default entry: 'backend 127.0.0.1:8080;'
[   13.966636] [tempesta]   spec handle: 'backend'
[   13.967107] [tempesta]   use default entry: 'listen 0.0.0.0:80;'
[   13.967718] [tempesta]   spec handle: 'listen'
[   13.968259] [tempesta]   created front-end socket: sk=ffff88003cc0c040
[   13.968752] [tempesta]   starting modules...
[   13.969073] [tempesta]   mod_start(): cache
[   13.969388] [tempesta]   mod_start(): sock_backend
[   13.969749] [tempesta]   Starting thread: tfw_bconnd
[   13.970169] [tempesta]   mod_start(): sock_frontend
[   13.970539] [tempesta]   start listening on socket: sk=ffff88003cc0c040
[   13.971042] [tempesta] modules are started
net.tempesta.state = start
done
done
Starting nginx: nginx.
[   17.973654] [tempesta] Connected to backend: 127.0.0.1:8080
[   22.517164] [tempesta]   New client socket ffff88003daf2080 (state=1)
[   22.519380] [tempesta]   Link new msg ffff88003da7e040 with connection ffff88003d923500
[   22.521026] [tempesta]   Add skb ffff88003db603c0 to message ffff88003da7e040
[   22.521026] [tempesta]   Received 62 client data bytes (GET / HTTP/1.1
[   22.521026] User-Agent: Wget/1.15 (linux-gnu)
[   22.521026] Accept: */*) on socket (conn=ffff88003d923500)
[   22.521026] [tempesta]   enter FSM at state 0
[   22.521026] [tempesta]   parser: Req_0(0:0): c=0x47(G), r=-2
[   22.521026] [tempesta]   parser: Req_Method(1:0): c=0x47(G), r=-2
[   22.521026] [tempesta]   parser: Req_MUSpace(2:0): c=0x2f(/), r=-2
[   22.521026] [tempesta]   parser: Req_UriAbsPath(6:0): c=0x20( ), r=-2
[   22.521026] [tempesta]   parser: Req_HttpVer(7:0): c=0x48(H), r=-2
[   22.521026] [tempesta]   parser: Req_EoL(15:0): c=0xd(.), r=-2
[   22.521026] [tempesta]   parser: Req_EoL(15:0): c=0xa(.), r=-2
[   22.521026] [tempesta]   parser: Req_Hdr(16:0): c=0x55(U), r=-2
[   22.521026] [tempesta]   parser: Req_HdrOther(92:0): c=0x55(U), r=-2
[   22.521026] [tempesta]   store header w/ ptr=ffff88003ccdaa92 len=33 flags=0 id=3
[   22.521026] [tempesta]   parser: Req_Hdr(16:0): c=0x41(A), r=-2
[   22.521026] [tempesta]   parser: Req_HdrOther(92:0): c=0x41(A), r=-2
[   22.521026] [tempesta]   store header w/ ptr=ffff88003ccdaab5 len=11 flags=0 id=4
[   22.521026] [tempesta]   request parsed: len=62 parsed=62 msg_len=62 res=-1
[   22.521026] [tempesta]   postpone skb ffff88003db603c0
[   22.521026] [tempesta]   Add skb ffff88003db603c0 to message ffff88003da7e040
[   22.521026] [tempesta]   Received 50 client data bytes () on socket (conn=ffff88003d923500)
[   22.521026] [tempesta]   enter FSM at state 92
[   22.521026] [tempesta]   parser: Req_HdrOther(92:0): c=0x1(.), r=-2
[   22.521026] [tempesta]   store header w/ ptr=          (null) len=40 flags=0 id=4
[   22.521026] [tempesta]   parser: Req_Hdr(16:0): c=0x1(.), r=-2
[   22.521026] [tempesta]   request parsed: len=50 parsed=0 msg_len=0 res=-2
[   22.521026] [tempesta]   Block bad HTTP request
[   22.521026] [sync_socket] Warning: can't process app data on socket ffff88003daf2080
[   22.521026] [sync_socket]   Close socket ffff88003daf2080 (account=1)
[   22.521026] [tempesta]   Close socket ffff88003daf2080, conn=ffff88003d923500
[   22.521026] [tempesta]   Free msg: ffff88003da7e040
[   22.521026] [tempesta]   free skb ffff88003db603c0: truesize=4864 sk=ffff88003daf2080, destructor=ffffffff812d2ea0 users=1
[   22.521026] [tempesta]   Free connection: ffff88003d923500
[   22.521026] [tempesta]   Free session: ffff88003da3f490
[   23.539579] [tempesta]   New client socket ffff88003db7d2c0 (state=1)
[   23.541371] [tempesta]   Link new msg ffff88003e344040 with connection ffff88003d923500
[   23.543410] [tempesta]   Add skb ffff88003db600c0 to message ffff88003e344040
[   23.543471] [tempesta]   Received 62 client data bytes (GET / HTTP/1.1
[   23.543471] User-Agent: Wget/1.15 (linux-gnu)
[   23.543471] Accept: */*) on socket (conn=ffff88003d923500)
[   23.543471] [tempesta]   enter FSM at state 0
[   23.543471] [tempesta]   parser: Req_0(0:0): c=0x47(G), r=-2
[   23.543471] [tempesta]   parser: Req_Method(1:0): c=0x47(G), r=-2
[   23.543471] [tempesta]   parser: Req_MUSpace(2:0): c=0x2f(/), r=-2
[   23.543471] [tempesta]   parser: Req_UriAbsPath(6:0): c=0x20( ), r=-2
[   23.543471] [tempesta]   parser: Req_HttpVer(7:0): c=0x48(H), r=-2
[   23.543471] [tempesta]   parser: Req_EoL(15:0): c=0xd(.), r=-2
[   23.543471] [tempesta]   parser: Req_EoL(15:0): c=0xa(.), r=-2
[   23.543471] [tempesta]   parser: Req_Hdr(16:0): c=0x55(U), r=-2
[   23.543471] [tempesta]   parser: Req_HdrOther(92:0): c=0x55(U), r=-2
[   23.543471] [tempesta]   store header w/ ptr=ffff88003ccdb292 len=33 flags=0 id=3
[   23.543471] [tempesta]   parser: Req_Hdr(16:0): c=0x41(A), r=-2
[   23.543471] [tempesta]   parser: Req_HdrOther(92:0): c=0x41(A), r=-2
[   23.543471] [tempesta]   store header w/ ptr=ffff88003ccdb2b5 len=11 flags=0 id=4
[   23.543471] [tempesta]   request parsed: len=62 parsed=62 msg_len=62 res=-1
[   23.543471] [tempesta]   postpone skb ffff88003db600c0
[   23.543471] [tempesta]   Add skb ffff88003db600c0 to message ffff88003e344040
[   23.543471] [tempesta]   Received 50 client data bytes () on socket (conn=ffff88003d923500)
[   23.543471] [tempesta]   enter FSM at state 92
[   23.543471] [tempesta]   parser: Req_HdrOther(92:0): c=0x1(.), r=-2
[   23.543471] [tempesta]   store header w/ ptr=          (null) len=40 flags=0 id=4
[   23.543471] [tempesta]   parser: Req_Hdr(16:0): c=0x1(.), r=-2
[   23.543471] [tempesta]   request parsed: len=50 parsed=0 msg_len=0 res=-2
[   23.543471] [tempesta]   Block bad HTTP request
[   23.543471] [sync_socket] Warning: can't process app data on socket ffff88003db7d2c0
[   23.543471] [sync_socket]   Close socket ffff88003db7d2c0 (account=1)
[   23.543471] [tempesta]   Close socket ffff88003db7d2c0, conn=ffff88003d923500
[   23.543471] [tempesta]   Free msg: ffff88003e344040
[   23.543471] [tempesta]   free skb ffff88003db600c0: truesize=4864 sk=ffff88003db7d2c0, destructor=ffffffff812d2ea0 users=1
[   23.543471] [tempesta]   Free connection: ffff88003d923500
[   23.543471] [tempesta]   Free session: ffff88003da3f490
[   78.033968] [sync_socket]   Close socket ffff88003daf3280 (account=1)
[   78.036185] [tempesta]   Close socket ffff88003daf3280, conn=ffff88003d923548
[   78.038443] [tempesta]   Free msg:           (null)
[   78.039954] [tempesta]   Free connection: ffff88003d923548
[   78.041824] [sync_socket]   free rcv skb ffff88003d88eda8

[krizhanovsky]

What exactly does "the code that passes the fragments to the parser is broken" mean?

[keshonok]

There was incorrect threatment of SKB's paged fragments. Please see the patch linked above.

[krizhanovsky]

The patch (a461f6b) is right and I'll apply it. However, motivation of the patch and how does it fix the problem is unclear.

skb_frag_address is defined in include/linux/skbuff.h as

    static inline void *skb_frag_address(const skb_frag_t *frag)
    {
            return page_address(skb_frag_page(frag)) + frag->page_offset;
    }

While kmap_atomic is basically just page_address(page) (see include/linux/highmem.h). So the patch fixes only the case when frag->page_offset != 0.

Please, recheck the bug with the new master branch and provide better explanation how the patch fixes the problem and/or provide test which reproduces the problem and shows that the problem is gone after the patch.

[keshonok]

In short: yes, that is correct, the patch fixes the problem only when frag->page_offset != 0.

The patch makes things clearer, cleaner, and shorter, doing the same thing without a chance of making this kind of a bug by using the function that exists specifically for that purpose. As intended, the function takes care of that specific case as well. That was the motivation for this patch, besides making the actual fix for the bug.

I was able to reproduce the problem each and every time by sending an HTTP request over an ethernet link. No specific test is necessary, just need to make sure the skb with received packet consists of multiple parts/fragments. Note that it can be a function of a network driver. Today's network drivers often put IP and MAC headers in the linear part of an skb, and put the rest of packet's data in the fragmented parts. When an skb with the received packet is moved up the network stack, the protocol headers (such as TCP header) are pulled to the linear part of an skb from fragmented parts, and that may (and does) change an offset into a fragmented part that had some data pulled from it.

Current master branch includes this fix. This issue should be closed.