lambda layer 99(3.38.1) introduces intermittent pg prepared statement error

[kcveitch]

updating from layer 98 to layer 99 introduces an intermittent postgres error with prepared statements.

Error: Prepared statements must be unique - 'InsertMarketNotifications' was used for a different statement

This appears to occur when multiple invocations of a lambda are happening in rapid sequence. In this case one lambda is processing a SQS queue of a few dozen records and are posting them to a REST API Gateway which is invoking another lambda to process and insert records into postgres. The lambda being invoked from the API Gateway to insert records into postges is the one experiencing the errors and is configured with the following settings.

It appears that the first few invocations are able to make their inserts into pg without error but as more invocations come in, the error begins to occur consistently until all invocations fail in the same way.

We are using a few DD products in BETA such as serverless profiling and ASM which could be related to the issue.

reverting to nodeLayerVersion 98 corrects the issue and the error no longer occurs

Specifications

Node 16
Typescript Built using Esbuild with dd-trace/esbuild plugin
nodeLayerVersion: 99
extensionLayerVersion: 50

DD_SERVICE: !Ref AppShortName
DD_ENV: !Ref AWSEnvironment
DD_VERSION: !Ref BitbucketBuildNumber
DD_TRACE_DEBUG: false
DD_TRACE_STARTUP_LOGS: false
DD_LOGS_INJECTION: true
DD_APPSEC_ENABLED: true
DD_PROFILING_ENABLED: true
DD_SERVERLESS_APPSEC_ENABLED: true
DD_PROFILING_CODEHOTSPOTS_ENABLED: true
DD_PROFILING_ENDPOINT_COLLECTION_ENABLED: true
AWS_LAMBDA_EXEC_WRAPPER: /opt/datadog_wrapper
DD_TRACE_ENABLED: true
DD_DBM_PROPAGATION_MODE: "full"
DD_TAGS: !Sub "git.commit.sha:${BitbucketCommit},git.repository_url:https://bitbucket.org/${BitbucketRepoFullName}"

  "dependencies": {
    "axios": "^1.6.0",
    "bluebird": "^3.7.2",
    "dayjs": "^1.11.9",
    "dotenv": "^16.0.1",
    "esbuild": "^0.18.2",
    "fast-xml-parser": "^4.2.5",
    "fs": "^0.0.1-security",
    "moment": "^2.29.4",
    "node-gyp": "^9.3.1",
    "pg": "^8.11.0",
    "pg-native": "^3.0.1",
    "pg-promise": "^11.5.0",
    "uuid": "^9.0.0"
  }

Stack Trace

Error: Prepared statements must be unique - 'InsertMarketNotifications' was used for a different statement
    at wo.submit (/tmp/tmp2dqgcwz8/node_modules/pg/lib/query.js:156:14)
    at ti._pulseQueryQueue (/tmp/tmp2dqgcwz8/node_modules/pg/lib/client.js:486:45)
    at ti.query (/tmp/tmp2dqgcwz8/node_modules/pg/lib/client.js:586:10)
    at /opt/nodejs/node_modules/dd-trace/packages/datadog-instrumentations/src/pg.js:71:28
    at exports.AsyncResource.runInAsyncScope (node:async_hooks:203:9)
    at ti.query (/opt/nodejs/node_modules/dd-trace/packages/datadog-instrumentations/src/pg.js:55:26)
    at executor (/tmp/tmp2dqgcwz8/node_modules/pg-promise/lib/query.js:156:27)
    at E.e._execute (/tmp/tmp2dqgcwz8/node_modules/bluebird/js/release/debuggability.js:384:9)
    at E.E._resolveFromExecutor (/tmp/tmp2dqgcwz8/node_modules/bluebird/js/release/promise.js:518:18)
    at E (/tmp/tmp2dqgcwz8/node_modules/bluebird/js/release/promise.js:103:10)
    at $p (/tmp/tmp2dqgcwz8/node_modules/pg-promise/lib/promise-parser.js:30:20)
    at lT.LC (/tmp/tmp2dqgcwz8/node_modules/pg-promise/lib/query.js:145:12)
    at lT.<anonymous> (/tmp/tmp2dqgcwz8/node_modules/pg-promise/lib/query.js:277:23)
    at db (/tmp/tmp2dqgcwz8/node_modules/pg-promise/lib/database.js:333:42)
    at /opt/nodejs/node_modules/dd-trace/packages/datadog-instrumentations/src/helpers/promise.js:26:23
    at AsyncResource.runInAsyncScope (node:async_hooks:203:9)

[kcveitch]

I suspect this might be related to https://github.com/DataDog/dd-trace-js/pull/3186

I dug into my db query logging and I'm seeing prepared statement queries with upwards of 40+ of the following comments prepended onto the statement:

/*dddbs='redacted-db-name',dde='stage',ddps='redacted-service-name',ddpv='305'*/ 
/*dddbs='redacted-db-name',dde='stage',ddps='redacted-service-name',ddpv='305'*/ 
/*dddbs='redacted-db-name',dde='stage',ddps='redacted-service-name',ddpv='305'*/ 
/*dddbs='redacted-db-name',dde='stage',ddps='redacted-service-name',ddpv='305'*/ 
/*dddbs='redacted-db-name',dde='stage',ddps='redacted-service-name',ddpv='305'*/ 
/*dddbs='redacted-db-name',dde='stage',ddps='redacted-service-name',ddpv='305'*/ 
/*dddbs='redacted-db-name',dde='stage',ddps='redacted-service-name',ddpv='305'*/ 
...
SELECT yadda yadda yadda...

