Exception being swallowed on access token error

[MinniArora]

Hi

We have come across an issue. A working set up on dev suddenly stopped working one day with the error below:

Access Token Error: null

No stack trace was printed. After building gateway from source and printing trace in KeycloakOAuthFactory, this is what we got:

java.lang.NullPointerException at io.apiman.gateway.platforms.vertx3.api.auth.KeycloakOAuthFactory$1.lambda$null$0(KeycloakOAuthFactory.java:121) at io.vertx.ext.auth.AbstractUser.lambda$isAuthorised$0(AbstractUser.java:53) at io.vertx.ext.auth.oauth2.impl.AccessTokenImpl.doIsPermitted(AccessTokenImpl.java:346) at io.vertx.ext.auth.AbstractUser.isAuthorised(AbstractUser.java:47) at io.apiman.gateway.platforms.vertx3.api.auth.KeycloakOAuthFactory$1.lambda$doBasic2Oauth$1(KeycloakOAuthFactory.java:117) at io.vertx.ext.auth.oauth2.impl.flow.PasswordImpl.lambda$getToken$0(PasswordImpl.java:61) at io.vertx.ext.auth.oauth2.impl.OAuth2API.handleToken(OAuth2API.java:267) at io.vertx.ext.auth.oauth2.impl.OAuth2API.lambda$null$1(OAuth2API.java:217) at io.vertx.core.http.impl.HttpClientResponseImpl$BodyHandler.notifyHandler(HttpClientResponseImpl.java:301) at io.vertx.core.http.impl.HttpClientResponseImpl.lambda$bodyHandler$0(HttpClientResponseImpl.java:193) at io.vertx.core.http.impl.HttpClientResponseImpl.handleEnd(HttpClientResponseImpl.java:257) at io.vertx.core.http.impl.ClientConnection.handleResponseEnd(ClientConnection.java:361) at io.vertx.core.http.impl.ClientHandler.doMessageReceived(ClientHandler.java:80) at io.vertx.core.http.impl.ClientHandler.doMessageReceived(ClientHandler.java:38) at io.vertx.core.http.impl.VertxHttpHandler.lambda$channelRead$0(VertxHttpHandler.java:71) at io.vertx.core.impl.ContextImpl.lambda$wrapTask$2(ContextImpl.java:335) at io.vertx.core.impl.ContextImpl.executeFromIO(ContextImpl.java:193) at io.vertx.core.http.impl.VertxHttpHandler.channelRead(VertxHttpHandler.java:71) at io.vertx.core.net.impl.VertxHandler.channelRead(VertxHandler.java:122) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:349) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:341) at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:435) at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:293) at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:267) at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:250) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:349) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:341) at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1334) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:349) at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:926) at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:129) at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:642) at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:565) at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:479) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:441) at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858) at java.lang.Thread.run(Thread.java:748)

Checking further, we saw that call to isAuthorised returned Future{cause=Expired Token} which caused NullPointerException

But we are unable to figure out reason behind expired token. Setting up gateway on laptop works fine.

[msavy]

Thanks for your report. It seems this error is being swallowed somehow when it should not be.

Which version of Apiman are you using that sees this error? I guess the print-lines you added have offset the stack trace a bit.

./apiman-gateway.sh --version

I've seen token expiry issues occur before when the time/date goes out of sync between the machine Keycloak is running on versus the machine Apiman is running on. I suggest having chronyd or similar NTP solution running.

Regards,
Marc

[MinniArora]

Thanks for the response. Initially it appeared to be a clock sync issue to us too, and, in-fact the clocks were not in sync.

But even after bringing them in sync and verifying ntpdate, hwclock, date, the issue remains.

Apiman versions tried:
./apiman-gateway.sh --version
[INFO ] 2018-07-10 17:19:15.031 [main] ApimanVersionCommand - Apiman 1.4.1.Final
[INFO ] 2018-07-10 17:19:15.037 [main] ApimanVersionCommand - Vert.x 3.4.2

./apiman-gateway.sh -version
[INFO ] 2018-07-10 17:20:28.155 [main] ApimanVersionCommand - Apiman 1.3.1.Final
[INFO ] 2018-07-10 17:20:28.161 [main] ApimanVersionCommand - Vert.x 3.4.0

[msavy]

Would you mind sharing the version of the code with tracing in it. It'll make it easier for me to follow your stack traces.

Perhaps throw it into a branch somewhere and share it with me.

[MinniArora]

Hi

The issue is resolved. We pointed it to a new elastic instance and the issue got resolved. Could it be that some entries in elastic had got corrupted.

[msavy]

Thanks for sharing the outcome, @MinniArora. It'd still be good to have your version with the debugging included so I can see where the swallowed exception came from -- so I can ensure it behaves better if this issue recurs.

[MinniArora]

Sure. It was just doBasic2Oauth from KeycloakOAuthFactory. Attached.

apiman-issue.tar.gz