search

elastic / apm-agent-nodejs

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

"pg/knex.test.js" fails with Node.js v18.19.0 #3823

Open trentm opened 9 months ago

trentm commented 9 months ago

"test/instrumentation/modules/pg/knex.test.js" fails with Node.js v18.19.0. It passes with v18.18.2.

$ nvm use 18.19.0
$ npm run docker:start postgres
$ node test/instrumentation/modules/pg/knex.test.js
...
# knex fixtures
# knex ESM (../fixtures/use-knex-pg.mjs)
# running: (cd "/Users/trentm/el/apm-agent-nodejs/test/instrumentation/modules/pg" && NODE_OPTIONS="--experimental-loader=../../../../loader.mjs --require=../../../../start.js" NODE_NO_WARNINGS=1 ELASTIC_APM_SPAN_STACK_TRACE_MIN_DURATION=0 node ../fixtures/use-knex-pg.mjs)
# elapsed: 0.815s
# err:
# |Error: Command failed: /Users/trentm/.nvm/versions/node/v18.19.0/bin/node ../fixtures/use-knex-pg.mjs
# |error: create table "users" ("id" serial primary key, "user_name" varchar(255)) - relation "users" already exists
# |    at Parser.parseErrorMessage (/Users/trentm/el/apm-agent-nodejs/node_modules/pg-protocol/dist/parser.js:287:98)
# |    at Parser.handlePacket (/Users/trentm/el/apm-agent-nodejs/node_modules/pg-protocol/dist/parser.js:126:29)
# |    at Parser.parse (/Users/trentm/el/apm-agent-nodejs/node_modules/pg-protocol/dist/parser.js:39:38)
# |    at Socket.<anonymous> (/Users/trentm/el/apm-agent-nodejs/node_modules/pg-protocol/dist/index.js:11:42)
# |    at Socket.emit (node:events:517:28)
# |    at addChunk (node:internal/streams/readable:368:12)
# |    at readableAddChunk (node:internal/streams/readable:341:9)
# |    at Readable.push (node:internal/streams/readable:278:10)
# |    at TCP.onStreamRead (node:internal/stream_base_commons:190:23)
# |    at TCP.callbackTrampoline (node:internal/async_hooks:128:17) {
# |  length: 99,
# |  severity: 'ERROR',
# |  code: '42P07',
# |  detail: undefined,
# |  hint: undefined,
# |  position: undefined,
# |  internalPosition: undefined,
# |  internalQuery: undefined,
# |  where: undefined,
# |  schema: undefined,
# |  table: undefined,
# |  column: undefined,
# |  dataType: undefined,
# |  constraint: undefined,
# |  file: 'heap.c',
# |  line: '1077',
# |  routine: 'heap_create_with_catalog'
# |}
# stdout:
# |{"log.level":"warn","@timestamp":"2024-01-11T21:50:51.884Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","message":"units missing in duration value \"0\" for \"spanStackTraceMinDuration\" config option: using default units \"ms\""}
# |{"log.level":"info","@timestamp":"2024-01-11T21:50:51.889Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","agentVersion":"4.3.0","env":{"pid":79931,"proctitle":"/Users/trentm/.nvm/versions/node/v18.19.0/bin/node","os":"darwin 23.2.0","arch":"x64","host":"pink.local","timezone":"UTC-0800","runtime":"Node.js v18.19.0"},"config":{"centralConfig":{"source":"environment","value":false,"sourceValue":"false"},"cloudProvider":{"source":"environment","value":"none"},"logLevel":{"source":"default","value":"info","commonName":"log_level"},"metricsInterval":{"source":"environment","value":0,"sourceValue":"0s"},"serverUrl":{"source":"environment","value":"http://localhost:61545/","commonName":"server_url"},"spanStackTraceMinDuration":{"source":"environment","value":0,"commonName":"span_stack_trace_min_duration","sourceValue":"0"},"serviceName":{"source":"default","value":"elastic-apm-node","commonName":"service_name"},"serviceVersion":{"source":"default","value":"4.3.0","commonName":"service_version"}},"activationMethod":"preload","message":"Elastic APM Node.js Agent v4.3.0"}
# stderr:
# |error: create table "users" ("id" serial primary key, "user_name" varchar(255)) - relation "users" already exists
# |    at Parser.parseErrorMessage (/Users/trentm/el/apm-agent-nodejs/node_modules/pg-protocol/dist/parser.js:287:98)
# |    at Parser.handlePacket (/Users/trentm/el/apm-agent-nodejs/node_modules/pg-protocol/dist/parser.js:126:29)
# |    at Parser.parse (/Users/trentm/el/apm-agent-nodejs/node_modules/pg-protocol/dist/parser.js:39:38)
# |    at Socket.<anonymous> (/Users/trentm/el/apm-agent-nodejs/node_modules/pg-protocol/dist/index.js:11:42)
# |    at Socket.emit (node:events:517:28)
# |    at addChunk (node:internal/streams/readable:368:12)
# |    at readableAddChunk (node:internal/streams/readable:341:9)
# |    at Readable.push (node:internal/streams/readable:278:10)
# |    at TCP.onStreamRead (node:internal/stream_base_commons:190:23)
# |    at TCP.callbackTrampoline (node:internal/async_hooks:128:17) {
# |  length: 99,
# |  severity: 'ERROR',
# |  code: '42P07',
# |  detail: undefined,
# |  hint: undefined,
# |  position: undefined,
# |  internalPosition: undefined,
# |  internalQuery: undefined,
# |  where: undefined,
# |  schema: undefined,
# |  table: undefined,
# |  column: undefined,
# |  dataType: undefined,
# |  constraint: undefined,
# |  file: 'heap.c',
# |  line: '1077',
# |  routine: 'heap_create_with_catalog'
# |}
not ok 118 ../fixtures/use-knex-pg.mjs exited successfully: err=Error: Command failed: /Users/trentm/.nvm/versions/node/v18.19.0/bin/node ../fixtures/use-knex-pg.mjs error: create table "users" ("id" serial primary key, "user_name" varchar(255)) - relation "users" already exists at Parser.parseErrorMessage (/Users/trentm/el/apm-agent-nodejs/node_modules/pg-protocol/dist/parser.js:287:98) at Parser.handlePacket (/Users/trentm/el/apm-agent-nodejs/node_modules/pg-protocol/dist/parser.js:126:29) at Parser.parse (/Users/trentm/el/apm-agent-nodejs/node_modules/pg-protocol/dist/parser.js:39:38) at Socket.<anonymous> (/Users/trentm/el/apm-agent-nodejs/node_modules/pg-protocol/dist/index.js:11:42) at Socket.emit (node:events:517:28) at addChunk (node:internal/streams/readable:368:12) at readableAddChunk (node:internal/streams/readable:341:9) at Readable.push (node:internal/streams/readable:278:10) at TCP.onStreamRead (node:internal/stream_base_commons:190:23) at TCP.callbackTrampoline (node:internal/async_hooks:128:17) { length: 99, severity: 'ERROR', code: '42P07', detail: undefined, hint: undefined, position: undefined, internalPosition: undefined, internalQuery: undefined, where: undefined, schema: undefined, table: undefined, column: undefined, dataType: undefined, constraint: undefined, file: 'heap.c', line: '1077', routine: 'heap_create_with_catalog' }
  ---
    operator: error
    at: done (/Users/trentm/el/apm-agent-nodejs/test/_utils.js:353:17)
    stack: |-
      Error: Command failed: /Users/trentm/.nvm/versions/node/v18.19.0/bin/node ../fixtures/use-knex-pg.mjs
      error: create table "users" ("id" serial primary key, "user_name" varchar(255)) - relation "users" already exists
          at Parser.parseErrorMessage (/Users/trentm/el/apm-agent-nodejs/node_modules/pg-protocol/dist/parser.js:287:98)
          at Parser.handlePacket (/Users/trentm/el/apm-agent-nodejs/node_modules/pg-protocol/dist/parser.js:126:29)
          at Parser.parse (/Users/trentm/el/apm-agent-nodejs/node_modules/pg-protocol/dist/parser.js:39:38)
          at Socket.<anonymous> (/Users/trentm/el/apm-agent-nodejs/node_modules/pg-protocol/dist/index.js:11:42)
          at Socket.emit (node:events:517:28)
          at addChunk (node:internal/streams/readable:368:12)
          at readableAddChunk (node:internal/streams/readable:341:9)
          at Readable.push (node:internal/streams/readable:278:10)
          at TCP.onStreamRead (node:internal/stream_base_commons:190:23)
          at TCP.callbackTrampoline (node:internal/async_hooks:128:17) {
        length: 99,
        severity: 'ERROR',
        code: '42P07',
        detail: undefined,
        hint: undefined,
        position: undefined,
        internalPosition: undefined,
        internalQuery: undefined,
        where: undefined,
        schema: undefined,
        table: undefined,
        column: undefined,
        dataType: undefined,
        constraint: undefined,
        file: 'heap.c',
        line: '1077',
        routine: 'heap_create_with_catalog'
      }

          at ChildProcess.exithandler (node:child_process:422:12)
          at ChildProcess.emit (node:events:517:28)
          at maybeClose (node:internal/child_process:1098:16)
          at Socket.<anonymous> (node:internal/child_process:450:11)
          at Socket.emit (node:events:517:28)
          at Pipe.<anonymous> (node:net:350:12)
          at Pipe.callbackTrampoline (node:internal/async_hooks:128:17)
  ...
