Page MenuHomePhabricator

Can't do shallow clone from phabricator
Open, MediumPublic

Description

Reproduce:

amsa@amsa-Latitude-7480:~$ git clone --depth 1 https://phabricator.wikimedia.org/source/tool-quickstatements.git 
Cloning into 'tool-quickstatements'...
error: RPC failed; HTTP 500 curl 22 The requested URL returned error: 500 Internal Server Error
fatal: The remote end hung up unexpectedly

git clone https://phabricator.wikimedia.org/source/tool-quickstatements.git works fine. The URL is advertised in https://toolsadmin.wikimedia.org/tools/id/quickstatements/repos/id/tool-quickstatements and https://phabricator.wikimedia.org/source/tool-quickstatements/

It causes failures in Wikibase docker images: https://travis-ci.org/wmde/wikibase-docker/jobs/625702926?utm_medium=notification&utm_source=github_status

Revisions and Commits

Event Timeline

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptDec 16 2019, 2:40 PM
Addshore triaged this task as Medium priority.Dec 16 2019, 5:45 PM
Addshore moved this task from incoming to monitoring on the Wikidata board.

Does it work over ssh? Shallow clone should work but I have no idea where to begin debugging this.

it works over ssh but I can't use it in the Dockerfile because it requires public/private ssh keys to connect to phabricator.

Legoktm added a subscriber: Legoktm.

This is definitely a regression, as codesearch used to be able to do shallow clones fine.

Is there an error log on the server for the HTTP 500 error?

This is definitely a regression, as codesearch used to be able to do shallow clones fine.

Is there an error log on the server for the HTTP 500 error?

It's dying with an error about missing objects. Somehow the shallow clone is trying to fetch some object that doesn't exist in the repo and I haven't been able to make sense of why. The object actually does not exist when I check on the server directly and I don't know how git builds the list of objects to fetch for a shallow clone.

I ran into this issue yesterday in during a submodule update for Wikibase with --depth 1.

