elastic / apm-agent-nodejs

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

React.JS Next.JS SPDY No data in elastic apm for nodejs application #3413

Closed khteh closed 1 year ago

khteh commented 1 year ago

Describe the bug

I put the following code snippet at the top of the first file loaded server.js:

var apm = require('elastic-apm-node').start({
  // Override service name from package.json
  // Allowed characters: a-z, A-Z, 0-9, -, _, and space
  serviceName: 'my-apm',
  // Set custom APM Server URL (default: http://127.0.0.1:8200)
  serverUrl: 'https://my-apm-http:8200',
  // Only activate the agent if it's running in production
  active: process.env.NODE_ENV === 'production',
  verifyServerCert: false
})

However, there is no data at all in kibana 8.8.0. I have also tried putting this config in elastic-apm-node.js but to no avail.

To Reproduce

Steps to reproduce the behavior:

  1. Use this config '...'
  2. Then call '....'
  3. Then do '....'
  4. See error

Expected behavior

Environment (please complete the following information)

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

Additional context

Agent config options:

Click to expand ``` replace this line with your agent config options ```

package.json dependencies:

Click to expand ``` replace this line with your dependencies section from package.json ```
trentm commented 1 year ago

@khteh Thanks for the question.

The best way to try to confirm what is happening would be to get trace-level logging from the APM agent as it is running. This can be done by setting the ELASTIC_APM_LOG_LEVEL=trace environment variable (or adding logLevel: 'trace' to your config) and re-running.

Here are some guesses as to what the issue might be and questions to try to find the issue:

  1. The support for Next.js attempts to instrument the Next server. Depending how you are running your Next.js application, using require('elastic-apm-node').start({...}) at the top of your "server.js" might be too late, because the Next server will have already initialized before calling your "server.js". https://www.elastic.co/guide/en/apm/agent/nodejs/master/nextjs.html suggests that for Next.js you start the APM agent using the --require elastic-apm-node/start.js argument to node.
  2. What version of Next.js are you using? The current elastic-apm-node does not support the very latest version of Next.js. Currently versions >=11.1.0 <13.3.0 are supported. See https://www.elastic.co/guide/en/apm/agent/nodejs/current/supported-technologies.html#compatibility-frameworks
  3. How are you running your Next.js application? Are you using the Next.js server (i.e. running next start or next dev)?
  4. You mention SPDY. We have not tested Next.js instrumentation using HTTP/2. It is possible there is some different behaviour here that elastic-apm-node does not handle.
khteh commented 1 year ago

I am using Next 13.2.4. Adding this to the Dockerfile:

          env:
            - name: NODE_ENV
              value: "production"
            - name: NODE_OPTIONS
              value: --max-old-space-size=16384 --require elastic-apm-node/start.js

results in

