APM agent crashes NodeJs after reporting exception in tedious instrumentation Code

astorm commented 3 years ago

From: https://discuss.elastic.co/t/apm-agent-crashes-nodejs-after-reporting-exception-in-tedious-instrumentation-code/259851

Kibana version: 7.8.1 (flavor:default, type:docker)

Elasticsearch version: 7.8.1 (flavor:default, type:docker)

APM Server version: 7.8.1 (flavor:default, type:docker)

APM Agent language and version: Elastic-apm-node v3.9.0

NodeJs version: 12.16.2

Browser version: Not relevant as server side

Original install method (e.g. download page, yum, deb, from source, etc.) and version:

docker image from https://hub.docker.com/_/elasticsearch
Elastic-apm-node from NPM central trough corporate Nexus sonatype

Fresh install or upgraded from other version? : Fresh install

Description of the problem including expected versus actual behavior. Please include screenshots (if relevant): Elastic-apm-node v3.9.0 crashes NodeJs running NestJs server after sending report due to exception in tedious instrumentation while executing bulk insert in MS.Sql DB Last log I get is Sending error to Elastic APM { id: '17a9b49682b3da680437918195822005' } NodeJs stopped just after that

NodeJs always stop due to the same error when the application execute the bulk. And, just in case you are wondering, it works just fine when APM agent is disabled.

Fortunately the error is sent to APM and can see the detail in Kibana We can see that root cause of the exception is an Null reference on the request params

APM-ExceptionStack

Steps to reproduce: There is only one bulk insert in the all application so easy to spot Below is a code extract

    const connection: Promise<mssql.ConnectionPool> = getConnection();
    //Prepare table  insert into Temp table data for current Session and list ids
    const tmpSessionIds = new mssql.Table("tmp_list");
    tmpSessionIds.create = false;
    tmpSessionIds.columns.add("sessionId", mssql.NVarChar(80), { nullable: false });
    tmpSessionIds.columns.add("identifier", mssql.NVarChar(50), { nullable: false });
    for (let i = 0; i < positions.length; i++) {
      tmpSessionIds.rows.add(sessionId, identifiers[i]);
    }
    const InsertResult = await new Promise((resolve, reject) => {
      connection.then((x) =>
        x.request().bulk(tmpSessionIds, function (err, rowCount) {
          if (err) {
            reject(err);
          } else {
            resolve(rowCount);
          }
        })
      );
    });

Provide logs and/or server output (if relevant):

Exception stack trace

Cannot read property 'statement' of undefined

node_modules\elastic-apm-node\lib\instrumentation\modules\tedious.js in makeRequest at line 75
node_modules\tedious\lib\connection.js in Request.<anonymous> at line 1619
node_modules\elastic-apm-node\lib\instrumentation\modules\tedious.js in Request.userCallback at line 93
node_modules\tedious\lib\request.js in Request.callback at line 56
node_modules\tedious\lib\connection.js in endOfMessageMarkerReceived at line 2407
node_modules\tedious\lib\connection.js in dispatchEvent at line 1279
node_modules\tedious\lib\connection.js in Parser.<anonymous> at line 1072
events.js in emit at line 310
node_modules\tedious\lib\token\token-stream-parser.js in Parser.<anonymous> at line 37
events.js in emit at line 310
node_modules\tedious\node_modules\readable-stream\lib\_stream_readable.js in addChunk at line 298
node_modules\tedious\node_modules\readable-stream\lib\_stream_readable.js in readableAddChunk at line 280
node_modules\tedious\node_modules\readable-stream\lib\_stream_readable.js in Readable.push at line 241
node_modules\tedious\node_modules\readable-stream\lib\_stream_transform.js in Transform.push at line 139
node_modules\tedious\node_modules\readable-stream\lib\_stream_transform.js in afterTransform at line 88
node_modules\tedious\lib\token\stream-parser.js in _transform at line 88
node_modules\tedious\node_modules\readable-stream\lib\_stream_transform.js in Transform._read at line 177
node_modules\tedious\node_modules\readable-stream\lib\_stream_transform.js in Transform._write at line 164
node_modules\tedious\node_modules\readable-stream\lib\_stream_writable.js in doWrite at line 409
node_modules\tedious\node_modules\readable-stream\lib\_stream_writable.js in writeOrBuffer at line 398
node_modules\tedious\node_modules\readable-stream\lib\_stream_writable.js in Writable.write at line 307
node_modules\tedious\lib\token\token-stream-parser.js in addEndOfMessageMarker at line 55
node_modules\tedious\lib\connection.js in message at line 2396
node_modules\tedious\lib\connection.js in dispatchEvent at line 1279
node_modules\tedious\lib\connection.js in MessageIO.<anonymous> at line 1139
events.js in emit at line 310
node_modules\tedious\lib\message-io.js in Message.<anonymous> at line 46
events.js in emit at line 322
node_modules\tedious\node_modules\readable-stream\lib\_stream_readable.js in endReadableNT at line 1094
internal/process/task_queues.js in processTicksAndRejections at line 84

Environment NodeJs : v12.16.2 Extract of package.json

    "@elastic/elasticsearch": "^7.10.0",
    "@nestjs/common": "^7.0.8",
    "@nestjs/core": "^7.0.8",
    "@nestjs/platform-express": "^7.0.8",
    "@nestjs/serve-static": "^2.1.0",
    "@nestjs/swagger": "^4.5.1",
    "@nestjs/typeorm": "^7.0.0",
    "@types/express-session": "^1.17.0",,
    "@types/mssql": "^6.0.0",
    "elastic-apm-node": "^3.9.0",
    "express-session": "^1.17.0",
    "log4js": "^6.2.0",
    "mssql": "^6.2.0",
    "typeorm": "^0.2.24"

astorm commented 3 years ago

It looks like our wrapper for the makeRequest method can't handle an argument that's missing its parametersByName property. This seems to be a legitimate use -- makeRequest is capable of accepting an BulkLoad object in addition to a Request object

https://github.com/tediousjs/tedious/blob/a1a2625712bd440f2c65970615e54e361fe23aac/src/connection.ts#L3130

I have not, however, been able to reproduce the behavior of a BulkLoad object being passed into the connection object's makeRequest method. It looks like the only place this happens in core tedious code is here

https://github.com/tediousjs/tedious/blob/a1a2625712bd440f2c65970615e54e361fe23aac/src/connection.ts#L2858

which is after tedious has generated the SQL for a bulk load. The code currently isn't organized in a way that makes "reproducing this fatal error under test" simple (especially without specific tedious knowledge).

Since this is a crasher I'm going to recommend a two phase approach

Phase 1: Get get out a quick patch that simply bails on instrumentation if the parameter if parametersByName is missing
Phase 2: Take a more considered approach as to how we want to instrument bulk inserts and how best to mock out the various parts of tedious and the agent to do this

astorm commented 3 years ago

Draft PR with a quick fix -- https://github.com/elastic/apm-agent-nodejs/pull/1935

will reach out to customer/user to see if they can test this vs. their crasher.

trentm commented 2 years ago

Draft PR with a quick fix -- #1935

@astorm Perhaps we could close this now?

elastic / apm-agent-nodejs

APM agent crashes NodeJs after reporting exception in tedious instrumentation Code #1934