IAM: interaction session (id cookie) not found

anon-967 · November 19, 2020, 1:29pm

We have 2 IAM (1.3.1) Servers installed, load balanced. Both point to a single domino Proton Server. Works most of the time. But sometimes, a user gets "invalid request, interaction session not found" or "interaction session id cookie not found". Of course, to make me happier, it's intermittent. What should I look at?

What happens in the background?

IAM Server:

[2020-11-17T12:45:35][debug][DominoDB]: DB.bulkReadDocuments.costTime = 6.999999997788109 ms.
[2020-11-17T12:45:35][debug][DominoDB]: Find 0 documents in findOne method
[2020-11-17T12:45:35][debug][DominoDB]: Not found the doc in db with { _id: 'CN=XXXXXXX,O=YYY' }, create the document.
[2020-11-17T12:45:35][debug][DominoDB]: DB.createDocument for collection [LoginedUsers].costTime = 6.000000001222361 ms.
[2020-11-17T12:45:35][debug][DominoDB]: DB.useDocument & document.read for collection [LoginedUsers].costTime = 5.999999993946403 ms.
[2020-11-17T12:45:35][debug][CustomUtils]: do interactionCheck to check the policy for requiring End-User interactions
[2020-11-17T12:45:35][debug][DominoDB]: DB.createDocument for collection [AuthorizationCode].costTime = 8.999999998195563 ms.
[2020-11-17T12:45:36][debug][DominoDB]: DB.useDocument & document.read for collection [AuthorizationCode].costTime = 6.000000001222361 ms.
[2020-11-17T12:45:36][debug][DominoDB]: DB.useDocument & document.replaceItems for collection [AuthorizationCode].costTime = 40.000000000873115 ms.
[2020-11-17T12:45:36][debug][DominoDB]: DB.useDocument & document.read for collection [LoginedUsers].costTime = 14.999999999417923 ms.
[2020-11-17T12:45:36][debug][DominoDB]: DB.createDocument for collection [AccessToken].costTime = 8.999999998195563 ms.
[2020-11-17T12:45:36][debug][DominoDB]: DB.useDocument & document.read for collection [AccessToken].costTime = 6.999999997788109 ms.
[2020-11-17T12:45:36][debug][DominoDB]: DB.useDocument & document.read for collection [LoginedUsers].costTime = 9.00000000547152 ms.
[2020-11-17T12:45:41][debug][DominoDB]: DB.useDocument & document.replace for collection [LoginedUsers].costTime = 38.99999999703141 ms.
[2020-11-17T12:45:41][debug][CustomUtils]: renderError: {
"error": "invalid_request",
"error_description": "interaction session not found"
}
[2020-11-17T13:15:57][debug][ldapAuth]: socket error with ldap client(TZFobd6z) :
[2020-11-17T13:15:57][debug][ldapAuth]: socket error with ldap client(bDIaEbq4) :
[2020-11-17T13:17:28][debug][clientManager]: Evicting invalid ldap client(bDIaEbq4)

Domino/PROTON:

