resmed-http-log-starter-loopback

v0.1.5

Published

4 months ago

Log formatting library for Express/Loopback applications

0High
0Medium
0Low

Overview

This library is used to log and format HTTP logs from Loopback applications, according to the standards outlined in the ResMed Application Logging Format v1.0. The logs will be sent to Datadog, and automatic trace correlation and parent-child span relationship maintenance amongst logs will occur, for every unique operation. This library uses the Winston logger as the underlying logger in which to log to Datadog, and dd-trace as the underlying tracer.

Definition

The concepts and terminology used in this library are borrowed from the Open Telemetry project (formerly Open Tracing).

Trace - A trace is a logical grouping of spans. The idea is to follow an operation through a distributed system end-to-end.
Span - A span is a unit of work within a distributed system. A parent span relationship is identified to maintain a hierarchy of spans

Installation

Run the following to add the dependency to your application:

npm install resmed-http-log-starter-loopback

Usage guide

Set up the AxiosInterceptor and LogEnricher, at the start of the file where you want the logs formatted:

import { get, RestBindings } from '@loopback/rest';  // Import LoopBack decorators and bindings
import { setupAxiosInterceptors } from 'resmed-http-log-starter-loopback'; // Import your AxiosInterceptor
import { LogEnricher } from 'resmed-http-log-starter-loopback';  // Import your LogEnricher

setupAxiosInterceptors();

export class LoggingController {
  private logEnricher: LogEnricher;

  constructor(
      @inject(RestBindings.Http.REQUEST) private request: any,
  ) {
    this.logEnricher = new LogEnricher();  // Create an instance of LogEnricher
  }
  
  //Endpoints for the controller
}

AxiosInterceptor
- Component that will intercept http requests, and if an active span exists (i.e. a parent process exists), it will set x-rmd-trace-id and x-parent-span-id headers to the request. Required for proper parent-child span relation propagation to subsequent sub-requests.
LogEnricher
- Component which will be used as the main logger utility, handling both formatting and actual logging to Datadog.

Set up the traceLoggingMiddleware in your sequence.ts file:

import { MiddlewareSequence, RequestContext } from '@loopback/rest';
import { traceLoggingMiddleware } from 'resmed-http-log-starter-loopback';  // Use middleware from resmed-log-core-ts

export class MySequence extends MiddlewareSequence {
    async handle(context: RequestContext) {  // Explicitly set type of context to RequestContext
        const { request, response } = context;

        // Call the trace logging middleware without returning a promise in the next() callback
        await traceLoggingMiddleware(['/ping'])(request, response, () => {
            super.handle(context);  // Just call the next handler without returning a promise
        });
    }
}

TraceLoggingMiddleware
- Middleware component which will trigger on requests and responses in the HTTP request lifecycle. This will generate the proper logs associated with requests and responses (for each entrypoint). It will also maintain parent child span relationships across processes of a single, unique operation.
- You may pass in a list of endpoints which you do not want this middleware to trigger on.
  - An example of this could be the endpoint called by your EKS http and health probes, which are unrelated to the core functionality of your application, but still can trigger the middleware as part of the infrastructure the app is run on.

Expected Output

As an example, suppose an operation requires a series of http requests to be made:

/outer-span ---calls---> /inner-span ---calls---> /log

@get('/outer-span')
  async logSpans() {
  this.logEnricher.log('info', 'outer-span'); //This runs first
  const response = await axios.get('http://127.0.0.1:3000/inner-span');
  this.logEnricher.log('info', 'Finished calling outer-span');  //This runs last
  
  return { response: response.data };
}

@get('/inner-span')
  async innerSpan() {
  this.logEnricher.log('warn', 'inner-span'); //This runs second
  const response = await axios.get('http://127.0.0.1:3000/log');
  return { response: response.data };
}

@get('/log')
  async log() {
  this.logEnricher.log('info', `log`); //This runs third
  return {};
}

Notice the use of the imported LogEnricher component as the logger utility.

Once the application is configured according to the Usage Guide, all http requests and responses processed by your application will be intercepted.

Once an http request is intercepted, the interceptor will set up a trace and a new span. If the http client sent an x-rmd-trace-id header with a value, then the trace is set up with the same trace identifier (thereby, extending the trace to this process). If the header is not supplied, then the trace is set up with a new trace identifier.

A new span is set up regardless. The span is scoped to the current process only.

Upon intercepting the http request, the trace captures/generates the following details.

traceId
spanId
spanName
requestMethod
requestUri
headers

Once an http response for the above http request is intercepted, the current span is ended and the tracer object will log that the span ended. The following properties are then captured/generated in addition to the properties captured from the http request.

