lookup user by id as well #85

butonic · 2020-08-11T08:24:42Z

we should add the uuid as a separate claim
fix warnings in log => moved to https://github.com/owncloud/ocis-proxy/issues/86
changelog

Signed-off-by: Jörn Friedrich Dreyer <jfd@butonic.de>

update-docs · 2020-08-11T08:25:02Z

Thanks for opening this pull request! The maintainers of this repository would appreciate it if you would create a changelog item based on your changes.

PVince81 · 2020-08-11T08:31:55Z

download works and md5 is fine, but we got these:

2020-08-11T10:30:00+02:00 INF access token is already provided pkg=rhttp service=reva traceid=9a614ab15294bbfcd19421c581a9b91d
2020-08-11T10:30:00+02:00 DBG http routing: head=data tail=/test.png svc=data pkg=rhttp service=reva
[tusd] 2020/08/11 10:30:00 event="RequestIncoming" method="GET" path="/test.png" requestId="" 
2020-08-11T10:30:00+02:00 INF tusd routing: path=/test.png pkg=rhttp service=reva traceid=9a614ab15294bbfcd19421c581a9b91d
2020-08-11 10:30:00.955675 I | http: superfluous response.WriteHeader call from net/http/httputil.(*ReverseProxy).ServeHTTP (reverseproxy.go:295)
2020-08-11 10:30:00.955748 I | suppressing panic for copyResponse error in test; copy error: http: wrote more than the declared Content-Length
2020-08-11T10:30:00+02:00 ERR error writing body after headers were sent error="write tcp 127.0.0.1:9140->127.0.0.1:47958: write: broken pipe" pkg=rhttp service=reva traceid=9a614ab15294bbfcd19421c581a9b91d
2020-08-11 10:30:00.957928 I | suppressing panic for copyResponse error in test; copy error: write tcp 127.0.0.1:9200->127.0.0.1:33198: write: connection reset by peer
2020-08-11T10:30:00+02:00 INF http end="11/Aug/2020:10:30:00 +0200" host=127.0.0.1 method=GET pkg=rhttp proto=HTTP/1.1 service=reva size=1380344 start="11/Aug/2020:10:30:00 +0200" status=200 time_ns=12283364 traceid=9a614ab15294bbfcd19421c581a9b91d uri=/data url=/data
2020-08-11T10:30:00+02:00 ERR error copying data to response error="write tcp 127.0.0.1:9156->127.0.0.1:51564: write: broken pipe" pkg=rhttp service=reva traceid=9a614ab15294bbfcd19421c581a9b91d
2020-08-11T10:30:00+02:00 INF http end="11/Aug/2020:10:30:00 +0200" host=127.0.0.1 method=GET pkg=rhttp proto=HTTP/1.1 service=reva size=1413112 start="11/Aug/2020:10:30:00 +0200" status=200 time_ns=10320494 traceid=9a614ab15294bbfcd19421c581a9b91d uri=/data/test.png url=/data/test.png
2020-08-11T10:30:00+02:00 ERR error finishing copying data to response error="write tcp 127.0.0.1:9140->127.0.0.1:47500: write: broken pipe" pkg=rhttp service=reva traceid=9a614ab15294bbfcd19421c581a9b91d
2020-08-11T10:30:00+02:00 INF http end="11/Aug/2020:10:30:00 +0200" host=127.0.0.1 method=GET pkg=rhttp proto=HTTP/1.1 service=reva size=720896 start="11/Aug/2020:10:30:00 +0200" status=200 time_ns=58548909 traceid=9a614ab15294bbfcd19421c581a9b91d uri=/remote.php/webdav/test.png?OC-Credential=4c510ada-c86b-4815-8820-42cdf82c3d51&OC-Date=2020-08-11T08%3A30%3A00.034Z&OC-Expires=1200&OC-Verb=GET url=/remote.php/webdav/test.png?OC-Credential=4c510ada-c86b-4815-8820-42cdf82c3d51&OC-Date=2020-08-11T08%3A30%3A00.034Z&OC-Expires=1200&OC-Verb=GET

I see a message the writeHeader has been called twice, that might be causing the subsequent errors.
I'll investigate.

PVince81 · 2020-08-11T08:49:42Z

these are the headers copied over from the data provider:

