fix(lambda-tiler): correctly log fetch requests (#3359)

### Motivation

Requests tracing has been broken for a while (not entire sure when it
broke)

It is very very helpful to have statistics on the number of s3 requests
required to make a tile

### Modifications

- `requestCount` is reserved for the number of lambda invocations so
move to `fetchCount` for number of fetches
- include the fetchIds to trace hot fetches
- increase the percent of requests with tracing enabled
- Use async local storage to gain access to the logger for the request
that triggers the log message, this fixes a bug where the request may be
in `trace` but the fetch is using the base logger which is set to `info`
so no logs are generated.


### Verification

Ran locally and verified logs are now appearing.

<!-- TODO: Say how you tested your changes. -->

---------

Co-authored-by: Wentao Kuang <[email protected]>

packages/lambda-tiler/src/index.ts

@@ -1,4 +1,4 @@
-import { FsaCache, FsaLog, LogConfig } from '@basemaps/shared';
+import { FsaCache, FsaLog, LogConfig, LogStorage } from '@basemaps/shared';
 import { LambdaHttpRequest, LambdaHttpResponse, lf } from '@linzjs/lambda';
 
 import { tileAttributionGet } from './routes/attribution.js';
@@ -34,13 +34,14 @@ function randomTrace(req: LambdaHttpRequest): void {
   const rand = Math.random();
   // 1% trace
   if (rand < 0.01) req.log.level = 'trace';
-  // 5% debug
-  else if (rand < 0.04) req.log.level = 'debug';
+  // 25% debug
+  else if (rand < 0.25) req.log.level = 'debug';
   // everything else info
   else req.log.level = 'info';
 }
 
 handler.router.hook('request', (req) => {
+  LogStorage.enterWith({ log: req.log });
   FsaLog.reset();
 
   randomTrace(req);
@@ -49,7 +50,8 @@ handler.router.hook('request', (req) => {
 });
 
 handler.router.hook('response', (req, res) => {
-  req.set('requestCount', FsaLog.requests.length);
+  req.set('fetchCount', FsaLog.count);
+  req.set('fetches', FsaLog.requests);
   req.set('cacheSize', FsaCache.size);
   // Force access-control-allow-origin to everything
   res.header('access-control-allow-origin', '*');

packages/shared/src/file.system.ts

@@ -45,7 +45,7 @@ applyS3MiddleWare(s3Fs);
 const credentials = new AwsS3CredentialProvider();
 
 credentials.onFileSystemCreated = (acc: AwsCredentialConfig, fs: FileSystem): void => {
-  LogConfig.get().debug({ prefix: acc.prefix, roleArn: acc.roleArn }, 'FileSystem:Register');
+  LogConfig.get().info({ prefix: acc.prefix, roleArn: acc.roleArn }, 'FileSystem:Register');
   applyS3MiddleWare(fs as FsAwsS3);
   fsa.register(acc.prefix, fs);
 };
@@ -81,9 +81,10 @@ export const FsaLog = {
     this.requests.push(requestId);
     const startTime = performance.now();
     const res = await next(req);
-    LogConfig.get().trace(
+    LogConfig.get().debug(
       {
         source: req.source.url.href,
+        sourceHost: req.source.url.hostname,
         offset: req.offset,
         length: req.length,
         requestId,

packages/shared/src/index.ts

@@ -8,7 +8,7 @@ export { ConfigProviderDynamo } from './dynamo/dynamo.config.js';
 export { Fsa as fsa, FsaCache, FsaChunk, FsaLog, stringToUrlFolder, urlToString } from './file.system.js';
 export { Fqdn } from './file.system.middleware.js';
 export { getImageryCenterZoom, getPreviewQuery, getPreviewUrl, PreviewSize } from './imagery.url.js';
-export { LogConfig, LogType } from './log.js';
+export { LogConfig, LogStorage, LogType } from './log.js';
 export { LoggerFatalError } from './logger.fatal.error.js';
 export { toQueryString } from './url.js';
 export * from './util.js';

packages/shared/src/log.ts

@@ -1,3 +1,5 @@
+import { AsyncLocalStorage } from 'node:async_hooks';
+
 import pino from 'pino';
 import { PrettyTransform } from 'pretty-json-log';
 
@@ -29,6 +31,11 @@ const defaultOpts = { level: 'debug' };
 export const LogConfig = {
   /** Get the currently configured logger */
   get(): LogType {
+    // If this .get() is called inside a async function eg a HTTP request
+    // use the logger from the async context if it has one
+    const localStorage = LogStorage.getStore()?.log;
+    if (localStorage) return localStorage;
+
     if (currentLog == null) {
       currentLog = process.stdout.isTTY
         ? pino.default(defaultOpts, PrettyTransform.stream())
@@ -46,3 +53,5 @@ export const LogConfig = {
     LogConfig.get().level = 'silent';
   },
 };
+
+export const LogStorage = new AsyncLocalStorage<{ log: LogType }>();