elastic / apm-agent-nodejs

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

spurious "not ok 25 send-a-span.js did not error" test failure in "stacktraces.test.js" #3111

Open trentm opened 1 year ago

trentm commented 1 year ago

E.g. https://github.com/elastic/apm-agent-nodejs/actions/runs/3954138838/jobs/6771163354

running test: cd . && node --require /home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/_promise_rejection.js test/stacktraces/stacktraces.test.js > test_output/test-stacktraces-stacktraces.test.js.tap 2&>1

TAP version 13
# error.exception.stacktrace
ok 1 throw-an-error.js errored out
ok 2 err.message includes /Error: boom/: "Command failed: /opt/hostedtoolcache/node/10.24.1/x64/bin/node fixtures/throw-an-error.js\nError: boom\n at main (/home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/stacktraces/fixtures/throw-an-error.js:21:9)\n at Object.<anonymous> (/home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/stacktraces/fixtures/throw-an-error.js:24:1)\n at Module._compile (internal/modules/cjs/loader.js:778:30)\n at Object.Module._extensions..js (internal/modules/cjs/loader.js:789:10)\n at Module.load (internal/modules/cjs/loader.js:653:32)\n at tryModuleLoad (internal/modules/cjs/loader.js:593:12)\n at Function.Module._load (internal/modules/cjs/loader.js:585:3)\n at Function.Module.runMain (internal/modules/cjs/loader.js:831:12)\n at startup (internal/bootstrap/node.js:283:19)\n at bootstrapNodeJSCore (internal/bootstrap/node.js:623:3)\n"
/home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/test.js:218
    if (err) throw err
ok 3 APM server got event metadata object
             ^

Error: non-zero error code
    at WriteStream.onClose (/home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/test.js:86:25)
    at WriteStream.emit (events.js:198:13)
ok 4 APM server got error event
ok 5 stacktrace top frame is as expected
# error.exception.stacktrace does not have "[Circular]" frames
ok 6 circular-stack.js exited non-zero
ok 7 APM server got first metadata object
ok 8 APM server got first error event
ok 9 APM server got second metadata object
ok 10 APM server got second error event
ok 11 "boom on zero" stacktrace frame is as expected
ok 12 "boom on zero" stacktrace frame is as expected
ok 13 "boom on zero" stacktrace frame is as expected
ok 14 "boom on zero" stacktrace frame is as expected
ok 15 "boom on zero" stacktrace frame is as expected
ok 16 "boom on zero" stacktrace frame is as expected
ok 17 "boom on zero" stacktrace frame is as expected
ok 18 "boom on zero" stacktrace frame is as expected
ok 19 "boom on zero" stacktrace frame is as expected
ok 20 found 9 "boom on zero" stacktrace frames
# error.log.stacktrace
ok 21 capture-error-string.js did not error
ok 22 APM server got event metadata object
ok 23 first error.log.stacktrace top frame is as expected
ok 24 second error.log.stacktrace top frame is as expected
# span.stacktrace
not ok 25 send-a-span.js did not error
  ---
    operator: error
    at: done (/home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/stacktraces/stacktraces.test.js:185:11)
    stack: |-
      Error: Command failed: /opt/hostedtoolcache/node/10.24.1/x64/bin/node fixtures/send-a-span.js

          at ChildProcess.exithandler (child_process.js:294:12)
          at ChildProcess.emit (events.js:198:13)
          at maybeClose (internal/child_process.js:982:16)
          at Process.ChildProcess._handle.onexit (internal/child_process.js:259:5)
  ...
/home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/stacktraces/stacktraces.test.js:186
        t.ok(server.events[0].metadata, 'APM server got event metadata object')
                              ^

TypeError: Cannot read property 'metadata' of undefined
    at done (/home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/stacktraces/stacktraces.test.js:186:31)
    at ChildProcess.exithandler (child_process.js:301:5)
    at ChildProcess.emit (events.js:198:13)
    at maybeClose (internal/child_process.js:982:16)
    at Process.ChildProcess._handle.onexit (internal/child_process.js:259:5)

    at lazyFs.close (internal/fs/streams.js:207:14)
    at FSReqWrap.args [as oncomplete] (fs.js:140:20)
npm ERR! Test failed.  See above for more details.

I think I've seen this before, and I just saw it again. The failure was on a CI run for https://github.com/elastic/apm-agent-nodejs/pull/3110 which is totally unrelated to this test.

trentm commented 1 year ago

2023-06-05 in test-vers (19)

https://github.com/elastic/apm-agent-nodejs/actions/runs/5180230985/jobs/9334144249

# error.log.stacktrace
ok 21 capture-error-string.js did not error
ok 22 APM server got event metadata object
ok 23 first error.log.stacktrace top frame is as expected
ok 24 second error.log.stacktrace top frame is as expected
# span.stacktrace
not ok 25 send-a-span.js did not error
  ---
    operator: error
    at: done (/home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/stacktraces/stacktraces.test.js:185:11)
    stack: |-
      Error: Command failed: /opt/hostedtoolcache/node/19.9.0/x64/bin/node fixtures/send-a-span.js

          at ChildProcess.exithandler (node:child_process:419:12)
          at ChildProcess.emit (node:events:513:28)
          at maybeClose (node:internal/child_process:1098:16)
          at ChildProcess._handle.onexit (node:internal/child_process:304:5)
  ...
/home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/stacktraces/stacktraces.test.js:186
        t.ok(server.events[0].metadata, 'APM server got event metadata object')
                              ^

TypeError: Cannot read properties of undefined (reading 'metadata')
    at done (/home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/stacktraces/stacktraces.test.js:186:31)
    at ChildProcess.exithandler (node:child_process:427:5)
    at ChildProcess.emit (node:events:513:28)
    at maybeClose (node:internal/child_process:1098:16)
    at ChildProcess._handle.onexit (node:internal/child_process:304:5)

Node.js v19.9.0

/home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/test.js:182
    if (err) throw err
             ^

Error: non-zero error code
    at WriteStream.onClose (/home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/test.js:65:25)
    at WriteStream.emit (node:events:513:28)
    at emitCloseNT (node:internal/streams/destroy:132:10)
    at process.processTicksAndRejections (node:internal/process/task_queues:81:21) {
  code: 'ENONZERO',
  exitCode: 1
}

Node.js v19.9.0
Error: Process completed with exit code 1.