feat: add spanId to all logs, add tests for traceId and spanId check (#69)

Author: goshander

package-lock.json

@@ -26,7 +26,7 @@
     "@commitlint/cli": "^17.7.1",
     "@commitlint/config-conventional": "^17.7.0",
     "@gravity-ui/eslint-config": "^3.2.0",
-    "@gravity-ui/nodekit": "^2.0.0",
+    "@gravity-ui/nodekit": "^2.4.1",
     "@gravity-ui/prettier-config": "^1.1.0",
     "@gravity-ui/tsconfig": "^1.0.0",
     "@types/accept-language-parser": "^1.5.6",

package.json

@@ -43,7 +43,6 @@ export function setupBaseMiddleware(ctx: AppContext, expressApp: Express) {
             const traceId = req.ctx.getTraceId();
             if (traceId) {
                 res.setHeader('x-trace-id', traceId);
-                req.ctx.addLoggerExtra('traceId', traceId);
             }
 
             req.ctx.addLoggerExtra('req', {
@@ -55,7 +54,6 @@ export function setupBaseMiddleware(ctx: AppContext, expressApp: Express) {
             const requestStartedExtra = ctx.config.appDevMode
                 ? {req: {url: ctx.utils.redactSensitiveQueryParams(req.url)}}
                 : {
-                      traceId,
                       req: {
                           id: requestId,
                           method: req.method,
@@ -74,7 +72,6 @@ export function setupBaseMiddleware(ctx: AppContext, expressApp: Express) {
                 const responseExtra = ctx.config.appDevMode
                     ? {res: {responseTime, statusCode}}
                     : {
-                          traceId,
                           res: {
                               responseTime,
                               statusCode,

src/base-middleware.ts

@@ -3,14 +3,27 @@ import {DEFAULT_REQUEST_ID_HEADER} from '../constants';
 import {NodeKit} from '@gravity-ui/nodekit';
 import request from 'supertest';
 
+const genRandomId = (length = 16) => {
+    return [...Array(length)].map(() => Math.floor(Math.random() * 16).toString(16)).join('');
+};
+
 const APP_NAME = 'app';
+const USER_AGENT_HEADER = 'user-agent';
+const UBER_TRACE_ID_KEY = 'uber-trace-id';
+const X_TRACE_ID_KEY = 'x-trace-id';
 
 const setupApp = () => {
     const logger = {
         write: jest.fn(),
     };
 
-    const nodekit = new NodeKit({config: {appLoggingDestination: logger, appName: 'app'}});
+    const nodekit = new NodeKit({
+        config: {
+            appLoggingDestination: logger,
+            appName: APP_NAME,
+            appTracingEnabled: true,
+        },
+    });
     const routes = {
         'GET /get': {
             handler: (_: Request, res: Response) => {
@@ -69,7 +82,7 @@ describe('log system', () => {
         await agent
             .get('/get')
             .set(DEFAULT_REQUEST_ID_HEADER, requestId)
-            .set('user-agent', userAgent);
+            .set(USER_AGENT_HEADER, userAgent);
 
         // last log with response
         let log = JSON.parse(logger.write.mock.calls?.pop() || '{}');
@@ -127,7 +140,7 @@ describe('log system', () => {
         await agent
             .post('/post')
             .set(DEFAULT_REQUEST_ID_HEADER, requestId)
-            .set('user-agent', userAgent);
+            .set(USER_AGENT_HEADER, userAgent);
 
         // last log with response
         let log = JSON.parse(logger.write.mock.calls?.pop() || '{}');
@@ -271,4 +284,76 @@ describe('log system', () => {
             },
         });
     });
+
+    it('log should contain traceId and spanId', async () => {
+        const {app, logger} = setupApp();
+
+        const agent = request.agent(app.express);
+
+        const requestId = Math.random().toString();
+        const userAgent = 'user-agent-' + Math.random().toString();
+
+        const traceId = genRandomId(32);
+        const spanId = genRandomId(16);
+        const traceFlags = '01';
+        const uberTraceId = `${traceId}:${spanId}:0:${traceFlags}`;
+
+        await agent
+            .get('/get')
+            .set(DEFAULT_REQUEST_ID_HEADER, requestId)
+            .set(USER_AGENT_HEADER, userAgent)
+            .set(UBER_TRACE_ID_KEY, uberTraceId);
+
+        // last log with response
+        let log = JSON.parse(logger.write.mock.calls?.pop() || '{}');
+
+        // check response log
+        expect(log).toMatchObject({
+            msg: `[Express GET] Request completed [${requestId}]`,
+            level: 30,
+            name: APP_NAME,
+            time: expect.any(Number),
+            traceId,
+            req: {
+                id: requestId,
+                method: 'GET',
+                url: '/get',
+            },
+            res: {
+                statusCode: '200',
+                responseTime: expect.any(Number),
+                headers: {
+                    [DEFAULT_REQUEST_ID_HEADER]: requestId,
+                    [X_TRACE_ID_KEY]: traceId,
+                },
+            },
+        });
+
+        expect(log?.spanId).toBeTruthy();
+
+        // first log with request
+        log = JSON.parse(logger.write.mock.calls?.pop() || '{}');
+
+        // check request log
+        expect(log).toMatchObject({
+            msg: `[Express GET] Request started [${requestId}]`,
+            level: 30,
+            name: APP_NAME,
+            time: expect.any(Number),
+            traceId,
+            req: {
+                id: requestId,
+                method: 'GET',
+                url: '/get',
+                headers: {
+                    [DEFAULT_REQUEST_ID_HEADER]: requestId,
+                    [UBER_TRACE_ID_KEY]: uberTraceId,
+                },
+                remoteAddress: expect.any(String),
+                remotePort: expect.any(Number),
+            },
+        });
+
+        expect(log?.spanId).toBeTruthy();
+    });
 });