Mailing List Archive

[Bug 64016] New: Apache HTTPD intermittently report errors AH01084 and AH01097 with 502
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: spallai@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-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org