$ git submodule update --init --recursive --depth 1 extensions/Wikibase
Submodule 'extensions/Wikibase' (https://gerrit.wikimedia.org/r/mediawiki/extensions/Wikibase) registered for path 'extensions/Wikibase'
Cloning into 'extensions/Wikibase'...
remote: Counting objects: 4463, done
remote: Finding sources: 100% (4463/4463)
remote: Getting sizes: 100% (4074/4074)
remote: Compressing objects:  99% (17225/17226)
remote: Total 4463 (delta 906), reused 1457 (delta 388)
Receiving objects: 100% (4463/4463), 4.88 MiB | 3.75 MiB/s, done.
Resolving deltas: 100% (906/906), done.
Checking connectivity... done.
Submodule path 'extensions/Wikibase': checked out 'ad76c4f09a21a877d20fb4d055c70277f323fba0'
Submodule 'lib/resources/wikibase-api' (https://gerrit.wikimedia.org/r/wikibase/javascript-api) registered for path 'lib/resources/wikibase-api'
Submodule 'view/lib/wikibase-data-model' (https://phabricator.wikimedia.org/source/wikibase-data-model.git) registered for path 'view/lib/wikibase-data-model'
Submodule 'view/lib/wikibase-data-values' (https://phabricator.wikimedia.org/source/datavalues-javascript.git) registered for path 'view/lib/wikibase-data-values'
Submodule 'view/lib/wikibase-data-values-value-view' (https://gerrit.wikimedia.org/r/data-values/value-view) registered for path 'view/lib/wikibase-data-values-value-view'
Submodule 'view/lib/wikibase-serialization' (https://phabricator.wikimedia.org/source/wikibase-serialization.git) registered for path 'view/lib/wikibase-serialization'
Submodule 'view/lib/wikibase-termbox' (https://gerrit.wikimedia.org/r/wikibase/termbox) registered for path 'view/lib/wikibase-termbox'
Cloning into 'lib/resources/wikibase-api'...
remote: Counting objects: 24, done
remote: Finding sources: 100% (24/24)
remote: Getting sizes: 100% (23/23)
remote: Compressing objects: 100% (60630/60630)
remote: Total 24 (delta 0), reused 12 (delta 0)
Unpacking objects: 100% (24/24), done.
Checking connectivity... done.
Submodule path 'extensions/Wikibase/lib/resources/wikibase-api': checked out '2bdd34cbe4c31cf67f0bf72d968c289209ff6cc8'
Cloning into 'view/lib/wikibase-data-model'...
error: RPC failed; result=22, HTTP code = 500
fatal: The remote end hung up unexpectedly
Clone of 'https://phabricator.wikimedia.org/source/wikibase-data-model.git' into submodule path 'view/lib/wikibase-data-model' failed
Failed to recurse into submodule path 'extensions/Wikibase'

@thcipriani and I peeked into the logs earlier but we couldn't see anything in the PHP error log, only the 500 response in the access logs.

Taking a look at the access logs and after doing some local tracing, it seems it fails on the pack request—something that is not sent when --depth 1 is omitted.

1> GET /diffusion/ANAB/analytics-blog.git/info/refs?service=git-upload-pack HTTP/1.1
2Host: phabricator.wikimedia.org
3User-Agent: git/2.6.1.dirty
4Accept: */*
5Accept-Encoding: gzip
6Pragma: no-cache
7
8< HTTP/1.1 200 OK
9< date: Fri, 23 Oct 2020 20:52:05 GMT
10< server: Apache
11< x-frame-options: Deny
12< content-security-policy: default-src https://phab.wmfusercontent.org; img-src https://phab.wmfusercontent.org data:; style-src https://phab.wmfusercontent.org 'unsafe-inline'; script-src https://phab.wmfusercontent.org; connect-src 'self'; frame-src 'self'; frame-ancestors 'none'; object-src 'none'; form-action 'self'; base-uri 'none'
13< referrer-policy: no-referrer
14< expires: Fri, 01 Jan 1980 00:00:00 GMT
15< pragma: no-cache
16< cache-control: no-cache, max-age=0, must-revalidate
17< content-type: application/x-git-upload-pack-advertisement
18< Age: 0
19< X-Cache: cp4027 miss, cp4029 pass
20< X-Cache-Status: pass
21< Server-Timing: cache;desc="pass"
22< Strict-Transport-Security: max-age=106384710; includeSubDomains; preload
23< Report-To: { "group": "wm_nel", "max_age": 86400, "endpoints": [{ "url": "https://intake-logging.wikimedia.org/v1/events?stream=w3c.reportingapi.network_error&schema_uri=/w3c/reportingapi/network_error/1.0.0" }] }
24< NEL: { "report_to": "wm_nel", "max_age": 86400, "failure_fraction": 0.05, "success_fraction": 0.0}
25< Set-Cookie: [omitted]
26< X-Client-IP: [omitted]
27< Accept-Ranges: bytes
28< Content-Length: 1079
29< Connection: keep-alive
30<
31* Connection #0 to host phabricator.wikimedia.org left intact
3213:52:05.432832 pkt-line.c:71 packet: git< # service=git-upload-pack
3313:52:05.433416 pkt-line.c:71 packet: git< 0000
3413:52:05.433437 pkt-line.c:71 packet: git< 09a632607a03e09fa750884a819b91b400504619 HEAD\0multi_ack thin-pack side-band side-band-64k ofs-delta shallow deepen-since deepen-not deepen-relative no-progress include-tag multi_ack_detailed no-done symref=HEAD:refs/heads/master agent=git/2.20.1
3513:52:05.433453 pkt-line.c:71 packet: git< a88c7a5bfe9660e5cc97b2d8ad16f85c21085230 refs/changes/56/180156/meta
3613:52:05.433463 pkt-line.c:71 packet: git< 671bd6414f5d7a2afdf44acfaecc1e9368c4c7a7 refs/changes/57/180157/meta
3713:52:05.433472 pkt-line.c:71 packet: git< 94a4407acb186b4367d10a46246b84cdba4faeae refs/changes/58/180158/meta
3813:52:05.433480 pkt-line.c:71 packet: git< e3e2e72530288b84a081e8e62a534740425e9242 refs/changes/59/180159/meta
3913:52:05.433489 pkt-line.c:71 packet: git< 343e913dac318fd2fa208dae2727501884fd0598 refs/changes/60/180160/meta
4013:52:05.433497 pkt-line.c:71 packet: git< aeac7452d44b50a9e0b911e774128200efb4066c refs/changes/61/180161/meta
4113:52:05.433505 pkt-line.c:71 packet: git< c127d6700e5a7a7558ffaabe68d5312ff85758f6 refs/changes/69/180369/meta
4213:52:05.433514 pkt-line.c:71 packet: git< 12496dd6de34d57940f5860f6918ddc597e6dfd2 refs/changes/72/180472/meta
4313:52:05.433526 pkt-line.c:71 packet: git< 6fa361bb1888c3ef4292fdb8ddbd9b64d38c24b0 refs/changes/93/60793/meta
4413:52:05.433539 pkt-line.c:71 packet: git< 86119f2be8e59637e354ab51051dffa34225f5bc refs/changes/94/60794/meta
4513:52:05.433550 pkt-line.c:71 packet: git< 09a632607a03e09fa750884a819b91b400504619 refs/heads/master
4613:52:05.433561 pkt-line.c:71 packet: git< 0000
4713:52:05.433779 pkt-line.c:71 packet: git> 09a632607a03e09fa750884a819b91b400504619 refs/heads/master\12
4813:52:05.433790 pkt-line.c:71 packet: git> 0000
4913:52:05.443387 pkt-line.c:71 packet: fetch-pack< 09a632607a03e09fa750884a819b91b400504619 refs/heads/master
5013:52:05.443825 pkt-line.c:71 packet: fetch-pack< 0000
5113:52:05.443834 pkt-line.c:71 packet: fetch-pack< 09a632607a03e09fa750884a819b91b400504619 HEAD\0multi_ack thin-pack side-band side-band-64k ofs-delta shallow deepen-since deepen-not deepen-relative no-progress include-tag multi_ack_detailed no-done symref=HEAD:refs/heads/master agent=git/2.20.1
5213:52:05.443847 pkt-line.c:71 packet: fetch-pack< a88c7a5bfe9660e5cc97b2d8ad16f85c21085230 refs/changes/56/180156/meta
5313:52:05.443852 pkt-line.c:71 packet: fetch-pack< 671bd6414f5d7a2afdf44acfaecc1e9368c4c7a7 refs/changes/57/180157/meta
5413:52:05.443857 pkt-line.c:71 packet: fetch-pack< 94a4407acb186b4367d10a46246b84cdba4faeae refs/changes/58/180158/meta
5513:52:05.443862 pkt-line.c:71 packet: fetch-pack< e3e2e72530288b84a081e8e62a534740425e9242 refs/changes/59/180159/meta
5613:52:05.443867 pkt-line.c:71 packet: fetch-pack< 343e913dac318fd2fa208dae2727501884fd0598 refs/changes/60/180160/meta
5713:52:05.443872 pkt-line.c:71 packet: fetch-pack< aeac7452d44b50a9e0b911e774128200efb4066c refs/changes/61/180161/meta
5813:52:05.443876 pkt-line.c:71 packet: fetch-pack< c127d6700e5a7a7558ffaabe68d5312ff85758f6 refs/changes/69/180369/meta
5913:52:05.443881 pkt-line.c:71 packet: fetch-pack< 12496dd6de34d57940f5860f6918ddc597e6dfd2 refs/changes/72/180472/meta
6013:52:05.443887 pkt-line.c:71 packet: fetch-pack< 6fa361bb1888c3ef4292fdb8ddbd9b64d38c24b0 refs/changes/93/60793/meta
6113:52:05.443891 pkt-line.c:71 packet: fetch-pack< 86119f2be8e59637e354ab51051dffa34225f5bc refs/changes/94/60794/meta
6213:52:05.443902 pkt-line.c:71 packet: fetch-pack< 09a632607a03e09fa750884a819b91b400504619 refs/heads/master
6313:52:05.443906 pkt-line.c:71 packet: fetch-pack< 0000
6413:52:05.444662 pkt-line.c:71 packet: fetch-pack> want 09a632607a03e09fa750884a819b91b400504619 multi_ack_detailed no-done side-band-64k thin-pack no-progress ofs-delta agent=git/2.6.1.dirty\12
6513:52:05.444672 pkt-line.c:71 packet: fetch-pack> shallow 09a632607a03e09fa750884a819b91b400504619
6613:52:05.444675 pkt-line.c:71 packet: fetch-pack> deepen 1
6713:52:05.444678 pkt-line.c:71 packet: fetch-pack> 0000
6813:52:05.444686 pkt-line.c:71 packet: fetch-pack> 0000
6913:52:05.444711 pkt-line.c:71 packet: git< 0091want 09a632607a03e09fa750884a819b91b400504619 multi_ack_detailed no-done side-band-64k thin-pack no-progress ofs-delta agent=git/2.6.1.dirty\120034shallow 09a632607a03e09fa750884a819b91b400504619000cdeepen 10000
7013:52:05.444741 pkt-line.c:71 packet: git< 0000
71* Couldn't find host phabricator.wikimedia.org in the .netrc file; using defaults
72* Found bundle for host phabricator.wikimedia.org: 0x7f895ac21dc0 [can pipeline]
73* Re-using existing connection! (#0) with host phabricator.wikimedia.org
74* Connected to phabricator.wikimedia.org (2620:0:863:ed1a::1) port 443 (#0)
75> POST /diffusion/ANAB/analytics-blog.git/git-upload-pack HTTP/1.1
76Host: phabricator.wikimedia.org
77User-Agent: git/2.6.1.dirty
78Accept-Encoding: gzip
79Cookie: WMF-Last-Access=23-Oct-2020
80Content-Type: application/x-git-upload-pack-request
81Accept: application/x-git-upload-pack-result
82Content-Length: 213
83
84* upload completely sent off: 213 out of 213 bytes
85* The requested URL returned error: 500 Internal Server Error
86* stopped the pause stream!
87* Closing connection 0
88error: RPC failed; result=22, HTTP code = 500
89fatal: The remote end hung up unexpectedly

The 500 can then be reproduced without git by sending this same request with curl.

1$ echo -ne "0091want 09a632607a03e09fa750884a819b91b400504619 multi_ack_detailed no-done side-band-64k thin-pack no-progress ofs-delta agent=git/2.6.1.dirty\n0034shallow 09a632607a03e09fa750884a819b91b400504619000cdeepen 10000" | curl -v --http1.1 https://phabricator.wikimedia.org/diffusion/ANAB/analytics-blog.git/git-upload-pack -H 'Content-Type: application/x-git-upload-pack-request' -H 'Accept: application/x-git-upload-pack-result' --data-binary @-
2> POST /diffusion/ANAB/analytics-blog.git/git-upload-pack HTTP/1.1
3> Host: phabricator.wikimedia.org
4> User-Agent: curl/7.54.0
5> Content-Type: application/x-git-upload-pack-request
6> Accept: application/x-git-upload-pack-result
7> Content-Length: 213
8>
9* upload completely sent off: 213 out of 213 bytes
10< HTTP/1.1 500 Internal Server Error
11< date: Fri, 23 Oct 2020 21:17:35 GMT
12< server: Apache
13< content-type: text/html; charset=UTF-8
14< Vary: Accept-Encoding
15< Age: 0
16< X-Cache: cp4032 miss, cp4029 pass
17< X-Cache-Status: pass
18< Server-Timing: cache;desc="pass"
19< Strict-Transport-Security: max-age=106384710; includeSubDomains; preload
20< Report-To: { "group": "wm_nel", "max_age": 86400, "endpoints": [{ "url": "https://intake-logging.wikimedia.org/v1/events?stream=w3c.reportingapi.network_error&schema_uri=/w3c/reportingapi/network_error/1.0.0" }] }
21< NEL: { "report_to": "wm_nel", "max_age": 86400, "failure_fraction": 0.05, "success_fraction": 0.0}
22< Set-Cookie: [omitted]
23< X-Client-IP: [omitted]
24< Content-Length: 56
25< Connection: keep-alive
26<
27500 Error 1: fatal: the remote end hung up unexpectedly
28* Connection #0 to host phabricator.wikimedia.org left intact

To see what a normal response might be, I sent the same HTTP request to the repo on GitHub, and it returns a successful response with a single git flush packet in the post body.

1$ echo -ne "0091want 09a632607a03e09fa750884a819b91b400504619 multi_ack_detailed no-done side-band-64k thin-pack no-progress ofs-delta agent=git/2.6.1.dirty\n0034shallow 09a632607a03e09fa750884a819b91b400504619000cdeepen 10000" | curl -v --http1.1 https://github.com/wikimedia/analytics-blog.git/git-upload-pack -H 'Content-Type: application/x-git-upload-pack-request' -H 'Accept: application/x-git-upload-pack-result' --data-binary @-
2> POST /wikimedia/analytics-blog.git/git-upload-pack HTTP/1.1
3> Host: github.com
4> User-Agent: curl/7.54.0
5> Content-Type: application/x-git-upload-pack-request
6> Accept: application/x-git-upload-pack-result
7> Content-Length: 213
8>
9* upload completely sent off: 213 out of 213 bytes
10< HTTP/1.1 200 OK
11< Server: GitHub Babel 2.0
12< Content-Type: application/x-git-upload-pack-result
13< Transfer-Encoding: chunked
14< Expires: Fri, 01 Jan 1980 00:00:00 GMT
15< Pragma: no-cache
16< Cache-Control: no-cache, max-age=0, must-revalidate
17< Vary: Accept-Encoding
18< X-GitHub-Request-Id: [omitted]
19< X-Frame-Options: DENY
20<
21* Connection #0 to host github.com left intact
220000

In further tracing the GitHub request, you can see that git should then perform a second request with a "done" packet to receive the packfile contents.

I don't know if this is helpful or not, but maybe we can use the case to reproduce the problem closer to the Phab source.

mmodell claimed this task.Sun, Nov 1, 9:26 PM

Assigning to myself so I remember to deploy this.

dduvall added a comment.EditedMon, Nov 2, 4:52 PM

For the paper trail:

  • The upstream patch has landed. If you run into rebase issues around this later, that's probably why, though it should be identical in its implementation.
  • The underlying issue is related to git-http-backend and git-upload-pack die()ing on unexpected EOF from the client. I've submitted a patch to git. Sounds like it might get applied at some point!
  • Git protocol v2 is not affected by the git-upload-pack bug. I'm wondering if we can also get Diffusion working with v2 by forwarding Git-Protocol headers to git-http-backend in the environment (as GIT_PROTOCOL). I'm not totally sure if Diffusion will play nicely with HTTP 100s used in v2 over HTTP but we should test it.

Mentioned in SAL (#wikimedia-operations) [2020-11-02T22:03:52Z] <twentyafterfour> applied 113a244a66 on phab1001 to hotfix T240862

This is now hotfixed by {0e3e3dd2fa143942db3928beea256ece0ca434f7} which is cherry-picked on production pending a proper deployment on wednesday.