Client displays Connection timed out after token expiration #5066
Assignees
Labels
Milestone
Comments
|
Please provide the relevant client logs, I'd expect them to contain a log message that tells us why the retry failed. |
|
I added the part of the logs where the 401s started. I can upload the whole log file if you need more. |
|
Hmm thats weird. Actually the 401 should cause the retry to be queued and trigger a reauth... |
|
Only saw it now that you are using a 2.10 client... |
|
Alright, I'll redo the test with the 3.0 client. 👍 |
|
Here is a short update: Ok now it's getting really strange.
I only once got the "Connection timed out" error, the other times the client just looks like it's still syncing. I'll attach a log file once I managed to remove distracting events from the log. |
|
Ok so here is what I found with the client version This is the first POST request that fails the client then does a token refresh (I can see the new token in the logs) but doesn't retry/continue with the POST requests, I only see PROPFINDs after the first failed POST request. |
|
Seems still happening with New logs uploaded here:
|
|
Server logs |
|
Looks like a refresh token error. The keycloak on this instance is configured with default values. That means, each refresh token can only be used once. This can cause problems if we do parallel upload queues. They would need to sync the refresh token on the client side across all queues. In web we see a similar problem when using more than one tab. Is that setup supported? @TheOneRing @fmoc
|
Same as with oC10 OAuth 2.0 app. No problem – can be handled in all client platforms. |
|
If request has expired |
|
@micbar @michaelstingl Not really sure what needs to be done from server side here? Does the server return the wrong status code? I couldn't find anything in the logs. Could you point me to it? If the server does return the |
I don't see a proper |
|
After investigation with @wkloucek we found a problem int the dektop client that might cause this problem. At least it makes finding the root cause of the When the desktop clients gets a Just upload a folder with a lot of small files (upload needs to take more than 5mins at least). After the first See mitmproxy screenshot for illustration: As you can see after the @michaelstingl @TheOneRing maybe you have an idea? |
|
Desktop client should be able to deal with the
|
|
Yes, it is still unclear what causes the I can reproduce stale client after |
|
If we receive a 401, we will queue the failed request, and queue all new requests, while we start to refresh the token. In the mitmproxy abort I can't see anything about the put jobs from the tus upload, shouldn't they get a 401 too? |
micbar
added
the
Priority:p2-high
|
After @wkloucek set the token lifetime to 5 Minutes on
|
POSToperation canceled0ef4ac77-2ce3-41fc-923c-22df69cc857d
9f1c4785c4ebb22816e1f89a2cbc3e88.json.tar.gz 248eb373-3883-4433-983f-f7d2f7c00594
71445ac6-df4b-40cf-9ffd-33ceb657dc3b
connection closed< 120 msnone of these was found in either the Traefik access log, nor in the oCIS access log > 120 ms12b58fbc-87b5-4102-ada9-e7fba3f34c78not found in oCIS and Traefik access logs c1f1a2c6-6606-4dae-aeb3-6457dec6d5ca47ede651-5ba0-4a84-b926-f9d1db8c5b890f4c92a3-0eeb-44e5-ad23-5e53bddb5f1798fe7dec-6269-4b8f-8bf7-4defed95862aae652a0a-5a01-45b7-8c74-fc58f530f71a3b192724-815f-415d-8280-28f8020fd666db2f0ac1-51d9-4ece-afe2-18943cbd6951196cb09b-1d62-4a1b-b225-79b9bc4f173b75129963-5551-41a8-ac75-4ebd4c7b6b08PROPFINDnone of these was found in either the Traefik access log, nor in the oCIS access log |
|
I can't reproduce "connection closed" when MITMproxy is active. But I can see the 401 behaviour. POST -> 201
POST -> 401
|
|
Without MITMproxy it's quite easy to reproduce:
Please note the different "Issue" for the first entry vs. all other entries |
|
The respective log for the "Host requires authentication" entry: The respective logs for the connection closed entry: |
|
New insights from Wireshark for request c02c6d1d-1145-42a6-a39a-5af87c51f75d:
stream-11-connection-closed.pcapng.tar.gz It shows many interesting things:
|
|
@wkloucek Thank you for investigating! Very valuable insights! |
|
I wrote down how to come to the debugging setup in owncloud/client#10299 |
|
It seems the server is closing the connection before the client has sent all bytes. We could verify this by reading (and discarding) the body before closing the connection like this: diff --git a/services/proxy/pkg/middleware/authentication.go b/services/proxy/pkg/middleware/authentication.go
index d32decfe5..72d953cb0 100644
--- a/services/proxy/pkg/middleware/authentication.go
+++ b/services/proxy/pkg/middleware/authentication.go
@@ -2,6 +2,8 @@ package middleware
import (
"fmt"
+ "io"
+ "io/ioutil"
"net/http"
"regexp"
"strings"
@@ -104,6 +106,8 @@ func Authentication(auths []Authenticator, opts ...Option) func(next http.Handle
webdav.HandleWebdavError(w, b, err)
}
+ defer r.Body.Close()
+ io.Copy(ioutil.Discard, r.Body)
})
}
}Unfortunately, this would leave us open to DoS attacks because clients could easily saturate all connections. I'm not sure why oc10 closes connections differently... |
micbar
added
Priority:p1-urgent
|
Basically our problem is summarized in golang/go#15527, which is also referenced in the underlying code: It can easily be triggered by a curl command: (where |
|
This makes no sense to me, really. If the HTTP spec mandates reading the entire request body (which honestly is how most servers do it; try sending some request that exceeds |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Pre-submission Checks
Describe the bug
@michaelstingl showed me that when the client is uploading a folder with lots of files and the
uploadsync of the folder take longer than the access token lifetime, then the client eventually displays "Connection timed out".Then it takes either an unknown amount of time or a client restart to make the client sync again.
Expected behavior
The client should refresh the access token and transparently use the new token for the uploads.
Steps to reproduce the issue
cd ocis/deployments/examples/ocis_keycloak//etc/hostsfile:docker-compose up -docis.owncloud.testConnection timed outerrorScreenshots
No response
Logs
client_test.log
This is a mitmproxy flows file. Load it with
mitmproxy -rfile=client_test.logIn there you can see that after the few successful uploads, the token expired and then a bunch of PROPFINDs fail with 401 errors.
Then for some reason a bunch of PROPFINDs work again and then all remaining PROPFINDs fail with 401.
Client logs:
Client version number
ownCloud Version 2.10.1 (build 7187) but also reproducible with the current testing client version.
Desktop environment (Linux only)
No response
Client package version and origin (Linux only)
No response
Installation path (Windows only)
No response
Server information
Current oCIS see description above
Additional context
No response
The text was updated successfully, but these errors were encountered: