You are viewing a plain text version of this content. The canonical link for it is here.
Posted to bugs@httpd.apache.org by bu...@apache.org on 2022/02/03 16:33:16 UTC
[Bug 65867] New: Apache is delaying response on Reader.cpp
https://bz.apache.org/bugzilla/show_bug.cgi?id=65867
Bug ID: 65867
Summary: Apache is delaying response on Reader.cpp
Product: Apache httpd-2
Version: 2.4.52
Hardware: Other
OS: Linux
Status: NEW
Severity: critical
Priority: P2
Component: All
Assignee: bugs@httpd.apache.org
Reporter: danimart@amdocs.com
Target Milestone: ---
We are facing an issue on our apaches, we are using the Weblogic Plugin for
12.1.3 version and we have upgraded our Apache to version 2.4.52. The main
issue is with calls getting “stuck/hold” in Apache for around 30 secs before it
sends the response to the originator of the call. The strange issue is that on
the logs you will see we receive a response 204 within 1 second but then after
that Apache is holding for around 30 secs. Can someone please advise what can
be causing this issue? Let me know if you need full httpd.conf file
*** httpd.conf ***
<Location /qos>
SetHandler qos-viewer
</Location>
<Location "/server-status">
SetHandler server-status
Require all denied
Require host localhost
</Location>
ExtendedStatus On
Include conf/qos.conf
KeepAlive Off
<VirtualHost *:5400>
<IfModule mod_weblogic.c>
WebLogicCluster 135.208.79.127:8001,135.208.79.127:8002
Include conf/Match-URLs.conf
WLTempDir /opt/app/logs/apache/
#DebugConfigInfo On
DebugConfigInfo Off
DynamicServerList OFF
KeepAliveEnabled OFF
#FileCaching ON
</IfModule>
</VirtualHost>
#Paramter to allow encoded slashes in request URL
AllowEncodedSlashes On
TraceEnable off
Header unset ETag
FileETag None
#ServerTokens Prod
ServerSignature Off
ErrorDocument 403 /index.html
*** APACHE LOGS ***
[Mon Jan 31 15:19:37.128591 2022] [weblogic:debug] [pid 31971:tid
140576078894848] ApacheProxy.cpp(841): [client 135.208.75.102:42698]
<3197116436639772> ================New Request: [POST
/ATTMx/OSB/SetNextOriginalInvoiceInfo HTTP/1.1] =================
[Mon Jan 31 15:19:37.128643 2022] [weblogic:debug] [pid 31971:tid
140576078894848] ApacheProxy.cpp(997): [client 135.208.75.102:42698]
<3197116436639772> Using Uri /ATTMx/OSB/SetNextOriginalInvoiceInfo
[Mon Jan 31 15:19:37.128671 2022] [weblogic:debug] [pid 31971:tid
140576078894848] ApacheProxy.cpp(1017): [client 135.208.75.102:42698]
<3197116436639772> After trimming path: '/ATTMx/OSB/SetNextOriginalInvoiceInfo'
[Mon Jan 31 15:19:37.128681 2022] [weblogic:debug] [pid 31971:tid
140576078894848] ApacheProxy.cpp(1093): [client 135.208.75.102:42698]
<3197116436639772> The final request string is
'/ATTMx/OSB/SetNextOriginalInvoiceInfo'
[Mon Jan 31 15:19:37.128719 2022] [weblogic:debug] [pid 31971:tid
140576078894848] BaseProxy.cpp(1936): [client 135.208.75.102:42698]
<3197116436639772> parseServerList: Socket Address hostnames
'135.208.79.127:8001,135.208.79.127:8002'
[Mon Jan 31 15:19:37.128739 2022] [weblogic:debug] [pid 31971:tid
140576078894848] BaseProxy.cpp(2002): [client 135.208.75.102:42698]
<3197116436639772> Host extracted from serverlist is [135.208.79.127]
[Mon Jan 31 15:19:37.128836 2022] [weblogic:debug] [pid 31971:tid
140576078894848] BaseProxy.cpp(2053): [client 135.208.75.102:42698]
<3197116436639772> parseServerList: trying IP addr 135.208.79.127
[Mon Jan 31 15:19:37.129073 2022] [weblogic:debug] [pid 31971:tid
140576078894848] BaseProxy.cpp(2089): [client 135.208.75.102:42698]
<3197116436639772> parseServerList: socket and connect succeeded
[Mon Jan 31 15:19:37.129121 2022] [weblogic:debug] [pid 31971:tid
140576078894848] BaseProxy.cpp(2110): [client 135.208.75.102:42698]
<3197116436639772> parseServerList: IP from socket Address [135.208.79.127]
[Mon Jan 31 15:19:37.129137 2022] [weblogic:debug] [pid 31971:tid
140576078894848] BaseProxy.cpp(2002): [client 135.208.75.102:42698]
<3197116436639772> Host extracted from serverlist is [135.208.79.127]
[Mon Jan 31 15:19:37.129165 2022] [weblogic:debug] [pid 31971:tid
140576078894848] BaseProxy.cpp(2053): [client 135.208.75.102:42698]
<3197116436639772> parseServerList: trying IP addr 135.208.79.127
[Mon Jan 31 15:19:37.129311 2022] [weblogic:debug] [pid 31971:tid
140576078894848] BaseProxy.cpp(2089): [client 135.208.75.102:42698]
<3197116436639772> parseServerList: socket and connect succeeded
[Mon Jan 31 15:19:37.129381 2022] [weblogic:debug] [pid 31971:tid
140576078894848] BaseProxy.cpp(2110): [client 135.208.75.102:42698]
<3197116436639772> parseServerList: IP from socket Address [135.208.79.127]
[Mon Jan 31 15:19:37.129431 2022] [weblogic:debug] [pid 31971:tid
140576078894848] BaseProxy.cpp(3028): [client 135.208.75.102:42698]
<3197116436639772> Initializing lastIndex=1 for a list of length=2
[Mon Jan 31 15:19:37.129459 2022] [weblogic:debug] [pid 31971:tid
140576078894848] BaseProxy.cpp(525): [client 135.208.75.102:42698]
<3197116436639772> getListNode: created a new server node:
id='135.208.79.127:8001,135.208.79.127:8002' server_name='135.208.79.129',
port='5400'
[Mon Jan 31 15:19:37.129495 2022] [weblogic:debug] [pid 31971:tid
140576078894848] ap_proxy.cpp(418): [client 135.208.75.102:42698]
<3197116436639772> Going to get the post data of size=292 clength=0
[Mon Jan 31 15:19:37.129584 2022] [weblogic:debug] [pid 31971:tid
140576078894848] ap_proxy.cpp(512): [client 135.208.75.102:42698]
<3197116436639772> attempt #0 out of a max of 5
[Mon Jan 31 15:19:37.129617 2022] [weblogic:debug] [pid 31971:tid
140576078894848] ApacheProxy.cpp(2833): [client 135.208.75.102:42698]
<3197116436639772> returning EmulatorFlag = 0
[Mon Jan 31 15:19:37.129632 2022] [weblogic:debug] [pid 31971:tid
140576078894848] ApacheProxy.cpp(2485): [client 135.208.75.102:42698]
<3197116436639772> keepAlive = 0, canRecycle = 1
[Mon Jan 31 15:19:37.129646 2022] [weblogic:debug] [pid 31971:tid
140576078894848] ApacheProxy.cpp(2520): [client 135.208.75.102:42698]
<3197116436639772> general list: trying connect to '135.208.79.127'/8002/8002
at line 2520 for '/ATTMx/OSB/SetNextOriginalInvoiceInfo'
[Mon Jan 31 15:19:37.129879 2022] [weblogic:debug] [pid 31971:tid
140576078894848] URL.cpp(1785): [client 135.208.75.102:42698]
<3197116436639772> URL::Connect: Connected successfully
[Mon Jan 31 15:19:37.129906 2022] [weblogic:debug] [pid 31971:tid
140576078894848] URL.cpp(1824): [client 135.208.75.102:42698]
<3197116436639772> SSL is not configured for this connection
[Mon Jan 31 15:19:37.129935 2022] [weblogic:debug] [pid 31971:tid
140576078894848] URL.cpp(1844): [client 135.208.75.102:42698]
<3197116436639772> Local Port of the socket is 43370
[Mon Jan 31 15:19:37.129944 2022] [weblogic:debug] [pid 31971:tid
140576078894848] URL.cpp(1850): [client 135.208.75.102:42698]
<3197116436639772> Remote Host 135.208.79.127 Remote Port 43370
[Mon Jan 31 15:19:37.130004 2022] [weblogic:debug] [pid 31971:tid
140576078894848] ApacheProxy.cpp(2554): [client 135.208.75.102:42698]
<3197116436639772> general list: created a new connection to
'135.208.79.127'/8002 for '/ATTMx/OSB/SetNextOriginalInvoiceInfo', Local
port:43370
[Mon Jan 31 15:19:37.130024 2022] [weblogic:debug] [pid 31971:tid
140576078894848] BaseProxy.cpp(583): [client 135.208.75.102:42698]
<3197116436639772> Entering method BaseProxy::sendRequest
[Mon Jan 31 15:19:37.130037 2022] [weblogic:debug] [pid 31971:tid
140576078894848] BaseProxy.cpp(1234): [client 135.208.75.102:42698]
<3197116436639772> Entering method BaseProxy::parse_headers
[Mon Jan 31 15:19:37.130045 2022] [weblogic:debug] [pid 31971:tid
140576078894848] BaseProxy.cpp(1252): [client 135.208.75.102:42698]
<3197116436639772> No of headers =6
[Mon Jan 31 15:19:37.130070 2022] [weblogic:info] [pid 31971:tid
140576078894848] [client 135.208.75.102:42698] <3197116436639772> Header from
client:[User-Agent]=[curl/7.19.7 (x86_64-redhat-linux-gnu) libcurl/7.19.7
NSS/3.44 zlib/1.2.3 libidn/1.18 libssh2/1.4.2]
[Mon Jan 31 15:19:37.130088 2022] [weblogic:info] [pid 31971:tid
140576078894848] [client 135.208.75.102:42698] <3197116436639772> Header from
client:[Host]=[135.208.79.129:5400]
[Mon Jan 31 15:19:37.130098 2022] [weblogic:info] [pid 31971:tid
140576078894848] [client 135.208.75.102:42698] <3197116436639772> Header from
client:[Accept]=[*/*]
[Mon Jan 31 15:19:37.130106 2022] [weblogic:info] [pid 31971:tid
140576078894848] [client 135.208.75.102:42698] <3197116436639772> Header from
client:[Authorization]=[Basic cGxhYnVzZXI6cGxhYnVzZXJAMTIzNA==]
[Mon Jan 31 15:19:37.130115 2022] [weblogic:info] [pid 31971:tid
140576078894848] [client 135.208.75.102:42698] <3197116436639772> Header from
client:[Content-Type]=[application/json]
[Mon Jan 31 15:19:37.130124 2022] [weblogic:info] [pid 31971:tid
140576078894848] [client 135.208.75.102:42698] <3197116436639772> Header from
client:[Content-Length]=[292]
[Mon Jan 31 15:19:37.130142 2022] [weblogic:debug] [pid 31971:tid
140576078894848] BaseProxy.cpp(1428): [client 135.208.75.102:42698]
<3197116436639772> Exiting method BaseProxy::parse_headers
[Mon Jan 31 15:19:37.130151 2022] [weblogic:debug] [pid 31971:tid
140576078894848] BaseProxy.cpp(593): [client 135.208.75.102:42698]
<3197116436639772> parse_client_headers is done
[Mon Jan 31 15:19:37.130163 2022] [weblogic:debug] [pid 31971:tid
140576078894848] BaseProxy.cpp(697): [client 135.208.75.102:42698]
<3197116436639772> Method is POST
[Mon Jan 31 15:19:37.130173 2022] [weblogic:info] [pid 31971:tid
140576078894848] [client 135.208.75.102:42698] <3197116436639772>
URL::sendHeaders(): meth='POST' file='/ATTMx/OSB/SetNextOriginalInvoiceInfo'
protocol='HTTP/1.1'
[Mon Jan 31 15:19:37.130185 2022] [weblogic:info] [pid 31971:tid
140576078894848] [client 135.208.75.102:42698] <3197116436639772> Header to
WLS: [User-Agent]=[curl/7.19.7 (x86_64-redhat-linux-gnu) libcurl/7.19.7
NSS/3.44 zlib/1.2.3 libidn/1.18 libssh2/1.4.2]
[Mon Jan 31 15:19:37.130194 2022] [weblogic:info] [pid 31971:tid
140576078894848] [client 135.208.75.102:42698] <3197116436639772> Header to
WLS: [Host]=[135.208.79.129:5400]
[Mon Jan 31 15:19:37.130202 2022] [weblogic:info] [pid 31971:tid
140576078894848] [client 135.208.75.102:42698] <3197116436639772> Header to
WLS: [Accept]=[*/*]
[Mon Jan 31 15:19:37.130210 2022] [weblogic:info] [pid 31971:tid
140576078894848] [client 135.208.75.102:42698] <3197116436639772> Header to
WLS: [Authorization]=[Basic cGxhYnVzZXI6cGxhYnVzZXJAMTIzNA==]
[Mon Jan 31 15:19:37.130226 2022] [weblogic:info] [pid 31971:tid
140576078894848] [client 135.208.75.102:42698] <3197116436639772> Header to
WLS: [Content-Type]=[application/json]
[Mon Jan 31 15:19:37.130234 2022] [weblogic:info] [pid 31971:tid
140576078894848] [client 135.208.75.102:42698] <3197116436639772> Header to
WLS: [Content-Length]=[292]
[Mon Jan 31 15:19:37.130242 2022] [weblogic:info] [pid 31971:tid
140576078894848] [client 135.208.75.102:42698] <3197116436639772> Header to
WLS: [Connection]=[Keep-Alive]
[Mon Jan 31 15:19:37.130249 2022] [weblogic:info] [pid 31971:tid
140576078894848] [client 135.208.75.102:42698] <3197116436639772> Header to
WLS: [WL-Proxy-SSL]=[false]
[Mon Jan 31 15:19:37.130257 2022] [weblogic:info] [pid 31971:tid
140576078894848] [client 135.208.75.102:42698] <3197116436639772> Header to
WLS: [X-Forwarded-For]=[135.208.75.102]
[Mon Jan 31 15:19:37.130265 2022] [weblogic:info] [pid 31971:tid
140576078894848] [client 135.208.75.102:42698] <3197116436639772> Header to
WLS: [WL-Proxy-Client-IP]=[135.208.75.102]
[Mon Jan 31 15:19:37.130273 2022] [weblogic:info] [pid 31971:tid
140576078894848] [client 135.208.75.102:42698] <3197116436639772> Header to
WLS: [WL-Proxy-Client-Port]=[42698]
[Mon Jan 31 15:19:37.130281 2022] [weblogic:info] [pid 31971:tid
140576078894848] [client 135.208.75.102:42698] <3197116436639772> Header to
WLS: [X-WebLogic-Force-JVMID]=[unset]
[Mon Jan 31 15:19:37.130324 2022] [weblogic:debug] [pid 31971:tid
140576078894848] ApacheProxy.cpp(1302): [client 135.208.75.102:42698]
<3197116436639772> Post data length: 292 (in memory)
[Mon Jan 31 15:19:37.130355 2022] [weblogic:debug] [pid 31971:tid
140576078894848] BaseProxy.cpp(782): [client 135.208.75.102:42698]
<3197116436639772> About to call parseHeaders
[Mon Jan 31 15:19:37.130369 2022] [weblogic:debug] [pid 31971:tid
140576078894848] Reader.cpp(221): [client 135.208.75.102:42698]
<3197116436639772> Reader::fill(): first=0 last=0 toRead=4096
[Mon Jan 31 15:19:37.253219 2022] [weblogic:debug] [pid 31971:tid
140576078894848] Reader.cpp(270): [client 135.208.75.102:42698]
<3197116436639772> Reader::fill(): sysRecv returned 199
[Mon Jan 31 15:19:37.253276 2022] [weblogic:debug] [pid 31971:tid
140576078894848] URL.cpp(842): [client 135.208.75.102:42698] <3197116436639772>
URL::parseHeaders: CompleteStatusLine set to [HTTP/1.1 204 No Content]
[Mon Jan 31 15:19:37.253286 2022] [weblogic:debug] [pid 31971:tid
140576078894848] URL.cpp(844): [client 135.208.75.102:42698] <3197116436639772>
URL::parseHeaders: StatusLine set to [204 No Content]
[Mon Jan 31 15:19:37.253294 2022] [weblogic:debug] [pid 31971:tid
140576078894848] URL.cpp(852): [client 135.208.75.102:42698] <3197116436639772>
URL::parseHeaders: StatusLineWithoutStatusCode set to [No Content]
[Mon Jan 31 15:19:37.253305 2022] [weblogic:info] [pid 31971:tid
140576078894848] [client 135.208.75.102:42698] <3197116436639772> Header from
WLS:[Date]=[Mon, 31 Jan 2022 21:19:37 GMT]
[Mon Jan 31 15:19:37.253319 2022] [weblogic:info] [pid 31971:tid
140576078894848] [client 135.208.75.102:42698] <3197116436639772> Header from
WLS:[Content-Type]=[text/xml; charset=utf-8]
[Mon Jan 31 15:19:37.253329 2022] [weblogic:info] [pid 31971:tid
140576078894848] [client 135.208.75.102:42698] <3197116436639772> Header from
WLS:[X-ORACLE-DMS-ECID]=[c22e0fc2-2a97-4d29-a7f0-2b8428d25586-0006c8a7]
[Mon Jan 31 15:19:37.253338 2022] [weblogic:info] [pid 31971:tid
140576078894848] [client 135.208.75.102:42698] <3197116436639772> Header from
WLS:[X-WebLogic-JVMID]=[-230478877]
[Mon Jan 31 15:19:37.253347 2022] [weblogic:debug] [pid 31971:tid
140576078894848] URL.cpp(966): [client 135.208.75.102:42698] <3197116436639772>
parsed all headers OK
[Mon Jan 31 15:19:37.253356 2022] [weblogic:debug] [pid 31971:tid
140576078894848] BaseProxy.cpp(856): [client 135.208.75.102:42698]
<3197116436639772> Exiting method BaseProxy::sendRequest
[Mon Jan 31 15:19:37.253365 2022] [weblogic:debug] [pid 31971:tid
140576078894848] ApacheProxy.cpp(255): [client 135.208.75.102:42698]
<3197116436639772> sendResponse() : r->status = '204'
[Mon Jan 31 15:19:37.253398 2022] [weblogic:info] [pid 31971:tid
140576078894848] [client 135.208.75.102:42698] <3197116436639772> Hdrs to
client (add):[Date]=[Mon, 31 Jan 2022 21:19:37 GMT]
[Mon Jan 31 15:19:37.253409 2022] [weblogic:info] [pid 31971:tid
140576078894848] [client 135.208.75.102:42698] <3197116436639772> Hdrs to
client
(add):[X-ORACLE-DMS-ECID]=[c22e0fc2-2a97-4d29-a7f0-2b8428d25586-0006c8a7]
[Mon Jan 31 15:19:37.253421 2022] [weblogic:debug] [pid 31971:tid
140576078894848] BaseProxy.cpp(270): [client 135.208.75.102:42698]
<3197116436639772> for 135.208.79.127/8002/8002, updated JVMID: -230478877
[Mon Jan 31 15:19:37.253431 2022] [weblogic:debug] [pid 31971:tid
140576078894848] Reader.cpp(221): [client 135.208.75.102:42698]
<3197116436639772> Reader::fill(): first=0 last=0 toRead=4096
[Mon Jan 31 15:20:09.897864 2022] [weblogic:debug] [pid 31971:tid
140576078894848] Reader.cpp(270): [client 135.208.75.102:42698]
<3197116436639772> Reader::fill(): sysRecv returned 0
[Mon Jan 31 15:20:09.897927 2022] [weblogic:debug] [pid 31971:tid
140576078894848] ap_proxy.cpp(720): [client 135.208.75.102:42698]
<3197116436639772> calling closeConn() with non-null URL* at 720
[Mon Jan 31 15:20:09.897942 2022] [weblogic:debug] [pid 31971:tid
140576078894848] URL.cpp(1860): [client 135.208.75.102:42698]
<3197116436639772> canRecycle: conn=1 status=204 isKA=0 clen=-1 isCTE=0
[Mon Jan 31 15:20:09.897953 2022] [weblogic:debug] [pid 31971:tid
140576078894848] BaseProxy.cpp(3134): [client 135.208.75.102:42698]
<3197116436639772> closeConn: URL.canRecycle() returns false, deleting URL
'135.208.79.127/8002'
[Mon Jan 31 15:20:09.898021 2022] [weblogic:debug] [pid 31971:tid
140576078894848] ap_proxy.cpp(735): [client 135.208.75.102:42698]
<3197116436639772> request [/ATTMx/OSB/SetNextOriginalInvoiceInfo] processed
successfully..................
[Mon Jan 31 15:20:09.898760 2022] [weblogic:debug] [pid 31971:tid
140576078894848] ap_proxy.cpp(776): BEFORE acquire_lock
[Mon Jan 31 15:20:09.898779 2022] [weblogic:debug] [pid 31971:tid
140576078894848] ap_proxy.cpp(786): AFTER acquire_lock
[Mon Jan 31 15:20:09.898787 2022] [weblogic:debug] [pid 31971:tid
140576078894848] ap_proxy.cpp(789): List size is 1
[Mon Jan 31 15:20:09.898796 2022] [weblogic:debug] [pid 31971:tid
140576078894848] ap_proxy.cpp(796): Cleaning up the list node
'135.208.79.127:8001,135.208.79.127:8002'list Length '2''
--
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
[Bug 65867] Apache is delaying response on Reader.cpp
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=65867
Yann Ylavic <yl...@gmail.com> changed:
What |Removed |Added
----------------------------------------------------------------------------
Status|NEW |RESOLVED
Resolution|--- |INVALID
--- Comment #1 from Yann Ylavic <yl...@gmail.com> ---
There is zero log from upstream httpd, all from Weblogic module(s), you should
probably ask for support to Oracle.
--
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