[19E0:0013-0E30] 17.11.2020 12:45:35,77 LDAP> Search State
[19E0:0013-0E30] 17.11.2020 12:45:35,77 LDAP> ***** Start search request processing *****
[19E0:0013-0E30] 17.11.2020 12:45:35,77 LDAP> Scope: SUBTREE
[19E0:0013-0E30] 17.11.2020 12:45:35,77 LDAP> Dereference Aliases: 0
[19E0:0013-0E30] 17.11.2020 12:45:35,77 LDAP> TimeLimit: 10
[19E0:0013-0E30] 17.11.2020 12:45:35,77 LDAP> SizeLimit: 1
[19E0:0013-0E30] 17.11.2020 12:45:35,77 LDAP> Attributes to return: ALL
[19E0:0013-0E30] 17.11.2020 12:45:35,77 LDAP> Base: o=GKP
[19E0:0013-0E30] 17.11.2020 12:45:35,77 LDAP> Filter: (|(cn=XXXXXX)(mail=XXXXXX))
[19E0:0013-0E30] 17.11.2020 12:45:35,77 LDAP> *** Searching in database D:\Dominodata\names.nsf ...
[19E0:0013-0E30] 17.11.2020 12:45:35,77 LDAP> Type of search: View Search
[19E0:0013-0E30] 17.11.2020 12:45:35,77 LDAP> ... Searching view ($LDAPCN) for match on cn = XXXXXX
[19E0:0013-0E30] 17.11.2020 12:45:35,77 LDAP> NIFFindByKey(XXXXXX) candidate matches: 0, error: 1028
[19E0:0013-0E30] 17.11.2020 12:45:35,77 LDAP> ... Searching view $Users for match on mail = XXXXXX
[19E0:0013-0E30] 17.11.2020 12:45:35,77 LDAP> NIFFindByKey(XXXXXX) candidate matches: 0, error: 1028
[19E0:0013-0E30] 17.11.2020 12:45:35,77 LDAP> GetSearchEntry State
[19E0:0013-0E30] 17.11.2020 12:45:35,77 LDAP> Search State
[19E0:0013-0E30] 17.11.2020 12:45:35,77 LDAP> Search State
[19E0:0013-0E30] 17.11.2020 12:45:35,77 LDAP> *** Searching in database D:\Dominodata\internet\oeak\oauth.nsf ...
[19E0:0013-0E30] 17.11.2020 12:45:35,77 LDAP> Type of search: View Search
[19E0:0013-0E30] 17.11.2020 12:45:35,77 LDAP> ... Searching view ($LDAPCN) for match on cn = XXXXXX
[19E0:0013-0E30] 17.11.2020 12:45:35,77 LDAP> NIFFindByKey(XXXXXX) candidate matches: 1, error: 0
[19E0:0013-0E30] 17.11.2020 12:45:35,77 LDAP> ... Searching view $Users for match on mail = XXXXXX
[19E0:0013-0E30] 17.11.2020 12:45:35,78 LDAP> NIFFindByKey(XXXXXX) candidate matches: 1, error: 0
[19E0:0013-0E30] 17.11.2020 12:45:35,78 LDAP> GetSearchEntry State
[19E0:0013-0E30] 17.11.2020 12:45:35,78 LDAP> Found matching entry, Note ID: 3174
[19E0:0013-0E30] 17.11.2020 12:45:35,78 LDAP> Entry:
[19E0:0013-0E30] 17.11.2020 12:45:35,78 LDAP> dn: CN=XXXXXX,O=YYY
[19E0:0013-0E30] 17.11.2020 12:45:35,78 LDAP> cn: XXXXXX
[19E0:0013-0E30] 17.11.2020 12:45:35,78 LDAP> mail: XXXXXX/YYY@some.domain
[19E0:0013-0E30] 17.11.2020 12:45:35,78 LDAP> displayname: XXXXXX/YYY
[19E0:0013-0E30] 17.11.2020 12:45:35,78 LDAP> bestafter: 20051215201823Z
[19E0:0013-0E30] 17.11.2020 12:45:35,78 LDAP> objectclass: dominoPerson
[19E0:0013-0E30] 17.11.2020 12:45:35,78 LDAP> objectclass: inetOrgPerson
[19E0:0013-0E30] 17.11.2020 12:45:35,78 LDAP> objectclass: organizationalPerson
[19E0:0013-0E30] 17.11.2020 12:45:35,78 LDAP> objectclass: person
[19E0:0013-0E30] 17.11.2020 12:45:35,78 LDAP> objectclass: top
[19E0:0013-0E30] 17.11.2020 12:45:35,78 LDAP> SendSearchEntry, sending entry CN=XXXXXX,O=YYY
[19E0:0013-0E30] 17.11.2020 12:45:35,78 LDAP> GetSearchEntry State
[19E0:0013-0E30] 17.11.2020 12:45:35,78 LDAP> Search State
[19E0:0013-0E30] 17.11.2020 12:45:35,78 LDAP> ***** Count of search entries returned (total): 1 *****
[19E0:0013-0E30] 17.11.2020 12:45:35,78 LDAP> Return Result State (Search operation)
[19E0:0011-0E30] 17.11.2020 12:45:35,78 LDAP> SendBufferFree
[19E0:0013-0E30] 17.11.2020 12:45:35,78 LDAP> InitForSearch
[19E0:0010-0E30] 17.11.2020 12:45:35,78 LDAP> BERGetTag State
[19E0:0010-0E30] 17.11.2020 12:45:35,78 LDAP> BERGetLeadingLengthByte State
[19E0:0010-0E30] 17.11.2020 12:45:35,78 LDAP> BERGetNext State
[19E0:0013-0E30] 17.11.2020 12:45:35,78 LDAP> Bind State
[19E0:0013-0E30] 17.11.2020 12:45:35,78 LDAP> Version: 3
[19E0:0013-0E30] 17.11.2020 12:45:35,78 LDAP> DN: CN=XXXXXX,O=YYY
[19E0:0013-0E30] 17.11.2020 12:45:35,78 LDAP> Method: 0x80 (Simple)
[19E0:0013-0E30] 17.11.2020 12:45:35,78 WebAuth> LOOKUP in view $Users (user='CN=XXXXXX/O=YYY' org='')
[19E0:0013-0E30] 17.11.2020 12:45:35,78 WebAuth> VERIFY password
[19E0:0013-0E30] 17.11.2020 12:45:35,78 WebAuth> GroupCache: WildCard Name='*'
[19E0:0013-0E30] 17.11.2020 12:45:35,78 WebAuth> GroupCache: Hierarchical Name='*/O=YYY'
[19E0:0013-0E30] 17.11.2020 12:45:35,78 WebAuth> GroupCache: Cached for User DN='CN=XXXXXX/O=YYY'
[19E0:0013-0E30] 17.11.2020 12:45:35,78 LDAP> Groups for name CN=XXXXXX/O=YYY:
[19E0:0013-0E30] 17.11.2020 12:45:35,78 LDAP> *
[19E0:0013-0E30] 17.11.2020 12:45:35,78 LDAP> */O=YYY
[19E0:0013-0E30] 17.11.2020 12:45:35,78 LDAP> Successful bind, user CN=XXXXXX,O=YYY authenticated as CN=XXXXXX/O=YYY
[19E0:0013-0E30] 17.11.2020 12:45:35,78 LDAP> Return Result State (Bind operation)
[19E0:0010-0E30] 17.11.2020 12:45:35,78 LDAP> SendBufferFree
[19E0:0013-0E30] 17.11.2020 12:45:35,78 LDAP> InitForSearch
[19F8:001F-16A0] 17.11.2020 12:45:35,78 PROTON> Session::init_via_server_context: enter
[19F8:001F-16A0] 17.11.2020 12:45:35,78 PROTON> Session::init_via_server_context2: enter
[19F8:001F-16A0] 17.11.2020 12:45:35,78 PROTON> Certificate::init: enter
[19F8:001F-16A0] 17.11.2020 12:45:35,78 PROTON> Certificate::init: subject: CN=app1/OU=Clients/O=GHK
[19F8:001F-16A0] 17.11.2020 12:45:35,78 PROTON> Certificate::init: exit
[19F8:001F-16A0] 17.11.2020 12:45:35,78 PROTON> SessionCache::find_session_entry: enter
[19F8:001F-16A0] 17.11.2020 12:45:35,78 PROTON> SessionCache::find_session_entry: certificate exists in cache: 550FF48299DF24B4600C8C27CB56FB5E71972EDD01
[19F8:001F-16A0] 17.11.2020 12:45:35,78 PROTON> SessionCache::find_session_entry: exit
[19F8:001F-16A0] 17.11.2020 12:45:35,78 PROTON> Session::get_password_from_request: enter
[19F8:001F-16A0] 17.11.2020 12:45:35,78 PROTON> Session::get_password_from_request: exit
[19F8:001F-16A0] 17.11.2020 12:45:35,78 PROTON> Session::init_hkey_from_cache_or_vault: enter
[19F8:001F-16A0] 17.11.2020 12:45:35,78 PROTON> SessionCache::get_idfile: enter
[19F8:001F-16A0] 17.11.2020 12:45:35,78 PROTON> SessionCache::get_idfile: get_idfile @00000176FE712FE0 rc=0 req_timeout_ms=0 elapsed_time_ms=0
[19F8:001F-16A0] 17.11.2020 12:45:35,78 PROTON> SessionCache::get_idfile: exit
[19F8:001F-16A0] 17.11.2020 12:45:35,78 PROTON> Session::init_hkey_from_memobj: enter
[19F8:001F-16A0] 17.11.2020 12:45:35,78 PROTON> Session::init_hkey_from_memobj: exit
[19F8:001F-16A0] 17.11.2020 12:45:35,78 PROTON> Session::init_hkey_from_cache_or_vault: rc=0 init_hkey_from_memobj
[19F8:001F-16A0] 17.11.2020 12:45:35,78 PROTON> Session::init_hkey_from_cache_or_vault: exit
[19F8:001F-16A0] 17.11.2020 12:45:35,78 PROTON> Session::init_via_server_context2: rc=0 client_cert_auth
[19F8:001F-16A0] 17.11.2020 12:45:35,78 PROTON> Session::init_via_server_context2: exit
[19F8:001F-16A0] 17.11.2020 12:45:35,78 PROTON> Session::init_via_server_context: rc=0 init
[19F8:001F-16A0] 17.11.2020 12:45:35,78 PROTON> Session::init_via_server_context: exit
[19F8:001F-16A0] 17.11.2020 12:45:35,78 NoteSearcher> Query: 'LoginedUsers'._id = 'CN=XXXXXX,O=YYY'
[19F8:001F-16A0] 17.11.2020 12:45:35,80 NoteSearcher> Query: 'LoginedUsers'._id = 'CN=XXXXXX,O=YYY', status=No error, idtable=20000770, count=0, time=2 ms
[19F8:001F-16A0] 17.11.2020 12:45:35,80 PROTON> Req:READNOTE FindBy:SRCH RetCode:65536 NoteCount:0 TimeMS:4
[19F8:001F-16A0] 17.11.2020 12:45:35,80 PROTON> Session::init_via_server_context: enter

