Issue with Teiid session not closing in background thread when using useCallingThread=true
anilallewar Nov 1, 2013 5:02 PMWe 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.