[Bug]: Got Exception ,Only supported hex string lengths are 16 and 32

[gokhanakgul]

Problem Description

We are using instana agent for our nodejs application. The agent throws exception time to time as following. The exception happening when the application try to send a message via kafka, due to exception some of the message sending operations fails. Our expectation is the instana agent should not break the application internal operations. We already tried to upgrade the latest version unfortunately we are still facing with exception.

Only supported hex string lengths are 16 and 32, got: 1521f334c97fd3d�[39m Error: Only supported hex string lengths are 16 and 32, got: 1521f334c97fd3d at Object.unsignedHexStringToBuffer (/src/node_modules/@instana/core/src/tracing/tracingUtil.js:111:11) at Object.unsignedHexStringsToBuffer (/src/node_modules/@instana/core/src/tracing/tracingUtil.js:124:11) at Object.renderTraceContextToBuffer (/src/node_modules/@instana/core/src/tracing/tracingUtil.js:153:18) at addLegacyTraceContextHeaderToAllMessages (/src/node_modules/@instana/core/src/tracing/instrumentation/messaging/kafkaJs.js:452:23) at addTraceContextHeaderToAllMessages (/src/node_modules/@instana/core/src/tracing/instrumentation/messaging/kafkaJs.js:437:7) at /src/node_modules/@instana/core/src/tracing/instrumentation/messaging/kafkaJs.js:94:7 at /src/node_modules/@instana/core/src/tracing/clsHooked/async_local_storage_context.js:161:15 at /src/node_modules/@instana/core/src/tracing/clsHooked/async_local_storage_context.js:148:32 at AsyncLocalStorage.run (node:async_hooks:338:14) at Namespace.run (/src/node_modules/@instana/core/src/tracing/clsHooked/async_local_storage_context.js:148:13)

Short, Self Contained Example

    try {
            await this.kafka.send({ topic: topic }, order, order?.dcid, {
                dcid: order.dcid,
            });
            this.logger.log(`PushOrderToQueue dc-order-api successfully queued item to ${topic} dcId: ${order?.dcid}`);
        } catch (error) {
            this.logger.error(`PushOrderToQueue error updating status: ${error} TopicName: ${topic} DcId: ${order?.dcid}`);
        }

Node.js Version

v18.16.1

package.json

{
  "name": "dc-api-service-order",
  "version": "0.0.1",
  "description": "",
  "author": "",
  "private": true,
  "license": "UNLICENSED",
  "scripts": {
    "prebuild": "rimraf dist",
    "build": "nest build",
    "format": "prettier --write \"src/**/*.ts\" \"test/**/*.ts\"",
    "start": "nest start",
    "start:dev": "nest start --watch",
    "start:debug": "nest start --debug --watch",
    "start:prod": "node dist/main",
    "lint": "eslint \"{src,apps,libs,test}/**/*.ts\" --fix",
    "test": "jest",
    "test:watch": "jest --watch",
    "test:cov": "jest --coverage",
    "test:debug": "node --inspect-brk -r tsconfig-paths/register -r ts-node/register node_modules/.bin/jest --runInBand",
    "test:e2e": "jest --config ./test/jest-e2e.json",
    "sonar": "sonar-scanner"
  },
  "dependencies": {
    "@instana/collector": "^2.27.0",
    "@nestjs/axios": "^1.0.1",
    "@nestjs/common": "9.3.9",
    "@nestjs/config": "2.3.1",
    "@nestjs/core": "9.3.9",
    "@nestjs/microservices": "9.3.9",
    "@nestjs/mongoose": "9.2.1",
    "@nestjs/passport": "^9.0.3",
    "@nestjs/platform-express": "9.3.9",
    "@nestjs/swagger": "6.2.1",
    "@type-cacheable/core": "11.0.1",
    "@type-cacheable/ioredis-adapter": "12.1.0",
    "agentkeepalive": "^4.3.0",
    "fast-xml-parser": "3.18.0",
    "he": "1.2.0",
    "ioredis": "^5.3.1",
    "kafkajs": "^1.16.0",
    "mongoose": "6.9.2",
    "passport": "^0.6.0",
    "passport-headerapikey": "^1.2.2",
    "reflect-metadata": "^0.1.13",
    "request-ip": "^3.3.0",
    "rxjs": "^7.8.0",
    "soap": "^1.0.0",
    "swagger-ui-express": "4.6.0",
    "uuid": "^9.0.0",
    "xml2js": "^0.4.23"
  },
  "devDependencies": {
    "@nestjs/cli": "9.2.0",
    "@nestjs/schematics": "9.0.4",
    "@nestjs/testing": "9.3.9",
    "@types/express": "4.17.17",
    "@types/jest": "29.4.0",
    "@types/node": "18.13.0",
    "@types/superagent": "4.1.16",
    "@types/supertest": "^2.0.12",
    "@typescript-eslint/eslint-plugin": "^5.52.0",
    "@typescript-eslint/parser": "^5.52.0",
    "eslint": "^8.34.0",
    "eslint-config-prettier": "8.6.0",
    "eslint-plugin-prettier": "^4.2.1",
    "jest": "^29.4.3",
    "prettier": "^2.8.4",
    "sonar-scanner": "^3.1.0",
    "supertest": "^6.3.3",
    "ts-jest": "^29.0.5",
    "ts-loader": "^9.4.2",
    "ts-node": "^10.9.1",
    "tsconfig-paths": "^4.1.2",
    "typescript": "^4.9.5"
  },
  "jest": {
    "moduleFileExtensions": [
      "js",
      "json",
      "ts"
    ],
    "rootDir": "src",
    "testRegex": ".*\\.spec\\.ts$",
    "transform": {
      "^.+\\.(t|j)s$": "ts-jest"
    },
    "collectCoverageFrom": [
      "**/*.(t|j)s"
    ],
    "coverageDirectory": "../coverage",
    "testEnvironment": "node"
  }
}

package-lock.json

{}

[basti1302]

Thank you very much for the detailed report. We will look into this right away.

You can work around this issue for now by configuring @instana/collector to only send the trace correlation headers as strings.

For that, you could either use:

com.instana.tracing:
  kafka:
    header-format: string

in your Instana agent configuration file, or set the environment variable INSTANA_KAFKA_HEADER_FORMAT=string on your Node.js process.

You can find more documentation around this https://www.ibm.com/docs/en/instana-observability/current?topic=references-kafka-header-migration#configuration-options.

[basti1302]

One question: Can you confirm that this only happens when your Node.js application receives an incoming call (could be another Kafka message, an HTTP request, an RPC call, ...) from another service that is also instrumented with either an Instana tracer or another W3C trace context compatible tracer (like OpenTelemetry, Dynatrace, ...)?

I can reproduce your issue for that scenario. I can't see how this would happen if your Node.js application is the one that starts the trace (that is, if it is the first service in this distributed transaction that is instrumented by a tracer).

Thanks in advance.

[gokhanakgul]

One question: Can you confirm that this only happens when your Node.js application receives an incoming call (could be another Kafka message, an HTTP request, an RPC call, ...) from another service that is also instrumented with either an Instana tracer or another W3C trace context compatible tracer (like OpenTelemetry, Dynatrace, ...)?

I can reproduce your issue for that scenario. I can't see how this would happen if your Node.js application is the one that starts the trace (that is, if it is the first service in this distributed transaction that is instrumented by a tracer).

Thanks in advance.

We are using only the instana right now. As you guess other applications communicate over kafka and instana shows the communication path on their dashboard.