Gerrit error with remote gerrit via http

[Richard Christie]

Has anyone seen issues where attempting to push to gerrit via https (over a slow link) ends up with something like:

git push -f --no-thin -o skip-validation --no-tags https://<remote-gerrit>/a/<remote-project>.git 'refs/heads/<any-head>:refs/heads/<any-head>'

Enumerating objects: 410, done.

Counting objects: 100% (410/410), done.

Delta compression using up to 24 threads

Compressing objects: 100% (109/109), done.

Writing objects: 100% (410/410), 539.83 KiB | 9.31 MiB/s, done.

Total 410 (delta 274), reused 384 (delta 260)

remote: Resolving deltas: 100% (274/274)

error: remote unpack failed: error Missing tree 423390797e48d2569f5d8658fc32c3e0adc161cf

To https://<remote-gerrit>/a/<remote-project>.git

 ! [remote rejected]         <src-ref> -> <dest-ref> (n/a (unpacker error))

error: failed to push some refs to 'https://<remote-gerrit>/a/<remote-project>.git'

But a "git show 423390797e48d2569f5d8658fc32c3e0adc161cf" on the remote repository in the file system shows the tree fine - as it does in the local. For security "reasons" there's no ssh between the two hosts so it's hard to verify whether this would happen via a standard git push against a (vanilla git) server. 

Regardless, any idea whether it's possible to do anything about this?

Equally, does gerrit even respect "--no-thin" or is that being ignored?

Finally (on a vaguely related note) is it possible to get "-o skip-validation" passed through by the replication plugin - didn't see any option for it - or does jgit not even support that?

[Luca Milanesio]

> On 16 Sep 2019, at 10:47, Richard Christie <r.d.f.c...@gmail.com> wrote:
>
> Has anyone seen issues where attempting to push to gerrit via https (over a slow link) ends up with something like:
>
> git push -f --no-thin -o skip-validation --no-tags https://<remote-gerrit>/a/<remote-project>.git 'refs/heads/<any-head>:refs/heads/<any-head>'
> Enumerating objects: 410, done.
> Counting objects: 100% (410/410), done.
> Delta compression using up to 24 threads
> Compressing objects: 100% (109/109), done.
> Writing objects: 100% (410/410), 539.83 KiB | 9.31 MiB/s, done.
> Total 410 (delta 274), reused 384 (delta 260)
> remote: Resolving deltas: 100% (274/274)
> error: remote unpack failed: error Missing tree 423390797e48d2569f5d8658fc32c3e0adc161cf
> To https://<remote-gerrit>/a/<remote-project>.git
> ! [remote rejected] <src-ref> -> <dest-ref> (n/a (unpacker error))
> error: failed to push some refs to 'https://<remote-gerrit>/a/<remote-project>.git'
>
> But a "git show 423390797e48d2569f5d8658fc32c3e0adc161cf" on the remote repository in the file system shows the tree fine - as it does in the local. For security "reasons" there's no ssh between the two hosts so it's hard to verify whether this would happen via a standard git push against a (vanilla git) server.

What version of Gerrit are you running on the server?

[Richard Christie]

On Monday, 16 September 2019 10:50:25 UTC+1, lucamilanesio wrote:

Currently 2.16.10.

I should note that the repo is also pretty bloated, circa 4-5G when gc'd and about 4400 refs (not including changes/notes)

Picking different refs to sync can result in different missing objects/blobs/trees; but the hashes are always present (both in source and destination) when checked with command line "git show".

The errors are brought to our attention by the replication plugin attempting to push refs out, but above I am reproducing with command line git 2.23.0, so have discounted it being anything to do with that for now.

[Luca Milanesio]

I believe the "Missing tree" could just be the tip of the Iceberg: do you have access to the server's log?

Is there any stacktrace before or related to the error?

Luca.

[Richard Christie]

On Monday, 16 September 2019 11:35:51 UTC+1, lucamilanesio wrote:

I should also add that the server is behind an nginx reverse proxy.

Anyway, yes, gerrit's error log has a monumental stack trace which you can see below:

[2019-09-16 05:45:27,220] [HTTP-185236] WARN  org.eclipse.jetty.server.handler.ContextHandler.ROOT : Internal error during receive-pack to <filesystem-location-of-git-repository>

org.eclipse.jgit.errors.MissingObjectException: Missing tree 423390797e48d2569f5d8658fc32c3e0adc161cf

