Page MenuHomePhabricator
Create Task
Maniphest T74113

[upstream] Zuul prepareRef does not handle failure to connect to Gearman
Closed, ResolvedPublic
Actions

Description

Screenshot of Zuul status

A few hours ago the Zuul queue started to get stuck. A stack of three changes in mediawiki-extensions-DonationInterface was reviewed with CodeReview+3. The top one (commit C, depending on B, depending on A) had a merge conflict in it.

C https://gerrit.wikimedia.org/r/#/c/166678/3
B https://gerrit.wikimedia.org/r/#/c/166803/1
A https://gerrit.wikimedia.org/r/#/c/166889/2

Somehow this caused Zuul's gate-and-submit pipeline to get stuck indefinitely. Even changes from mwext-VisualEditor, mediawiki-core, mwext-MobileFrontend were all waiting.

Debug information from Zuul's log

$ cat /var/log/zuul/zuul.log.2014-10-15 | grep '166678,3'
2014-10-15 19:17:14,453 INFO zuul.Gerrit: Updating information for 166678,3
2014-10-15 19:17:15,169 INFO zuul.Scheduler: Adding mediawiki/extensions/DonationInterface, <Change 0x7f17b0ff0590 166678,3> to <Pipeline check-only>
2014-10-15 19:17:15,169 INFO zuul.Scheduler: Adding mediawiki/extensions/DonationInterface, <Change 0x7f17b0ff0590 166678,3> to <Pipeline check-voter>
2014-10-15 19:17:15,170 INFO zuul.Scheduler: Adding mediawiki/extensions/DonationInterface, <Change 0x7f17b0ff0590 166678,3> to <Pipeline test>
2014-10-15 19:17:15,171 INFO zuul.IndependentPipelineManager: Change <Change 0x7f17b0ff0590 166678,3> depends on changes []
2014-10-15 19:17:17,470 INFO zuul.IndependentPipelineManager: Change <Change 0x7f17b0ff0590 166678,3> depends on changes []
2014-10-15 19:17:17,470 INFO zuul.Gearman: Launch job mwext-DonationInterface-lint for change <Change 0x7f17b0ff0590 166678,3> with dependent changes []
2014-10-15 19:17:17,474 INFO zuul.Gearman: Launch job mwext-DonationInterface-npm for change <Change 0x7f17b0ff0590 166678,3> with dependent changes []
2014-10-15 19:17:19,481 INFO zuul.IndependentPipelineManager: Change <Change 0x7f17b0ff0590 166678,3> depends on changes []
2014-10-15 19:17:19,481 INFO zuul.Gearman: Launch job mwext-DonationInterface-testextension for change <Change 0x7f17b0ff0590 166678,3> with dependent changes []
2014-10-15 19:18:08,759 INFO zuul.IndependentPipelineManager: Reporting change <Change 0x7f17b0ff0590 166678,3>, actions: [<ActionReporter <zuul.reporter.gerrit.Reporter object at 0x1b6c310>, {'verified': 2}>]
2014-10-15 19:18:08,842 INFO zuul.Gerrit: Updating information for 166678,3
2014-10-15 23:21:16,969 INFO zuul.Gerrit: Updating information for 166678,3
2014-10-15 23:21:17,284 INFO zuul.Scheduler: Adding mediawiki/extensions/DonationInterface, <Change 0x7f17b0ff0590 166678,3> to <Pipeline gate-and-submit>
2014-10-15 23:21:17,284 INFO zuul.DependentPipelineManager: Reporting start, action [<ActionReporter <zuul.reporter.gerrit.Reporter object at 0x1b6c310>, {'verified': 0}>] change <Change 0x7f17b0ff0590 166678,3>
2014-10-15 23:21:17,359 INFO zuul.Gerrit: Updating information for 166678,3
2014-10-15 23:21:17,362 INFO zuul.DependentPipelineManager: Change <Change 0x7f17b0ff0590 166678,3> depends on changes [<Change 0x7f17b0c2e750 166607,6>]
2014-10-15 23:47:30,406 INFO zuul.DependentPipelineManager: Change <Change 0x7f17b0f64c10 166803,1> depends on changes [<Change 0x7f17b0ff0590 166678,3>, <Change 0x7f17b0c2e750 166607,6>]
2014-10-15 23:47:31,790 INFO zuul.DependentPipelineManager: Change <Change 0x7f17b0f64c10 166803,1> depends on changes [<Change 0x7f17b0ff0590 166678,3>, <Change 0x7f17b0c2e750 166607,6>]
2014-10-15 23:47:31,790 INFO zuul.Gearman: Launch job mediawiki-gate for change <Change 0x7f17b0f64c10 166803,1> with dependent changes [<Change 0x7f17b0ff0590 166678,3>, <Change 0x7f17b0c2e750 166607,6>]
2014-10-15 23:47:31,794 INFO zuul.Gearman: Launch job mwext-DonationInterface-lint for change <Change 0x7f17b0f64c10 166803,1> with dependent changes [<Change 0x7f17b0ff0590 166678,3>, <Change 0x7f17b0c2e750 166607,6>]
2014-10-15 23:47:31,798 INFO zuul.Gearman: Launch job mwext-DonationInterface-npm for change <Change 0x7f17b0f64c10 166803,1> with dependent changes [<Change 0x7f17b0ff0590 166678,3>, <Change 0x7f17b0c2e750 166607,6>]
2014-10-15 23:48:30,564 INFO zuul.DependentPipelineManager: Change <Change 0x7f17b13caed0 166889,2> depends on changes [<Change 0x7f17b0f64c10 166803,1>, <Change 0x7f17b0ff0590 166678,3>, <Change 0x7f17b0c2e750 166607,6>]
2014-10-15 23:50:13,976 INFO zuul.DependentPipelineManager: Change <Change 0x7f17b0f64c10 166803,1> depends on changes [<Change 0x7f17b0ff0590 166678,3>, <Change 0x7f17b0c2e750 166607,6>]
2014-10-15 23:50:13,976 INFO zuul.Gearman: Launch job mwext-DonationInterface-testextension for change <Change 0x7f17b0f64c10 166803,1> with dependent changes [<Change 0x7f17b0ff0590 166678,3>, <Change 0x7f17b0c2e750 166607,6>]
2014-10-15 23:59:51,805 INFO zuul.DependentPipelineManager: Change <Change 0x7f17b0c3d250 166918,2> depends on changes [<Change 0x7f17b0f64c10 166803,1>, <Change 0x7f17b0ff0590 166678,3>]
2014-10-15 23:59:55,864 INFO zuul.DependentPipelineManager: Change <Change 0x7f17b0c3d250 166918,2> depends on changes [<Change 0x7f17b0f64c10 166803,1>, <Change 0x7f17b0ff0590 166678,3>]
2014-10-15 23:59:55,864 INFO zuul.Gearman: Launch job mwext-VisualEditor-qunit for change <Change 0x7f17b0c3d250 166918,2> with dependent changes [<Change 0x7f17b0f64c10 166803,1>, <Change 0x7f17b0ff0590 166678,3>]
2014-10-15 23:59:55,868 INFO zuul.Gearman: Launch job mwext-VisualEditor-bundle-rubocop for change <Change 0x7f17b0c3d250 166918,2> with dependent changes [<Change 0x7f17b0f64c10 166803,1>, <Change 0x7f17b0ff0590 166678,3>]
2014-10-15 23:59:55,876 INFO zuul.Gearman: Launch job mwext-VisualEditor-phpcs-HEAD for change <Change 0x7f17b0c3d250 166918,2> with dependent changes [<Change 0x7f17b0f64c10 166803,1>, <Change 0x7f17b0ff0590 166678,3>]
2014-10-15 23:59:55,884 INFO zuul.Gearman: Launch job mediawiki-gate for change <Change 0x7f17b0c3d250 166918,2> with dependent changes [<Change 0x7f17b0f64c10 166803,1>, <Change 0x7f17b0ff0590 166678,3>]
2014-10-15 23:59:55,888 INFO zuul.Gearman: Launch job mwext-VisualEditor-npm for change <Change 0x7f17b0c3d250 166918,2> with dependent changes [<Change 0x7f17b0f64c10 166803,1>, <Change 0x7f17b0ff0590 166678,3>]
2014-10-15 23:59:55,893 INFO zuul.Gearman: Launch job mwext-VisualEditor-lint for change <Change 0x7f17b0c3d250 166918,2> with dependent changes [<Change 0x7f17b0f64c10 166803,1>, <Change 0x7f17b0ff0590 166678,3>]
2014-10-15 23:59:55,957 INFO zuul.Gearman: Launch job mwext-VisualEditor-doc-test for change <Change 0x7f17b0c3d250 166918,2> with dependent changes [<Change 0x7f17b0f64c10 166803,1>, <Change 0x7f17b0ff0590 166678,3>]
2014-10-15 23:59:56,023 INFO zuul.Gearman: Launch job experiment-gating-dependencies for change <Change 0x7f17b0c3d250 166918,2> with dependent changes [<Change 0x7f17b0f64c10 166803,1>, <Change 0x7f17b0ff0590 166678,3>]
[00:45 UTC] zuul at gallium.wikimedia.org in /srv/org/wikimedia/integration ((no branch)%)
$ cat /var/log/zuul/zuul.log.2014-10-15 | grep '166803,1'
2014-10-15 19:38:32,047 INFO zuul.Gerrit: Updating information for 166803,1
2014-10-15 19:38:32,382 INFO zuul.Scheduler: Adding mediawiki/extensions/DonationInterface, <Change 0x7f17b0f64c10 166803,1> to <Pipeline check-only>
2014-10-15 19:38:32,405 INFO zuul.Scheduler: Adding mediawiki/extensions/DonationInterface, <Change 0x7f17b0f64c10 166803,1> to <Pipeline check-voter>
2014-10-15 19:38:32,406 INFO zuul.Scheduler: Adding mediawiki/extensions/DonationInterface, <Change 0x7f17b0f64c10 166803,1> to <Pipeline test>
2014-10-15 19:38:32,407 INFO zuul.IndependentPipelineManager: Change <Change 0x7f17b0f64c10 166803,1> depends on changes []
2014-10-15 19:38:34,115 INFO zuul.IndependentPipelineManager: Change <Change 0x7f17b0f64c10 166803,1> depends on changes []
2014-10-15 19:38:34,115 INFO zuul.Gearman: Launch job mwext-DonationInterface-lint for change <Change 0x7f17b0f64c10 166803,1> with dependent changes []
2014-10-15 19:38:34,119 INFO zuul.Gearman: Launch job mwext-DonationInterface-npm for change <Change 0x7f17b0f64c10 166803,1> with dependent changes []
2014-10-15 19:38:35,718 INFO zuul.IndependentPipelineManager: Change <Change 0x7f17b0f64c10 166803,1> depends on changes []
2014-10-15 19:38:35,718 INFO zuul.Gearman: Launch job mwext-DonationInterface-testextension for change <Change 0x7f17b0f64c10 166803,1> with dependent changes []
2014-10-15 19:38:48,199 INFO zuul.IndependentPipelineManager: Reporting change <Change 0x7f17b0f64c10 166803,1>, actions: [<ActionReporter <zuul.reporter.gerrit.Reporter object at 0x1b6c310>, {'verified': 2}>]
2014-10-15 19:38:48,273 INFO zuul.Gerrit: Updating information for 166803,1
2014-10-15 19:40:23,214 INFO zuul.Gerrit: Updating information for 166803,1
2014-10-15 19:40:23,668 INFO zuul.Gerrit: Updating information for 166803,1
2014-10-15 23:47:29,998 INFO zuul.Gerrit: Updating information for 166803,1
2014-10-15 23:47:30,326 INFO zuul.Scheduler: Adding mediawiki/extensions/DonationInterface, <Change 0x7f17b0f64c10 166803,1> to <Pipeline gate-and-submit>
2014-10-15 23:47:30,327 INFO zuul.DependentPipelineManager: Reporting start, action [<ActionReporter <zuul.reporter.gerrit.Reporter object at 0x1b6c310>, {'verified': 0}>] change <Change 0x7f17b0f64c10 166803,1>
2014-10-15 23:47:30,402 INFO zuul.Gerrit: Updating information for 166803,1
2014-10-15 23:47:30,406 INFO zuul.DependentPipelineManager: Change <Change 0x7f17b0f64c10 166803,1> depends on changes [<Change 0x7f17b0ff0590 166678,3>, <Change 0x7f17b0c2e750 166607,6>]
2014-10-15 23:47:31,790 INFO zuul.DependentPipelineManager: Change <Change 0x7f17b0f64c10 166803,1> depends on changes [<Change 0x7f17b0ff0590 166678,3>, <Change 0x7f17b0c2e750 166607,6>]
2014-10-15 23:47:31,790 INFO zuul.Gearman: Launch job mediawiki-gate for change <Change 0x7f17b0f64c10 166803,1> with dependent changes [<Change 0x7f17b0ff0590 166678,3>, <Change 0x7f17b0c2e750 166607,6>]
2014-10-15 23:47:31,794 INFO zuul.Gearman: Launch job mwext-DonationInterface-lint for change <Change 0x7f17b0f64c10 166803,1> with dependent changes [<Change 0x7f17b0ff0590 166678,3>, <Change 0x7f17b0c2e750 166607,6>]
2014-10-15 23:47:31,798 INFO zuul.Gearman: Launch job mwext-DonationInterface-npm for change <Change 0x7f17b0f64c10 166803,1> with dependent changes [<Change 0x7f17b0ff0590 166678,3>, <Change 0x7f17b0c2e750 166607,6>]
2014-10-15 23:48:30,564 INFO zuul.DependentPipelineManager: Change <Change 0x7f17b13caed0 166889,2> depends on changes [<Change 0x7f17b0f64c10 166803,1>, <Change 0x7f17b0ff0590 166678,3>, <Change 0x7f17b0c2e750 166607,6>]
2014-10-15 23:50:13,976 INFO zuul.DependentPipelineManager: Change <Change 0x7f17b0f64c10 166803,1> depends on changes [<Change 0x7f17b0ff0590 166678,3>, <Change 0x7f17b0c2e750 166607,6>]
2014-10-15 23:50:13,976 INFO zuul.Gearman: Launch job mwext-DonationInterface-testextension for change <Change 0x7f17b0f64c10 166803,1> with dependent changes [<Change 0x7f17b0ff0590 166678,3>, <Change 0x7f17b0c2e750 166607,6>]
2014-10-15 23:59:51,805 INFO zuul.DependentPipelineManager: Resetting builds for change <Change 0x7f17b0c3d250 166918,2> because the item ahead, <QueueItem 0x7f180b290c10 for <Change 0x7f17b13caed0 166889,2> in gate-and-submit>, is not the nearest non-failing item, <QueueItem 0x7f17b10042d0 for <Change 0x7f17b0f64c10 166803,1> in gate-and-submit>
2014-10-15 23:59:51,805 INFO zuul.DependentPipelineManager: Change <Change 0x7f17b0c3d250 166918,2> depends on changes [<Change 0x7f17b0f64c10 166803,1>, <Change 0x7f17b0ff0590 166678,3>]
2014-10-15 23:59:55,864 INFO zuul.DependentPipelineManager: Change <Change 0x7f17b0c3d250 166918,2> depends on changes [<Change 0x7f17b0f64c10 166803,1>, <Change 0x7f17b0ff0590 166678,3>]
2014-10-15 23:59:55,864 INFO zuul.Gearman: Launch job mwext-VisualEditor-qunit for change <Change 0x7f17b0c3d250 166918,2> with dependent changes [<Change 0x7f17b0f64c10 166803,1>, <Change 0x7f17b0ff0590 166678,3>]
2014-10-15 23:59:55,868 INFO zuul.Gearman: Launch job mwext-VisualEditor-bundle-rubocop for change <Change 0x7f17b0c3d250 166918,2> with dependent changes [<Change 0x7f17b0f64c10 166803,1>, <Change 0x7f17b0ff0590 166678,3>]
2014-10-15 23:59:55,876 INFO zuul.Gearman: Launch job mwext-VisualEditor-phpcs-HEAD for change <Change 0x7f17b0c3d250 166918,2> with dependent changes [<Change 0x7f17b0f64c10 166803,1>, <Change 0x7f17b0ff0590 166678,3>]
2014-10-15 23:59:55,884 INFO zuul.Gearman: Launch job mediawiki-gate for change <Change 0x7f17b0c3d250 166918,2> with dependent changes [<Change 0x7f17b0f64c10 166803,1>, <Change 0x7f17b0ff0590 166678,3>]
2014-10-15 23:59:55,888 INFO zuul.Gearman: Launch job mwext-VisualEditor-npm for change <Change 0x7f17b0c3d250 166918,2> with dependent changes [<Change 0x7f17b0f64c10 166803,1>, <Change 0x7f17b0ff0590 166678,3>]
2014-10-15 23:59:55,893 INFO zuul.Gearman: Launch job mwext-VisualEditor-lint for change <Change 0x7f17b0c3d250 166918,2> with dependent changes [<Change 0x7f17b0f64c10 166803,1>, <Change 0x7f17b0ff0590 166678,3>]
2014-10-15 23:59:55,957 INFO zuul.Gearman: Launch job mwext-VisualEditor-doc-test for change <Change 0x7f17b0c3d250 166918,2> with dependent changes [<Change 0x7f17b0f64c10 166803,1>, <Change 0x7f17b0ff0590 166678,3>]
2014-10-15 23:59:56,023 INFO zuul.Gearman: Launch job experiment-gating-dependencies for change <Change 0x7f17b0c3d250 166918,2> with dependent changes [<Change 0x7f17b0f64c10 166803,1>, <Change 0x7f17b0ff0590 166678,3>]
$ cat /var/log/zuul/zuul.log.2014-10-15 | grep '166889,2'
2014-10-15 22:33:35,953 INFO zuul.Gerrit: Updating information for 166889,2
2014-10-15 22:33:36,261 INFO zuul.Scheduler: Adding mediawiki/extensions/DonationInterface, <Change 0x7f17b13caed0 166889,2> to <Pipeline check-only>
2014-10-15 22:33:36,261 INFO zuul.Scheduler: Adding mediawiki/extensions/DonationInterface, <Change 0x7f17b13caed0 166889,2> to <Pipeline check-voter>
2014-10-15 22:33:36,262 INFO zuul.Scheduler: Adding mediawiki/extensions/DonationInterface, <Change 0x7f17b13caed0 166889,2> to <Pipeline test>
2014-10-15 22:33:36,263 INFO zuul.IndependentPipelineManager: Change <Change 0x7f17b13caed0 166889,2> depends on changes []
2014-10-15 22:33:39,803 INFO zuul.IndependentPipelineManager: Unable to merge change <Change 0x7f17b13caed0 166889,2>
2014-10-15 22:33:39,803 INFO zuul.IndependentPipelineManager: Reporting change <Change 0x7f17b13caed0 166889,2>, actions: [<ActionReporter <zuul.reporter.gerrit.Reporter object at 0x1b6c310>, {'verified': -1}>]
2014-10-15 22:33:39,876 INFO zuul.Gerrit: Updating information for 166889,2
2014-10-15 23:48:30,171 INFO zuul.Gerrit: Updating information for 166889,2
2014-10-15 23:48:30,484 INFO zuul.Scheduler: Adding mediawiki/extensions/DonationInterface, <Change 0x7f17b13caed0 166889,2> to <Pipeline gate-and-submit>
2014-10-15 23:48:30,484 INFO zuul.DependentPipelineManager: Reporting start, action [<ActionReporter <zuul.reporter.gerrit.Reporter object at 0x1b6c310>, {'verified': 0}>] change <Change 0x7f17b13caed0 166889,2>
2014-10-15 23:48:30,559 INFO zuul.Gerrit: Updating information for 166889,2
2014-10-15 23:48:30,564 INFO zuul.DependentPipelineManager: Change <Change 0x7f17b13caed0 166889,2> depends on changes [<Change 0x7f17b0f64c10 166803,1>, <Change 0x7f17b0ff0590 166678,3>, <Change 0x7f17b0c2e750 166607,6>]
2014-10-15 23:48:31,761 INFO zuul.DependentPipelineManager: Unable to merge change <Change 0x7f17b13caed0 166889,2>
2014-10-15 23:59:51,805 INFO zuul.DependentPipelineManager: Resetting builds for change <Change 0x7f17b0c3d250 166918,2> because the item ahead, <QueueItem 0x7f180b290c10 for <Change 0x7f17b13caed0 166889,2> in gate-and-submit>, is not the nearest non-failing item, <QueueItem 0x7f17b10042d0 for <Change 0x7f17b0f64c10 166803,1> in gate-and-submit>

