spdy: No active transaction found - cannot build new span

[boriskogan81]

I am trying to set up the agent in my Node app. I am not seeing logs; when I set logLevel to trace, I see these sorts of errors:

(on a route which makes a call to an Elasticsearch instance):

2019-04-03T11:09:15.183Z | INFO | Events GET attempt by 
no active transaction found - cannot build new span
intercepted call to elasticsearch.Transport.prototype.request { id: null, method: 'POST', path: '/sb-app-events-*/_search' }
could not instrument elasticsearch request { id: null }
no active transaction found - cannot build new span

(on a route which makes a call to a MySQL backend):

2019-04-03T11:09:15.180Z | INFO | GET user preferences attempt by 
capturing custom stack trace for knex
shimming knex runner.query
intercepted call to knex runner.query
no active transaction found - cannot build new span
intercepted call to mysql connection.query { id: null }

Expected behavior I'd like to trace transactions with the APM agent.

Environment (please complete the following information)

• OS: Windows 10
• Node.js version: 10.14.2
• APM Server version: 6.4.7
• Agent version:2.7.1

How are you starting the agent? (please tick one of the boxes)

• [x] Calling agent.start() directly (e.g. require('elastic-apm-node').start(...))

• [ ] Requiring elastic-apm-node/start from within the source code

• [ ] Starting node with -r elastic-apm-node/start

• Agent config options

  Click to expand

const apm = require('elastic-apm-node').start({
    // Set custom APM Server URL (default: http://localhost:8200)
    serverUrl: "http://server-address:8200",
    logLevel: 'trace'
})

• package.json dependencies:
  Click to expand

    "bcrypt": "^3.0.5",
    "blt-http2-router": "^0.5.4404",
    "blt-log": "^0.5.3564",
    "blt-smc-event-types-subtypes": "^0.5.5941",
    "blt-web-utils": "^0.5.3314",
    "body-parser": "^1.18.3",
    "bookshelf": "^0.14.2",
    "bookshelf-json-columns": "^2.1.1",
    "bookshelf-upsert": "^0.2.0",
    "connect-timeout": "^1.9.0",
    "cookie-parser": "~1.4.4",
    "debug": "~4.1.1",
    "dotenv": "^6.2.0",
    "elastic-apm-node": "^2.7.1",
    "elasticsearch": "^15.4.1",
    "express": "^4.16.4",
    "express-fileupload": "latest",
    "express-ipfilter": "^0.3.1",
    "http-errors": "~1.7.2",
    "jwt-simple": "^0.5.5",
    "kafka-streams": "^4.8.0",
    "knex": "^0.16.3",
    "knex-migrate": "^1.7.2",
    "knex-schema-reader": "git+https://git@github.com/mattjcowan/knex-schema-reader.git",
    "lodash": "^4.17.11",
    "moment": "latest",
    "morgan": "^1.9.1",
    "mysql": "^2.16.0",
    "mysql2": "^1.6.5",
    "nock": "^10.0.6",
    "parse-error": "^0.2.0",
    "passport": "^0.4.0",
    "passport-jwt": "^4.0.0",
    "pug": "2.0.3",
    "query-string": "^6.4.2",
    "request": "^2.88.0",
    "request-ip": "^2.1.3",
    "request-promise-native": "^1.0.7",
    "spdy": "^4.0.0",
    "sqlite": "^3.0.3",
    "uuid4": "^1.1.4",
    "validator": "^10.11.0",
    "winston": "^3.2.1",
    "winston-daily-rotate-file": "^3.8.0"

[watson]

When the agent boots up with logLevel: 'trace' it will output a lot of information about which modules it's shimming. Could I get you to paste that log output here?

[boriskogan81]

Sure!

Shims

``` "C:\Program Files\nodejs\node.exe" ./bin/www adding hook to Node.js module loader shimming finalhandler@1.1.1 module shimming http@10.14.2 module shimming http.Server.prototype.emit function shimming http.request function shimming http.get function shimming http.ServerResponse.prototype.writeHead function shimming express@4.16.4 module shimming express.Router.use function shimming express.static function copying property mime from express.static ../config/env is invalid, moving on to the next path shimming bluebird@3.5.3 module shimming bluebird.prototype functions: [ '_then', '_addCallbacks' ] shimming bluebird.config shimming knex@0.16.3 module shimming Knex.Client.prototype.runner shimming Knex.Client.prototype functions: [ 'queryBuilder', 'raw' ] shimming mysql@2.16.0 module shimming mysql.createPool shimming mysql.createPoolCluster shimming mysql.createConnection capturing custom stack trace for knex shimming bluebird@3.5.1 module shimming bluebird.prototype functions: [ '_then', '_addCallbacks' ] shimming bluebird.config shimming https@10.14.2 module shimming https.Server.prototype.emit function shimming https.request function shimming https.get function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming bluebird@3.5.3 module shimming bluebird.prototype functions: [ '_then', '_addCallbacks' ] shimming bluebird.config shimming bluebird@3.5.3 module shimming bluebird.prototype functions: [ '_then', '_addCallbacks' ] shimming bluebird.config 2019-04-03T10:47:58.645Z | INFO | starting Producer. 2019-04-03T10:47:58.646Z | INFO | [Publisher] buffer disabled. 2019-04-03T10:47:58.647Z | INFO | starting Producer. 2019-04-03T10:47:58.647Z | INFO | [Publisher] buffer disabled. 2019-04-03T10:47:58.649Z | INFO | starting ConsumerGroup for topic: ["sample-results"] 2019-04-03T10:47:58.649Z | INFO | [Drainer] started drain process. 2019-04-03T10:47:58.650Z | INFO | starting Producer. 2019-04-03T10:47:58.650Z | INFO | [Publisher] buffer disabled. shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming elasticsearch@15.4.1 module shimming elasticsearch.Transport.prototype.request shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function capturing custom stack trace for knex shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function shimming express.Router.Layer.handle function ```

