3 Replies Latest reply on Nov 19, 2015 10:08 AM by Steven Hawkins

    Session may already be closed on resultset get next

    gadeyne.bram Master

      Hi,

       

      In april I started a thread on a similar issue but I'm not sure if it is the same problem. question about Session may already be closed

       

      I'm using Teiid 8.11.3 in combination with Jasperserver 6.1.1. The jasper server complains that at a given time it can not retrieve the next result from the resultset. The causing exception mentions Session may already be closed.

       

      On the Teiid server side I see a lot of these warning messages:

       

      10:21:44,543 WARN  [org.teiid.PROCESSOR] (New I/O worker #4) Ur/i/TxYq+v1 TEIID40011 Processing exception 'TEIID30495 The request Ur/i/TxYq+v1.3 has been closed.' for session Ur/i/TxYq+v1.  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.

       

      Does anyone know what might be causing this issue?

       

      The datasource in tomcat is defined as

       

      <Resource name="jdbc/Teiid" auth="Container" type="javax.sql.DataSource"

                     maxActive="10" maxIdle="3" maxWait="10000"

                     username="xxx" password="xxx" driverClassName="org.teiid.jdbc.TeiidDriver"

                     url="jdbc:teiid:vdb3@mm://localhost:31000;autoFailover=true;"

                      removeAbandoned="true" removeAbandonedTimeout="60" validationQuery="select 1" validationQueryTimeout="5" testWhileIdle="true" testOnBorrow="true" testOnReturn="false" validationInterval="30000" />

       

      With kind regards

      Bram

        • 1. Re: Session may already be closed on resultset get next
          Steven Hawkins Master

          > 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 Master

            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
              Steven Hawkins Master

              > 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?