Version: wmf-deployment
Severity: normal
See Also:
https://launchpad.net/bugs/1358517

Attached:

Screen_Shot_2014-10-16_at_02.25.10.png (1×2 px, 438 KB)

Details

Reference
bz72113

Related Objects
Search...

Event Timeline

• bzimport raised the priority of this task from to Medium.Nov 22 2014, 3:57 AM
• bzimport added projects: Continuous-Integration-Infrastructure, Upstream.
• bzimport set Reference to bz72113.
Krinkle created this task.Oct 16 2014, 12:47 AM
hashar added a comment.Oct 16 2014, 1:08 PM

Looking at debug.log.2014-10-15

23:21:17

  • receives a code review +2 event for change 166678,3
  • triggers a merge:merge function

23:21:47 (30 seconds later):

ERROR gear.Client.unknown:

Connection <gear.Connection 0x1ca7f90 host: 208.80.154.135 port: 4730>
timed out waiting for a response to a submit job request:
   <gear.Job 0x7f1809f1dd50
       handle: None
       name: merger:merge
       unique: d928090c54474fa59b51d1661263750b>

NoConnectedServersError: No connected Gearman servers

Zuul forks to spawn a Gearman server and both process communicate over TCP 4730 via the host public IP.

The Zuul code that handles the creation of the reference (zuul.scheduler.BasePipelineManager.prepareRef() ) does not handle exceptions when submitting the job to Gearman, so it is raised up to the main loop and leave the enqueued change in an inconsistent state.

