885422 - Firefox 17.0.7esr is in a weird state on ship it

Status: RESOLVED DUPLICATE of bug 879763

(Release Engineering :: Release Automation, defect)

Description

[[e-mail] (:bhearsum)]

This release is already started, but it's being shown on the "Submitted" section. Here's the logs from the web heads:
2013-06-18 10:07:35,774 - kickoff.views.submit.post#58: Firefox-17.0.7esr-build1 added to the database
2013-06-18 10:18:42,276 - kickoff.views.releases.post#119: Firefox-17.0.7esr-build1 is being marked as ready
2013-06-18 10:19:13,615 - kickoff.views.releases.post#78: Firefox-17.0.7esr-build1: status being changed to: Writing configs
2013-06-18 10:19:15,670 - kickoff.views.releases.post#78: Firefox-17.0.7esr-build1: status being changed to: Running release sanity
2013-06-18 10:19:44,230 - kickoff.views.releases.post#78: Firefox-17.0.7esr-build1: status being changed to: Tagging other repositories
2013-06-18 10:19:47,746 - kickoff.views.releases.post#78: Firefox-17.0.7esr-build1: status being changed to: Reconfiging masters
2013-06-18 10:20:17,314 - kickoff.views.releases.post#72: Firefox-17.0.7esr-build1: ready being changed to: False
2013-06-18 10:20:17,314 - kickoff.views.releases.post#78: Firefox-17.0.7esr-build1: status being changed to: Failed: CalledProcessError()
2013-06-18 11:19:13,782 - kickoff.views.releases.post#119: Firefox-17.0.7esr-build1 is being marked as ready
2013-06-18 11:19:38,920 - kickoff.views.releases.post#78: Firefox-17.0.7esr-build1: status being changed to: Writing configs
2013-06-18 11:19:42,794 - kickoff.views.releases.post#78: Firefox-17.0.7esr-build1: status being changed to: Reconfiging masters
2013-06-18 11:19:41,049 - kickoff.views.releases.post#72: Firefox-17.0.7esr-build1: ready being changed to: False
2013-06-18 11:19:41,049 - kickoff.views.releases.post#78: Firefox-17.0.7esr-build1: status being changed to: Failed: CalledProcessError()
2013-06-18 11:24:18,835 - kickoff.views.releases.post#78: Firefox-17.0.7esr-build1: status being changed to: Running sendchange command
2013-06-18 11:24:19,111 - kickoff.views.releases.post#75: Firefox-17.0.7esr-build1: complete being changed to: True
2013-06-18 11:24:19,112 - kickoff.views.releases.post#78: Firefox-17.0.7esr-build1: status being changed to: Started

And the current database state:
mysql> select name, ready, complete, status, submittedAt from firefox_release where name='Firefox-17.0.7esr-build1';
+--------------------------+-------+----------+---------+---------------------+
| name                     | ready | complete | status  | submittedAt         |
+--------------------------+-------+----------+---------+---------------------+
| Firefox-17.0.7esr-build1 |     0 |        1 | Started | 2013-06-18 17:07:35 |
+--------------------------+-------+----------+---------+---------------------+


So, clearly the problem is that it's not ready when it should be. I wonder if there's a bug in the work from bug 860290 that causes releases not to get marked as ready if they've failed once? Also could be some weird db issue.

Massimo, can you see if there's anything obvious in the code?

Comment 1

[Massimo Gervasini [:massimo]]

Hi Ben,

I don't think this is caused by bug 860290 as it only prints an extra string if rel.status is not empty.

I've noticed that logs are not sorted by time stamp... here is the sorted list:

10:07:35  added to the database
10:18:42  is being marked as ready
10:19:13 : status being changed to: Writing configs
10:19:15 : status being changed to: Running release sanity
10:19:44 : status being changed to: Tagging other repositories
10:19:47 : status being changed to: Reconfiging masters
10:20:17 : status being changed to: Failed: CalledProcessError()
10:20:17 : ready being changed to: False
11:19:13  is being marked as ready
11:19:38 : status being changed to: Writing configs
11:19:41 : status being changed to: Failed: CalledProcessError()
11:19:41 : ready being changed to: False
11:19:42 : status being changed to: Reconfiging masters
11:24:18 : status being changed to: Running sendchange command
11:24:19 : complete being changed to: True
11:24:19 : status being changed to: Started

ready changes from False to True and then back to False.
What did trigger 'ready' back to False? Did anything bad happen during the second Writing configs ?

Comment 2

[[e-mail] (:bhearsum)]

Here's the logs from release runner, with some excess lines removed:
2013-06-18 10:19:10,796 - INFO - Got a new release request: {'ready': True, 'mozillaRevision': '0d36e01126b0', 'name': 'Firefox-17.0.7esr-build1'}
2013-06-18 10:19:13,498 - INFO - updating status for Firefox-17.0.7esr-build1 to Writing configs
2013-06-18 10:19:15,592 - INFO - updating status for Firefox-17.0.7esr-build1 to Running release sanity
...
2013-06-18 10:19:42,623 - INFO - updating status for Firefox-17.0.7esr-build1 to Waiting for other releases to run release sanity
2013-06-18 10:19:44,192 - INFO - updating status for Firefox-17.0.7esr-build1 to Tagging other repositories
2013-06-18 10:19:47,722 - INFO - updating status for Firefox-17.0.7esr-build1 to Reconfiging masters
2013-06-18 10:20:17,162 - INFO - mark as failed Firefox-17.0.7esr-build1

2013-06-18 11:19:38,744 - INFO - Got a new release request: {'ready': True, 'mozillaRevision': '0d36e01126b0', 'name': 'Firefox-17.0.7esr-build1'}
2013-06-18 11:19:42,606 - INFO - updating status for Firefox-17.0.7esr-build1 to Reconfiging masters
[buildbot-master36.srv.releng.scl3.mozilla.com] out: 2013-06-18 11:22:18-0700 [-] Unhandled Error
[buildbot-master36.srv.releng.scl3.mozilla.com] out: 2013-06-18 11:22:18-0700 [-] Unhandled Error
[buildbot-master36.srv.releng.scl3.mozilla.com] out: 2013-06-18 11:22:18-0700 [-] Unhandled Error
[buildbot-master65.srv.releng.usw2.mozilla.com] out: [buildbot-master62.srv.releng.use1.mozilla.com] out: 2013-06-18 11:23:23-0700 [-] Unhandled Error
...
2013-06-18 11:24:18,686 - INFO - updating status for Firefox-17.0.7esr-build1 to Running sendchange command
2013-06-18 11:24:19,037 - INFO - mark as completed Firefox-17.0.7esr-build1



I'm not really sure what happened still, but I suspect it's related to the weird unhandled errors during the second reconfig. What's _really_ weird is the first reconfig doesn't have any indication of failure, yet marks the release as failed.

Rail, any clue what's happened? Maybe something related to Fabric output weirdness?

Comment 3

[Rail Aliiev [:rail]]

We talked offline about this and couldn't figure out why it happened. The mentioned unhandled errors are normal for reconfigs.

Comment 4

[[e-mail] (:bhearsum)]

Rail and I talked about this some more, and we also got some help from db folks. Turns out that this is a result of bug 879763, which Rail is planning to fix next week.

Comment 5

[[e-mail] (:bhearsum)]

Oh, and I manually updated the db to set ready=1 again.