DO NOT REPLY TO THIS EMAIL, BUT PLEASE POST YOUR BUG· RELATED COMMENTS THROUGH THE WEB INTERFACE AVAILABLE AT <http://issues.apache.org/bugzilla/show_bug.cgi?id=43607>. ANY REPLY MADE TO THIS MESSAGE WILL NOT BE COLLECTED AND· INSERTED IN THE BUG DATABASE.
http://issues.apache.org/bugzilla/show_bug.cgi?id=43607 Summary: mod_proxy sends data on closed connections without checking Product: Apache httpd-2 Version: 2.2.6 Platform: Sun OS/Version: Solaris Status: NEW Severity: normal Priority: P2 Component: mod_proxy AssignedTo: [email protected] ReportedBy: [EMAIL PROTECTED] If an HTTP request is split into two packets and, due to network congestion (or anything else), the second packet arrives significantly later than the first (5 or more seconds), we have a situation where Apache tries to send data down a closed connection. This happens because Apache first parses the HTTP header, then opens a connection to the backend server (without sending any data), then parses the HTTP body, and then tries to send everything at once to the backend server. When the delay between HTTP header and HTTP body exceeds the timeout of the backend server (5 seconds in my case), the backend server closes the connection. When Apache sends the data to the backend server, it gets a reset from the app server, which results in a 502 error being sent back to the web browser. Per the truss output, below, you can see that the header is processed, the connection is opened, and then the body is parsed. After that, the data is sent to the backend server (unsuccessfully). Either mod_proxy should wait to open the connection to the backend server until after it's processed the body, or Apache should at least check the state of the connection before sending data. Or maybe if it gets a reset, it tries again. ** NOTE INCOMING POST FROM CLIEN 2030/24: 0.0006 read(61, " P O S T /<OMITTED>".., 8000) = 128 2030/24: 0.0006 pollsys(0xFFFFFFFF6B7FB6A8, 1, 0xFFFFFFFF6B7FB5E0, 0x00000000) = 1 2030/24: fd=61 ev=POLLIN rev=POLLIN 2030/24: timeout: 300.000000000 sec 2030/24: 0.0005 read(61, " H o s t : <OMITTED>".., 8000) = 177 2030/24: 0.6335 pollsys(0xFFFFFFFF6B7FB6A8, 1, 0xFFFFFFFF6B7FB5E0, 0x00000000) = 1 2030/24: fd=61 ev=POLLIN rev=POLLIN 2030/24: timeout: 300.000000000 sec 2030/24: 0.0005 read(61, "\r\n", 8000) = 2 2030/24: 0.0117 open("/dev/udp", O_RDONLY) = 62 2030/24: 0.0005 ioctl(62, SIOCGLIFNUM, 0xFFFFFFFF6B7FB174) = 0 2030/24: 0.0003 close(62) = 0 2030/24: 0.0007 open("/etc/default/nss", O_RDONLY|O_LARGEFILE) = 62 2030/24: 0.0004 fcntl(62, F_DUPFD, 0x00000100) = 256 2030/24: 0.0002 close(62) = 0 2030/24: 0.0002 read(256, " # i d e n t\t " @ ( #".., 1024) = 1024 2030/24: 0.0002 read(256, " y t h o s e\n # f u n".., 1024) = 211 2030/24: 0.0004 read(256, 0x10071B5C4, 1024) = 0 2030/24: 0.0002 close(256) = 0 2030/24: 0.0004 so_socket(PF_INET, SOCK_STREAM, IPPROTO_TCP, "", SOV_DEFAULT) = 62 2030/24: 0.0003 setsockopt(62, tcp, TCP_NODELAY, 0xFFFFFFFF6B7FB66C, 4, SOV_DEFAULT) = 0 ** NOW APACHE OPENS A CONNECTION TO THE BACKEND SERVER 2030/24: 0.0003 fcntl(62, F_GETFL) = 2 2030/24: 0.0001 fcntl(62, F_SETFL, FWRITE|FNONBLOCK) = 0 2030/24: 0.0005 connect(62, 0x100310CA8, 16, SOV_DEFAULT) Err#150 EINPROGRESS 2030/24: AF_INET name = 10.10.5.10 port = 7929 2030/24: 0.0067 pollsys(0xFFFFFFFF6B7FB5A8, 1, 0xFFFFFFFF6B7FB4E0, 0x00000000) = 1 2030/24: fd=62 ev=POLLOUT rev=POLLOUT 2030/24: timeout: 300.000000000 sec 2030/24: 0.0003 getsockopt(62, SOL_SOCKET, SO_ERROR, 0xFFFFFFFF6B7FB668, 0xFFFFFFFF6B7FB66C, SOV_DEFAULT) = 0 2030/24: 0.0004 getsockname(62, 0x100310E48, 0x100310E28, SOV_DEFAULT) = 0 2030/24: AF_INET name = 10.10.4.10 port = 44706 2030/24: pollsys(0xFFFFFFFF6B7FB338, 1, 0xFFFFFFFF6B7FB270, 0x00000000) (sleeping...) 2030/24: fd=61 ev=POLLIN rev=0xFFFFB49C 2030/24: timeout: 300.000000000 sec ** NOTE THE DELAY IN RECEIVING THE BODY: 14.49 SECONDS 2030/24: 14.4911 pollsys(0xFFFFFFFF6B7FB338, 1, 0xFFFFFFFF6B7FB270, 0x00000000) = 1 2030/24: fd=61 ev=POLLIN rev=POLLIN 2030/24: timeout: 300.000000000 sec ** HERE'S THE BODY 2030/24: 0.0005 read(61, " j _ u s e r n a m e = ".., 8000) = 52 2030/24: 0.0009 writev(62, 0xFFFFFFFF6B7FB650, 14) = 480 ** HERE'S WHERE APACHE TRIES TO WRITE TO THE BACKEND CONNECTION WHICH ** HAS ALREADY EXPIRED AND CLOSED 2030/24: iov_base = 0x1006FA5C0 iov_len = 38 2030/24: P O S T /<SOME PATH. DELETED FOR THIS EXAMPLE> ** THE BACKEND SERVER SENDS US A RESET 2030/24: 0.0009 read(62, 0x10071B0C8, 8000) Err#131 ECONNRESET ** A PROXY ERROR IS THROWN BACK TO THE WEB BROWSER/CLIENT 2030/24: 0.0007 write(28, 0xFFFFFFFF6B7F7680, 203) = 203 2030/24: [ T h u O c t 1 1 1 4 : 3 3 : 0 3 2 0 0 7 ] [ e r r o 2030/24: r ] [ c l i e n t 1 0 . 1 0 . 4 . 1 0 ] ( 1 3 1 ) C o n n 2030/24: e c t i o n r e s e t b y p e e r : p r o x y : e r r 2030/24: o r r e a d i n g s t a t u s l i n e f r o m r e m o 2030/24: t e s e r v e r XX , r e f e r e r : SOMEURL\n 2030/24: 0.0006 write(28, 0xFFFFFFFF6B7F75A0, 184) = 184 2030/24: [ T h u O c t 1 1 1 4 : 3 3 : 0 3 2 0 0 7 ] [ e r r o 2030/24: r ] [ c l i e n t 1 0 . 1 0 . 4 . 1 0 ] p r o x y : E r 2030/24: r o r r e a d i n g f r o m r e m o t e s e r v e r r 2030/24: e t u r n e d b y A_URL, r e f e r e r : SOME_URL\n 2030/24: 0.0004 close(62) = 0 2030/24: 0.0006 brk(0x10071FD60) = 0 2030/24: 0.0002 brk(0x100723D60) = 0 2030/24: 0.0006 writev(61, 0xFFFFFFFF6B7FB930, 2) = 576 2030/24: iov_base = 0x10071D0D8 iov_len = 154 2030/24: H T T P / 1 . 1 5 0 2 P r o x y E r r o r\r\n D a t e : 2030/24: T h u , 1 1 O c t 2 0 0 7 2 1 : 3 2 : 4 7 G M T\r\n V 2030/24: a r y : A c c e p t - E n c o d i n g\r\n C o n t e n t - L e 2030/24: n g t h : 4 2 2\r\n C o n t e n t - T y p e : t e x t / h t 2030/24: m l ; c h a r s e t = i s o - 8 8 5 9 - 1\r\n\r\n 2030/24: iov_base = 0x10071B0C8 iov_len = 422 2030/24: < ! D O C T Y P E H T M L P U B L I C " - / / I E T F / / 2030/24: D T D H T M L 2 . 0 / / E N " >\n < h t m l > < h e a d >\n 2030/24: < t i t l e > 5 0 2 P r o x y E r r o r < / t i t l e >\n < 2030/24: / h e a d > < b o d y >\n < h 1 > P r o x y E r r o r < / h 1 2030/24: >\n < p > T h e p r o x y s e r v e r r e c e i v e d a 2030/24: n i n v a l i d\r\n r e s p o n s e f r o m a n u p s t 2030/24: r e a m s e r v e r . < b r / >\r\n T h e p r o x y s e 2030/24: r v e r c o u l d n o t h a n d l e t h e r e q u e s 2030/24: t < e m > < a h r e f = "A_URL" > P O S T & n b s p ; URL< / a > < / e m > . < p >\n R e a s o n : < s t 2030/24: r o n g > E r r o r r e a d i n g f r o m r e m o t e s 2030/24: e r v e r < / s t r o n g > < / p > < / p >\n < / b o d y > < / 2030/24: h t m l >\n -- Configure bugmail: http://issues.apache.org/bugzilla/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee. --------------------------------------------------------------------- To unsubscribe, e-mail: [EMAIL PROTECTED] For additional commands, e-mail: [EMAIL PROTECTED]
