Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
Vhndaree opened this issue Aug 21, 2023 · 14 comments
Closed

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

Vhndaree opened this issue Aug 21, 2023 · 14 comments
Assignees
Labels

Comments

@Vhndaree
Copy link

Vhndaree commented Aug 21, 2023

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"
    }
}
@Vhndaree Vhndaree added the bug label Aug 21, 2023
@kirrg001 kirrg001 self-assigned this Aug 21, 2023
@kirrg001
Copy link
Contributor

Thanks for your report. We are taking a look

@kirrg001
Copy link
Contributor

kirrg001 commented Aug 21, 2023

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
Copy link
Author

Vhndaree commented Aug 21, 2023

{
    "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
Copy link
Contributor

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
Copy link
Contributor

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
Copy link
Author

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
Copy link
Contributor

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
Copy link
Author

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
Copy link
Contributor

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
Copy link
Author

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

@Vhndaree
Copy link
Author

Vhndaree commented Aug 23, 2023

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
Copy link
Contributor

kirrg001 commented Aug 23, 2023

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
Copy link
Contributor

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

@Vhndaree
Copy link
Author

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

2 participants