git cl upload hanging

[Chris Hamilton]

Recently I've started to see "git cl upload" hang indefinitely. Looking at running processes and I have an instance of "git-remote-https" running that consumes 100% CPU. I've pulled out the individual command (it's the "git cl push" at the root of the process tree), and rerun it with --verbose, and don't see much that's informative:

Pushing to https://chromium.googlesource.com/chromium/src.git
Enumerating objects: 377, done.
Counting objects: 100% (377/377), done.
Delta compression using up to 6 threads
Compressing objects: 100% (194/194), done.
Writing objects: 100% (211/211), 47.08 KiB | 2.24 MiB/s, done.
Total 211 (delta 177), reused 34 (delta 7), pack-reused 0
POST git-receive-pack (48435 bytes)

I've left the process for O(hours) and it's not finished. Typically, if I pull master, rebase, and reupload it will finish just fine. So somehow it appears a particular local branch gets into a weird state that never finishes uploading.

Anybody else seeing behaviour like this? It started sometime in the last couple weeks for me, and has occurred to 2 or 3 different branches.

Cheers,

Chris

[Mike Frysinger]

yes, the further behind you get from ToT, the slower it gets.  periodically rebasing should help mitigate.

-mike

--
--
Chromium Developers mailing list: chromi...@chromium.org
View archives, change email options, or unsubscribe:
http://groups.google.com/a/chromium.org/group/chromium-dev
---
You received this message because you are subscribed to the Google Groups "Chromium-dev" group.
To unsubscribe from this group and stop receiving emails from it, send an email to chromium-dev...@chromium.org.
To view this discussion on the web visit https://groups.google.com/a/chromium.org/d/msgid/chromium-dev/CAA2pCLe%3D82q20WzPMw2n7G-ecAMhpyzs0rc6QJLveFjVhbmV5g%40mail.gmail.com.

[Erik Chen]

This is not WAI. Protocol v2 was supposed to fix this, I believe. There may be logs dropped somewhere (?), +Andy Perelson  would know more. There may also be detailed debugging instructions somewhere?

I usually run something like this:

```

GIT_TR2_EVENT=1 GIT_TRACE2_EVENT=1 GIT_DAPPER_TRACE=1 GIT_TRACE_CURL=1 GIT_TRACE_CURL_NO_DATA=1 GIT_REDACT_COOKIES=o,SSO,GSSO_UberProxy,__Secure-GSSO_UberProxy GIT_TRACE_PACKET=1  time git fetch "https://chromium.googlesource.com/chromium/src" refs/changes/78/1028178/1 > temp10 2>&1

```

This assumes that `git fetch refs/changes/78/1028178/1` is the slow command, you'll need to do some digging to find the appropriate git command to time for `git cl upload` -- I imagine it will be in the form `git push <blah>`

If you can actually get logs in this form factor, then we can narrow down whether hte problem is with `git cl` or with gerrit, and then the appropriate team can dig further.

To view this discussion on the web visit https://groups.google.com/a/chromium.org/d/msgid/chromium-dev/CAAbOScnUvQ%3DCPkqsvan0yAC6zBmG5jFOV2EVQSNm-A28_Md2PQ%40mail.gmail.com.

[Chris Hamilton]

Note that when this happened to me today I was only half a day behind tip of tree; I had rebased earlier in the day. I'll see if I can retroactively repro and use Eric's detailed logging instructions. 

[Andy Perelson]

There is no protocol 2 version of push yet, though they are working on it and it will help for pushes that are slow due to how far behind master they are. There have been some things put in place to help mitigate slow pushes on old CLs, which helps but isn't a full solution. But if you're only half a day behind tip of tree I doubt that's the cause.

But yeah, the best thing to do is collect traces and file a bug. If you file it in Monorail our source team trooper will take the info and pass it along to the internal teams for investigation. I've seen at least one other report of very long uploads this week, and we haven't for a while. So more debugging info and reports would be useful.

Andy

To view this discussion on the web visit https://groups.google.com/a/chromium.org/d/msgid/chromium-dev/CAA2pCLd3_yPurO1hT4WTQdCCjK%2BWijGtspArJ_Ois7vgNtaoDg%40mail.gmail.com.

[Mike Frysinger]

i'm not saying it's WAI, i'm just not surprised by it

-mike

[Erik Chen]

My armchair debugging suggests that you want to do this:

(1) Run git cl upload -vvvvv. This will list in great detail everything subcommand that's running

(2) Confirm it's a git subcommand that's slow. Note the exact parameters.

(3) Rerun with details logging as per instructions above.

To view this discussion on the web visit https://groups.google.com/a/chromium.org/d/msgid/chromium-dev/CAA2pCLd3_yPurO1hT4WTQdCCjK%2BWijGtspArJ_Ois7vgNtaoDg%40mail.gmail.com.

[Dale Curtis]

Just happened to me on a branch which came from a git cl patch. Hung for 10+ minutes, but then cherry-picking to a new branch and uploading that completed quickly.

- dale

To view this discussion on the web visit https://groups.google.com/a/chromium.org/d/msgid/chromium-dev/CAEYHnr16u5hC-AzaFW8zuboGwXTFp9d482h6vzgA3MMXvW5SDQ%40mail.gmail.com.

[Erik Chen]

@Andy Perelson  -- is there an easy way to get the necessary debugging info aside from the mechanism I suggested above? Alternatively, is there more precise documentation?

[Erik Chen]

Oops, and as noted by @Andy Perelson -- the protocol v2 thing is a red herring as it isn't implemented for push.

On Fri, Jul 31, 2020 at 7:25 PM Erik Chen <erik...@chromium.org> wrote:

I ran into this issue myself so took some logging info:

$ git --version

git version 2.28.0.163.g6104cc2f0b6-goog

$ git log origin/master | head -n 3

commit 28ed2aa6c7bafca17142e15c71c239a68238cb2d
Author: Jeff Yoon <jeff...@google.com>
Date:   Mon Jul 27 20:15:13 2020 +0000

$ git log | head -n 15
commit 5f2f29871a6cd183bc8ee2496b99780ba645e914
Author: Erik Chen <erik...@chromium.org>
Date:   Fri Jul 31 18:19:57 2020 -0700

    add lacros to generator

commit b529b0eaafd8b374dfc5458d83ef11e9307e9f79
Author: Erik Chen <erik...@chromium.org>
Date:   Fri Jul 31 13:32:08 2020 -0700

    tempt cl

commit 28ed2aa6c7bafca17142e15c71c239a68238cb2d
Author: Jeff Yoon <jeff...@google.com>
Date:   Mon Jul 27 20:15:13 2020 +0000

Note: my branch is only a few days old.

$ GIT_TR2_EVENT=1 GIT_TRACE2_EVENT=1 GIT_DAPPER_TRACE=1 GIT_TRACE_CURL=1 GIT_TRACE_CURL_NO_DATA=1 GIT_REDACT_COOKIES=o,SSO,GSSO_UberProxy,__Secure-GSSO_UberProxy GIT_TRACE_PACKET=1 git push https://chromium.googlesource.com/chromium/src.git 396c26f16bbee8e149540e5d0e1d1407ac8c5029:refs/for/refs/heads/master%wip,m=Initial_upload,cc=chromium...@chromium.org > temp10 2>&1

temp10.zip file attached. I manually killed it after ~1 hour. Note: I took a quick scan through the log file -- it doesn't look like we're using protocol v2.

I then manually edited .git/config and the command line command to point to sso:// instead of https://. I was hoping to get a dapper trace of the problem -- but surprisingly, it completed very quickly. See temp11 attached.

$ GIT_TR2_EVENT=1 GIT_TRACE2_EVENT=1 GIT_DAPPER_TRACE=1 GIT_TRACE_CURL=1 GIT_TRACE_CURL_NO_DATA=1 GIT_REDACT_COOKIES=o,SSO,GSSO_UberProxy,__Secure-GSSO_UberProxy GIT_TRACE_PACKET=1 git push sso://chromium.googlesource.com/chromium/src.git 396c26f16bbee8e149540e5d0e1d1407ac8c5029:refs/for/refs/heads/master%wip,m=Initial_upload,cc=chromium...@chromium.org > temp11 2>&1

Weirdly enough, temp11 also does not seem to be using protocol v2. It does have a dapper trace but since it finished so quickly [~23 seconds], seems like the problem is not reproducing with sso://?

@Andy Perelson -- hopefully that's enough info to get the git-on-borg team started?

[Erik Chen]

[Mason Freed]

I've been running into this also, for a few weeks or so. One time, I let it sit for several hours, and it finally crashed with a set of crash logs, which I filed as crbug.com/1110018. That got merged into b/162276382. Just FYI in case that turns out to be the same thing as this thread, and those logs are somehow helpful.

[Andreas Papacharalampous]

i've had some issues with `git cl patch xxx -b branch` this week, not sure if it's relevant to this but worth mentioning.  my experience with sending CLs this week also has been somewhat problematic too, the command `git cl upload` hung for about 10 minutes past the "Title for patchset..." part until I killed it and ran it again.

[Dirk Pranke]

When you run `git-cl upload`, we automatically collect traces and store them as timestamped files in the `traces` subdirectory of depot_tools (to be clear: we don't upload this data automatically without your knowledge).

If you have a command that runs a long time and completes, you can file a bug under Infra>SDK and attach those log files.

I haven't tested whether we still create the trace files if you interrupt the command, but if we don't, we probably should, so someone can check that as well.

-- Dirk

To view this discussion on the web visit https://groups.google.com/a/chromium.org/d/msgid/chromium-dev/467c4110-0aa4-4fdf-af5b-a81b1e6f113fn%40chromium.org.

[Andy Perelson]

We do create traces even if you interrupt (really always, since we can't predict failures), and in fact in that case still prompt you to file a bug if things aren't working correctly. I was going to change the behavior to not prompt that on interrupt, but I got stymied writing tests and haven't gotten back to it in ages. Maybe it is best as is though.

Uploading those traces even if you have to dig for them is probably the easiest way to collect them. This has me wondering if we should add an option like --trace that provides them regardless of exit status. 

We're definitely hearing a rise in feedback on this, so something is going on and getting more information will be very helpful in debugging.

Andy

[Dirk Pranke]

Update: I caught an instance of this in mid-hang and filed a bug for it: https://crbug.com/1112954

My checkout was only a few hours old, and a subsequent upload attempt completed in the normal time.

-- Dirk

[Andy Perelson]

There are two unrelated issues that are both impacting git/Gerrit. But you can easily workaround one of them, which is around problems with using http/2, by forcing http/1.1 with 'git config http.version HTTP/1.1'. So I recommend that for anyone still having issues.

For internal folks who want a lot more info:

http://b/137034666

http://b/162566420 (which is broader than just push but may also be impacting it)

Andy