# skip checkApmServer because script errored out

1..118
# tests 118
# pass  117
# fail  1

This isn't currently showing up in our testing because we are currently pinning v18 testing to v18.18.2 for another reason: #3784

david-luna commented 9 months ago

It's strange the message tells about a table already existing

|error: create table "users" ("id" serial primary key, "user_name" varchar(255)) - relation "users" already exists

I could only reproduce it when I'm commenting out the teardownDb() process of the fixture file. The 2nd time it fails with the same error because the DB & table is already existing.

diff --git a/test/instrumentation/modules/fixtures/use-knex-pg.mjs b/test/instrumentation/modules/fixtures/use-knex-pg.mjs
index 074b5307..f812f595 100644
--- a/test/instrumentation/modules/fixtures/use-knex-pg.mjs
+++ b/test/instrumentation/modules/fixtures/use-knex-pg.mjs
@@ -60,7 +60,7 @@ async function main() {
     trans.end();

     await knex.destroy();
-    await teardownDb();
+    // await teardownDb();
   }
 }

Maybe we could update the fixture to check for existence of the table with https://knexjs.org/guide/schema-builder.html#hastable. We already have other fixtures that check for the existence of a resource before creating it (eg. client-s3 checks for existing bucket)

trentm commented 9 months ago

Maybe we could update the fixture to check for existence of the table

Yup, that would likely be good.

It would be nice to spend a little time trying to understand what has changed here. I didn't see anything obvious in https://nodejs.org/en/blog/release/v18.19.0 that hints at a change here.

As a total guess: is this a timing issue? That test file has some in-process usage and out-of-process (via runTestFixtures) usage. Could the in-process tests still have some incomplete shutdown (or state) before the test fixture is run?