evhtp_request_pause (req) issue

[Ultima1252]

Details

evhtp_request_pause will freeze current connections from sending data. I don't entirely understand how evhtp works, so this could be a problem in the seafile code and not evhtp, but I'm not positive.

In version 1.2.9, [1] changed to [2] and in every version after it. This caused the main issue that I am experiencing and have reverted the change as shown at [3]. My guess is that EV_WRITE isn't being re enabled when it should. It is very difficult to debug the seafile code though because there isn't any debugging code in it. If you have a suggestion of how to debug the library I am open to suggestions.

[4] [5] is the seafile code using this function, I'm fairly certain [4] is where the bug is occurring. Also want to mention that [6] is a patch I am using that the previous libevhtp developer suggested, which didn't fix the issue unfortunately.

[1] https://github.com/criticalstack/libevhtp/blob/1.2.9/evhtp.c#L1984
[2] https://github.com/criticalstack/libevhtp/blob/1.2.13/evhtp.c#L2865
[3] https://github.com/freebsd/freebsd-ports/blob/branches/2018Q1/www/libevhtp/files/patch-evhtp.c
[4] https://github.com/haiwen/seafile-server/blob/v6.2.3-server/server/access-file.c
[5] https://github.com/haiwen/seafile-server/blob/v6.2.3-server/server/upload-file.c
[6] https://github.com/freebsd/freebsd-ports/blob/branches/2018Q1/net-mgmt/seafile-server/files/patch-server_access-file.c

Steps or code to reproduce the problem.

1. Use [7] to patch libevhtp in FreeBSD ports
2. modify version run and make makesum
3. compile libevhtp and seafile-server, install seahub.
4. Attempt to upload files / download files. Will fail with, Error 404. [8] is curl -v output.

[7] https://reviews.freebsd.org/D13742
[8] curl -v "https://OBSCURED/seafhttp/files/c6629c8c-5324-OBSCURED-a9a46bf4aaa8/OBSCURED.rar"

• Trying 2601:646:OBSCURED:feed:c6a6...
• TCP_NODELAY set
• Connected to seafile.ultimasbox.com (2601:646:OBSCURED:feed:c6a6) port 443 (#0)
• ALPN, offering h2
• ALPN, offering http/1.1
• successfully set certificate verify locations:
• CAfile: /etc/ssl/certs/ca-certificates.crt
  CApath: none
• TLSv1.2 (OUT), TLS handshake, Client hello (1):
• TLSv1.2 (IN), TLS handshake, Server hello (2):
• TLSv1.2 (IN), TLS handshake, Certificate (11):
• TLSv1.2 (IN), TLS handshake, Server key exchange (12):
• TLSv1.2 (IN), TLS handshake, Server finished (14):
• TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
• TLSv1.2 (OUT), TLS change cipher, Client hello (1):
• TLSv1.2 (OUT), TLS handshake, Finished (20):
• TLSv1.2 (IN), TLS handshake, Finished (20):
• SSL connection using TLSv1.2 / ECDHE-RSA-CHACHA20-POLY1305
• ALPN, server accepted to use h2
• Server certificate:
• subject: CN=OBSCURED
• start date: Oct 30 07:28:47 2017 GMT
• expire date: Jan 28 07:28:47 2018 GMT
• subjectAltName: host "OBSCURED" matched cert's "OBSCURED"
• issuer: C=US; O=Let's Encrypt; CN=Let's Encrypt Authority X3
• SSL certificate verify ok.
• Using HTTP2, server supports multi-use
• Connection state changed (HTTP/2 confirmed)
• Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
• Using Stream ID: 1 (easy handle 0x5585f5bf7090)

GET /seafhttp/files/c6629c8c-5324-OBSCURED-a9a46bf4aaa8/OBSCURED.rar HTTP/2
Host: OBSCURED
User-Agent: curl/7.57.0
Accept: /

• Connection state changed (MAX_CONCURRENT_STREAMS updated)!
  < HTTP/2 404
  < server: nginx
  < date: Wed, 03 Jan 2018 22:09:47 GMT
  < content-type: text/plain
  < content-length: 0
  <
• Connection #0 to host OBSCURED left intact

Version

1.2.9 (works) --> 1.2.10 (Fails), 1.2.11 (Fails), 1.2.13 (Fails)
1.2.12 Also seems to be not work. Removing EV_WRITE on the line mentioned in [2] will cause everything to work again as it did in 1.2.9.

[NathanFrench]

Wow, this is a lot to take in tonight. I may see where things could go wrong. I'm very tired tonight and will look into this tomorrow.

But oddly enough, I wrote a detailed example of proper request pausing usage here: https://github.com/criticalstack/libevhtp/blob/develop/examples/example_pause.c

Until tomorrow!

[Ultima1252]

Yeah, sorry I provided so much. Its an issue I'v been stuck with for some time now and struggling with. I'll work on it some more and maybe this will be closed before you get a chance to look at it! =]

[Ultima1252]

It actually maybe more of a work around than a fix, but I found [1] which instead of calling request_pause, only disabled EV_READ. Its probably an issue on the seafile side, so closing. Thanks for your help.

[1] https://sml.zincube.net/~niol/repositories.git/seafile-server/plain/debian/patches/recent-libevhtp

[Ultima1252]

More information about the issue if interested in reading more.

haiwen/seafile#1119

[NathanFrench]

Reopening as I remember seeing this issue, and I'm not 100% sure it's a seafile issue.

[NathanFrench]

Ah, that patch above in (zincube) will only work correctly if the callback where the request is paused is the final one. Otherwise, the API wouldn't know to short-circuit and return back to the function that called the parser. So that person should watch out for that.

