Flushing 0 metrics via HTTP on Hapi js integration

[aaestrada]

Expected behavior Automatic instrumentation should work for hapi js integration without noise

Actual behavior Looks like the tracing integration for hapi js plugin is working, but, there is a noise caused by the dd-trace js library in the logs: that after a time, cause a timeout issue in the node js server:

Flushing 0 metrics via HTTP
Flushing 0 metrics via HTTP
Flushing 0 metrics via HTTP
Flushing 0 metrics via HTTP
Flushing 0 metrics via HTTP
Flushing 0 metrics via HTTP
Flushing 0 metrics via HTTP
ERROR [09:24:05.556] (68211): Request timeout
    dd: {
      "service": "hapi-test",
      "version": "1.0.0"
    }
    tags: [
      "connection",
      "client",
      "error"
    ]
    err: {
      "type": "Error",
      "message": "Request timeout",
      "stack":
          Error [ERR_HTTP_REQUEST_TIMEOUT]: Request timeout
              at new NodeError (node:internal/errors:399:5)
              at onRequestTimeout (node:_http_server:787:30)
              at Server.checkConnections (node:_http_server:600:7)
              at listOnTimeout (node:internal/timers:569:17)
              at process.processTimers (node:internal/timers:512:7)
      "code": "ERR_HTTP_REQUEST_TIMEOUT"
    }
Flushing 0 metrics via HTTP
Flushing 0 metrics via HTTP
Flushing 0 metrics via HTTP
Flushing 0 metrics via HTTP
Flushing 0 metrics via HTTP

deployed in the ams server this logs also cause a lot if noise there. But these logs are interpreted by the istio mesh as: PassthroughCluster with a response code 0

Steps to reproduce use the automatic hapi js integration:

{
  "name": "hapi-test",
  "version": "1.0.0",
  "description": "",
  "main": "index.js",
  "scripts": {
    "start": "DD_CIVISIBILITY_AGENTLESS_ENABLED=true DD_TRACE_DEBUG=1 DD_TRACE_LOG_LEVEL=debug node . "
  },
  "keywords": [],
  "author": "",
  "license": "ISC",
  "dependencies": {
    "@hapi/hapi": "^21.3.2",
    "dd-trace": "^4.16.0",
    "hapi-pino": "^12.1.0"
  },
  "devDependencies": {
    "pino-pretty": "^10.2.3"
  }
}

// This line must come before importing any instrumented module.
const ddTrace = require('dd-trace');

// enable and configure hapi integration
ddTrace.use('hapi', {});
ddTrace.init({
    logInjection: true,
});
const Hapi = require('@hapi/hapi');
// manage logs
const Pino = require('hapi-pino');

const getResponse = [
    {string: 'string1', number: 1, boolean: true},
    {string: 'string2', number: 2, boolean: false},
];

async function start() {
    // Create a server with a host and port
    const server = Hapi.server({
        host: 'localhost',
        port: 3000,
        debug: false, // disable Hapi debug console logging
    });

    // Add the route
    server.route({
        method: 'GET',
        path: '/items',
        async handler(request, h) {
            // test sonicBoob library works
            // const sonic = new SonicBoom({
            //   dest: './pino-logs/node_trace.1.log',
            //   append: true,
            //   mkdir: true
            // });
            return h.response(getResponse);
        },
    });
    //   const tmpDir = Path.join(__dirname, '.tmp_' + Date.now())
    //   const destination = join(tmpDir, 'output')

    await server.register({
        plugin: Pino,
        options: {
            logPayload: true,
            mergeHapiLogData: true,
            ignorePaths: ['/alive.txt', '/private'],
            ignoreFunc: (options, request) =>
                request.path.startsWith('/private'),
            transport: {
                target: 'pino-pretty',
                options: {
                    colorize: true,
                    minimumLevel: 'info',
                    levelFirst: true,
                    messageFormat: true,
                    timestampKey: 'time',
                    translateTime: true,
                },
            },
        },
    });
    await server.start();
    server.log(['info'], `server running: ${server.info.uri}/items`);
    return server;
}

start().catch((err) => {
    // eslint-disable-next-line no-console
    console.log(err);
    process.exit(1);
});

run the start script and the issue will be visible.

Environment