responseCode
responseSize
responseTime

Example log outputs

The log entries below are generated from a single http request to the /outer-span endpoint of the application, which kicks off a series of chaining http requests to child endpoints.

Initial HTTP request logs to /outer-span

{"creationDateTime":"2024-09-26T19:58:57.022Z","headers":{"accept":"text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.7","accept-encoding":"gzip,deflate, br, zstd",
  "accept-language":"en-US,en;q=0.9","connection":"keep-alive","host":"127.0.0.1:3000","sec-ch-ua":"\"Google Chrome\";v=\"129\", \"Not=A?Brand\";v=\"8\", \"Chromium\";v=\"129\"","sec-ch-ua-mobile":"?0","sec-ch-ua-platform":"\"Windows\"",
  "sec-fetch-dest":"document","sec-fetch-mode":"navigate","sec-fetch-site":"none","sec-fetch-user":"?1","upgrade-insecure-requests":"1","user-agent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/129.0.0.0 Safari/537.36"},
  "level":"info","message":"Request Headers","schemaId":"1.0.0","spanId":"4581064183778673141","spanName":"incoming http request","traceId":"4581064183778673141"}
{"creationDateTime":"2024-09-26T19:58:57.023Z","level":"info","message":"Request","requestMethod":"GET","requestUri":"/outer-span","schemaId":"1.0.0","spanId":"4581064183778673141","spanName":"incoming http request","traceId":"4581064183778673141"}
{"creationDateTime":"2024-09-26T19:58:57.025Z","level":"info","message":"outer-span","schemaId":"1.0.0","spanId":"4581064183778673141","spanName":"incoming http request","traceId":"4581064183778673141"}

The Request Headers and Request come in first, then the log message from /outer-span is logged. All logs are enriched with the required fields outlined by the ResMed standard.
Notice that parentSpanId doesn't exist yet, since this request is the topmost in the span hierarchy.

Subsequent request logs from /outer-span to /inner-span

{"creationDateTime":"2024-09-26T19:58:57.044Z","headers":{"accept":"application/json, text/plain, */*","accept-encoding":"gzip, compress, deflate, br","connection":"close","host":"127.0.0.1:3000", "traceparent":"00-66f5bd01000000003f93359a876481f5-072ea2e0a24fd701-01",
  "tracestate":"dd=t.dm:-0;t.tid:66f5bd0100000000;s:1;p:072ea2e0a24fd701","user-agent":"axios/1.7.7","x-datadog-parent-id":"517530092873701121","x-datadog-sampling-priority":"1","x-datadog-tags":"_dd.p.tid=66f5bd0100000000,_dd.p.dm=-0","x-datadog-trace-id":"4581064183778673141", 
  "x-parent-span-id":"4581064183778673141","x-rmd-trace-id":"4581064183778673141"},"level":"info","message":"Request Headers","parentSpanId":"4581064183778673141","schemaId":"1.0.0","spanId":"3619609428626353998","spanName":"incoming http request","traceId":"4581064183778673141"}
{"creationDateTime":"2024-09-26T19:58:57.046Z","level":"info","message":"Request", "parentSpanId":"4581064183778673141","requestMethod":"GET","requestUri":"/inner-span", "schemaId":"1.0.0", "spanId":"3619609428626353998","spanName": "incoming http request", "traceId":"4581064183778673141"}
{"creationDateTime":"2024-09-26T19:58:57.049Z","level":"warn","message":"inner-span","parentSpanId":"4581064183778673141","schemaId":"1.0.0","spanId":"3619609428626353998","spanName":"incoming http request","traceId":"4581064183778673141"}

Notice here that the x-rmd-trace-id and x-parent-span-id headers are set. This was set by the AxiosInterceptor, since now the tracer has context on the parent span's traceId and spanId.
The parentSpanId (which is equal to the spanId of the parent span) is now added to the log, and a new spanId is generated. The traceId remains the same, since it's still part of the same overall operation.

Subsequent request logs from /inner-span to /log

