Trace Ids not added on uncaught exceptions - ecsFormat()?

[alexsanderp]

Trace Ids not added on uncaught exceptions?

When using ECSFormat with winston I don't have TraceIds (transaction.id e etc...) information in uncaught Exceptions. https://github.com/elastic/ecs-logging-nodejs/issues/124

import { createLogger, format, transports } from 'winston';
import ecsFormat from '@elastic/ecs-winston-format';

const consoleOptions = {
    level: 'info',
    handleExceptions: true,
    format: ecsFormat(),
};

const consoleTransport = new transports.Console(consoleOptions);

const logger = createLogger({
    exitOnError: true,
    transports: [
        consoleTransport,
    ]
});

INFO:

{"@timestamp":"2022-05-27T19:10:13.556Z","log.level":"info","message":"testing info with winston logger","ecs":{"version":"1.6.0"},"event":{"dataset":"example_normal.log"},"trace":{"id":"e477cd64384c8c0f78cc00787ee622d4"},"transaction":{"id":"8c9cc366b48425c0"},"service":{"name":"example_normal","environment":"local"},"test2":"test2"}

UNCAUGHT EXCEPTION:

{"@timestamp":"2022-05-27T19:10:13.563Z","log.level":"error","message":"uncaughtException: a is not defined\nReferenceError: a is not defined\n    at file:///home/user/code/logs-nodejs-lib/examples/example_normal.js:19:1\n    at ModuleJob.run (node:internal/modules/esm/module_job:195:25)\n    at async Promise.all (index 0)\n    at async ESMLoader.import (node:internal/modules/esm/loader:337:24)\n    at async loadESM (node:internal/process/esm_loader:88:5)\n    at async handleMainPromise (node:internal/modules/run_main:61:12)","ecs":{"version":"1.6.0"},"event":{"dataset":"example_normal.log"},"trace":{},"service":{"name":"example_normal","environment":"local"},"error":{"message":"a is not defined"},"stack":"ReferenceError: a is not defined\n    at file:///home/user/code/logs-nodejs-lib/examples/example_normal.js:19:1\n    at ModuleJob.run (node:internal/modules/esm/module_job:195:25)\n    at async Promise.all (index 0)\n    at async ESMLoader.import (node:internal/modules/esm/loader:337:24)\n    at async loadESM (node:internal/process/esm_loader:88:5)\n    at async handleMainPromise (node:internal/modules/run_main:61:12)","exception":true,"date":"Fri May 27 2022 16:10:13 GMT-0300 (Brasilia Standard Time)","process":{"pid":359643,"uid":1000,"gid":1000,"cwd":"/home/user/code/logs-nodejs-lib/examples","execPath":"/usr/local/bin/node","version":"v16.14.0","argv":["/usr/local/bin/node","/home/user/code/logs-nodejs-lib/examples/example_normal.js"],"memoryUsage":{"rss":60342272,"heapTotal":19537920,"heapUsed":14871160,"external":2825769,"arrayBuffers":317453}},"os":{"loadavg":[1.61,1.57,1.91],"uptime":110849.91}}

[trentm]

Hi @alexsanderp. Thanks for the issue.

