Improve heartbeat log

packages/pusher/src/heartbeat/heartbeat.test.ts

@@ -3,13 +3,13 @@ import { join } from 'node:path';
 
 import * as promiseUtilsModule from '@api3/promise-utils';
 
-import { config, parseHeartbeatLog } from '../../test/fixtures';
+import { config, verifyHeartbeatLog } from '../../test/fixtures';
 import * as stateModule from '../state';
 import * as configModule from '../validation/config';
 
 import { heartbeatLogger } from './logger';
 
-import { initiateHeartbeat, logHeartbeat, createHash } from '.';
+import { initiateHeartbeat, logHeartbeat, type HeartbeatPayload, stringifyUnsignedHeartbeatPayload } from '.';
 
 // eslint-disable-next-line jest/no-hooks
 beforeEach(() => {
@@ -21,17 +21,17 @@ afterEach(() => {
 });
 
 describe(logHeartbeat.name, () => {
-  const expectedLogMessage = [
-    '0xbF3137b0a7574563a23a8fC8badC6537F98197CC',
-    'test',
-    '0.1.0',
-    '1674172803',
-    '1674172800',
-    '0x126e768ba244efdb790d63a76821047e163dfc502ace09b2546a93075594c286',
-    '0x14f123ec1006bace8f8971cd8c94eb022b9bb0e1364e88ae4e8562a5f02de43e35dd4ecdefc976595eba5fec3d04222a0249e876453599b27847e85e14ff77601b',
-  ].join(' - ');
-
   it('sends the correct heartbeat log', async () => {
+    const expectedLogMessage: HeartbeatPayload = {
+      airnode: '0xbF3137b0a7574563a23a8fC8badC6537F98197CC',
+      stage: 'test',
+      nodeVersion: '0.1.0',
+      currentTimestamp: '1674172803',
+      deploymentTimestamp: '1674172800',
+      configHash: '0x126e768ba244efdb790d63a76821047e163dfc502ace09b2546a93075594c286',
+      signature:
+        '0x24467037db96b652286c30c39ee9611faff07e1c17916f5c154ea7a27dfbc32f308969bdadf586bdaee0951b84819633e126a4fc72e3aa2e98a6eda95ce640081b',
+    };
     const rawConfig = JSON.parse(readFileSync(join(__dirname, '../../config/pusher.example.json'), 'utf8'));
     jest.spyOn(configModule, 'loadRawConfig').mockReturnValue(rawConfig);
     const state = stateModule.getInitialState(config);
@@ -41,27 +41,51 @@ describe(logHeartbeat.name, () => {
 
     await logHeartbeat();
 
-    expect(heartbeatLogger.info).toHaveBeenCalledWith(expectedLogMessage);
+    expect(heartbeatLogger.info).toHaveBeenCalledWith('Sending heartbeat log', expectedLogMessage);
   });
+});
 
-  it('the heartbeat log can be parsed', () => {
-    const rawConfig = JSON.parse(readFileSync(join(__dirname, '../../config/pusher.example.json'), 'utf8'));
-    jest.spyOn(configModule, 'loadRawConfig').mockReturnValue(rawConfig);
-    const expectedHeartbeatPayload = {
-      airnodeAddress: '0xbF3137b0a7574563a23a8fC8badC6537F98197CC',
-      stage: 'test',
-      nodeVersion: '0.1.0',
-      heartbeatTimestamp: '1674172803',
-      deploymentTimestamp: '1674172800',
-      configHash: '0x126e768ba244efdb790d63a76821047e163dfc502ace09b2546a93075594c286',
-      signature:
-        '0x14f123ec1006bace8f8971cd8c94eb022b9bb0e1364e88ae4e8562a5f02de43e35dd4ecdefc976595eba5fec3d04222a0249e876453599b27847e85e14ff77601b',
+describe(verifyHeartbeatLog.name, () => {
+  it('heartbeat payload can be parsed from JSON log', () => {
+    const jsonLog = {
+      context: {
+        airnode: '0xbF3137b0a7574563a23a8fC8badC6537F98197CC',
+        configHash: '0x126e768ba244efdb790d63a76821047e163dfc502ace09b2546a93075594c286',
+        currentTimestamp: '1674172803',
+        deploymentTimestamp: '1674172800',
+        nodeVersion: '0.1.0',
+        signature:
+          '0x24467037db96b652286c30c39ee9611faff07e1c17916f5c154ea7a27dfbc32f308969bdadf586bdaee0951b84819633e126a4fc72e3aa2e98a6eda95ce640081b',
+        stage: 'test',
+      },
+      level: 'info',
+      message: 'Sending heartbeat log',
+      ms: '+0ms',
+      timestamp: '2023-01-20T00:00:03.000Z',
     };
+    // The config hash is taken from config with all spaces removed.
+    const rawConfig = JSON.stringify(
+      JSON.parse(readFileSync(join(__dirname, '../../config/pusher.example.json'), 'utf8'))
+    );
 
-    const heartbeatPayload = parseHeartbeatLog(expectedLogMessage);
+    expect(() => verifyHeartbeatLog(jsonLog.context, rawConfig)).not.toThrow();
+  });
+});
 
-    expect(heartbeatPayload).toStrictEqual(expectedHeartbeatPayload);
-    expect(heartbeatPayload.configHash).toBe(createHash(JSON.stringify(rawConfig)));
+describe(stringifyUnsignedHeartbeatPayload.name, () => {
+  it('sorts the keys alphabetically', () => {
+    expect(
+      stringifyUnsignedHeartbeatPayload({
+        airnode: '0xbF3137b0a7574563a23a8fC8badC6537F98197CC',
+        stage: 'test',
+        nodeVersion: '0.1.0',
+        currentTimestamp: '1674172803',
+        deploymentTimestamp: '1674172800',
+        configHash: '0x126e768ba244efdb790d63a76821047e163dfc502ace09b2546a93075594c286',
+      })
+    ).toBe(
+      '{"airnode":"0xbF3137b0a7574563a23a8fC8badC6537F98197CC","configHash":"0x126e768ba244efdb790d63a76821047e163dfc502ace09b2546a93075594c286","currentTimestamp":"1674172803","deploymentTimestamp":"1674172800","nodeVersion":"0.1.0","stage":"test"}'
+    );
   });
 });
 

packages/pusher/src/heartbeat/heartbeat.ts

@@ -14,11 +14,27 @@ export const initiateHeartbeat = () => {
     if (!goLogHeartbeat.success) logger.error('Failed to log heartbeat', goLogHeartbeat.error);
   }, 1000 * 60); // Frequency is hardcoded to 1 minute.
 };
+export interface HeartbeatPayload {
+  airnode: string;
+  stage: string;
+  nodeVersion: string;
+  currentTimestamp: string;
+  deploymentTimestamp: string;
+  configHash: string;
+  signature: string;
+}
 
-export const signHeartbeat = async (airnodeWallet: ethers.Wallet, heartbeatPayload: unknown[]) => {
+// We need to make sure the object is stringified in the same way every time, so we sort the keys alphabetically.
+export const stringifyUnsignedHeartbeatPayload = (unsignedHeartbeatPayload: Omit<HeartbeatPayload, 'signature'>) =>
+  JSON.stringify(unsignedHeartbeatPayload, Object.keys(unsignedHeartbeatPayload).sort());
+
+export const signHeartbeat = async (
+  airnodeWallet: ethers.Wallet,
+  unsignedHeartbeatPayload: Omit<HeartbeatPayload, 'signature'>
+) => {
   logger.debug('Signing heartbeat payload');
-  const signaturePayload = ethers.utils.arrayify(createHash(JSON.stringify(heartbeatPayload)));
-  return airnodeWallet.signMessage(signaturePayload);
+  const messageToSign = ethers.utils.arrayify(createHash(stringifyUnsignedHeartbeatPayload(unsignedHeartbeatPayload)));
+  return airnodeWallet.signMessage(messageToSign);
 };
 
 export const createHash = (value: string) => ethers.utils.keccak256(ethers.utils.toUtf8Bytes(value));
@@ -27,7 +43,7 @@ export const logHeartbeat = async () => {
   logger.debug('Creating heartbeat log');
 
   const rawConfig = loadRawConfig(); // We want to log the raw config, not the one with interpolated secrets.
-  const rawConfigHash = createHash(JSON.stringify(rawConfig));
+  const configHash = createHash(JSON.stringify(rawConfig));
   const {
     airnodeWallet,
     deploymentTimestamp,
@@ -37,19 +53,19 @@ export const logHeartbeat = async () => {
   } = getState();
 
   logger.debug('Creating heartbeat payload');
-  const currentTimestamp = Math.floor(Date.now() / 1000);
-  const heartbeatPayload = [
-    airnodeWallet.address,
+  const currentTimestamp = Math.floor(Date.now() / 1000).toString();
+  const unsignedHeartbeatPayload = {
+    airnode: airnodeWallet.address,
     stage,
     nodeVersion,
-    currentTimestamp.toString(),
-    deploymentTimestamp.toString(),
-    rawConfigHash,
-  ];
-  const heartbeatSignature = await signHeartbeat(airnodeWallet, heartbeatPayload);
-  const heartbeatLog = [...heartbeatPayload, heartbeatSignature].join(' - ');
+    currentTimestamp,
+    deploymentTimestamp,
+    configHash,
+  };
+  const signature = await signHeartbeat(airnodeWallet, unsignedHeartbeatPayload);
+  const heartbeatPayload: HeartbeatPayload = { ...unsignedHeartbeatPayload, signature };
 
   // The logs are sent to API3 for validation (that the data provider deployed deployed the correct configuration) and
   // monitoring purposes (whether the instance is running).
-  heartbeatLogger.info(heartbeatLog);
+  heartbeatLogger.info('Sending heartbeat log', heartbeatPayload);
 };

packages/pusher/src/state.ts

@@ -15,7 +15,7 @@ export interface State {
   // We persist the derived Airnode wallet in memory as a performance optimization.
   airnodeWallet: ethers.Wallet;
   // The timestamp of when the service was initialized. This can be treated as a "deployment" timestamp.
-  deploymentTimestamp: number;
+  deploymentTimestamp: string;
 }
 
 let state: State;
@@ -88,7 +88,7 @@ export const getInitialState = (config: Config): State => {
     templateValues: buildTemplateStorages(config),
     apiLimiters: buildApiLimiters(config),
     airnodeWallet: ethers.Wallet.fromMnemonic(config.nodeSettings.airnodeWalletMnemonic),
-    deploymentTimestamp: Math.floor(Date.now() / 1000),
+    deploymentTimestamp: Math.floor(Date.now() / 1000).toString(),
   };
 };
 

packages/pusher/test/fixtures.ts

@@ -1,7 +1,9 @@
 import type { AxiosResponse } from 'axios';
 import { ethers } from 'ethers';
+import { omit } from 'lodash';
 
 import packageJson from '../package.json';
+import { type HeartbeatPayload, createHash, stringifyUnsignedHeartbeatPayload } from '../src/heartbeat';
 import type { SignedResponse, TemplateResponse } from '../src/sign-template-data';
 import type { Config } from '../src/validation/schema';
 
@@ -186,25 +188,14 @@ export const signedApiResponse: Partial<AxiosResponse> = {
   data: { count: 3 },
 };
 
-export const parseHeartbeatLog = (logMessage: string) => {
-  const [airnodeAddress, stage, nodeVersion, heartbeatTimestamp, deploymentTimestamp, configHash, signature] =
-    logMessage.split(' - ');
-
+export const verifyHeartbeatLog = (heartbeatPayload: HeartbeatPayload, rawConfig: string) => {
   // Verify that the signature is valid.
-  const heartbeatPayload = [airnodeAddress, stage, nodeVersion, heartbeatTimestamp, deploymentTimestamp, configHash];
-  const signaturePayload = ethers.utils.arrayify(
-    ethers.utils.keccak256(ethers.utils.toUtf8Bytes(JSON.stringify(heartbeatPayload)))
-  );
-  const recoveredAddress = ethers.utils.verifyMessage(signaturePayload, signature!);
-  if (recoveredAddress !== airnodeAddress) throw new Error('Invalid signature');
+  const unsignedHeartbeatPayload = omit(heartbeatPayload, 'signature');
+  const messageToSign = ethers.utils.arrayify(createHash(stringifyUnsignedHeartbeatPayload(unsignedHeartbeatPayload)));
+  const expectedAirnodeAddress = ethers.utils.verifyMessage(messageToSign, heartbeatPayload.signature);
+  if (expectedAirnodeAddress !== heartbeatPayload.airnode) throw new Error('Invalid signature');
 
-  return {
-    airnodeAddress,
-    stage,
-    nodeVersion,
-    deploymentTimestamp,
-    heartbeatTimestamp,
-    configHash,
-    signature,
-  };
+  // Verify that the config hash is valid.
+  const expectedConfigHash = createHash(rawConfig);
+  if (expectedConfigHash !== heartbeatPayload.configHash) throw new Error('Invalid config hash');
 };