

![Hero](/images/asynclocalstorage-logs-nestjs/hero.png)

Logging is invaluable in backend services. Structured logging makes logs more useful by enabling you to categorize, analyze and search logs effectively. Sadly though, setting up structured logging correctly is difficult, especially in dependency injection-oriented frameworks such as [Nest.js](https://nestjs.com/).

This blog post is code-snippet heavy. It's the most succinct way to convey the problem I'm trying to solve, so prepare to read a lot of code.

Consider the following `AuthService` that validates a user's credentials and logs information using a hypothetical `StructuredLogger`:

```typescript
@Injectable()
class AuthService {
  constructor(
    private readonly logger: StructuredLogger,
    private readonly auth0: Auth0Service
  ) {}

  validate = async (creds: Credentials): Promise<string | Error> => {
    this.logger.info({ ...creds }, "Validating credentials");

    const result = await checkCredentials(creds);
    if (!result.success) {
      this.logger.error({ error: result.error }, "Invalid credentials");
      return result.error;
    }

    this.logger.info("Credentials valid");
    return result.accessToken;
  };
}
```

The `validate` method produces the following log statment whenever it runs:

```
[2021-07-11 06:56:49.574 +0000] INFO: Validating credentials
    username: "johndoe"
    scopes: [
      "offline profile email"
    ]
    redirectUrl: "https://example.com/auth/redirect"
```

It is useful because it contains the arguments passed to the `validate` method. A clever log parser can then process this line to separate the log message (_"Validating credentials"_) and the log metadata (_username, scopes, redirectUrl_) to produce clean logs.

## Context of Execution

While the above log statement is alright, it can be better. A key piece of information missing from it is its context of execution, such as the name of the service and the method that produced it, as well as the ID of incoming request that triggered the service.

### Service Name

It's easy to add the name of the service to the logger. Most logging packages support extending a parent logger with some default metadata that is appended to every log line. Therefore we can inject a common base logger, and extend it inside our service's constructor with the service name.

```typescript
@Injectable()
class AuthService {
  private readonly logger: StructuredLogger;

  constructor(
    baseLogger: StructuredLogger,
    private readonly auth0: Auth0Service
  ) {
    this.logger = baseLogger.child({ serviceName: AuthService.name });
  }

  validate = async (creds: Credentials) => {
    this.logger.info({ ...creds }, "Validating credentials");
    // ...
  };
}
```

Now the same log statement includes the service name as well:

```
[2021-07-11 06:56:49.574 +0000] INFO: Validating credentials
    serviceName: "AuthService"
    username: "johndoe"
    scopes: [
      "offline profile email"
    ]
    redirectUrl: "https://example.com/auth/redirect"
```

### Method Name

You can extend the service's logger inside every method to append the `methodName` property to the logger's metadata:

```typescript
validate = async (creds: Credentials) => {
  const methodLogger = this.logger.child({ methodName: "validate" });
  this.logger.info({ ...creds }, "Validating credentials");
  // ...
};
```

Now the same log line contains the `methodName` attribute as well:

```
[2021-07-11 06:56:49.574 +0000] INFO: Validating credentials
    serviceName: "AuthService"
    methodName: "validate"
    username: "johndoe"
    scopes: [
      "offline profile email"
    ]
    redirectUrl: "https://example.com/auth/redirect"
```

### Request ID

The ID of a request is typically contained inside the `x-request-id` header in an incoming request. Therefore, the simplest way of adding it to the logs is to pass the incoming request to the `validate` method, and let it extend its parent logger with a `requestId`.

```typescript
validate = async (creds: Credentials, req: Request) => {
  const requestId = req.headers["x-request-id"];
  const correlationId = req.headers["x-correlation-id"];
  const methodLogger = this.logger.child({
    methodName: "validate",
    reqId: requestId,
    cid: correlationId,
  });
  // ...
};
```

Now the logs include the request ID too:

```
[2021-07-11 06:56:49.574 +0000] INFO: Validating credentials
    serviceName: "AuthService"
    methodName: "validate"
    reqId: "4d426f0a-cf13-47de-a824-f98d98ff7e83"
    cid: "fa38e3d4-6fc0-4bd6-b5cd-cb9f43f994f8"
    username: "johndoe"
    scopes: [
      "offline profile email"
    ]
    redirectUrl: "https://example.com/auth/redirect"
```

It works, _but not really_.

1. It pollutes the signature of the `validate` method, which should only be concerned with the credentials argument.
2. It makes `AuthService` harder to test, as now every test must stub or mock the `req` parameter when testing the `validate` method.
3. It's terribly inconvenient. Extending a logger at every step of execution is a fragile process, and someone on your team can easily forget to do so.

## Injecting a Customized Logger

An alternative solution to this problem is to inject a customized logger using Nest.js that is scoped to a request:

```typescript
export const LoggerProvider: Provider<StructuredLogger> = {
  provide: StructuredLogger,
  scope: Scope.REQUEST,
  useFactory: () => new StructuredLogger(),
};
```

You might be able to do some [ExecutionContext](https://docs.nestjs.com/fundamentals/execution-context) magic and inject a request's ID into this logger, but I'm not sure how. Either way, this solution has the following problems:

1. You're forced to inject a logger instance, even though loggers should be created and destroyed freely.
2. This provider is limited to a _Request Scope_, which means it is recreated on every request. It implies that any service or controller that depends on this provider will **also be request scoped**, regardless of any explicitly specified scope, thus causing needless object allocations on every request.

## Enter: `AsyncLocalStorage`

[`AsyncLocalStorage`](https://nodejs.org/api/async_context.html#async_context_class_asynclocalstorage) is a feature introduced in Node v14 as a part of the `async_hooks` package. It allows you to access an implicitly passed object anywhere in an asynchronous call chain. Its canonical use case is to keep a track of a request ID throughout the request's lifetime.

> While the `async_hooks` API is unstable, the `AsyncLocalStorage` class is considered stable in Node.js. It has been backported to Node.js v12 too.

### Middleware

You can create a functional middleware to create a request context for every incoming request with `AsyncLocalStorage`.

- First, define a global store for storing contexts of every incoming request:

```typescript
interface RequestContext {
  [key: string]: string;
}

const globalStore = new AsyncLocalStorage<RequestContext>();
```

- Then create a couple of convenience methods that enable wrapping a request with a context and accessing that context within the request:

```typescript
// Allows easy access to a request's context
const ctx = (): RequestContext => {
  const context = globalStore.getStore();
  if (!context) {
    throw new NoContextError("No context attached to the current req");
  }
  return context;
};

// Allows wrapping a request in a context
const runWithCtx = (
  fx: (ctx: RequestContext) => Promise<unknown>,
  context: RequestContext = {}
) => {
  globalStore.run(context, () => {
    return fx(ctx());
  });
};
```

- Then create a Nest Functional Middleware that wraps every request in a context:

```typescript
const withContext = (_req: Request, _res: Response, next: NextFunction) => {
  runWithCtx(() => next(), {});
};
```

- Then create a middleware that stores a request's `x-request-id` and `x-correlation-id` headers in the request context:

```typescript
const withRequestId = (req: Request, _res: Response, next: NextFunction) => {
  const context = ctx();
  context.correlationID = req.headers["x-correlation-id"];
  context.requestID = req.headers["x-request-id"];
  return next();
};
```

- Finally, apply the `withContext` and `withRequestId` middleware as early as possible in the Nest application's middleware chain. Ensure that `withContext` executes before `withRequestId`:

```typescript
async function main() {
  const app = await NestFactory.create(AppModule);
  app.useLogger(withContext, withRequestId);
  await app.listen(3000);
}
```

With this setup complete, you can now access the request context implicitly inside any service or controller. I recommend creating a logger factory method to automatically initialize a logger with such details:

```typescript
const createLogger = (
  serviceName: string,
  methodName: string
): StructuredLogger => {
  const context = ctx();
  const { requestId, correlationId } = context;
  const baseLogger = new StructuredLogger();
  const customizedLogger = baseLogger.child({
    serviceName,
    methodName,
    requestId,
    correlationId,
  });
  return customizedLogger;
};
```

### Usage

The `createLogger` method greatly simplifies the logging setup in `AuthService`:

```typescript
@Injectable()
class AuthService {
  constructor(private readonly auth0: Auth0Service) {}

  validate = async (creds: Credentials): Promise<string | Error> => {
    const logger = createLogger(AuthService.name, "validate");
    logger.info({ ...creds }, "Validating credentials");

    const result = await checkCredentials(creds);
    if (!result.success) {
      logger.error({ error: result.error }, "Invalid credentials");
      return result.error;
    }

    logger.info("Credentials valid");
    return result.accessToken;
  };
}
```

1. You no longer need a `logger` parameter in the constructor.
2. The `createLogger` method simplifies extending a base logger with metadata.
3. Since the logger is not a class property anymore, you don't need to access it with `this.logger`.

## Performance Caveat

I like this log setup, but as with everything else in programming, it's a compromise. `AsyncLocalStorage` has a non-negotiable performance hit. It's quite small, but measurable. Make sure to benchmark your setup to check if the convenience is worth the performance penalty.

Here are the results from a rudimentary benchmark for an endpoint that returns _"Hello world!"_ to every request, using the [Apache Benchmarking tool](https://httpd.apache.org/docs/2.4/programs/ab.html). I ran the test on an Apple M1 MacBook Air running Node v16.1.0.

![Request Throughput](/images/asynclocalstorage-logs-nestjs/req-per-sec.svg)
![Request Latency](/images/asynclocalstorage-logs-nestjs/mean-time-per-req.svg)

- Without `AsyncLocalStorage` middlware:

```shell
$ ab -n 1000 -c 100 localhost:3000/greet

Server Software:
Server Hostname:        localhost
Server Port:            3000

Document Path:          /greet
Document Length:        13 bytes

Concurrency Level:      100
Time taken for tests:   0.201 seconds
Complete requests:      1000
Failed requests:        0
Total transferred:      212000 bytes
HTML transferred:       13000 bytes
Requests per second:    4965.98 [#/sec] (mean)
Time per request:       20.137 [ms] (mean)
Time per request:       0.201 [ms] (mean, across all concurrent requests)
Transfer rate:          1028.11 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    1   1.0      0       3
Processing:     5   19   5.8     18      33
Waiting:        2   11   4.5     11      29
Total:          5   20   6.4     18      35
WARNING: The median and mean for the initial connection time are not within a normal deviation
        These results are probably not that reliable.

Percentage of the requests served within a certain time (ms)
  50%     18
  66%     21
  75%     22
  80%     25
  90%     29
  95%     35
  98%     35
  99%     35
 100%     35 (longest request)
```

- With `AsyncLocalStorage` middlware:

```shell
$ ab -n 1000 -c 100 localhost:3000/greet

Server Software:
Server Hostname:        localhost
Server Port:            3000

Document Path:          /greet
Document Length:        13 bytes

Concurrency Level:      100
Time taken for tests:   0.219 seconds
Complete requests:      1000
Failed requests:        0
Total transferred:      382000 bytes
HTML transferred:       13000 bytes
Requests per second:    4565.08 [#/sec] (mean)
Time per request:       21.905 [ms] (mean)
Time per request:       0.219 [ms] (mean, across all concurrent requests)
Transfer rate:          1702.99 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    1   1.1      2       4
Processing:     4   19   8.4     17      41
Waiting:        3   11   6.2     10      38
Total:          5   20   8.9     18      43

Percentage of the requests served within a certain time (ms)
  50%     18
  66%     21
  75%     21
  80%     26
  90%     41
  95%     42
  98%     42
  99%     42
 100%     43 (longest request)
```

4965.98 vs 4565.08 requests per second. I think I can take a loss of 400 requests per second for the added convenience, but you should decide what works for you based on your usecase.


Using request context for more detailed logs

haroldadmin

# JavaScript