(I don't use winston much myself, so it took me a little while before I realized that winston has an uncaughtException handler by default. :)

Here is a sample JS example of mine that shows me getting trace ids in the log error that winston's uncaughtException handler emits:

// Usage:
//      node -r elastic-apm-node/start play.js
//      curl -i http://localhost:3000/
const { createLogger, format, transports } = require('winston');
const ecsFormat = require('@elastic/ecs-winston-format');
const http = require('http');

const consoleOptions = {
    level: 'info',
    handleExceptions: true,
    format: ecsFormat(),
};

const consoleTransport = new transports.Console(consoleOptions);

const logger = createLogger({
    exitOnError: true,
    transports: [
        consoleTransport,
    ]
});

const server = http.createServer(function handler (req, res) {
    res.end('ok')
    logger.info('handled request')
    a // ReferenceError
    server.close() // Exit after handling one request.
})
server.listen(3000, () => {
    logger.info('listening at http://localhost:3000')
})

If you run that with node -r elastic-apm-node/start.js play.js and then make an HTTP request to it in a separate terminal with curl -i http://localhost:3000/, then the output I see is:

% node -r elastic-apm-node/start.js play.js
{"@timestamp":"2022-05-31T19:08:34.656Z","log.level":"info","message":"listening at http://localhost:3000","ecs":{"version":"1.6.0"},"event":{"dataset":"issue2730.log"},"service":{"name":"issue2730"}}
{"@timestamp":"2022-05-31T19:08:36.761Z","log.level":"info","message":"handled request","ecs":{"version":"1.6.0"},"event":{"dataset":"issue2730.log"},"trace":{"id":"d1eba1cb1b6b3ccb63f8c6c997709f16"},"transaction":{"id":"3e50f6429a46ab6b"},"service":{"name":"issue2730"}}
{"@timestamp":"2022-05-31T19:08:36.765Z","log.level":"error","message":"uncaughtException: a is not defined\nReferenceError: a is not defined\n    at Server.handler (/Users/trentm/tmp/issue2730/play.js:26:5)\n    at Server.emit (node:events:527:28)\n    at Server.emit (/Users/trentm/tmp/issue2730/node_modules/elastic-apm-node/lib/instrumentation/http-shared.js:67:19)\n    at parserOnIncoming (node:_http_server:956:12)\n    at HTTPParser.parserOnHeadersComplete (node:_http_common:128:17)","ecs":{"version":"1.6.0"},"event":{"dataset":"issue2730.log"},"trace":{"id":"d1eba1cb1b6b3ccb63f8c6c997709f16"},"transaction":{"id":"3e50f6429a46ab6b"},"service":{"name":"issue2730"},"error":{"message":"a is not defined"},"stack":"ReferenceError: a is not defined\n    at Server.handler (/Users/trentm/tmp/issue2730/play.js:26:5)\n    at Server.emit (node:events:527:28)\n    at Server.emit (/Users/trentm/tmp/issue2730/node_modules/elastic-apm-node/lib/instrumentation/http-shared.js:67:19)\n    at parserOnIncoming (node:_http_server:956:12)\n    at HTTPParser.parserOnHeadersComplete (node:_http_common:128:17)","exception":true,"date":"Tue May 31 2022 12:08:36 GMT-0700 (Pacific Daylight Saving Time)","process":{"pid":45270,"uid":501,"gid":20,"cwd":"/Users/trentm/tmp/issue2730","execPath":"/Users/trentm/.nvm/versions/node/v16.15.0/bin/node","version":"v16.15.0","argv":["/Users/trentm/.nvm/versions/node/v16.15.0/bin/node","/Users/trentm/tmp/issue2730/play.js"],"memoryUsage":{"rss":53526528,"heapTotal":20078592,"heapUsed":14799176,"external":2669502,"arrayBuffers":200198}},"os":{"loadavg":[1.67041015625,1.72119140625,1.7666015625],"uptime":1130328}}
{"log.level":"info","@timestamp":"2022-05-31T19:08:36.779Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"Sending error to Elastic APM: {\"id\":\"6996fb047e3978d543e2ed4b685bed72\"}"}

Pretty-printing that with ecslog:

% ecslog trent.log
[2022-05-31T19:08:34.656Z]  INFO (issue2730): listening at http://localhost:3000
    event: {"dataset": "issue2730.log"}
[2022-05-31T19:08:36.761Z]  INFO (issue2730): handled request
    event: {"dataset": "issue2730.log"}
    trace: {"id": "d1eba1cb1b6b3ccb63f8c6c997709f16"}
    transaction: {"id": "3e50f6429a46ab6b"}
[2022-05-31T19:08:36.765Z] ERROR (issue2730): uncaughtException: a is not defined
ReferenceError: a is not defined
    at Server.handler (/Users/trentm/tmp/issue2730/play.js:26:5)
    at Server.emit (node:events:527:28)
    at Server.emit (/Users/trentm/tmp/issue2730/node_modules/elastic-apm-node/lib/instrumentation/http-shared.js:67:19)
    at parserOnIncoming (node:_http_server:956:12)
    at HTTPParser.parserOnHeadersComplete (node:_http_common:128:17)
    event: {"dataset": "issue2730.log"}
    trace: {"id": "d1eba1cb1b6b3ccb63f8c6c997709f16"}
    transaction: {"id": "3e50f6429a46ab6b"}
    error: {"message": "a is not defined"}
    stack:
        ReferenceError: a is not defined
            at Server.handler (/Users/trentm/tmp/issue2730/play.js:26:5)
            at Server.emit (node:events:527:28)
            at Server.emit (/Users/trentm/tmp/issue2730/node_modules/elastic-apm-node/lib/instrumentation/http-shared.js:67:19)
            at parserOnIncoming (node:_http_server:956:12)
            at HTTPParser.parserOnHeadersComplete (node:_http_common:128:17)
    exception: true
    date: "Tue May 31 2022 12:08:36 GMT-0700 (Pacific Daylight Saving Time)"
    process: {
        "pid": 45270,
        "uid": 501,
        "gid": 20,
        "cwd": "/Users/trentm/tmp/issue2730",
        "execPath": "/Users/trentm/.nvm/versions/node/v16.15.0/bin/node",
        "version": "v16.15.0",
        "argv": [
            "/Users/trentm/.nvm/versions/node/v16.15.0/bin/node",
            "/Users/trentm/tmp/issue2730/play.js"
        ],
        "memoryUsage": {
            "rss": 53526528,
            "heapTotal": 20078592,
            "heapUsed": 14799176,
            "external": 2669502,
            "arrayBuffers": 200198
        }
    }
    os: {
        "loadavg": [
            1.67041015625,
            1.72119140625,
            1.7666015625
        ],
        "uptime": 1130328
    }
[2022-05-31T19:08:36.779Z]  INFO (elastic-apm-node): Sending error to Elastic APM: {"id":"6996fb047e3978d543e2ed4b685bed72"}

This shows that I got trace ids with the error log record:

    trace: {"id": "d1eba1cb1b6b3ccb63f8c6c997709f16"}
    transaction: {"id": "3e50f6429a46ab6b"}

For the record, here are the versions I am using:

% node --version
v16.15.0
% npm ls @elastic/ecs-winston-format winston elastic-apm-node
issue2730@1.0.0 /Users/trentm/tmp/issue2730
├── @elastic/ecs-winston-format@1.3.1
├── elastic-apm-node@3.34.0
└── winston@3.7.2

A couple things could be going on for why you are not seeing the same thing:

1. I noticed your example code above was using import ...-statements. Is this your JavaScript code and you are using ESM imports? I'm guessing that is the case because your posted stack is:

        ReferenceError: a is not defined
            at file:///home/user/code/logs-nodejs-lib/examples/example_normal.js:19:1
            at ModuleJob.run (node:internal/modules/esm/module_job:195:25)
            at async Promise.all (index 0)
            at async ESMLoader.import (node:internal/modules/esm/loader:337:24)
            at async loadESM (node:internal/process/esm_loader:88:5)
            at async handleMainPromise (node:internal/modules/run_main:61:12)

Unfortunately our current Node.js APM agent does not support ECMAScript Modules (ESM) -- import ... statements. It only supports CommonJS modules -- require function. The mechanism that the APM agent uses to instrument code relies on overriding node's require function.

If this is the issue, then the APM agent will likely not be creating APM transactions/spans that you would expect, so there won't be current trace IDs to use for a log record.

2. If that is not the issue, is it possible that there is no current APM transaction when your code hits an uncaughtException? A more complete code example might help me identify if that could be the case.

[alexsanderp]

I'll try to investigate, but it seems that after some changes it is working now:

2022-06-01T14:56:30.376Z  error         uncaughtException: a is not defined
ReferenceError: a is not defined
    at Object.<anonymous> (/home/alex/Documents/code/dadosfera/logs-nodejs-lib/examples/example_normal.js:19:1)
    at Module._compile (node:internal/modules/cjs/loader:1103:14)
    at Object.Module._extensions..js (node:internal/modules/cjs/loader:1155:10)
    at Module.load (node:internal/modules/cjs/loader:981:32)
    at Function.Module._load (node:internal/modules/cjs/loader:822:12)
    at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:77:12)
    at node:internal/main/run_main_module:17:47  EXTRA[{"transaction":{"id":"04b84774e7b9aeb6"},"error":{},"exception":true,"date":"Wed Jun 01 2022 11:56:30 GMT-0300 (Brasilia Standard Time)","process":{"pid":852708,"uid":1000,"gid":1000,"cwd":"/home/alex/Documents/code/dadosfera/logs-nodejs-lib/examples","execPath":"/usr/local/bin/node","version":"v16.14.0","argv":["/usr/local/bin/node","/home/alex/Documents/code/dadosfera/logs-nodejs-lib/examples/example_normal.js"],"memoryUsage":{"rss":58925056,"heapTotal":19275776,"heapUsed":13912216,"external":2609646,"arrayBuffers":315097}},"os":{"loadavg":[1.36,2.87,2.5],"uptime":527625.5},"trace":[{"column":1,"file":"/home/alex/Documents/code/dadosfera/logs-nodejs-lib/examples/example_normal.js","function":null,"line":19,"method":null,"native":false},{"column":14,"file":"node:internal/modules/cjs/loader","function":"Module._compile","line":1103,"method":"_compile","native":false},{"column":10,"file":"node:internal/modules/cjs/loader","function":"Module._extensions..js","line":1155,"method":".js","native":false},{"column":32,"file":"node:internal/modules/cjs/loader","function":"Module.load","line":981,"method":"load","native":false},{"column":12,"file":"node:internal/modules/cjs/loader","function":"Module._load","line":822,"method":"_load","native":false},{"column":12,"file":"node:internal/modules/run_main","function":"Function.executeUserEntryPoint [as runMain]","line":77,"method":"executeUserEntryPoint [as runMain]","native":false},{"column":47,"file":"node:internal/main/run_main_module","function":null,"line":17,"method":null,"native":false}],"service":{"name":"example_normal","environment":"local"}}]