Chunked-upload errors

After fixing Request signature we calculated does not match (bis) [chunked-upload] and using 3.0.5 I could observe the following problem using chunked-upload (behind Cloudflare) to an unstructured S3 object storage backend.

./cells configure sites gives

+---+--------------------------+--------------+--------------------------+
| # |               BIND(S)    |     TLS      |          EXTERNAL URL    |
+---+--------------------------------------+--------------+--------------+
| 0 | https://mydomain.org:443 | Lets Encrypt | https://mydomain.org     |
+---+--------------------------+--------------+--------------------------+

One is, I think, a notice I can see dozen of times during a single upload (of a 100MB file split into 5MB chunks):
2022-02-28T19:13:21.777Z DEBUG http: TLS handshake error from 172.69.102.71:54547: EOF
The IP address often change, here is an extract

141.101.109.13
162.158.113.26
162.158.117.186
162.158.196.20
162.158.224.82
162.158.248.73
172.68.206.73
172.69.102.71
172.69.193.35
172.69.198.69
172.70.101.71
172.70.103.69
172.70.121.8
172.70.84.49

They all belong to Cloudflare. My interpretation is that, for an unknown reason, there are a lot of requests (initiated?) by Cells to Cloudflare (or to itself going through CF?) which result in an error.

This is clearly not desirable and it’s to be noted that they are logged in DEBUG level (instead of WARNING)
I’m already in debug loglevel, how to further investigate this?

The other kind of error (which was, again, mislabeled as DEBUG instead of WARNING/ERROR) is:

2022-02-28T19:09:59.422Z	DEBUG	pydio.gateway.data	jwt rawIdToken verify: failed	{"error": "token_expired", "errorVerbose": "token_expired\ngithub.com/pydio/cells/vendor/github.com/ory/fosite.(*Fosite).IntrospectToken\n\tgithub.com/pydio/cells/vendor/github.com/ory/fosite/introspect.go:69\ngithub.com/pydio/cells/common/auth.(*oryprovider).Verify\n\tgithub.com/pydio/cells/common/auth/jwt_ory.go:381\ngithub.com/pydio/cells/common/auth.(*JWTVerifier).verifyTokenWithRetry\n\tgithub.com/pydio/cells/common/auth/jwt.go:245\ngithub.com/pydio/cells/common/auth.(*JWTVerifier).Verify\n\tgithub.com/pydio/cells/common/auth/jwt.go:293\ngithub.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd.pydioAuthHandler.ServeHTTP\n\tgithub.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd/gateway-pydio-auth-handler.go:83\ngithub.com/pydio/cells/common/service/context.HttpSpanHandlerWrapper.func1\n\tgithub.com/pydio/cells/common/service/context/span.go:198\nnet/http.HandlerFunc.ServeHTTP\n\tnet/http/server.go:2042\ngithub.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd.criticalErrorHandler.ServeHTTP\n\tgithub.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd/generic-handlers.go:775\ngithub.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd/http.(*Server).Start.func1\n\tgithub.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd/http/server.go:115\nnet/http.HandlerFunc.ServeHTTP\n\tnet/http/server.go:2042\nnet/http.serverHandler.ServeHTTP\n\tnet/http/server.go:2843\nnet/http.(*conn).serve\n\tnet/http/server.go:1925\nruntime.goexit\n\truntime/asm_amd64.s:1374"}
2022-02-28T19:09:59.426Z	DEBUG	pydio.gateway.data	jwt rawIdToken verify: failed	{"error": "{\"id\":\"\",\"code\":0,\"detail\":\"token_expired\",\"status\":\"\"}"}
2022-02-28T19:09:59.427Z	DEBUG	pydio.gateway.data	jwt rawIdToken verify: failed	{"error": "{\"id\":\"token.invalid\",\"code\":401,\"detail\":\"Cannot validate token\",\"status\":\"Unauthorized\"}"}
2022-02-28T19:09:59.428Z	DEBUG	pydio.gateway.data	jwt rawIdToken verify: failed	{"error": "token_expired", "errorVerbose": "token_expired\ngithub.com/pydio/cells/vendor/github.com/ory/fosite.(*Fosite).IntrospectToken\n\tgithub.com/pydio/cells/vendor/github.com/ory/fosite/introspect.go:69\ngithub.com/pydio/cells/common/auth.(*oryprovider).Verify\n\tgithub.com/pydio/cells/common/auth/jwt_ory.go:381\ngithub.com/pydio/cells/common/auth.(*JWTVerifier).verifyTokenWithRetry\n\tgithub.com/pydio/cells/common/auth/jwt.go:245\ngithub.com/pydio/cells/common/auth.(*JWTVerifier).verifyTokenWithRetry\n\tgithub.com/pydio/cells/common/auth/jwt.go:254\ngithub.com/pydio/cells/common/auth.(*JWTVerifier).Verify\n\tgithub.com/pydio/cells/common/auth/jwt.go:293\ngithub.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd.pydioAuthHandler.ServeHTTP\n\tgithub.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd/gateway-pydio-auth-handler.go:83\ngithub.com/pydio/cells/common/service/context.HttpSpanHandlerWrapper.func1\n\tgithub.com/pydio/cells/common/service/context/span.go:198\nnet/http.HandlerFunc.ServeHTTP\n\tnet/http/server.go:2042\ngithub.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd.criticalErrorHandler.ServeHTTP\n\tgithub.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd/generic-handlers.go:775\ngithub.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd/http.(*Server).Start.func1\n\tgithub.com/pydio/cells/vendor/github.com/pydio/minio-srv/cmd/http/server.go:115\nnet/http.HandlerFunc.ServeHTTP\n\tnet/http/server.go:2042\nnet/http.serverHandler.ServeHTTP\n\tnet/http/server.go:2843\nnet/http.(*conn).serve\n\tnet/http/server.go:1925\nruntime.goexit\n\truntime/asm_amd64.s:1374"}
2022-02-28T19:09:59.430Z	DEBUG	pydio.gateway.data	jwt rawIdToken verify: failed	{"error": "{\"id\":\"\",\"code\":0,\"detail\":\"token_expired\",\"status\":\"\"}"}
2022-02-28T19:09:59.432Z	DEBUG	pydio.gateway.data	jwt rawIdToken verify: failed	{"error": "{\"id\":\"token.invalid\",\"code\":401,\"detail\":\"Cannot validate token\",\"status\":\"Unauthorized\"}"}
2022-02-28T19:09:59.432Z	DEBUG	pydio.gateway.data	error verifying token	{"token": "A7pZEOJIuknwJxUguVuHbsHI8L1JG80KdxDyCqkxBsM.XxvpHcy06UOsNG5BrrIsjYTlqKuEuIlFmclcJNbAISE", "error": "empty idToken"}
  • About the empty idToken, I read Users logged out immediately after login - #2 by bsinou, but it can’t be a cache problem (the Firefox console was opened during the upload what discard any caching problem), and the server time is correct (server = UTC+00, client = UTC-03)

  • About the token_expired, I can’t tell.

