AbstractResponseListener.onError(HTTPResponse@3068428d, eof unexpected)

We are seeing intermittently below exception in PROD having on-prem 5-node architecture installation. Here are the Message Processor logs and please help me and suggest.

2018-09-25 07:19:03,802 org:abcdef env:prod api:rsapassthrough rev:1 messageid:abcdef-99036-2181790-1 NIOThread@1 ERROR HTTP.CLIENT - HTTPClient$Context$3.onException() : SSLClientChannel[C:23.101.157.243:443 Remote host:1.2.3.4:44562]@591217 useCount=7 bytesRead=0 bytesWritten=3069 age=35103ms lastIO=20ms lastIO=20ms isOpen=true.onExceptionRead exception: {} java.io.EOFException: eof unexpected at com.apigee.nio.channels.PatternInputChannel.doRead(PatternInputChannel.java:45) ~[nio-1.0.0.jar:na] at com.apigee.nio.channels.InputChannel.read(InputChannel.java:103) ~[nio-1.0.0.jar:na] at com.apigee.protocol.http.io.MessageReader.onRead(MessageReader.java:79) ~[http-1.0.0.jar:na] at com.apigee.nio.channels.DefaultNIOSupport$DefaultIOChannelHandler.onIO(NIOSupport.java:51) [nio-1.0.0.jar:na] at com.apigee.nio.handlers.NIOThread.run(NIOThread.java:164) [nio-1.0.0.jar:na] 2018-09-25 07:19:03,802 org:abcdef env:prod api:rsapassthrough rev:1 messageid:abcdef-99036-2181790-1 NIOThread@1 INFO HTTP.CLIENT - HTTPClient$Context.logContextDetails() : Request details : host=abcdef path=/AdaptiveAuthentication/services/AdaptiveAuthentication method=POST. Channel details : Bytes read=0 2018-09-25 07:19:03,802 org:abcdef env:prod api:rsapassthrough rev:1 messageid:abcdef-99036-2181790-1 NIOThread@1 ERROR ADAPTORS.HTTP.FLOW - AbstractResponseListener.onException() : AbstractResponseListener.onError(HTTPResponse@3068428d, eof unexpected) 2018-09-25 07:22:25,304 Apigee-Timer-2 INFO METRICSLOGGING - MetricsLogger.log() : Release id 171117_01 RPM apigee-rpm-1.0.0.1478.8984e84.1801291806-171117_01 CACHE.total [numHits=19290968 hitRate=99 elementsInMem=274 queue_remaining=500 memUsed=238955 averageElementSize=872] NIO.0.selectors [connected=22497 maxOpenCount=3 timeouts=1078 currentServers=2 maximumConnectionsOpened=8 pooledConnectionClose=4680 accepted=1526 closeSuccessful=24024] NIO.1.selectors [currentAccepted=7 pooledConnectionClose=4371 connected=102688 maximumConnectionsOpened=29 currentPoolSize=2 currentConnected=2 closeSuccessful=127026 accepted=24345 maxOpenCount=9 currentServers=2 timeouts=16087] NIO.2.selectors [maximumConnectionsOpened=10 timeouts=2014 pooledConnectionClose=7399 maxOpenCount=3 connected=42667 currentServers=2 closeSuccessful=45615 accepted=2945] NIO.3.selectors [maxOpenCount=3 pooledConnectionClose=5370 timeouts=1135 connected=28013 accepted=1851 maximumConnectionsOpened=9 closeSuccessful=29865 currentServers=2] NIO.4.selectors [connected=81100 timeouts=5115 maxOpenCount=6 accepted=6804 maximumConnectionsOpened=16 currentServers=2 pooledConnectionClose=9807 currentPoolSize=1 currentAccepted=1 closeSuccessful=87910 currentConnected=1] NIO.5.selectors [currentServers=2 connected=45099 maxOpenCount=4 accepted=3524 maximumConnectionsOpened=12 timeouts=2506 pooledConnectionClose=8043 closeSuccessful=48628] NIO.6.selectors [maximumConnectionsOpened=25 pooledConnectionClose=6554 closeSuccessful=125941 currentPoolSize=2 currentConnected=2 maxOpenCount=8 currentServers=2 currentAccepted=7 timeouts=11268 connected=109496 accepted=16446] NIO.7.selectors [currentServers=2 currentConnected=2 currentPoolSize=2 closeSuccessful=102228 timeouts=6177 maximumConnectionsOpened=18 maxOpenCount=6 currentAccepted=5 connected=93480 accepted=8750 pooledConnectionClose=9525] NIO.total [currentPoolSize=7 accepted=66191 closeSuccessful=591237 timeouts=45380 maxOpenCount=20 currentServers=2 connected=525040 currentAccepted=20 currentConnected=7 pooledConnectionClose=55749 maximumConnectionsOpened=127] THREADPOOL.Main.statistics [completedTaskCount=10890734 largestPoolSize=10 activeThreadCount=1 corePoolSize=10 currentPoolSize=10 maxAllowedPoolSize=100] THREADPOOL.Timer.statistics [corePoolSize=10 activeThreadCount=1 maxAllowedPoolSize=2147483647 largestPoolSize=10 currentPoolSize=10 completedTaskCount=3377916] ZOOKEEPER.configuration [connectInfo=State:CONNECTED Timeout:40000 sessionid:0x1659508bd040001 local:/1.2.3.4:54990 remoteserver:1.2.3.4/1.2.3.4:2181 lastZxid:77309411423 xid:769033 sent:906661 recv:906662 queuedpkts:0 pendingresp:0 queuedevents:0] ZOOKEEPER.counters [successfulOperations=768963 operations=768974] ZOOKEEPER.operations [exists=533368 create=1 getData=193894 getChildren=41654 setData=57] ZOOKEEPER.pathWatcher [create=29 add=39] ZOOKEEPER.statistics [operations=768963]

