SessionConstraint may cause a hang about openam

[sp193]

Within CoreSystem, there is this loop that appears. The only difference is the suffix of the transactionId attribute of the query, which makes me believe that a single, same request got stuck.

tokenDataLayer:12/02/2023 12:10:54:134 PM UTC: Thread[http-nio-9090-exec-4,5,main]: TransactionId[3f4a4eee-7166-44fb-925c-8d578f8c94ae-9826]
CTS Async: Queuing Task ReadTask: -8136762284537127581
tokenDataLayer:12/02/2023 12:10:54:146 PM UTC: Thread[http-nio-9090-exec-4,5,main]: TransactionId[3f4a4eee-7166-44fb-925c-8d578f8c94ae-9826]
CTS Async: Queuing Task QueryTask: TokenFilter: Filter: [coreTokenMultiString01 eq "AQIC5wM2LY4SfcwV282pLmPmxFjnwCrkto2w86_1K7BU9nU.*AAJTSQACMDEAAlNLABQtODEzNjc2MjI4NDUzNzEyNzU4MQACUzEAAA..*"] Attributes: 
tokenDataLayer:12/02/2023 12:10:54:149 PM UTC: Thread[CTSWorkerPool-2,5,main]: TransactionId[3f4a4eee-7166-44fb-925c-8d578f8c94ae-9826]
CTS Async: Creating Embedded Factory:
URL: [ldap://opendj:50389]
Max Connections: 10
Heartbeat: 10
Operation Timeout: 10
tokenDataLayer:12/02/2023 12:10:54:152 PM UTC: Thread[CTSWorkerPool-2,5,main]: TransactionId[3f4a4eee-7166-44fb-925c-8d578f8c94ae-9826]
CTS: Query: matched 0 results
Search Request: SearchRequest(name=ou=famrecords,ou=openam-session,ou=tokens,dc=openam,dc=forgerock,dc=org, scope=sub, dereferenceAliasesPolicy=never, sizeLimit=0, timeLimit=0, typesOnly=false, filter=(&(coreTokenMultiString01=AQIC5wM2LY4SfcwV282pLmPmxFjnwCrkto2w86_1K7BU9nU.\2AAAJTSQACMDEAAlNLABQtODEzNjc2MjI4NDUzNzEyNzU4MQACUzEAAA..\2A)(objectClass=frCoreToken)), attributes=[*, etag], controls=[TransactionIdControl(oid=1.3.6.1.4.1.36733.2.1.5.1, transactionId=3f4a4eee-7166-44fb-925c-8d578f8c94ae-9826/153959)])
Filter: (&(coreTokenMultiString01=AQIC5wM2LY4SfcwV282pLmPmxFjnwCrkto2w86_1K7BU9nU.\2AAAJTSQACMDEAAlNLABQtODEzNjc2MjI4NDUzNzEyNzU4MQACUzEAAA..\2A)(objectClass=frCoreToken))
Result: Result(resultCode=Success, matchedDN=, diagnosticMessage=, referrals=[], controls=[])
tokenDataLayer:12/02/2023 12:10:54:153 PM UTC: Thread[CTSWorkerPool-2,5,main]: TransactionId[3f4a4eee-7166-44fb-925c-8d578f8c94ae-9826]
CTS: Query: Matched 0, some Tokens are shown below:

Within Session, there is this loop that also bears the same transactionId:

amCoreTokenService:12/02/2023 12:10:29:561 PM UTC: Thread[http-nio-9090-exec-4,5,main]: TransactionId[3f4a4eee-7166-44fb-925c-8d578f8c94ae-9826]
CTS: Read: queued -8136762284537127581
amCoreTokenService:12/02/2023 12:10:29:564 PM UTC: Thread[CTSWorkerPool-0,5,main]: TransactionId[3f4a4eee-7166-44fb-925c-8d578f8c94ae-0]
CTS Async: Task Processor: process Task org.forgerock.openam.sm.datalayer.impl.SeriesTaskExecutor$AuditRequestContextPropagatingTask@62508546
amCTSAsync:12/02/2023 12:10:29:566 PM UTC: Thread[CTSWorkerPool-0,5,main]: TransactionId[3f4a4eee-7166-44fb-925c-8d578f8c94ae-9826]
CTS Async: Received: results: <null>
amCTSAsync:12/02/2023 12:10:29:567 PM UTC: Thread[http-nio-9090-exec-4,5,main]: TransactionId[3f4a4eee-7166-44fb-925c-8d578f8c94ae-9826]
CTS Async: Results: <null>
amCoreTokenService:12/02/2023 12:10:29:569 PM UTC: Thread[http-nio-9090-exec-4,5,main]: TransactionId[3f4a4eee-7166-44fb-925c-8d578f8c94ae-9826]
CTS: Read: no Token found for -8136762284537127581
amCoreTokenService:12/02/2023 12:10:29:570 PM UTC: Thread[http-nio-9090-exec-4,5,main]: TransactionId[3f4a4eee-7166-44fb-925c-8d578f8c94ae-9826]
CTS: Token -8136762284537127581 did not exist
amCoreTokenService:12/02/2023 12:10:29:572 PM UTC: Thread[http-nio-9090-exec-4,5,main]: TransactionId[3f4a4eee-7166-44fb-925c-8d578f8c94ae-9826]
CTS: Query: TokenFilter: Filter: [coreTokenMultiString01 eq "AQIC5wM2LY4SfcwV282pLmPmxFjnwCrkto2w86_1K7BU9nU.*AAJTSQACMDEAAlNLABQtODEzNjc2MjI4NDUzNzEyNzU4MQACUzEAAA..*"] Attributes: 
amCoreTokenService:12/02/2023 12:10:29:573 PM UTC: Thread[http-nio-9090-exec-4,5,main]: TransactionId[3f4a4eee-7166-44fb-925c-8d578f8c94ae-9826]
CTS: Query: queued with Filter: TokenFilter: Filter: [coreTokenMultiString01 eq "AQIC5wM2LY4SfcwV282pLmPmxFjnwCrkto2w86_1K7BU9nU.*AAJTSQACMDEAAlNLABQtODEzNjc2MjI4NDUzNzEyNzU4MQACUzEAAA..*"] Attributes: 
amCoreTokenService:12/02/2023 12:10:29:576 PM UTC: Thread[CTSWorkerPool-5,5,main]: TransactionId[3f4a4eee-7166-44fb-925c-8d578f8c94ae-0]
CTS Async: Task Processor: process Task org.forgerock.openam.sm.datalayer.impl.SeriesTaskExecutor$AuditRequestContextPropagatingTask@671a528e
amCTSAsync:12/02/2023 12:10:29:583 PM UTC: Thread[CTSWorkerPool-5,5,main]: TransactionId[3f4a4eee-7166-44fb-925c-8d578f8c94ae-9826]
CTS Async: Received: results: []
amCTSAsync:12/02/2023 12:10:29:585 PM UTC: Thread[http-nio-9090-exec-4,5,main]: TransactionId[3f4a4eee-7166-44fb-925c-8d578f8c94ae-9826]
CTS Async: Results: []
amCoreTokenService:12/02/2023 12:10:29:586 PM UTC: Thread[http-nio-9090-exec-4,5,main]: TransactionId[3f4a4eee-7166-44fb-925c-8d578f8c94ae-9826]
CTS: Query: returned 0 Tokens with Filter: TokenFilter: Filter: [coreTokenMultiString01 eq "AQIC5wM2LY4SfcwV282pLmPmxFjnwCrkto2w86_1K7BU9nU.*AAJTSQACMDEAAlNLABQtODEzNjc2MjI4NDUzNzEyNzU4MQACUzEAAA..*"] Attributes: 
amSession:12/02/2023 12:10:29:588 PM UTC: Thread[http-nio-9090-exec-4,5,main]: TransactionId[3f4a4eee-7166-44fb-925c-8d578f8c94ae-9826]
session.Refresh Removed SID:AQIC5wM2LY4SfcwV282pLmPmxFjnwCrkto2w86_1K7BU9nU.*AAJTSQACMDEAAlNLABQtODEzNjc2MjI4NDUzNzEyNzU4MQACUzEAAA..*
amSession:12/02/2023 12:10:29:589 PM UTC: Thread[http-nio-9090-exec-4,5,main]: TransactionId[3f4a4eee-7166-44fb-925c-8d578f8c94ae-9826]
AQIC5wM2LY4SfcwV282pLmPmxFjnwCrkto2w86_1K7BU9nU.*AAJTSQACMDEAAlNLABQtODEzNjc2MjI4NDUzNzEyNzU4MQACUzEAAA..*: LocalOperations selected.
amSession:12/02/2023 12:10:29:590 PM UTC: Thread[http-nio-9090-exec-4,5,main]: TransactionId[3f4a4eee-7166-44fb-925c-8d578f8c94ae-9826]
Local fetch SessionInfo for AQIC5wM2LY4SfcwV282pLmPmxFjnwCrkto2w86_1K7BU9nU.*AAJTSQACMDEAAlNLABQtODEzNjc2MjI4NDUzNzEyNzU4MQACUzEAAA..*
Reset: false

What I understand from the Session log, and studying the code with reference to the stack trace:
"CTS: Query: returned 0 Tokens with Filter" is printed because there are no matches for the given token.
"Removed SID" is printed here by Session.
The exception that is caught by Session is thrown here by LocalOperations.

[vharseko]

please provide

1. version ?
2. jstack PID >> thread.txt (multiple files)

[sp193]

Thank you for looking into this. Apologies for taking a while to get back to you, but I have been getting increasingly busy at work.
Since the only platform I have which can rather reliably replicate this is a soon-to-be production environment, I can only test the new commit over the weekend (which is very soon). I think that your change does look like a way to solve this problem of being unable to destroy a session which cannot be destroyed.

I made a heap dump before (.hprof), which seems to have the status of all threads. Would this do? https://www.sendspace.com/file/e4be8p
As mentioned above, one of the threads stuck in the loop was http-nio-9090-exec-4.

The version of OpenAM is this repository's head, a 14.8.1 snapshot.

[sp193]

Hi again. It has been 2 days and I think the patch has been working well. Closing as fixed by #682. Thank you.