APM missing SQL Span (NestJS/Typeorm/SQL Server)

Tam2 · December 8, 2021, 1:26pm

I've got a NestJS monorepo and i'm loading in the elastic-apm-node at the top of the main.ts file:

require('elastic-apm-node').start({
  // Override the service name from package.json
  // Allowed characters: a-z, A-Z, 0-9, -, _, and space
  serviceName: 'api',

  // Use if APM Server requires a secret token
  secretToken: '<token>',

  // Set the custom APM Server URL (default: http://localhost:8200)
  serverUrl:
    '<server_url>',

  // Set the service environment
  environment: process.env.NODE_ENV,
  cloudProvider: 'none',
  captureBody: 'all',
});

I can see the HTTP requests properly labelled however the traces are missing the SQL spans

Elastic APM Logs:

{"log.level":"debug","@timestamp":"2021-12-08T13:25:03.456Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted request event call to http.Server.prototype.emit for /stock/inventory/9823"}
{"log.level":"debug","@timestamp":"2021-12-08T13:25:03.457Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start trace {\"trans\":\"7b1bae9fb898237a\",\"trace\":\"54a93045decc466de194252e06b0f62c\",\"name\":\"unnamed\",\"type\":null,\"subtype\":null,\"action\":null}"}
{"log.level":"debug","@timestamp":"2021-12-08T13:25:03.458Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"setting default transaction name: GET /stock/inventory/:id {\"trans\":\"7b1bae9fb898237a\",\"trace\":\"54a93045decc466de194252e06b0f62c\"}"}
{"log.level":"debug","@timestamp":"2021-12-08T13:25:03.494Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"setting transaction result {\"trans\":\"7b1bae9fb898237a\",\"trace\":\"54a93045decc466de194252e06b0f62c\",\"result\":\"HTTP 2xx\"}"}
{"log.level":"debug","@timestamp":"2021-12-08T13:25:03.495Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"sending transaction {\"trans\":\"7b1bae9fb898237a\",\"trace\":\"54a93045decc466de194252e06b0f62c\"}"}
{"log.level":"debug","@timestamp":"2021-12-08T13:25:03.496Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"ended transaction {\"trans\":\"7b1bae9fb898237a\",\"trace\":\"54a93045decc466de194252e06b0f62c\",\"type\":\"request\",\"result\":\"HTTP 2xx\",\"name\":\"GET /stock/inventory/:id\"}"}
{"log.level":"trace","@timestamp":"2021-12-08T13:25:03.528Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","fullTimeMs":0.1722,"numEvents":1,"numBytes":1178,"ecs":{"version":"1.6.0"},"message":"_write: encode object"}
{"log.level":"trace","@timestamp":"2021-12-08T13:25:05.044Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"e8984bbe9c64f05cf884605429016425","ecs":{"version":"1.6.0"},"message":"gzipStream \"finish\""}
{"log.level":"trace","@timestamp":"2021-12-08T13:25:05.045Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"e8984bbe9c64f05cf884605429016425","timeout":10000,"ecs":{"version":"1.6.0"},"message":"start intakeResTimer"}
{"log.level":"trace","@timestamp":"2021-12-08T13:25:05.045Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"e8984bbe9c64f05cf884605429016425","ecs":{"version":"1.6.0"},"message":"gzipStream \"end\""}
{"log.level":"trace","@timestamp":"2021-12-08T13:25:05.045Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"e8984bbe9c64f05cf884605429016425","concluded":false,"ecs":{"version":"1.6.0"},"message":"completePart gzipStream"}
{"log.level":"trace","@timestamp":"2021-12-08T13:25:05.046Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"e8984bbe9c64f05cf884605429016425","ecs":{"version":"1.6.0"},"message":"intakeReq \"finish\""}
{"log.level":"trace","@timestamp":"2021-12-08T13:25:05.046Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"e8984bbe9c64f05cf884605429016425","concluded":false,"ecs":{"version":"1.6.0"},"message":"completePart intakeReq"}
{"log.level":"trace","@timestamp":"2021-12-08T13:25:05.092Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"e8984bbe9c64f05cf884605429016425","statusCode":202,"reqFinished":true,"ecs":{"version":"1.6.0"},"message":"intakeReq \"response\""}
{"log.level":"trace","@timestamp":"2021-12-08T13:25:05.093Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"e8984bbe9c64f05cf884605429016425","ecs":{"version":"1.6.0"},"message":"intakeRes \"end\""}
{"log.level":"trace","@timestamp":"2021-12-08T13:25:05.093Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"e8984bbe9c64f05cf884605429016425","concluded":false,"ecs":{"version":"1.6.0"},"message":"completePart intakeRes"}
{"log.level":"trace","@timestamp":"2021-12-08T13:25:05.093Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"e8984bbe9c64f05cf884605429016425","timeline":[[10008.921,"completePart gzipStream",null],[10009.3674,"completePart intakeReq",null],[10056.5654,"completePart intakeRes",null]],"bytesWritten":2811,"backoffDelayMs":0,"ecs":{"version":"1.6.0"},"message":"conclude intake request: success"}
{"log.level":"trace","@timestamp":"2021-12-08T13:25:11.819Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"d84003da4f1d0be521db52785e14f80c","ecs":{"version":"1.6.0"},"message":"intake request start"}
{"log.level":"trace","@timestamp":"2021-12-08T13:25:11.819Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","encodeTimeMs":0.5345,"fullTimeMs":1.5251,"numEvents":7,"numBytes":2520,"ecs":{"version":"1.6.0"},"message":"_writeBatch"}
{"log.level":"trace","@timestamp":"2021-12-08T13:25:11.819Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"d84003da4f1d0be521db52785e14f80c","ecs":{"version":"1.6.0"},"message":"intakeReq \"socket\": unref it"}

alanstorm · December 8, 2021, 4:33pm

@Tam2 sorry to hear you're running into an issue, let's see if we can get you up and running.

Question: What library are you using to make your SQL queries? Can you share some sample code?

Tam2 · December 8, 2021, 4:48pm

I'm using Typeorm with SQL Server, which i believe uses node-mssql with the Tedious driver

I thought the issue might be because i'm building the monorepo with webpack, so i changed it to just use tsc for built and still doesn't seem to work.

The other spans for redis and Elasticsearch work, just seems to be the SQL Server that's not being picked up.

Not sure what code to share that would be helpful, as above i'm requiring the elastic-apm-node in my main.ts file and then within my app.module.ts file i'm setting up TypeORM like this:

    TypeOrmModule.forRootAsync({
      imports: [ConfigModule],
      useFactory: async (configService: ConfigService) => ({
        type: 'mssql',
        host: configService.get('database.host'),
        port: parseInt(configService.get('database.port')),
        username: configService.get('database.username'),
        password: configService.get('database.password'),
        options: {
          enableArithAbort: true,
          trustServerCertificate: true,
        },
        pool: {
          min: 0,
          max: 100,
        },
        maxQueryExecutionTime: 500,
        logger: 'advanced-console',
        autoLoadEntities: true,
      }),
      inject: [ConfigService],
    }),

Then an example of an actual SQL query within the service:

async getById(clientId: number, pageId: number): Promise<Navigation> {
    return await this.navigationRepository
      .createQueryBuilder('navigation')
      .where('navigation.id = :pageId', { pageId: pageId })
      .andWhere('navigation.status = :status', { status: Status.ACTIVE })
      .andWhere('navigation.clientId = :clientId', { clientId: clientId })
      .getOne();
  }

An example of a controller calling the service:

  @Version('1')
  @Get(':id')
  async getById(
    @ClientId() clientId,
    @Param() params,
  ): Promise<PageResponseWrapperDTO> {
    const navigation = await this.navigationService.getById(
      clientId,
      params.id,
    );

    if (navigation) {
      const markup = await this.markupService.getById(
        params.id,
        RelatedType.Navigation,
        clientId,
      );
      const content = await this.contentService.getById(
        params.id,
        RelatedType.Navigation,
      );
      const assets = await this.assetService.getById(
        clientId,
        params.id,
        RelatedType.Navigation,
      );

      return new PageResponseWrapperDTO(navigation, markup, content, assets);
    } else {
      throw new NotFoundException();
    }
  }

alanstorm · December 8, 2021, 5:19pm

Thanks @Tam2, that's a good start. We do support node-mssql and tedious, but we don't explicitly support TypeORM.

Next follow up question: How are you invoking node, and what order does your compiled output load modules in? I ask because APM Agents need to be the first thing loaded and many compilers will reorder the loading order of the modules. If one of the three modules you're using for DB queries gets in inadvertently loaded before the agent, that module won't be instrumented.

We recommend that you start node with a -r elastic-apm-node/start flag when using typescript. This will ensure the agent is the first thing loaded.

Could you give that a try and let us know if it fixes the problem? If not we'll move on to looking at how TypeORM works and determine what (if anything) is preventing those DB spans from being created.

Tam2 · December 9, 2021, 11:27pm

I think i might have found the issue in the logs when it's starting up

tedious version 11.8.0 not supported - aborting...

{"log.level":"debug","@timestamp":"2021-12-09T23:24:48.003Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming tedious@11.8.0 module"}
{"log.level":"debug","@timestamp":"2021-12-09T23:24:48.006Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"tedious version 11.8.0 not supported - aborting..."}

In another version of the app it uses an older tedious version and that seems to work

{"log.level":"debug","@timestamp":"2021-12-09T23:26:39.459Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming tedious@6.7.1 module"}

This looks to be caused by this which means only up till version 9 of tedious is supported?

github.com

elastic/apm-agent-nodejs/blob/751b9b2a154ed5b50a7306bfdf129c04845a3333/lib/instrumentation/modules/tedious.js#L11

    
      
          'use strict'
          
          
var semver = require('semver')
          var clone = require('shallow-clone-shim')
          var sqlSummary = require('sql-summary')
          
          
var { getDBDestination } = require('../context')
          
          
module.exports = function (tedious, agent, { version, enabled }) {
            if (!enabled) return tedious
            if (!semver.satisfies(version, '^1.9.0 || 2.x || 3.x || ^4.0.1 || 5.x || 6.x || 7.x || 8.x || 9.x')) {
              agent.logger.debug('tedious version %s not supported - aborting...', version)
              return tedious
            }
          
          
  const ins = agent._instrumentation
          
          
  return clone({}, tedious, {
              Connection (descriptor) {
                const getter = descriptor.get
                if (getter) {

Removing this restriction in a local copy means it does start up correctly

{"log.level":"debug","@timestamp":"2021-12-09T23:33:14.010Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming tedious@11.8.0 module"}

And the SQL spans are showing, but the actual queries are not showing

Tam2 · December 9, 2021, 11:58pm

This looks to be the cause of the queries not showing:

github.com

elastic/apm-agent-nodejs/blob/751b9b2a154ed5b50a7306bfdf129c04845a3333/lib/instrumentation/modules/tedious.js#L79

    
      
          if (!request.parametersByName) {
            return super.makeRequest(...arguments)
          }
          const span = agent.startSpan(null, 'db', 'mssql', 'query')
          if (!span) {
            return super.makeRequest(...arguments)
          }
          
          
const preparing = request.sqlTextOrProcedure === 'sp_prepare'
          const params = request.parametersByName
          const sql = (params.statement || params.stmt || {}).value
          span.name = sqlSummary(sql) + (preparing ? ' (prepare)' : '')
          span.setDbContext({ statement: sql, type: 'sql' })
          // extract hostname and port from connection config
          let host, port
          if (typeof this.config === 'object') {
            host = this.config.server
            port = this.config.options && this.config.options.port
          }
          span.setDestinationContext(getDBDestination(span, host, port))

Logging the request object shows this (request.parametersByName.statement/stmt don't exist)

{
  "_events": {},
  "_eventsCount": 5,
  "sqlTextOrProcedure": "SELECT \"asset\".\"Id\" AS \"asset_Id\", \"asset\".\"AssetType\" AS \"asset_AssetType\", \"asset\".\"ScrapName\" AS \"asset_ScrapName\", \"images\".\"Id\" AS \"images_Id\", \"images\".\"Filename\" AS \"images_Filename\", \"images\".\"Caption\" AS \"images_Caption\", \"images\".\"Url\" AS \"images_Url\", \"images\".\"AssetId\" AS \"images_AssetId\", \"snippet\".\"Id\" AS \"snippet_Id\", \"snippet\".\"Snippet\" AS \"snippet_Snippet\", \"assetContent\".\"Id\" AS \"assetContent_Id\", \"assetContent\".\"Article\" AS \"assetContent_Article\", @0 AS \"images_clientId\" FROM \"ComposerWeb\"..\"Assets\" \"asset\" LEFT JOIN \"ComposerWeb\"..\"AssetImages\" \"images\" ON \"images\".\"AssetId\"=\"asset\".\"Id\"  LEFT JOIN \"ComposerWeb\"..\"AssetSnippets\" \"snippet\" ON \"snippet\".\"Id\"=\"asset\".\"Id\"  LEFT JOIN \"ComposerWeb\"..\"AssetContents\" \"assetContent\" ON \"assetContent\".\"Id\"=\"asset\".\"Id\" WHERE \"asset\".\"RelatedId\" = @1 AND \"asset\".\"RelatedType\" = @2 ORDER BY \"asset\".\"Priority\" ASC",
  "parameters": [
    {
      "type": {
        "id": 231,
        "type": "NVARCHAR",
        "name": "NVarChar",
        "maximumLength": 4000
      },
      "name": "0",
      "value": "12",
      "output": false
    },
    {
      "type": {
        "id": 231,
        "type": "NVARCHAR",
        "name": "NVarChar",
        "maximumLength": 4000
      },
      "name": "1",
      "value": "21",
      "output": false
    },
    {
      "type": {
        "id": 56,
        "type": "INT4",
        "name": "Int"
      },
      "name": "2",
      "value": 1,
      "output": false
    }
  ],
  "parametersByName": {
    "0": {
      "type": {
        "id": 231,
        "type": "NVARCHAR",
        "name": "NVarChar",
        "maximumLength": 4000
      },
      "name": "0",
      "value": "12",
      "output": false
    },
    "1": {
      "type": {
        "id": 231,
        "type": "NVARCHAR",
        "name": "NVarChar",
        "maximumLength": 4000
      },
      "name": "1",
      "value": "21",
      "output": false
    },
    "2": {
      "type": {
        "id": 56,
        "type": "INT4",
        "name": "Int"
      },
      "name": "2",
      "value": 1,
      "output": false
    }
  },
  "preparing": false,
  "canceled": false,
  "paused": false,
  "statementColumnEncryptionSetting": 0,
  "cryptoMetadataLoaded": false
}

Changing this line to the below solves the problem and the spans and queries show up

const sql = request.sqlTextOrProcedure ? request.sqlTextOrProcedure : {};

I think an change is required to the elastic-apm-node agent to work with later versions of tedious, seems like a pretty simple fix to add support in for 11.x by also looking for the statement in request.sqlTextOrProcedure

system · December 30, 2021, 7:58pm

This topic was automatically closed 20 days after the last reply. New replies are no longer allowed.