Spanner - Running Spanner on AppEngine SDK throws an NPE

[saturnism]

https://github.com/GoogleCloudPlatform/google-cloud-java/blob/master/google-cloud-spanner/src/main/java/com/google/cloud/spanner/SessionPool.java#L987

When using Spanner library in AppEngine Standard w/ Java 8 (alpha), createSession() ultimately throws an error, but was consumed and not propagated. Debugger shows a NullPointerException was thrown. However, because it wasn't propagated, the application thread was hung while waiting to take an available session:
https://github.com/GoogleCloudPlatform/google-cloud-java/blob/master/google-cloud-spanner/src/main/java/com/google/cloud/spanner/SessionPool.java#L697

Expected behavior - if connection is unable to open, propagate the exception.

[vkedia]

We dont expect any other exception to be thrown by createSession other than SpannerException, which is why it just catches that.
Do you have the trace for NPE?

[ludoch]

No, even in the debugger, could not see it.. You can reproduce with a local devserver on gae standard Java8...

…

On Apr 5, 2017 07:40, "Vikas Kedia" ***@***.***> wrote: We dont expect any other exception to be thrown by createSession other than SpannerException, which is why it just catches that. Do you have the trace for NPE? — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#1856 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAE4zWwCYIrsb3Cl60tmSAsSQR_rtV7jks5rsylTgaJpZM4Myx67> .

[ludoch]

appengine-guestbook-java.zip
contains a simple (stupid) spanner servlet with hardcoded project data...
You can execute with mvn appengine:devserver which starts the local server in debug mode with
-agentlib:jdwp=transport=dt_socket,address=7999,server=y,suspend=n
so you can debug if you want....
If you want to deploy (mvn appengine:update), change the project name and version in the pom.xml but first, you need to be whitelisted for Java8. Ask me...

[vkedia]

Thanks. I will try this out. I will let you know if I need to be whitelisted.

[saturnism]

the issue w/o exception is that the subsequent operations get blocked indefinitely (e.g.., getting a readcontext). It took a while to trace back to what was blocking it.

i'm inclined to say exception should always be propagated when it wasn't working as intended.

[ludoch]

Friendly ping.

[vkedia]

Sorry I was on vacation. I will take a look at this next week.

[vkedia]

@saturnism I think you are right. We should handle any Runtime exception here. I will make that change.

[vkedia]

#2026 should fix the issue with exception handling.

[vkedia]

This should be fixed now. @ludoch Can you please try now and close this issue is it works.

[ludoch]

So I tried the attached sample above with upgrading to 1.9.53 for GAE and 0.17.2-beta for Spanner.