But it seems clearly related to the random 403 (or Cloudflare 520) returned to the browser these PUT /io/foobar.mp4?partNumber=4&uploadId=xxxx requests)

The uploader is able to overcome these issues (reuploading chunks until it succeeds) but this is still a quality/instability problem I’d like to see resolved before I roll into production.

thx!

Any hint about this @charles ?

Hello @drzraf

I’m not really sure about your case here. Do you mean that these connections are opened by the server to these cloudfare urls ? Maybe the micro-services are binding themselves on a public ip and internal calls are going through cloudflare? do you have a internal (private) IP on your server? Normally it is priviledged for binding the internal services, and only the main proxy is binding on the public IP.

It happens only with chunked-upload (whatever chunk-size I set). I don’t know if my interface bindings are corrects. Any command-line you’d like ?


1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
       valid_lft forever preferred_lft forever
    inet6 ::1/128 scope host 
       valid_lft forever preferred_lft forever
2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP group default qlen 1000
    link/ether fa:16:xx:xx:xx:xx brd ff:ff:ff:ff:ff:ff
    inet 51.xx.xx.xx/32 brd 51.xx.xx.xx scope global dynamic eth0
       valid_lft 65372sec preferred_lft 65372sec
    inet 10.0.0.1/8 scope global eth0:1
       valid_lft forever preferred_lft forever
    inet6 2001:xxxx/128 scope global 
       valid_lft forever preferred_lft forever
    inet6 fe80::f816:3eff:fee7:2a12/64 scope link 
       valid_lft forever preferred_lft forever
