[Bug]: version upgrade from 2.29.0 to 2.30.0 causing log flood.

[Vhndaree]

Problem Description

I upgrade from 2.29.0 to 2.30.0 and after that

Cannot start an exit span as this requires an active entry (or intermediate) span as parent. Currently there is no span active at all

is being logged as INFO a lot of time, which causes issues in service performance

Short, Self Contained Example

Usage

if (agentPort && agentHost) {
    require('@instana/collector')();
}

Node.js Version

^18.14.0

package.json

{
    "name": "service",
    "version": "0.1.0",
    "private": true,
    "description": "",
    "main": "",
    "scripts": {
        "build": "tsc"
    },
    "engines": {
        "node": "^18.14.0"
    },
    "license": "UNLICENSED",
    "dependencies": {
        "@instana/collector": "^2.30.0"
    }
}

[kirrg001]

Thanks for your report. We are taking a look

[kirrg001]

Could you please share your package.json with me? Thank you We need to to know your use case. Which NPM modules are you using?

[Vhndaree]

{
    "name": "service",
    "version": "0.1.0",
    "private": true,
    "description": "",
    "main": "",
    "scripts": {
        "build": "tsc",
        "build:debug": "tsc --sourceMap",
        "start": "node --max-http-header-size=32768 dist/cmd/service/main.js",
        "lint": "eslint . --ext .ts",
        "lint:fix": "eslint . --ext .ts --fix",
        "format": "prettier '**/*.ts' --write",
        "test:all": "npm run test"
    },
    "engines": {
        "node": "^18.14.0"
    },
    "keywords": [],
    "license": "UNLICENSED",
    "dependencies": {
        "@instana/collector": "^2.29.0",
        "@wireapp/lru-cache": "^3.8.1",
        "agentkeepalive": "^4.5.0",
        "ajv": "^8.12.0",
        "avsc": "^5.7.7",
        "axios": "^0.27.2",
        "body-parser": "^1.20.2",
        "chokidar": "^3.5.3",
        "cookie-parser": "^1.4.6",
        "dns-cache": "^2.0.0",
        "ejs": "^3.1.9",
        "express": "^4.18.2",
        "express-promise-router": "^4.1.1",
        "html-entities": "^2.4.0",
        "ioredis": "^5.3.2",
        "jsonwebtoken": "^9.0.1",
        "kafkajs": "^2.2.4",
        "method-override": "^3.0.0",
        "murmurhash": "^2.0.1",
        "node-jose": "^2.2.0",
        "opossum": "^8.1.0",
        "path-to-regexp": "^3.1.0",
        "pino": "^8.15.0",
        "prom-client": "^14.2.0",
        "toobusy-js": "^0.5.1"
    },
    "devDependencies": {
        "@tsconfig/node18": "18.2.0",
        "@types/body-parser": "^1.19.2",
        "@types/compression": "^1.7.2",
        "@types/cookie-parser": "^1.4.3",
        "@types/express": "^4.17.17",
        "@types/jsdom": "^21.1.1",
        "@types/jsonwebtoken": "^9.0.2",
        "@types/method-override": "^0.0.32",
        "@types/mocha": "^10.0.1",
        "@types/node": "^18.13.0",
        "@types/node-jose": "^1.1.10",
        "@types/opossum": "^8.1.0",
        "@types/sinon": "^10.0.16",
        "@types/toobusy-js": "^0.5.2",
        "@typescript-eslint/eslint-plugin": "^5.62.0",
        "@typescript-eslint/parser": "^5.62.0",
        "compression": "^1.7.4",
        "eslint": "^8.47.0",
        "eslint-import-resolver-typescript": "^3.6.0",
        "eslint-plugin-import": "^2.28.0",
        "jsdom": "^22.1.0",
        "mocha": "^10.2.0",
        "nock": "^13.3.3",
        "node-mocks-http": "^1.13.0",
        "prettier": "3.0.2",
        "sinon": "^15.2.0",
        "strict-event-emitter-types": "^2.0.0",
        "ts-node": "^10.9.1",
        "typescript": "^5.1.6"
    }
}

[kirrg001]

Thanks for sharing. We are taking a look at the target libraries.

Cannot start an exit span as this requires an active entry (or intermediate) span as parent. Currently there is no span active at all is being logged as INFO a lot of time, which causes issues in service performance

