Bug 64016 - Apache HTTPD intermittently report errors AH01084 and AH01097 with 502
Summary: Apache HTTPD intermittently report errors AH01084 and AH01097 with 502
Status: NEW
Alias: None
Product: Apache httpd-2
Classification: Unclassified
Component: All (show other bugs)
Version: 2.4.6
Hardware: Other Linux
: P2 blocker (vote)
Target Milestone: ---
Assignee: Apache HTTPD Bugs Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-12-18 18:55 UTC by Sidharth
Modified: 2020-05-21 07:06 UTC (History)
1 user (show)



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Sidharth 2019-12-18 18:55:42 UTC
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

---------------------------------
Comment 1 Sidharth 2019-12-18 19:00:10 UTC
Errors as below:

[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 ()
Comment 2 Michael Osipov 2020-05-20 19:29:52 UTC
Here is another in-detail description of the issue: https://www.mail-archive.com/users@tomcat.apache.org/msg135207.html