{"creationDateTime":"2024-09-26T19:58:57.059Z","headers":{"accept":"application/json, text/plain, */*","accept-encoding":"gzip, compress, deflate, br", "connection":"close","host":"127.0.0.1:3000","traceparent":"00-66f5bd01000000003f93359a876481f5-552fbbffc5229168-01",
  "tracestate":"dd=t.dm:-0;t.tid:66f5bd0100000000;s:1;p:552fbbffc5229168","user-agent":"axios/1.7.7","x-datadog-parent-id":"6138331524327706984","x-datadog-sampling-priority":"1", "x-datadog-tags":"_dd.p.tid=66f5bd0100000000,_dd.p.dm=-0","x-datadog-trace-id":"4581064183778673141",
  "x-parent-span-id":"3619609428626353998","x-rmd-trace-id":"4581064183778673141"},"level":"info","message":"Request Headers","parentSpanId":"3619609428626353998","schemaId":"1.0.0", "spanId":"8469547191467029156","spanName":"incoming http request","traceId":"4581064183778673141"}
{"creationDateTime":"2024-09-26T19:58:57.060Z","level":"info","message":"Request","parentSpanId":"3619609428626353998","requestMethod":"GET","requestUri":"/log","schemaId":"1.0.0","spanId":"8469547191467029156","spanName":"incoming http request","traceId":"4581064183778673141"}
{"creationDateTime":"2024-09-26T19:58:57.062Z","level":"info","message":"log","parentSpanId":"3619609428626353998","schemaId":"1.0.0","spanId":"8469547191467029156","spanName":"incoming http request","traceId":"4581064183778673141"}

Similar to the previous chain of logs, the parentSpanId (spanId of /inner-span) is set here, and a new spanId is generated. The traceId still remains the same as the very first span.

Response logs from /log

{"creationDateTime":"2024-09-26T19:58:57.064Z","headers":{"access-control-allow-credentials":"true","access-control-allow-origin":"*","content-type":"application/json","x-powered-by":"Express"},"level":"info","message":"ResponseHeaders","parentSpanId":"3619609428626353998","schemaId":"1.0.0","spanId":"8469547191467029156",
  "spanName":"incoming http request","traceId":"4581064183778673141"}
{"creationDateTime":"2024-09-26T19:58:57.065Z","level":"info","message":"Response","parentSpanId":"3619609428626353998","requestMethod":"GET","requestUri":"/log","responseCode":200,"responseSize":2,"responseTime":6,"schemaId":"1.0.0","spanId":"8469547191467029156","spanName":"incoming http request","traceId":"4581064183778673141"}

Since the entire chain of requests ends at /log, the response from /log is now logged, with the required fields.

Subsequent response logs from /inner-span

{"creationDateTime":"2024-09-26T19:58:57.075Z","headers":{"access-control-allow-credentials":"true","access-control-allow-origin":"*","content-type":"application/json","x-powered-by":"Express"},"level":"info","message":"ResponseHeaders","parentSpanId":"4581064183778673141","schemaId":"1.0.0","spanId":"3619609428626353998",
  "spanName":"incoming http request","traceId":"4581064183778673141"}
{"creationDateTime":"2024-09-26T19:58:57.076Z","level":"info","message":"Response","parentSpanId":"4581064183778673141","requestMethod":"GET","requestUri":"/inner-span","responseCode":200,"responseSize":15,"responseTime":32,"schemaId":"1.0.0","spanId":"3619609428626353998","spanName":"incoming http request","traceId":"4581064183778673141"}

Response from /inner-span are now logged, since its child process /log has finished responding.

Final response logs from /outer-span

{"creationDateTime":"2024-09-26T19:58:57.079Z","level":"info","message":"Finished calling outer-span","schemaId":"1.0.0","spanId":"4581064183778673141","spanName":"incoming http request","traceId":"4581064183778673141"}
{"creationDateTime":"2024-09-26T19:58:57.081Z","headers":{"access-control-allow-credentials":"true","access-control-allow-origin":"*","content-type":"application/json","x-powered-by":"Express"},"level":"info","message":"ResponseHeaders","schemaId":"1.0.0","spanId":"4581064183778673141",
  "spanName":"incoming http request","traceId":"4581064183778673141"}
{"creationDateTime":"2024-09-26T19:58:57.082Z","level":"info","message":"Response","requestMethod":"GET","requestUri":"/outer-span","responseCode":200,"responseSize":28,"responseTime":60,"schemaId":"1.0.0","spanId":"4581064183778673141","spanName":"incoming http request","traceId":"4581064183778673141"}

The first log here corresponds to the log message called in /outer-span after the /inner-span is done processing.
The last two logs are the response logs from /outer-span, the topmost span in the hierarchy.
This marks the end of the full trace of this particular chain of http requests.

View in Datadog

Each log message will be associated with a trace in datadog in the APM section. All the logs for a trace can be seen and the trace associated with a log can be navigated.

The following shows the Datadog output from the above example, an http request to the /outer-span endpoint: Example Trace Example Trace 2 Example Trace 3

Published

Vulnerabilities

Links

Maintainers

Keywords

Readme