opentelemetry-js icon indicating copy to clipboard operation
opentelemetry-js copied to clipboard

BatchLogRecordProcessor not sending records when queue hits maxExportBatchSize

Open Emut opened this issue 5 months ago • 1 comments
trafficstars

What happened?

Steps to Reproduce

See the repro repo

Expected Result

With at least maxExportBatchSizerecords in queue, a batch should be sent to the exporter.

Actual Result

Records are emitted at every scheduledDelayMillisms, regardless of queue length. Processor still respects the maxExportBatchSize though and sending them in batches, while waiting for another scheduledDelayMillis between batches.

Additional Details

The JavaDocs state:

Logs are exported either when there are maxExportBatchSize pending logs or scheduleDelayNanos has passed since the last export finished.

Which makes more sense given this is a batch processor. Js implementation acts more or less as a rate limiter.

Unsure if there is a language agnostic SDK definition describing the intended behavior.

OpenTelemetry Setup Code

import {BatchLogRecordProcessor, ConsoleLogRecordExporter, LoggerProvider} from "@opentelemetry/sdk-logs";

const main = async ():Promise<void> => {
    const consoleExporter = new ConsoleLogRecordExporter();
    const batchProcessor = new BatchLogRecordProcessor(consoleExporter, {maxExportBatchSize: 2, scheduledDelayMillis: 5_000});
    const loggerProvider = new LoggerProvider({processors:[batchProcessor]});
    const logger = loggerProvider.getLogger('default');

    for (let i = 0; i < 5; ++i) {
        logger.emit({body: `${i}`});
    }

    // 5 logs of batches of 2
    // expect to see 2 batches of 2 immediately, followed by the 5th one after 5_000ms
    // instead get (5_000ms wait, 2 logs, 5_000ms wait, 2 logs, 5_000ms wait, 1 log)

    setInterval(() => console.log(Date.now()), 1_000);
};

(async () => {
    await main();
})();

package.json

{
  "name": "otel-batch-issue",
  "version": "1.0.0",
  "description": "repro for BatchLogRecordProcessor not sending records when queue hits maxExportBatchSize",
  "main": "index.js",
  "scripts": {
    "test": "echo \"Error: no test specified\" && exit 1"
  },
  "engines": {
    "node": "22.15.0"
  },
  "repository": {
    "type": "git",
    "url": "git+https://github.com/Emut/otel-batch-issue.git"
  },
  "keywords": [],
  "author": "",
  "license": "ISC",
  "bugs": {
    "url": "https://github.com/Emut/otel-batch-issue/issues"
  },
  "homepage": "https://github.com/Emut/otel-batch-issue#readme",
  "dependencies": {
    "@opentelemetry/api-logs": "^0.201.1",
    "@opentelemetry/exporter-logs-otlp-proto": "^0.201.1",
    "@opentelemetry/sdk-logs": "^0.201.1"
  }
}

Relevant log output

1747928982729
1747928983731
1747928984732
1747928985733
{
  resource: {
    attributes: {
      'service.name': 'unknown_service:/usr/local/bin/node',
      'telemetry.sdk.language': 'nodejs',
      'telemetry.sdk.name': 'opentelemetry',
      'telemetry.sdk.version': '2.0.1'
    }
  },
  instrumentationScope: { name: 'default', version: undefined, schemaUrl: undefined },
  timestamp: 1747928981728000,
  traceId: undefined,
  spanId: undefined,
  traceFlags: undefined,
  severityText: undefined,
  severityNumber: undefined,
  body: '0',
  attributes: {}
}
{
  resource: {
    attributes: {
      'service.name': 'unknown_service:/usr/local/bin/node',
      'telemetry.sdk.language': 'nodejs',
      'telemetry.sdk.name': 'opentelemetry',
      'telemetry.sdk.version': '2.0.1'
    }
  },
  instrumentationScope: { name: 'default', version: undefined, schemaUrl: undefined },
  timestamp: 1747928981728000,
  traceId: undefined,
  spanId: undefined,
  traceFlags: undefined,
  severityText: undefined,
  severityNumber: undefined,
  body: '1',
  attributes: {}
}
1747928986735
1747928987736
1747928988737
1747928989738
1747928990739
{
  resource: {
    attributes: {
      'service.name': 'unknown_service:/usr/local/bin/node',
      'telemetry.sdk.language': 'nodejs',
      'telemetry.sdk.name': 'opentelemetry',
      'telemetry.sdk.version': '2.0.1'
    }
  },
  instrumentationScope: { name: 'default', version: undefined, schemaUrl: undefined },
  timestamp: 1747928981728000,
  traceId: undefined,
  spanId: undefined,
  traceFlags: undefined,
  severityText: undefined,
  severityNumber: undefined,
  body: '2',
  attributes: {}
}
{
  resource: {
    attributes: {
      'service.name': 'unknown_service:/usr/local/bin/node',
      'telemetry.sdk.language': 'nodejs',
      'telemetry.sdk.name': 'opentelemetry',
      'telemetry.sdk.version': '2.0.1'
    }
  },
  instrumentationScope: { name: 'default', version: undefined, schemaUrl: undefined },
  timestamp: 1747928981728000,
  traceId: undefined,
  spanId: undefined,
  traceFlags: undefined,
  severityText: undefined,
  severityNumber: undefined,
  body: '3',
  attributes: {}
}
1747928991740
1747928992741
1747928993743
1747928994743
1747928995743
{
  resource: {
    attributes: {
      'service.name': 'unknown_service:/usr/local/bin/node',
      'telemetry.sdk.language': 'nodejs',
      'telemetry.sdk.name': 'opentelemetry',
      'telemetry.sdk.version': '2.0.1'
    }
  },
  instrumentationScope: { name: 'default', version: undefined, schemaUrl: undefined },
  timestamp: 1747928981728000,
  traceId: undefined,
  spanId: undefined,
  traceFlags: undefined,
  severityText: undefined,
  severityNumber: undefined,
  body: '4',
  attributes: {}
}
1747928996743
1747928997745

Operating System and Version

macOS Version 15.4.1 (24E263)

Runtime and Version

Node.js v22.11.0

Emut avatar May 22 '25 15:05 Emut