anon-1234 · November 19, 2020, 7:37pm

We've not yet been able to declare support for a load-balanced deployment yet. Though, if configured properly, I am not sure why it wouldn't work.

In your LB, do you have session-affinity enabled? I think that will be required.

We used to store the session info in the domino database, but with many users we were seeing performance problems that we needed fixes for in base domino. It's been a while since we re-visited that. I can poke around and see if that's safe to turn back on. In the mean time, if session-affinity settings don't work with the load balancer, then you might have to wait for this kind of configuration until we can properly support the deployment scenario.

anon-967 · November 20, 2020, 8:23am

Thank you Dan, we are checking session affinity on the LB, which happily crashed last night. ;-) I keep you informed on that subject, when the repair team and testing is done. Thank you for pointing me to it.

anon-967 · March 17, 2021, 8:46am

What we did in the meantime, is to set up a single instance of IAM and a separate Domino/Proton Server. No LB between them. Today I upgraded to Domino 11.01 FP2 and IAM 1.7.0.

Still we occasionally find this error (besides the id cookie error) in our worker logs:

[2021-03-17T08:35:04][debug][CustomUtils]: renderError: {

"error": "invalid_request",

"error_description": "interaction session not found"

}

We are clueless about where to look for this intermittent problem. Any ideas?