Header={"Content-Type":["image/png"],"Date":["Tue, 11 Aug 2020 08:47:59 GMT"],"Tus-Resumable":["1.0.0"],"Vary":["Origin"],"X-Content-Type-Options":["nosniff"]}

no trace of status code.

if I comment out the last writeHeader https://github.com/refs/reva/blob/fix-error-propagation/internal/http/services/datagateway/datagateway.go#L245 the error "superfluous" disappeares, but the other error about "connection reset by peer" is still there.

PVince81 · 2020-08-11T08:54:41Z

there seems to be a hint there suppressing panic for copyResponse error in test; copy error: http: wrote more than the declared Content-Length: apparently the advertised content-length does not match the data, it might be smaller.
so the client (here Chromium) is closing the connection as soon as it received as many bytes as advertised.

but logging the headers that were copied did not show any content-length there, so not sure where that error comes from

PVince81 · 2020-08-11T09:01:31Z

nothing there...

2020-08-11T10:57:56+02:00 DBG #### DEBUG HEADER content-length= pkg=rhttp service=reva traceid=979e80e40458bf18fb5b5645d8695752
2020-08-11T10:57:56+02:00 DBG #### DEBUG HEADER httpRes.Header={"Content-Type":["image/png"],"Date":["Tue, 11 Aug 2020 08:57:56 GMT"],"Tus-Resumable":["1.0.0"],"X-Content-Type-Options":["nosniff"]} pkg=rhttp service=reva traceid=979e80e40458bf18fb5b5645d8695752
2020-08-11T10:57:56+02:00 DBG #### DEBUG HEADER pkg=rhttp service=reva traceid=979e80e40458bf18fb5b5645d8695752 w.Header={"Content-Type":["image/png"],"Date":["Tue, 11 Aug 2020 08:57:56 GMT"],"Tus-Resumable":["1.0.0"],"Vary":["Origin"],"X-Content-Type-Options":["nosniff"]}

the md5sum in the reva data folder matches the one from the downloaded file and also the source from which it was uploaded.

weird...

PVince81 · 2020-08-11T09:37:15Z

seems it's rather happening in ocdav, I was looking at the data gateway.

here in ocdav:

2020-08-11T11:36:14+02:00 DBG #### DEBUG HEADER OCDAV httpRes.Header={"Content-Type":["image/png"],"Date":["Tue, 11 Aug 2020 09:36:14 GMT"],"Tus-Resumable":["1.0.0"],"Vary":["Origin"],"X-Content-Type-Options":["nosniff"]} pkg=rhttp service=reva traceid=692e1ccb955666f4e0066390788a3d98
2020-08-11T11:36:14+02:00 DBG #### DEBUG HEADER OCDAV pkg=rhttp service=reva traceid=692e1ccb955666f4e0066390788a3d98 w.Header={"Access-Control-Allow-Origin":["*"],"Content-Disposition":["attachment; filename*=UTF-8''test.png; filename=\"test.png\""],"Content-Length":["13493516"],"Content-Security-Policy":["default-src 'none';"],"Content-Type":["image/png"],"Etag":["\"d60062e7623d1df31641d5c79986a765\""],"Last-Modified":["Fri, 21 Jun 2019 18:33:52 +0200"],"Oc-Etag":["\"d60062e7623d1df31641d5c79986a765\""],"Oc-Fileid":["MTI4NGQyMzgtYWE5Mi00MmNlLWJkYzQtMGIwMDAwMDA5MTU0OjAxMjAzZDUyLWZiNjEtNDMxZi1iOGI3LWEzMzE4NWRkNzgwOQ=="],"Vary":["Origin"],"X-Content-Type-Options":["nosniff"],"X-Download-Options":["noopen"],"X-Frame-Options":["SAMEORIGIN"],"X-Permitted-Cross-Domain-Policies":["none"],"X-Robots-Tag":["none"],"X-Xss-Protection":["1; mode=block"]}
2020-08-11 11:36:14.490270 I | http: superfluous response.WriteHeader call from net/http/httputil.(*ReverseProxy).ServeHTTP (reverseproxy.go:295)
2020-08-11 11:36:14.490607 I | suppressing panic for copyResponse error in test; copy error: http: wrote more than the declared Content-Length
2020-08-11 11:36:14.495740 I | suppressing panic for copyResponse error in test; copy error: context canceled
2020-08-11T11:36:14+02:00 ERR error finishing copying data to response error="context canceled" pkg=rhttp service=reva traceid=692e1ccb955666f4e0066390788a3d98
2020-08-11T11:36:14+02:00 INF http end="11/Aug/2020:11:36:14 +0200" host=127.0.0.1 method=GET pkg=rhttp proto=HTTP/1.1 service=reva size=1474560 start="11/Aug/2020:11:36:14 +0200" status=200 time_ns=67938037 traceid=692e1ccb955666f4e0066390788a3d98 uri=/remote.php/webdav/test.png?OC-Credential=4c510ada-c86b-4815-8820-42cdf82c3d51&OC-Date=2020-08-11T09%3A36%3A13.463Z&OC-Expires=1200&OC-Verb=GET url=/remote.php/webdav/test.png?OC-Credential=4c510ada-c86b-4815-8820-42cdf82c3d51&OC-Date=2020-08-11T09%3A36%3A13.463Z&OC-Expires=1200&OC-Verb=GET

