Hi guys,
I just noticed I had missed a "timeout client".. When disabling that - I
can't seem to reproduce the 408 issue.
Willy Tarreau said the following on 02/20/2014 08:44 PM:
[CUT]
> --- a/src/proto_http.c
> +++ b/src/proto_http.c
> @@ -2484,6 +2484,10 @@ int http_wait_for_request(struct session *s, struct
> channel *req, int an_bit)
>
> /* 3: has the read timeout expired ? */
> else if (req->flags & CF_READ_TIMEOUT ||
> tick_is_expired(req->analyse_exp, now_ms)) {
> + send_log(s->fe, LOG_DEBUG,
> + "Timeout detected: fe=%s s->flags=%08x
> txn->flags=%08x req->flags=%08x msg->flags=%08x now_ms=%u req->analyse_exp=%u
> (%d)\n",
> + s->fe->id, s->flags, txn->flags, req->flags,
> msg->flags, now_ms, req->analyse_exp, req->analyse_exp - now_ms);
> +
> if (!(s->flags & SN_ERR_MASK))
> s->flags |= SN_ERR_CLITO;
>
>
> And if you're willing to do a second test, please apply this one :
>
> --- a/src/proto_http.c
> +++ b/src/proto_http.c
> @@ -4444,6 +4452,7 @@ void http_end_txn_clean_session(struct session *s)
> s->req->cons->exp = TICK_ETERNITY;
> s->req->cons->flags &= SI_FL_DONT_WAKE; /* we're in the context of
> process_session */
> s->req->flags &=
> ~(CF_SHUTW|CF_SHUTW_NOW|CF_AUTO_CONNECT|CF_WRITE_ERROR|CF_STREAMER|CF_STREAMER_FAST|CF_NEVER_WAIT);
> + s->req->flags &= ~CF_READ_TIMEOUT;
> s->rep->flags &=
> ~(CF_SHUTR|CF_SHUTR_NOW|CF_READ_ATTACHED|CF_READ_ERROR|CF_READ_NOEXP|CF_STREAMER|CF_STREAMER_FAST|CF_WRITE_PARTIAL|CF_NEVER_WAIT);
> s->flags &=
> ~(SN_DIRECT|SN_ASSIGNED|SN_ADDR_SET|SN_BE_ASSIGNED|SN_FORCE_PRST|SN_IGNORE_PRST);
> s->flags &= ~(SN_CURR_SESS|SN_REDIRECTABLE);
>
> It removes the CF_READ_TIMEOUT flag between requests. If the problem
> disappears, it means the flag is inherited between requests (though we still
> have to figure when it can happen without being an issue).
>
I applied both patches, and can still reproduce the error (when timeout
client is set), but the log no longer logs cR (since I enabled httplog).
This was the log entries from the last try, where I got a 408 in the
browser.
Feb 25 09:00:29 localhost haproxy[10486]: 10.46.10.145:39602
[25/Feb/2014:09:00:28.834] example.dk varnish-dmz/varnish01
0/0/0/177/177 200 4840 - - ---- 6/6/0/1/0 0/0 "GET /user/login HTTP/1.1"
Feb 25 09:00:29 localhost haproxy[10486]: 10.46.10.145:39602
[25/Feb/2014:09:00:29.010] example.dk varnish-dmz/varnish02 28/0/1/0/29
304 461 - - ---- 4/4/0/1/0 0/0 "GET
/sites/test1.testms.example.dk/files/css/css_LYss46ysJxRRPkNn97hs6CWd7YXPB2emRjXSSVfLgCU.css
HTTP/1.1"
Feb 25 09:00:29 localhost haproxy[10486]: 10.46.10.145:39603
[25/Feb/2014:09:00:29.044] example.dk varnish-dmz/varnish02 0/0/0/0/0
304 461 - - ---- 5/5/0/1/0 0/0 "GET
/sites/test1.testms.example.dk/files/css/css_PotrMOiE3wsU0p53VT41Vp_TlyGnJa_IOPSf74RYDNs.css
HTTP/1.1"
Feb 25 09:00:29 localhost haproxy[10486]: 10.46.10.145:39604
[25/Feb/2014:09:00:29.045] example.dk varnish-dmz/varnish02 0/0/0/0/0
304 462 - - ---- 9/9/4/2/0 0/0 "GET
/sites/test1.testms.example.dk/files/css/css_9Bngx0XRCGG3sSIyd4AvOFOks7o2IpfayRORBN6c3Xw.css
HTTP/1.1"
Feb 25 09:00:29 localhost haproxy[10486]: 10.46.10.145:39606
[25/Feb/2014:09:00:29.045] example.dk varnish-dmz/varnish02 0/0/0/0/0
304 469 - - ---- 9/9/3/1/0 0/0 "GET
/sites/test1.testms.example.dk/files/js/js_IkgOrrVZK1UTp2HktvFi5vo1g7b25Muyr5GoySikuic.js
HTTP/1.1"
Feb 25 09:00:29 localhost haproxy[10486]: 10.46.10.145:39602
[25/Feb/2014:09:00:29.040] example.dk varnish-dmz/varnish01 4/0/1/1/6
304 463 - - ---- 9/9/2/3/0 0/0 "GET
/sites/test1.testms.example.dk/files/css/css_AFNnEjvDR5CvJkNKTljzBrlXpHTR2BYWPNnWbH1OEx4.css
HTTP/1.1"
Feb 25 09:00:29 localhost haproxy[10486]: 10.46.10.145:39605
[25/Feb/2014:09:00:29.045] example.dk varnish-dmz/varnish01 0/0/0/1/1
304 463 - - ---- 9/9/1/2/0 0/0 "GET
/sites/test1.testms.example.dk/files/css/css__nTXAnD87M2AhWF2DiSgN1-uhQqgJ3Op1bl5N06Pvu4.css
HTTP/1.1"
Feb 25 09:00:29 localhost haproxy[10486]: 10.46.10.145:39607
[25/Feb/2014:09:00:29.045] example.dk varnish-dmz/varnish01 0/0/0/1/1
304 471 - - ---- 9/9/0/1/0 0/0 "GET
/sites/test1.testms.example.dk/files/js/js_5cYf1A6mNLYEmlwo2Ftk3pqeuzLOxPQdHymcr4I4idM.js
HTTP/1.1"
Feb 25 09:00:29 localhost haproxy[10486]: 10.46.10.145:39603
[25/Feb/2014:09:00:29.044] example.dk varnish-dmz/varnish02 2/0/0/0/2
304 469 - - ---- 9/9/0/1/0 0/0 "GET
/sites/test1.testms.example.dk/files/js/js_R_ItDCoKeqPMRgcU-D-9yzx190CQeBCgO07IOiqZeLU.js
HTTP/1.1"
Feb 25 09:00:29 localhost haproxy[10486]: 10.46.10.145:39602
[25/Feb/2014:09:00:29.046] example.dk varnish-dmz/varnish01 2/0/0/0/2
304 470 - - ---- 9/9/0/1/0 0/0 "GET
/sites/test1.testms.example.dk/files/js/js_Dpwj9_jdZx11LB9vWakYPT-NglBvlNPbjDg8kKHykyQ.js
HTTP/1.1"
Feb 25 09:00:29 localhost haproxy[10486]: 10.46.10.145:39609
[25/Feb/2014:09:00:29.131] example.dk varnish-dmz/varnish02 0/0/0/0/0
304 414 - - ---- 2/2/1/1/0 0/0 "GET
/sites/all/modules/contrib/feedback_simple/feedback_simple.gif HTTP/1.1"
Feb 25 09:00:29 localhost haproxy[10486]: 10.46.10.145:39608
[25/Feb/2014:09:00:29.131] example.dk varnish-dmz/varnish01 0/0/0/1/1
304 415 - - ---- 2/2/0/1/0 0/0 "GET
/sites/all/themes/kkms_theme/logo.png HTTP/1.1"
Feb 25 09:00:29 localhost haproxy[10486]: 10.46.10.145:39609
[25/Feb/2014:09:00:29.132] example.dk varnish-dmz/varnish01 16/0/1/0/17
304 415 - - ---- 2/2/0/1/0 0/0 "GET
/sites/all/themes/kkms_theme/images/icon-search.png HTTP/1.1"
Feb 25 09:00:29 localhost haproxy[10486]: 10.46.10.145:39608
[25/Feb/2014:09:00:29.132] example.dk varnish-dmz/varnish02 19/0/1/0/20
304 419 - - ---- 2/2/0/1/0 0/0 "GET
/sites/all/themes/kkms_theme/js/libraries/jquery.fitvids.js HTTP/1.1"
--
Regards,
Klavs Klavsen, GSEC - k...@vsen.dk - http://www.vsen.dk - Tlf. 61281200
"Those who do not understand Unix are condemned to reinvent it, poorly."
--Henry Spencer
