Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Json decode error during upload stage #2

Closed
adds68 opened this issue Feb 27, 2019 · 13 comments
Closed

Json decode error during upload stage #2

adds68 opened this issue Feb 27, 2019 · 13 comments

Comments

@adds68
Copy link

adds68 commented Feb 27, 2019

Since switching to flat-manager we have had some builds failed with:

json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

This happens during upload.

There has also been some failed builds at Flathub.

https://gitlab.com/freedesktop-sdk/freedesktop-sdk/-/jobs/168340169

https://flathub.org/builds/#/builders/20/builds/28

@nanonyme
Copy link
Contributor

nanonyme commented Mar 1, 2019

@tilosp
Copy link
Contributor

tilosp commented Mar 2, 2019

@abderrahim
Copy link

It seems there are two problems here:

  • The server returns a 400 Bad Request response with an empty body, after some requests for the log.
  • The client seems unable to cope with this, as trying to parse the empty response as json raises an exception.

There is also a mention of HTTP/2 in the source code, but flathub seems to be using HTTP/1.1.

@alexlarsson
Copy link
Member

So, part of the issue here is that we have an nginx front in front of the flat-manager service. Take the eclipse error above:

    raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

This expects an error page to contain a json, but the actual error is from the nginx front:

2019/02/26 16:19:25 [error] 12442#0: *11349083 sendfile() failed (32: Broken pipe) while sending request to upstream, client: 2604:1380:0:1300::1, server: hub.flathub.org, request: "POST /api/v1/build/369/upload HTTP/1.1", upstream: "http://127.0.0.1:8080/api/v1/build/369/upload", host: "hub.flathub.org"

Clearly we should handle this better in the client, but in the end that doesn't really help us here.

Early on in the new infra we got a lot of these for large delta uploads when the proxy timed out, but since then i've bumped the timeout and we see less of these. Its unclear exactly what caused this one though. "broken pipe", wth??

@alexlarsson
Copy link
Member

Also https://gitlab.com/freedesktop-sdk/freedesktop-sdk/-/jobs/170079994

2019/03/01 15:11:01 [error] 12444#0: *14978582 sendfile() failed (32: Broken pipe) while sending request to upstream, client: 147.75.106.214, server: hub.flathub.org, request: "POST /api/v1/build/506/upload HTTP/1.1", upstream: "http://127.0.0.1:8080/api/v1/build/506/upload", host: "hub.flathub.org"

https://flathub.org/builds/#/builders/32/builds/567

This is not in the error logs, but the access.log for it ends with:

46.235.226.135 - - [02/Mar/2019:10:56:08 +0000] "GET /api/v1/build/528/commit HTTP/1.1" 200 87 "-" "python-requests/2.12.5" "-"
46.235.226.135 - - [02/Mar/2019:10:56:11 +0000] "GET /api/v1/build/528/commit HTTP/1.1" 200 181 "-" "python-requests/2.12.5" "-"
46.235.226.135 - - [02/Mar/2019:10:56:12 +0000] "GET /api/v1/build/528/commit HTTP/1.1" 200 340 "-" "python-requests/2.12.5" "-"
46.235.226.135 - - [02/Mar/2019:10:56:13 +0000] "GET /api/v1/build/528/commit HTTP/1.1" 200 87 "-" "python-requests/2.12.5" "-"
46.235.226.135 - - [02/Mar/2019:10:56:14 +0000] "GET /api/v1/build/528/commit HTTP/1.1" 200 87 "-" "python-requests/2.12.5" "-"
46.235.226.135 - - [02/Mar/2019:10:56:46 +0000] "GET /api/v1/build/528/commit HTTP/1.1" 408 0 "-" "python-requests/2.12.5" "-"
46.235.226.135 - - [02/Mar/2019:10:56:52 +0000] "POST /api/v1/build/528/purge HTTP/1.1" 400 65 "-" "python-requests/2.12.5" "-"

