https://bz.apache.org/bugzilla/show_bug.cgi?id=64016
Bug ID: 64016 Summary: Apache HTTPD intermittently report errors AH01084 and AH01097 with 502 Product: Apache httpd-2 Version: 2.4.6 Hardware: Other OS: Linux Status: NEW Severity: blocker Priority: P2 Component: All Assignee: bugs@httpd.apache.org Reporter: spal...@rbbn.com Target Milestone: --- When request payload to Apache proxy is increased , it intermittently fails with 502 [2019-12-18 07:22:22 root@ems101: /etc/httpd/logs ]# apachectl -version Server version: Apache/2.4.6 (Red Hat Enterprise Linux) Server built: May 28 2018 16:19:32 error.log --------- -----Success------- [Wed Dec 18 06:00:39.058210 2019] [ssl:info] [pid 6793] [client 10.158.40.160:18009] AH01964: Connection to child 0 established (server 127.0.0.1:443) [Wed Dec 18 06:00:39.102557 2019] [socache_shmcb:debug] [pid 6793] mod_socache_shmcb.c(485): AH00831: socache_shmcb_store (0xd1 -> subcache 17) [Wed Dec 18 06:00:39.102627 2019] [socache_shmcb:debug] [pid 6793] mod_socache_shmcb.c(810): AH00847: insert happened at idx=1, data=(180:212) [Wed Dec 18 06:00:39.102641 2019] [socache_shmcb:debug] [pid 6793] mod_socache_shmcb.c(815): AH00848: finished insert, subcache: idx_pos/idx_used=0/2, data_pos/data_used=0/360 [Wed Dec 18 06:00:39.102653 2019] [socache_shmcb:debug] [pid 6793] mod_socache_shmcb.c(506): AH00834: leaving socache_shmcb_store successfully [Wed Dec 18 06:00:39.102680 2019] [ssl:debug] [pid 6793] ssl_engine_kernel.c(1823): [client 10.158.40.160:18009] AH02041: Protocol: TLSv1.2, Cipher: ECDHE-RSA-AES256-SHA384 (256/256 bits) [Wed Dec 18 06:00:39.104026 2019] [ssl:debug] [pid 6793] ssl_engine_kernel.c(225): [client 10.158.40.160:18009] AH02034: Initial (No.1) HTTPS request received for child 0 (server 127.0.0.1:443) [Wed Dec 18 06:00:39.104112 2019] [authz_core:debug] [pid 6793] mod_authz_core.c(809): [client 10.158.40.160:18009] AH01626: authorization result of Require all granted: granted [Wed Dec 18 06:00:39.104131 2019] [authz_core:debug] [pid 6793] mod_authz_core.c(809): [client 10.158.40.160:18009] AH01626: authorization result of <RequireAny>: granted [Wed Dec 18 06:00:39.104276 2019] [proxy:debug] [pid 6793] mod_proxy.c(1123): [client 10.158.40.160:18009] AH01143: Running scheme http handler (attempt 0) [Wed Dec 18 06:00:39.104305 2019] [proxy_ajp:debug] [pid 6793] mod_proxy_ajp.c(722): [client 10.158.40.160:18009] AH00894: declining URL http://127.0.0.1:8080/emsapi/services/PSXAPI/r11_02_00 [Wed Dec 18 06:00:39.104320 2019] [proxy_fcgi:debug] [pid 6793] mod_proxy_fcgi.c(972): [client 10.158.40.160:18009] AH01076: url: http://127.0.0.1:8080/emsapi/services/PSXAPI/r11_02_00 proxyname: (null) proxyport: 0 [Wed Dec 18 06:00:39.104355 2019] [proxy_fcgi:debug] [pid 6793] mod_proxy_fcgi.c(975): [client 10.158.40.160:18009] AH01077: declining URL http://127.0.0.1:8080/emsapi/services/PSXAPI/r11_02_00 [Wed Dec 18 06:00:39.104370 2019] [proxy:debug] [pid 6793] proxy_util.c(2203): AH00942: HTTP: has acquired connection for (127.0.0.1) [Wed Dec 18 06:00:39.104386 2019] [proxy:debug] [pid 6793] proxy_util.c(2256): [client 10.158.40.160:18009] AH00944: connecting http://127.0.0.1:8080/emsapi/services/PSXAPI/r11_02_00 to 127.0.0.1:8080 [Wed Dec 18 06:00:39.104400 2019] [proxy:debug] [pid 6793] proxy_util.c(2426): [client 10.158.40.160:18009] AH00947: connected /emsapi/services/PSXAPI/r11_02_00 to 127.0.0.1:8080 [Wed Dec 18 06:00:42.597287 2019] [headers:debug] [pid 6793] mod_headers.c(823): AH01502: headers: ap_headers_output_filter() [Wed Dec 18 06:00:42.597561 2019] [proxy:debug] [pid 6793] proxy_util.c(2218): AH00943: http: has released connection for (127.0.0.1) [Wed Dec 18 06:00:42.597717 2019] [ssl:debug] [pid 6793] ssl_engine_io.c(993): [client 10.158.40.160:18009] AH02001: Connection closed to child 0 with standard shutdown (server 127.0.0.1:443) -------------------- -----Failure--------- [Wed Dec 18 06:00:42.622787 2019] [ssl:info] [pid 7221] [client 10.158.40.160:18019] AH01964: Connection to child 5 established (server 127.0.0.1:443) [Wed Dec 18 06:00:42.669547 2019] [socache_shmcb:debug] [pid 7221] mod_socache_shmcb.c(485): AH00831: socache_shmcb_store (0x17 -> subcache 23) [Wed Dec 18 06:00:42.669617 2019] [socache_shmcb:debug] [pid 7221] mod_socache_shmcb.c(810): AH00847: insert happened at idx=1, data=(180:212) [Wed Dec 18 06:00:42.669632 2019] [socache_shmcb:debug] [pid 7221] mod_socache_shmcb.c(815): AH00848: finished insert, subcache: idx_pos/idx_used=0/2, data_pos/data_used=0/360 [Wed Dec 18 06:00:42.669644 2019] [socache_shmcb:debug] [pid 7221] mod_socache_shmcb.c(506): AH00834: leaving socache_shmcb_store successfully [Wed Dec 18 06:00:42.669674 2019] [ssl:debug] [pid 7221] ssl_engine_kernel.c(1823): [client 10.158.40.160:18019] AH02041: Protocol: TLSv1.2, Cipher: ECDHE-RSA-AES256-SHA384 (256/256 bits) [Wed Dec 18 06:00:42.671106 2019] [ssl:debug] [pid 7221] ssl_engine_kernel.c(225): [client 10.158.40.160:18019] AH02034: Initial (No.1) HTTPS request received for child 5 (server 127.0.0.1:443) [Wed Dec 18 06:00:42.671224 2019] [authz_core:debug] [pid 7221] mod_authz_core.c(809): [client 10.158.40.160:18019] AH01626: authorization result of Require all granted: granted [Wed Dec 18 06:00:42.671246 2019] [authz_core:debug] [pid 7221] mod_authz_core.c(809): [client 10.158.40.160:18019] AH01626: authorization result of <RequireAny>: granted [Wed Dec 18 06:00:42.671394 2019] [proxy:debug] [pid 7221] mod_proxy.c(1123): [client 10.158.40.160:18019] AH01143: Running scheme http handler (attempt 0) [Wed Dec 18 06:00:42.671416 2019] [proxy_ajp:debug] [pid 7221] mod_proxy_ajp.c(722): [client 10.158.40.160:18019] AH00894: declining URL http://127.0.0.1:8080/emsapi/services/PSXAPI/r11_02_00 [Wed Dec 18 06:00:42.671430 2019] [proxy_fcgi:debug] [pid 7221] mod_proxy_fcgi.c(972): [client 10.158.40.160:18019] AH01076: url: http://127.0.0.1:8080/emsapi/services/PSXAPI/r11_02_00 proxyname: (null) proxyport: 0 [Wed Dec 18 06:00:42.671443 2019] [proxy_fcgi:debug] [pid 7221] mod_proxy_fcgi.c(975): [client 10.158.40.160:18019] AH01077: declining URL http://127.0.0.1:8080/emsapi/services/PSXAPI/r11_02_00 [Wed Dec 18 06:00:42.671459 2019] [proxy:debug] [pid 7221] proxy_util.c(2203): AH00942: HTTP: has acquired connection for (127.0.0.1) [Wed Dec 18 06:00:42.671474 2019] [proxy:debug] [pid 7221] proxy_util.c(2256): [client 10.158.40.160:18019] AH00944: connecting http://127.0.0.1:8080/emsapi/services/PSXAPI/r11_02_00 to 127.0.0.1:8080 [Wed Dec 18 06:00:42.671490 2019] [proxy:debug] [pid 7221] proxy_util.c(2426): [client 10.158.40.160:18019] AH00947: connected /emsapi/services/PSXAPI/r11_02_00 to 127.0.0.1:8080 [Wed Dec 18 06:00:42.711384 2019] [proxy:error] [pid 7221] (104)Connection reset by peer: [client 10.158.40.160:18019] AH01084: pass request body failed to 127.0.0.1:8080 (127.0.0.1) [Wed Dec 18 06:00:42.711506 2019] [proxy_http:error] [pid 7221] [client 10.158.40.160:18019] AH01097: pass request body failed to 127.0.0.1:8080 (127.0.0.1) from 10.158.40.160 () [Wed Dec 18 06:00:42.711524 2019] [proxy:debug] [pid 7221] proxy_util.c(2218): AH00943: HTTP: has released connection for (127.0.0.1) [Wed Dec 18 06:00:42.711603 2019] [headers:debug] [pid 7221] mod_headers.c(848): AH01503: headers: ap_headers_error_filter() [Wed Dec 18 06:00:42.711858 2019] [ssl:debug] [pid 7221] ssl_engine_io.c(993): [client 10.158.40.160:18019] AH02001: Connection closed to child 5 with standard shutdown (server 127.0.0.1:443) ---- access.log ---------- 10.158.40.160 - - [18/Dec/2019:06:00:35 -0500] "POST /emsapi/services/PSXAPI/r11_02_00 HTTP/1.0" 200 411 "-" "Axis/1.2.1" 10.158.40.160 - - [18/Dec/2019:06:00:39 -0500] "POST /emsapi/services/PSXAPI/r11_02_00 HTTP/1.0" 200 411 "-" "Axis/1.2.1" 10.158.40.160 - - [18/Dec/2019:06:00:42 -0500] "POST /emsapi/services/PSXAPI/r11_02_00 HTTP/1.0" 502 232 "-" "Axis/1.2.1" 10.158.40.160 - - [18/Dec/2019:06:00:42 -0500] "POST /emsapi/services/PSXAPI/r11_02_00 HTTP/1.0" 200 411 "-" "Axis/1.2.1" 10.158.40.160 - - [18/Dec/2019:06:00:46 -0500] "POST /emsapi/services/PSXAPI/r11_02_00 HTTP/1.0" 502 232 "-" "Axis/1.2.1" ---------- ----------forensic log----------- +XfoLm3gDU6Xey4@YBCu9ewAAAAE|POST /emsapi/services/PSXAPI/r11_02_00 HTTP/1.0|Content-Type:text/xml; charset=utf-8|Accept:application/soap+xml, application/dime, multipart/related, text/*|User-Agent:Axis/1.2.1|Host:10.158.40.160|Cache-Control:no-cache|Pragma:no-cache|SOAPAction:""|Content-Length:24840 -XfoLm3gDU6Xey4@YBCu9ewAAAAE +XfoLm8UmmQmsBjdXxEDRoAAAAAM|POST /emsapi/services/PSXAPI/r11_02_00 HTTP/1.0|Content-Type:text/xml; charset=utf-8|Accept:application/soap+xml, application/dime, multipart/related, text/*|User-Agent:Axis/1.2.1|Host:10.158.40.160|Cache-Control:no-cache|Pragma:no-cache|SOAPAction:""|Content-Length:24840 -XfoLm8UmmQmsBjdXxEDRoAAAAAM +XfoLm-xhBLUf6fpMRbgDTQAAAAQ|POST /emsapi/services/PSXAPI/r11_02_00 HTTP/1.0|Content-Type:text/xml; charset=utf-8|Accept:application/soap+xml, application/dime, multipart/related, text/*|User-Agent:Axis/1.2.1|Host:10.158.40.160|Cache-Control:no-cache|Pragma:no-cache|SOAPAction:""|Content-Length:24840 -XfoLm-xhBLUf6fpMRbgDTQAAAAQ +XfoLnq5pgZp-8qrPbGo@tQAAAAA|POST /emsapi/services/PSXAPI/r11_02_00 HTTP/1.0|Content-Type:text/xml; charset=utf-8|Accept:application/soap+xml, application/dime, multipart/related, text/*|User-Agent:Axis/1.2.1|Host:10.158.40.160|Cache-Control:no-cache|Pragma:no-cache|SOAPAction:""|Content-Length:24840 -XfoLnq5pgZp-8qrPbGo@tQAAAAA --------------------------------- -- You are receiving this mail because: You are the assignee for the bug. --------------------------------------------------------------------- To unsubscribe, e-mail: bugs-unsubscr...@httpd.apache.org For additional commands, e-mail: bugs-h...@httpd.apache.org