Router Logs

Report Inappropriate Content · 09-15-2015 03:07 PM

Hi,

On my on-prem apigee installation (5-node, 4.15.04.00) I am seeing the following error message thousands and thousands of times on the Router. The only thing that changes is the end of the Message ID (besides timestamps).

2015-09-15 17:20:13,801 Router-ClientThread-0-2 ERROR Proxy-session - RouterProxySession$ClientContext.onException() : Session Id: RouterProxy-4-427912 Message Id: hostname.com_BT4n3kmA_RouterProxy-4-427912_1 Exception on MP channel null 2015-09-15 17:20:13,802 Router-ClientThread-0-2 ERROR Proxy-session - RouterProxySession$ClientContext.onException() : Exception Cause java.lang.NullPointerException: null

I have also attached a log portion with the debug feature enabled on the router. (which I edited out IP addresses and hostnames, but they are always to the same machine). It seems to have started after a production stress test was run

Please let me know if you have any suggestions, I figure it has something to do with the MP, but I don't know what. BTW, these occur when no API requests are being made.

Thanks,

Ryan

adas

@rj.walsh The router periodically sends heartbeat requests to the message processor over RPC to check the health of the message-processors. This usually happens over port 4526 unless you have changed that in the config. From your logs, I see the below error:

2015-09-15 17:26:55,890  RPCClientClientProtocolChildGroup-RPC-0 DEBUG RPC - ClientHandleImpl.sendHandshake() : Connection failed to [[id: 0x97223aac], java.net.ConnectException: Connection refused: /XX.XXX.210.116:4528]: {}
java.net.ConnectException: Connection refused: /XX.XXX.210.116:4528

This suggest that you have changed the RPC port to be 4528. This is usually in the communication.properties file and the property is called rpc.port

Please make sure you actually intended to change this and didn't change it by mistake. If you happened to change it intentionally, you need to make sure that your router and message-processor are able to talk to each other on this port 4528 and its open. You can try to telnet from the router machine into the message-processor on this port and see if it works. If it doesn't then that's the problem. You can either change you firewall rules to open the port 4528 between instances or change it back to 4526 and make sure that works.

akashtp

Hello @arghya das I have seen another instance of a similar issue where all the Apigee Gateways were down for ~20 minutes and then autorecovered.

The below error was seen continuously during the downtime window. Can you please comment?

2015-10-03 18:18:13,309 org: env: Router-ServerThread-0 WARN  i.n.h.ssl.SslHandler - Slf4JLogger.warn() : SSLEngine.closeInbound() raised an exception due to closed connection.
javax.net.ssl.SSLException: Inbound closed before receiving peer's close_notify: possible truncation attack?
	at sun.security.ssl.Alerts.getSSLException(Alerts.java:208) ~[na:1.7.0_65]
	at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1619) ~[na:1.7.0_65]
	at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1587) ~[na:1.7.0_65]
	at sun.security.ssl.SSLEngineImpl.closeInbound(SSLEngineImpl.java:1517) ~[na:1.7.0_65]
	at io.netty.handler.ssl.SslHandler.setHandshakeFailure(SslHandler.java:975) [netty-all-4.0.0.CR1.jar:na]
	at io.netty.handler.ssl.SslHandler.channelInactive(SslHandler.java:646) [netty-all-4.0.0.CR1.jar:na]
	at io.netty.channel.DefaultChannelHandlerContext.invokeChannelInactive(DefaultChannelHandlerContext.java:752) [netty-all-4.0.0.CR1.jar:na]
	at io.netty.channel.DefaultChannelHandlerContext.fireChannelInactive(DefaultChannelHandlerContext.java:738) [netty-all-4.0.0.CR1.jar:na]
	at com.apigee.proxy.container.netty.GenericServerContainer$SessionStateHandler.channelInactive(GenericServerContainer.java:341) [message-router-api-1.0.0.jar:na]
	at io.netty.channel.DefaultChannelHandlerContext.invokeChannelInactive(DefaultChannelHandlerContext.java:752) [netty-all-4.0.0.CR1.jar:na]
	at io.netty.channel.DefaultChannelHandlerContext.access$1600(DefaultChannelHandlerContext.java:36) [netty-all-4.0.0.CR1.jar:na]
	at io.netty.channel.DefaultChannelHandlerContext$6.run(DefaultChannelHandlerContext.java:743) [netty-all-4.0.0.CR1.jar:na]
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:328) [netty-all-4.0.0.CR1.jar:na]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:331) [netty-all-4.0.0.CR1.jar:na]
	at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:109) [netty-all-4.0.0.CR1.jar:na]
	at java.lang.Thread.run(Thread.java:745) [na:1.7.0_65]