408 is Request Timeout, which means shutting down an unused connection, which apparently the client takes for a real error and aborts (purges). I think we should make the client handle this and re-try?

https://flathub.org/builds/#/builders/24/builds/63

This is weird though, this is the full log:

2604:1380:0:1300::7 - - [02/Mar/2019:13:43:10 +0000] "GET /api/v1/build/532/missing_objects HTTP/1.1" 200 4867 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:43:11 +0000] "GET /api/v1/build/532/missing_objects HTTP/1.1" 200 40151 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:43:12 +0000] "GET /api/v1/build/532/missing_objects HTTP/1.1" 200 40581 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:43:13 +0000] "GET /api/v1/build/532/missing_objects HTTP/1.1" 200 139 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:43:23 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 910 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:43:24 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 183 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:43:40 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 10 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:43:45 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 691 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:43:49 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 816 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:43:52 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 345 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:44:08 +0000] "GET /api/v1/build/532/missing_objects HTTP/1.1" 200 6920 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:44:09 +0000] "GET /api/v1/build/532/missing_objects HTTP/1.1" 200 21363 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:44:09 +0000] "GET /api/v1/build/532/missing_objects HTTP/1.1" 200 21256 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:44:10 +0000] "GET /api/v1/build/532/missing_objects HTTP/1.1" 200 764 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:44:13 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 10 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:44:14 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 114 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:44:16 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 733 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:44:18 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 748 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:44:21 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 544 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:44:22 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 200 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:44:31 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 10 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:44:39 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 10 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:44:41 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 586 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:44:56 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 408 0 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:44:57 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 333 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:45:08 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 10 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:45:20 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 86 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:45:22 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 460 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:45:40 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 10 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:45:43 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 186 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:45:45 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 406 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:45:48 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 341 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:45:55 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 86 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:46:00 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 142 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:46:08 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 372 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:46:16 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 610 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:46:35 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 10 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:46:36 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 176 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:46:37 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 357 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:46:37 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 6 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:46:38 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 9 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:46:39 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 7 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:46:44 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 9 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:46:45 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 8 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:46:47 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 9 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:46:55 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 9 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:47:04 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 9 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:47:17 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 9 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:47:22 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 9 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:47:24 +0000] "POST /api/v1/build/532/build_ref HTTP/1.1" 200 155 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:47:25 +0000] "POST /api/v1/build/532/build_ref HTTP/1.1" 200 148 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:47:25 +0000] "POST /api/v1/build/532/build_ref HTTP/1.1" 200 130 "-" "python-requests/2.9.1" "-"
2604:1380:0:1300::7 - - [02/Mar/2019:13:47:25 +0000] "POST /api/v1/build/532/build_ref HTTP/1.1" 200 154 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:13:58:17 +0000] "GET /api/v1/build/532/missing_objects HTTP/1.1" 200 1669 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:13:58:17 +0000] "GET /api/v1/build/532/missing_objects HTTP/1.1" 200 4625 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:13:58:17 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 59 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:13:58:18 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 39 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:13:58:20 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 10 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:13:58:21 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 107 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:13:58:21 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 159 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:13:58:22 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 21 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:13:58:31 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 10 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:13:58:31 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 97 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:13:58:37 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 10 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:13:58:38 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 94 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:13:58:38 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 115 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:13:58:39 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 9 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:13:58:40 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 9 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:13:58:40 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 9 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:13:58:41 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 9 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:13:58:41 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 8 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:13:58:42 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 9 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:13:58:43 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 9 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:13:58:43 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 7 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:13:58:43 +0000] "POST /api/v1/build/532/build_ref HTTP/1.1" 200 127 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:13:58:43 +0000] "POST /api/v1/build/532/build_ref HTTP/1.1" 200 152 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:13:58:43 +0000] "POST /api/v1/build/532/build_ref HTTP/1.1" 200 143 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:13:59:56 +0000] "GET /api/v1/build/532/missing_objects HTTP/1.1" 200 1142 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:13:59:57 +0000] "GET /api/v1/build/532/missing_objects HTTP/1.1" 200 4176 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:13:59:57 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 65 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:14:00:04 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 28 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:14:00:15 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 101 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:14:00:18 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 10 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:14:00:19 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 122 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:14:00:29 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 10 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:14:00:30 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 132 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:14:00:36 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 10 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:14:00:37 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 80 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:14:00:37 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 91 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:14:00:38 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 9 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:14:00:38 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 8 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:14:00:39 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 9 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:14:00:40 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 9 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:14:00:40 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 9 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:14:00:41 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 9 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:14:00:41 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 7 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:14:00:42 +0000] "POST /api/v1/build/532/upload HTTP/1.1" 200 9 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:14:00:42 +0000] "POST /api/v1/build/532/build_ref HTTP/1.1" 200 131 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:14:00:42 +0000] "POST /api/v1/build/532/build_ref HTTP/1.1" 200 154 "-" "python-requests/2.9.1" "-"
78.40.148.164 - - [02/Mar/2019:14:00:42 +0000] "POST /api/v1/build/532/build_ref HTTP/1.1" 200 146 "-" "python-requests/2.9.1" "-"
46.235.226.135 - - [02/Mar/2019:14:00:45 +0000] "POST /api/v1/build/532/purge HTTP/1.1" 200 119 "-" "python-requests/2.12.5" "-"