the content-length value matches what's on-disk...

PVince81 · 2020-08-11T09:38:53Z

the matching curl also returns the correct content-length:

% curl -D - -k -u einstein:relativity "https://localhost:9200/remote.php/webdav/test.png?OC-Credential=4c510ada-c86b-4815-8820-42cdf82c3d51&OC-Date=2020-08-11T09%3A36%3A13.463Z&OC-Expires=1200&OC-Verb=GET" -o test-download.png
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0HTTP/1.1 200 OK
Access-Control-Allow-Origin: *
Content-Disposition: attachment; filename*=UTF-8''test.png; filename="test.png"
Content-Length: 13493516
Content-Security-Policy: default-src 'none';
Content-Type: image/png
Date: Tue, 11 Aug 2020 09:38:11 GMT
Etag: "d60062e7623d1df31641d5c79986a765"
Last-Modified: Fri, 21 Jun 2019 18:33:52 +0200
Oc-Etag: "d60062e7623d1df31641d5c79986a765"
Oc-Fileid: MTI4NGQyMzgtYWE5Mi00MmNlLWJkYzQtMGIwMDAwMDA5MTU0OjAxMjAzZDUyLWZiNjEtNDMxZi1iOGI3LWEzMzE4NWRkNzgwOQ==
Vary: Origin
X-Access-Token: eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJyZXZhIiwiZXhwIjoxNTk3MTQyMjkxLCJpYXQiOjE1OTcxMzg2OTEsImlzcyI6Imh0dHBzOi8vbG9jYWxob3N0OjkyMDAiLCJ1c2VyIjp7ImlkIjp7ImlkcCI6Imh0dHBzOi8vbG9jYWxob3N0OjkyMDAiLCJvcGFxdWVfaWQiOiI0YzUxMGFkYS1jODZiLTQ4MTUtODgyMC00MmNkZjgyYzNkNTEifSwidXNlcm5hbWUiOiJlaW5zdGVpbiIsIm1haWwiOiJlaW5zdGVpbkBleGFtcGxlLm9yZyIsImRpc3BsYXlfbmFtZSI6IkFsYmVydCBFaW5zdGVpbiJ9fQ.LBWkqkO-e6iHLL6SJ4N1IxZCVBaIJvouJkbOQN2Pp8Q
X-Content-Type-Options: nosniff
X-Download-Options: noopen
X-Frame-Options: SAMEORIGIN
X-Permitted-Cross-Domain-Policies: none
X-Robots-Tag: none
X-Xss-Protection: 1; mode=block

and the file's md5 matches

PVince81 · 2020-08-11T09:41:44Z

when downloading with curl there are no errors in the code.
maybe because we are closing the connection and not the client.

with Firefox or Chromium, I guess the browsers are closing the connection as soon as they have enough bytes.

I'll compare this with earlier ocis versions and hope it's not a regression

PVince81 · 2020-08-11T09:47:20Z

in ocis-beta8 the error does not appear for downloading:

2020-08-11T11:46:10+02:00 DBG sending request to internal data server pkg=rhttp service=reva target=http://localhost:9156/data/test.png traceid=56e4c4cf7dec607ff468672547156d4c
2020-08-11T11:46:10+02:00 INF access token is already provided pkg=rhttp service=reva traceid=56e4c4cf7dec607ff468672547156d4c
2020-08-11T11:46:10+02:00 DBG http routing: head=data tail=/test.png svc=data pkg=rhttp service=reva
[tusd] 2020/08/11 11:46:10 event="RequestIncoming" method="GET" path="/test.png" requestId="" 
2020-08-11T11:46:10+02:00 INF tusd routing: path=/test.png pkg=rhttp service=reva traceid=56e4c4cf7dec607ff468672547156d4c
2020-08-11T11:46:10+02:00 INF http end="11/Aug/2020:11:46:10 +0200" host=127.0.0.1 method=GET pkg=rhttp proto=HTTP/1.1 service=reva size=13493516 start="11/Aug/2020:11:46:10 +0200" status=200 time_ns=35834358 traceid=56e4c4cf7dec607ff468672547156d4c uri=/data/test.png url=/data/test.png
2020-08-11T11:46:10+02:00 INF http end="11/Aug/2020:11:46:10 +0200" host=127.0.0.1 method=GET pkg=rhttp proto=HTTP/1.1 service=reva size=13493516 start="11/Aug/2020:11:46:10 +0200" status=200 time_ns=50140351 traceid=56e4c4cf7dec607ff468672547156d4c uri=/data url=/data
2020-08-11T11:46:10+02:00 INF http end="11/Aug/2020:11:46:10 +0200" host=127.0.0.1 method=GET pkg=rhttp proto=HTTP/1.1 service=reva size=13493516 start="11/Aug/2020:11:46:09 +0200" status=200 time_ns=132387905 traceid=56e4c4cf7dec607ff468672547156d4c uri=/remote.php/webdav/test.png url=/remote.php/webdav/test.png

I'll bisect reva to see if it's a regression there.

PVince81 · 2020-08-11T10:02:58Z

with ocis-beta8 and the latest reva before ocfs fix, sitting on commit 75664dd downloading still works fine, no errors in log.

this is before presigned urls

PVince81 · 2020-08-11T10:10:01Z

ok, so reva seems to work fine on the latest code of reva and ocis-reva owncloud/ocis-reva#420
but without any other updated modules, so no ocis-accounts update, etc.

so this confirms that there is no regression in reva and the problem is likely triggered somehow by the code path of pre-signed URLs.

PVince81 · 2020-08-11T10:18:25Z

looking at the error again:

2020-08-11T12:14:08+02:00 ERR error finishing copying data to response OCDAV error="context canceled" pkg=rhttp service=reva traceid=4022b8fe8075875b2be081882944bece
2020-08-11T12:14:08+02:00 INF http end="11/Aug/2020:12:14:08 +0200" host=127.0.0.1 method=GET pkg=rhttp proto=HTTP/1.1 service=reva size=3604480 start="11/Aug/2020:12:14:08 +0200" status=200 time_ns=69521908 traceid=4022b8fe8075875b2be081882944bece uri=/remote.php/webdav/test.png?OC-Credential=4c510ada-c86b-4815-8820-42cdf82c3d51&OC-Date=2020-08-11T10%3A14%3A07.785Z&OC-Expires=1200&OC-Verb=GET url=/remote.php/webdav/test.png?OC-Credential=4c510ada-c86b-4815-8820-42cdf82c3d51&OC-Date=2020-08-11T10%3A14%3A07.785Z&OC-Expires=1200&OC-Verb=GET
2020-08-11T12:14:08+02:00 ERR error writing body after headers were sent DATAGATEWAY error="write tcp 127.0.0.1:9140->127.0.0.1:50710: write: connection reset by peer" pkg=rhttp service=reva traceid=4022b8fe8075875b2be081882944bece
2020-08-11T12:14:08+02:00 ERR error copying data to response error="write tcp 127.0.0.1:9156->127.0.0.1:54432: write: connection reset by peer" pkg=rhttp service=reva traceid=4022b8fe8075875b2be081882944bece

the log entries appear in that order:

OCDAV's io.Copy fails
data gateway io.Copy fails
data provider get io.Copy fails: https://github.com/PVince81/butonic-reva/blob/master/internal/http/services/dataprovider/get.go#L59

it's not yet clear which one is influencing which

PVince81 · 2020-08-11T10:29:16Z

so I added logging for the written value of the copy operation, strangely the values don't seem to make sense, and are different:

2020-08-11T12:28:34+02:00 ERR error finishing copying data to response OCDAV error="write tcp 127.0.0.1:9140->127.0.0.1:54806: write: broken pipe" pkg=rhttp service=reva traceid=103080b4c3766228dde9c32e2ec518fb written=131072
2020-08-11T12:28:34+02:00 INF http end="11/Aug/2020:12:28:34 +0200" host=127.0.0.1 method=GET pkg=rhttp proto=HTTP/1.1 service=reva size=131072 start="11/Aug/2020:12:28:34 +0200" status=200 time_ns=49213460 traceid=103080b4c3766228dde9c32e2ec518fb uri=/remote.php/webdav/test.png?OC-Credential=4c510ada-c86b-4815-8820-42cdf82c3d51&OC-Date=2020-08-11T10%3A28%3A33.738Z&OC-Expires=1200&OC-Verb=GET url=/remote.php/webdav/test.png?OC-Credential=4c510ada-c86b-4815-8820-42cdf82c3d51&OC-Date=2020-08-11T10%3A28%3A33.738Z&OC-Expires=1200&OC-Verb=GET
2020-08-11T12:28:34+02:00 ERR error writing body after headers were sent DATAGATEWAY error="write tcp 127.0.0.1:9140->127.0.0.1:54334: write: connection reset by peer" pkg=rhttp service=reva traceid=103080b4c3766228dde9c32e2ec518fb written=3379192
2020-08-11T12:28:34+02:00 ERR error copying data to response DATAPROVIDER error="write tcp 127.0.0.1:9156->127.0.0.1:58644: write: connection reset by peer" pkg=rhttp service=reva traceid=103080b4c3766228dde9c32e2ec518fb written=3641336

PVince81 · 2020-08-11T10:55:45Z

2020-08-11T12:53:51+02:00 DBG After Download calling io.Copy pkg=rhttp service=reva traceid=6eb1d38a60d0b15b89b550b8b668c3c0
2020-08-11 12:53:51.563372 I | http: superfluous response.WriteHeader call from net/http/httputil.(*ReverseProxy).ServeHTTP (reverseproxy.go:295)
2020-08-11 12:53:51.563593 I | suppressing panic for copyResponse error in test; copy error: http: wrote more than the declared Content-Length
2020-08-11 12:53:51.564292 I | suppressing panic for copyResponse error in test; copy error: context canceled
2020-08-11T12:53:51+02:00 ERR error finishing copying data to response OCDAV error="context canceled" pkg=rhttp service=reva traceid=6eb1d38a60d0b15b89b550b8b668c3c0 written=98304

So this means the trigger is happening in io.Copy from the data provider.
Probably somewhere in there it's overflowing the expected amount of bytes, but somehow the written number is still way smaller than my test file which has about 12 MB.

I'm wondering if an absence content-length qualifies as zero... but why would that only be relevant now with presigned URL and not before ?

PVince81 · 2020-08-11T11:02:22Z

another set here:

Jun 2019 18:33:52 +0200"],"Oc-Etag":["\"c7c8905d61ebf938b1a217fdd3939804\""],"Oc-Fileid":["MTI4NGQyMzgtYWE5Mi00MmNlLWJkYzQtMGIwMDAwMDA5MTU0OmM5NGI2Y2JiLTZiMGEtNGJiMy1hYmFiLWE0ZDU0NGFkYjVjMA=="],"Vary":["Origin"],"X-Content-Type-Options":["nosniff"],"X-Download-Options":["noopen"],"X-Frame-Options":["SAMEORIGIN"],"X-Permitted-Cross-Domain-Policies":["none"],"X-Robots-Tag":["none"],"X-Xss-Protection":["1; mode=block"]}
2020-08-11 12:59:40.450259 I | http: superfluous response.WriteHeader call from net/http/httputil.(*ReverseProxy).ServeHTTP (reverseproxy.go:295)
2020-08-11 12:59:40.450335 I | suppressing panic for copyResponse error in test; copy error: http: wrote more than the declared Content-Length
2020-08-11T12:59:40+02:00 ERR error finishing copying data to response OCDAV error="write tcp 127.0.0.1:9140->127.0.0.1:35422: write: broken pipe" pkg=rhttp service=reva traceid=d95da4890c7a050bd3186a4cea2ac704 written=458752
2020-08-11T12:59:40+02:00 INF http end="11/Aug/2020:12:59:40 +0200" host=127.0.0.1 method=GET pkg=rhttp proto=HTTP/1.1 service=reva size=458752 start="11/Aug/2020:12:59:40 +0200" status=200 time_ns=48970095 traceid=d95da4890c7a050bd3186a4cea2ac704 uri=/remote.php/webdav/test.png?OC-Credential=4c510ada-c86b-4815-8820-42cdf82c3d51&OC-Date=2020-08-11T10%3A59%3A39.464Z&OC-Expires=1200&OC-Verb=GET url=/remote.php/webdav/test.png?OC-Credential=4c510ada-c86b-4815-8820-42cdf82c3d51&OC-Date=2020-08-11T10%3A59%3A39.464Z&OC-Expires=1200&OC-Verb=GET
2020-08-11 12:59:40.451511 I | suppressing panic for copyResponse error in test; copy error: write tcp 127.0.0.1:9200->127.0.0.1:49096: write: connection reset by peer
2020-08-11T12:59:40+02:00 ERR error writing body after headers were sent DATAGATEWAY error="write tcp 127.0.0.1:9140->127.0.0.1:35538: write: broken pipe" pkg=rhttp service=reva traceid=d95da4890c7a050bd3186a4cea2ac704 written=5148664
2020-08-11T12:59:40+02:00 ERR error copying data to response DATAPROVIDER error="write tcp 127.0.0.1:9156->127.0.0.1:39230: write: connection reset by peer" pkg=rhttp service=reva traceid=d95da4890c7a050bd3186a4cea2ac704 written=5246968

it seems the written values are changing with each test run (I always use the same test file which has a size of 13493516)

But I don't understand how the download can still go through...

At first I suspected that maybe this is due to the HEAD call that is done by Phoenix, but the HEAD call alone doesn't produce anything. And doing a GET with curl on the URL also doesn't trigger anything. So maybe it's something extra that the browsers do when downloading ?

PVince81 · 2020-08-11T11:05:04Z

I've checked the trace for the HEAD request and it doesn't contain any error.

Signed-off-by: Jörn Friedrich Dreyer <jfd@butonic.de>

butonic · 2020-08-11T11:38:15Z

@PVince81 the browser is sending a GET request like this:

https://localhost:9200/remote.php/webdav/youcandrawcomicbookcharacters.pdf?OC-Credential=4c510ada-c86b-4815-8820-42cdf82c3d51&OC-Date=2020-08-11T08%3A15%3A48.036Z&OC-Expires=1200&OC-Verb=GET&OC-Signature=72405e58334a8843fc95fa9849acdfe53aa07a8c14ba3ca89abe2c4d7ba44bec

This request uses the old webdav endpoint and will be forwarded to the ocdav handler in reva.

That in turn will lookup the responsible storage provider and issue the actual GET request. Maybe something is not copying the streams correctly there. Might not be a browser issue...

does ocdav talk to the dataprovider directly or the datagateway? I assume the latter ... another possible cause of failure.

PVince81 · 2020-08-11T12:05:24Z

from all the tests I did today, these are the locally saved files by Chromium:

0da2914f3b3003e3acb862f293272fac  test (10).png
0da2914f3b3003e3acb862f293272fac  test (11).png
0da2914f3b3003e3acb862f293272fac  test (12).png
0da2914f3b3003e3acb862f293272fac  test (13).png
0da2914f3b3003e3acb862f293272fac  test (14).png
0da2914f3b3003e3acb862f293272fac  test (15).png
0da2914f3b3003e3acb862f293272fac  test (16).png
0da2914f3b3003e3acb862f293272fac  test (17).png
0da2914f3b3003e3acb862f293272fac  test (18).png
0da2914f3b3003e3acb862f293272fac  test (19).png
0da2914f3b3003e3acb862f293272fac  test (1).png
0da2914f3b3003e3acb862f293272fac  test (20).png
0da2914f3b3003e3acb862f293272fac  test (21).png
0da2914f3b3003e3acb862f293272fac  test (22).png
0da2914f3b3003e3acb862f293272fac  test (23).png
0da2914f3b3003e3acb862f293272fac  test (24).png
0da2914f3b3003e3acb862f293272fac  test (25).png
0da2914f3b3003e3acb862f293272fac  test (26).png
0da2914f3b3003e3acb862f293272fac  test (27).png
0da2914f3b3003e3acb862f293272fac  test (28).png
0da2914f3b3003e3acb862f293272fac  test (29).png
0da2914f3b3003e3acb862f293272fac  test (2).png
0da2914f3b3003e3acb862f293272fac  test (3).png
0da2914f3b3003e3acb862f293272fac  test (4).png
0da2914f3b3003e3acb862f293272fac  test (5).png
0da2914f3b3003e3acb862f293272fac  test (6).png
0da2914f3b3003e3acb862f293272fac  test (7).png
0da2914f3b3003e3acb862f293272fac  test (8).png
0da2914f3b3003e3acb862f293272fac  test (9).png
0da2914f3b3003e3acb862f293272fac  test.png