I'm gonna trey disabling DD_DBM_PROPAGATION_MODE: "full" and will post results

[kcveitch]

i think our issue is a combination of https://github.com/DataDog/dd-trace-js/commit/d7c7dfb1ee9b6e484e60083e7779bd659727db34 and https://github.com/DataDog/dd-trace-js/commit/4a1e4a600e848fdb9fc9d7e22178855e2f

It looks like the intent was to remove the traceparent ID from prepared comment injection into the query to prevent each query from being classified as a unique use of the named prepared statement and colliding.

query.__ddInjectableQuery = this.injectDbmQuery(query.text, service, !!query.name)

  injectDbmQuery (query, serviceName, isPreparedStatement = false) {
    if (this.config.dbmPropagationMode === 'disabled') {
      return query
    }
    const servicePropagation = this.createDBMPropagationCommentService(serviceName)
    if (isPreparedStatement || this.config.dbmPropagationMode === 'service') {           <<<<<-----------------  HERE
      return `/*${servicePropagation}*/ ${query}`    
    } else if (this.config.dbmPropagationMode === 'full') {
      this.activeSpan.setTag('_dd.dbm_trace_injected', 'true')
      const traceparent = this.activeSpan._spanContext.toTraceparent()
      return `/*${servicePropagation},traceparent='${traceparent}'*/ ${query}`
    }
  }
}

However it looks like at least in the lambda case, multiple invocations are reusing the previously appended query as the base query and prepending the comment to it again. Which effectively causes the same problem we were trying to avoid in the first place. Someone who is more familiar with how this is invoked will need to dig further. But the following (customer data redacted) debug logs show it pretty clearly.

2023-11-14T15:47:22.603Z    ea075bdc-3eac-4e31-9f02-ef362f043621    INFO    [dd.trace_id=6176123562029933226 dd.span_id=8391433016477006182] Error: Prepared statements must be unique - 'InsertMarketNotifications' was used for a different statement
    at wo.submit (/tmp/tmpmkggk4vf/node_modules/pg/lib/query.js:156:14)
    at ti._pulseQueryQueue (/tmp/tmpmkggk4vf/node_modules/pg/lib/client.js:486:45)
    at ti.query (/tmp/tmpmkggk4vf/node_modules/pg/lib/client.js:586:10)
    at /opt/nodejs/node_modules/dd-trace/packages/datadog-instrumentations/src/pg.js:71:28
    at exports.AsyncResource.runInAsyncScope (node:async_hooks:203:9)
    at ti.query (/opt/nodejs/node_modules/dd-trace/packages/datadog-instrumentations/src/pg.js:55:26)
    at executor (/tmp/tmpmkggk4vf/node_modules/pg-promise/lib/query.js:156:27)
    at E.e._execute (/tmp/tmpmkggk4vf/node_modules/bluebird/js/release/debuggability.js:384:9)
    at E.E._resolveFromExecutor (/tmp/tmpmkggk4vf/node_modules/bluebird/js/release/promise.js:518:18)
    at E (/tmp/tmpmkggk4vf/node_modules/bluebird/js/release/promise.js:103:10)
    at $p (/tmp/tmpmkggk4vf/node_modules/pg-promise/lib/promise-parser.js:30:20)
    at lT.LC (/tmp/tmpmkggk4vf/node_modules/pg-promise/lib/query.js:145:12)
    at lT.<anonymous> (/tmp/tmpmkggk4vf/node_modules/pg-promise/lib/query.js:277:23)
    at db (/tmp/tmpmkggk4vf/node_modules/pg-promise/lib/database.js:333:42)
    at /opt/nodejs/node_modules/dd-trace/packages/datadog-instrumentations/src/helpers/promise.js:26:23
    at AsyncResource.runInAsyncScope (node:async_hooks:203:9) {
  query: {
    name: 'InsertMarketNotifications',
    text: [Getter],
    values: [
      'REDACTED-VALUE',
      'REDACTED-VALUE',
      'submitted',
      '2023-11-14T15:32:22.511Z',
      '2023-11-15',
      2
    ],
    __ddInjectableQuery: "/*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',
    dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /
    *dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',
    REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /
    *dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',
    REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /
    *dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',
    REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /
    *dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',
    REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /
    *dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',
    REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /
    *dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',
    REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /
    *dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',
    REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /
    *dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',
    REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /
    *dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',
    REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ /*dddbs='REDACTED-NAME',dde='stage',REDACTED-OTHER-NAME',ddpv='305'*/ INSERT INTO 
    redacted_schema.market_notifications ( some-id, external_id, market_status_id, submitted_date, trading_date, created_by_id) select $1, $2, (select id from redacted_schema.market_status where 
    market_status_name = $3) as market_status_id, $4, $5, $6 WHERE NOT EXISTS (SELECT 1 FROM redacted_schema.market_notifications WHERE some-id = $1 AND external_id = $2 AND submitted_date = $4)
     RETURNING id",
    callback: [Function (anonymous)]
  },
  params: undefined
}