[watson]

Thanks. That all looks ok. I was mostly curious to see if it correctly picked up the http module as that's required in order to be notified about incoming HTTP requests (without which the agent will not be able to automatically create transactions).

For each incoming HTTP request, the agent should log this debug output:

intercepted request event call to http.Server.prototype.emit

Do you see that?

[boriskogan81]

Nope.

[watson]

🤔 That's odd. This would explain why there are no active transactions, and hence why the agent can't build any spans. But I can't see how this would happen unless your application isn't using the built in HTTP server from Node.js core.

Would it be possible for you to create a small test application that issolates this problem so we can better debug it?

[boriskogan81]

If I just run an express server returning Hello World as per the basic express docs, and add the apm agent, it works.

[boriskogan81]

Hold on-I'm using SPDY to wrap the app to allow HTTP2 connections. Could this be it?

[watson]

In your application that has this problem, would it be possible for you to do the following:

1. Start the application with logLevel: 'trace'
2. Send a single HTTP request to one of its endpoints
3. Paste the resulting log from start till finish here - i.e. the entire log from when you started the server till it finished responding to the HTTP request

That way I can see more of what happens around the time where the HTTP request is handled by the app.

[boriskogan81]

That's it.

This works:

app
    .listen(httpConfig.port, httpConfig.host, (error) => {
        if (error) {
            console.error(error);
            return process.exit(1);
        }
        logger.info(`Security center API running on`, {host: httpConfig.host, port: httpConfig.port});
    });

This fails:

spdy
    .createServer(options, app)
    .listen(httpConfig.port, httpConfig.host, (error) => {
        if (error) {
            logger.error(`Backend spdy server failed `, {error});
            apm.captureError(error)
            return process.exit(1);
        }

        logger.info(`Security center API running`, {host: httpConfig.host, port: httpConfig.port});
    });

[watson]

Oh, didn't see your SPDY/HTTP2 comment... never mind. That might be the issue

[boriskogan81]

So how can I make this work with SPDY?

[watson]

Good question. I think SPDY uses the underlying net module and operates on the raw TCP socket. If you used the built in http2 from Node.js core, it should work, but I don't think it does with the spdy module - which would also explain your issue.

For this to work you will have to start and stop transactions manually. For more information on how to do that, see the Custom Transactions part of our documentation.

[boriskogan81]

Okay. Let's say that I have a flow like this: 1) An HTTP2 request comes through on a SPDY route. I set up a custom transaction. 2) I then send an HTTP2 request to another service from within that route. 3) The other service gets this request.

How do I get the transaction from this second request inside the route of the second service?

I have a similar question about Kafka, using Kafka Node, but that should probably be a separate issue.

[watson]

If I understand your question correctly, then you're asking about distributed tracing, i.e. how to tie two or more transactions together in a trace that spans multiple services?

To do that, each outgoing HTTP request needs to have a special header with information about the ongoing trace. By default, the Node.js agent will add this header for you on all outgoing HTTP/HTTPS requests. But I think maybe we don't support that for HTTP2. I'll have to look more into this.

On the receiving end, the agent will automatically pick up this HTTP header if the request is using HTTP/HTTPS - but again, not HTTP2 if I recall correctly.

We have a PR open to make it possible for you to manually add these headers to outgoing requests, but right now there's, unfortunately, no public API for this.

To continue a trace when starting a new transaction manually, you can use the 3rd options argument to supply the parent using the childOf option: https://www.elastic.co/guide/en/apm/agent/nodejs/current/agent-api.html#apm-start-transaction

But bottom line is that there's no public API ready yet for you to serialize the data when making the outgoing HTTP2 request. So you either have to resort to using a private API (which might break later) or wait a little till we release a version which support this (which should be soon).

[boriskogan81]

That is exactly what I'm asking.

How soon do you think the version will come out?

[watson]

I hope next week - but no promises.

In the meantime, you could use this code here for inspiration on how to add the header manually yourself (this is the code that currently adds it to outgoing HTTP requests):

https://github.com/elastic/apm-agent-nodejs/blob/853c9ddde1ce2d671e3d478e103edeeac5f29539/lib/instrumentation/http-shared.js#L122-L130

[watson]

FYI: The API for getting the traceparent is now public and has just landed in v2.9.0:

3 new getters have been added from which you can get the traceparent string:

• agent.currentTraceparent
• span.traceparent
• transaction.traceparent

[watson]

Did you try out the new traceparent api?

[boriskogan81]

Yes, works great, thanks!