After a local run, I go to the http://localhost:8080/SpannerServlet . URL and gets this error:
May 24, 2017 2:44:17 PM com.google.appengine.api.datastore.dev.LocalDatastoreService load
INFO: The backing store, /Users/ludo/Downloads/appengine-guestbook-javaspannerbug/target/spaneerbug-guestbook-Java8-Standard-1.0-SNAPSHOT/WEB-INF/appengine-generated/local_db.bin, does not exist. It will be created.
May 24, 2017 2:44:22 PM io.grpc.internal.ChannelExecutor drain
WARNING: Runnable threw exception in ChannelExecutor
java.lang.NullPointerException
at com.google.appengine.tools.development.RequestEndListenerHelper.getListeners(RequestEndListenerHelper.java:52)
at com.google.appengine.tools.development.RequestEndListenerHelper.register(RequestEndListenerHelper.java:39)
at com.google.appengine.tools.development.RequestThreadFactory$1$1.start(RequestThreadFactory.java:65)
at java.util.concurrent.ThreadPoolExecutor.addWorker(ThreadPoolExecutor.java:950)
at java.util.concurrent.ThreadPoolExecutor.ensurePrestart(ThreadPoolExecutor.java:1587)
at java.util.concurrent.ScheduledThreadPoolExecutor.delayedExecute(ScheduledThreadPoolExecutor.java:334)
at java.util.concurrent.ScheduledThreadPoolExecutor.schedule(ScheduledThreadPoolExecutor.java:533)
at io.grpc.internal.ManagedChannelImpl.rescheduleIdleTimer(ManagedChannelImpl.java:336)
at io.grpc.internal.ManagedChannelImpl.exitIdleMode(ManagedChannelImpl.java:301)
at io.grpc.internal.ManagedChannelImpl$4$1.run(ManagedChannelImpl.java:359)
at io.grpc.internal.ChannelExecutor.drain(ChannelExecutor.java:87)
at io.grpc.internal.ManagedChannelImpl$4.get(ManagedChannelImpl.java:361)
at io.grpc.internal.ClientCallImpl.start(ClientCallImpl.java:221)
at io.grpc.ForwardingClientCall.start(ForwardingClientCall.java:47)
at com.google.cloud.spanner.spi.v1.WatchdogInterceptor$MonitoredCall.start(WatchdogInterceptor.java:194)
at io.grpc.ForwardingClientCall.start(ForwardingClientCall.java:47)
at com.google.cloud.spanner.spi.v1.SpannerErrorInterceptor$1.start(SpannerErrorInterceptor.java:67)
at io.grpc.ForwardingClientCall.start(ForwardingClientCall.java:47)
at com.google.cloud.spanner.spi.v1.GrpcSpannerRpc$MetadataClientCall.start(GrpcSpannerRpc.java:456)
at io.grpc.stub.ClientCalls.startCall(ClientCalls.java:270)
at io.grpc.stub.ClientCalls.asyncUnaryRequestCall(ClientCalls.java:249)
at io.grpc.stub.ClientCalls.futureUnaryCall(ClientCalls.java:186)
at com.google.cloud.spanner.spi.v1.GrpcSpannerRpc.doUnaryCall(GrpcSpannerRpc.java:420)
at com.google.cloud.spanner.spi.v1.GrpcSpannerRpc.createSession(GrpcSpannerRpc.java:323)
at com.google.cloud.spanner.SpannerImpl$2.call(SpannerImpl.java:223)
at com.google.cloud.spanner.SpannerImpl$2.call(SpannerImpl.java:220)
at com.google.cloud.spanner.SpannerImpl.runWithRetries(SpannerImpl.java:202)
at com.google.cloud.spanner.SpannerImpl.createSession(SpannerImpl.java:219)
at com.google.cloud.spanner.SessionPool$4.run(SessionPool.java:987)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:748)

