From da753e65cd4b122e44b72c9dc151bfb56e2ea701 Mon Sep 17 00:00:00 2001 From: Thodoris Greasidis Date: Mon, 5 Aug 2024 17:12:28 +0300 Subject: [PATCH] Add the device.last_api_heartbeat_change_date term to the model Resolves: #644 Change-type: minor See: https://balena.fibery.io/Work/Project/Start-recording-the-last-timestamp-the-device-heartbeat-changed-254 --- src/balena-model.ts | 2 + src/balena.sbvr | 8 +- src/features/device-heartbeat/index.ts | 13 +- ...-last-api-heartbeat-state-change-event.sql | 2 + src/translations/v6/v6.sbvr | 6 + test/03_device-state.ts | 262 ++++++++++++------ test/test-lib/api-helpers.ts | 18 ++ 7 files changed, 223 insertions(+), 88 deletions(-) create mode 100644 src/migrations/00092-device-last-api-heartbeat-state-change-event.sql diff --git a/src/balena-model.ts b/src/balena-model.ts index e758ef8bea..3cbb44f7e5 100644 --- a/src/balena-model.ts +++ b/src/balena-model.ts @@ -682,6 +682,7 @@ export interface Device { id: Types['Serial']['Read']; actor: { __id: Actor['Read']['id'] } | [Actor['Read']]; api_heartbeat_state: 'online' | 'offline' | 'timeout' | 'unknown'; + last_api_heartbeat_change_date: Types['Date Time']['Read'] | null; uuid: Types['Text']['Read']; local_id: Types['Short Text']['Read'] | null; device_name: Types['Short Text']['Read'] | null; @@ -777,6 +778,7 @@ export interface Device { id: Types['Serial']['Write']; actor: Actor['Write']['id']; api_heartbeat_state: 'online' | 'offline' | 'timeout' | 'unknown'; + last_api_heartbeat_change_date: Types['Date Time']['Write'] | null; uuid: Types['Text']['Write']; local_id: Types['Short Text']['Write'] | null; device_name: Types['Short Text']['Write'] | null; diff --git a/src/balena.sbvr b/src/balena.sbvr index 8168d13bfe..409c79eebd 100644 --- a/src/balena.sbvr +++ b/src/balena.sbvr @@ -82,6 +82,9 @@ Term: alias Term: api heartbeat state Concept Type: Short Text (Type) +Term: last api heartbeat change date + Concept Type: Date Time (Type) + Term: api port Concept Type: Integer (Type) @@ -368,6 +371,9 @@ Term: device Necessity: each device has exactly one api heartbeat state Definition: "online" or "offline" or "timeout" or "unknown" + Fact type: device has last api heartbeat change date + Necessity: each device has at most one last api heartbeat change date. + Fact type: device has env var name Term Form: device environment variable Database Table Name: device environment variable @@ -445,7 +451,7 @@ Fact type: user (Auth) has public key -- user public key Fact type: user public key has title - Necessity: each user public key has exactly one title + Necessity: each user public key has exactly one title -- application type diff --git a/src/features/device-heartbeat/index.ts b/src/features/device-heartbeat/index.ts index 32b865213f..066a095ff9 100644 --- a/src/features/device-heartbeat/index.ts +++ b/src/features/device-heartbeat/index.ts @@ -259,7 +259,7 @@ export class DeviceOnlineStateManager extends EventEmitter<{ try { // patch the api_heartbeat_state value to the new state... - const body = { + const baseBody = { api_heartbeat_state: newState, }; await api.resin.patch({ @@ -268,10 +268,17 @@ export class DeviceOnlineStateManager extends EventEmitter<{ id: deviceId, options: { $filter: { - $not: body, + $not: baseBody, }, }, - body, + body: { + ...baseBody, + // Since the heartbeat manager is the only place that we update the heartbeat state + // we are updating the heartbeat's change date in here rather than a hook, so that + // we can avoid the extra DB request that a generic hook would require for checking + // whether the value actually changed or not. + last_api_heartbeat_change_date: Date.now(), + }, }); } catch ($err) { err = $err; diff --git a/src/migrations/00092-device-last-api-heartbeat-state-change-event.sql b/src/migrations/00092-device-last-api-heartbeat-state-change-event.sql new file mode 100644 index 0000000000..35fa69e3d8 --- /dev/null +++ b/src/migrations/00092-device-last-api-heartbeat-state-change-event.sql @@ -0,0 +1,2 @@ +ALTER TABLE "device" +ADD COLUMN IF NOT EXISTS "last api heartbeat change date" TIMESTAMP NULL; diff --git a/src/translations/v6/v6.sbvr b/src/translations/v6/v6.sbvr index ba1b4fea51..4c26788ab7 100644 --- a/src/translations/v6/v6.sbvr +++ b/src/translations/v6/v6.sbvr @@ -82,6 +82,9 @@ Term: alias Term: api heartbeat state Concept Type: Short Text (Type) +Term: last api heartbeat change date + Concept Type: Date Time (Type) + Term: api port Concept Type: Integer (Type) @@ -378,6 +381,9 @@ Term: device Necessity: each device has exactly one api heartbeat state Definition: "online" or "offline" or "timeout" or "unknown" + Fact type: device has last api heartbeat change date + Necessity: each device has at most one last api heartbeat change date. + Fact type: device has env var name Term Form: device environment variable Database Table Name: device environment variable diff --git a/test/03_device-state.ts b/test/03_device-state.ts index 73a0badf6d..ac5f29f2f6 100644 --- a/test/03_device-state.ts +++ b/test/03_device-state.ts @@ -11,7 +11,10 @@ import * as config from '../src/lib/config.js'; import * as stateMock from '../src/features/device-heartbeat/index.js'; import { assertExists, itExpectsError, waitFor } from './test-lib/common.js'; import * as fixtures from './test-lib/fixtures.js'; -import { expectResourceToMatch } from './test-lib/api-helpers.js'; +import { + expectResourceToMatch, + thatIsDateStringAfter, +} from './test-lib/api-helpers.js'; import { redis, redisRO } from '../src/infra/redis/index.js'; import { setTimeout } from 'timers/promises'; import { MINUTES, SECONDS } from '@balena/env-parsing'; @@ -253,7 +256,10 @@ export default () => { [ { tokenType: 'device API Key', - getActor: () => device, + getPineActor: () => + pineTest.clone({ + passthrough: { user: device }, + }), heartbeatAfterGet: DeviceOnlineStates.Online, getDevice: () => device, getState: () => @@ -261,7 +267,10 @@ export default () => { }, { tokenType: 'user token', - getActor: () => admin, + getPineActor: () => + pineTest.clone({ + passthrough: { user: admin }, + }), heartbeatAfterGet: DeviceOnlineStates.Unknown, getDevice: () => deviceUserRequestedState, getState: () => @@ -274,27 +283,27 @@ export default () => { ].forEach( ({ tokenType, - getActor, + getPineActor, heartbeatAfterGet, getDevice, getState, }) => { describe(`Given a ${tokenType}`, function () { it('Should see state initially as "unknown"', async () => { - const { body } = await supertest(getActor()) - .get(`/${version}/device(${getDevice().id})`) - .expect(200); - - assertExists(body.d[0]); - expect(body.d[0]).to.have.property( - 'api_heartbeat_state', - DeviceOnlineStates.Unknown, - 'API heartbeat state is not unknown (default)', + await expectResourceToMatch( + getPineActor(), + 'device', + getDevice().id, + { + api_heartbeat_state: DeviceOnlineStates.Unknown, + last_api_heartbeat_change_date: null, + }, ); }); it(`Should have the "${heartbeatAfterGet}" heartbeat state after a state poll`, async () => { stateChangeEventSpy.resetHistory(); + const stateUpdatedAfter = Date.now(); await getState(); if (heartbeatAfterGet !== DeviceOnlineStates.Unknown) { @@ -312,15 +321,17 @@ export default () => { : undefined, ); - const { body } = await supertest(getActor()) - .get(`/${version}/device(${getDevice().id})`) - .expect(200); - - assertExists(body.d[0]); - expect(body.d[0]).to.have.property( - 'api_heartbeat_state', - heartbeatAfterGet, - `API heartbeat state is not ${heartbeatAfterGet}`, + await expectResourceToMatch( + getPineActor(), + 'device', + getDevice().id, + { + api_heartbeat_state: heartbeatAfterGet, + last_api_heartbeat_change_date: + heartbeatAfterGet === DeviceOnlineStates.Unknown + ? null + : thatIsDateStringAfter(stateUpdatedAfter), + }, ); }); @@ -332,31 +343,43 @@ export default () => { devicePollInterval / 1000 } seconds`, async () => { stateChangeEventSpy.resetHistory(); + let stateUpdatedAfter = Date.now(); await setTimeout(devicePollInterval); await waitFor({ - checkFn: () => stateChangeEventSpy.called, + checkFn: () => { + if (stateChangeEventSpy.called) { + return true; + } + stateUpdatedAfter = Math.max( + // The 10ms are there to account for concurrency between + // the spy check and the DB commiting the TX. + Date.now() - 10, + stateUpdatedAfter, + ); + return false; + }, }); expect(tracker.states[getDevice().id]).to.equal( DeviceOnlineStates.Timeout, ); - const { body } = await supertest(getActor()) - .get(`/${version}/device(${getDevice().id})`) - .expect(200); - - assertExists(body.d[0]); - expect(body.d[0]).to.have.property( - 'api_heartbeat_state', - DeviceOnlineStates.Timeout, - 'API heartbeat state is not timeout', + await expectResourceToMatch( + getPineActor(), + 'device', + getDevice().id, + { + api_heartbeat_state: DeviceOnlineStates.Timeout, + last_api_heartbeat_change_date: + thatIsDateStringAfter(stateUpdatedAfter), + }, ); }); it(`Should see state become "online" again, following a state poll`, async () => { stateChangeEventSpy.resetHistory(); - + const stateUpdatedAfter = Date.now(); await getState(); await waitFor({ @@ -367,15 +390,15 @@ export default () => { DeviceOnlineStates.Online, ); - const { body } = await supertest(getActor()) - .get(`/${version}/device(${getDevice().id})`) - .expect(200); - - assertExists(body.d[0]); - expect(body.d[0]).to.have.property( - 'api_heartbeat_state', - DeviceOnlineStates.Online, - 'API heartbeat state is not online', + await expectResourceToMatch( + getPineActor(), + 'device', + getDevice().id, + { + api_heartbeat_state: DeviceOnlineStates.Online, + last_api_heartbeat_change_date: + thatIsDateStringAfter(stateUpdatedAfter), + }, ); }); @@ -383,27 +406,38 @@ export default () => { TIMEOUT_SEC + devicePollInterval / 1000 } seconds`, async () => { stateChangeEventSpy.resetHistory(); - + let stateUpdatedAfter = Date.now(); await setTimeout(devicePollInterval + TIMEOUT_SEC * 1000); // it will be called for TIMEOUT and OFFLINE... await waitFor({ - checkFn: () => stateChangeEventSpy.calledTwice, + checkFn: () => { + if (stateChangeEventSpy.calledTwice) { + return true; + } + stateUpdatedAfter = Math.max( + // The 10ms are there to account for concurrency between + // the spy check and the DB commiting the TX. + Date.now() - 10, + stateUpdatedAfter, + ); + return false; + }, }); expect(tracker.states[getDevice().id]).to.equal( DeviceOnlineStates.Offline, ); - const { body } = await supertest(getActor()) - .get(`/${version}/device(${getDevice().id})`) - .expect(200); - - assertExists(body.d[0]); - expect(body.d[0]).to.have.property( - 'api_heartbeat_state', - DeviceOnlineStates.Offline, - 'API heartbeat state is not offline', + await expectResourceToMatch( + getPineActor(), + 'device', + getDevice().id, + { + api_heartbeat_state: DeviceOnlineStates.Offline, + last_api_heartbeat_change_date: + thatIsDateStringAfter(stateUpdatedAfter), + }, ); }); }); @@ -443,16 +477,9 @@ export default () => { DeviceOnlineStates.Offline, ); - const { body } = await supertest(admin) - .get(`/${version}/device(${device.id})`) - .expect(200); - - assertExists(body.d[0]); - expect(body.d[0]).to.have.property( - 'api_heartbeat_state', - DeviceOnlineStates.Offline, - 'API heartbeat state changed using an expired api key', - ); + await expectResourceToMatch(pineUser, 'device', device.id, { + api_heartbeat_state: DeviceOnlineStates.Offline, + }); }); it(`should see state become "online" again following a state poll after removing the expiry date from the api key`, async () => { @@ -481,16 +508,9 @@ export default () => { DeviceOnlineStates.Online, ); - const { body } = await supertest(admin) - .get(`/${version}/device(${device.id})`) - .expect(200); - - assertExists(body.d[0]); - expect(body.d[0]).to.have.property( - 'api_heartbeat_state', - DeviceOnlineStates.Online, - 'API heartbeat state is not online', - ); + await expectResourceToMatch(pineUser, 'device', device.id, { + api_heartbeat_state: DeviceOnlineStates.Online, + }); }); }); }); @@ -499,6 +519,23 @@ export default () => { let device2: fakeDevice.Device; const device2ChangeEventSpy = sinon.spy(); let lastPersistedTimestamp: number | undefined; + let lastApiHeartbeatStateChangeEvent: string | null = null; + + async function getLastApiHeartbeatStateChangeEvent( + id: number, + ): Promise { + const { body } = await pineUser + .get({ + resource: 'device', + id, + options: { + $select: 'last_api_heartbeat_change_date', + }, + }) + .expect(200); + assertExists(body); + return body.last_api_heartbeat_change_date; + } before(async () => { device2 = await fakeDevice.provisionDevice(admin, applicationId); @@ -510,6 +547,7 @@ export default () => { }); await expectResourceToMatch(pineUser, 'device', device2.id, { api_heartbeat_state: DeviceOnlineStates.Unknown, + last_api_heartbeat_change_date: null, }); }); beforeEach(function () { @@ -526,9 +564,19 @@ export default () => { it('The initial state poll should update the DB heartbeat to Online', async () => { await fakeDevice.getState(device2, device2.uuid, stateVersion); await waitFor({ checkFn: () => device2ChangeEventSpy.called }); - await expectResourceToMatch(pineUser, 'device', device2.id, { - api_heartbeat_state: DeviceOnlineStates.Online, - }); + const fetchedDevice = await expectResourceToMatch( + pineUser, + 'device', + device2.id, + { + api_heartbeat_state: DeviceOnlineStates.Online, + last_api_heartbeat_change_date: (prop) => + prop.that.is.a('string'), + }, + ); + + lastApiHeartbeatStateChangeEvent = + fetchedDevice.last_api_heartbeat_change_date; }); it('should not update the DB heartbeat on subsequent polls', async () => { @@ -537,6 +585,12 @@ export default () => { await setTimeout(1000); expect(tracker.states[device2.id]).to.be.undefined; expect(device2ChangeEventSpy.called).to.be.false; + + await expectResourceToMatch(pineUser, 'device', device2.id, { + api_heartbeat_state: DeviceOnlineStates.Online, + last_api_heartbeat_change_date: + lastApiHeartbeatStateChangeEvent, + }); }); it('will trust Redis and not update the DB heartbeat on subsequent polls even if the DB has diverged :(', async () => { @@ -547,12 +601,17 @@ export default () => { api_heartbeat_state: DeviceOnlineStates.Offline, }, }); + lastApiHeartbeatStateChangeEvent = + await getLastApiHeartbeatStateChangeEvent(device2.id); + await fakeDevice.getState(device2, device2.uuid, stateVersion); await setTimeout(1000); expect(tracker.states[device2.id]).to.be.undefined; expect(device2ChangeEventSpy.called).to.be.false; await expectResourceToMatch(pineUser, 'device', device2.id, { api_heartbeat_state: DeviceOnlineStates.Offline, + last_api_heartbeat_change_date: + lastApiHeartbeatStateChangeEvent, }); }); @@ -814,6 +873,8 @@ export default () => { api_heartbeat_state: DeviceOnlineStates.Unknown, }, }); + lastApiHeartbeatStateChangeEvent = + await getLastApiHeartbeatStateChangeEvent(device2.id); }); it('should update the DB heartbeat on the first request that finds the ttl being null', async () => { @@ -821,6 +882,9 @@ export default () => { await waitFor({ checkFn: () => device2ChangeEventSpy.called }); await expectResourceToMatch(pineUser, 'device', device2.id, { api_heartbeat_state: DeviceOnlineStates.Online, + last_api_heartbeat_change_date: thatIsDateStringAfter( + lastApiHeartbeatStateChangeEvent, + ), }); }); @@ -833,6 +897,9 @@ export default () => { api_heartbeat_state: DeviceOnlineStates.Unknown, }, }); + lastApiHeartbeatStateChangeEvent = + await getLastApiHeartbeatStateChangeEvent(device2.id); + for (let i = 0; i < 3; i++) { await fakeDevice.getState( device2, @@ -845,6 +912,8 @@ export default () => { expect(device2ChangeEventSpy.called).to.be.false; await expectResourceToMatch(pineUser, 'device', device2.id, { api_heartbeat_state: DeviceOnlineStates.Unknown, + last_api_heartbeat_change_date: + lastApiHeartbeatStateChangeEvent, }); }); @@ -855,6 +924,9 @@ export default () => { await waitFor({ checkFn: () => device2ChangeEventSpy.called }); await expectResourceToMatch(pineUser, 'device', device2.id, { api_heartbeat_state: DeviceOnlineStates.Online, + last_api_heartbeat_change_date: thatIsDateStringAfter( + lastApiHeartbeatStateChangeEvent, + ), }); }); }); @@ -870,9 +942,11 @@ export default () => { api_heartbeat_state: DeviceOnlineStates.Unknown, }, }); + lastApiHeartbeatStateChangeEvent = + await getLastApiHeartbeatStateChangeEvent(device2.id); }); - it(`should update the DB heartbeat on every poll`, async () => { + it(`should update the DB heartbeat on every poll, but only change the last_api_heartbeat_change_date the first time`, async () => { for (let i = 0; i < 3; i++) { await fakeDevice.getState( device2, @@ -883,10 +957,23 @@ export default () => { checkFn: () => device2ChangeEventSpy.called, }); device2ChangeEventSpy.resetHistory(); + const fetchedDevice = await expectResourceToMatch( + pineUser, + 'device', + device2.id, + { + api_heartbeat_state: DeviceOnlineStates.Online, + last_api_heartbeat_change_date: + i === 0 + ? thatIsDateStringAfter( + lastApiHeartbeatStateChangeEvent, + ) + : lastApiHeartbeatStateChangeEvent, + }, + ); + lastApiHeartbeatStateChangeEvent = + fetchedDevice.last_api_heartbeat_change_date; } - await expectResourceToMatch(pineUser, 'device', device2.id, { - api_heartbeat_state: DeviceOnlineStates.Online, - }); }); }); @@ -902,6 +989,8 @@ export default () => { api_heartbeat_state: DeviceOnlineStates.Unknown, }, }); + lastApiHeartbeatStateChangeEvent = + await getLastApiHeartbeatStateChangeEvent(device2.id); }); it(`should not update the DB heartbeat on polls within the validity period`, async () => { @@ -917,6 +1006,8 @@ export default () => { expect(device2ChangeEventSpy.called).to.be.false; await expectResourceToMatch(pineUser, 'device', device2.id, { api_heartbeat_state: DeviceOnlineStates.Unknown, + last_api_heartbeat_change_date: + lastApiHeartbeatStateChangeEvent, }); }); }); @@ -940,6 +1031,8 @@ export default () => { expect(device2ChangeEventSpy.called).to.be.false; await expectResourceToMatch(pineUser, 'device', device2.id, { api_heartbeat_state: DeviceOnlineStates.Unknown, + last_api_heartbeat_change_date: + lastApiHeartbeatStateChangeEvent, }); }); @@ -950,6 +1043,9 @@ export default () => { await waitFor({ checkFn: () => device2ChangeEventSpy.called }); await expectResourceToMatch(pineUser, 'device', device2.id, { api_heartbeat_state: DeviceOnlineStates.Online, + last_api_heartbeat_change_date: thatIsDateStringAfter( + lastApiHeartbeatStateChangeEvent, + ), }); }); }); @@ -1425,10 +1521,8 @@ export default () => { ); await expectResourceToMatch(pineUser, 'device', device.id, { - is_running__release: (chaiPropertyAssetion) => - chaiPropertyAssetion.that.is - .an('object') - .that.has.property('__id', r.id), + is_running__release: (prop) => + prop.that.is.an('object').that.has.property('__id', r.id), }); } }); diff --git a/test/test-lib/api-helpers.ts b/test/test-lib/api-helpers.ts index ee042b2174..1d75311acb 100644 --- a/test/test-lib/api-helpers.ts +++ b/test/test-lib/api-helpers.ts @@ -188,6 +188,24 @@ export const getUserFromToken = (token: string) => { return user; }; +export const thatIsDateStringAfter = ( + dateParam: Date | string | number | null, +) => { + if (dateParam == null) { + throw new Error( + `The date ${dateParam} provided to thatIsAfterDateString has to have a value`, + ); + } + const date = !_.isDate(dateParam) ? new Date(dateParam) : dateParam; + return (prop: Chai.Assertion, value: unknown) => + prop.that.is + .a('string') + .that.satisfies( + (d: string) => new Date(d) > date, + `Expected ${value} to be after ${date.toISOString()}`, + ); +}; + const validJwtProps = ['id', 'jwt_secret', 'authTime', 'iat', 'exp'].sort(); export function expectJwt(tokenOrJwt: string | AnyObject) {