-
1. Re: Session may already be closed on resultset get next
shawkins Nov 18, 2015 8:39 AM (in response to gadeyne.bram)> On the Teiid server side I see a lot of these warning messages:
[TEIID-3697] minimize invalid session exceptions in the logs - JBoss Issue Tracker should make it so that only meaningful exceptions are shown at the warning level.
> Does anyone know what might be causing this issue?
Can you turn up logging and look prior to this issue happening for an indication of why the session is being closed?
-
2. Re: Session may already be closed on resultset get next
gadeyne.bram Nov 19, 2015 9:34 AM (in response to shawkins)Hi,
I think that the problem is not with Teiid but with the jasperserver. With DEBUG level on I see the following:
15:30:04,284 DEBUG [org.teiid.SECURITY] (New I/O worker #4) elN+MpJeH+g8 Keep-alive ping received for session: elN+MpJeH+g8
15:30:05,297 DEBUG [org.teiid.SECURITY] (New I/O worker #4) elN+MpJeH+g8 closeSession elN+MpJeH+g8
15:30:05,299 DEBUG [org.teiid.COMMAND_LOG] (New I/O worker #4) elN+MpJeH+g8 CANCEL USER COMMAND: endTime=2015-11-19 15:30:05.299 requestID=elN+MpJeH+g8.7 txID=null sessionID=elN+MpJeH+g8 principal=jasper@teiid-security vdbName=vdb3 vdbVersion=8 finalRowCount=null
15:30:05,344 WARN [org.teiid.SECURITY] (New I/O worker #1) null TEIID40011 Processing exception 'TEIID40042 Invalid Session elN+MpJeH+g8. Session may have already been terminated.' for session null. Exception type org.teiid.client.security.InvalidSessionException thrown from org.teiid.services.SessionServiceImpl.getSessionInfo(SessionServiceImpl.java:339).: org.teiid.client.security.InvalidSessionException: TEIID40042 Invalid Session elN+MpJeH+g8. Session may have already been terminated.
at org.teiid.services.SessionServiceImpl.getSessionInfo(SessionServiceImpl.java:339) [teiid-runtime-8.11.3.jar:8.11.3]
at org.teiid.services.SessionServiceImpl.validateSession(SessionServiceImpl.java:328) [teiid-runtime-8.11.3.jar:8.11.3]
at org.teiid.transport.LogonImpl.assertIdentity(LogonImpl.java:273) [teiid-runtime-8.11.3.jar:8.11.3]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.8.0_60]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) [rt.jar:1.8.0_60]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_60]
at java.lang.reflect.Method.invoke(Method.java:497) [rt.jar:1.8.0_60]
at org.teiid.transport.ServerWorkItem.run(ServerWorkItem.java:87) [teiid-runtime-8.11.3.jar:8.11.3]
at org.teiid.dqp.internal.process.DQPWorkContext.runInContext(DQPWorkContext.java:276) [teiid-engine-8.11.3.jar:8.11.3]
at org.teiid.transport.SocketClientInstance.processMessagePacket(SocketClientInstance.java:223) [teiid-runtime-8.11.3.jar:8.11.3]
at org.teiid.transport.SocketClientInstance.receivedMessage(SocketClientInstance.java:209) [teiid-runtime-8.11.3.jar:8.11.3]
at org.teiid.transport.SSLAwareChannelHandler.messageReceived(SSLAwareChannelHandler.java:212) [teiid-runtime-8.11.3.jar:8.11.3]
at org.jboss.netty.channel.SimpleChannelHandler.handleUpstream(SimpleChannelHandler.java:88) [netty-3.6.10.Final-redhat-1.jar:3.6.10.Final-redhat-1]
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.6.10.Final-redhat-1.jar:3.6.10.Final-redhat-1]
at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) [netty-3.6.10.Final-redhat-1.jar:3.6.10.Final-redhat-1]
at org.jboss.netty.handler.stream.ChunkedWriteHandler.handleUpstream(ChunkedWriteHandler.java:142) [netty-3.6.10.Final-redhat-1.jar:3.6.10.Final-redhat-1]
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.6.10.Final-redhat-1.jar:3.6.10.Final-redhat-1]
at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) [netty-3.6.10.Final-redhat-1.jar:3.6.10.Final-redhat-1]
at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:296) [netty-3.6.10.Final-redhat-1.jar:3.6.10.Final-redhat-1]
at org.jboss.netty.handler.codec.frame.FrameDecoder.unfoldAndFireMessageReceived(FrameDecoder.java:462) [netty-3.6.10.Final-redhat-1.jar:3.6.10.Final-redhat-1]
at org.jboss.netty.handler.codec.frame.FrameDecoder.callDecode(FrameDecoder.java:443) [netty-3.6.10.Final-redhat-1.jar:3.6.10.Final-redhat-1]
at org.jboss.netty.handler.codec.frame.FrameDecoder.messageReceived(FrameDecoder.java:303) [netty-3.6.10.Final-redhat-1.jar:3.6.10.Final-redhat-1]
at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70) [netty-3.6.10.Final-redhat-1.jar:3.6.10.Final-redhat-1]
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.6.10.Final-redhat-1.jar:3.6.10.Final-redhat-1]
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:559) [netty-3.6.10.Final-redhat-1.jar:3.6.10.Final-redhat-1]
at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:268) [netty-3.6.10.Final-redhat-1.jar:3.6.10.Final-redhat-1]
at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:255) [netty-3.6.10.Final-redhat-1.jar:3.6.10.Final-redhat-1]
at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:88) [netty-3.6.10.Final-redhat-1.jar:3.6.10.Final-redhat-1]
at org.jboss.netty.channel.socket.nio.AbstractNioWorker.process(AbstractNioWorker.java:109) [netty-3.6.10.Final-redhat-1.jar:3.6.10.Final-redhat-1]
at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:328) [netty-3.6.10.Final-redhat-1.jar:3.6.10.Final-redhat-1]
at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:90) [netty-3.6.10.Final-redhat-1.jar:3.6.10.Final-redhat-1]
at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178) [netty-3.6.10.Final-redhat-1.jar:3.6.10.Final-redhat-1]
at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108) [netty-3.6.10.Final-redhat-1.jar:3.6.10.Final-redhat-1]
at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42) [netty-3.6.10.Final-redhat-1.jar:3.6.10.Final-redhat-1]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [rt.jar:1.8.0_60]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [rt.jar:1.8.0_60]
at java.lang.Thread.run(Thread.java:745) [rt.jar:1.8.0_60]
15:30:05,359 DEBUG [org.teiid.SECURITY] (New I/O worker #1) null authenticateUser jasper JDBC
15:30:05,360 DEBUG [org.teiid.SECURITY] (New I/O worker #1) null Logon successful for " jasper " in security domain teiid-security
15:30:05,360 DEBUG [org.teiid.SECURITY] (New I/O worker #1) null Logon successful, created session: sessionid=q9f8pvWlWTc8; userName=jasper@teiid-security; vdbName=vdb3; vdbVersion=8; createdTime=Thu Nov 19 15:30:05 CET 2015; applicationName=JDBC; clientHostName=localhost; clientHardwareAddress=null; IPAddress=127.0.0.1; securityDomain=teiid-security; lastPingTime=Thu Nov 19 15:30:05 CET 2015
15:30:05,366 WARN [org.teiid.PROCESSOR] (New I/O worker #1) q9f8pvWlWTc8 TEIID40011 Processing exception 'TEIID30495 The request q9f8pvWlWTc8.7 has been closed.' for session q9f8pvWlWTc8. Exception type org.teiid.core.TeiidProcessingException thrown from org.teiid.dqp.internal.process.DQPCore.getRequestWorkItem(DQPCore.java:426). Enable more detailed logging to see the entire stacktrace.
So it seems likt jasper first closes the session and then reopens it or creates a new one.
-
3. Re: Session may already be closed on resultset get next
shawkins Nov 19, 2015 10:08 AM (in response to gadeyne.bram)> 15:30:05,297 DEBUG [org.teiid.SECURITY] (New I/O worker #4) elN+MpJeH+g8 closeSession elN+MpJeH+g8
Yes, that should be an explicit close call on the client Connection. Could you debug jasperserver to see why it is calling close?