May 24, 2017 2:44:22 PM io.grpc.internal.ManagedChannelImpl$NameResolverListenerImpl onError
WARNING: [io.grpc.internal.ManagedChannelImpl-1] Failed to resolve name. status=Status{code=UNKNOWN, description=null, cause=java.lang.NullPointerException
at com.google.appengine.tools.development.RequestEndListenerHelper.getListeners(RequestEndListenerHelper.java:52)
at com.google.appengine.tools.development.RequestEndListenerHelper.register(RequestEndListenerHelper.java:39)
at com.google.appengine.tools.development.RequestThreadFactory$1$1.start(RequestThreadFactory.java:65)
at java.util.concurrent.ThreadPoolExecutor.addWorker(ThreadPoolExecutor.java:950)
at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1368)
at io.grpc.internal.DnsNameResolver.resolve(DnsNameResolver.java:205)
at io.grpc.internal.DnsNameResolver.start(DnsNameResolver.java:116)
at io.grpc.internal.ManagedChannelImpl.exitIdleMode(ManagedChannelImpl.java:313)
at io.grpc.internal.ManagedChannelImpl$2.handleInUse(ManagedChannelImpl.java:241)
at io.grpc.internal.InUseStateAggregator.updateObjectInUse(InUseStateAggregator.java:55)
at io.grpc.internal.ManagedChannelImpl$1.transportInUse(ManagedChannelImpl.java:200)
at io.grpc.internal.DelayedClientTransport$1.run(DelayedClientTransport.java:110)
at io.grpc.internal.ChannelExecutor.drain(ChannelExecutor.java:87)
at io.grpc.internal.DelayedClientTransport.newStream(DelayedClientTransport.java:185)
at io.grpc.internal.ClientCallImpl.start(ClientCallImpl.java:225)
at io.grpc.ForwardingClientCall.start(ForwardingClientCall.java:47)
at com.google.cloud.spanner.spi.v1.WatchdogInterceptor$MonitoredCall.start(WatchdogInterceptor.java:194)
at io.grpc.ForwardingClientCall.start(ForwardingClientCall.java:47)
at com.google.cloud.spanner.spi.v1.SpannerErrorInterceptor$1.start(SpannerErrorInterceptor.java:67)
at io.grpc.ForwardingClientCall.start(ForwardingClientCall.java:47)
at com.google.cloud.spanner.spi.v1.GrpcSpannerRpc$MetadataClientCall.start(GrpcSpannerRpc.java:456)
at io.grpc.stub.ClientCalls.startCall(ClientCalls.java:270)
at io.grpc.stub.ClientCalls.asyncUnaryRequestCall(ClientCalls.java:249)
at io.grpc.stub.ClientCalls.futureUnaryCall(ClientCalls.java:186)
at com.google.cloud.spanner.spi.v1.GrpcSpannerRpc.doUnaryCall(GrpcSpannerRpc.java:420)
at com.google.cloud.spanner.spi.v1.GrpcSpannerRpc.createSession(GrpcSpannerRpc.java:323)
at com.google.cloud.spanner.SpannerImpl$2.call(SpannerImpl.java:223)
at com.google.cloud.spanner.SpannerImpl$2.call(SpannerImpl.java:220)
at com.google.cloud.spanner.SpannerImpl.runWithRetries(SpannerImpl.java:202)
at com.google.cloud.spanner.SpannerImpl.createSession(SpannerImpl.java:219)
at com.google.cloud.spanner.SessionPool$4.run(SessionPool.java:987)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:748)
}
May 24, 2017 2:44:22 PM io.grpc.internal.ChannelExecutor drain
WARNING: Runnable threw exception in ChannelExecutor
java.lang.NullPointerException
at com.google.appengine.tools.development.RequestEndListenerHelper.getListeners(RequestEndListenerHelper.java:52)
at com.google.appengine.tools.development.RequestEndListenerHelper.register(RequestEndListenerHelper.java:39)
at com.google.appengine.tools.development.RequestThreadFactory$1$1.start(RequestThreadFactory.java:65)
at java.util.concurrent.ThreadPoolExecutor.addWorker(ThreadPoolExecutor.java:950)
at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1368)
at io.grpc.internal.DelayedClientTransport.reprocess(DelayedClientTransport.java:306)
at io.grpc.internal.ManagedChannelImpl$LbHelperImpl$5.run(ManagedChannelImpl.java:724)
at io.grpc.internal.ChannelExecutor.drain(ChannelExecutor.java:87)
at io.grpc.internal.DelayedClientTransport.newStream(DelayedClientTransport.java:185)
at io.grpc.internal.ClientCallImpl.start(ClientCallImpl.java:225)
at io.grpc.ForwardingClientCall.start(ForwardingClientCall.java:47)
at com.google.cloud.spanner.spi.v1.WatchdogInterceptor$MonitoredCall.start(WatchdogInterceptor.java:194)
at io.grpc.ForwardingClientCall.start(ForwardingClientCall.java:47)
at com.google.cloud.spanner.spi.v1.SpannerErrorInterceptor$1.start(SpannerErrorInterceptor.java:67)
at io.grpc.ForwardingClientCall.start(ForwardingClientCall.java:47)
at com.google.cloud.spanner.spi.v1.GrpcSpannerRpc$MetadataClientCall.start(GrpcSpannerRpc.java:456)
at io.grpc.stub.ClientCalls.startCall(ClientCalls.java:270)
at io.grpc.stub.ClientCalls.asyncUnaryRequestCall(ClientCalls.java:249)
at io.grpc.stub.ClientCalls.futureUnaryCall(ClientCalls.java:186)
at com.google.cloud.spanner.spi.v1.GrpcSpannerRpc.doUnaryCall(GrpcSpannerRpc.java:420)
at com.google.cloud.spanner.spi.v1.GrpcSpannerRpc.createSession(GrpcSpannerRpc.java:323)
at com.google.cloud.spanner.SpannerImpl$2.call(SpannerImpl.java:223)
at com.google.cloud.spanner.SpannerImpl$2.call(SpannerImpl.java:220)
at com.google.cloud.spanner.SpannerImpl.runWithRetries(SpannerImpl.java:202)
at com.google.cloud.spanner.SpannerImpl.createSession(SpannerImpl.java:219)
at com.google.cloud.spanner.SessionPool$4.run(SessionPool.java:987)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:748)

