fix: Ensure fatal logs are issued reliably when processes crash (#399)

* uncaughtException handler

* update docs

* refactor

* fix formatting

* Configure make-promises-safe

* silence TSLint warning

* Replace make-promises-safe with --unhandled-rejections=strict

* configure gRPC

* increase functional test suite timeout

* integrate CRC queue

* refactor

* integrate generate-keypairs.ts

* integrate pdc queue

* integrate fastify

* fix broken test

* fix broken tests

* fix broken test

* fix broken tests

.github/workflows/ci-cd.yml

@@ -69,7 +69,7 @@ jobs:
       - run: npm run test:functional
         env:
           IS_GITHUB: 'true'
-        timeout-minutes: 1
+        timeout-minutes: 2
       - name: Output diagnostic information upon failure
         if: failure()
         run: .github/scripts/output-diagnostics.sh

Dockerfile

@@ -9,5 +9,5 @@ FROM node:12.20.1-slim
 WORKDIR /opt/gw
 COPY --from=build /tmp/gw ./
 USER node
-ENTRYPOINT ["node"]
+ENTRYPOINT ["node", "--unhandled-rejections=strict"]
 EXPOSE 8080

chart/templates/cogrpc-deploy.yml

@@ -34,8 +34,7 @@ spec:
             {{- toYaml .Values.securityContext | nindent 12 }}
           image: {{ include "relaynet-internet-gateway.image" . }}
           imagePullPolicy: IfNotPresent
-          command:
-            - node
+          args:
             - build/main/bin/cogrpc-server.js
           env:
             - name: PUBLIC_ADDRESS

chart/templates/crcin-deploy.yml

@@ -33,8 +33,7 @@ spec:
             {{- toYaml .Values.securityContext | nindent 12 }}
           image: {{ include "relaynet-internet-gateway.image" . }}
           imagePullPolicy: IfNotPresent
-          command:
-            - node
+          args:
             - build/main/bin/crc-queue-worker.js
           env:
             - name: WORKER_ID

chart/templates/keygen-job.yml

@@ -24,8 +24,7 @@ spec:
         - name: keygen
           image: {{ include "relaynet-internet-gateway.image" . }}
           imagePullPolicy: IfNotPresent
-          command:
-            - node
+          args:
             - build/main/bin/generate-keypairs.js
           envFrom:
             - configMapRef:

chart/templates/pdcout-deploy.yml

@@ -31,8 +31,7 @@ spec:
             {{- toYaml .Values.securityContext | nindent 12 }}
           image: {{ include "relaynet-internet-gateway.image" . }}
           imagePullPolicy: IfNotPresent
-          command:
-            - node
+          args:
             - build/main/bin/pdc-outgoing-queue-worker.js
           env:
             - name: POHTTP_ADDRESS

chart/templates/pohttp-deploy.yml

@@ -33,8 +33,7 @@ spec:
             {{- toYaml .Values.securityContext | nindent 12 }}
           image: {{ include "relaynet-internet-gateway.image" . }}
           imagePullPolicy: IfNotPresent
-          command:
-            - node
+          args:
             - build/main/bin/pohttp-server.js
           env:
             {{- if .Values.proxyRequestIdHeader }}

chart/templates/poweb-deploy.yml

@@ -34,8 +34,7 @@ spec:
             {{- toYaml .Values.securityContext | nindent 12 }}
           image: {{ include "relaynet-internet-gateway.image" . }}
           imagePullPolicy: IfNotPresent
-          command:
-            - node
+          args:
             - build/main/bin/poweb-server.js
           env:
             {{- if .Values.proxyRequestIdHeader }}

docs/instrumentation.md

@@ -22,4 +22,4 @@ We use log levels as follows:
 - `info`: Events for any outcome observed outside the gateway, or any unusual interaction with a backing service.
 - `warning`: Something has gone wrong but it's being handled gracefully. Triage can start on the next working day.
 - `error`: Something has gone wrong and triage must start within a few minutes. Wake up an SRE if necessary.
-- `fatal`: Not used.
+- `fatal`: A process has crashed.

package.json

@@ -84,7 +84,6 @@
     "grpc": "^1.24.4",
     "grpc-health-check": "^1.8.0",
     "it-pipe": "^1.1.0",
-    "make-promises-safe": "^5.1.0",
     "mongoose": "^5.10.18",
     "node-nats-streaming": "^0.3.2",
     "pino": "^6.11.0",

src/bin/cogrpc-server.ts

@@ -1,6 +1,3 @@
-// tslint:disable-next-line:no-var-requires
-require('make-promises-safe');
-
 import { runServer } from '../services/cogrpc/server';
 
 runServer();

src/bin/crc-queue-worker.ts

@@ -1,12 +1,6 @@
-// tslint:disable-next-line:no-var-requires
-require('make-promises-safe');
-
 import { get as getEnvVar } from 'env-var';
 
 import { processIncomingCrcCargo } from '../services/crcQueueWorker';
 
 const WORKER_ID = getEnvVar('WORKER_ID').required().asString();
 processIncomingCrcCargo(WORKER_ID);
-
-// tslint:disable-next-line:no-console
-console.log(`Starting queue worker ${WORKER_ID}`);

src/bin/generate-keypairs.ts

@@ -1,8 +1,3 @@
-// tslint:disable:no-console
-
-// tslint:disable-next-line:no-var-requires
-require('make-promises-safe');
-
 import {
   Certificate,
   generateECDHKeyPair,
@@ -17,6 +12,11 @@ import { get as getEnvVar } from 'env-var';
 import { initVaultKeyStore } from '../backingServices/keyStores';
 import { createMongooseConnectionFromEnv } from '../backingServices/mongo';
 import { OwnCertificate } from '../services/models';
+import { configureExitHandling } from '../utilities/exitHandling';
+import { makeLogger } from '../utilities/logging';
+
+const LOGGER = makeLogger();
+configureExitHandling(LOGGER);
 
 const NODE_CERTIFICATE_TTL_DAYS = 180;
 const SESSION_CERTIFICATE_TTL_DAYS = 60;
@@ -29,10 +29,10 @@ async function main(): Promise<void> {
   const keyId = Buffer.from(KEY_ID_BASE64, 'base64');
   try {
     await sessionStore.fetchNodeKey(keyId);
-    console.warn(`Gateway key ${KEY_ID_BASE64} already exists`);
+    LOGGER.warn(`Gateway key ${KEY_ID_BASE64} already exists`);
     return;
   } catch (error) {
-    console.log(`Gateway key will be created because it doesn't already exist`);
+    LOGGER.info(`Gateway key will be created because it doesn't already exist`);
   }
 
   const gatewayKeyPair = await generateRSAKeyPair();
@@ -66,12 +66,13 @@ async function main(): Promise<void> {
   });
   await sessionStore.saveInitialSessionKey(initialSessionKeyPair.privateKey, initialKeyCertificate);
 
-  console.log(
-    JSON.stringify({
+  LOGGER.info(
+    {
       gatewayCertificate: base64Encode(gatewayCertificate.serialize()),
       initialSessionCertificate: base64Encode(initialKeyCertificate.serialize()),
       keyPairId: KEY_ID_BASE64,
-    }),
+    },
+    'Key pairs were successfully generated',
   );
 }
 

src/bin/pdc-outgoing-queue-worker.ts

@@ -1,6 +1,3 @@
-// tslint:disable-next-line:no-var-requires
-require('make-promises-safe');
-
 import { get as getEnvVar } from 'env-var';
 
 import { processInternetBoundParcels } from '../services/internetBoundParcelsQueueWorker';

src/bin/pohttp-server.ts

@@ -1,6 +1,3 @@
-// tslint:disable-next-line:no-var-requires
-require('make-promises-safe');
-
 import { makeServer } from '../services/pohttp/server';
 import { runFastify } from '../utilities/fastify';
 

src/bin/poweb-server.ts

@@ -1,6 +1,3 @@
-// tslint:disable-next-line:no-var-requires
-require('make-promises-safe');
-
 import { makeServer } from '../services/poweb/server';
 import { runFastify } from '../utilities/fastify';
 

src/services/cogrpc/server.spec.ts

@@ -5,6 +5,7 @@ import { Logger } from 'pino';
 import selfsigned from 'selfsigned';
 
 import { makeMockLogging, mockSpy, partialPinoLog } from '../../_test_utils';
+import * as exitHandling from '../../utilities/exitHandling';
 import * as logging from '../../utilities/logging';
 import { configureMockEnvVars, getMockContext } from '../_test_utils';
 import { MAX_RAMF_MESSAGE_SIZE } from '../constants';
@@ -33,6 +34,8 @@ const mockSelfSignedOutput = {
 };
 const mockSelfSigned = mockSpy(jest.spyOn(selfsigned, 'generate'), () => mockSelfSignedOutput);
 
+const mockExitHandler = mockSpy(jest.spyOn(exitHandling, 'configureExitHandling'));
+
 const BASE_ENV_VARS = {
   GATEWAY_KEY_ID: 'base64-encoded key id',
   NATS_CLUSTER_ID: 'nats-cluster-id',
@@ -47,6 +50,13 @@ const mockLogger = makeMockLogging().logger;
 const mockMakeLogger = mockSpy(jest.spyOn(logging, 'makeLogger'), () => mockLogger);
 
 describe('runServer', () => {
+  test('Exit handler should be configured as the very first step', async () => {
+    mockEnvVars({});
+
+    await expect(runServer()).toReject();
+    expect(mockExitHandler).toBeCalledWith(mockLogger);
+  });
+
   test.each([
     'GATEWAY_KEY_ID',
     'NATS_SERVER_URL',

src/services/cogrpc/server.ts

@@ -4,6 +4,7 @@ import { KeyCertPair, Server, ServerCredentials } from 'grpc';
 import grpcHealthCheck from 'grpc-health-check';
 import { Logger } from 'pino';
 import * as selfsigned from 'selfsigned';
+import { configureExitHandling } from '../../utilities/exitHandling';
 
 import { makeLogger } from '../../utilities/logging';
 import { MAX_RAMF_MESSAGE_SIZE } from '../constants';
@@ -19,6 +20,9 @@ const MAX_CONNECTION_AGE_GRACE_SECONDS = 30;
 const MAX_CONNECTION_IDLE_SECONDS = 5;
 
 export async function runServer(logger?: Logger): Promise<void> {
+  const baseLogger = logger ?? makeLogger();
+  configureExitHandling(baseLogger);
+
   const gatewayKeyIdBase64 = getEnvVar('GATEWAY_KEY_ID').required().asString();
   const publicAddress = getEnvVar('PUBLIC_ADDRESS').required().asString();
   const parcelStoreBucket = getEnvVar('OBJECT_STORE_BUCKET').required().asString();
@@ -34,7 +38,6 @@ export async function runServer(logger?: Logger): Promise<void> {
     'grpc.max_receive_message_length': MAX_RECEIVED_MESSAGE_LENGTH,
   });
 
-  const baseLogger = logger ?? makeLogger();
   const serviceImplementation = await makeServiceImplementation({
     baseLogger,
     gatewayKeyIdBase64,

src/services/crcQueueWorker.spec.ts

@@ -30,6 +30,7 @@ import * as privateKeyStore from '../backingServices/keyStores';
 import * as mongo from '../backingServices/mongo';
 import { NatsStreamingClient } from '../backingServices/natsStreaming';
 import * as objectStorage from '../backingServices/objectStorage';
+import * as exitHandling from '../utilities/exitHandling';
 import * as logging from '../utilities/logging';
 import {
   castMock,
@@ -61,7 +62,10 @@ beforeEach(() => {
     makeQueueConsumer: jest.fn().mockImplementation(mockMakeQueueConsumer),
   });
 });
-mockSpy(jest.spyOn(NatsStreamingClient, 'initFromEnv'), () => mockNatsClient);
+const mockNatsInitFromEnv = mockSpy(
+  jest.spyOn(NatsStreamingClient, 'initFromEnv'),
+  () => mockNatsClient,
+);
 
 //region Mongoose-related fixtures
 
@@ -143,13 +147,35 @@ beforeAll(() => {
 });
 const mockMakeLogger = mockSpy(jest.spyOn(logging, 'makeLogger'), () => mockLogging.logger);
 
+const mockExitHandler = mockSpy(jest.spyOn(exitHandling, 'configureExitHandling'));
+
 describe('Queue subscription', () => {
   test('Logger should be configured', async () => {
     await processIncomingCrcCargo(STUB_WORKER_NAME);
 
     expect(mockMakeLogger).toBeCalledWith();
   });
 
+  test('Exit handler should be configured as the very first step', async () => {
+    const error = new Error('oh noes');
+    mockNatsInitFromEnv.mockImplementation(() => {
+      throw error;
+    });
+
+    await expect(processIncomingCrcCargo(STUB_WORKER_NAME)).rejects.toEqual(error);
+    expect(mockExitHandler).toBeCalledWith(
+      expect.toSatisfy((logger) => logger.bindings().worker === STUB_WORKER_NAME),
+    );
+  });
+
+  test('Start of the queue should be logged', async () => {
+    await processIncomingCrcCargo(STUB_WORKER_NAME);
+
+    expect(mockLogging.logs).toContainEqual(
+      partialPinoLog('info', 'Starting queue worker', { worker: STUB_WORKER_NAME }),
+    );
+  });
+
   test('Worker should subscribe to channel "crc-cargo"', async () => {
     await processIncomingCrcCargo(STUB_WORKER_NAME);
 

src/services/crcQueueWorker.ts

@@ -18,11 +18,16 @@ import { initVaultKeyStore } from '../backingServices/keyStores';
 import { createMongooseConnectionFromEnv } from '../backingServices/mongo';
 import { NatsStreamingClient } from '../backingServices/natsStreaming';
 import { initObjectStoreFromEnv } from '../backingServices/objectStorage';
+import { configureExitHandling } from '../utilities/exitHandling';
 import { makeLogger } from '../utilities/logging';
 import { MongoPublicKeyStore } from './MongoPublicKeyStore';
 import { ParcelStore } from './parcelStore';
 
 export async function processIncomingCrcCargo(workerName: string): Promise<void> {
+  const logger = makeLogger().child({ worker: workerName });
+  configureExitHandling(logger);
+  logger.info('Starting queue worker');
+
   const natsStreamingClient = NatsStreamingClient.initFromEnv(workerName);
 
   const queueConsumer = natsStreamingClient.makeQueueConsumer(
@@ -32,16 +37,14 @@ export async function processIncomingCrcCargo(workerName: string): Promise<void>
     undefined,
     '-consumer',
   );
-  await pipe(queueConsumer, makeCargoProcessor(workerName, natsStreamingClient));
+  await pipe(queueConsumer, makeCargoProcessor(natsStreamingClient, logger));
 }
 
 function makeCargoProcessor(
-  workerName: string,
   natsStreamingClient: NatsStreamingClient,
+  logger: Logger,
 ): (messages: AsyncIterable<Message>) => Promise<void> {
   return async (messages) => {
-    const logger = makeLogger();
-
     const mongooseConnection = await createMongooseConnectionFromEnv();
     const gateway = new Gateway(initVaultKeyStore(), new MongoPublicKeyStore(mongooseConnection));
 
@@ -54,7 +57,7 @@ function makeCargoProcessor(
         await processCargo(
           message,
           gateway,
-          logger.child({ worker: workerName }),
+          logger,
           parcelStore,
           mongooseConnection,
           natsStreamingClient,