JaegerExporter can throw on export

[dyladan]

Please answer these questions before submitting a bug report.

What version of OpenTelemetry are you using?

0.2.0

What version of Node are you using?

8 and 10

What did you do?

If possible, provide a recipe for reproducing the error.

// tracing.ts
const opentelemetry = require('@opentelemetry/core');
const {NodeTracer} = require('@opentelemetry/node');

const {BatchSpanProcessor} = require('@opentelemetry/tracing');
const {JaegerExporter} = require('@opentelemetry/exporter-jaeger');

const tracer = new NodeTracer({
    logLevel: opentelemetry.LogLevel.DEBUG,
    plugins: {
        dns: {
            enabled: true,
            path: '@opentelemetry/plugin-dns',
            ignoreHostnames: ['localhost'],
        },
        grpc: {
            enabled: true,
            path: '@opentelemetry/plugin-grpc',
        },
        http: {
            enabled: true,
            path: '@opentelemetry/plugin-http',
        },
        https: {
            enabled: true,
            path: '@opentelemetry/plugin-https',
        },
    },
});

opentelemetry.initGlobalTracer(tracer);

const host = process.env.JAEGER_AGENT_HOST || process.env.JAEGER_HOST || process.env.DD_AGENT_HOST || 'localhost';
tracer.addSpanProcessor(
    new BatchSpanProcessor(
        new JaegerExporter({
            serviceName: process.env.JAEGER_SERVICE_NAME,
            host,
        })
    )
);

// Workaround for bug
// https://github.com/open-telemetry/opentelemetry-js/issues/423#issuecomment-559982657
require('dns');

console.log('tracing initialized');

// index.ts

require("./tracing");

import * as express from "express";
import * as http from "http";

const app = express()

app.get("/", (req, res) => {
  res.send();
});

app.listen(8080)

Make an http request to localhost:8080, wait about 5 seconds for the batch to send.

What did you expect to see?

spans in the backend

What did you see instead?

process crash

RangeError [ERR_BUFFER_OUT_OF_BOUNDS]: Attempt to write outside buffer bounds
    at boundsError (internal/buffer.js:51:11)
    at checkBounds (internal/buffer.js:30:5)
    at checkInt (internal/buffer.js:37:3)
    at writeU_Int16BE (internal/buffer.js:653:3)
    at Buffer.writeUInt16BE (internal/buffer.js:661:10)
    at MessageRW.poolStrictWriteInto (/Users/daniel.dyla/playground/opentelemetry/testbed/node_modules/thriftrw/message.js:165:12)
    at MessageRW.poolWriteInto (/Users/daniel.dyla/playground/opentelemetry/testbed/node_modules/thriftrw/message.js:144:23)
    at MessageRW.writeInto (/Users/daniel.dyla/playground/opentelemetry/testbed/node_modules/bufrw/base.js:83:10)
    at UDPSender.flush (/Users/daniel.dyla/playground/opentelemetry/testbed/node_modules/jaeger-client/dist/src/reporters/udp_sender.js:164:78)
    at UDPSender.append (/Users/daniel.dyla/playground/opentelemetry/testbed/node_modules/jaeger-client/dist/src/reporters/udp_sender.js:146:12)

Additional context

Add any other context about the problem here.

@mayurkale22 please assign me, I think i found the issue

[dyladan]

Explanation of the issue

BatchSpanProcessor has a 20 second default timeout
JaegerExporter has a 5 second default timeout

When the JaegerExporter exports, it calls append on the _sender. In the default configuration, the sender flushes on every append.

After 20 seconds, the BatchSpanProcessor exports a batch of spans, which are appended and then exported. During this export, the 4th 5 second interval of the Jaeger exporter timeout occurs and it attempts to flush. 2 concurrent flushes cause the crash.

Fix: remove the 5 second timer from jaeger exporter

the jaeger exporter is already flushing on every export so there is no need for it to ever flush manually.

[mayurkale22]

the jaeger exporter is already flushing on every export so there is no need for it to ever flush manually.

I think this is not true, sender will wait till internal buffer reaches maxPacketSize: https://github.com/jaegertracing/jaeger-client-node/blob/master/src/reporters/udp_sender.js#L106-L113

[mayurkale22]

Fix: remove the 5 second timer from jaeger exporter

This might very well work in the production, but in case of examples you might not see the full traces unless you call shutdown on exporter (with forceFlush = true).

[dyladan]

@mayurkale22 stopping my simple example in the debugger shows max packet size to be NaN, therefore that check always fails. This seems like it is either a bug in our implementation or a bug in theirs.

It comes from line 87, but _emitSpanBatchOverhead is undefined. number - undefined => NaN.

_emitSpanBatchOverhead comes from the line before _calcBatchSize which takes a batch, but doesn't actually appear to use it and returns undefined no matter what.

All of this is to say, the branch you linked always evaluates to false no matter how the Jaeger exporter is configured.

[mayurkale22]

I just did console.log in udp_sender.js and I see these values 64934(this._maxSpanBytes), 65000(this._maxPacketSize), 66 (this._emitSpanBatchOverhead).

[dyladan]

with the exact above code using the 0.2.0 release versions of otel?

[dyladan]

blowing away my node_modules and rebuilding also gave me 64935.

[flanfly]

In case someone else stumbles over the same error: double check you used serviceName as parameter when creating the JaegerExporter object, not service (like I did). If that does not fix it, add a console.log() to the _calcBatchSize function in node_modules/jaeger-client/dist/src/reporters/udp_sender.js like this.

const x = this._agentThrift.Agent.emitBatch.argumentsMessageRW.byteLength(this._convertBatchToThriftMessage());
console.log(x, x.length)
return x.length

If something is wrong with the message itself this function barfs the error message out (x) instead of a buffer making x.length undefined as mentioned in #608 (comment)

Hope that helps someone.