{"log.level":"error","@timestamp":"2023-06-13T02:30:01.290Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"APM Server transport error: error fetching APM Server version: connect ECONNREFUSED 127.0.0.1:8200"}
{"log.level":"error","@timestamp":"2023-06-13T02:30:01.291Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"APM Server transport error (ECONNREFUSED): connect ECONNREFUSED 127.0.0.1:8200"}
{"log.level":"error","@timestamp":"2023-06-13T02:30:01.305Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"APM Server transport error (ECONNREFUSED): connect ECONNREFUSED 127.0.0.1:8200"}
{"log.level":"info","@timestamp":"2023-06-13T02:30:01.306Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"Sending error to Elastic APM: {\"id\":\"cbc1c6588ed0c2ef01ebc1d642e753a0\"}"}
{"log.level":"error","@timestamp":"2023-06-13T02:30:01.308Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"APM Server transport error (ECONNREFUSED): connect ECONNREFUSED 127.0.0.1:8200"}

This is how I start the application in the container:

ENTRYPOINT ["node", "--trace-warnings", "--trace-deprecation", "--experimental-specifier-resolution=node", "server.js"]
khteh commented 1 year ago

Where to check the trace? I don't see anything in APM > Logs and there is nothing in the Traces tab.

trentm commented 1 year ago

Where to check the trace?

The trace/debug logs I was referring to are printed to stdout by the APM agent. They aren't automatically sent to APM server to be visible in the Kibana APM app. Given that you are running your app in Docker, then you should be able to see the logs by running docker logs NAME-OF-YOUR-APP-CONTAINER.

results in

{"log.level":"error","@timestamp":"2023-06-13T02:30:01.290Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"APM Server transport error: error fetching APM Server version: connect ECONNREFUSED 127.0.0.1:8200"}
...

That error log from the APM agent shows that the serverUrl configuration setting is not set -- it is using the default http://127.0.0.1:8200. There is no local APM server running at 127.0.0.1:8200, so the APM agent isn't able to send any trace data.

khteh commented 1 year ago

This is all that I see in the log:

[buyerportal-0 buyerportal] {"log.level":"trace","@timestamp":"2023-06-14T02:22:00.482Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"b43a099f3306a4111f327ecf1df4a2d0","timeline":[[10001.410907,"completePart gzipStream",null],[10001.599615,"completePart intakeReq",null],[10002.673543,"completePart intakeRes",null]],"bytesWritten":731,"backoffDelayMs":0,"ecs":{"version":"1.6.0"},"message":"conclude intake request: success"}

The serverUrl is configured in server.js which is in the startup command of the application.

trentm commented 1 year ago

This is all that I see in the log:

[buyerportal-0 buyerportal] {"log.level":"trace"...

Okay, so you are getting trace logs. Can you please send the full log output that covers a time period when your buyerportal container has received some requests?

khteh commented 1 year ago
[buyerportal-1 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:25.762Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"64e75b8cffa6419bdaa07ccfac279fa5","ecs":{"version":"1.6.0"},"message":"gzipStream \"finish\""}
[buyerportal-1 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:25.762Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"64e75b8cffa6419bdaa07ccfac279fa5","timeout":10000,"ecs":{"version":"1.6.0"},"message":"start intakeResTimer"}
[buyerportal-1 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:25.762Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"64e75b8cffa6419bdaa07ccfac279fa5","ecs":{"version":"1.6.0"},"message":"gzipStream \"end\""}
[buyerportal-1 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:25.762Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"64e75b8cffa6419bdaa07ccfac279fa5","concluded":false,"ecs":{"version":"1.6.0"},"message":"completePart gzipStream"}
[buyerportal-1 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:25.762Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"64e75b8cffa6419bdaa07ccfac279fa5","ecs":{"version":"1.6.0"},"message":"intakeReq \"finish\""}
[buyerportal-1 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:25.762Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"64e75b8cffa6419bdaa07ccfac279fa5","concluded":false,"ecs":{"version":"1.6.0"},"message":"completePart intakeReq"}
[buyerportal-1 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:25.764Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"64e75b8cffa6419bdaa07ccfac279fa5","statusCode":202,"reqFinished":true,"ecs":{"version":"1.6.0"},"message":"intakeReq \"response\""}
[buyerportal-1 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:25.764Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"64e75b8cffa6419bdaa07ccfac279fa5","ecs":{"version":"1.6.0"},"message":"intakeRes \"end\""}
[buyerportal-1 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:25.764Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"64e75b8cffa6419bdaa07ccfac279fa5","concluded":false,"ecs":{"version":"1.6.0"},"message":"completePart intakeRes"}
[buyerportal-1 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:25.764Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"64e75b8cffa6419bdaa07ccfac279fa5","timeline":[[10001.564759,"completePart gzipStream",null],[10001.695262,"completePart intakeReq",null],[10002.999542,"completePart intakeRes",null]],"bytesWritten":736,"backoffDelayMs":0,"ecs":{"version":"1.6.0"},"message":"conclude intake request: success"}
[buyerportal-0 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:38.714Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"007a5566624710d7bab45987c324c77e","ecs":{"version":"1.6.0"},"message":"intake request start"}
[buyerportal-0 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:38.714Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","fullTimeMs":1.457031,"numEvents":1,"numBytes":921,"ecs":{"version":"1.6.0"},"message":"_write: encode object"}
[buyerportal-0 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:38.715Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"007a5566624710d7bab45987c324c77e","ecs":{"version":"1.6.0"},"message":"intakeReq \"socket\": unref it"}
[buyerportal-1 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:45.762Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"f73a72929c656f6c976983f0c2b4f6ea","ecs":{"version":"1.6.0"},"message":"intake request start"}
[buyerportal-1 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:45.762Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","fullTimeMs":1.387292,"numEvents":1,"numBytes":921,"ecs":{"version":"1.6.0"},"message":"_write: encode object"}
[buyerportal-1 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:45.762Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"f73a72929c656f6c976983f0c2b4f6ea","ecs":{"version":"1.6.0"},"message":"intakeReq \"socket\": unref it"}
[buyerportal-0 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:48.715Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"007a5566624710d7bab45987c324c77e","ecs":{"version":"1.6.0"},"message":"gzipStream \"finish\""}
[buyerportal-0 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:48.716Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"007a5566624710d7bab45987c324c77e","timeout":10000,"ecs":{"version":"1.6.0"},"message":"start intakeResTimer"}
[buyerportal-0 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:48.716Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"007a5566624710d7bab45987c324c77e","ecs":{"version":"1.6.0"},"message":"gzipStream \"end\""}
[buyerportal-0 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:48.716Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"007a5566624710d7bab45987c324c77e","concluded":false,"ecs":{"version":"1.6.0"},"message":"completePart gzipStream"}
[buyerportal-0 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:48.716Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"007a5566624710d7bab45987c324c77e","ecs":{"version":"1.6.0"},"message":"intakeReq \"finish\""}
[buyerportal-0 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:48.716Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"007a5566624710d7bab45987c324c77e","concluded":false,"ecs":{"version":"1.6.0"},"message":"completePart intakeReq"}
[buyerportal-0 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:48.717Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"007a5566624710d7bab45987c324c77e","statusCode":202,"reqFinished":true,"ecs":{"version":"1.6.0"},"message":"intakeReq \"response\""}
[buyerportal-0 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:48.717Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"007a5566624710d7bab45987c324c77e","ecs":{"version":"1.6.0"},"message":"intakeRes \"end\""}
[buyerportal-0 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:48.717Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"007a5566624710d7bab45987c324c77e","concluded":false,"ecs":{"version":"1.6.0"},"message":"completePart intakeRes"}
[buyerportal-0 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:48.717Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"007a5566624710d7bab45987c324c77e","timeline":[[10002.567412,"completePart gzipStream",null],[10002.887287,"completePart intakeReq",null],[10003.521677,"completePart intakeRes",null]],"bytesWritten":735,"backoffDelayMs":0,"ecs":{"version":"1.6.0"},"message":"conclude intake request: success"}
[buyerportal-1 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:55.762Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"f73a72929c656f6c976983f0c2b4f6ea","ecs":{"version":"1.6.0"},"message":"gzipStream \"finish\""}
[buyerportal-1 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:55.762Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"f73a72929c656f6c976983f0c2b4f6ea","timeout":10000,"ecs":{"version":"1.6.0"},"message":"start intakeResTimer"}
[buyerportal-1 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:55.762Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"f73a72929c656f6c976983f0c2b4f6ea","ecs":{"version":"1.6.0"},"message":"gzipStream \"end\""}
[buyerportal-1 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:55.762Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"f73a72929c656f6c976983f0c2b4f6ea","concluded":false,"ecs":{"version":"1.6.0"},"message":"completePart gzipStream"}
[buyerportal-1 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:55.762Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"f73a72929c656f6c976983f0c2b4f6ea","ecs":{"version":"1.6.0"},"message":"intakeReq \"finish\""}
[buyerportal-1 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:55.762Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"f73a72929c656f6c976983f0c2b4f6ea","concluded":false,"ecs":{"version":"1.6.0"},"message":"completePart intakeReq"}
[buyerportal-1 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:55.764Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"f73a72929c656f6c976983f0c2b4f6ea","statusCode":202,"reqFinished":true,"ecs":{"version":"1.6.0"},"message":"intakeReq \"response\""}
[buyerportal-1 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:55.764Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"f73a72929c656f6c976983f0c2b4f6ea","ecs":{"version":"1.6.0"},"message":"intakeRes \"end\""}
[buyerportal-1 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:55.764Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"f73a72929c656f6c976983f0c2b4f6ea","concluded":false,"ecs":{"version":"1.6.0"},"message":"completePart intakeRes"}
[buyerportal-1 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:57:55.764Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"f73a72929c656f6c976983f0c2b4f6ea","timeline":[[10001.761449,"completePart gzipStream",null],[10001.8982,"completePart intakeReq",null],[10003.265764,"completePart intakeRes",null]],"bytesWritten":741,"backoffDelayMs":0,"ecs":{"version":"1.6.0"},"message":"conclude intake request: success"}
[buyerportal-0 buyerportal] {"log.level":"debug","@timestamp":"2023-06-16T06:57:57.474Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"no active transaction found - cannot build new span"}
[buyerportal-0 buyerportal] {"log.level":"trace","@timestamp":"2023-06-16T06:58:08.715Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"15e3f453b9fba96ec1a49223921e41a1","ecs":{"version":"1.6.0"},"message":"intake request start"}
trentm commented 1 year ago

@khteh Thanks. The one line in there that is helpful is this one:

[buyerportal-0 buyerportal] {"log.level":"debug","@timestamp":"2023-06-16T06:57:57.474Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"no active transaction found - cannot build new span"}

It shows that the APM agent instrumented some activity in your code that would have generated a span, but it didn't because there is no active "transaction". Typically a transaction is created automatically for an incoming HTTP request -- if your app implements an HTTP server. (More details on the types of transactions here: https://www.elastic.co/guide/en/apm/guide/current/data-model-transactions.html) Alternatively, to get tracing for activity in your app that isn't part of an HTTP request you can manually start transactions via the apm.startTransaction(...) API (https://www.elastic.co/guide/en/apm/agent/nodejs/current/agent-api.html#apm-start-transaction).

Are you able to give some details on your app? What does it do? What modules does your app use that you expect the APM agent to be generating tracing data for?

khteh commented 1 year ago

I expect normal HTTP request tracing. This is my startup server.js:

// Add this to the very top of the first file loaded in your app
var apm = require('elastic-apm-node').start({
  // Override service name from package.json
  // Allowed characters: a-z, A-Z, 0-9, -, _, and space
  serviceName: 'buyerportal-apm',
  // Set custom APM Server URL (default: http://127.0.0.1:8200)
  serverUrl: 'https://my-apm-http:8200',
  // Only activate the agent if it's running in production
  active: process.env.NODE_ENV === 'production',
  verifyServerCert: false,
  ignoreUrls: [
    /^\/health\//i
  ],
  logLevel: 'trace'
})
const https = require('https')
const http2 = require('http2')
const fs = require('fs')
const path = require('path')
const { parse } = require('url')
const next = require('next')
const spdy = require('spdy')
const config = require('config')
const logger = require('morgan')
const json = require('morgan-json')
const express = require('express')
const compression = require('compression')
const cors = require('cors')
const helmet = require('helmet')
const createError = require('http-errors')
const cookieParser = require('cookie-parser')
const rfs = require('rotating-file-stream')
process.chdir(__dirname)
// Make sure commands gracefully respect termination signals (e.g. from Docker)
// Allow the graceful termination to be manually configurable
if (!process.env.NEXT_MANUAL_SIG_HANDLE) {
  process.on('SIGTERM', () => process.exit(0))
  process.on('SIGINT', () => process.exit(0))
  process.on('warning', (e) => console.warn(e.stack))
}
console.log(`NODE_ENV: ${process.env.NODE_ENV}`)
const port = parseInt(process.env.PORT, 10) || 443
const dev = process.env.NODE_ENV !== 'production'

const shouldCompress = (req, res) => {
  // don't compress responses asking explicitly not
  if (req.headers['x-no-compression']) {
    return false
  }

  // use compression filter function
  return compression.filter(req, res)
}
// Init the Next app:
const app = next({ dev, dir: __dirname })
const handle = app.getRequestHandler()
/*https://stackoverflow.com/questions/59534717/how-to-integrate-http2-with-expressjs-using-nodejs-module-http2
expressjs still does not officially support Node http2
https://github.com/expressjs/express/issues/5061
const server = http2.createSecureServer({
  key: fs.readFileSync('server.key'),
  cert: fs.readFileSync('server.crt')
}, app);
*/
const options = {
  key: fs.readFileSync('server.key'),
  cert: fs.readFileSync('server.crt'),
}
/*
app.prepare().then(() => { // This works perfectly well!
  https.createServer(options, (req, res) => {
    const parsedUrl = parse(req.url, true);
    handle(req, res, parsedUrl);
  }).listen(port, err => {
    if (err) throw err
    console.log(`> Ready on localhost:${port}`)
  })
})*/
app.prepare().then(() => {
  // This works perfectly too!
  // express setup
  const expressApp = express()
  /*
  expressApp.use(helmet()) // adding set of security middlewares
  */
  expressApp.use(apm.middleware.connect())
  expressApp.use(express.json())
  expressApp.use(express.urlencoded({ extended: false }))
  expressApp.use(cookieParser())
  expressApp.use(express.static(path.join(__dirname, 'public')))
  //expressApp.use(helmet()) adding set of security middlewares. This breaks!
  expressApp.use(cors()) // enable all CORS request
  expressApp.set('port', port)
  expressApp.use(compression({ filter: shouldCompress }))
  expressApp.enable("trust proxy");

  if (config.util.getEnv('NODE_ENV') !== 'test') {
    var accessLogStream = rfs.createStream('log', {
      interval: '1d', // rotate daily
      path: '/var/log/myapp',
    })
    //var format: string = ':remote-addr - :remote-user [:date[clf]] ":method :url HTTP/:http-version" :status :res[content-length] ":referrer" ":user-agent - :response-time ms"';
    const format = json({
      IP: ':remote-addr',
      User: ':remote-user',
      Timestamp: ':date[clf]',
      Method: ':method',
      Path: ':url',
      Protocol: 'HTTP/:http-version',
      Status: ':status',
      ContentLength: ':res[content-length]',
      Referrer: ':referrer',
      Agent: ':user-agent',
      ResponseTime: ':response-time ms',
    })
    // log only 4xx and 5xx responses to console
    if (config.util.getEnv('NODE_ENV') === 'development')
      expressApp.use(
        logger('combined', {
          skip: function (req, res) {
            return res.statusCode < 400
          },
        })
      )

    // log all requests to access.log
    expressApp.use(
      logger(format, {
        stream: accessLogStream,
      })
    )
  }

  // declaring routes for our pages
  expressApp.get('/index', (req, res) => {
    return app.render(req, res, '/', req.query)
  })
  /* k8s liveness check */
  expressApp.get('/health/ready', function (req, res, next) {
    res.send('OK')
  })
  expressApp.get('/health/live', function (req, res, next) {
    res.send('OK')
  })
  // fallback all request to next request handler
  expressApp.all('*', (req, res) => {
    //const parsedUrl = parse(req.url, true);
    //return handle(req, res, parsedUrl)
    return handle(req, res)
  })
  const server = spdy.createServer(options, expressApp)
  server.on('error', (error) => {
    if (error.syscall !== 'listen') {
      throw error
    }
    var bind = typeof port === 'string' ? 'Pipe ' + port : 'Port ' + port

    // handle specific listen errors with friendly messages
    switch (error.code) {
      case 'EACCES':
        console.error(bind + ' requires elevated privileges')
        process.exit(1)
      case 'EADDRINUSE':
        console.error(bind + ' is already in use')
        process.exit(1)
      default:
        throw error
    }
  })
  server.on('stream', (stream, headers) => {
    // stream is a Duplex
    stream.respond({
      'content-type': 'text/html; charset=utf-8',
      ':status': 200,
    })
    stream.end('<h1>Hello World</h1>')
  })
  server.listen(port, (err) => {
    if (err) {
      apm.captureError(err)
      console.error('Failed to start server', err)
      process.exit(1)
    } else {
      console.log(`HTTP/2 server listening on port: ${port}`)
    }
  })
})

How to get it to work?

trentm commented 1 year ago

I cannot get server.js running. Here is my attempt:

% node server.js
{"log.level":"debug","@timestamp":"2023-06-21T20:25:35.648Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"Elastic APM agent disabled (`active` is false)"}
WARNING: No configurations found in configuration directory:/Users/trentm/tmp/b/config
WARNING: To disable this warning set SUPPRESS_NO_CONFIG_WARNING in the environment.
NODE_ENV: undefined
(node:58775) [DEP0111] DeprecationWarning: Access to process.binding('http_parser') is deprecated.
(Use `node --trace-deprecation ...` to show where the warning was created)
DeprecationWarning: Access to process.binding('http_parser') is deprecated.
    at process.binding (node:internal/bootstrap/loaders:140:17)
    at Object.<anonymous> (/Users/trentm/tmp/b/node_modules/http-deceiver/lib/deceiver.js:22:24)
    at Module._compile (node:internal/modules/cjs/loader:1275:14)
    at Module._extensions..js (node:internal/modules/cjs/loader:1329:10)
    at Module.load (node:internal/modules/cjs/loader:1133:32)
    at Module._load (node:internal/modules/cjs/loader:972:12)
    at Module.require (node:internal/modules/cjs/loader:1157:19)
    at require (node:internal/modules/helpers:119:18)
    at Object.<anonymous> (/Users/trentm/tmp/b/node_modules/spdy/lib/spdy/handle.js:5:20)
    at Module._compile (node:internal/modules/cjs/loader:1275:14)

Using this package.json:

{
  "name": "b",
  "version": "1.0.0",
  "main": "server.js",
  "scripts": {},
  "dependencies": {
    "compression": "^1.7.4",
    "config": "^3.3.9",
    "cookie-parser": "^1.4.6",
    "cors": "^2.8.5",
    "elastic-apm-node": "^3.45.0",
    "express": "^4.18.2",
    "helmet": "^7.0.0",
    "http-errors": "^2.0.0",
    "morgan": "^1.10.0",
    "morgan-json": "^1.1.0",
    "next": "^13.2.4",
    "rotating-file-stream": "^3.1.0",
    "spdy": "^4.0.2"
  }
}

and node v19.8.1.

Can you share a small repository that reproduces the issue?


Looking at https://github.com/spdy-http2/node-spdy/issues/380 I wonder if the spdy module just doesn't work with Node v19 that you mentioned you are using.

Also, if spdy is the module that is accepting incoming HTTP requests, then the elastic-apm-node agent doesn't current automatically instrument the spdy module -- so that would explain why an APM transaction is not automatically created.

khteh commented 1 year ago

Also, if spdy is the module that is accepting incoming HTTP requests, then the elastic-apm-node agent doesn't current automatically instrument the spdy module -- so that would explain why an APM transaction is not automatically created.

How to make it work without "automatically"?

trentm commented 1 year ago

You would need to use the Agent API (e.g. apm.startTransaction(...) and apm.endTransaction(...), https://www.elastic.co/guide/en/apm/agent/nodejs/current/agent-api.html#apm-start-transaction) to start and end transactions for incoming requests. It might be sufficient to write an express middleware to handle that. However, I don't know your application well, so I might be oversimplifying.

khteh commented 1 year ago

Can you share a small repository that reproduces the issue?

You can start an Next.JS app with https://nextjs.org/learn/basics/create-nextjs-app and start the app with export NODE_ENV=development PORT=3000&& node --experimental-specifier-resolution=node server.js

khteh commented 1 year ago

I added start and end:

  expressApp.all('*', (req, res) => {
    apm.startTransaction()
    const result = handle(req, res)
    apm.endTransaction()
    return result
  })

but still don't see any data in kibana

khteh commented 1 year ago

There was a delay. I see the data now.