at org.eclipse.jgit.transport.BaseReceivePack.checkConnectivity(BaseReceivePack.java:1600)

at org.eclipse.jgit.transport.BaseReceivePack.receivePackAndCheckConnectivity(BaseReceivePack.java:1196)

at org.eclipse.jgit.transport.ReceivePack.service(ReceivePack.java:266)

at org.eclipse.jgit.transport.ReceivePack.receive(ReceivePack.java:221)

at org.eclipse.jgit.http.server.ReceivePackServlet.doPost(ReceivePackServlet.java:197)

at javax.servlet.http.HttpServlet.service(HttpServlet.java:661)

at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)

at org.eclipse.jgit.http.server.glue.UrlPipeline$Chain.doFilter(UrlPipeline.java:244)

at com.google.gerrit.httpd.GitOverHttpServlet$ReceiveFilter.doFilter(GitOverHttpServlet.java:470)

at org.eclipse.jgit.http.server.glue.UrlPipeline$Chain.doFilter(UrlPipeline.java:242)

at org.eclipse.jgit.http.server.ReceivePackServlet$Factory.doFilter(ReceivePackServlet.java:151)

at org.eclipse.jgit.http.server.glue.UrlPipeline$Chain.doFilter(UrlPipeline.java:242)

at org.eclipse.jgit.http.server.RepositoryFilter.doFilter(RepositoryFilter.java:145)

at org.eclipse.jgit.http.server.glue.UrlPipeline$Chain.doFilter(UrlPipeline.java:242)

at org.eclipse.jgit.http.server.NoCacheFilter.doFilter(NoCacheFilter.java:86)

at org.eclipse.jgit.http.server.glue.UrlPipeline$Chain.doFilter(UrlPipeline.java:242)

at org.eclipse.jgit.http.server.glue.UrlPipeline.service(UrlPipeline.java:221)

at org.eclipse.jgit.http.server.glue.SuffixPipeline.service(SuffixPipeline.java:103)

at org.eclipse.jgit.http.server.glue.MetaFilter.doFilter(MetaFilter.java:183)

at org.eclipse.jgit.http.server.glue.MetaServlet.service(MetaServlet.java:143)

at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)

at com.google.inject.servlet.ServletDefinition.doServiceImpl(ServletDefinition.java:290)

at com.google.inject.servlet.ServletDefinition.doService(ServletDefinition.java:280)

at com.google.inject.servlet.ServletDefinition.service(ServletDefinition.java:184)

at com.google.inject.servlet.ManagedServletPipeline.service(ManagedServletPipeline.java:89)

at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:85)

at com.google.gerrit.httpd.raw.StaticModule$PolyGerritFilter.doFilter(StaticModule.java:485)

at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)

at com.google.gerrit.httpd.GetUserFilter.doFilter(GetUserFilter.java:92)

at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)

at com.google.gerrit.httpd.RequireSslFilter.doFilter(RequireSslFilter.java:72)

at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)

at com.google.gerrit.httpd.RunAsFilter.doFilter(RunAsFilter.java:121)

at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)

at com.google.gerrit.httpd.RequireIdentifiedUserFilter.doFilter(RequireIdentifiedUserFilter.java:50)

at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)

at com.google.gerrit.httpd.GwtCacheControlFilter.doFilter(GwtCacheControlFilter.java:72)

at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)

at com.google.gerrit.httpd.AllRequestFilter$FilterProxy$1.doFilter(AllRequestFilter.java:133)

at com.googlesource.gerrit.plugins.quota.RestApiRateLimiter.doFilter(RestApiRateLimiter.java:108)

at com.google.gerrit.httpd.AllRequestFilter$FilterProxy$1.doFilter(AllRequestFilter.java:129)

at com.google.gerrit.httpd.AllRequestFilter$FilterProxy.doFilter(AllRequestFilter.java:135)

at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)

at com.google.gerrit.httpd.ProjectBasicAuthFilter.doFilter(ProjectBasicAuthFilter.java:100)

at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)

at com.google.gerrit.httpd.ProjectBasicAuthFilter.doFilter(ProjectBasicAuthFilter.java:100)

at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)

at com.google.gerrit.httpd.RequestMetricsFilter.doFilter(RequestMetricsFilter.java:57)

at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)

at com.google.gerrit.httpd.RequestContextFilter.doFilter(RequestContextFilter.java:69)

at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)

