1113944 - (vcshangs) Intermittent "connection hangs" to both hg & git servers

Status: NEW

(Developer Services :: General, task)

Description

[hwine]

Now seeing this in 2 different systems, and it is causing production tests to fail (bug 1024573).

My suspicion is that this is an interaction issue between the client <-> zlb <-> apache server, so will take a cross team approach to isolating the root cause.

There are two independent client systems seeing, and logging, occurrences of these "hangs":
 - legacy vcs-sync mirroring which sees the issue with both {git,hg}.m.o and occasional remote servers. It successfully forces retries by kill -hup on the process hung on network I/O. It emails details of each event - anyone in releng has access to the email (see https://wiki.mozilla.org/ReleaseEngineering/How_To/Process_release_email#vcs2vcs). It is the AUTOFIX emails which document the hangs.

 - gaia test runs, which sees the issue with git.mozilla.org. Bug 1024573 has many instances with timing.

I believe the next steps are to:
 - match client side events with server logs
 - work with webops to correlate VIP logs for those times
 - determine further steps

Note: from the vcs-sync side, this has "always" happened. However, the frequency has increased over the last several month from approx every few days in August to at least 1 daily, with 4-10 occurrences being more common currently.

Comment 1

[hwine]

Example current notification from vcs-sync:
report from /opt/vcs2vcs/bin/check_process_delay on github-sync3.dmz.scl3.mozilla.com:
Attempting unstick of hung process 11397
0 S vcs2vcs  11397 14898  0  80   0 - 49225 sk_wai 18:40 pts/10   00:00:00 /opt/vcs2vcs/venv/hg/bin/python /opt/vcs2vcs/bin/hg id http://hg.mozilla.org/releases/mozilla-b2g28_v1_3

Which is the output of 'ps -flwwwp' of the hung process. ("Hung" is heuristic of >10m without output and status of 'sk_wait'.)

Comment 2

[hwine]

Impacted release 35.0b8:
command: START
command: hg clone -U https://hg.mozilla.org/releases/l10n/mozilla-beta/an /builds/hg-shared/releases/l10n/mozilla-beta/an
command: cwd: /builds/slave/rel-m-beta-osx64_rpk_1-0000000
command: env: {'HGPLAIN': '1'}

command timed out: 2400 seconds without output running ['bash', 'scripts/scripts/l10n/release_repacks.sh', 'macosx64', 'mozilla/production_config.py', '--chunks', '10', '--this-chunk', '1', '--stage-ssh-key', 'ffxbld_rsa', '--stage-server', 'stage.mozilla.org', '--stage-username', 'ffxbld', '--hghost', 'hg.mozilla.org', '--compare-locales-repo-path', 'build/compare-locales', '--generate-partials', '--tooltool-manifest', 'browser/config/tooltool-manifests/macosx64/l10n.manifest', '--tooltool-url', 'http://tooltool.pvt.build.mozilla.org/build', '--balrog-api-root', 'https://aus4-admin.mozilla.org', '--balrog-username', 'ffxbld', '--credentials-file', 'oauth.txt'], attempting to kill
process killed by signal 9
program finished with exit code -1
elapsedTime=3761.506823

Comment 3

[hwine]

Here are the 4 detected occurrences on Dec 29:

Examples of connection hangs to hg.mozilla.org on Dec 29, 2014:

Date: Mon, 29 Dec 2014 11:47:02 +0000

report from /opt/vcs2vcs/bin/check_process_delay on github-sync3.dmz.scl3.mozilla.com:
Attempting unstick of hung process 25861
0 S vcs2vcs  25861 14898  0  80   0 - 49225 sk_wai 11:11 pts/10   00:00:00 /opt/vcs2vcs/venv/hg/bin/python /opt/vcs2vcs/bin/hg id http://hg.mozilla.org/releases/mozilla-b2g28_v1_3t

Date: Mon, 29 Dec 2014 13:47:02 +0000

report from /opt/vcs2vcs/bin/check_process_delay on github-sync3.dmz.scl3.mozilla.com:
Attempting unstick of hung process 11678
0 S vcs2vcs  11678 11675  0  80   0 - 19833 poll_s 13:18 pts/8    00:00:00 git-remote-http origin http://sprdsource.spreadtrum.com:8085/b2g/android/platform/external/mdnsresponder

Date: Mon, 29 Dec 2014 19:07:03 +0000

report from /opt/vcs2vcs/bin/check_process_delay on github-sync3.dmz.scl3.mozilla.com:
Attempting unstick of hung process 11397
0 S vcs2vcs  11397 14898  0  80   0 - 49225 sk_wai 18:40 pts/10   00:00:00 /opt/vcs2vcs/venv/hg/bin/python /opt/vcs2vcs/bin/hg id http://hg.mozilla.org/releases/mozilla-b2g28_v1_3

Date: Mon, 29 Dec 2014 22:27:02 +0000

report from /opt/vcs2vcs/bin/check_process_delay on github-sync3.dmz.scl3.mozilla.com:
Attempting unstick of hung process 18530
0 S vcs2vcs  18530 18529  0  80   0 - 50524 sk_wai 21:54 pts/5    00:00:00 /opt/vcs2vcs/venv/hg/bin/python /opt/vcs2vcs/bin/hg --cwd /opt/vcs2vcs/repos/releases-l10n-br-gaia pull v2_1

v2_1 = https://hg.mozilla.org/releases/gaia-l10n/v2_1/br

Per meeting, ni :fubar to look into these.

Comment 4

[Gregory Szorc [:gps]]

There is a bug reported against Mercurial tracking connection issues to hg.mozilla.org. Not sure if it is us or a Mercurial bug. Bug given the presence of this bug, I'm leaning towards us :/

Comment 5

[Massimo Gervasini [:massimo]]

We are trying to mitigate this in bug 1088590, forcing release automation scripts to retry 'hg clone' if the connections hangs.

Comment 6

[Kendall Libby [:fubar] (he/him)]

Attachment: releases-l10n-br-gaia-v2_1.txt

(In reply to Hal Wine [:hwine] (use needinfo) from comment #3)
>
> Date: Mon, 29 Dec 2014 11:47:02 +0000
> report from /opt/vcs2vcs/bin/check_process_delay on
> github-sync3.dmz.scl3.mozilla.com:
> Attempting unstick of hung process 25861
> 0 S vcs2vcs  25861 14898  0  80   0 - 49225 sk_wai 11:11 pts/10   00:00:00
> /opt/vcs2vcs/venv/hg/bin/python /opt/vcs2vcs/bin/hg id
> http://hg.mozilla.org/releases/mozilla-b2g28_v1_3t
>
> Date: Mon, 29 Dec 2014 19:07:03 +0000
> report from /opt/vcs2vcs/bin/check_process_delay on
> github-sync3.dmz.scl3.mozilla.com:
> Attempting unstick of hung process 11397
> 0 S vcs2vcs  11397 14898  0  80   0 - 49225 sk_wai 18:40 pts/10   00:00:00
> /opt/vcs2vcs/venv/hg/bin/python /opt/vcs2vcs/bin/hg id
> http://hg.mozilla.org/releases/mozilla-b2g28_v1_3

For these two, I can't see anything that matches. Only requests around those time frames, and coming through nat-fw1, are all for '/json-pushes/?full=1&fromchange=......' and there's one per minute.


> Date: Mon, 29 Dec 2014 22:27:02 +0000
> report from /opt/vcs2vcs/bin/check_process_delay on
> github-sync3.dmz.scl3.mozilla.com:
> Attempting unstick of hung process 18530
> 0 S vcs2vcs  18530 18529  0  80   0 - 50524 sk_wai 21:54 pts/5    00:00:00
> /opt/vcs2vcs/venv/hg/bin/python /opt/vcs2vcs/bin/hg --cwd
> /opt/vcs2vcs/repos/releases-l10n-br-gaia pull v2_1
>
> v2_1 = https://hg.mozilla.org/releases/gaia-l10n/v2_1/br

Application level logs on zlb5 and hgweb nodes show this as successful (see attachment)

Comment 7

[Kendall Libby [:fubar] (he/him)]

(In reply to Gregory Szorc [:gps] from comment #4)
> There is a bug reported against Mercurial tracking connection issues to
> hg.mozilla.org. Not sure if it is us or a Mercurial bug. Bug given the
> presence of this bug, I'm leaning towards us :/

(In reply to Greg's comment on Mercurial's bug)
> That 10s timeout is also weird.

There are two active timeout settings on the zlbs that are set at 10s:
- connect_timeout (The time, in seconds, to wait for data from a new connection. If no data is received within this time, the connection will be closed.)
- keepalive_timeout (The length of time that the virtual server should keep an idle keepalive connection before discarding it.)

The first clearly doesn't apply, based on the Mercurial bug. The keepalive timeout *shouldn't* apply based on same, as it appeared to be not idle.

I see nothing in the zlb error logs that correlate (we have been dropping connections from AWS nodes for too many concurrent connections at times). However, the periodic netstat dumps from zeus don't look exactly happy.

counter increases between 0134 and 1304 PST, Jan 14 2015 (today):

zlb5.ops.scl3# grep 'timeouts after reno' periodic-logs/current/netstat  | head -1;grep 'timeouts after reno' periodic-logs/current/netstat  | tail -1
    1490360 timeouts after reno fast retransmit
    1500390 timeouts after reno fast retransmit
zlb5.ops.scl3# grep 'timeouts after SACK' periodic-logs/current/netstat  | head -1;grep 'timeouts after SACK' periodic-logs/current/netstat  | tail -1
    55840761 timeouts after SACK recovery
    56213916 timeouts after SACK recovery
zlb5.ops.scl3# grep 'timeouts in loss' periodic-logs/current/netstat  | head -1;grep 'timeouts in loss' periodic-logs/current/netstat  | tail -1
    58040473 timeouts in loss state
    58429475 timeouts in loss state
zlb5.ops.scl3# grep 'TCP data loss events' periodic-logs/current/netstat  | head -1;grep 'TCP data loss events' periodic-logs/current/netstat  | tail -1
    3832679730 TCP data loss events
    3855452846 TCP data loss events
zlb5.ops.scl3# grep 'pruned from receive queue' periodic-logs/current/netstat  | head -1;grep 'pruned from receive queue'  periodic-logs/current/netstat  | tail -1
    45194579 packets pruned from receive queue because of socket buffer overrun
    3644056 packets pruned from receive queue
zlb5.ops.scl3# grep 'pruned from receive queue' periodic-logs/current/netstat  | head -2;grep 'pruned from receive queue'  periodic-logs/current/netstat  | tail -2
    45194579 packets pruned from receive queue because of socket buffer overrun
    3621402 packets pruned from receive queue
    45482773 packets pruned from receive queue because of socket buffer overrun
    3644056 packets pruned from receive queue

I'm not up to snuff sufficiently on my TCP at the moment to say that any one of this is particularly a problem, but "TCP data loss events" doesn't exactly inspire confidence.

Comment 8

[Chris AtLee [:catlee]]

we're hitting this semi-frequently with the b2g bumper. We're working around it by adding timeouts to the hg operations, but obviously would be better if it just worked :)

Latest hang was on the push operation; the ssh connection via hg-zlb.vips.scl3.mozilla.com was hung for >1 hr.