2015-10-03 18:18:13,309 org: env: Router-ClientThread-0-1 ERROR Proxy-session - RouterProxySession$ClientContext.onTimeout() : Message Id: abc.com_BT+GCNtY_RouterProxy-4-22864971_5 Session state: CLOSED MP channel null timed out
2015-10-03 18:18:13,309 org: env: Router-ClientThread-0-0 ERROR Proxy-session - RouterProxySession$ClientContext.onTimeout() : Message Id: abc.com_BT+GCNtY_RouterProxy-4-23582098_1 Session state: CLOSED MP channel null timed out
2015-10-03 18:18:13,311 org: env: Router-ClientThread-0-1 ERROR Proxy-session - RouterProxySession$ClientContext.onException() : Session Id: RouterProxy-4-22864971 Message Id: abc.com_BT+GCNtY_RouterProxy-4-22864971_5 Exception on MP channel null
2015-10-03 18:18:13,311 org: env: Router-ClientThread-0-0 ERROR Proxy-session - RouterProxySession$ClientContext.onException() : Session Id: RouterProxy-4-23582098 Message Id: abc.com_BT+GCNtY_RouterProxy-4-23582098_1 Exception on MP channel null
2015-10-03 18:18:13,311 org: env: Router-ClientThread-0-1 ERROR Proxy-session - RouterProxySession$ClientContext.onException() : Exception Cause
java.lang.NullPointerException: null

Report Inappropriate Content

Hi Argya Das,

Could you please help me to understand why i could see below error in router logs.

router Router-ClientThread-0-6 ERROR Proxy-session - RouterProxySession$ClientContext.onException() : Exception Cause java.lang.NullPointerException: null at com.apigee.proxy.router.http.RouterProxySession$ClientContext.onTimeout(RouterProxySession.java:838) ~[message-router-proxy-1.0.0.jar:na] at com.apigee.proxy.handlers.channel.ChannelStateHandler.userEventTriggered(ChannelStateHandler.java:88) ~[message-router-api-1.0.0.jar:na] at io.netty.channel.DefaultChannelHandlerContext.invokeUserEventTriggered(DefaultChannelHandlerContext.java:831) [netty-all-4.0.0.CR1.jar:na] at io.netty.channel.DefaultChannelHandlerContext.fireUserEventTriggered(DefaultChannelHandlerContext.java:815) [netty-all-4.0.0.CR1.jar:na] at io.netty.handler.timeout.IdleStateHandler.channelIdle(IdleStateHandler.java:366) [netty-all-4.0.0.CR1.jar:na] at io.netty.handler.timeout.IdleStateHandler$AllIdleTimeoutTask.run(IdleStateHandler.java:479) [netty-all-4.0.0.CR1.jar:na] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [na:1.7.0_75] at io.netty.util.concurrent.SingleThreadEventExecutor$ScheduledFutureTask.run(SingleThreadEventExecutor.java:799) [netty-all-4.0.0.CR1.jar:na] at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:328) [netty-all-4.0.0.CR1.jar:na] at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:331) [netty-all-4.0.0.CR1.jar:na] at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:109) [netty-all-4.0.0.CR1.jar:na] at java.lang.Thread.run(Thread.java:745) [na:1.7.0_75]

Thanks & Regards,

Ranganath P

Report Inappropriate Content

Hi Argya Das,

Could you please help me to understand why i could see below error in router logs.

router Router-ClientThread-0-6 ERROR Proxy-session - RouterProxySession$ClientContext.onException() : Exception Cause java.lang.NullPointerException: null at com.apigee.proxy.router.http.RouterProxySession$ClientContext.onTimeout(RouterProxySession.java:838) ~[message-router-proxy-1.0.0.jar:na] at com.apigee.proxy.handlers.channel.ChannelStateHandler.userEventTriggered(ChannelStateHandler.java:88) ~[message-router-api-1.0.0.jar:na] at io.netty.channel.DefaultChannelHandlerContext.invokeUserEventTriggered(DefaultChannelHandlerContext.java:831) [netty-all-4.0.0.CR1.jar:na] at io.netty.channel.DefaultChannelHandlerContext.fireUserEventTriggered(DefaultChannelHandlerContext.java:815) [netty-all-4.0.0.CR1.jar:na] at io.netty.handler.timeout.IdleStateHandler.channelIdle(IdleStateHandler.java:366) [netty-all-4.0.0.CR1.jar:na] at io.netty.handler.timeout.IdleStateHandler$AllIdleTimeoutTask.run(IdleStateHandler.java:479) [netty-all-4.0.0.CR1.jar:na] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [na:1.7.0_75] at io.netty.util.concurrent.SingleThreadEventExecutor$ScheduledFutureTask.run(SingleThreadEventExecutor.java:799) [netty-all-4.0.0.CR1.jar:na] at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:328) [netty-all-4.0.0.CR1.jar:na] at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:331) [netty-all-4.0.0.CR1.jar:na] at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:109) [netty-all-4.0.0.CR1.jar:na] at java.lang.Thread.run(Thread.java:745) [na:1.7.0_75]

Thanks & Regards,

Ranganath P