@hashar could it be we have to do http://docs.openstack.org/infra/zuul/connections.html

@Paladox Yup that is what 66c8e52 to 30a433b is mostly about: switching to that new connection system. Something is broken there somehow though ;(

@hashar but doint we need to update the zuul.conf file with those new configs for connections.

https://github.com/openstack-infra/zuul/blob/352264b3c22b501ae53c1643e31df2ccdfc89388/tests/fixtures/layouts/good_connections1.conf

It is back compatible with the old way of defining connections (such as a [gerrit] section) https://github.com/openstack-infra/zuul/blob/30a433b202/zuul/lib/connections.py#L56-L64

It definitely spawn just fine and start handling events but get stuck at some point due to an unknown condition. Probably a thread going deadlock somehow.

And I think P3204 is the thread dump, possibly deadlocked with Crypto.Random.UserFriendlyRNG

@hashar thanks for finding that. Do we update that package.

Or do you know how to fix it please.

Or could it be a bug in zuul.

@hashar could it be that gallium was the problem since it went faulty on wednesday but you turned this update a week before. Sounds like it may be gallium but I carnt be sure.

If I knew the cause or a commit that fix it, that would have been done already. This task is about investigating the issue which has a first step needs a way to reproduce.

@hashar Maybe update zuul to a newer commit. Meaning if the current commit we are on that we backported from upstream. we should try a newer commit, to see if they fixed it without adding in the commit msg about fixing something.

@hashar could it be gerrit 2.8 not being supported since upstream use a newer gerrit version so there not really testing against gerrit 2.8

@hashar we could report it upstream to see what they say please. To see if they can reproduce with gerrit 2.8 if they do then it is the gerrit version we are using.

@hashar could it have been caused by https://phabricator.wikimedia.org/rCIZU52f0ef1a94c1aec4f83ed0e7d2f7ad425e9ad821 or https://phabricator.wikimedia.org/rCIZUc908abf822a85a461c9563e17a0c8eca69c377b0 it might be because of the new connection like model like you said but I doint know why it is not giving us any logs to go one.

Also could it be related to projects not being able to clone because it carn't resolve gerrit host name. <!-- sound like our most likely problem

@hashar it seems it is deffintly related to

File "/usr/share/python/zuul/local/lib/python2.7/site-packages/zuul/connection/gerrit.py", line 362, in _ssh
  self._open()

Since it all links back to ^^

https://phabricator.wikimedia.org/rCIZU52f0ef1a94c1aec4f83ed0e7d2f7ad425e9ad821

Maybe try by building it again but reverting ^^ and try it. See if it will work.

https://phabricator.wikimedia.org/rCIZUc908abf822a85a461c9563e17a0c8eca69c377b0 is included in the current run.

Really there is no point in pasting random commits. Have to find time to attempt to reproduce the issue with extra logging and then debug it :(

@hashar I'm wondering if we were to do https://github.com/openstack-infra/zuul/commit/490f4aa7d81ce497b7b6ed8854f63ad886f242cb would that help us please. Seem they might have a similar error to us https://review.openstack.org/#/c/328504/

I think I found a fix https://review.openstack.org/#/c/238988/ and https://review.openstack.org/#/c/329796/ :)

and potentially https://review.openstack.org/#/c/304133/

Yeah they are all potential candidates. But I want to reproduce the issue on labs first, take trace and from there we can test out / cherry pick upstream commits and make sure it/they actually fix the issue.

@hashar ok. :)

@hashar zuul is dropping jenkins support in v3.

@hashar sorry for asking but could it be a gerrit bug since according to https://gerrit-documentation.storage.googleapis.com/ReleaseNotes/ReleaseNotes-2.8.5.html it says this

Upgrade SSHD to version 0.11.0.

Fixes Issue 2406: "git clone" hangs after 100% resolving deltas with git over SSH.

Fixes a number of other issues including a null pointer exception that could cause ssh commands to hang.

and ssh hangs for us.

@hashar could you try reinstalling it on the server as https://phabricator.wikimedia.org/rOPUP29188f7ea628ff8148544923957069bb62088a9b has been merged to see if we can get some information on why it stalls.

Also there's a chance it was a one time thing.

Please.

@hashar It seems to be a gerrit bug since according to https://gerrit-documentation.storage.googleapis.com/ReleaseNotes/ReleaseNotes-2.9.2.html they fixed a sshd bug that caused it to freeze on stream-events which zuul uses.

Ive been testing and using gerrit 2.12.2 and 2.12.3 does not freeze.

Gerrit is due to be updated this week on Wikimedia so we can test.

The version was downgraded back to 0.9 but then upgraded in 2.10.3.

https://gerrit-documentation.storage.googleapis.com/ReleaseNotes/ReleaseNotes-2.10.3.html

Using gerrit 2.12 and zuul version 2.1.0-151-g30a433b-wmf1jessie1 works no ssh problems.

Mentioned in SAL [2016-07-13T12:36:07Z] <hashar> T137525 Upgrading Zuul 2.1.0-95-g66c8e52-wmf1precise1 ... zuul_2.1.0-151-g30a433b-wmf1precise1_amd64.deb

Mentioned in SAL [2016-07-13T12:36:08Z] <hashar> T137525 Upgrading Zuul 2.1.0-95-g66c8e52-wmf1precise1 ... zuul_2.1.0-151-g30a433b-wmf1precise1_amd64.deb

Mentioned in SAL [2016-07-13T12:52:59Z] <hashar> CI is processing with Zuul 2.1.0-151-g30a433b. It might stop processing events at anytime though due to T137525

$ sudo -u zuul /usr/share/python/zuul/bin/python /usr/bin/zuul-server -c /etc/zuul/zuul-server.conf -d
/usr/lib/python2.7/dist-packages/paramiko/client.py:95: UserWarning: Unknown ssh-rsa host key for [ytterbium.wikimedia.org]:29418: dce9687b991b27d0f9fdce6a2ebf92e1
  (key.get_name(), hostname, hexlify(key.get_fingerprint())))