Context:

[2021-03-17T08:34:39][debug][DominoDB]: Build query object: { query: '\'LoginedUsers\'._id = ?',
queryArgs: [ { ordinal: 1, value: 'CN=YYYYYYYY,O=ZZZ' } ],
queryFlags: { noViewRefresh: true },
start: 0,
itemNames: [ '@unid' ],
onErrorOptions: 'ON_ERROR_ABORT_REMAINING',
count: 1 }
[2021-03-17T08:34:39][debug][DominoDB]: DB.bulkReadDocuments.costTime = 19.00000000023283 ms.
[2021-03-17T08:34:39][debug][DominoDB]: Find 1 documents in findOne method
[2021-03-17T08:34:39][debug][DominoDB]: DB.useDocument & document.replaceItems for collection [LoginedUsers].costTime = 34.0000000001055 ms.
[2021-03-17T08:34:39][debug][DominoDB]: DB.useDocument & document.read for collection [LoginedUsers].costTime = 12.999999999919964 ms.
[2021-03-17T08:34:39][debug][CustomUtils]: do interactionCheck to check the policy for requiring End-User interactions
[2021-03-17T08:34:39][debug][DominoDB]: DB.createDocument for collection [AuthorizationCode].costTime = 8.000000000265572 ms.
[2021-03-17T08:35:04][debug][DominoDB]: DB.useDocument & document.replace for collection [LoginedUsers].costTime = 101.99999999986176 ms.
[2021-03-17T08:35:04][debug][CustomUtils]: renderError: {
"error": "invalid_request",
"error_description": "interaction session not found"
}
[2021-03-17T08:35:04][info][routes]: serviceRootPath = C:\IAM\views\static
[2021-03-17T08:35:15][info][routes]: serviceRootPath = C:\IAM\views\static
[2021-03-17T08:35:15][info][routes]: serviceRootPath = C:\IAM\views\static
[2021-03-17T08:35:16][info][routes]: serviceRootPath = C:\IAM\views\static
[2021-03-17T08:35:16][info][routes]: serviceRootPath = C:\IAM\views\static
[2021-03-17T08:35:17][debug][DominoDB]: commonConfig.ENABLE_QUERY_BY_ID setting is set to false
[2021-03-17T08:35:17][debug][DominoDB]: Build query object: { query: '\'LoginedUsers\'._id = ?',
queryArgs: [ { ordinal: 1, value: 'CN=KKKKKKKK,O=ZZZ' } ],
queryFlags: { noViewRefresh: true },
start: 0,
itemNames: [ '@unid' ],
onErrorOptions: 'ON_ERROR_ABORT_REMAINING',
count: 1 }
[2021-03-17T08:35:17][debug][DominoDB]: DB.bulkReadDocuments.costTime = 21.000000000185537 ms.
[2021-03-17T08:35:17][debug][DominoDB]: Find 1 documents in findOne method
[2021-03-17T08:35:17][debug][DominoDB]: DB.useDocument & document.replaceItems for collection [LoginedUsers].costTime = 32.000000000152795 ms.
[2021-03-17T08:35:17][debug][DominoDB]: DB.useDocument & document.read for collection [LoginedUsers].costTime = 12.999999999919964 ms.
[2021-03-17T08:35:17][debug][CustomUtils]: do interactionCheck to check the policy for requiring End-User interactions
[2021-03-17T08:35:17][debug][DominoDB]: DB.createDocument for collection [AuthorizationCode].costTime = 8.000000000265572 ms.
[2021-03-17T08:35:18][debug][DominoDB]: DB.useDocument & document.read for collection [AuthorizationCode].costTime = 7.999999999810825 ms.
[2021-03-17T08:35:18][debug][DominoDB]: DB.useDocument & document.replaceItems for collection [AuthorizationCode].costTime = 36.99999999980719 ms.
[2021-03-17T08:35:18][debug][DominoDB]: DB.useDocument & document.read for collection [LoginedUsers].costTime = 5.999999999858119 ms.
[2021-03-17T08:35:18][debug][DominoDB]: DB.createDocument for collection [AccessToken].costTime = 5.999999999858119 ms.
[2021-03-17T08:35:25][debug][DominoDB]: DB.useDocument & document.read for collection [LoginedUsers].costTime = 12.999999999919964 ms.
[2021-03-17T08:35:25][info][routes]: serviceRootPath = C:\IAM\views\static
[2021-03-17T08:35:26][info][routes]: serviceRootPath = C:\IAM\views\static
[2021-03-17T08:35:26][info][routes]: serviceRootPath = C:\IAM\views\static
[2021-03-17T08:35:26][info][routes]: serviceRootPath = C:\IAM\views\static
[2021-03-17T08:35:27][debug][DominoDB]: DB.useDocument & document.replace for collection [LoginedUsers].costTime = 9.000000000014552 ms.
[2021-03-17T08:35:27][debug][DominoDB]: DB.useDocument & document.read for collection [LoginedUsers].costTime = 7.999999999810825 ms.
[2021-03-17T08:35:27][debug][CustomUtils]: do interactionCheck to check the policy for requiring End-User interactions
[2021-03-17T08:35:27][debug][DominoDB]: DB.createDocument for collection [AuthorizationCode].costTime = 11.999999999716238 ms.
[2021-03-17T08:37:32][info][routes]: serviceRootPath = C:\IAM\views\static
[2021-03-17T08:38:39][info][routes]: serviceRootPath = C:\IAM\views\static
[2021-03-17T08:38:59][info][routes]: serviceRootPath = C:\IAM\views\static
[2021-03-17T08:39:40][info][routes]: serviceRootPath = C:\IAM\views\static
[2021-03-17T08:41:32][info][routes]: serviceRootPath = C:\IAM\views\static
[2021-03-17T08:41:32][info][routes]: serviceRootPath = C:\IAM\views\static
[2021-03-17T08:41:32][info][routes]: serviceRootPath = C:\IAM\views\static
[2021-03-17T08:45:18][info][routes]: serviceRootPath = C:\IAM\views\static
[2021-03-17T08:45:21][debug][DominoDB]: commonConfig.ENABLE_QUERY_BY_ID setting is set to false
[2021-03-17T08:45:21][debug][DominoDB]: Build query object: { query: '\'LoginedUsers\'._id = ?',
queryArgs: [ { ordinal: 1, value: 'CN=NNNNNNNN,O=ZZZ' } ],
queryFlags: { noViewRefresh: true },
start: 0,
itemNames: [ '@unid' ],
onErrorOptions: 'ON_ERROR_ABORT_REMAINING',
count: 1 }
[2021-03-17T08:45:21][debug][DominoDB]: DB.bulkReadDocuments.costTime = 27.000000000043656 ms.
[2021-03-17T08:45:21][debug][DominoDB]: Find 1 documents in findOne method
[2021-03-17T08:45:21][debug][DominoDB]: DB.useDocument & document.replaceItems for collection [LoginedUsers].costTime = 27.000000000043656 ms.
[2021-03-17T08:45:21][debug][DominoDB]: DB.useDocument & document.read for collection [Client].costTime = 6.999999999607098 ms.
[2021-03-17T08:45:21][debug][DominoDB]: DB.useDocument & document.read for collection [LoginedUsers].costTime = 6.000000000312866 ms.
[2021-03-17T08:45:21][debug][CustomUtils]: do interactionCheck to check the policy for requiring End-User interactions
[2021-03-17T08:45:21][debug][DominoDB]: DB.createDocument for collection [AuthorizationCode].costTime = 5.000000000109139 ms.
[2021-03-17T08:45:56][info][routes]: serviceRootPath = C:\IAM\views\static
[2021-03-17T08:47:28][info][routes]: serviceRootPath = C:\IAM\views\static
[2021-03-17T08:47:28][info][routes]: serviceRootPath = C:\IAM\views\static
[2021-03-17T08:47:55][debug][DominoDB]: commonConfig.ENABLE_QUERY_BY_ID setting is set to false
[2021-03-17T08:47:55][debug][DominoDB]: Build query object: { query: '\'LoginedUsers\'._id = ?',
queryArgs: [ { ordinal: 1, value: 'CN=PPPPPPPP,O=ZZZ' } ],
queryFlags: { noViewRefresh: true },
start: 0,
itemNames: [ '@unid' ],
onErrorOptions: 'ON_ERROR_ABORT_REMAINING',
count: 1 }
[2021-03-17T08:47:55][debug][DominoDB]: DB.bulkReadDocuments.costTime = 32.000000000152795 ms.
[2021-03-17T08:47:55][debug][DominoDB]: Find 1 documents in findOne method
[2021-03-17T08:47:55][debug][DominoDB]: DB.useDocument & document.replaceItems for collection [LoginedUsers].costTime = 38.99999999975989 ms.
[2021-03-17T08:47:55][debug][DominoDB]: DB.useDocument & document.read for collection [LoginedUsers].costTime = 10.000000000218279 ms.
[2021-03-17T08:47:55][debug][CustomUtils]: do interactionCheck to check the policy for requiring End-User interactions
[2021-03-17T08:47:55][debug][DominoDB]: DB.createDocument for collection [AuthorizationCode].costTime = 5.9999999994033715 ms.
[2021-03-17T08:47:55][debug][DominoDB]: DB.useDocument & document.read for collection [AuthorizationCode].costTime = 12.999999999919964 ms.
[2021-03-17T08:47:56][debug][DominoDB]: DB.useDocument & document.replaceItems for collection [AuthorizationCode].costTime = 38.00000000046566 ms.
[2021-03-17T08:47:56][debug][DominoDB]: DB.useDocument & document.read for collection [LoginedUsers].costTime = 7.999999999810825 ms.
[2021-03-17T08:47:56][debug][DominoDB]: DB.createDocument for collection [AccessToken].costTime = 6.000000000312866 ms.
[2021-03-17T08:48:18][debug][DominoDB]: DB.useDocument & document.read for collection [LoginedUsers].costTime = 12.000000000625732 ms.
[2021-03-17T08:48:18][info][routes]: serviceRootPath = C:\IAM\views\static

