fix(CogRPC): Log errors (#191)

* Reuse pino instance children

* Complete logging in collectCargoes

* Fix typo

* Document logging

* Log events in deliverCargo method

README.md

@@ -44,3 +44,18 @@ Create Minio buckets:
 MC_HOST_minio=http://THE-KEY-ID:letmeinpls@object-store:9000
 docker run --rm --network=relaynet-internet-gateway_default -e MC_HOST_minio minio/mc mb minio/relaynet-public-gateway
 ```
+
+## Logging
+
+We use [pino](https://getpino.io/) for logging. Some common log attributes include:
+
+- `cargoId`/`parcelId`: The id of a cargo or parcel, respectively. Useful to track its processing from delivery to collection.
+- `peerGatewayAddress`: The address of a private gateway paired or potentially paired to this public gateway. Useful to find all the events involving a specific private gateway.
+
+We use log levels as follows:
+
+- `debug`: Events that are only relevant during development or debugging. They should be ignored in production.
+- `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.
+- `critical`: Not used.

src/bin/cogrpc-server.ts

@@ -3,10 +3,4 @@ require('make-promises-safe');
 
 import { runServer } from '../services/cogrpc/server';
 
-async function main(): Promise<void> {
-  await runServer();
-  // tslint:disable-next-line:no-console
-  console.log('Ready to receive requests');
-}
-
-main();
+runServer();

src/services/_test_utils.ts

@@ -13,7 +13,6 @@ import { FastifyInstance, HTTPMethods } from 'fastify';
 import fastifyPlugin from 'fastify-plugin';
 import { Connection } from 'mongoose';
 import * as stan from 'node-nats-streaming';
-import * as pkijs from 'pkijs';
 
 import { PdaChain } from '../_test_utils';
 import { HTTP_METHODS } from './fastifyUtils';
@@ -123,10 +122,6 @@ export async function generateStubEndpointCertificate(
   });
 }
 
-export function makeEmptyCertificate(): Certificate {
-  return new Certificate(new pkijs.Certificate());
-}
-
 export interface StubParcelOptions {
   readonly recipientAddress: string;
   readonly senderCertificate: Certificate;

src/services/cogrpc/_test_utils.ts

@@ -44,6 +44,10 @@ export class MockGrpcBidiCall<Input, Output> extends Duplex {
     this.emit('end');
   }
 
+  public getPeer(): string {
+    return '127.0.0.1';
+  }
+
   public convertToGrpcStream(): grpc.ServerDuplexStream<Input, Output> {
     // Unfortunately, ServerDuplexStream's constructor is private so we have to resort to this
     // ugly hack

src/services/cogrpc/server.spec.ts

@@ -3,9 +3,10 @@
 import { CargoRelayService } from '@relaycorp/cogrpc';
 import * as grpc from 'grpc';
 import * as grpcHealthCheck from 'grpc-health-check';
+import { Logger } from 'pino';
 import selfsigned from 'selfsigned';
 
-import { mockSpy } from '../../_test_utils';
+import { makeMockLogging, mockSpy, partialPinoLog } from '../../_test_utils';
 import { configureMockEnvVars } from '../_test_utils';
 import { MAX_RAMF_MESSAGE_SIZE } from '../constants';
 import { runServer } from './server';
@@ -112,6 +113,10 @@ describe('runServer', () => {
 
     expect(makeServiceImplementationSpy).toBeCalledTimes(1);
     expect(makeServiceImplementationSpy).toBeCalledWith({
+      baseLogger: expect.objectContaining<Partial<Logger>>({
+        debug: expect.anything(),
+        error: expect.anything(),
+      }),
       cogrpcAddress: BASE_ENV_VARS.COGRPC_ADDRESS,
       gatewayKeyIdBase64: BASE_ENV_VARS.GATEWAY_KEY_ID,
       natsClusterId: BASE_ENV_VARS.NATS_CLUSTER_ID,
@@ -190,4 +195,12 @@ describe('runServer', () => {
     expect(mockServer.start).toBeCalledWith();
     expect(mockServer.start).toHaveBeenCalledAfter(mockServer.bind as jest.Mock);
   });
+
+  test('A log should be produced when the server is ready', async () => {
+    const mockLogging = makeMockLogging();
+
+    await runServer(mockLogging.logger);
+
+    expect(mockLogging.logs).toContainEqual(partialPinoLog('info', 'Ready to receive requests'));
+  });
 });

src/services/cogrpc/server.ts

@@ -2,6 +2,7 @@ import { CargoRelayService } from '@relaycorp/cogrpc';
 import { get as getEnvVar } from 'env-var';
 import { KeyCertPair, Server, ServerCredentials } from 'grpc';
 import grpcHealthCheck from 'grpc-health-check';
+import pino, { Logger } from 'pino';
 import * as selfsigned from 'selfsigned';
 
 import { MAX_RAMF_MESSAGE_SIZE } from '../constants';
@@ -16,7 +17,7 @@ const MAX_CONNECTION_AGE_MINUTES = 15;
 const MAX_CONNECTION_AGE_GRACE_SECONDS = 30;
 const MAX_CONNECTION_IDLE_SECONDS = 5;
 
-export async function runServer(): Promise<void> {
+export async function runServer(logger?: Logger): Promise<void> {
   const gatewayKeyIdBase64 = getEnvVar('GATEWAY_KEY_ID').required().asString();
   const cogrpcAddress = getEnvVar('COGRPC_ADDRESS').required().asString();
   const parcelStoreBucket = getEnvVar('OBJECT_STORE_BUCKET').required().asString();
@@ -31,7 +32,10 @@ export async function runServer(): Promise<void> {
     'grpc.max_metadata_size': MAX_METADATA_SIZE,
     'grpc.max_receive_message_length': MAX_RECEIVED_MESSAGE_LENGTH,
   });
+
+  const baseLogger = logger ?? pino();
   const serviceImplementation = await makeServiceImplementation({
+    baseLogger,
     cogrpcAddress,
     gatewayKeyIdBase64,
     natsClusterId,
@@ -56,6 +60,8 @@ export async function runServer(): Promise<void> {
     throw new Error(`Failed to listen on ${NETLOC}`);
   }
   server.start();
+
+  baseLogger.info('Ready to receive requests');
 }
 
 /**