Merge pull request #1340 from balena-io/1249-log-healthcheck-failure

log healthcheck failure

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() {

src/device-state.ts

@@ -1,5 +1,6 @@
 import * as Bluebird from 'bluebird';
 import * as bodyParser from 'body-parser';
+import { stripIndent } from 'common-tags';
 import { EventEmitter } from 'events';
 import * as express from 'express';
 import * as _ from 'lodash';
@@ -285,19 +286,36 @@ export class DeviceState extends (EventEmitter as new () => DeviceStateEventEmit
 
 	public async healthcheck() {
 		const unmanaged = await this.config.get('unmanaged');
+
+		// Don't have to perform checks for unmanaged
+		if (unmanaged) {
+			return true;
+		}
+
 		const cycleTime = process.hrtime(this.lastApplyStart);
 		const cycleTimeMs = cycleTime[0] * 1000 + cycleTime[1] / 1e6;
-
 		const cycleTimeWithinInterval =
 			cycleTimeMs - this.applications.timeSpentFetching < 2 * this.maxPollTime;
 
+		// Check if target is healthy
 		const applyTargetHealthy =
-			unmanaged ||
 			!this.applyInProgress ||
 			this.applications.fetchesInProgress > 0 ||
 			cycleTimeWithinInterval;
 
-		return applyTargetHealthy;
+		if (!applyTargetHealthy) {
+			log.info(
+				stripIndent`
+				Healthcheck failure - Atleast ONE of the following conditions must be true:
+					- No applyInProgress      ? ${!(this.applyInProgress === true)}
+					- fetchesInProgress       ? ${this.applications.fetchesInProgress > 0}
+					- cycleTimeWithinInterval ? ${cycleTimeWithinInterval}`,
+			);
+			return false;
+		}
+
+		// All tests pass!
+		return true;
 	}
 
 	public async init() {

test/05-device-state.spec.ts

@@ -1,23 +1,22 @@
 import * as Bluebird from 'bluebird';
+import { stripIndent } from 'common-tags';
 import * as _ from 'lodash';
-import { stub } from 'sinon';
+import { SinonSpy, SinonStub, spy, stub } from 'sinon';
 
 import chai = require('./lib/chai-config');
 import prepare = require('./lib/prepare');
-// tslint:disable-next-line
-chai.use(require('chai-events'));
-
-const { expect } = chai;
-
+import Log from '../src/lib/supervisor-console';
 import Config from '../src/config';
 import { RPiConfigBackend } from '../src/config/backend';
 import DeviceState from '../src/device-state';
-
 import { loadTargetFromFile } from '../src/device-state/preload';
-
 import Service from '../src/compose/service';
 import { intialiseContractRequirements } from '../src/lib/contracts';
 
+// tslint:disable-next-line
+chai.use(require('chai-events'));
+const { expect } = chai;
+
 const mockedInitialConfig = {
 	RESIN_SUPERVISOR_CONNECTIVITY_CHECK: 'true',
 	RESIN_SUPERVISOR_DELTA: 'false',
@@ -384,4 +383,63 @@ describe('deviceState', () => {
 	it('applies the target state for device config');
 
 	it('applies the target state for applications');
+
+	describe('healthchecks', () => {
+		let configStub: SinonStub;
+		let infoLobSpy: SinonSpy;
+
+		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, 'get');
+			infoLobSpy = spy(Log, 'info');
+		});
+
+		afterEach(() => {
+			configStub.restore();
+			infoLobSpy.restore();
+		});
+
+		it('passes with correct conditions', async () => {
+			// Setup passing condition
+			const previousValue = deviceState.applyInProgress;
+			deviceState.applyInProgress = false;
+			expect(await deviceState.healthcheck()).to.equal(true);
+			// Restore value
+			deviceState.applyInProgress = previousValue;
+		});
+
+		it('passes if unmanaged is true and exit early', async () => {
+			// Setup failing conditions
+			const previousValue = deviceState.applyInProgress;
+			deviceState.applyInProgress = true;
+			// Verify this causes healthcheck to fail
+			expect(await deviceState.healthcheck()).to.equal(false);
+			// Do it again but set unmanaged to true
+			configStub.resolves({
+				unmanaged: true,
+			});
+			expect(await deviceState.healthcheck()).to.equal(true);
+			// Restore value
+			deviceState.applyInProgress = previousValue;
+		});
+
+		it('fails when applyTargetHealthy is false', async () => {
+			// Copy previous values to restore later
+			const previousValue = deviceState.applyInProgress;
+			// Setup failing conditions
+			deviceState.applyInProgress = true;
+			expect(await deviceState.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 applyInProgress      ? false
+					- fetchesInProgress       ? false
+					- cycleTimeWithinInterval ? false`,
+			);
+			// Restore value
+			deviceState.applyInProgress = previousValue;
+		});
+	});
 });

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(async () => {
+			await 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;
+		});
+	});
 });

test/21-supervisor-api.spec.ts

@@ -1,7 +1,9 @@
 import { expect } from 'chai';
-import { spy } from 'sinon';
+import { spy, stub, SinonStub } from 'sinon';
 import * as supertest from 'supertest';
 
+import APIBinder from '../src/api-binder';
+import DeviceState from '../src/device-state';
 import Log from '../src/lib/supervisor-console';
 import SupervisorAPI from '../src/supervisor-api';
 import sampleResponses = require('./data/device-api-responses.json');
@@ -17,9 +19,15 @@ const ALLOWED_INTERFACES = ['lo']; // Only need loopback since this is for testi
 
 describe('SupervisorAPI', () => {
 	let api: SupervisorAPI;
+	let healthCheckStubs: SinonStub[];
 	const request = supertest(`http://127.0.0.1:${mockedOptions.listenPort}`);
 
 	before(async () => {
+		// Stub health checks so we can modify them whenever needed
+		healthCheckStubs = [
+			stub(APIBinder.prototype, 'healthcheck'),
+			stub(DeviceState.prototype, 'healthcheck'),
+		];
 		// The mockedAPI contains stubs that might create unexpected results
 		// See the module to know what has been stubbed
 		api = await mockedAPI.create();
@@ -39,6 +47,8 @@ describe('SupervisorAPI', () => {
 				throw e;
 			}
 		}
+		// Restore healthcheck stubs
+		healthCheckStubs.forEach((hc) => hc.restore);
 		// Remove any test data generated
 		await mockedAPI.cleanUp();
 	});
@@ -56,7 +66,43 @@ describe('SupervisorAPI', () => {
 		});
 	});
 
-	describe.skip('V1 endpoints', () => {
+	describe('V1 endpoints', () => {
+		describe('GET /v1/healthy', () => {
+			it('returns OK because all checks pass', async () => {
+				// Make all healthChecks pass
+				healthCheckStubs.forEach((hc) => hc.resolves(true));
+				await request
+					.get('/v1/healthy')
+					.set('Accept', 'application/json')
+					.set('Authorization', `Bearer ${VALID_SECRET}`)
+					.expect(sampleResponses.V1.GET['/healthy'].statusCode)
+					.then((response) => {
+						expect(response.body).to.deep.equal(
+							sampleResponses.V1.GET['/healthy'].body,
+						);
+						expect(response.text).to.deep.equal(
+							sampleResponses.V1.GET['/healthy'].text,
+						);
+					});
+			});
+			it('Fails because some checks did not pass', async () => {
+				// Make one of the healthChecks fail
+				healthCheckStubs[0].resolves(false);
+				await request
+					.get('/v1/healthy')
+					.set('Accept', 'application/json')
+					.set('Authorization', `Bearer ${VALID_SECRET}`)
+					.expect(sampleResponses.V1.GET['/healthy [2]'].statusCode)
+					.then((response) => {
+						expect(response.body).to.deep.equal(
+							sampleResponses.V1.GET['/healthy [2]'].body,
+						);
+						expect(response.text).to.deep.equal(
+							sampleResponses.V1.GET['/healthy [2]'].text,
+						);
+					});
+			});
+		});
 		// TODO: add tests for V1 endpoints
 	});
 

test/data/device-api-responses.json

@@ -1,5 +1,18 @@
 {
-  "V1": {},
+  "V1": {
+    "GET": {
+      "/healthy": {
+        "statusCode": 200,
+        "body": {},
+        "text": "OK"
+      },
+      "/healthy [2]": {
+        "statusCode": 500,
+        "body": {},
+        "text": "Unhealthy"
+      }
+    }
+  },
   "V2": {
     "GET": {
       "/device/vpn": {

test/lib/mocked-device-api.ts

@@ -11,6 +11,7 @@ import Config from '../../src/config';
 import * as db from '../../src/db';
 import { createV1Api } from '../../src/device-api/v1';
 import { createV2Api } from '../../src/device-api/v2';
+import APIBinder from '../../src/api-binder';
 import DeviceState from '../../src/device-state';
 import EventTracker from '../../src/event-tracker';
 import SupervisorAPI from '../../src/supervisor-api';
@@ -67,7 +68,12 @@ const STUBBED_VALUES = {
 
 async function create(): Promise<SupervisorAPI> {
 	// Get SupervisorAPI construct options
-	const { config, eventTracker, deviceState } = await createAPIOpts();
+	const {
+		config,
+		eventTracker,
+		deviceState,
+		apiBinder,
+	} = await createAPIOpts();
 	// Stub functions
 	setupStubs();
 	// Create ApplicationManager
@@ -83,7 +89,7 @@ async function create(): Promise<SupervisorAPI> {
 		config,
 		eventTracker,
 		routers: [buildRoutes(appManager)],
-		healthchecks: [],
+		healthchecks: [deviceState.healthcheck, apiBinder.healthcheck],
 	});
 	// Return SupervisorAPI that is not listening yet
 	return api;
@@ -115,10 +121,16 @@ async function createAPIOpts(): Promise<SupervisorAPIOpts> {
 		logger: null as any,
 		apiBinder: null as any,
 	});
+	const apiBinder = new APIBinder({
+		config: mockedConfig,
+		eventTracker: tracker,
+		logger: null as any,
+	});
 	return {
 		config: mockedConfig,
 		eventTracker: tracker,
 		deviceState,
+		apiBinder,
 	};
 }
 
@@ -168,6 +180,7 @@ interface SupervisorAPIOpts {
 	config: Config;
 	eventTracker: EventTracker;
 	deviceState: DeviceState;
+	apiBinder: APIBinder;
 }
 
 export = { create, cleanUp, STUBBED_VALUES };