2009/7/13 Ken Brownfield <[email protected]>: > I would try correlating these 503's with actual Apache log lines. That way, > you'll see what Apache told Varnish (if it made it to Apache at all). there are no sign of thiese requests in apache logs
> > Also, try tcpdumping the backend port to a file, and then use wireshark to > go back to the traffic at the time you see another 503. it happens with or without keep-alive (it was set before and I disabled it recently) it's likelly the same issue as in "tcp reset problem with varnish 2.0.4 o n Solaris 10 (SPARC)" thread it happens on 0,09% of request's, mostly POST'S but not only now I rechecked the logs and I found that varnish closed the connection just after sending the request tcpdump follows, there are no backend connection errors 01:03:50.181412 IP x.x.x.x.48563 > x.x.x.x.88: S 3999574413:3999574413(0) win 32792 <mss 16396,sackOK,timestamp 458935307 0,nop,wscale 7> 0x0000: 4500 003c 6586 4000 4006 3b56 566f f680 E..<e...@.@.;VVo.. 0x0010: 566f f680 bdb3 0058 ee64 a98d 0000 0000 Vo.....X.d...... 0x0020: a002 8018 b64b 0000 0204 400c 0402 080a .....k....@..... 0x0030: 1b5a cc0b 0000 0000 0103 0307 .Z.......... 01:03:50.181422 IP x.x.x.x.88 > x.x.x.x.48563: S 4006066350:4006066350(0) ack 3999574414 win 32768 <mss 16396,sackOK,timestamp 458935307 458935307,nop,wscale 7> 0x0000: 4500 003c 0000 4000 4006 a0dc 566f f680 E..<....@[email protected].. 0x0010: 566f f680 0058 bdb3 eec7 b8ae ee64 a98e Vo...X.......d.. 0x0020: a012 8000 2776 0000 0204 400c 0402 080a ....'v....@..... 0x0030: 1b5a cc0b 1b5a cc0b 0103 0307 .Z...Z...... 01:03:50.181433 IP x.x.x.x.48563 > x.x.x.x.88: . ack 1 win 257 <nop,nop,timestamp 458935307 458935307> 0x0000: 4500 0034 6587 4000 4006 3b5d 566f f680 e.....@.@.;]Vo.. 0x0010: 566f f680 bdb3 0058 ee64 a98e eec7 b8af Vo.....X.d...... 0x0020: 8010 0101 0f9a 0000 0101 080a 1b5a cc0b .............Z.. 0x0030: 1b5a cc0b .Z.. 01:03:54.581224 IP x.x.x.x.88 > x.x.x.x.48563: S 4006066350:4006066350(0) ack 3999574414 win 32768 <mss 16396,sackOK,timestamp 458936407 458935307,nop,wscale 7> 0x0000: 4500 003c 0000 4000 4006 a0dc 566f f680 E..<....@[email protected].. 0x0010: 566f f680 0058 bdb3 eec7 b8ae ee64 a98e Vo...X.......d.. 0x0020: a012 8000 232a 0000 0204 400c 0402 080a ....#*....@..... 0x0030: 1b5a d057 1b5a cc0b 0103 0307 .Z.W.Z...... 01:03:54.581245 IP x.x.x.x.48563 > x.x.x.x.88: . ack 1 win 257 <nop,nop,timestamp 458936407 458936407,nop,nop,sack 1 {0:1}> 0x0000: 4500 0040 6588 4000 4006 3b50 566f f680 ...@e.@....@.;PVo.. 0x0010: 566f f680 bdb3 0058 ee64 a98e eec7 b8af Vo.....X.d...... 0x0020: b010 0101 81fc 0000 0101 080a 1b5a d057 .............Z.W 0x0030: 1b5a d057 0101 050a eec7 b8ae eec7 b8af .Z.W............ 01:03:55.181239 IP x.x.x.x.48563 > x.x.x.x.88: P 1:896(895) ack 1 win 257 <nop,nop,timestamp 458936557 458936407> 0x0000: 4500 03b3 6589 4000 4006 37dc 566f f680 e.....@[email protected].. 0x0010: 566f f680 bdb3 0058 ee64 a98e eec7 b8af Vo.....X.d...... 0x0020: 8018 0101 9d85 0000 0101 080a 1b5a d0ed .............Z.. 0x0030: 1b5a d057 504f 5354 202f 7175 697a 2f71 .Z.WPOST./quiz/q 0x0040: 7565 7374 696f 6e20 4854 5450 2f31 2e31 uestion.HTTP/1.1 0x0050: 0d0a 782d 7265 7175 6573 7465 642d 7769 ..x-requested-wi 0x0060: 7468 3a20 584d 4c48 7474 7052 6571 7565 th:.XMLHttpReque ...................... request data 01:03:55.181256 IP x.x.x.x.88 > x.x.x.x.48563: . ack 896 win 270 <nop,nop,timestamp 458936557 458936557> 0x0000: 4500 0034 6842 4000 4006 38a2 566f f680 e.....@[email protected].. 0x0010: 566f f680 0058 bdb3 eec7 b8af ee64 ad0d Vo...X.......d.. 0x0020: 8010 010e 024a 0000 0101 080a 1b5a d0ed .....J.......Z.. 0x0030: 1b5a d0ed .Z.. ........... acked 01:03:55.181302 IP x.x.x.x.48563 > x.x.x.x.88: F 896:896(0) ack 1 win 257 <nop,nop,timestamp 458936557 458936557> 0x0000: 4500 0034 658a 4000 4006 3b5a 566f f680 e.....@.@.;ZVo.. 0x0010: 566f f680 bdb3 0058 ee64 ad0d eec7 b8af Vo.....X.d...... 0x0020: 8011 0101 0256 0000 0101 080a 1b5a d0ed .....V.......Z.. 0x0030: 1b5a d0ed .Z.. ........... connection closed ??? 01:03:55.185068 IP x.x.x.x.88 > x.x.x.x.48563: P 1:2485(2484) ack 897 win 270 <nop,nop,timestamp 458936557 458936557> 0x0000: 4500 09e8 6843 4000 4006 2eed 566f f680 e.....@[email protected].. 0x0010: 566f f680 0058 bdb3 eec7 b8af ee64 ad0e Vo...X.......d.. 0x0020: 8018 010e a3ba 0000 0101 080a 1b5a d0ed .............Z.. 0x0030: 1b5a d0ed 4854 5450 2f31 2e31 2032 3030 .Z..HTTP/1.1.200 0x0040: 204f 4b0d 0a44 6174 653a 2046 7269 2c20 .OK..Date:.Fri,. 0x0050: 3130 204a 756c 2032 3030 3920 3233 3a30 10.Jul.2009.23:0 0x0060: 333a 3535 2047 4d54 0d0a 5365 7276 6572 3:55.GMT..Server 0x0070: 3a20 4170 6163 6865 0d0a 4578 7069 7265 :.Apache..Expire 0x0080: 733a 2054 6875 2c20 3139 204e 6f76 2031 s:.Thu,.19.Nov.1 0x0090: 3938 3120 3038 3a35 323a 3030 2047 4d54 981.08:52:00.GMT 0x00a0: 0d0a 4361 6368 652d 436f 6e74 726f 6c3a ..Cache-Control: 0x00b0: 206e 6f2d 7374 6f72 652c 206e 6f2d 6361 .no-store,.no-ca 0x00c0: 6368 652c 206d 7573 742d 7265 7661 6c69 che,.must-revali 0x00d0: 6461 7465 2c20 706f 7374 2d63 6865 636b date,.post-check 0x00e0: 3d30 2c20 7072 652d 6368 6563 6b3d 300d =0,.pre-check=0. 0x00f0: 0a50 7261 676d 613a 206e 6f2d 6361 6368 .Pragma:.no-cach 0x0100: 650d 0a43 6f6e 7465 6e74 2d4c 656e 6774 e..Content-Lengt 0x0110: 683a 2032 3230 390d 0a43 6f6e 6e65 6374 h:.2209..Connect .......... reset 01:03:55.185091 IP x.x.x.x.48563 > x.x.x.x.88: R 3999575310:3999575310(0) win 0 0x0000: 4500 0028 0000 4000 4006 a0f0 566f f680 E..(....@[email protected].. 0x0010: 566f f680 bdb3 0058 ee64 ad0e 0000 0000 Vo.....X.d...... 0x0020: 5004 0000 bc81 0000 P....... > > Varnish should be logging failed health checks, which could explain periodic > 503s. If the health checks are succeeding, then Apache is likely > periodically closing a connection or sending bad data. > > You could also try turning off HTTP 1.1 to Apache from Varnish > (backend_http11=off) to see if that does anything. With Varnish fronting > Apache, doing 1.1 to the backend isn't necessarily a huge win. > > In the 503 case specifically, I'm not sure if restarts are respected. Does > this happen if you relax the connect_timeout, or if you remove the restart? I tried to fix the issue by adding a restart, it works as expected except that there is no automatic max restarts limit (it whould be nice if there was some just like in vcl_retr) > Does this happen only with POST? Do you have any custom settings in > vcl_pipe(), or do you bail out of vcl_recv() without falling through to the > default VCL? no, vcl_recv() was empty before, now it only has a restart (not trigerd by the closing connection issue) > > Finally, did you edit the Cookie header? It's malformed, which in theory > could cause either Apache or Varnish to dump it. no _______________________________________________ varnish-misc mailing list [email protected] http://projects.linpro.no/mailman/listinfo/varnish-misc