This log message is not an INFO log, it's a warning. Could you please double check your statement?

[kirrg001]

Could you please share a code snippet how you are using ioredis and kafkajs when the warning appears? That would help us. Thank you

[Vhndaree]

This seems like not an issue with ioredis and kafkajs because I encounter similar issue with a service using different dependencies.

"dependencies": {
    "@instana/collector": "^2.30.0",
    "@rdten/node-service-modules": "^10.1.0",
    "ajv": "^8.12.0",
    "ajv-formats": "^2.1.1",
    "lodash": "^4.17.21"
  }

[kirrg001]

Ok thanks. It might be that there is an issue, but to trigger the warning, what are you doing in your code? Could you please share a snippet?

[Vhndaree]

I have setup instana port and host in env, and rest I initialize the instana as shown in the docs itself

require('@instana/collector')();

That is basically it.

[kirrg001]

What is @rdten/node-service-modules? This module does not exist on npm.

Can you please share an example application? I cannot reproduce what you are seeing.

My example app is:

{
  "name": "nodejstest",
  "author": "",
  "license": "ISC",
  "dependencies": {
      "@instana/collector": "^2.30.0",
      "express": "^4.18.2",
      "ajv": "^8.12.0",
      "ajv-formats": "^2.1.1",
      "lodash": "^4.17.21"
  }
}

require('@instana/collector')();

const express = require('express');
const app = express();

app.get('/', function (req, res) {
  res.send('Hello World');
});

app.listen(3002);

There are no warnings. There must be something in your application which triggers the warning.

[Vhndaree]

Thanks for the hint, I will try to replicate with a simple app and post.

[Vhndaree]

The behavior exist when I use kafkajs and try to send message to kafka topic.

index.js

require("@instana/collector")();

const { Kafka } = require("kafkajs");
const { v4: uuidv4 } = require("uuid");
const express = require("express");
const app = express();

const kafka = new Kafka({
  clientId: "my-kafka-producer",
  brokers: ["localhost:9092"],
});

const producer = kafka.producer();

app.use(express.json());

app.post("/", async (req, res) => {
  try {
    await producer.connect();
    await producer.send({
      topic: "my-kafka-topic",
      acks: 1,
      compression: 0,
      messages: [
        {
          value: JSON.stringify({
            key: uuidv4(),
            createdAt: Date.now().toString(),
          }),
        },
      ],
    });
    await producer.disconnect();

    res.status(201).send("Message sent successfully");
  } catch (error) {
    console.error("Error producing message:", error);
    res.status(500).send("Internal Server Error");
  }
});

app.listen(3000, () => {
  console.log("Server is running on port 3000");
});

package.json

{
  "name": "nodejstest",
  "author": "",
  "scripts": {
    "start": "node index.js"
  },
  "dependencies": {
    "@instana/collector": "^2.30.0",
    "express": "^4.18.2",
    "kafkajs": "^2.2.4",
    "uuid": "^9.0.0"
  }
}

docker-compose.yml

version: "3"

services:
  zookeeper:
    image: wurstmeister/zookeeper
    container_name: zookeeper
    ports:
      - "2181:2181"
  kafka:
    image: wurstmeister/kafka
    container_name: kafka
    ports:
      - "9092:9092"
    environment:
      KAFKA_ADVERTISED_HOST_NAME: localhost
      KAFKA_ZOOKEEPER_CONNECT: zookeeper:2181

[kirrg001]

Thanks for sharing.

Could you please share your log? Do you see this log message?

{"name":"@instana/collector","thread":0,"__in":1,"hostname":"kirrg001s-MacBook-Pro.local","pid":80282,"module":"announceCycle/agentready","level":30,"msg":"The Instana Node.js collector is now fully initialized and connected to the Instana host agent.","time":"2023-08-23T11:56:16.225Z","v":0}

I think you are running into this warning because the Instana collector cannot connect to the Instana agent and is not fully initialized. And then the log is flooded when there is already traffic.

[kirrg001]

Hi! We've released a potential fix in v2.30.1. Could you please check if the problem is resolved? Thank you

[Vhndaree]

@kirrg001 The new version has resolved our problem. I appreciate the prompt assistance.