• Operation system: Mac OS venture 13.6
• Node.js version: v18.16.1
• Tracer version: ^4.16.0
• Agent version: v7
• Relevant library versions: "@hapi/hapi": "^21.3.2", "hapi-pino": "^12.1.0", "pino-pretty": "^10.2.3"

[aaestrada]

looks like the timeout issue:

ERROR [09:24:05.556] (68211): Request timeout
    dd: {
      "service": "hapi-test",
      "version": "1.0.0"
    }
    tags: [
      "connection",
      "client",
      "error"
    ]
    err: {
      "type": "Error",
      "message": "Request timeout",
      "stack":
          Error [ERR_HTTP_REQUEST_TIMEOUT]: Request timeout
              at new NodeError (node:internal/errors:399:5)
              at onRequestTimeout (node:_http_server:787:30)
              at Server.checkConnections (node:_http_server:600:7)
              at listOnTimeout (node:internal/timers:569:17)
              at process.processTimers (node:internal/timers:512:7)
      "code": "ERR_HTTP_REQUEST_TIMEOUT"
    }

don't come from dd-trace. It comes from node js itself. See more details in: https://github.com/nodejs/node/issues/47822

My question now is:

the log that we see:

Flushing 0 metrics via HTTP

is it really a dd-trace problem? Or is it just a wrong configuration on our side?

[aaestrada]

Using previous version of dd-trace... With dd-trace@3.0.0 we got:

Adding encoded trace to buffer: dd 00 00 00 01 8b a8 74 72 61 63 65 5f 69 64 cf 53 23 46 da 76 f5 b9 d1 a7 73 70 61 6e 5f 69 64 cf 53 23 46 da 76 f5 b9 d1 a9 70 61 72 65 6e 74 5f 69 64 cf 00 00 00 00 00 00 00 00 a4 6e 61 6d 65 aa 64 6e 73 2e 6c 6f 6f 6b 75 70 a8 72 65 73 6f 75 72 63 65 a7 30 2e 30 2e 30 2e 30 a7 73 65 72 76 69 63 65 b5 61 61 72 6f 6e 2d 72 63 70 2d 74 65 73 74 69 6e 67 2d 61 70 70 a5 65 72 72 6f 72 ce 00 00 00 00 a5 73 74 61 72 74 cf 17 95 aa a7 ed 23 97 00 a8 64 75 72 61 74 69 6f 6e cf 00 00 00 00 00 08 19 4a a4 6d 65 74 61 df 00 00 00 07 a7 73 65 72 76 69 63 65 b5 61 61 72 6f 6e 2d 72 63 70 2d 74 65 73 74 69 6e 67 2d 61 70 70 a7 76 65 72 73 69 6f 6e a5 31 2e 30 2e 30 aa 72 75 6e 74 69 6d 65 2d 69 64 db 00 00 00 24 64 33 65 34 38 64 30 38 2d 35 39 30 30 2d 34 61 39 35 2d 62 33 63 39 2d 32 34 61 65 30 35 38 61 62 66 66 63 a9 73 70 61 6e 2e 6b 69 6e 64 a6 63 6c 69 65 6e 74 ac 64 6e 73 2e 68 6f 73 74 6e 61 6d 65 a7 30 2e 30 2e 30 2e 30 ab 64 6e 73 2e 61 64 64 72 65 73 73 a7 30 2e 30 2e 30 2e 30 a8 6c 61 6e 67 75 61 67 65 aa 6a 61 76 61 73 63 72 69 70 74 a7 6d 65 74 72 69 63 73 df 00 00 00 03 ad 5f 64 64 2e 61 67 65 6e 74 5f 70 73 72 cb 3f f0 00 00 00 00 00 00 ac 5f 64 64 2e 6d 65 61 73 75 72 65 64 cb 3f f0 00 00 00 00 00 00 b5 5f 73 61 6d 70 6c 69 6e 67 5f 70 72 69 6f 72 69 74 79 5f 76 31 cb 3f f0 00 00 00 00 00 00

the log that says,

Flushing 0 metrics via HTTP

replaced the encoded tracer to the buffer?

[tlhunter]

Is the problem that your logs are full of those flushing metrics messages? They should only be visible if the DD_TRACE_DEBUG=true env var is supplied, which is guaranteed to lead to noisy logs. Has the variable been set accidentally?

[tlhunter]

I'll close this for now but we can reopen it if it's still an issue.