But I think he's on the right track, here is how pausing works at the moment:

1. when request_pause is called, it sets the EVHTP_CONN_FLAG_PAUSED on the connection

(evhtp_connection_t *)c->flags &= EVHP_CONN_FLAG_PAUSED)

2. The above actually happens from evhtp_connection_pause, but after it returns, it disables both EV_READ and EV_WRITE.

3. It then sets the requests status to EVHTP_CONN_FLAG_PAUSED

4. This tells any further processing from htparser to stop, and as nested as it may be, all functions check for the paused status and return back until it finally gets back to the read callback.

5. when evhtp_request_resume is called, it executes an event_active(conn->resume_ev, EV_WRITE, 1) which will call htp__connection_resumecb_. This event is initialized as follows:

    connection->resume_ev = event_new(evbase, -1, EV_READ | EV_PERSIST,
                                      htp__connection_resumecb_, connection);

When event_active gets around to calling htp__connection_resumecb_ it unsets the EVHTP_CONN_FLAG_PAUSED flag, and does some checks here and there,
but I think the culprit may be here:

    if (evbuffer_get_length(bufferevent_get_output(c->bev)))
    {
        HTP_FLAG_ON(c, EVHTP_CONN_FLAG_WAITING);
 
        bufferevent_enable(c->bev, EV_WRITE);
    } else {
        bufferevent_enable(c->bev, EV_READ | EV_WRITE);
        htp__connection_readcb_(c->bev, c);
    }

If there is pending data on the output buffer, it will only set the bufferevent to EV_WRITE. The assumption was that libevent would automatically start transferring pending data to the socket once the EV_WRITE flag was set on the bufferevent. This is a dumb assumption. It does not. So if there is pending data, it just stays there until the bufferevent is written to again.

6. The flag EVHTP_CONN_FLAG_WAITING is set on the connection, which only gets checked and unset in htp__connection_writecb_ (the write callback). But with the assumption above, and no data is written to the socket AFTER htp__connection_resumecb_.

7. When (and if, in some cases apparently) htp__connection_writecb_ is called by libevent, it checks for the EVHTP_CONN_FLAG_WAITING flag in the connection, if enabled, it enables EV_READ again on the connection's bufferevent, then immediately calls htp__connection_readcb_. But this doesn't take into account pending data on the write end of the bufferevent (unless, as I said, something writes to it afterwards).

It should be noted that even if htp__connection_writecb_ is called before htp__connection_resumecb_ (don't ask me how this could happen), it will return do to:

    /* run user-hook for on_write callback before further analysis */
    htp__hook_connection_write_(conn);                                                                                              
         
    /* connection is in a paused state, no further processing yet */
    if ((conn->flags & EVHTP_CONN_FLAG_PAUSED))
    {    
        return;
    }

    /* checks for EVHTP_CONN_FLAG_WAITING, then enables read again */

I think some of the patches above were on the write (get it, "write", not "right"?) track. I do not think the EV_WRITE flag should be unset on the connection's bufferevent when paused. We should let libevent do its dirty work of sending all pending data.

We might want to rearrange some of the code there, I'm thinking something like:

    /* run user-hook for on_write callback before further analysis */
    htp__hook_connection_write_(conn);
             
    /* connection is in a paused state, no further processing yet */
    if ((conn->flags & EVHTP_CONN_FLAG_PAUSED))
    {        
        return;
    }        
             
    if (conn->flags & EVHTP_CONN_FLAG_WAITING)

to

    /* connection is in a paused state, no further processing yet */
    if ((conn->flags & EVHTP_CONN_FLAG_PAUSED))
    {        
        return;
    }        

    /* run user-hook for on_write callback before further analysis */
    htp__hook_connection_write_(conn);

    if (conn->flags & EVHTP_CONN_FLAG_WAITING)

and

void              
evhtp_connection_pause(evhtp_connection_t * c)                                                                                      
{                 
    evhtp_assert(c != NULL);
                  
    HTP_FLAG_ON(c, EVHTP_CONN_FLAG_PAUSED);
                  
    bufferevent_disable(c->bev, EV_READ | EV_WRITE);
                  
    return;       
}                 

should be

void              
evhtp_connection_pause(evhtp_connection_t * c)                                                                                      
{                 
    evhtp_assert(c != NULL);
                  
    HTP_FLAG_ON(c, EVHTP_CONN_FLAG_PAUSED);
                  
    bufferevent_disable(c->bev, EV_READ);
                  
    return;       
}                 

Thoughts?

[Ultima1252]

Pretty sure adding "Thoughts?" would upset the compiler quite a bit. =] Seriously though the suggested changes look good to me. This is more or less the patch i'v been using up until a few days ago. Rearranging the htp__hook_connection_write_(conn); would make more sense as well. After digesting all the information provided.

This is probably what should have occurred in 1.2.9 --> 1.2.10, but its hard to say because of how much the code has changed and how long ago I read that very detailed bug report on why it was done in the first place.(memory a bit spotty on the issue that user was having) Pretty sure it was lost with the project transfer, would have been nice to take another look at it. =/

I didn't expect the rearranging to break anything, but I'v had bad experiences with these assumptions so ran a quick test. Everything looks to be in order.

Thank you for digging into this issue.

[NathanFrench]

Merged your pull request. Thanks for that. Hopefully, that fixes things. I tested, and nothing went wrong.

Cheers!

[Ultima1252]

That's great news! When do you think you'll be tagging a new release?

[NathanFrench]

https://github.com/criticalstack/libevhtp/releases/tag/1.2.16

And that's a wrap!