open-telemetry / open-telemetry/opentelemetry-zig

BatchingLogRecordProcessor does not flush on shutdown

Open
#89 0 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

Dominant language
Zig
Stars
22
Forks
16
Avg merge
1d 18h
Merged PRs (30d)
13

Description

The source states that LogRecordProcessor.shutdown includes the effect of forceFlush. On the other hand in BatchLogRecordProcessor the flushing thread skips the last flush since the task.cancel in shutdown causes every cancelable operation from that task to fail with error.Canceled:

pub const BatchingLogRecordProcessor = struct {

    // ...

    fn shutdown(ctx: *anyopaque) anyerror!void {
        // ...

        // Cancel the background task (unblocks its wait and waits for it to finish)
        if (self.export_task) |*task| {
            task.cancel(self.io); // <---- exportLoop is canceled
            self.export_task = null;
        }
    }

    // ...

    fn exportLoop(self: *Self) void {
        while (true) {
            self.mutex.lockUncancelable(self.io);
            if (self.should_shutdown.load(.acquire)) {
                while (self.queue.len > 0) {
                    if (!self.exportBatch()) break; // <--- exportBatch may be canceled
                }
                self.mutex.unlock(self.io);
                break;
            }

            // ...
        }
    }

    /// Must be called while holding the mutex
    fn exportBatch(self: *Self) bool {

        // ...

        // Export the batch (unlock mutex during export to allow concurrent onEmit calls)
        self.mutex.unlock(self.io);
        self.exporter.exportLogs(logs_to_export) catch |err| { // <--- the last exportLogs may be canceled, causing the last flush to be lost
            // ...
        };
        self.mutex.lockUncancelable(self.io);

        // ...
    }

    // ...
};

You can reproduce this problem with the following script:

const std = @import("std");
const sdk = @import("opentelemetry-sdk");

const N = 6;

const Exporter = struct {
    io: std.Io,
    got: usize = 0,

    fn iface(self: *Exporter) sdk.logs.LogRecordExporter {
        return .{ .ptr = self, .vtable = &.{ .exportLogsFn = exp, .shutdownFn = nop } };
    }

    // Count exported records
    fn exp(ctx: *anyopaque, recs: []sdk.logs.ReadbleLogRecord) anyerror!void {
        const self: *Exporter = @ptrCast(@alignCast(ctx));
        var never_set: std.Io.Event = .unset;
        const in_1ms: std.Io.Timeout = .{ .duration = .{ .raw = .{ .nanoseconds = std.time.ns_per_ms }, .clock = .awake } };
        never_set.waitTimeout(self.io, in_1ms) catch |e| switch (e) {
            error.Timeout => {},
            else => return e,
        };
        self.got += recs.len;
    }

    fn nop(_: *anyopaque) anyerror!void {}
};

fn run(gpa: std.mem.Allocator, io: std.Io, flush: bool) !usize {
    var ex = Exporter{ .io = io };
    var proc = try sdk.logs.BatchingLogRecordProcessor.init(gpa, io, ex.iface(), .{
        // the background loop can never fire, so forceFlush/shutdown is the only export
        .max_export_batch_size = N + 1,
        .scheduled_delay_millis = 60_000,
    });

    var provider = try sdk.logs.LoggerProvider.init(gpa, io, null);
    defer provider.deinit();
    try provider.addLogRecordProcessor(proc.asLogRecordProcessor());

    const logger = try provider.getLogger(.{ .name = "repro" });
    for (0..N) |_| {
        logger.emit(.info, "record", .{});
    }

    if (flush) {
        try provider.forceFlush();
    }

    try provider.shutdown();
    proc.deinit();
    return ex.got;
}

pub fn main(init: std.process.Init) !void {
    const without = try run(init.gpa, init.io, false);
    const with = try run(init.gpa, init.io, true);

    std.debug.print("no explicit flush:   {d}/{d}\n", .{ without, N });
    std.debug.print("with explicit flush: {d}/{d}\n", .{ with, N });

    if (without < N) std.process.exit(1);
}

Which prints:

error: BatchingLogRecordProcessor failed to export log batch: error.Canceled
no explicit flush:   0/6
with explicit flush: 6/6

Traces have the same problem, where shutdown cancels the worker causing exportSpans to fail

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start with opentelemetry-sdk/src/sdk/logs/log_record_processor.zig, especially BatchingLogRecordProcessor.shutdown, exportLoop, and exportBatch, and run the supplied reproduction to observe the canceled final export. Then inspect opentelemetry-sdk/src/sdk/trace/span_processor.zig, including shutdown and exportSpans. Done means shutdown performs the required final flush for both logs and traces without requiring an explicit forceFlush.

Written by the indexing model from the issue text.

Assessment

Tech stack
zig
Domain
observability-sre
Issue type
Bug
Difficulty
3/5
Estimated time
1-2 days
Activity status
Active
Clarity
Clearly specified
Newbie friendliness
75/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.