at com.google.gerrit.pgm.http.jetty.ProjectQoSFilter.doFilter(ProjectQoSFilter.java:129)

at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)

at com.google.inject.servlet.ManagedFilterPipeline.dispatch(ManagedFilterPipeline.java:121)

at com.google.inject.servlet.GuiceFilter.doFilter(GuiceFilter.java:133)

at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1610)

at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:540)

at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255)

at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1588)

at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255)

at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1345)

at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203)

at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:480)

at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1557)

at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201)

at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1247)

at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144)

at org.eclipse.jetty.server.handler.RequestLogHandler.handle(RequestLogHandler.java:56)

at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)

at org.eclipse.jetty.server.Server.handleAsync(Server.java:547)

at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:388)

at org.eclipse.jetty.server.HttpChannel.run(HttpChannel.java:305)

at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:765)

at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:683)

at java.lang.Thread.run(Thread.java:748)

 

[Luca Milanesio]

Is that *the only* error you see for that repository? Is there anything before that? (look at the previous 3h for instance)

Are you making concurrent GCs on it?

What is the associated gitconfig?

Luca.

[Richard Christie]

On Monday, 16 September 2019 11:53:01 UTC+1, lucamilanesio wrote:

There are similar errors each time the replication plugin tries to push (as mentioned, missing hashes vary depending on the incoming ref).

Gerrit has GC on cron, the previous attempt to GC the repo showed (looking at the gc log)

[2019-09-16 01:13:43,309] INFO  : [<repo>] gc config: gc.aggressive=false; 

[2019-09-16 01:13:43,309] INFO  : [<repo>] pack config: maxDeltaDepth=50, deltaSearchWindowSize=10, deltaSearchMemoryLimit=0, deltaCacheSize=52428800, deltaCacheLimit=100, compressionLevel=-1, indexVersion=2, bigFileThreshold=52428800, threads=0, reuseDeltas=true, reuseObjects=true, deltaCompress=true, buildBitmaps=true, bitmapContiguousCommitCount=100, bitmapRecentCommitCount=20000, bitmapRecentCommitSpan=100, bitmapDistantCommitSpan=5000, bitmapExcessiveBranchCount=100, bitmapInactiveBranchAge=90, singlePack=false

[2019-09-16 01:13:43,443] INFO  : [<repo>] before: sizeOfPackedObjects=24306253687, sizeOfLooseObjects=235946889, numberOfPackedObjects=15368095, numberOfPackFiles=7, numberOfPackedRefs=4107, numberOfLooseRefs=0, numberOfLooseObjects=16855

[2019-09-16 01:22:23,833] INFO  : [<repo>] after:  sizeOfPackedObjects=4419861312, sizeOfLooseObjects=238355369, numberOfPackedObjects=2781745, numberOfPackFiles=2, numberOfPackedRefs=4107, numberOfLooseRefs=0, numberOfLooseObjects=17010

no errors there. It is quite possible replication might try to push during that time though I cannot see evidence of it in the pushing server's replication.log, which has entries for

[2019-09-15 19:39:02,552]

and then

[2019-09-16 01:40:22,661] [] scheduling replication …

The replication has also been failing for other reasons (permission denied) for the past several days so we only started noticing this when that got fixed up.

There are plenty of other repositories being pushed between the two servers via the same reverse proxied https, which are all fine, so I'm tempted to call "repository corruption" here. Does gerrit's own "scheduled" GC lock the repository to incoming push attempts during that time? Or is that dangerous/racy?

[Richard Christie]

Oh, by "on cron" above, I actually mean scheduled within the "gerrit.config" not using an actual crontab to manually call the gc APIs.

[Richard Christie]

On Monday, 16 September 2019 12:10:10 UTC+1, Richard Christie wrote:

Oh, by "on cron" above, I actually mean scheduled within the "gerrit.config" not using an actual crontab to manually call the gc APIs.

So I took a copy of the repository on the destination side (just via cp -r to /tmp) and then instigated a command line fetch from that side from the pushing gerrit. It completed without any problems.

