Page MenuHomePhabricator
Paste P17446

git clone --depth=1 https://gerrit.wikimedia.org/r/mediawiki/core.git mediawiki
ArchivedPublic

Authored by zeljkofilipin on Oct 8 2021, 3:53 PM.
~$ GIT_TRACE_CURL=1 GIT_TRACE_CURL_NO_DATA=1 git clone --depth=1 https://gerrit.wikimedia.org/r/mediawiki/core.git mediawiki
Cloning into 'mediawiki'...
18:11:59.377481 http.c:731 == Info: Couldn't find host gerrit.wikimedia.org in the .netrc file; using defaults
18:11:59.535149 http.c:731 == Info: Trying 208.80.154.137...
18:11:59.535178 http.c:731 == Info: TCP_NODELAY set
18:11:59.679604 http.c:731 == Info: Connected to gerrit.wikimedia.org (208.80.154.137) port 443 (#0)
18:11:59.679739 http.c:731 == Info: ALPN, offering h2
18:11:59.679748 http.c:731 == Info: ALPN, offering http/1.1
18:11:59.687143 http.c:731 == Info: successfully set certificate verify locations:
18:11:59.687156 http.c:731 == Info: CAfile: /etc/ssl/cert.pem
CApath: none
18:11:59.687245 http.c:731 == Info: TLSv1.2 (OUT), TLS handshake, Client hello (1):
18:11:59.828884 http.c:731 == Info: TLSv1.2 (IN), TLS handshake, Server hello (2):
18:11:59.829086 http.c:731 == Info: TLSv1.2 (IN), TLS handshake, Certificate (11):
18:11:59.849901 http.c:731 == Info: TLSv1.2 (IN), TLS handshake, Server key exchange (12):
18:11:59.850401 http.c:731 == Info: TLSv1.2 (IN), TLS handshake, Server finished (14):
18:11:59.850696 http.c:731 == Info: TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
18:11:59.850705 http.c:731 == Info: TLSv1.2 (OUT), TLS change cipher, Change cipher spec (1):
18:11:59.850742 http.c:731 == Info: TLSv1.2 (OUT), TLS handshake, Finished (20):
18:11:59.994151 http.c:731 == Info: TLSv1.2 (IN), TLS change cipher, Change cipher spec (1):
18:11:59.994282 http.c:731 == Info: TLSv1.2 (IN), TLS handshake, Finished (20):
18:11:59.994311 http.c:731 == Info: SSL connection using TLSv1.2 / ECDHE-ECDSA-CHACHA20-POLY1305
18:11:59.994325 http.c:731 == Info: ALPN, server accepted to use http/1.1
18:11:59.994331 http.c:731 == Info: Server certificate:
18:11:59.994342 http.c:731 == Info: subject: CN=gerrit.wikimedia.org
18:11:59.994348 http.c:731 == Info: start date: Aug 31 17:00:16 2021 GMT
18:11:59.994353 http.c:731 == Info: expire date: Nov 29 17:00:15 2021 GMT
18:11:59.994369 http.c:731 == Info: subjectAltName: host "gerrit.wikimedia.org" matched cert's "gerrit.wikimedia.org"
18:11:59.994379 http.c:731 == Info: issuer: C=US; O=Let's Encrypt; CN=R3
18:11:59.994383 http.c:731 == Info: SSL certificate verify ok.
18:11:59.994480 http.c:678 => Send header, 0000000228 bytes (0x000000e4)
18:11:59.994489 http.c:690 => Send header: GET /r/mediawiki/core.git/info/refs?service=git-upload-pack HTTP/1.1
18:11:59.994493 http.c:690 => Send header: Host: gerrit.wikimedia.org
18:11:59.994496 http.c:690 => Send header: User-Agent: git/2.24.3 (Apple Git-128)
18:11:59.994500 http.c:690 => Send header: Accept: */*
18:11:59.994503 http.c:690 => Send header: Accept-Encoding: deflate, gzip
18:11:59.994506 http.c:690 => Send header: Pragma: no-cache
18:11:59.994509 http.c:690 => Send header: Git-Protocol: version=2
18:11:59.994512 http.c:690 => Send header:
18:12:00.608040 http.c:678 <= Recv header, 0000000017 bytes (0x00000011)
18:12:00.608081 http.c:690 <= Recv header: HTTP/1.1 200 OK
18:12:00.608088 http.c:678 <= Recv header, 0000000037 bytes (0x00000025)
18:12:00.608092 http.c:690 <= Recv header: Date: Fri, 08 Oct 2021 16:12:00 GMT
18:12:00.608098 http.c:678 <= Recv header, 0000000016 bytes (0x00000010)
18:12:00.608102 http.c:690 <= Recv header: Server: Apache
18:12:00.608106 http.c:678 <= Recv header, 0000000074 bytes (0x0000004a)
18:12:00.608118 http.c:690 <= Recv header: Strict-Transport-Security: max-age=106384710; includeSubDomains; preload
18:12:00.608123 http.c:678 <= Recv header, 0000000023 bytes (0x00000017)
18:12:00.608127 http.c:690 <= Recv header: X-Frame-Options: DENY
18:12:00.608131 http.c:678 <= Recv header, 0000000040 bytes (0x00000028)
18:12:00.608134 http.c:690 <= Recv header: Expires: Tue, 01 Jan 1980 00:00:00 GMT
18:12:00.608138 http.c:678 <= Recv header, 0000000018 bytes (0x00000012)
18:12:00.608142 http.c:690 <= Recv header: Pragma: no-cache
18:12:00.608146 http.c:678 <= Recv header, 0000000053 bytes (0x00000035)
18:12:00.608150 http.c:690 <= Recv header: Cache-Control: no-cache, max-age=0, must-revalidate
18:12:00.608154 http.c:678 <= Recv header, 0000000059 bytes (0x0000003b)
18:12:00.608158 http.c:690 <= Recv header: Content-Type: application/x-git-upload-pack-advertisement
18:12:00.608163 http.c:678 <= Recv header, 0000000020 bytes (0x00000014)
18:12:00.608166 http.c:690 <= Recv header: Content-Length: 62
18:12:00.608170 http.c:678 <= Recv header, 0000000043 bytes (0x0000002b)
18:12:00.608174 http.c:690 <= Recv header: Backend-Timing: D=1688 t=1633709520077989
18:12:00.608178 http.c:678 <= Recv header, 0000000002 bytes (0x00000002)
18:12:00.608182 http.c:690 <= Recv header:
18:12:00.608197 http.c:731 == Info: Connection #0 to host gerrit.wikimedia.org left intact
18:12:00.608388 http.c:731 == Info: Couldn't find host gerrit.wikimedia.org in the .netrc file; using defaults
18:12:00.608424 http.c:731 == Info: Found bundle for host gerrit.wikimedia.org: 0x7ff7d6d04a80 [can pipeline]
18:12:00.608429 http.c:731 == Info: Could pipeline, but not asked to!
18:12:00.608444 http.c:731 == Info: Re-using existing connection! (#0) with host gerrit.wikimedia.org
18:12:00.608451 http.c:731 == Info: Connected to gerrit.wikimedia.org (208.80.154.137) port 443 (#0)
18:12:00.608516 http.c:678 => Send header, 0000000300 bytes (0x0000012c)
18:12:00.608524 http.c:690 => Send header: POST /r/mediawiki/core.git/git-upload-pack HTTP/1.1
18:12:00.608530 http.c:690 => Send header: Host: gerrit.wikimedia.org
18:12:00.608534 http.c:690 => Send header: User-Agent: git/2.24.3 (Apple Git-128)
18:12:00.608537 http.c:690 => Send header: Accept-Encoding: deflate, gzip
18:12:00.608541 http.c:690 => Send header: Content-Type: application/x-git-upload-pack-request
18:12:00.608545 http.c:690 => Send header: Accept: application/x-git-upload-pack-result
18:12:00.608548 http.c:690 => Send header: Git-Protocol: version=2
18:12:00.608551 http.c:690 => Send header: Content-Length: 122
18:12:00.608554 http.c:690 => Send header:
18:12:00.608560 http.c:731 == Info: upload completely sent off: 122 out of 122 bytes
18:12:00.897137 http.c:678 <= Recv header, 0000000017 bytes (0x00000011)
18:12:00.897157 http.c:690 <= Recv header: HTTP/1.1 200 OK
18:12:00.897163 http.c:678 <= Recv header, 0000000037 bytes (0x00000025)
18:12:00.897167 http.c:690 <= Recv header: Date: Fri, 08 Oct 2021 16:12:00 GMT
18:12:00.897172 http.c:678 <= Recv header, 0000000016 bytes (0x00000010)
18:12:00.897176 http.c:690 <= Recv header: Server: Apache
18:12:00.897180 http.c:678 <= Recv header, 0000000074 bytes (0x0000004a)
18:12:00.897184 http.c:690 <= Recv header: Strict-Transport-Security: max-age=106384710; includeSubDomains; preload
18:12:00.897188 http.c:678 <= Recv header, 0000000023 bytes (0x00000017)
18:12:00.897192 http.c:690 <= Recv header: X-Frame-Options: DENY
18:12:00.897206 http.c:678 <= Recv header, 0000000040 bytes (0x00000028)
18:12:00.897210 http.c:690 <= Recv header: Expires: Tue, 01 Jan 1980 00:00:00 GMT
18:12:00.897224 http.c:678 <= Recv header, 0000000018 bytes (0x00000012)
18:12:00.897237 http.c:690 <= Recv header: Pragma: no-cache
18:12:00.897243 http.c:678 <= Recv header, 0000000053 bytes (0x00000035)
18:12:00.897247 http.c:690 <= Recv header: Cache-Control: no-cache, max-age=0, must-revalidate
18:12:00.897252 http.c:678 <= Recv header, 0000000052 bytes (0x00000034)
18:12:00.897256 http.c:690 <= Recv header: Content-Type: application/x-git-upload-pack-result
18:12:00.897260 http.c:678 <= Recv header, 0000000045 bytes (0x0000002d)
18:12:00.897264 http.c:690 <= Recv header: Backend-Timing: D=143034 t=1633709520688117
18:12:00.897269 http.c:678 <= Recv header, 0000000028 bytes (0x0000001c)
18:12:00.897281 http.c:690 <= Recv header: Transfer-Encoding: chunked
18:12:00.897285 http.c:678 <= Recv header, 0000000002 bytes (0x00000002)
18:12:00.897288 http.c:690 <= Recv header:
18:12:01.181998 http.c:731 == Info: Connection #0 to host gerrit.wikimedia.org left intact
18:12:01.186693 http.c:731 == Info: Couldn't find host gerrit.wikimedia.org in the .netrc file; using defaults
18:12:01.186712 http.c:731 == Info: Found bundle for host gerrit.wikimedia.org: 0x7ff7d6d04a80 [can pipeline]
18:12:01.186717 http.c:731 == Info: Could pipeline, but not asked to!
18:12:01.186735 http.c:731 == Info: Re-using existing connection! (#0) with host gerrit.wikimedia.org
18:12:01.186743 http.c:731 == Info: Connected to gerrit.wikimedia.org (208.80.154.137) port 443 (#0)
18:12:01.186796 http.c:678 => Send header, 0000000300 bytes (0x0000012c)
18:12:01.186805 http.c:690 => Send header: POST /r/mediawiki/core.git/git-upload-pack HTTP/1.1
18:12:01.186809 http.c:690 => Send header: Host: gerrit.wikimedia.org
18:12:01.186812 http.c:690 => Send header: User-Agent: git/2.24.3 (Apple Git-128)
18:12:01.186824 http.c:690 => Send header: Accept-Encoding: deflate, gzip
18:12:01.186828 http.c:690 => Send header: Content-Type: application/x-git-upload-pack-request
18:12:01.186831 http.c:690 => Send header: Accept: application/x-git-upload-pack-result
18:12:01.186835 http.c:690 => Send header: Git-Protocol: version=2
18:12:01.186838 http.c:690 => Send header: Content-Length: 187
18:12:01.186841 http.c:690 => Send header:
18:12:01.186848 http.c:731 == Info: upload completely sent off: 187 out of 187 bytes
18:12:01.825005 http.c:678 <= Recv header, 0000000017 bytes (0x00000011)
18:12:01.825022 http.c:690 <= Recv header: HTTP/1.1 200 OK
18:12:01.825029 http.c:678 <= Recv header, 0000000037 bytes (0x00000025)
18:12:01.825033 http.c:690 <= Recv header: Date: Fri, 08 Oct 2021 16:12:01 GMT
18:12:01.825038 http.c:678 <= Recv header, 0000000016 bytes (0x00000010)
18:12:01.825042 http.c:690 <= Recv header: Server: Apache
18:12:01.825046 http.c:678 <= Recv header, 0000000074 bytes (0x0000004a)
18:12:01.825056 http.c:690 <= Recv header: Strict-Transport-Security: max-age=106384710; includeSubDomains; preload
18:12:01.825069 http.c:678 <= Recv header, 0000000023 bytes (0x00000017)
18:12:01.825074 http.c:690 <= Recv header: X-Frame-Options: DENY
18:12:01.825078 http.c:678 <= Recv header, 0000000040 bytes (0x00000028)
18:12:01.825082 http.c:690 <= Recv header: Expires: Tue, 01 Jan 1980 00:00:00 GMT
18:12:01.825087 http.c:678 <= Recv header, 0000000018 bytes (0x00000012)
18:12:01.825090 http.c:690 <= Recv header: Pragma: no-cache
18:12:01.825095 http.c:678 <= Recv header, 0000000053 bytes (0x00000035)
18:12:01.825099 http.c:690 <= Recv header: Cache-Control: no-cache, max-age=0, must-revalidate
18:12:01.825104 http.c:678 <= Recv header, 0000000052 bytes (0x00000034)
18:12:01.825107 http.c:690 <= Recv header: Content-Type: application/x-git-upload-pack-result
18:12:01.825112 http.c:678 <= Recv header, 0000000045 bytes (0x0000002d)
18:12:01.825115 http.c:690 <= Recv header: Backend-Timing: D=495370 t=1633709521266171
18:12:01.825120 http.c:678 <= Recv header, 0000000028 bytes (0x0000001c)
18:12:01.825124 http.c:690 <= Recv header: Transfer-Encoding: chunked
18:12:01.825128 http.c:678 <= Recv header, 0000000002 bytes (0x00000002)
18:12:01.825140 http.c:690 <= Recv header:
remote: Counting objects: 8957, done
remote: Finding sources: 100% (8957/8957)
remote: Getting sizes: 100% (7335/7335)
remote: Compressing objects: 99% (93223/93224)
18:17:13.944725 http.c:731 == Info: TLSv1.2 (IN), TLS alert, close notify (256):
18:17:13.944745 http.c:731 == Info: transfer closed with outstanding read data remaining
18:17:13.944760 http.c:731 == Info: Closing connection 0
18:17:13.944787 http.c:731 == Info: TLSv1.2 (OUT), TLS alert, close notify (256):
error: RPC failed; curl 18 transfer closed with outstanding read data remaining
fatal: the remote end hung up unexpectedly
fatal: early EOF
fatal: index-pack failed

Event Timeline

The corresponding errors:

16:12:01.825140 http.c:690              <= Recv header:
	remote: Counting objects: 8957, done
	remote: Finding sources: 100% (8957/8957)
	remote: Getting sizes: 100% (7335/7335)
	remote: Compressing objects:  99% (93223/93224)

On Gerrit server side we have 38 seconds later:

[2021-10-08T16:12:39.410Z] [HTTP POST /r/mediawiki/core.git/git-upload-pack (N/A from )]
WARN  org.eclipse.jetty.server.handler.ContextHandler.r : Internal error during upload-pack from /srv/gerrit/git/mediawiki/core.git

Which is Gerrit hitting httpd.idleTimeout = 30s.

In Apache 5 minutes later:

[Fri Oct 08 16:17:12.854086 2021] [proxy_http:error] [pid 28634:tid 139644410783488]
(70008)Partial results are valid but processing is incomplete: [client x.x.x.x:16503] AH01110: error reading response

And finally a second later on the client side we end up with:

16:17:13.944725 http.c:731              == Info: TLSv1.2 (IN), TLS alert, close notify (256):
16:17:13.944745 http.c:731              == Info: transfer closed with outstanding read data remaining
16:17:13.944760 http.c:731              == Info: Closing connection 0
16:17:13.944787 http.c:731              == Info: TLSv1.2 (OUT), TLS alert, close notify (256):
	error: RPC failed; curl 18 transfer closed with outstanding read data remaining
	fatal: the remote end hung up unexpectedly
	fatal: early EOF
	fatal: index-pack failed

So it is two bug:

  • the httpd idletimeout is reached which might be jgit taking too long to generate the pack file to be send?
  • Apache should abort the connection earlier?