search

instana / nodejs

Node.js in-process collectors for Instana
MIT License
69 stars 36 forks source link

[Bug]: "Cannot start an exit span" log messages in conjunction with web socket #885

Closed chromey closed 11 months ago

chromey commented 11 months ago

Problem Description

A recent update of this package caused two of our NestJS services to be flooded with log statements like this:

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

basically, similar to #867

We have many Nest services that don't exhibit this problem. What sets the two affected ones apart is that they both use a websocket gateway, which is why I believe this causes the problem.

I could not add the package-lock.json as it was too long for this form. Let me know if you need specific version details on certain packages.

@instana/collector is 2.33.1 @nestjs/websockets is 10.2.6

Thanks!

Short, Self Contained Example

No response

Node.js Version

Node.js 20.x

package.json

{
    "name": "xxx",
    "version": "0.0.9",
    "license": "MIT",
    "scripts": {
        "start": "nx serve",
        "build": "nx build",
        "test": "nx test",
        "prepare": "is-docker || (husky install && nx run-many --target env-decrypt --all)",
        "mongo-rs": "run-rs -v 5.0.14 --host 127.0.0.1 --portStart 45000 --dbpath mongodb-data"
    },
    "private": true,
    "devDependencies": {
        "@compodoc/compodoc": "^1.1.15",
        "@golevelup/ts-jest": "^0.4.0",
        "@jest-mock/express": "^2.0.1",
        "@nestjs/schematics": "10.0.2",
        "@nestjs/testing": "10.2.6",
        "@nx-tools/nx-container": "^4.0.2",
        "@nx-tools/nx-docker": "^3.0.1",
        "@nx/devkit": "16.9.1",
        "@nx/eslint-plugin": "16.9.1",
        "@nx/jest": "16.9.1",
        "@nx/js": "16.9.1",
        "@nx/linter": "16.9.1",
        "@nx/nest": "16.9.1",
        "@nx/node": "16.9.1",
        "@nx/plugin": "16.9.1",
        "@nx/webpack": "16.9.1",
        "@nx/workspace": "16.9.1",
        "@swc-node/register": "~1.6.7",
        "@swc/cli": "~0.1.62",
        "@swc/core": "1.3.90",
        "@swc/helpers": "0.5.2",
        "@twittwer/compodoc": "^1.8.0",
        "@types/amqp-connection-manager": "^3.4.1",
        "@types/boom": "^7.3.2",
        "@types/cache-manager": "^4.0.2",
        "@types/express": "^4.17.13",
        "@types/formdata": "^0.10.1",
        "@types/http-proxy": "^1.17.5",
        "@types/jest": "29.5.3",
        "@types/lodash": "^4.14.178",
        "@types/luxon": "^3.0.0",
        "@types/moment": "^2.13.0",
        "@types/moment-business-time": "^1.1.1",
        "@types/moment-timezone": "^0.5.30",
        "@types/node": "18.7.1",
        "@types/object-hash": "^2.2.1",
        "@types/pg": "^8.6.5",
        "@types/pg-cursor": "^2.7.0",
        "@types/supertest": "^2.0.11",
        "@types/tar": "^6.1.1",
        "@types/vcf": "^2.0.3",
        "@types/web-push": "^3.3.2",
        "@typescript-eslint/eslint-plugin": "5.62.0",
        "@typescript-eslint/parser": "5.62.0",
        "axios-mock-adapter": "1.21.2",
        "eslint": "8.46.0",
        "eslint-config-prettier": "^8.5.0",
        "husky": "^8.0.1",
        "jest": "^29.6.1",
        "jest-each": "^29.6.1",
        "jest-environment-jsdom": "29.6.1",
        "jest-environment-node": "^29.6.1",
        "jest-junit": "^15.0.0",
        "jest-when": "^3.5.0",
        "json-schema-to-typescript": "^11.0.2",
        "jsonc-eslint-parser": "^2.1.0",
        "lint-staged": "^13.0.0",
        "mock-express-request": "^0.2.2",
        "mock-express-response": "^0.3.0",
        "mongodb-memory-server": "^8.6.0",
        "nock": "^13.2.9",
        "node-gyp": "^8.4.1",
        "nx": "16.9.1",
        "nx-cloud": "16.4.0",
        "organize-imports-cli": "^0.10.0",
        "prettier": "^2.7.1",
        "run-rs": "^0.7.7",
        "sonar-scanner": "^3.1.0",
        "supertest": "^6.2.1",
        "ts-jest": "29.1.0",
        "ts-node": "10.9.1",
        "typescript": "5.1.6"
    },
    "dependencies": {
        "@aws-sdk/client-s3": "^3.241.0",
        "@babel/core": "^7.21.8",
        "@fast-csv/format": "^4.3.5",
        "@golevelup/nestjs-discovery": "4.0.0",
        "@golevelup/nestjs-rabbitmq": "4.0.0",
        "@instana/collector": "^2.20.0",
        "@ladjs/country-language": "^1.0.2",
        "@nestjs/axios": "^3.0.0",
        "@nestjs/cache-manager": "^2.1.0",
        "@nestjs/common": "10.2.6",
        "@nestjs/core": "10.2.6",
        "@nestjs/jwt": "^10.1.0",
        "@nestjs/mongoose": "^10.0.0",
        "@nestjs/platform-express": "10.2.6",
        "@nestjs/platform-socket.io": "^10.1.0",
        "@nestjs/serve-static": "^4.0.0",
        "@nestjs/swagger": "7.1.2",
        "@nestjs/terminus": "^10.0.1",
        "@nestjs/websockets": "^10.1.0",
        "@type-cacheable/core": "^11.0.1",
        "@type-cacheable/ioredis-adapter": "^12.1.0",
        "@types/amqplib": "^0.10.0",
        "@types/simple-oauth2": "^4.1.1",
        "amqplib": "^0.10.0",
        "await-to-js": "^3.0.0",
        "axios": "1.3.4",
        "axios-retry": "^3.3.1",
        "basic-auth-parser": "^0.0.2-1",
        "bson": "^5.4.0",
        "cache-manager": "^5.1.4",
        "cache-manager-ioredis": "^2.1.0",
        "class-transformer": "^0.5.1",
        "class-validator": "^0.13.2",
        "dotenv": "^16.0.1",
        "exceljs": "^4.3.0",
        "express": "^4.18.2",
        "express-bearer-token": "^2.4.0",
        "form-data": "^4.0.0",
        "generate-password": "^1.7.0",
        "http-proxy": "^1.18.1",
        "http-proxy-middleware": "^2.0.3",
        "http-status-codes": "^2.2.0",
        "image-size": "^1.0.2",
        "ioredis": "^5.0.6",
        "is-docker": "^3.0.0",
        "json-to-pretty-yaml": "^1.2.2",
        "jwks-rsa": "^3.0.1",
        "kafkajs": "^2.2.3",
        "libphonenumber-js": "^1.10.28",
        "lodash": "^4.17.21",
        "lru-cache": "^7.12.0",
        "luxon": "^3.0.1",
        "migrate-mongo": "^9.0.0",
        "mime-types": "^2.1.35",
        "minimist": "^1.2.6",
        "moment": "^2.29.4",
        "moment-business-time": "^2.0.0",
        "moment-timezone": "^0.5.41",
        "mongoose": "^7.0.2",
        "nest-winston": "^1.9.3",
        "nestjs-asyncapi": "^1.2.1",
        "nestjs-cls": "^3.5.0",
        "object-hash": "^3.0.0",
        "oniyi-ltpa": "^2.1.0",
        "p-limit": "^3.1.0",
        "pg": "^8.7.3",
        "pg-cursor": "^2.7.3",
        "query-string": "^7.1.1",
        "redlock": "^5.0.0-beta.2",
        "reflect-metadata": "^0.1.13",
        "rxjs": "^7.8.0",
        "simple-oauth2": "^5.0.0",
        "socket.io": "^4.5.1",
        "socket.io-client": "^4.5.1",
        "swagger-ui-express": "^4.4.0",
        "tar": "^6.1.11",
        "tslib": "^2.3.1",
        "uuid": "^9.0.0",
        "vcf": "^2.1.1",
        "web-push": "^3.4.5",
        "winston": "^3.4.0"
    },
    "overrides": {
        "@nx/node@15.6.3": {
            "node-abort-controller": "3.1.1"
        }
    },
    "lint-staged": {
        "*.ts": "organize-imports-cli",
        "*.{ts,js,json,yml,yaml}": "prettier --write"
    }
}

package-lock.json

too long
kirrg001 commented 11 months ago

Hi there!

services to be flooded with log statements like this:

We will release a fix to improve this asap.

Are you missing any spans?

chromey commented 11 months ago

Thanks. No not really, spans created by websocket messages are created just fine as far as I can tell.

kirrg001 commented 11 months ago

We have merged a fix and release asap 👍

basti1302 commented 11 months ago

The fix has been released with version 2.34.1.