Solved Solved
0 5 1,427
1 ACCEPTED SOLUTION

The most informative information in the snip of log you provided is


2018-09-25 07:19:03,802 org:abcdef env:prod api:rsapassthrough rev:1 messageid:abcdef-99036-2181790-1 NIOThread@1 ERROR HTTP.CLIENT - HTTPClient$Context$3.onException() : SSLClientChannel[C:23.101.157.243:443 Remote host:1.2.3.4:44562]@591217 useCount=7 bytesRead=0 bytesWritten=3069 age=35103ms lastIO=20ms lastIO=20ms isOpen=true.onExceptionRead exception: {}


java.io.EOFException: eof unexpected
 at com.apigee.nio.channels.PatternInputChannel.doRead(PatternInputChannel.java:45) ~[nio-1.0.0.jar:na]
 at com.apigee.nio.channels.InputChannel.read(InputChannel.java:103) ~[nio-1.0.0.jar:na]
 at com.apigee.protocol.http.io.MessageReader.onRead(MessageReader.java:79) ~[http-1.0.0.jar:na]
 at com.apigee.nio.channels.DefaultNIOSupport$DefaultIOChannelHandler.onIO(NIOSupport.java:51) [nio-1.0.0.jar:na]
 at com.apigee.nio.handlers.NIOThread.run(NIOThread.java:164) [nio-1.0.0.jar:na]


2018-09-25 07:19:03,802 org:abcdef env:prod api:rsapassthrough rev:1 messageid:abcdef-99036-2181790-1 NIOThread@1 INFO HTTP.CLIENT - HTTPClient$Context.logContextDetails() : Request details : host=abcdef path=/AdaptiveAuthentication/services/AdaptiveAuthentication method=POST. Channel details : Bytes read=0


2018-09-25 07:19:03,802 org:abcdef env:prod api:rsapassthrough rev:1 messageid:abcdef-99036-2181790-1 NIOThread@1 ERROR ADAPTORS.HTTP.FLOW - AbstractResponseListener.onException() : AbstractResponseListener.onError(HTTPResponse@3068428d, eof unexpected)