`Curiouser and curiouser!' cried Alice

[Matthias Sohn]

what's the output for

$ git fsck --full

does it show any errors ? 

[Richard Christie]

On Monday, 16 September 2019 16:48:09 UTC+1, Matthias Sohn wrote:

On the source repository there are a few dangling commits, though that's fairly normal, given that people frequently force-push to some branches. No other issues found.

On the destination repository it is likewise along with "notice: HEAD points to an unborn branch (master)" - which we expect.

No other issues/errors, though it does take ~35mins to do the fsck.

Also Luca, sorry, missed some of your earlier questions there:

> Are you making concurrent GCs on it?

No, though you did not answer my questions as to whether it was safe to push to a repo in gerrit (via gerrit) at the same as gerrit was performing a GC. Not sure we've seen that happen as we time GC to try and avoid it, but we certainly do not take steps to prevent it.

> What is the associated gitconfig?

We don't touch the config file for the most part; so it looks like default gerrit. The source side looks like:

> Any other errors

No, only when the replication plugin tries to push. People seem to be fetching from it fine.

[core]

symlinks = false

repositoryformatversion = 0

filemode = true

bare = true

logallrefupdates = true

Destination side looks like

[core]

repositoryformatversion = 0

filemode = true

bare = true

[Richard Christie]

The updates started failing against yesterday. We manually synched (via pulling from the destination side) and after that, the replication plugin was happy for the next 5h or so, during which time many reference updates came across fine. Then a bit later, it suddenly started failing with the "missing … hash" - blob this time. No GC was run during that interval.

[Richard Christie]

So another observation:

I tied fetching to a copy of the repository and then pushing through https through gerrit (and the reverse proxy) exactly the same refs, and it works. So there's something very fishy here - I'm now leaning towards gerrit weirdness being triggered by the link in to the secure site.

- Is there any trace we can activate on the gerrit side of all the low-level git operations so we can compare and get to why it thinks these refs are missing when they're not?

- As before but was unanswered - does gerrit respect --no-thin coming in from command line git?

- And likewise - is there a way to pass "-o skip-validation" through the replication plugin? If not (I'm guessing as I couldn't see anything in the docs), is the capability there in JGIT and it just needs plumbing through?

Next time it goes wrong (since it seems to every half day or so), I'll run with maximum trace on the git client side to see whether that shows anything.

[Richard Christie]

So one more try at bumping this as I did a bit more research

- I was not able to find anything useful with the low level git client trace.

- Every so often pushes start failing, normally it seems to be merge commits that cause the issue

- Sometimes failing ones just "magically" resolve themselves later on, for example [1]

- Objects supposedly missing are always in the remote end

- pushing the same to a host ssh daemon on the affected host (so using c-git on both ends) never fails

- fetching from the affected host side never fails

- pushing to gerrit ssh or http from the same host (including bypassing the reverse-proxy for https) always fails 

- Cloning the "sick" repository from the destination gerrit works fine and checking out commits which contain the missing blobs/trees works fine too

- git fsck --full (still) reports no problems

So I'm minded (given the weirdness, and fsck working etc) to blame gerrit at this point and raise a ticket. Does that make sense? Or can anyone suggest anything else?

[1] Extract using grep on the replication log for the destination repo in question. A single commit on the X ref is being pushed and failing. The missing blob in question is in that commit along with hundreds, if not thousands of other commits (wasn't changed in that commit). The commit was a merge. It fails until a second ref tries to be replicated at the same time (which also contains the same blob) and suddenly, they both "just work".

[2019-09-25 10:53:01,734] [] scheduling replication <repo>:refs/heads/X => https://<server>/<repo>

[2019-09-25 10:53:01,735] [] scheduled <repo>:refs/heads/X => [4e5931b6] push https://<server>/<repo> to run after 2s

[2019-09-25 10:53:03,735] [4e5931b6] Replication to https://<server>/<repo> started...

[2019-09-25 10:53:03,741] [4e5931b6] Push to https://<server>/<repo> references: [RemoteRefUpdate[remoteName=refs/heads/upstream/X, NOT_ATTEMPTED, (null)...ce30ff9eacd057b39c240731ca95f4c1ce01b4f0, srcRef=refs/heads/X, forceUpdate, message=null]]

[2019-09-25 10:53:08,278] [4e5931b6] Cannot replicate to https://<server>/<repo>

org.eclipse.jgit.errors.TransportException: https://<server>/<repo>: error occurred during unpacking on the remote end: error Missing blob c52dddb55862509bd544af3193435239064b5926

[2019-09-25 10:58:08,283] [4e5931b6] Replication to https://<server>/<repo> started...

[2019-09-25 10:58:08,288] [4e5931b6] Push to https://<server>/<repo> references: [RemoteRefUpdate[remoteName=refs/heads/upstream/X, NOT_ATTEMPTED, (null)...ce30ff9eacd057b39c240731ca95f4c1ce01b4f0, srcRef=refs/heads/X, forceUpdate, message=null]]

[2019-09-25 10:58:12,779] [4e5931b6] Cannot replicate to https://<server>/<repo>

org.eclipse.jgit.errors.TransportException: https://<server>/<repo>: error occurred during unpacking on the remote end: error Missing blob c52dddb55862509bd544af3193435239064b5926

[2019-09-25 11:03:12,786] [4e5931b6] Replication to https://<server>/<repo> started...

[2019-09-25 11:03:12,792] [4e5931b6] Push to https://<server>/<repo> references: [RemoteRefUpdate[remoteName=refs/heads/upstream/X, NOT_ATTEMPTED, (null)...ce30ff9eacd057b39c240731ca95f4c1ce01b4f0, srcRef=refs/heads/X, forceUpdate, message=null]]

[2019-09-25 11:03:17,381] [4e5931b6] Cannot replicate to https://<server>/<repo>

org.eclipse.jgit.errors.TransportException: https://<server>/<repo>: error occurred during unpacking on the remote end: error Missing blob c52dddb55862509bd544af3193435239064b5926

[2019-09-25 11:05:35,694] [] scheduling replication <repo>:refs/heads/Y => https://<server>/<repo>

[2019-09-25 11:05:35,695] [] scheduled <repo>:refs/heads/Y => (retry 3) [4e5931b6] push https://<server>/<repo> to run after 2s

[2019-09-25 11:08:17,388] [4e5931b6] Replication to https://<server>/<repo> started...

[2019-09-25 11:08:17,394] [4e5931b6] Push to https://<server>/<repo> references: [RemoteRefUpdate[remoteName=refs/heads/upstream/X, NOT_ATTEMPTED, (null)...ce30ff9eacd057b39c240731ca95f4c1ce01b4f0, srcRef=refs/heads/X, forceUpdate, message=null], RemoteRefUpdate[remoteName=refs/heads/upstream/Y, NOT_ATTEMPTED, (null)...db240ac31a0e1233c5ad29b91419a008a55e1ec1, srcRef=refs/heads/Y, forceUpdate, message=null]]

[2019-09-25 11:08:26,075] [4e5931b6] Replication to https://<server>/<repo> completed in 8687ms, 915653ms delay, 3 retries

[2019-09-25 11:19:05,510] [] scheduling replication <repo>:refs/heads/Y => https://<server>/<repo>

[2019-09-25 11:19:05,510] [] scheduled <repo>:refs/heads/Y => [663cd0e9] push https://<server>/<repo> to run after 2s

[2019-09-25 11:19:07,514] [663cd0e9] Replication to https://<server>/<repo> started...

[2019-09-25 11:19:07,520] [663cd0e9] Push to https://<server>/<repo> references: [RemoteRefUpdate[remoteName=refs/heads/upstream/Y, NOT_ATTEMPTED, (null)...375abdb3f42579be210dc8d6987b1a29bf94c966, srcRef=refs/heads/Y, forceUpdate, message=null]]

[2019-09-25 11:19:13,327] [663cd0e9] Replication to https://<server>/<repo> completed in 5813ms, 2003ms delay, 0 retries

[Richard Christie]

So I finally got to the bottom of this.

If you are replicating to a repo through gerrit, and the repo owner has done some fun with exclusive READ permissions for a repository (thus losing anything non-blocking set higher in the hierarchy) replication can fail with the above mentioned errors.

The result is git sending data, and data already being there on the remote, but just reachable from refs that the pushing user cannot see.

The error message is deeply confusing; I imagine what is going on is that an object is actually pushed when it doesn't need to be and causing a duplicate, but it could be more complicated than that. An example of surplus pushing can easily be done by having a ref which does already exist on the server, pushing it as some other ref but without READ to the original ref. Git tries to send everything (when it shouldn't need to send anything, no new commits are coming across) and the above error _may_ happen.

So question - is there any way when replicating via Gerrit (not the underlying filesystem, which we usually use but cannot at the moment for "security reasons") to invoke some sort of god user account that ignores ACLs set by repositories so as not to get these messages?

Our workaround for now is having to tell users that they must always need to remember to add our replication user accounts to READ whenever they exclusive override read anywhere. That's obviously not ideal.