Unexpected redirect to the access-denied page despite valid SSO session

[micbar]

Steps to reproduce

1. Use Infinite Scale with Keycloak, set Access Token Lifetime to 300s
2. Wait 300s

Expected behaviour

The WebUI should stay logged in for the time of the SSO session (In this case 8 hours)

Actual behaviour

The browser is redirected to the access-denied page

Network

Environment general

ownCloud	Infinite Scale
Edition	Community
Web Version	3.0.0-rc.1+357c6a98a
Version	7.0.0-rc.35

Browser log

Insert your browser log here, this could for example include:

a) The javascript console log
b) The network log 

[kulmann]

Two things that are suspicious so far:

• there are 2 - in words TWO - token requests happening at the same time at the time when the notifications request gets a 401
• the notifications request seems to use the OLD access token, not the one that was refreshed just now.

Might be an awful timing issue with notifications and token requests happening at the same time... usually that would not be an issue, because a failing notifications request would be fine / we could just ignore it. But since we have the workaround of interpreting the 401 on notifications as "user was logged out in the backend" this turns out this way (redirect to the access denied page).

[kulmann]

@micbar We do the token renewal 10 seconds before the expiration. Is the old access token still accepted during this 10 seconds? Or already rejected when we obtained a new one?

[micbar]

good question. We need to debug that.

[micbar]

@dragonchaser Can you give a hint? I think we store the access token in the proxy cache by the sessionID which would mean that the renewal will overwrite the old token in the cache.

[JammingBen]

We do the token renewal 10 seconds before the expiration. Is the old access token still accepted during this 10 seconds? Or already rejected when we obtained a new one?

I've tested it by increasing this to 60 seconds. That means Web does the token renewal 60 before a token expires. During that 60 seconds, I tried to curl an authenticated endpoint with the old token, which returned valid 200 responses. After the 60 seconds, it returned 401. So it looks like to old token is still valid until it finally expires... which makes this issue even more confusing to me.

Edit: I tested locally with the build-in IDP. Now doing another test with a Keycloak deployment.
Edit2: Same result with a Keycloak deployment.

[JammingBen]

I tried to debug this further, let me try to explain my findings. Right away: I don't think this is a timing issue with the token renewal. I think the notification endpoint just sometimes returns a 401 for whatever reason.

On 0001.schule, token renewal takes places every 5 minutes. Notifications get polled every 30 seconds. That means we should see 10 (maybe 9) notification requests between token renewals. If the notification request would clash with the token renewal, it therefore would affect every 10th (or 9th) notification request. But that is not the case. It happens randomly, sometimes after just 6 notification requests. (The token requests after the failed notification requests don't happen because of the token renewal, but because we handle the auth error (?). Although that last point, I'm not sure... maybe they come from another issue.)

Also, I've had scenarios locally where the token renewal and the notification request took place at the very exact time according to the network waterfall diagram - no issues whatsoever.

My last finding, which is a bit odd and may be a coincidence: the issue happens when I'm browsing in another browser tab. If I'm in the Web tab directly, I don't get 401's.

[kulmann]

Our handling of auth errors indeed does not only redirect to the accessDenied page but also clears all session information from the session storage and removes the user from memory / the application state. I don't know why it then tries to re-authenticate the user (as the accessDenied page is an anonymous page this should not happen). But I can imagine that something ™️ triggers a token renewal after all session information has been removed.

[kulmann]

Needs further debugging as for why the notifications endpoint sometimes runs into a 401.

Until then, since this is a P1, I would like to propose that we remove the auth error handler from the notifications 401. I.e. not redirect to accessDenied anymore if notifications has a 401. We can re-introduce it later. Downside would be that a backend channel logout can go unnoticed for a longer time (until the user navigates into a subfolder, parent folder or different space, which currently also reacts to the 401 in the same way). Do you agree @micbar and @tbsbdr ?

[JammingBen]

To add on top of my findings above:

That means we should see 10 (maybe 9) notification requests between token renewals.

Turns out that doesn't need to be the case. When the browser sets a tab in an inactive state it may affect JS timers and intervals... which kinda invalidates this point. But the following point is still valid and hints that token renewal and notification requests should to along even when they happen at the same time.

Either way, I agree with @kulmann 👍

[micbar]

agreed @kulmann

[tbsbdr]

agreed @kulmann

[kulmann]

Has been resolved by not reacting to the 401 from notifications requests anymore...