It is connected to Gerrit apparently though:

Session     Start     Idle   User            Remote Host
--------------------------------------------------------------
f85690c4 12:47:06 00:00:09   jenkins-bot     <gallium IPv6 address>
d87aac55 12:48:05 00:00:03   jenkins-bot     <gallium IPv6 address>

The new Zuul has been running for 40 minutes now and seems to be all fine. Maybe it was some random rare deadlock ? I am keeping it running for now and will reassess later.

Revert would be to go back to previous good version. On gallium:

# /etc/init.d/zuul stop
# dpkg -i /root/zuul_2.1.0-95-g66c8e52-wmf1precise1_amd64.deb

Mentioned in SAL [2016-07-13T13:46:36Z] <hashar> T137525 Stopped zuul that ran in a terminal (with -d). Started it with the init script.

Zuul did not properly connect to Gerrit / stream-events:

+ ssh -p 29418 hashar@gerrit.wikimedia.org 'gerrit show-connections -w'
Session     Start     Idle   User            Remote Host
--------------------------------------------------------------
066c6c0c 13:44:45 00:05:17                   <gallium IPv6>

Mentioned in SAL [2016-07-13T13:58:24Z] <hashar> T137525 reverted Zuul back to zuul_2.1.0-95-g66c8e52-wmf1precise1_amd64.deb . It could not connect to Gerrit reliably

Mentioned in SAL [2016-07-13T13:58:26Z] <hashar> T137525 reverted Zuul back to zuul_2.1.0-95-g66c8e52-wmf1precise1_amd64.deb . It could not connect to Gerrit reliably

Thread dump of Zuul just after it started and with Gerrit showing a connection from gallium but without a username is P3415. We might want to diff it with the previous one ( P3204 ).

summary

During a chat with @thcipriani he conducted a bunch of proof checks. Among others:

• Confirm host finger print with ssh-keyscan -v ytterbium.wikimedia.org -p 29418
• /var/lib/zuul/.ssh/known_hosts has encrypted host but has the key
• ssh hmac/algos selection. Gerrit 29418 uses old ones supported by paramiko
• paramiko version

A thing that is striking is that running the daemon from the command line in foreground mode (zuul-server -d) worked all fine. At least for 45 minutes. At 14:00 UTC I have killed it and spawned the usual way /etc/init.d/zuul start, that is when it deadlocks with the above trace P3415.

So there is something varying when Zuul is put in daemon / running in context of init.d.

I have filtered out a bunch of threads from P3415 and ends up with three threads P3423

Namely:

• zuul.connection.gerrit GerritWatcher._run() connecting to Gerrit over SSH.
  • Locked via Crypto/Random/_UserFriendlyRNG reinit()

• paramiko.transport invoking Random.atfork() which tries to read(32*32) according to the code from /dev/urandom.
  • Does it really read 32*32 bytes?
  • Is it really from /dev/urandom

• zuul.connection.gerrit GerritEventConnector() waiting for events to shows up in the queue.

HINT HINT. OpenStack infra had a discussion about a similar thing on http://eavesdrop.openstack.org/irclogs/%23openstack-infra/%23openstack-infra.2014-12-09.log . Then it is quite old:

2014-12-09T03:28:42  <jeblair> clarkb, fungi: good news and bad news on the reproducibility
 front; when i started builds of 1000 fake servers on precise and trusty, it looked like trusty was
 lagging behind measurably.  but then i ended up with 999 threads deadlocked in
 "/usr/local/lib/python2.7/dist-packages/Crypto/Random/_UserFriendlyRNG.py" which has
 had a significant negative impact on my ability to test
2014-12-09T03:29:16  <jeblair> clarkb, fungi: pycrypto is 2.6.1 on trusty and 2.4.1 on precise

2014-12-09T03:31:26  <jeblair> clarkb, fungi: oh neat, it wasn't a deadlock; it unwedged

2014-12-09T03:35:12  <jeblair> interestingly pycrypto 2.6.1 is a release to fix a cve related
to entropy: https://www.dlitz.net/software/pycrypto/

2014-12-09T03:33:01  <clarkb> jeblair: do we just not have the same entropy on trusty?
2014-12-09T03:36:43  <jeblair> however, i don't think it affects us
2014-12-09T03:37:33  <jeblair> clarkb: it reads from urandom, so it shouldn't be blocking on that

2014-12-09T03:52:27  <jeblair> clarkb, fungi: when i did the thread dump, 186 threads were
trying to acquire the lock, 14 were doing computation outside the lock, 1 held the lock and was
doing computation, and 800 threads were releasing the lock
2014-12-09T03:53:21  <jeblair> clarkb, fungi: what i'm getting from this is that we weren't
stuck waiting on entropy, but rather, when threads released the lock, they stopped getting
scheduled.

The jeblair went to sleep / EOD. Fast forward to the day after

2014-12-09T18:32:10  <jeblair> clarkb, fungi: http://paste.openstack.org/show/148067/
2014-12-09T18:32:28  <jeblair> clarkb, fungi: that script takes 3 seconds on our precise
 nodepool config, and 1 minute 12 seconds on trusty
2014-12-09T18:33:09  <jeblair> clarkb, fungi: it exhibits the same behavior where lots
of threads are apparently releasing a lock at the same time that i saw in my artificial test
 yesterday
2014-12-09T18:33:25  <jeblair> clarkb, fungi: i do not know if that is the _cause_ of our
 actual problems, or if it _shares the cause_

2014-12-09T18:38:35  <jeblair> clarkb, fungi: i can reproduce on precise with merely an upgrade of pycrypto from 2.4.1 to 2.6.1

Post lunch:

2014-12-09T21:20:28  <jeblair> clarkb, fungi: warning: GMP or MPIR library not found;
Not building Crypto.PublicKey._fastmath.
2014-12-09T21:42:35  <jeblair> fungi, clarkb: so my best theory is that what i've been seeing in my testing is just pycrypto hogging the cpu by doing lots of math while holding the GIL
2014-12-09T21:43:42  <jeblair> and what looks like threads stuck releasing the lock is threads being starved (it locks and releases a lot, so many of the releases are not at the same point in the cycle)

So that was merely a perf issue due to a missing fast math library. Got solved by adding the lib so pycrypto compiles with GMP:

Install libgmp-dev on nodepool  https://review.openstack.org/140490

Most probably unrelated.

http://eavesdrop.openstack.org/irclogs/%23openstack-infra/%23openstack-infra.2014-12-10.log

