Refactor api-binder healthchecks to log reason for failure

Signed-off-by: Miguel Casqueira <miguel@balena.io>

src/api-binder.ts

@@ -1,5 +1,6 @@
 import * as Bluebird from 'bluebird';
 import * as bodyParser from 'body-parser';
+import { stripIndent } from 'common-tags';
 import * as express from 'express';
 import { isLeft } from 'fp-ts/lib/Either';
 import * as t from 'io-ts';
@@ -113,24 +114,49 @@ export class APIBinder {
 			'connectivityCheckEnabled',
 		]);
 
+		// Don't have to perform checks for unmanaged
 		if (unmanaged) {
 			return true;
 		}
 
 		if (appUpdatePollInterval == null) {
+			log.info(
+				'Healthcheck failure - Config value `appUpdatePollInterval` cannot be null',
+			);
 			return false;
 		}
 
+		// Check last time target state has been polled
 		const timeSinceLastFetch = process.hrtime(this.lastTargetStateFetch);
 		const timeSinceLastFetchMs =
 			timeSinceLastFetch[0] * 1000 + timeSinceLastFetch[1] / 1e6;
-		const stateFetchHealthy = timeSinceLastFetchMs < 2 * appUpdatePollInterval;
+
+		if (!(timeSinceLastFetchMs < 2 * appUpdatePollInterval)) {
+			log.info(
+				'Healthcheck failure - Device has not fetched target state within appUpdatePollInterval limit',
+			);
+			return false;
+		}
+
+		// Check if state report is healthy
 		const stateReportHealthy =
 			!connectivityCheckEnabled ||
 			!this.deviceState.connected ||
 			this.stateReportErrors < 3;
 
-		return stateFetchHealthy && stateReportHealthy;
+		if (!stateReportHealthy) {
+			log.info(
+				stripIndent`
+				Healthcheck failure - Atleast ONE of the following conditions must be true:
+					- No connectivityCheckEnabled   ? ${!(connectivityCheckEnabled === true)}
+					- device state is disconnected  ? ${!(this.deviceState.connected === true)}
+					- stateReportErrors less then 3 ? ${this.stateReportErrors < 3}`,
+			);
+			return false;
+		}
+
+		// All tests pass!
+		return true;
 	}
 
 	public async initClient() {

test/11-api-binder.spec.ts

@@ -1,3 +1,4 @@
+import { stripIndent } from 'common-tags';
 import { fs } from 'mz';
 import { Server } from 'net';
 import { SinonSpy, SinonStub, spy, stub } from 'sinon';
@@ -279,4 +280,108 @@ describe('ApiBinder', () => {
 			});
 		});
 	});
+
+	describe('healthchecks', () => {
+		const components: Dictionary<any> = {};
+		let configStub: SinonStub;
+		let infoLobSpy: SinonSpy;
+
+		before(() => {
+			initModels(components, '/config-apibinder.json');
+		});
+
+		beforeEach(() => {
+			// This configStub will be modified in each test case so we can
+			// create the exact conditions we want to for testing healthchecks
+			configStub = stub(Config.prototype, 'getMany');
+			infoLobSpy = spy(Log, 'info');
+		});
+
+		afterEach(() => {
+			configStub.restore();
+			infoLobSpy.restore();
+		});
+
+		it('passes with correct conditions', async () => {
+			// Set unmanaged to false so we check all values
+			// The other values are stubbed to make it pass
+			configStub.resolves({
+				unmanaged: false,
+				appUpdatePollInterval: 1000,
+				connectivityCheckEnabled: false,
+			});
+			expect(await components.apiBinder.healthcheck()).to.equal(true);
+		});
+
+		it('passes if unmanaged is true and exit early', async () => {
+			// Setup failing conditions
+			configStub.resolves({
+				unmanaged: false,
+				appUpdatePollInterval: null,
+				connectivityCheckEnabled: false,
+			});
+			// Verify this causes healthcheck to fail
+			expect(await components.apiBinder.healthcheck()).to.equal(false);
+			// Do it again but set unmanaged to true
+			configStub.resolves({
+				unmanaged: true,
+				appUpdatePollInterval: null,
+				connectivityCheckEnabled: false,
+			});
+			expect(await components.apiBinder.healthcheck()).to.equal(true);
+		});
+
+		it('fails if appUpdatePollInterval not set in config and exit early', async () => {
+			configStub.resolves({
+				unmanaged: false,
+				appUpdatePollInterval: null,
+				connectivityCheckEnabled: false,
+			});
+			expect(await components.apiBinder.healthcheck()).to.equal(false);
+			expect(Log.info).to.be.calledOnce;
+			expect((Log.info as SinonSpy).lastCall?.lastArg).to.equal(
+				'Healthcheck failure - Config value `appUpdatePollInterval` cannot be null',
+			);
+		});
+
+		it("fails when hasn't checked target state within poll interval", async () => {
+			configStub.resolves({
+				unmanaged: false,
+				appUpdatePollInterval: 1,
+				connectivityCheckEnabled: false,
+			});
+			expect(await components.apiBinder.healthcheck()).to.equal(false);
+			expect(Log.info).to.be.calledOnce;
+			expect((Log.info as SinonSpy).lastCall?.lastArg).to.equal(
+				'Healthcheck failure - Device has not fetched target state within appUpdatePollInterval limit',
+			);
+		});
+
+		it('fails when stateReportHealthy is false', async () => {
+			configStub.resolves({
+				unmanaged: false,
+				appUpdatePollInterval: 1000,
+				connectivityCheckEnabled: true,
+			});
+			// Copy previous values to restore later
+			const previousStateReportErrors = components.apiBinder.stateReportErrors;
+			const previousDeviceStateConnected =
+				components.apiBinder.deviceState.connected;
+			// Set additional conditions not in configStub to cause a fail
+			components.apiBinder.stateReportErrors = 4;
+			components.apiBinder.deviceState.connected = true;
+			expect(await components.apiBinder.healthcheck()).to.equal(false);
+			expect(Log.info).to.be.calledOnce;
+			expect((Log.info as SinonSpy).lastCall?.lastArg).to.equal(
+				stripIndent`
+				Healthcheck failure - Atleast ONE of the following conditions must be true:
+					- No connectivityCheckEnabled   ? false
+					- device state is disconnected  ? false
+					- stateReportErrors less then 3 ? false`,
+			);
+			// Restore previous values
+			components.apiBinder.stateReportErrors = previousStateReportErrors;
+			components.apiBinder.deviceState.connected = previousDeviceStateConnected;
+		});
+	});
 });