What that tells me is: The Apigee Edge MP is trying to read a response, and is getting nothing. It has bytesRead=0, which means no response at all.

The "other end", aka upstream, aka target server, is not sending a response.

This symptom, this log message, does not indicate a problem in the Apigee Edge MP. If the other end hangs up immediately upon receiving an inbound request, the error logged in the MP log is what we would expect to see. This might happen if there is an error in the request handling code on the backend service. Apigee Edge is just logging the event.

To diagnose this you need to correlate the exceptions seen at the MP with the handling service at the backend.

Look into this endpoint on the backend:

host=abcdef path=/AdaptiveAuthentication/services/AdaptiveAuthentication method=POST

It's curious that the error has occurred at age=35103ms .

Do the other exceptions also timeout at 35s? Do you have a timeout set somewhere in your system to be 35s ? A timeout enforced by Apigee Edge would result in a different error message - it would explicitly state that the connection has timed out. This is not what is happening in your case.

In your case Apigee Edge is trying to read the response and is getting no response. No bytes. It's possible, and seems more likely, that the remote end has timed out at 35s and just didn't respond. This is especially likely if you find the other messages in the MP log all indicate an age of just over 35s.

View solution in original post

5 REPLIES 5

Please contact Apigee Support with such questions.

The most informative information in the snip of log you provided is


2018-09-25 07:19:03,802 org:abcdef env:prod api:rsapassthrough rev:1 messageid:abcdef-99036-2181790-1 NIOThread@1 ERROR HTTP.CLIENT - HTTPClient$Context$3.onException() : SSLClientChannel[C:23.101.157.243:443 Remote host:1.2.3.4:44562]@591217 useCount=7 bytesRead=0 bytesWritten=3069 age=35103ms lastIO=20ms lastIO=20ms isOpen=true.onExceptionRead exception: {}


java.io.EOFException: eof unexpected
 at com.apigee.nio.channels.PatternInputChannel.doRead(PatternInputChannel.java:45) ~[nio-1.0.0.jar:na]
 at com.apigee.nio.channels.InputChannel.read(InputChannel.java:103) ~[nio-1.0.0.jar:na]
 at com.apigee.protocol.http.io.MessageReader.onRead(MessageReader.java:79) ~[http-1.0.0.jar:na]
 at com.apigee.nio.channels.DefaultNIOSupport$DefaultIOChannelHandler.onIO(NIOSupport.java:51) [nio-1.0.0.jar:na]
 at com.apigee.nio.handlers.NIOThread.run(NIOThread.java:164) [nio-1.0.0.jar:na]


2018-09-25 07:19:03,802 org:abcdef env:prod api:rsapassthrough rev:1 messageid:abcdef-99036-2181790-1 NIOThread@1 INFO HTTP.CLIENT - HTTPClient$Context.logContextDetails() : Request details : host=abcdef path=/AdaptiveAuthentication/services/AdaptiveAuthentication method=POST. Channel details : Bytes read=0


2018-09-25 07:19:03,802 org:abcdef env:prod api:rsapassthrough rev:1 messageid:abcdef-99036-2181790-1 NIOThread@1 ERROR ADAPTORS.HTTP.FLOW - AbstractResponseListener.onException() : AbstractResponseListener.onError(HTTPResponse@3068428d, eof unexpected)


What that tells me is: The Apigee Edge MP is trying to read a response, and is getting nothing. It has bytesRead=0, which means no response at all.

The "other end", aka upstream, aka target server, is not sending a response.

This symptom, this log message, does not indicate a problem in the Apigee Edge MP. If the other end hangs up immediately upon receiving an inbound request, the error logged in the MP log is what we would expect to see. This might happen if there is an error in the request handling code on the backend service. Apigee Edge is just logging the event.

To diagnose this you need to correlate the exceptions seen at the MP with the handling service at the backend.

Look into this endpoint on the backend:

host=abcdef path=/AdaptiveAuthentication/services/AdaptiveAuthentication method=POST