I.e. at one point it returns 408, but that client continues anyway. But then suddently at the end it decides to purge? I'm not sure why this happened at all.

@alexlarsson
Copy link
Member

So, for the broken pipe requests, i looked at the logs for the same time for the flat-manager service, and everything looks ok. Take the nginx error above for instance:

2019/02/26 16:19:25 [error] 12442#0: *11349083 sendfile() failed (32: Broken pipe) while sending request to upstream, client: 2604:1380:0:1300::1, server: hub.flathub.org, request: "POST /api/v1/build/369/upload HTTP/1.1", upstream: "http://127.0.0.1:8080/api/v1/build/369/upload", host: "hub.flathub.org"

In the service logs all related reqests to build 369 around this time are:

feb 26 16:19:09 hub.flathub.org flat-manager[21320]: INFO 2019-02-26T16:19:09Z: actix_web::middleware::logger: 127.0.0.1:34984 "GET /api/v1/build/369/missing_objects HTTP/1.0" 200 358 "-" "python-requests/2.9.1" 0.000516
feb 26 16:19:10 hub.flathub.org flat-manager[21320]: INFO 2019-02-26T16:19:10Z: actix_web::middleware::logger: 127.0.0.1:34972 "POST /api/v1/build/369/upload HTTP/1.0" 200 10 "-" "python-requests/2.9.1" 1.277650
feb 26 16:19:20 hub.flathub.org flat-manager[21320]: INFO 2019-02-26T16:19:20Z: flat_manager::tokens: 127.0.0.1:34996 Presented token: Claims { sub: "build/369", scope: ["upload"], prefixes: [""], repos: [""], name: "buildbot/upload", exp: 1551283625 }
feb 26 16:19:20 hub.flathub.org flat-manager[21320]: INFO 2019-02-26T16:19:20Z: actix_web::middleware::logger: 127.0.0.1:34996 "POST /api/v1/build/369/upload HTTP/1.0" 200 17 "-" "python-requests/2.9.1" 0.121799
feb 26 16:19:32 hub.flathub.org flat-manager[21320]: INFO 2019-02-26T16:19:32Z: flat_manager::tokens: 127.0.0.1:35006 Presented token: Claims { sub: "build/369", scope: ["upload"], prefixes: [""], repos: [""], name: "buildbot/upload", exp: 1551283625 }
feb 26 16:19:33 hub.flathub.org flat-manager[21320]: INFO 2019-02-26T16:19:33Z: actix_web::middleware::logger: 127.0.0.1:35006 "POST /api/v1/build/369/upload HTTP/1.0" 200 10 "-" "python-requests/2.9.1" 1.509101
feb 26 16:19:38 hub.flathub.org flat-manager[21320]: INFO 2019-02-26T16:19:38Z: flat_manager::tokens: 127.0.0.1:35016 Presented token: Claims { sub: "build/369", scope: ["upload"], prefixes: [""], repos: [""], name: "buildbot/upload", exp: 1551283625 }
feb 26 16:19:38 hub.flathub.org flat-manager[21320]: INFO 2019-02-26T16:19:38Z: actix_web::middleware::logger: 127.0.0.1:35016 "POST /api/v1/build/369/upload HTTP/1.0" 200 10 "-" "python-requests/2.9.1" 0.491167
feb 26 16:19:42 hub.flathub.org flat-manager[21320]: INFO 2019-02-26T16:19:42Z: flat_manager::tokens: 127.0.0.1:35026 Presented token: Claims { sub: "build/369", scope: ["upload"], prefixes: [""], repos: [""], name: "buildbot/upload", exp: 1551283625 }
feb 26 16:19:42 hub.flathub.org flat-manager[21320]: INFO 2019-02-26T16:19:42Z: actix_web::middleware::logger: 127.0.0.1:35026 "POST /api/v1/build/369/upload HTTP/1.0" 200 29 "-" "python-requests/2.9.1" 0.183526
feb 26 16:19:44 hub.flathub.org flat-manager[21320]: INFO 2019-02-26T16:19:44Z: flat_manager::tokens: 127.0.0.1:35028 Presented token: Claims { sub: "build/369", scope: ["upload"], prefixes: [""], repos: [""], name: "buildbot/upload", exp: 1551283625 }

