search

elastic / apm-agent-nodejs

https://www.elastic.co/guide/en/apm/agent/nodejs/current/index.html
BSD 2-Clause "Simplified" License
582 stars 224 forks source link

stacktrace source context does not use "sourcesContent" source map field #2095

Closed trentm closed 3 years ago

trentm commented 3 years ago

background

The APM agent will collect a stacktrace object for captured errors and for spans (if captureSpanStackTraces is enabled). Depending on the sourceLines*Frames config vars:

  sourceLinesErrorAppFrames: 5,
  sourceLinesErrorLibraryFrames: 5,
  sourceLinesSpanAppFrames: 0,
  sourceLinesSpanLibraryFrames: 0,

source file context lines will be added to the stacktrace frame objects, e.g. the *context* fields in:

      "stacktrace": [
        {
          "filename": "bin/pathosapp.js",
          "lineno": 148,
          "function": "err",
          "library_frame": false,
          "abs_path": "/Users/trentm/src/foo/bin/pathosapp.js",
          "pre_context": [
            "",
            "  'err': function err(req, res, next) {"
          ],
          "context_line": "    next(new Error('oof'))",
          "post_context": [
            "  },",
            ""
          ]
        },

Gathering this source file context content supports sourcemaps (https://www.html5rocks.com/en/tutorials/developertools/sourcemaps/). For example this "ib/error-src-embedded.js"

'use strict';

// Just a little prefixing line
var generateError = function generateError() {
  var msg = arguments.length > 0 && arguments[0] !== undefined ? arguments[0] : 'foo';
  return new Error(msg);
};

module.exports = generateError;

//# sourceMappingURL=error-src-embedded.js.map

refers to a "error-src-embedded.js.map" source map file. It can look like this:

{
  "version": 3,
  "sources": [
    "../src/error.js"
  ],
  "names": [],
  "mappings": ";;AAAA;AACA,IAAM,gBAAgB,SAAhB,aAAgB;AAAA,MAAC,GAAD,uEAAO,KAAP;AAAA,SAAiB,IAAI,KAAJ,CAAU,GAAV,CAAjB;AAAA,CAAtB;;AAEA,OAAO,OAAP,GAAiB,aAAjB",
  "file": "error.js",
  "sourcesContent": [
    "// Just a little prefixing line\nconst generateError = (msg = 'foo') => new Error(msg)\n\nmodule.exports = generateError\n"
  ]
}

(Source maps can also be embedded in the file rather than referring to a separate JSON .map file.)

When the APM agent is adding source file context to a stacktrace frame, it will load file content according to this source map.

the bug

The APM agent's source map handling does not properly handle relative files in sources when looking for file content in the sourcesContent field. The result is that source map handling by the agent will typically never use sourcesContent and will fallback to attempting to load the sources file -- "../src/error.js" in this example -- from disk. If that file is missing (the point of sourcesContent is to not have to deploy the original files listed in sources) then adding source file context to the stacktrace frame will not work.

The current tests in "test/sourcemaps/" don't catch this because they all refer to "../src/error.js" -- which exists. So when "sourcesContent" lookup fails, the agent falls back to loading the file from disk, and the test "passes" because the content in the file and in "sourcesContent" agree.

repro

One way to observe this failure is to tweak the test case as follows (we change the "sources" path to be something that doesn't exist on disk):

diff --git a/test/sourcemaps/fixtures/lib/error-src-embedded.js.map b/test/sourcemaps/fixtures/lib/error-src-embedded.js.map
index 4c2bfba..a426169 100644
--- a/test/sourcemaps/fixtures/lib/error-src-embedded.js.map
+++ b/test/sourcemaps/fixtures/lib/error-src-embedded.js.map
@@ -1 +1 @@
-{"version":3,"sources":["../src/error.js"],"names":[],"mappings":";;AAAA;AACA,IAAM,gBAAgB,SAAhB,aAAgB;AAAA,MAAC,GAAD,uEAAO,KAAP;AAAA,SAAiB,IAAI,KAAJ,CAAU,GAAV,CAAjB;AAAA,CAAtB;;AAEA,OAAO,OAAP,GAAiB,aAAjB","file":"error.js","sourcesContent":["// Just a little prefixing line\nconst generateError = (msg = 'foo') => new Error(msg)\n\nmodule.exports = generateError\n"]}
\ No newline at end of file
+{"version":3,"sources":["../src/errorXXX.js"],"names":[],"mappings":";;AAAA;AACA,IAAM,gBAAgB,SAAhB,aAAgB;AAAA,MAAC,GAAD,uEAAO,KAAP;AAAA,SAAiB,IAAI,KAAJ,CAAU,GAAV,CAAjB;AAAA,CAAtB;;AAEA,OAAO,OAAP,GAAiB,aAAjB","file":"error.js","sourcesContent":["// Just a little prefixing line\nconst generateError = (msg = 'foo') => new Error(msg)\n\nmodule.exports = generateError\n"]}

Then running the test fails:


% node test/sourcemaps/index.js
TAP version 13
# source map inlined
ok 1 should be strictly equal
ok 2 should be strictly equal
ok 3 should be strictly equal
ok 4 should be strictly equal
ok 5 should be strictly equal
ok 6 should be strictly equal
ok 7 should be strictly equal
ok 8 should be strictly equal
ok 9 should be deeply equivalent
ok 10 should be strictly equal
ok 11 should be deeply equivalent
# source map linked
# source mapped source code embedded
ok 12 should be strictly equal
ok 13 should be strictly equal
not ok 14 should be strictly equal
  ---
    operator: equal
    expected: 'generateError (test/sourcemaps/fixtures/src/error.js)'
    actual:   'generateError (test/sourcemaps/fixtures/src/errorXXX.js)'
    at: assertSourceFound (/Users/trentm/el/apm-agent-nodejs3/test/sourcemaps/index.js:105:5)
    stack: |-
      Error: should be strictly equal
          at Test.assert [as _assert] (/Users/trentm/el/apm-agent-nodejs3/node_modules/tape/lib/test.js:304:54)
          at Test.bound [as _assert] (/Users/trentm/el/apm-agent-nodejs3/node_modules/tape/lib/test.js:91:32)
          at Test.strictEqual (/Users/trentm/el/apm-agent-nodejs3/node_modules/tape/lib/test.js:468:10)
          at Test.bound [as strictEqual] (/Users/trentm/el/apm-agent-nodejs3/node_modules/tape/lib/test.js:91:32)
          at assertSourceFound (/Users/trentm/el/apm-agent-nodejs3/test/sourcemaps/index.js:105:5)
          at Object.sendError (/Users/trentm/el/apm-agent-nodejs3/test/sourcemaps/index.js:96:7)
          at send (/Users/trentm/el/apm-agent-nodejs3/lib/agent.js:453:24)
          at prepareError (/Users/trentm/el/apm-agent-nodejs3/lib/agent.js:436:7)
          at /Users/trentm/el/apm-agent-nodejs3/lib/agent.js:348:7
          at /Users/trentm/el/apm-agent-nodejs3/lib/parsers.js:127:7
          at /Users/trentm/el/apm-agent-nodejs3/node_modules/after-all-results/index.js:20:25
          at processTicksAndRejections (internal/process/task_queues.js:79:11)
  ...
not ok 15 should be strictly equal
  ---
    operator: equal
    expected: 'test/sourcemaps/fixtures/src/error.js'
    actual:   'test/sourcemaps/fixtures/src/errorXXX.js'
    at: assertSourceFound (/Users/trentm/el/apm-agent-nodejs3/test/sourcemaps/index.js:108:5)
    stack: |-
      Error: should be strictly equal
          at Test.assert [as _assert] (/Users/trentm/el/apm-agent-nodejs3/node_modules/tape/lib/test.js:304:54)
          at Test.bound [as _assert] (/Users/trentm/el/apm-agent-nodejs3/node_modules/tape/lib/test.js:91:32)
          at Test.strictEqual (/Users/trentm/el/apm-agent-nodejs3/node_modules/tape/lib/test.js:468:10)
          at Test.bound [as strictEqual] (/Users/trentm/el/apm-agent-nodejs3/node_modules/tape/lib/test.js:91:32)
          at assertSourceFound (/Users/trentm/el/apm-agent-nodejs3/test/sourcemaps/index.js:108:5)
          at Object.sendError (/Users/trentm/el/apm-agent-nodejs3/test/sourcemaps/index.js:96:7)
          at send (/Users/trentm/el/apm-agent-nodejs3/lib/agent.js:453:24)
          at prepareError (/Users/trentm/el/apm-agent-nodejs3/lib/agent.js:436:7)
          at /Users/trentm/el/apm-agent-nodejs3/lib/agent.js:348:7
          at /Users/trentm/el/apm-agent-nodejs3/lib/parsers.js:127:7
          at /Users/trentm/el/apm-agent-nodejs3/node_modules/after-all-results/index.js:20:25
          at processTicksAndRejections (internal/process/task_queues.js:79:11)
  ...
ok 16 should be strictly equal
ok 17 should be strictly equal
ok 18 should be strictly equal
not ok 19 should be strictly equal
  ---
    operator: equal
    expected: |-
      '/Users/trentm/el/apm-agent-nodejs3/test/sourcemaps/fixtures/src/error.js'
    actual: |-
      '/Users/trentm/el/apm-agent-nodejs3/test/sourcemaps/fixtures/src/errorXXX.js'
    at: assertSourceFound (/Users/trentm/el/apm-agent-nodejs3/test/sourcemaps/index.js:112:5)
    stack: |-
      Error: should be strictly equal
          at Test.assert [as _assert] (/Users/trentm/el/apm-agent-nodejs3/node_modules/tape/lib/test.js:304:54)
          at Test.bound [as _assert] (/Users/trentm/el/apm-agent-nodejs3/node_modules/tape/lib/test.js:91:32)
          at Test.strictEqual (/Users/trentm/el/apm-agent-nodejs3/node_modules/tape/lib/test.js:468:10)
          at Test.bound [as strictEqual] (/Users/trentm/el/apm-agent-nodejs3/node_modules/tape/lib/test.js:91:32)
          at assertSourceFound (/Users/trentm/el/apm-agent-nodejs3/test/sourcemaps/index.js:112:5)
          at Object.sendError (/Users/trentm/el/apm-agent-nodejs3/test/sourcemaps/index.js:96:7)
          at send (/Users/trentm/el/apm-agent-nodejs3/lib/agent.js:453:24)
          at prepareError (/Users/trentm/el/apm-agent-nodejs3/lib/agent.js:436:7)
          at /Users/trentm/el/apm-agent-nodejs3/lib/agent.js:348:7
          at /Users/trentm/el/apm-agent-nodejs3/lib/parsers.js:127:7
          at /Users/trentm/el/apm-agent-nodejs3/node_modules/after-all-results/index.js:20:25
          at processTicksAndRejections (internal/process/task_queues.js:79:11)
  ...
not ok 20 should be deeply equivalent
  ---
    operator: deepEqual
    expected: [ '// Just a little prefixing line' ]
    actual:   undefined
    at: assertSourceFound (/Users/trentm/el/apm-agent-nodejs3/test/sourcemaps/index.js:113:5)
    stack: |-
      Error: should be deeply equivalent
          at Test.assert [as _assert] (/Users/trentm/el/apm-agent-nodejs3/node_modules/tape/lib/test.js:304:54)
          at Test.bound [as _assert] (/Users/trentm/el/apm-agent-nodejs3/node_modules/tape/lib/test.js:91:32)
          at Test.tapeDeepEqual (/Users/trentm/el/apm-agent-nodejs3/node_modules/tape/lib/test.js:545:10)
          at Test.bound [as deepEqual] (/Users/trentm/el/apm-agent-nodejs3/node_modules/tape/lib/test.js:91:32)
          at assertSourceFound (/Users/trentm/el/apm-agent-nodejs3/test/sourcemaps/index.js:113:5)
          at Object.sendError (/Users/trentm/el/apm-agent-nodejs3/test/sourcemaps/index.js:96:7)
          at send (/Users/trentm/el/apm-agent-nodejs3/lib/agent.js:453:24)
          at prepareError (/Users/trentm/el/apm-agent-nodejs3/lib/agent.js:436:7)
          at /Users/trentm/el/apm-agent-nodejs3/lib/agent.js:348:7
          at /Users/trentm/el/apm-agent-nodejs3/lib/parsers.js:127:7
          at /Users/trentm/el/apm-agent-nodejs3/node_modules/after-all-results/index.js:20:25
          at processTicksAndRejections (internal/process/task_queues.js:79:11)
  ...
not ok 21 should be strictly equal
  ---
    operator: equal
    expected: 'const generateError = (msg = \'foo\') => new Error(msg)'
    actual:   undefined
    at: assertSourceFound (/Users/trentm/el/apm-agent-nodejs3/test/sourcemaps/index.js:114:5)
    stack: |-
      Error: should be strictly equal
          at Test.assert [as _assert] (/Users/trentm/el/apm-agent-nodejs3/node_modules/tape/lib/test.js:304:54)
          at Test.bound [as _assert] (/Users/trentm/el/apm-agent-nodejs3/node_modules/tape/lib/test.js:91:32)
          at Test.strictEqual (/Users/trentm/el/apm-agent-nodejs3/node_modules/tape/lib/test.js:468:10)
          at Test.bound [as strictEqual] (/Users/trentm/el/apm-agent-nodejs3/node_modules/tape/lib/test.js:91:32)
          at assertSourceFound (/Users/trentm/el/apm-agent-nodejs3/test/sourcemaps/index.js:114:5)
          at Object.sendError (/Users/trentm/el/apm-agent-nodejs3/test/sourcemaps/index.js:96:7)
          at send (/Users/trentm/el/apm-agent-nodejs3/lib/agent.js:453:24)
          at prepareError (/Users/trentm/el/apm-agent-nodejs3/lib/agent.js:436:7)
          at /Users/trentm/el/apm-agent-nodejs3/lib/agent.js:348:7
          at /Users/trentm/el/apm-agent-nodejs3/lib/parsers.js:127:7
          at /Users/trentm/el/apm-agent-nodejs3/node_modules/after-all-results/index.js:20:25
          at processTicksAndRejections (internal/process/task_queues.js:79:11)
  ...
not ok 22 should be deeply equivalent
  ---
    operator: deepEqual
    expected: [ '', 'module.exports = generateError' ]
    actual:   undefined
    at: assertSourceFound (/Users/trentm/el/apm-agent-nodejs3/test/sourcemaps/index.js:115:5)
    stack: |-
      Error: should be deeply equivalent
          at Test.assert [as _assert] (/Users/trentm/el/apm-agent-nodejs3/node_modules/tape/lib/test.js:304:54)
          at Test.bound [as _assert] (/Users/trentm/el/apm-agent-nodejs3/node_modules/tape/lib/test.js:91:32)
          at Test.tapeDeepEqual (/Users/trentm/el/apm-agent-nodejs3/node_modules/tape/lib/test.js:545:10)
          at Test.bound [as deepEqual] (/Users/trentm/el/apm-agent-nodejs3/node_modules/tape/lib/test.js:91:32)
          at assertSourceFound (/Users/trentm/el/apm-agent-nodejs3/test/sourcemaps/index.js:115:5)
          at Object.sendError (/Users/trentm/el/apm-agent-nodejs3/test/sourcemaps/index.js:96:7)
          at send (/Users/trentm/el/apm-agent-nodejs3/lib/agent.js:453:24)
          at prepareError (/Users/trentm/el/apm-agent-nodejs3/lib/agent.js:436:7)
          at /Users/trentm/el/apm-agent-nodejs3/lib/agent.js:348:7
          at /Users/trentm/el/apm-agent-nodejs3/lib/parsers.js:127:7
          at /Users/trentm/el/apm-agent-nodejs3/node_modules/after-all-results/index.js:20:25
          at processTicksAndRejections (internal/process/task_queues.js:79:11)
  ...
...
trentm commented 3 years ago

Currently the erroneous code is in the "stackman" dependency. After https://github.com/elastic/apm-agent-nodejs/pull/2094 this dep will be moved inline.