May 24, 2017 2:44:23 PM io.grpc.internal.ChannelExecutor drain
WARNING: Runnable threw exception in ChannelExecutor
java.lang.NullPointerException
at com.google.appengine.tools.development.RequestEndListenerHelper.getListeners(RequestEndListenerHelper.java:52)
at com.google.appengine.tools.development.RequestEndListenerHelper.register(RequestEndListenerHelper.java:39)
at com.google.appengine.tools.development.RequestThreadFactory$1$1.start(RequestThreadFactory.java:65)
at java.util.concurrent.ThreadPoolExecutor.addWorker(ThreadPoolExecutor.java:950)
at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1366)
at io.grpc.internal.DelayedClientTransport.reprocess(DelayedClientTransport.java:306)
at io.grpc.internal.ManagedChannelImpl$LbHelperImpl$5.run(ManagedChannelImpl.java:724)
at io.grpc.internal.ChannelExecutor.drain(ChannelExecutor.java:87)
at io.grpc.internal.InternalSubchannel$TransportListener.transportReady(InternalSubchannel.java:415)
at io.grpc.netty.ClientTransportLifecycleManager.notifyReady(ClientTransportLifecycleManager.java:58)
at io.grpc.netty.NettyClientHandler$FrameListener.onSettingsRead(NettyClientHandler.java:636)
at io.grpc.netty.FixedHttp2ConnectionDecoder$FrameReadListener.onSettingsRead(FixedHttp2ConnectionDecoder.java:458)
at io.grpc.netty.FixedHttp2ConnectionDecoder$PrefaceFrameListener.onSettingsRead(FixedHttp2ConnectionDecoder.java:670)
at io.netty.handler.codec.http2.Http2InboundFrameLogger$1.onSettingsRead(Http2InboundFrameLogger.java:93)
at io.netty.handler.codec.http2.DefaultHttp2FrameReader.readSettingsFrame(DefaultHttp2FrameReader.java:546)
at io.netty.handler.codec.http2.DefaultHttp2FrameReader.processPayloadState(DefaultHttp2FrameReader.java:262)
at io.netty.handler.codec.http2.DefaultHttp2FrameReader.readFrame(DefaultHttp2FrameReader.java:160)
at io.netty.handler.codec.http2.Http2InboundFrameLogger.readFrame(Http2InboundFrameLogger.java:41)
at io.grpc.netty.FixedHttp2ConnectionDecoder.decodeFrame(FixedHttp2ConnectionDecoder.java:119)
at io.netty.handler.codec.http2.Http2ConnectionHandler$FrameDecoder.decode(Http2ConnectionHandler.java:341)
at io.netty.handler.codec.http2.Http2ConnectionHandler$PrefaceDecoder.decode(Http2ConnectionHandler.java:220)
at io.netty.handler.codec.http2.Http2ConnectionHandler.decode(Http2ConnectionHandler.java:401)
at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:411)
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:248)
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.handler.ssl.SslHandler.unwrap(SslHandler.java:1228)
at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1039)
at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:411)
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:248)
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 io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:144)
at java.lang.Thread.run(Thread.java:748)

Maybe it now a different error?