fix: bigint logging does not work

`JSON.stringify(1n)` throws a exception

Restructure logging so that the stream can be overriden rather than disabled.
This allows the logger to continue working so it can be tested

packages/lambda-api-tracker/src/index.ts

@@ -1,6 +1,5 @@
 import {
     Const,
-    Projection,
     getXyzFromPath,
     HttpHeader,
     LambdaFunction,
@@ -9,7 +8,8 @@ import {
     LambdaHttpResponseCloudFrontRequest,
     LambdaSession,
     LambdaType,
-    Logger,
+    Projection,
+    LogType,
 } from '@basemaps/shared';
 import { CloudFrontRequestEvent, Context } from 'aws-lambda';
 import { queryStringExtractor } from './query';
@@ -22,7 +22,7 @@ const projection = new Projection(256);
 export async function handleRequest(
     event: CloudFrontRequestEvent,
     context: Context,
-    logger: typeof Logger,
+    logger: LogType,
 ): Promise<LambdaHttpResponse> {
     const session = LambdaSession.get();
     const [record] = event.Records;

packages/lambda-api-tracker/src/validate.ts

@@ -1,11 +1,11 @@
-import { Aws, Logger, Const, LambdaHttpResponseCloudFront, HttpHeader, LambdaSession } from '@basemaps/shared';
+import { Aws, LogType, Const, LambdaHttpResponseCloudFront, HttpHeader, LambdaSession } from '@basemaps/shared';
 
 export const ValidateRequest = {
     /**
      * Validate that a API Key is valid
      * @param apiKey API key to validate
      */
-    async validate(apiKey: string, log: typeof Logger): Promise<LambdaHttpResponseCloudFront | void> {
+    async validate(apiKey: string, log: LogType): Promise<LambdaHttpResponseCloudFront | void> {
         const timer = LambdaSession.get().timer;
         // TODO increment the api counter
         timer.start('validate:db');

packages/lambda-xyz/src/__test__/xyz.test.ts

@@ -2,7 +2,7 @@ process.env['COG_BUCKET'] = 'fake-bucket';
 
 jest.mock('@cogeotiff/source-aws');
 
-import { Logger, Env, LambdaSession } from '@basemaps/shared';
+import { Env, LambdaSession, LogConfig } from '@basemaps/shared';
 import { ALBEvent } from 'aws-lambda';
 import { handleRequest } from '../index';
 import { CogSourceAwsS3 } from '@cogeotiff/source-aws';
@@ -45,10 +45,12 @@ describe('LambdaXyz', () => {
         }
         // For each tiff created generate a unique number
         createMock.mockImplementation(() => counter++);
+
+        jest.spyOn(LogConfig.getOutputStream(), 'write').mockImplementation();
     });
 
     it('should generate a tile 0,0,0', async () => {
-        const res = await handleRequest(req('/0/0/0/0.png'), null as any, Logger);
+        const res = await handleRequest(req('/0/0/0/0.png'), null as any, LogConfig.get());
         expect(res.status).toEqual(200);
         expect(res.headers).toEqual({
             'content-type': 'image/png',
@@ -76,7 +78,7 @@ describe('LambdaXyz', () => {
 
     it('should 404 if a tile is in bounds', async () => {
         tileMock.mockReset();
-        const res = await handleRequest(req('/0/0/0/0.png'), null as any, Logger);
+        const res = await handleRequest(req('/0/0/0/0.png'), null as any, LogConfig.get());
         expect(res.status).toEqual(404);
         expect(tileMock.mock.calls.length).toEqual(1);
         expect(rasterMock.mock.calls.length).toEqual(0);
@@ -85,7 +87,7 @@ describe('LambdaXyz', () => {
     it('should 304 if a tile is not modified', async () => {
         const request = req('/0/0/0/0.png');
         request.headers = { 'if-none-match': '"IIasQDnNSdw55Q4npcCyYmLmkWB8vBbemMiDIdAgqC4="' };
-        const res = await handleRequest(request, null as any, Logger);
+        const res = await handleRequest(request, null as any, LogConfig.get());
         expect(res.status).toEqual(304);
         expect(tileMock.mock.calls.length).toEqual(1);
         expect(rasterMock.mock.calls.length).toEqual(0);
@@ -96,31 +98,31 @@ describe('LambdaXyz', () => {
 
     ['/favicon.ico', '/index.html', '/foo/bar'].forEach(path => {
         it('should error on invalid paths: ' + path, async () => {
-            const res = await handleRequest(req(path), null as any, Logger);
+            const res = await handleRequest(req(path), null as any, LogConfig.get());
             expect(res.status).toEqual(404);
         });
     });
 
     it('should respond to /version', async () => {
         process.env[Env.Version] = 'version';
         process.env[Env.Hash] = 'hash';
-        const res = await handleRequest(req('/version'), null as any, Logger);
+        const res = await handleRequest(req('/version'), null as any, LogConfig.get());
         expect(res.statusDescription).toEqual('ok');
         expect(res.status).toEqual(200);
         expect(res.toResponse().body).toEqual(JSON.stringify({ version: 'version', hash: 'hash' }));
         expect(res.toResponse().headers).toEqual({ 'content-type': 'application/json' });
     });
 
     it('should respond to /health', async () => {
-        const res = await handleRequest(req('/health'), null as any, Logger);
+        const res = await handleRequest(req('/health'), null as any, LogConfig.get());
         expect(res.statusDescription).toEqual('ok');
         expect(res.status).toEqual(200);
         expect(res.toResponse().body).toEqual(JSON.stringify({ status: 200, message: 'ok' }));
         expect(res.toResponse().headers).toEqual({ 'content-type': 'application/json' });
     });
 
     it('should respond to /ping', async () => {
-        const res = await handleRequest(req('/ping'), null as any, Logger);
+        const res = await handleRequest(req('/ping'), null as any, LogConfig.get());
         expect(res.statusDescription).toEqual('ok');
         expect(res.status).toEqual(200);
         expect(res.toResponse().body).toEqual(JSON.stringify({ status: 200, message: 'ok' }));

packages/lambda-xyz/src/index.ts

@@ -1,5 +1,11 @@
-import { HttpHeader, LambdaFunction, LambdaHttpResponseAlb, LambdaSession, LambdaType, Logger } from '@basemaps/shared';
-import { Log } from '@cogeotiff/core';
+import {
+    HttpHeader,
+    LambdaFunction,
+    LambdaHttpResponseAlb,
+    LambdaSession,
+    LambdaType,
+    LogType,
+} from '@basemaps/shared';
 import { ALBEvent, Context } from 'aws-lambda';
 import { createHash } from 'crypto';
 import { route } from './router';
@@ -19,11 +25,11 @@ function getHeader(evt: ALBEvent, header: string): string | null {
 export async function handleRequest(
     event: ALBEvent,
     context: Context,
-    logger: typeof Logger,
+    logger: LogType,
 ): Promise<LambdaHttpResponseAlb> {
     const session = LambdaSession.get();
     const tiler = Tilers.tile256;
-    Log.set(logger);
+
     const httpMethod = event.httpMethod.toLowerCase();
 
     session.set('method', httpMethod);

packages/shared/src/__test__/lambda.test.ts

@@ -4,6 +4,8 @@ import { LambdaType } from '../lambda.response.http';
 import { ALBResult, CloudFrontResultResponse } from 'aws-lambda';
 import { HttpHeader } from '../header';
 import { LambdaHttpResponseAlb } from '../lambda.response.alb';
+import { LambdaSession } from '../session';
+import { LogSpy } from './log.spy';
 
 describe('LambdaFunction', () => {
     const DoneError = new Error('Done');
@@ -57,11 +59,23 @@ describe('LambdaFunction', () => {
 
     it('should callback on success', async () => {
         const albOk = new LambdaHttpResponseAlb(200, 'ok');
-        const testFunc = LambdaFunction.wrap(LambdaType.Alb, async () => albOk);
+
+        const testFunc = LambdaFunction.wrap(LambdaType.Alb, async () => {
+            const { timer } = LambdaSession.get();
+            timer.start('xxx');
+            timer.end('xxx');
+            return albOk;
+        });
 
         const cbSpy = jest.fn();
         await testFunc(null as any, null as any, cbSpy);
         expect(cbSpy).toBeCalledTimes(1);
         expect(cbSpy).toBeCalledWith(null, albOk.toResponse());
+
+        expect(LogSpy.mock.calls.length).toBeGreaterThan(1);
+        const lastCall = LogSpy.mock.calls[LogSpy.mock.calls.length - 1];
+        const json = JSON.parse(lastCall[0]);
+        expect(json.duration).toBeGreaterThan(0);
+        expect(json.metrics.xxx).toBeGreaterThan(0);
     });
 });

packages/shared/src/__test__/log.spy.ts

@@ -0,0 +1,7 @@
+import { LogConfig } from '../log';
+
+export const LogSpy = jest.spyOn(LogConfig.getOutputStream(), 'write').mockImplementation();
+
+beforeEach(() => {
+    LogSpy.mockClear();
+});

packages/shared/src/index.ts

@@ -7,7 +7,7 @@ export { LambdaFunction } from './lambda';
 export { LambdaHttpResponseAlb } from './lambda.response.alb';
 export { LambdaHttpResponseCloudFront, LambdaHttpResponseCloudFrontRequest } from './lambda.response.cf';
 export { LambdaHttpResponse, LambdaType } from './lambda.response.http';
-export { Logger } from './log';
+export { LogConfig, LogType } from './log';
 export { getXyzFromPath, PathData } from './path';
 export { Projection } from './projection';
 export { LambdaSession } from './session';

packages/shared/src/lambda.ts

@@ -1,8 +1,7 @@
 import { ALBEvent, ALBResult, Callback, CloudFrontRequestEvent, CloudFrontRequestResult, Context } from 'aws-lambda';
-import * as pino from 'pino';
 import { HttpHeader } from './header';
 import { LambdaHttpResponse, LambdaType } from './lambda.response.http';
-import { Logger } from './log';
+import { LogConfig, LogType } from './log';
 import { LambdaSession } from './session';
 import { LambdaHttp } from './lambda.response';
 import { Const } from './const';
@@ -23,10 +22,10 @@ export class LambdaFunction {
      */
     public static wrap<T extends LambdaHttpRequestType>(
         type: LambdaType,
-        fn: (event: T, context: Context, logger: pino.Logger) => Promise<LambdaHttpResponse>,
-        logger = Logger,
+        fn: (event: T, context: Context, logger: LogType) => Promise<LambdaHttpResponse>,
     ): (event: T, context: Context, callback: Callback<LambdaHttpReturnType>) => Promise<void> {
         return async (event: T, context: Context, callback: Callback<LambdaHttpReturnType>): Promise<void> => {
+            const logger = LogConfig.get();
             // Extract the correlationId from the provided http headers
             const correlationId = LambdaHttp.getHeader(type, event, HttpHeader.CorrelationId);
             const session = LambdaSession.reset(correlationId);
@@ -75,6 +74,7 @@ export class LambdaFunction {
             session.set('duration', duration);
 
             log.info(session.logContext, 'LambdaDone');
+
             // There will always be a response
             callback(null, res.toResponse());
         };

packages/shared/src/log.ts

@@ -1,5 +1,41 @@
 import * as pino from 'pino';
+import { Writable } from 'stream';
 
-// Disable logging while jest is doing it's testing thing
-const isEnabled = process.env['JEST_WORKER_ID'] == null;
-export const Logger = pino({ level: 'debug', enabled: isEnabled });
+let currentLog: pino.Logger;
+
+/**
+ * Expose log type so functions that do not have direct access to pino have access to the log type
+ */
+export type LogType = pino.Logger;
+
+/**
+ * Encapsulate the logger so that it can be swapped out
+ */
+export const LogConfig = {
+    /**
+     * Getting access to the current log stream is hard,
+     *
+     * Pino uses Symbols for all its internal functions,
+     * getting access to them without knowing the logger is a pino logger is difficult
+     *
+     * **Used for testing**
+     * To allow overwriting of the .write() to get access to the output logs
+     */
+    getOutputStream(): Writable {
+        // There are no types for pino.symbols
+        const streamSym = (pino as any).symbols.streamSym;
+        // there is no type for pino['Symbol(stream)']
+        return LogConfig.get()[streamSym] as any;
+    },
+
+    /** Get the currently configured logger */
+    get: (): pino.Logger => {
+        if (currentLog == null) {
+            currentLog = pino({ level: 'debug' });
+        }
+        return currentLog;
+    },
+    set: (log: pino.Logger): void => {
+        currentLog = log;
+    },
+};

packages/shared/src/metrics.ts

@@ -30,23 +30,30 @@ export class Metrics {
      * End the timer, returning the duration in milliseconds
      * @param timeName timer to end
      */
-    public end(timeName: string): bigint {
+    public end(timeName: string): number {
         if (this.timers[timeName] == null) {
             throw new Error(`Missing startTime information for "${timeName}"`);
         }
         const duration = this.getTime() - this.timers[timeName];
         this.time[timeName] = duration;
-        return duration;
+        return Number(duration);
     }
 
-    public get metrics(): Record<string, bigint> | undefined {
+    /**
+     * Convert all the times to Number so that they can be used
+     */
+    public get metrics(): Record<string, number> | undefined {
         const endTimes = Object.keys(this.time);
         // No metrics were started
         if (endTimes.length === 0) {
             return undefined;
         }
+        const output: Record<string, number> = {};
+        for (const key of endTimes) {
+            output[key] = Number(this.time[key]);
+        }
 
-        return this.time;
+        return output;
     }
 
     /** Get a list of timers that never finished */

packages/tiler/src/__test__/tile.benchmark.test.ts

@@ -1,4 +1,4 @@
-import { LambdaSession, Logger } from '@basemaps/shared';
+import { LambdaSession, LogConfig } from '@basemaps/shared';
 import { CogTiff } from '@cogeotiff/core';
 import { CogSourceFile } from '@cogeotiff/source-file';
 import { writeFileSync } from 'fs';
@@ -26,22 +26,26 @@ describe('TileCreationBenchmark', () => {
         timer.end('tiff:init');
 
         timer.start('tiler:tile');
-        const layers = await tiler.tile([tiff], CenterTile, CenterTile, Zoom, Logger);
+        const layers = await tiler.tile([tiff], CenterTile, CenterTile, Zoom, LogConfig.get());
         timer.end('tiler:tile');
 
         if (layers == null) throw new Error('Tile is null');
         await tiler.raster.compose(
             layers,
-            Logger,
+            LogConfig.get(),
         );
     }
-    const results: Record<string, Record<string, bigint[]>> = {};
+    const results: Record<string, Record<string, number[]>> = {};
+
+    beforeEach(() => {
+        jest.spyOn(LogConfig.getOutputStream(), 'write').mockImplementation();
+    });
 
     [256, 512].forEach(tileSize => {
         it(`should render ${RenderCount}x${tileSize} tiles`, async () => {
             jest.setTimeout(TimeoutSeconds);
 
-            const metrics: Record<string, bigint[]> = {};
+            const metrics: Record<string, number[]> = {};
 
             for (let i = 0; i < RenderCount; i++) {
                 const { timer } = LambdaSession.reset();
@@ -56,7 +60,7 @@ describe('TileCreationBenchmark', () => {
                 }
                 for (const key of Object.keys(m)) {
                     const arr = (metrics[key] = metrics[key] || []);
-                    arr.push(m[key]);
+                    arr.push(Number(m[key]));
                 }
             }
 
@@ -65,13 +69,13 @@ describe('TileCreationBenchmark', () => {
     });
 
     /** Compute the average for the result */
-    function computeStats(records: Record<string, bigint[]>): Record<string, number> {
+    function computeStats(records: Record<string, number[]>): Record<string, number> {
         const output: Record<string, number> = {};
         for (const key of Object.keys(records)) {
             const values = records[key];
             let total = 0;
             for (const val of values) {
-                total += Number(val) / NanoSecondToMillisecond;
+                total += val / NanoSecondToMillisecond;
             }
 
             output[key] = parseFloat((total / values.length).toFixed(3));