2014-12-09T23:37:21  <jeblair> clarkb: reduced to: set {paramiko, ecdsa}
2014-12-10T00:07:47  <jeblair> clarkb, fungi: one line in fact:
2014-12-10T00:07:50  <jeblair> in paramiko/rsakey.py
2014-12-10T00:07:50  <jeblair> -        rsa = RSA.generate(bits, rng.read, progress_func)
2014-12-10T00:07:50  <jeblair> +        rsa = RSA.generate(bits, os.urandom, progress_func)
2014-12-10T00:08:02  <jeblair> this has a familiar ring to it somehow
2014-12-10T00:10:47  <jeblair> https://github.com/paramiko/paramiko/commit/6f211115f49edcea7d23b764d7cf3a84ff12f5f0
2014-12-10T00:11:32  <clarkb> 5) it makes multithreaded python terrible

etc.... sleep time for me.

Change 298957 had a related patch set uploaded (by Paladox):
2.1.0-151-g30a433b-wmf3precise1

https://gerrit.wikimedia.org/r/298957

Change 298957 abandoned by Paladox:
2.1.0-151-g30a433b-wmf3precise1

Reason:
Per hashar

https://gerrit.wikimedia.org/r/298957

Change 298957 restored by Paladox:
2.1.0-151-g30a433b-wmf3precise1

Reason:
Actually on Jessie it runs 2.6.1 and works fine so I am wondering weather because we use an old version on precise that might be the reason.

https://gerrit.wikimedia.org/r/298957

I have finally managed to reproduce the deadlock on the labs instance integration-slave-precise-1002 with zuul_2.1.0-151-g30a433b-wmf1precise1_amd64.deb and a very dummy layout file \O/

Exact same trace with the paramiko transport thread being blocked by UserFriendlyRNG attempting to acquire entropy. A read() is blocked.

Turns out the issue is that python-daemon closes all file descriptor when daemonizing the application. That causes paramiko / Crypto random generator to loose track of /dev/urandom

Paramiko issue: https://github.com/paramiko/paramiko/issues/59

That is apparently solved by switching from PyCrypto Random to os.urandom https://github.com/paramiko/paramiko/commit/6f211115f49edcea7d23b764d7cf3a84ff12f5f0

Nodepool has it fixed in https://review.openstack.org/#/c/269303/ by bumping paramiko to 1.11.6.

I have confirmed that Random.Crypto is imported before the daemonization occurs. In zuul/cmd/server.py:

+ sys.exit(1)
  with daemon.DaemonContext(pidfile=pid):
      server.main()

Then using python -v to look at the import as:

/usr/share/python/zuul/bin/python -v /usr/bin/zuul-server -c /etc/zuul/zuul-server.conf

That shows paramiko / Crypto being imported :(

@hashar does that mean we have to update nodepool but also shoulden we use version paramiko 1.11.6 on precise

And see also http://stackoverflow.com/questions/20636678/paramiko-inside-python-daemon-causes-ioerror with relevant pointers.

@hashar we could do it so it imports it after it daemonizing.

And then potentially upload the workaround to openstack for Zuul.

Or try this pull https://github.com/paramiko/paramiko/pull/691/files please.

Change 298957 abandoned by Paladox:
2.1.0-151-g30a433b-wmf3precise1

https://gerrit.wikimedia.org/r/298957

Change 299136 had a related patch set uploaded (by Hashar):
Do not import paramiko before daemonization

https://gerrit.wikimedia.org/r/299136

Change 299139 had a related patch set uploaded (by Hashar):
2.1.0-151-g30a433b-wmf3precise1

https://gerrit.wikimedia.org/r/299139

I have rebuild the Debian package and published it on https://people.wikimedia.org/~hashar/debs/zuul_2.1.0-151-g30a433b/

Also includes a few other unrelated bugfix.

Will want to deploy zuul_2.1.0-151-g30a433b-wmf3precise1_amd64.deb next week.

Change 299136 merged by Hashar:
Do not import paramiko before daemonization

https://gerrit.wikimedia.org/r/299136

Change 299139 merged by Hashar:
2.1.0-151-g30a433b-wmf3precise1

https://gerrit.wikimedia.org/r/299139

Mentioned in SAL [2016-07-18T08:31:45Z] <hashar> gallium: upgrading Zuul 2.1.0-95-g66c8e52-wmf1precise1 .. zuul_2.1.0-151-g30a433b-wmf3precise1 T137525

Change 308805 had a related patch set uploaded (by Hashar):
zuul: stop logging paramiko

https://gerrit.wikimedia.org/r/308805

Change 308805 merged by Giuseppe Lavagetto:
zuul: stop logging paramiko

https://gerrit.wikimedia.org/r/308805