I am not familiar with that part of the code. I guess exceptions should be caught and some internal status (there is a ready variable) be set accordingly.

To unblock such issue either:

A) potentially a new patchset could be sent (that would remove the previous one from the Zuul queues) then +2ed again to reenter the gate-and-submit pipeline

B) use the Zuul client to move the change ahead in the queue (an action known as 'promote') which would reorder the changes in the pipeline and retrigger merge jobs. Ie:

zuul promote --pipeline gate-and-submit --changes 166678,3

See doc at http://ci.openstack.org/zuul/client.html#usage

Adjusting priority, we can't have everything highest/critical.

hashar added a comment.Oct 16 2014, 1:27 PM

Turns out I already filled a bug upstream in August. The case was the connection to Gearman timing out while preparing a reference (same code path): https://bugs.launchpad.net/zuul/+bug/1358517

I have replied there with a potential solution to the issue.

Marking bug as an upstream issue.

hashar added a comment.Oct 20 2014, 8:41 PM

I have proposed a change at https://review.openstack.org/#/c/128921/ with a test which most probably has a race condition :D

hashar added a comment.Oct 30 2014, 3:55 PM

I am now deploying https://review.openstack.org/#/c/128921/3 by merging in our Zuul fork at integration/zuul.git

hashar added a comment.Oct 30 2014, 9:03 PM

The patch has been deployed. Lets monitor the issue for a few days.

hashar added a comment.Nov 1 2014, 3:41 PM

The patch solved the issues of patches being stuck in the event queue whenever the connection is lost with the Gearman server. That happened yesterday on the Wikimedia setup, on reestablishing the connection, all the pending merger:merge function have been executed and the event queue processed everything :-)

Keeping bug open until the patch is approved by upstream.

hashar moved this task from Untriaged to Externally Blocked on the Continuous-Integration-Infrastructure board.Nov 24 2014, 10:08 AM
hashar updated the task description. (Show Details)
hashar set Security to None.
hashar mentioned this in T65760: [upstream] Jobs are sometime no more being triggered by Zuul / Jenkins.Mar 30 2015, 2:39 PM
hashar added a project: Zuul.Jun 16 2015, 3:26 PM
hashar closed this task as Resolved.Apr 19 2016, 9:37 AM
hashar moved this task from Backlog to Patch merged upstream on the Upstream board.

Patch got merged upstream.

Content licensed under Creative Commons Attribution-ShareAlike (CC BY-SA) 4.0 unless otherwise noted; code licensed under GNU General Public License (GPL) 2.0 or later and other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL · Credits