anon-1234 · March 17, 2021, 4:42pm

This can happen if a user hits back when primarily using page re-direction instead of opening a new window to do the oauth flow. Are you seeing any issues other than notes on the console related to this? We can try to turn off the logging if it's distracting.

interaction ids are only valid once, so if the page is navigated back to, you would see this error because the interaction has already been consumed and no longer exists.

anon-967 · March 18, 2021, 10:19am

Thank you, Dan.

Yes, sometimes users see that error message and call us. With your background information, we will now begin to ask them what they did before coming to that message. I never thought of user interaction and behaviour, thank you for pointing me to that.

Is there a piece of documentation for other messages somewhere? I got these:

"error_description": "unrecognized route"

interaction session id cookie not found (this one seems to explain itself because mostly there is an invalid user login (unknown user) ahead of it.

method GET not allowed on /interaction/3e9765a3-59c7-4c11-a1a4-99d774c73971/login

I like the logging, though.

anon-1234 · March 18, 2021, 6:57pm

unrecognized route probably means that the koa server had a request come in that didn't match a configured route. There could be a few reasons for this... maybe a user editing/deleting part of the request URI to attempt to recover from another error page.

If you'd like we might be able to add the route that was requested to the error logs so you can see what's going on there. I can create a bug in our backlog for that.

method GET not allowed on /interaction/3e9765a3-59c7-4c11-a1a4-99d774c73971/login

This one is interesting... this might be a result of a redirect to the login because the sessionid cookie was not valid (and neither was the interaction). Maybe a browser restoring tabs in the middle of a login?