mozilla/browserid_deployer — pull request #12 by 6a68 (2013-08-06 22:41:35+00:00)
Title: Issue 11 dueling deployers

We currently have the deployer check for updates when the github githook fires. We also check on a 15-minute backup loop, in case the githook is busted. Have a look at where the `deployer.checkForUpdates()` calls are made in [this part](https://github.com/mozilla/browserid_deployer/blob/de5b58f9c153f759838289587bc13139f9931f74/deploy_server.js#L255-L281) of `deploy_server`.

To avoid running more than one deployer at a time, we [set](https://github.com/mozilla/browserid_deployer/blob/de5b58f9c153f759838289587bc13139f9931f74/deploy_server.js#L156-L164) a boolean on the deployer object, `self._busy`.

Unfortunately, we aren't consistently using `self` after assigning `var self = this`. Because we are periodically calling `checkForUpdates` from inside a `setInterval` loop, the value of `this` is sometimes different. And so we see stuff in the logs where the bad checks are happening at 15 minute intervals, right in the middle of a new VM being deployed.

Here are some examples from today:

In this snippet, we're in the middle of deploying an awsbox (the lines with `progress:`), and then, `deployment_begins`. Note the time is 17:14.

````bash
2013-08-06T17:14:43.012Z: progress: Loaded plugins: fastestmirror, priorities, security, update-motd, upgrade-helper
2013-08-06T17:14:43.116Z: progress: Loading mirror speeds from cached hostfile
2013-08-06T17:14:43.635Z: progress: * amzn-main: packages.us-east-1.amazonaws.com
2013-08-06T17:14:43.636Z: progress: * amzn-updates: packages.us-east-1.amazonaws.com
2013-08-06T17:14:43.636Z: progress: * epel: mirror.symnds.com
2013-08-06T17:14:44.303Z: progress: ... nope. not yet. retrying.
2013-08-06T17:14:48.822Z: info: checking for updates
2013-08-06T17:14:49.074Z: progress: Already up-to-date.
2013-08-06T17:14:49.097Z: info: latest available sha is e66df44
2013-08-06T17:14:49.178Z: resolved login.dev.anosrep.org -> 107.21.151.72
2013-08-06T17:14:49.182Z: info: can't get current running code: Error: connect ECONNREFUSED
2013-08-06T17:14:49.182Z: deployment_begins: {
"sha": "e66df44"
}
2013-08-06T17:14:49.401Z: progress: ... nope. not yet. retrying.
2013-08-06T17:14:49.646Z: progress: BO: remote: npm
2013-08-06T17:14:49.648Z: progress: BO: WARN engine connect@1.7.2: wanted: {"node":">= 0.4.1 < 0.7.0"} (current: {"node":"v0.8
.17","npm":"1.2.0"})ESC[K
````

A bit earlier in history, exactly 15 minutes earlier (16:59), same deal. Loglines with 'progress' are the awsbox deploy, loglines with 'info' are the setInterval loop:

````bash
2013-08-06T16:59:48.691Z: progress: BO: remote: npm
2013-08-06T16:59:48.691Z: progress: BO: http
2013-08-06T16:59:48.692Z: progress: BO: 200 http://127.0.0.1:36199/iconv-lite/-/iconv-lite-0.2.7.tgzESC[K
2013-08-06T16:59:48.820Z: info: checking for updates
2013-08-06T16:59:48.864Z: progress: BO: remote: make: Entering directory `/tmp/deploy11372-5720-bpboqw/node_modules/jwcrypto/n
ode_modules/bigint/build'ESC[K
2013-08-06T16:59:48.864Z: progress: BO: remote: CXX(target) Release/obj.target/bigint/bigint.oESC[K
2013-08-06T16:59:48.933Z: progress: ... nope. not yet. retrying.
2013-08-06T16:59:48.976Z: progress: BO: remote: npm

2013-08-06T16:59:49.131Z: progress: BO: http
2013-08-06T16:59:49.131Z: progress: BO: GET
2013-08-06T16:59:49.132Z: progress: BO: http://127.0.0.1:15797/colors/-/colors-0.3.0.tgzESC[K
2013-08-06T16:59:49.247Z: progress: Already up-to-date.
2013-08-06T16:59:49.276Z: info: latest available sha is e66df44
2013-08-06T16:59:49.352Z: resolved login.dev.anosrep.org -> 54.211.32.231
2013-08-06T16:59:49.358Z: info: current running sha is: c0bf068
2013-08-06T16:59:49.358Z: deployment_begins: {
"sha": "e66df44"
}
2013-08-06T16:59:49.733Z: progress: BO: remote: path.existsSync is now called `fs.existsSync`.ESC[K
2013-08-06T16:59:49.745Z: progress: BO: remote: npm
````

Same deal, exactly 15 minutes earlier (16:44)--the only difference in this snippet is that DNS lookup failed in the setInterval loop. I'm not sure the reason, but it shouldn't have kicked off in the first place.

````bash
2013-08-06T16:44:53.104Z: progress: BO: http://127.0.0.1:32301/minimatch/-/minimatch-0.0.5.tgzESC[K
2013-08-06T16:44:53.105Z: progress: Verifying : mysql55-libs-5.5.31-1.32.amzn1.x86_64 2/6
2013-08-06T16:44:53.166Z: progress: Verifying : mysql-server-5.5-1.3.amzn1.noarch 3/6
2013-08-06T16:44:53.166Z: info: can't get current running code: Timeout resolving login.dev.anosrep.org
2013-08-06T16:44:53.166Z: deployment_begins: {
"sha": "e66df44"
}
2013-08-06T16:44:53.198Z: resolved login.dev.anosrep.org -> null
2013-08-06T16:44:53.200Z: info: can't get current running code: Error: connect ECONNREFUSED
2013-08-06T16:44:53.200Z: deployment_begins: {
"sha": "e66df44"
}
2013-08-06T16:44:53.259Z: progress: Verifying : mysql55-server-5.5.31-1.32.amzn1.x86_64 4/6
2013-08-06T16:44:53.331Z: progress: BO: remote:
2013-08-06T16:44:53.331Z: progress: BO: remote: > browserid@1.0.0-b2 preinstall /tmp/deploy11372-5713-17kg5qiESC[K
2013-08-06T16:44:53.331Z: progress: BO: remote: > node ./scripts/lockdownESC[K
````

I suppose it's possible there's some other root cause, but this seems like a pretty solid explanation to me.