and the original one:

0da2914f3b3003e3acb862f293272fac  test.png

so that interruption is not relevant to the download.
I wonder if there is a code path that just does a "quick check" of some sorts and closes the connection before doing the real actual download. But if that was the case we'd see the io.Copy calls multiple times but we only see them ones.

So is Chromium downloading the bytes from the ether ??

butonic · 2020-08-11T12:22:25Z

that error is not caused by chrome ... it is logged by the ocdav get handler in https://github.com/cs3org/reva/blob/b946f40f6a020cea81175127b0871654d53a0e28/internal/http/services/owncloud/ocdav/get.go#L144

PVince81 · 2020-08-11T12:24:41Z

correction: I actually see two sets of call to OCDAV, but both seem to report coming from a "GET", but no mention of "HEAD" in the log.

PVince81 · 2020-08-11T13:30:37Z

with small files we only get the suppressing panic for copyResponse error in test but no "connection reset by peer".

I had a look at Wireshark but the packets all seemed fine.

PVince81 · 2020-08-11T13:31:01Z

commenting out "res.Close" in all involved layers did not help, like advised in https://forum.golangbridge.org/t/code-works-fine-but-i-get-error-in-io-copy-write-tcp-write-connection-reset-by-peer/3370/5

butonic · 2020-08-11T13:42:20Z

Some of the log lines are created by the proxy: openshift/origin#23651

butonic · 2020-08-11T13:53:26Z

that bubbles up from https://github.com/golang/go/blob/21898524f66c075d7cfb64a38f17684140e57675/src/net/http/httputil/reverseproxy.go#L328-L340

butonic · 2020-08-11T13:57:59Z

also: the log lines are reproducable for larger files with normal curl:

curl https://localhost:9200/remote.php/webdav/youcandrawcomicbookcharacters.pdf -u einstein:relativity -k

this file is ~67MB ... and produces

2020-08-11T15:57:36+02:00 DBG sending request to internal data server pkg=rhttp service=reva target=http://localhost:9156/data/youcandrawcomicbookcharacters.pdf traceid=f7a6d97ad3c4be56b86531761d773ce4
2020-08-11T15:57:36+02:00 INF access token is already provided pkg=rhttp service=reva traceid=f7a6d97ad3c4be56b86531761d773ce4
2020-08-11T15:57:36+02:00 DBG http routing: head=data tail=/youcandrawcomicbookcharacters.pdf svc=data pkg=rhttp service=reva
[tusd] 2020/08/11 15:57:36 event="RequestIncoming" method="GET" path="/youcandrawcomicbookcharacters.pdf" requestId="" 
2020-08-11T15:57:36+02:00 INF tusd routing: path=/youcandrawcomicbookcharacters.pdf pkg=rhttp service=reva traceid=f7a6d97ad3c4be56b86531761d773ce4
2020-08-11 15:57:36.007348 I | suppressing panic for copyResponse error in test; copy error: context canceled
2020-08-11T15:57:36+02:00 ERR error finishing copying data to response error="context canceled" pkg=rhttp service=reva traceid=f7a6d97ad3c4be56b86531761d773ce4
2020-08-11T15:57:36+02:00 INF http end="11/Aug/2020:15:57:36 +0200" host=::1 method=GET pkg=rhttp proto=HTTP/1.1 service=reva size=118776 start="11/Aug/2020:15:57:35 +0200" status=200 time_ns=87400266 traceid=f7a6d97ad3c4be56b86531761d773ce4 uri=/remote.php/webdav/youcandrawcomicbookcharacters.pdf url=/remote.php/webdav/youcandrawcomicbookcharacters.pdf
2020-08-11 15:57:36.010798 I | suppressing panic for copyResponse error in test; copy error: write tcp [::1]:9200->[::1]:36596: write: connection reset by peer
2020-08-11T15:57:36+02:00 ERR error writing body after headers were sent error="write tcp [::1]:9140->[::1]:54152: write: broken pipe" pkg=rhttp service=reva traceid=f7a6d97ad3c4be56b86531761d773ce4
2020-08-11T15:57:36+02:00 ERR error copying data to response error="write tcp [::1]:9156->[::1]:47844: write: connection reset by peer" count=10092328 pkg=rhttp service=reva traceid=f7a6d97ad3c4be56b86531761d773ce4
2020-08-11T15:57:36+02:00 INF http end="11/Aug/2020:15:57:36 +0200" host=::1 method=GET pkg=rhttp proto=HTTP/1.1 service=reva size=4034552 start="11/Aug/2020:15:57:36 +0200" status=200 time_ns=7074474 traceid=f7a6d97ad3c4be56b86531761d773ce4 uri=/data url=/data
2020-08-11T15:57:36+02:00 INF http end="11/Aug/2020:15:57:36 +0200" host=::1 method=GET pkg=rhttp proto=HTTP/1.1 service=reva size=10092328 start="11/Aug/2020:15:57:36 +0200" status=200 time_ns=6569878 traceid=f7a6d97ad3c4be56b86531761d773ce4 uri=/data/youcandrawcomicbookcharacters.pdf url=/data/youcandrawcomicbookcharacters.pdf

