Merge pull request #905 from balena-io/better-backoff

Better backoff and update lock reporting

package-lock.json

@@ -7347,6 +7347,12 @@
         "json-parse-better-errors": "^1.0.1"
       }
     },
+    "parse-ms": {
+      "version": "2.0.0",
+      "resolved": "https://registry.npmjs.org/parse-ms/-/parse-ms-2.0.0.tgz",
+      "integrity": "sha512-AddiXFSLLCqj+tCRJ9MrUtHZB4DWojO3tk0NVZ+g5MaMQHF2+p2ktqxuoXyPFLljz/aUK0Nfhd/uGWnhXVXEyA==",
+      "dev": true
+    },
     "parse-passwd": {
       "version": "1.0.0",
       "resolved": "https://registry.npmjs.org/parse-passwd/-/parse-passwd-1.0.0.tgz",
@@ -7625,6 +7631,15 @@
         }
       }
     },
+    "pretty-ms": {
+      "version": "4.0.0",
+      "resolved": "https://registry.npmjs.org/pretty-ms/-/pretty-ms-4.0.0.tgz",
+      "integrity": "sha512-qG66ahoLCwpLXD09ZPHSCbUWYTqdosB7SMP4OffgTgL2PBKXMuUsrk5Bwg8q4qPkjTXsKBMr+YK3Ltd/6F9s/Q==",
+      "dev": true,
+      "requires": {
+        "parse-ms": "^2.0.0"
+      }
+    },
     "process": {
       "version": "0.11.10",
       "resolved": "https://registry.npmjs.org/process/-/process-0.11.10.tgz",
@@ -8009,7 +8024,7 @@
     },
     "require-npm4-to-publish": {
       "version": "1.0.0",
-      "resolved": "https://registry.npmjs.org/require-npm4-to-publish/-/require-npm4-to-publish-1.0.0.tgz",
+      "resolved": "http://registry.npmjs.org/require-npm4-to-publish/-/require-npm4-to-publish-1.0.0.tgz",
       "integrity": "sha1-5Z7D5ikQFT3Fu90MpA20IrLE2ec=",
       "dev": true,
       "requires": {

package.json

@@ -84,6 +84,7 @@
     "network-checker": "^0.1.1",
     "pinejs-client-request": "^5.2.0",
     "prettier": "^1.15.3",
+    "pretty-ms": "^4.0.0",
     "request": "^2.51.0",
     "resin-lint": "^2.0.1",
     "resin-register-device": "^3.0.0",

src/device-state.coffee

@@ -4,6 +4,7 @@ EventEmitter = require 'events'
 fs = Promise.promisifyAll(require('fs'))
 express = require 'express'
 bodyParser = require 'body-parser'
+prettyMs = require 'pretty-ms'
 hostConfig = require './host-config'
 network = require './network'
 execAsync = Promise.promisify(require('child_process').exec)
@@ -132,7 +133,8 @@ module.exports = class DeviceState extends EventEmitter
 		@router = createDeviceStateRouter(this)
 		@on 'apply-target-state-end', (err) ->
 			if err?
-				console.log("Apply error #{err}")
+				if not (err instanceof UpdatesLockedError)
+					console.log("Apply error #{err}")
 			else
 				console.log('Apply success!')
 		@applications.on('change', @reportCurrentState)
@@ -342,6 +344,10 @@ module.exports = class DeviceState extends EventEmitter
 		Promise.using @_inferStepsLock, -> fn()
 
 	setTarget: (target, localSource = false) ->
+		# When we get a new target state, clear any built up apply errors
+		# This means that we can attempt to apply the new state instantly
+		@failedUpdates = 0
+
 		Promise.join(
 			@config.get('apiEndpoint'),
 			validateState(target),
@@ -573,11 +579,17 @@ module.exports = class DeviceState extends EventEmitter
 		@failedUpdates += 1
 		@reportCurrentState(update_failed: true)
 		if @scheduledApply?
-			console.log("Updating failed, but there's another update scheduled immediately: ", err)
+			if not (err instanceof UpdatesLockedError)
+				console.log("Updating failed, but there's another update scheduled immediately: ", err)
 		else
 			delay = Math.min((2 ** @failedUpdates) * constants.backoffIncrement, @maxPollTime)
 			# If there was an error then schedule another attempt briefly in the future.
-			console.log('Scheduling another update attempt due to failure: ', delay, err)
+			if err instanceof UpdatesLockedError
+				message = "Updates are locked, retrying in #{prettyMs(delay, compact: true)}..."
+				@logger.logSystemMessage(message, {}, 'updateLocked', false)
+				console.log(message)
+			else
+				console.log('Scheduling another update attempt due to failure: ', delay, err)
 			@triggerApplyTarget({ force, delay, initial })
 
 	applyTarget: ({ force = false, initial = false, intermediate = false, skipLock = false, nextDelay = 200, retryCount = 0 } = {}) =>