So, there is nothing at 16:19:25, which seems to indicate that the request didn't even reach the service. Anyone has any idea why nginx would get a broken pipe error like this?

@alexlarsson
Copy link
Member

Some references here:
https://stackoverflow.com/questions/35725438/sendfile-failed-32-broken-pipe-while-sending-request-to-upstream-nginx-502

Nothing clear, but some mentions that doing the backend connection via a unix domain socket might help. We should maybe try that.

@tilosp
Copy link
Contributor

tilosp commented Mar 4, 2019

the interesting thing it that it doesn't seem to happen on the freedesktop sdk flat-manager instance.
They use a similar nginx config:

Flathub:
location /api {
    # Allow uploading large builds, deltas, etc
    client_max_body_size 0;
    proxy_pass http://127.0.0.1:8080;
    proxy_read_timeout 6000s;
    add_header Vary Accept-Encoding;
}
freedesktop
location /api {
    # Allow uploading large builds, deltas, etc
    client_max_body_size 0;
    proxy_pass http://127.0.0.1:8080;
    proxy_read_timeout 600s;
    add_header Vary Accept-Encoding;
}

@alexlarsson have you tried to turn proxy_request_buffering off?
maybe the disk is to slow to buffer all request as they are coming in.

@alexlarsson
Copy link
Member

I have not, i'm currently doing a major rework of the publish/update-repo part of flat-manager, so I'm focused on getting that done first.

However, disabling that seems useful to try.

Also, yes, flathub is quite overloaded since its serving a lot of request for the main repo while also generating deltas and handling new uploads. So, load it likely part of the issue.

@alexlarsson
Copy link
Member

@jurf
Copy link
Member

jurf commented Mar 11, 2019

I can’t reproduce this anymore: https://flathub.org/builds/#/builders/32/builds/975.

@barthalion
Copy link
Member

It's dependent on the load, it won't happen every time.

@barthalion
Copy link
Member

Client now retries uploading if error returned an error. It's not technically a fix, but as it doesn't happen for FreeDesktop SDK and GNOME Nightly repo, it's hard to say if it's actual bug in flat-manager or Flathub hardware is not handling the load.

So while it's not technically "fixed", I'll close it for now as it shouldn't be happening anymore, at least in a way preventing builds from being uploaded.

doc22940 pushed a commit to doc22940/free-desktop-sdk that referenced this issue Nov 18, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

7 participants