13 Replies Latest reply on Nov 22, 2013 3:45 PM by Steven Hawkins

    Issue with Teiid session not closing in background thread when using useCallingThread=true

    Anil Allewar Newbie

      We have certain tables with large number of data that are being accessed through our application and we also provide server side paging. In order to provide server side paging we create a JPA cursor on the executed query (basically keep the resultset open) and then provide the next set of records based on what the user is requesting. Since the user can start requesting for a entity and not read the whole set of data, we have a background thread that will try to close the cursor and associated entity manager assuming that this will close the Teiid connection and Teiid internally will release the connection to the source system.

       

      We also use the PassthroughAuthentication=true and useCallingThread=true JDBC connection parameters so that we are able to pass the user's principle available in the HTTP request thread all the way to Teiid and use that for authorization in the source translator and database.

       

      The problem we have been seeing for a while is that if Teiid worker thread doesn't read through all the source records when it gets multiple read requests for that entity, then when the background thread closes the connection Teiid doesn't release the source connection back to the pool. My assumption is that Teiid utilizes the user's principle to track the Teiid session created for reading the entities and hence is able to read the next set of records from the same resultset; obviously it is implied that Teiid uses the same connection that has the resultset between subsequent HTTP requests.

       

      One of the possible solution that I can think of is to keep track of the user principle that started the query and bind that to the background thread that will try to close the cursor. Can you please verify if my understanding is correct and if so how do I attach the principle to the thread? If it's through a thread local, does Teiid need to have a specific name/type for the thread local key/value pair?

       

      Please see the log below for more details.

       

      ----------------------------------------1st request------------------------------
      14:40:34,937 DEBUG [org.teiid.PROCESSOR] (http-/0.0.0.0:8080-1) Request Thread W80Wjrwps4Yr.2 - processor blocked
      14:40:34,946 DEBUG [org.teiid.CONNECTOR] (Worker0_QueryProcessorQueue4) W80Wjrwps4Yr.2.0.0 Obtained results from connector, current row count: 2560
      ----------------------------------------2nd request request------------------------------
      14:42:03,021 DEBUG [org.teiid.PROCESSOR] (http-/0.0.0.0:8080-2) Request Thread 9voUSD1iyHOG.2 - processor blocked
      14:42:03,028 DEBUG [org.teiid.CONNECTOR] (Worker0_QueryProcessorQueue9) 9voUSD1iyHOG.2.0.1 Obtained results from connector, current row count: 2560
      -----------------------------------------1st request---------------------------------------------------------
      14:42:59,616 DEBUG [org.teiid.PROCESSOR] (http-/0.0.0.0:8080-2) Restarting processing using the calling thread W80Wjrwps4Yr.2
      14:42:59,679 DEBUG [org.teiid.CONNECTOR] (Worker0_QueryProcessorQueue14) W80Wjrwps4Yr.2.0.0 Obtained results from connector, current row count: 5120
      -----------------------------------------1st request---------------------------------------------------------
      14:46:07,230 DEBUG [org.teiid.PROCESSOR] (http-/0.0.0.0:8080-2) Request Thread W80Wjrwps4Yr.2 - processor blocked
      14:46:07,234 DEBUG [org.teiid.CONNECTOR] (Worker0_QueryProcessorQueue20) W80Wjrwps4Yr.2.0.0 Obtained results from connector, current row count: 8192
      ------------------------------------------2nd request while 1st is blocked---------------------------------------
      14:47:09,875 DEBUG [org.teiid.PROCESSOR] (http-/0.0.0.0:8080-3) Restarting processing using the calling thread 9voUSD1iyHOG.2
      14:47:09,880 DEBUG [org.teiid.CONNECTOR] (Worker0_QueryProcessorQueue21) 9voUSD1iyHOG.2.0.1 Obtained results from connector, current row count: 3072
      14:47:09,912 DEBUG [org.teiid.BUFFER_MGR] (http-/0.0.0.0:8080-3) 9voUSD1iyHOG.2 Blocking on source request(s).
      14:47:09,916 DEBUG [org.teiid.CONNECTOR] (Worker0_QueryProcessorQueue24) 9voUSD1iyHOG.2.0.1 Obtained results from connector, current row count: 4608
      

       

      -------------------------- First call ------------------------------
      16:29:18,416 DEBUG [org.teiid.PROCESSOR] (http-/0.0.0.0:8080-3) Request Thread qYyyqK5Y2UHF.2 with state NEW
      16:29:18,416 DEBUG [org.teiid.PROCESSOR] (http-/0.0.0.0:8080-3) qYyyqK5Y2UHF.2 executing prepared SELECT "FIELD_NAME", "TABLE_NAME", "TEIID_MULTI_DATA_SOURCE_COLUMN", "MEASURE_ID", "USE_DATUM" FROM "MD_SITE_STORAGE_UNITS" WHERE ("TEIID_MULTI_DATA_SOURCE_COLUMN" = ?)
      16:29:18,423 DEBUG [org.teiid.PROCESSOR] (Worker3_QueryProcessorQueue40) Running task for parent thread http-/0.0.0.0:8080-3
      16:29:18,427 DEBUG [org.jboss.jca.core.connectionmanager.pool.strategy.PoolBySubject] (Worker3_QueryProcessorQueue40) OracleDirectEDM: getConnection(Subject:
       Principal: edm
       Private Credential: javax.resource.spi.security.PasswordCredential@21417eb
      , null) [9/50]
      16:29:18,456 FINE  [org.teiid.jdbc] (http-/0.0.0.0:8080-3) Successfully executed a query SELECT "FIELD_NAME", "TABLE_NAME", "TEIID_MULTI_DATA_SOURCE_COLUMN", "MEASURE_ID", "USE_DATUM" FROM "MD_SITE_STORAGE_UNITS" WHERE ("TEIID_MULTI_DATA_SOURCE_COLUMN" = ?) and obtained results
      16:29:18,460 DEBUG [org.teiid.PROCESSOR] (http-/0.0.0.0:8080-3) Restarting processing using the calling thread qYyyqK5Y2UHF.2
      16:29:18,462 DEBUG [org.teiid.CONNECTOR] (Worker4_QueryProcessorQueue43) qYyyqK5Y2UHF.2.0.9 Obtained results from connector, current row count: 2048
      -------------------------- Second call for next 1000 ------------------------------
      16:30:11,125 DEBUG [org.teiid.PROCESSOR] (http-/0.0.0.0:8080-3) Restarting processing using the calling thread qYyyqK5Y2UHF.2
      16:30:11,125 DEBUG [org.teiid.PROCESSOR] (Worker4_QueryProcessorQueue44) Running task for parent thread http-/0.0.0.0:8080-3
      16:30:11,137 DEBUG [org.teiid.CONNECTOR] (Worker4_QueryProcessorQueue44) qYyyqK5Y2UHF.2.0.9 Obtained results from connector, current row count: 2560
      -------------------------- Third call for next 1000 ------------------------------
      16:31:08,961 DEBUG [org.teiid.CONNECTOR] (Worker4_QueryProcessorQueue46) qYyyqK5Y2UHF.2.0.9 Obtained results from connector, current row count: 3584
      16:31:08,962 DEBUG [org.teiid.PROCESSOR] (http-/0.0.0.0:8080-3) Request Thread qYyyqK5Y2UHF.2 - processor blocked
      -------------------------- Connection close call ------------------------------
      16:33:07,521 FINE  [com.lgc.dsl.producer.jpa.helper.QueryTableManager] (Thread-124) closing timed out session
      16:33:07,522 DEBUG [org.teiid.SECURITY] (Thread-124) authenticateUser  EDMDirect|OracleDirectEDM
      16:33:07,522 DEBUG [org.teiid.SECURITY] (Thread-124) authenticateUser  EDMDirect|OracleDirectEDM
      16:33:07,522 DEBUG [org.teiid.SECURITY] (Thread-124) Logon successful, created session: sessionid=oCWp4v3DIUCz; userName=edm@dsds-security-domain; vdbName=EDMDirectVDB; vdbVersion=1; createdTime=Wed Oct 30 16:33:07 CDT 2013; applicationName=EDMDirect|OracleDirectEDM; clientHostName=null; clientHardwareAddress=null; IPAddress=null; securityDomain=dsds-security-domain; lastPingTime=Wed Oct 30 16:33:07 CDT 2013
      16:33:07,522 DEBUG [org.teiid.SECURITY] (Thread-124) Logon successful, created session: sessionid=oCWp4v3DIUCz; userName=edm@dsds-security-domain; vdbName=EDMDirectVDB; vdbVersion=1; createdTime=Wed Oct 30 16:33:07 CDT 2013; applicationName=EDMDirect|OracleDirectEDM; clientHostName=null; clientHardwareAddress=null; IPAddress=null; securityDomain=dsds-security-domain; lastPingTime=Wed Oct 30 16:33:07 CDT 2013
      16:33:07,522 DEBUG [org.teiid.PROCESSOR] (Thread-124) closeQuery for requestID=oCWp4v3DIUCz.2
      16:33:07,522 DEBUG [org.teiid.PROCESSOR] (Thread-124) closeQuery for requestID=oCWp4v3DIUCz.2
      16:33:07,522 DEBUG [org.teiid.PROCESSOR] (Thread-124) oCWp4v3DIUCz.2 close call ignored as the request has already been removed.
      16:33:07,522 DEBUG [org.teiid.PROCESSOR] (Thread-124) oCWp4v3DIUCz.2 close call ignored as the request has already been removed.
      16:33:07,523 FINE  [org.teiid.jdbc] (Thread-124) Statement closed successfully.
      16:33:07,523 FINE  [org.teiid.jdbc] (Thread-124) Statement closed successfully.
      16:33:07,523 CONFIG [org.eclipse.persistence.session.vfs:/C:/Softwares/Landmark/DSDataServer5000.10.0/ApplicationServer/bin/content/dsdataserver.war/WEB-INF/classes/_teiidDynamicUnit_transactionType=RESOURCE_LOCAL_url=jdbc:teiid:EDMDirectVDB;version=1;PassthroughAuthentication=true;fetchSize=2048;ApplicationName=EDMDirect|OracleDirectEDM;VirtualDatabaseName=EDMDirectVDB;useCallingThread=true.connection] (Thread-124) disconnect  __EclipseLinkSessionId__: 849798576
      16:33:07,524 DEBUG [org.teiid.SECURITY] (Thread-124) closeSession oCWp4v3DIUCz
      16:33:07,524 DEBUG [org.teiid.SECURITY] (Thread-124) closeSession oCWp4v3DIUCz
      16:33:07,524 DEBUG [org.teiid.TXN_LOG] (Thread-124) before cancelTransactions:org.teiid.dqp.internal.process.TransactionServerImpl@3bc09aa5(oCWp4v3DIUCz,false)
      16:33:07,524 DEBUG [org.teiid.TXN_LOG] (Thread-124) before cancelTransactions:org.teiid.dqp.internal.process.TransactionServerImpl@3bc09aa5(oCWp4v3DIUCz,false)
      16:33:07,524 DEBUG [org.teiid.TXN_LOG] (Thread-124) after cancelTransactions : null
      16:33:07,524 DEBUG [org.teiid.TXN_LOG] (Thread-124) after cancelTransactions : null
      16:33:07,524 FINE  [org.teiid.jdbc] (Thread-124) Connection successfully closed.
      16:33:07,524 FINE  [org.teiid.jdbc] (Thread-124) Connection successfully closed.
      
        • 1. Re: Issue with Teiid session not closing in background thread when using useCallingThread=true
          Steven Hawkins Master

          > My assumption is that Teiid utilizes the user's principle to track the Teiid session created for reading the entities and hence is able to read the next set of records from the same resultset; obviously it is implied that Teiid uses the same connection that has the resultset between subsequent HTTP requests.

           

          Teiid leaves all pooling considerations up to the underlying pool.  Our basic flow is that a connection is associated with the source execution and then closed when the execution is finished.  That may occur before the overall user query has finished or may be delayed for example when there are lob values that may need the result set left open for streaming.  In any case when the user command is closed all source executions should be closed.

           

          So what is needed from the log is to see the whole sequence of events related to oCWp4v3DIUCz.2 and the associated executions.  In particular we see close, but the engine has already reported the that the request has been closed/removed.  That should also be in the log.

           

          Steve

          • 2. Re: Re: Issue with Teiid session not closing in background thread when using useCallingThread=true
            Anil Allewar Newbie

            Steve,

             

            I have attached 3 files with the relevant logs and the behavior observed. The use case is

            • The user retrieves records with an OData call on the browser by requesting for an entity. By convention the server always returns the results in batch of 1000.
            • The server executes a query against Teiid and gets the resultset. The resultset will be kept open on the server and tied to the user session so that we can continue reading next results from the resultset. The sample connection URL to connect to Teiid is
            jdbc:teiid:<vdbName>;version=<versionNumber>;PassthroughAuthentication=true;fetchSize=2048;ApplicationName=<appSpecific>;VirtualDatabaseName=<vdbName>;useCallingThread=true
            
            
            
            
            

             

            • The server keeps the connection to the Teiid VDB open by keeping the reference of connection (internally uses a JPA EntityManager with exclusive connections)
            • The user can request for subsequent batches of 1000 which are read from the Teiid resultset reference held by the application.
            • If the user does not request the next batch for a pre-determined time; we close the held Teiid connection using a background thread that runs every x seconds.

             

            The log files are

            1. session_lost_when_closing_connection.log - Here the user reads some data (see session Ldg17J4ZoI2i.2) and then the background thread tries to close the connection at which time this session doesn't get closed but instead the reference is to session /bB9KfTnJy58 that gets closed. In this case when we create a new Teiid connection, it creates a new source connection.
            2. session_closed_when_read_all_data.log- Here the user keeps reading data till Teiid has been able to read all source rows (see session Y0B7nSaDrxP/.2). In this case since Teiid is able to read all records; it goes ahead and closes the source connection (line # 8207). The same source connection is re-used by the next Teiid connection and there is no increase in the number of source connections.
            3. server_crash_if_read_cursor_before_close.log - I modified the code slightly to read all the resultset in the background thread before closing the connection (see session clvvO9m3BwvF.2); however this is causing server crash because is trying to read data from a different session that has already been closed.

             

            Here is the list of connections opened to the underlying oracle server.

             

            spidsidserial#serverprogramlogon_time
            240840316705DEDICATEDJDBC Thin Client11/04/2013 10:59:22
            298840757051DEDICATEDJDBC Thin Client11/04/2013 11:10:19
            607218951DEDICATEDJDBC Thin Client11/04/2013 11:16:04
            20044444229DEDICATEDJDBC Thin Client11/04/2013 11:24:09

             

            Please let me know if you have any further questions.

             

            Thanks,

            Anil

            • 3. Re: Re: Issue with Teiid session not closing in background thread when using useCallingThread=true
              Steven Hawkins Master

              Before diving in, it's important to consider that Connections are not thread-safe - especially so for local connections.  With local connections using the calling thread, the thread will be assumed to have thread-local and other other container/security state beyond just the normal JDBC api considerations that make Connections not thread safe.  If you have a look at Teiid's own odata serving logic https://github.com/teiid/teiid/tree/master/odata the pagination is handled out of cache - not by holding connections/resultsets.

               

              If you can, switch to using socket based connections, just to narrow down that the issue is with the thread usage pattern with local connections.

               

              Steve

              • 4. Re: Re: Issue with Teiid session not closing in background thread when using useCallingThread=true
                Anil Allewar Newbie

                Steve,

                 

                I looked into the OData Teiid source code and as you mentioned saw that you are associating the query results to cache; and close the connection for each call. So the assumption is that the results would be available in the cache;else we would be running the query again and then the cycle follows.

                 

                We tried to follow the same approach earlier but there were some issues

                1. If the cache doesn't work, we will be creating a new connection everytime and querying for the same results. For the datasource we are testing against the difference in performance was 8 hours when querying everytime and 13 mins when we hold reference to resultset.
                2. Our ORM implementation in JPA and not pure JDBC so it would be be difficult to make it work with the Teiid Query interface.
                3. I was testing out Teiid caching and found that if the results contained more rows (say more than 3-4), then Teiid returned the results from the cache but the resultset had 0 rows. I'll post a separate discussion with those details.

                 

                If you can provide me more details(or point me to relevant code) about what thread-local and other other container/security state need to be attached to the calling thread; then I can give it a shot and see if I can bind the same information to the calling background thread.

                 

                Anil

                • 5. Re: Re: Issue with Teiid session not closing in background thread when using useCallingThread=true
                  Ramesh Reddy Master

                  Anil,

                   

                  I am trying to understand your usecase. You have web application, that is connecting to Teiid, that in turn connecting to a JPA source? And you are trying to do pagination in the WebTier application (I understand that web, Teiid, source JPA) all in same VM. If this not correct can you explain, it was not clear for me from above description.

                   

                  Now,

                  1) I do not understand what you mean by when cache does't work, you mean it was cache miss? if that the case, how was your solution different than Teiid's

                  2) I do not understand your ORM comment at all, if you explain the usecase that may be beneficial.

                  3) 3 may be bug

                   

                  Also, if you were to use multiple threads from the client, why even use "useCallingThread=true" to complicate the issue? Is using the "PassthoughAuthentication" required? I mean your application already validated the user at webtier, unless you are doing more with user credentials at Teiid (data roles etc) or source authentication, you can configure Teiid to not have any auth check on the LocalConnections. That means, now your back ground thread can do all the reading from the Teiid, leaving your primary thread to read from your cache.

                   

                  Ramesh..

                  • 6. Re: Re: Issue with Teiid session not closing in background thread when using useCallingThread=true
                    Anil Allewar Newbie

                    Ramesh,

                     

                    The web application uses JPA to map the entities exposed by Teiid. So in essence when the web application requests for data (through OData protocol), we use the mapped JPA class to get all entities and JPA in turn fires a JDBC query on Teiid VDB. I am trying to serve pagination at the web tier by using skiptoken directives on the OData side.

                     

                    1. What I am trying to say is that if it's a cache miss (staleness, resultset moved out because of cache eviction strategy like LIFO etc), then with the current paging solution we would have to read the resultset again from the VDB.

                    2. As described above we use JPA to map the tables held in the VDB, hence the SQL is generated by JPA layer and we don't have fine grained control over how we execute the query. Hence we can't force the use of Teiid Query interface or provide hints in the generated SQL.

                     

                    We need to pass the logged in user's credentials to the source for authorization; hence we need to use both local connections and passthrough authentication. That is one of the requirements as the data authorization is enforced at the source level.

                     

                    I hope this makes sense from a use case perspective.

                     

                    What I have observed is that Teiid is able to associate the session correctly for the subsequent HTTP threads if I use the same Teiid connection but when I try to close the connection from a background thread it does not restart and try to close the session on which the data was read from source. It instead create a new session and closes it while the original session that held reference to the original resultset remains orphaned and is not closed leading to source connection leaks.

                     

                    Anil

                    • 7. Re: Issue with Teiid session not closing in background thread when using useCallingThread=true
                      Steven Hawkins Master

                      > 1. What I am trying to say is that if it's a cache miss (staleness, resultset moved out because of cache eviction strategy like LIFO etc), then with the current paging solution we would have to read the resultset again from the VDB.

                       

                      Should there be more materialization or caching above Teiid in this case?  Or are you possibly looking for a caching option similar to named cursors or some other mechanism to explicitly purge?

                       

                      > 2. As described above we use JPA to map the tables held in the VDB, hence the SQL is generated by JPA layer and we don't have fine grained control over how we execute the query. Hence we can't force the use of Teiid Query interface or provide hints in the generated SQL.

                       

                      Is it possible to just use the ResultSetCacheMode property?

                       

                      > What I have observed is that Teiid is able to associate the session correctly for the subsequent HTTP threads if I use the same Teiid connection but when I try to close the connection from a background thread it does not restart and try to close the session on which the data was read from source.

                       

                      Would it be possible to put this sequence together as a unit test?  That would help ensure that I could see the same behavior and determine if it's something we should support.

                       

                      Steve

                      • 8. Re: Re: Issue with Teiid session not closing in background thread when using useCallingThread=true
                        Ramesh Reddy Master

                        With risk of sounding stupid, when you are already using Teiid why even bother to implement yet another odata layer? It is not that JPA layer is any special here as it is again sitting on top Teiid, a relational source which is gateway to the actual source.

                         

                        From Steve's comment #2 is on the URL connection string, does not need Cache Hints.

                         

                        From your comment about thread closing connection, you are saying that the thread that created the connection is the only one that can clean it up properly in the LocalConnection scenario, I suggest trying this without the "useCallingThread=true", not saying it would fix, but to try to see if behavior changes. Typically it should not matter. Yes, a unit test would be beneficial to walk and understand the workflow.

                        • 9. Re: Re: Issue with Teiid session not closing in background thread when using useCallingThread=true
                          Steven Hawkins Master

                          > I suggest trying this without the "useCallingThread=true"


                          The default is true, so setting it explicitly to false would be needed.

                          • 10. Re: Issue with Teiid session not closing in background thread when using useCallingThread=true
                            Anil Allewar Newbie

                            Sorry for the long delay; was busy on a couple of things.

                             

                            The OData layer provides an abstraction for any client that wants to access the Teiid data using SOA paradigm. With a pure JDBC approach we would be constrained to the client knowing the metadata (or using the connection metadata) and issuing custom queries but with OData any compliant client can discover the metadata and consume the data as a service.

                             

                            I debugged through the Teiid code to find out how Teiid was able to associate the correct session in case of HTTP threads and not in case of background thread. What I observed was that Teiid compares the org.jboss.security.SecurityContext held as reference in the org.teiid.dqp.internal.process.DQPWorkContext to the current org.jboss.security.SecurityContext available in the JAAS subsystem. If they don't match it authenticates the user again leading to creation of new session.

                             

                            So in our case since the background thread did not have any org.jboss.security.SecurityContext associated with it through a threadlocal, the SecurityContext came up as null and didn't match with the SecurityContext stored in the DQPWorkContext. Hence when I tried to close the Teiid connection, it couldn't find any associated sessions that had useCallingThread=true.

                             

                            I fixed this issue by keeping a reference to the org.jboss.security.SecurityContext when I created the resultset and then associate it to the disposal thread using PicketBox API. Once Teiid is able to find the same org.jboss.security.SecurityContext as it has reference to, it goes ahead and closes the correct session associated with the current connection.

                             

                            Thanks,

                            Anil

                            1 of 1 people found this helpful
                            • 11. Re: Issue with Teiid session not closing in background thread when using useCallingThread=true
                              Ramesh Reddy Master

                              May be Teiid instead of doing a anonymous login for the new thread, should just fail to proceed and acknowledge that security context is not found?

                              • 12. Re: Issue with Teiid session not closing in background thread when using useCallingThread=true
                                Steven Hawkins Master

                                I think the intention there was to allow for use in pools so that the identity would switch to the next user.  To keep that behavior implicit we would at least need to close ensure the previous session has been terminated.  I'm not sure if there are any implications of doing that as another user.