It's curious that the error has occurred at age=35103ms .

Do the other exceptions also timeout at 35s? Do you have a timeout set somewhere in your system to be 35s ? A timeout enforced by Apigee Edge would result in a different error message - it would explicitly state that the connection has timed out. This is not what is happening in your case.

In your case Apigee Edge is trying to read the response and is getting no response. No bytes. It's possible, and seems more likely, that the remote end has timed out at 35s and just didn't respond. This is especially likely if you find the other messages in the MP log all indicate an age of just over 35s.

@Dino-at-Google we haven't set any timeouts and using the default settings, however, I can see the other exception messages at age= 18200ms/18661ms/20515ms... with same error message - AbstractResponseListener.onError(HTTPResponse@3068428d, eof unexpected)

OK, that tells us that it's not a 35s fixed timeout.

In that case, maybe there is a bug in the backend system that is causing exceptions, crashes, or hangups at varying intervals on the "upstream" (aka remote from the point of view of Apigee Edge) system.

It will be interesting to examine the logs for the backend system that correlate to these MP messages.

 Hi @dchiesa1

i am having the same issue. Below is my log. Can i have any help on this.

 

2021-10-15 21:21:55,763 Apigee-Timer-2 INFO SenseService - SenseServiceImpl.lambda$getUpdateTask$1() : Updating the sense bot map data for these Scopes [ServerScope{organization='mhg', environment='dev'}, ServerScope{organization='mhg', environment='test'}, ServerScope{organization='mhg', environment='stage'}, ServerScope{organization='mhg', environment='training'}, ServerScope{organization='VALIDATE', environment='test'}]
2021-10-15 21:22:13,533 org:mhg env:dev api:hulknewproxy2 rev:5 messageid:mhg-apigee-dev-01-amhgtb.noalocal-3726-3966332-1 NIOThread@2 ERROR HTTP.CLIENT - HTTPClient$Context$3.onException() : SSLClientChannel[Connected: Remote:10.90.0.17:9603 Local:10.1.2.3:35005]@808173 useCount=1 bytesRead=0 bytesWritten=802 age=424ms lastIO=0ms isOpen=true.onExceptionRead exception: {}
com.apigee.errors.http.server.BadGateway: Header origin,content-type,accept,authorization,userid,branch,source,password,msgid,x-requested-with contains invalid character ,
at com.apigee.protocol.http.msg.HTTPHeaders.validateName(HTTPHeaders.java:762)
at com.apigee.protocol.http.msg.HTTPHeaders.addNormalizedValue(HTTPHeaders.java:328)
at com.apigee.protocol.http.msg.HTTPHeaders.addWithValidation(HTTPHeaders.java:695)
at com.apigee.protocol.http.msg.HTTPHeaders.load(HTTPHeaders.java:624)
at com.apigee.protocol.http.io.MessageReader.onRead(MessageReader.java:124)
at com.apigee.nio.channels.DefaultNIOSupport$DefaultIOChannelHandler.onIO(NIOSupport.java:51)
at com.apigee.nio.handlers.NIOThread.run(NIOThread.java:220)
2021-10-15 21:22:13,533 org:mhg env:dev api:hulknewproxy2 rev:5 messageid:mhg-apigee-dev-01-amhgtb.noalocal-3726-3966332-1 NIOThread@2 INFO HTTP.CLIENT - HTTPClient$Context.logContextDetails() : Request details : host=null path=/FCAccountService/FCAccount/CreateAcc/ method=POST. Channel details : Bytes read=0
2021-10-15 21:22:13,533 org:mhg env:dev api:hulknewproxy2 rev:5 messageid:mhg-apigee-dev-01-amhgtb.noalocal-3726-3966332-1 NIOThread@2 ERROR ADAPTORS.HTTP.FLOW - AbstractResponseListener.onException() : AbstractResponseListener.onError(HTTPResponse@5b10647a, Header origin,content-type,accept,authorization,userid,branch,source,password,msgid,x-requested-with contains invalid character ,)

Thanks,

Mahesh