$ sudo ss -taple | grep -f <(pgrep -wf pydio) -
LISTEN   0         128                0.0.0.0:37193              0.0.0.0:*       users:(("cells",pid=9000,fd=18)) uid:998 ino:92390272 sk:3 <->                 
LISTEN   0         128                0.0.0.0:9001               0.0.0.0:*       users:(("cells",pid=8996,fd=17)) uid:998 ino:92389820 sk:4 <->                 
LISTEN   0         128                0.0.0.0:9002               0.0.0.0:*       users:(("cells",pid=8991,fd=18)) uid:998 ino:92390529 sk:5 <->                 
LISTEN   0         128                0.0.0.0:34243              0.0.0.0:*       users:(("cells",pid=8957,fd=84)) uid:998 ino:92388187 sk:b <->                 
LISTEN   0         128                      *:32873                    *:*       users:(("cells",pid=9029,fd=17)) uid:998 ino:92392178 sk:c v6only:0 <->        
LISTEN   0         128                      *:44649                    *:*       users:(("cells",pid=9006,fd=17)) uid:998 ino:92391414 sk:d v6only:0 <->        
LISTEN   0         128                      *:41673                    *:*       users:(("cells",pid=9058,fd=17)) uid:998 ino:92391382 sk:e v6only:0 <->        
LISTEN   0         128                      *:37257                    *:*       users:(("cells",pid=8957,fd=269)) uid:998 ino:92390764 sk:f v6only:0 <->       
LISTEN   0         128                      *:43081                    *:*       users:(("cells",pid=8957,fd=262)) uid:998 ino:92390747 sk:10 v6only:0 <->      
LISTEN   0         128                      *:44297                    *:*       users:(("cells",pid=8957,fd=243)) uid:998 ino:92390688 sk:11 v6only:0 <->      
LISTEN   0         128                      *:36201                    *:*       users:(("cells",pid=8987,fd=36)) uid:998 ino:92390460 sk:12 v6only:0 <->       
LISTEN   0         128                      *:42857                    *:*       users:(("cells",pid=8957,fd=178)) uid:998 ino:92389909 sk:13 v6only:0 <->      
LISTEN   0         128                      *:34409                    *:*       users:(("cells",pid=8957,fd=72)) uid:998 ino:92388245 sk:14 v6only:0 <->       
LISTEN   0         128                      *:46187                    *:*       users:(("cells",pid=9129,fd=15)) uid:998 ino:92391145 sk:15 v6only:0 <->       
LISTEN   0         128                      *:42347                    *:*       users:(("cells",pid=8957,fd=247)) uid:998 ino:92390393 sk:16 v6only:0 <->      
LISTEN   0         128                      *:35243                    *:*       users:(("cells",pid=8957,fd=213)) uid:998 ino:92390504 sk:17 v6only:0 <->      
LISTEN   0         128                      *:37931                    *:*       users:(("cells",pid=8957,fd=177)) uid:998 ino:92389905 sk:18 v6only:0 <->      
LISTEN   0         128                      *:41419                    *:*       users:(("cells",pid=8957,fd=144)) uid:998 ino:92389574 sk:19 v6only:0 <->      
LISTEN   0         128                      *:41291                    *:*       users:(("cells",pid=8957,fd=83)) uid:998 ino:92388859 sk:1a v6only:0 <->       
LISTEN   0         128                      *:44301                    *:*       users:(("cells",pid=9115,fd=15)) uid:998 ino:92391120 sk:1c v6only:0 <->       
LISTEN   0         128                      *:34029                    *:*       users:(("cells",pid=8957,fd=274)) uid:998 ino:92390812 sk:1d v6only:0 <->      
LISTEN   0         128                      *:33453                    *:*       users:(("cells",pid=8957,fd=40)) uid:998 ino:92389039 sk:1e v6only:0 <->       
LISTEN   0         128                      *:39247                    *:*       users:(("cells",pid=9047,fd=17)) uid:998 ino:92392655 sk:1f v6only:0 <->       
LISTEN   0         128                      *:43343                    *:*       users:(("cells",pid=9041,fd=17)) uid:998 ino:92391291 sk:20 v6only:0 <->       
LISTEN   0         128                      *:35311                    *:*       users:(("cells",pid=9009,fd=17)) uid:998 ino:92391869 sk:21 v6only:0 <->       
LISTEN   0         128                      *:42991                    *:*       users:(("cells",pid=8957,fd=214)) uid:998 ino:92390508 sk:22 v6only:0 <->      
LISTEN   0         128                      *:33807                    *:*       users:(("cells",pid=8957,fd=172)) uid:998 ino:92389884 sk:23 v6only:0 <->      
LISTEN   0         128                      *:39567                    *:*       users:(("cells",pid=8957,fd=142)) uid:998 ino:92389452 sk:24 v6only:0 <->      
LISTEN   0         128                      *:41999                    *:*       users:(("cells",pid=8957,fd=141)) uid:998 ino:92389058 sk:25 v6only:0 <->      
LISTEN   0         128                      *:http                     *:*       users:(("cells",pid=8957,fd=284)) uid:998 ino:92388835 sk:26 v6only:0 <->      
LISTEN   0         128                      *:46769                    *:*       users:(("cells",pid=9124,fd=14)) uid:998 ino:92391151 sk:27 v6only:0 <->       
LISTEN   0         128                      *:46193                    *:*       users:(("cells",pid=9125,fd=14)) uid:998 ino:92391112 sk:28 v6only:0 <->       
LISTEN   0         128                      *:42289                    *:*       users:(("cells",pid=8974,fd=20)) uid:998 ino:92391461 sk:29 v6only:0 <->       
LISTEN   0         128                      *:39633                    *:*       users:(("cells",pid=8991,fd=13)) uid:998 ino:92390513 sk:2a v6only:0 <->       
LISTEN   0         128                      *:34929                    *:*       users:(("cells",pid=8957,fd=179)) uid:998 ino:92389913 sk:2b v6only:0 <->      
LISTEN   0         128                      *:33201                    *:*       users:(("cells",pid=8957,fd=145)) uid:998 ino:92389578 sk:2c v6only:0 <->      
LISTEN   0         128                      *:34259                    *:*       users:(("cells",pid=9061,fd=17)) uid:998 ino:92391903 sk:2d v6only:0 <->       
LISTEN   0         128                      *:39443                    *:*       users:(("cells",pid=9121,fd=15)) uid:998 ino:92391834 sk:2e v6only:0 <->       
LISTEN   0         128                      *:36179                    *:*       users:(("cells",pid=9113,fd=15)) uid:998 ino:92391130 sk:2f v6only:0 <->       
LISTEN   0         128                      *:45459                    *:*       users:(("cells",pid=8957,fd=231)) uid:998 ino:92390212 sk:30 v6only:0 <->      
LISTEN   0         128                      *:42707                    *:*       users:(("cells",pid=8975,fd=15)) uid:998 ino:92389970 sk:31 v6only:0 <->       
LISTEN   0         128                      *:37683                    *:*       users:(("cells",pid=8957,fd=175)) uid:998 ino:92389897 sk:32 v6only:0 <->      
LISTEN   0         128                      *:35859                    *:*       users:(("cells",pid=8957,fd=173)) uid:998 ino:92389887 sk:33 v6only:0 <->      
LISTEN   0         128                      *:38259                    *:*       users:(("cells",pid=8957,fd=14)) uid:998 ino:92388792 sk:34 v6only:0 <->       
LISTEN   0         128                      *:45461                    *:*       users:(("cells",pid=8997,fd=17)) uid:998 ino:92392142 sk:35 v6only:0 <->       
LISTEN   0         128                      *:40981                    *:*       users:(("cells",pid=8957,fd=271)) uid:998 ino:92391470 sk:36 v6only:0 <->      
LISTEN   0         128                      *:33525                    *:*       users:(("cells",pid=9002,fd=12)) uid:998 ino:92390053 sk:37 v6only:0 <->       
LISTEN   0         128                      *:39541                    *:*       users:(("cells",pid=8957,fd=82)) uid:998 ino:92389054 sk:38 v6only:0 <->       
LISTEN   0         128                      *:38325                    *:*       users:(("cells",pid=8957,fd=71)) uid:998 ino:92388241 sk:39 v6only:0 <->       
LISTEN   0         128                      *:34521                    *:*       users:(("cells",pid=8957,fd=266)) uid:998 ino:92390755 sk:3b v6only:0 <->      
LISTEN   0         128                      *:44729                    *:*       users:(("cells",pid=8957,fd=66)) uid:998 ino:92389043 sk:3c v6only:0 <->       
LISTEN   0         128                      *:38553                    *:*       users:(("cells",pid=8957,fd=23)) uid:998 ino:92388820 sk:3d v6only:0 <->       
LISTEN   0         128                      *:38969                    *:*       users:(("cells",pid=8957,fd=16)) uid:998 ino:92388806 sk:3e v6only:0 <->       
LISTEN   0         128                      *:41499                    *:*       users:(("cells",pid=9107,fd=14)) uid:998 ino:92391013 sk:40 v6only:0 <->       
LISTEN   0         128                      *:34651                    *:*       users:(("cells",pid=8957,fd=176)) uid:998 ino:92389901 sk:41 v6only:0 <->      
LISTEN   0         128                      *:36859                    *:*       users:(("cells",pid=8957,fd=140)) uid:998 ino:92388928 sk:42 v6only:0 <->      
LISTEN   0         128                      *:https                    *:*       users:(("cells",pid=8957,fd=283)) uid:998 ino:92388834 sk:43 v6only:0 <->      
LISTEN   0         128                      *:43035                    *:*       users:(("cells",pid=8957,fd=21)) uid:998 ino:92388816 sk:44 v6only:0 <->       
LISTEN   0         128                      *:44253                    *:*       users:(("cells",pid=8957,fd=259)) uid:998 ino:92390705 sk:45 v6only:0 <->      
LISTEN   0         128                      *:40733                    *:*       users:(("cells",pid=8957,fd=67)) uid:998 ino:92388235 sk:46 v6only:0 <->       
LISTEN   0         128                      *:34079                    *:*       users:(("cells",pid=8957,fd=260)) uid:998 ino:92390733 sk:47 v6only:0 <->      
LISTEN   0         128                      *:34911                    *:*       users:(("cells",pid=8957,fd=180)) uid:998 ino:92389918 sk:48 v6only:0 <->      
LISTEN   0         128                      *:38591                    *:*       users:(("cells",pid=8996,fd=10)) uid:998 ino:92389358 sk:49 v6only:0 <->       
LISTEN   0         128                      *:8000                     *:*       users:(("cells",pid=8957,fd=15)) uid:998 ino:92388798 sk:4a v6only:0 <->       
LISTEN   0         128                      *:37889                    *:*       users:(("cells",pid=8957,fd=263)) uid:998 ino:92390760 sk:4b v6only:0 <->      
LISTEN   0         128                      *:38177                    *:*       users:(("cells",pid=8957,fd=255)) uid:998 ino:92390729 sk:4c v6only:0 <->      
LISTEN   0         128                      *:42017                    *:*       users:(("cells",pid=8957,fd=211)) uid:998 ino:92390563 sk:4d v6only:0 <->      
LISTEN   0         128                      *:33571                    *:*       users:(("cells",pid=9114,fd=15)) uid:998 ino:92391156 sk:4e v6only:0 <->       
LISTEN   0         128                      *:45699                    *:*       users:(("cells",pid=8957,fd=264)) uid:998 ino:92390751 sk:4f v6only:0 <->      
LISTEN   0         128                      *:44931                    *:*       users:(("cells",pid=8957,fd=245)) uid:998 ino:92390384 sk:50 v6only:0 <->      
LISTEN   0         128                      *:8003                     *:*       users:(("cells",pid=8957,fd=10)) uid:998 ino:92388788 sk:51 v6only:0 <->       
LISTEN   0         128                      *:41189                    *:*       users:(("cells",pid=8957,fd=81)) uid:998 ino:92388261 sk:52 v6only:0 <->       
LISTEN   0         128                      *:39301                    *:*       users:(("cells",pid=8957,fd=79)) uid:998 ino:92388257 sk:53 v6only:0 <->       
LISTEN   0         128                      *:43461                    *:*       users:(("cells",pid=8957,fd=143)) uid:998 ino:92388932 sk:54 v6only:0 <->      
LISTEN   0         128                      *:34023                    *:*       users:(("cells",pid=8957,fd=273)) uid:998 ino:92390809 sk:55 v6only:0 <->      
LISTEN   0         128                      *:45063                    *:*       users:(("cells",pid=8957,fd=244)) uid:998 ino:92390691 sk:56 v6only:0 <->      
LISTEN   0         128                      *:43911                    *:*       users:(("cells",pid=9000,fd=13)) uid:998 ino:92390259 sk:57 v6only:0 <->       
LISTEN   0         128                      *:38631                    *:*       users:(("cells",pid=8957,fd=227)) uid:998 ino:92390178 sk:58 v6only:0 <->      
LISTEN   0         128                      *:39175                    *:*       users:(("cells",pid=8957,fd=181)) uid:998 ino:92389921 sk:59 v6only:0 <->      
LISTEN   0         128                      *:44039                    *:*       users:(("cells",pid=8957,fd=174)) uid:998 ino:92389891 sk:5a v6only:0 <->      
LISTEN   0         128                      *:36423                    *:*       users:(("cells",pid=8957,fd=77)) uid:998 ino:92388253 sk:5b v6only:0 <->       
LISTEN   0         128                      *:38087                    *:*       users:(("cells",pid=8957,fd=86)) uid:998 ino:92388867 sk:5c v6only:0 <->       
LISTEN   0         128                      *:44583                    *:*       users:(("cells",pid=8957,fd=18)) uid:998 ino:92388165 sk:5d v6only:0 <->

I was able to confirm that the problem was exclusively due to Cloudflare reverse-proxy.
When times come to reenable it, I’ll try to pinpoint and let you know which particular CF settings was at cause.