PVince81 · 2020-08-11T14:10:25Z

since downloading works anyway, let's move the debugging to another ticket: https://github.com/owncloud/ocis-proxy/issues/86

Signed-off-by: Jörn Friedrich Dreyer <jfd@butonic.de>

PVince81

👍

ownclouders · 2020-08-11T15:19:15Z

Here is an overview of what got changed by this pull request:

Complexity increasing per file
==============================
- pkg/middleware/account_uuid.go  1

See the complete overview on Codacy

lookup user by id as well

fba1746

Signed-off-by: Jörn Friedrich Dreyer <jfd@butonic.de>

PVince81 mentioned this pull request Aug 11, 2020

Use UUID for account lookup from presigned URLs #84

Closed

2 tasks

PVince81 assigned PVince81 and butonic Aug 11, 2020

PVince81 mentioned this pull request Aug 11, 2020

Download with signing key not working owncloud/ocis#436

Closed

properly distinguish userid from username

3e29ee9

Signed-off-by: Jörn Friedrich Dreyer <jfd@butonic.de>

add changelog

6e590a0

Signed-off-by: Jörn Friedrich Dreyer <jfd@butonic.de>

butonic added the bug Something isn't working label Aug 11, 2020

PVince81 approved these changes Aug 11, 2020

View reviewed changes

PVince81 mentioned this pull request Aug 11, 2020

Update deps 2020 07 22 owncloud/ocis#409

Merged

63 tasks

PVince81 merged commit 99c1dba into master Aug 11, 2020

PVince81 mentioned this pull request Aug 18, 2020

Download through proxy works but is logging scary messages owncloud/product#149

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

lookup user by id as well #85

lookup user by id as well #85

butonic commented Aug 11, 2020 •

edited by PVince81

Loading

update-docs bot commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

butonic commented Aug 11, 2020

PVince81 commented Aug 11, 2020

butonic commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

butonic commented Aug 11, 2020

butonic commented Aug 11, 2020

butonic commented Aug 11, 2020 •

edited

Loading

PVince81 commented Aug 11, 2020

PVince81 left a comment

ownclouders commented Aug 11, 2020

lookup user by id as well #85

lookup user by id as well #85

Conversation

butonic commented Aug 11, 2020 • edited by PVince81 Loading

update-docs bot commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

butonic commented Aug 11, 2020

PVince81 commented Aug 11, 2020

butonic commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

PVince81 commented Aug 11, 2020

butonic commented Aug 11, 2020

butonic commented Aug 11, 2020

butonic commented Aug 11, 2020 • edited Loading

PVince81 commented Aug 11, 2020

PVince81 left a comment

Choose a reason for hiding this comment

ownclouders commented Aug 11, 2020

butonic commented Aug 11, 2020 •

edited by PVince81

Loading

butonic commented Aug 11, 2020 •

edited

Loading