Looks like std.fs.File.Writer broken on MacOs

I was experimenting with pre-allocated buffer, using stderr() and stdout() as well, and I could not get the output to show as a whole. I tried using cmd 1>test.out and used cmd 1>>test.out and I did get different results. Code I was using to test was a custom logging fn that used a particular writer:

fn logFn(
    comptime message_level: std.log.Level,
    comptime scope: @TypeOf(.enum_literal),
    comptime format: []const u8,
    args: anytype,
) void {
    if (builtin.os.tag == .macos) {
        var buf: [64]u8 = undefined;
        // const stderr, const ttyconfig = std.debug.lockStderrWriter(&buf);
        // defer std.debug.unlockStdErrWriter();
        var stderr_init = std.fs.File.stderr().writer(&buf); //or std.fs.File.stdout().writer(&buf);
        const stderr = &stderr_init.interface;
        const TtyConf = std.Io.tty.Config.detect(std.fs.File.stderr());

        // Write timestamp first to avoid coloring it.
        TtyConf.setColor(stderr, .reset) catch {};
        currentTime(stderr) catch return;
        stderr.writeAll(" ") catch return;

        TtyConf.setColor(stderr, switch (message_level) {
            .err => .red,
            .warn => .yellow,
            .info => .green,
            .debug => .magenta,
        }) catch {};

        TtyConf.setColor(stderr, .bold) catch {};
        stderr.writeAll("[") catch return;
        stderr.writeAll(message_level.asText()) catch return;
        stderr.writeAll("]") catch return;
        TtyConf.setColor(stderr, .reset) catch {};
        TtyConf.setColor(stderr, .dim) catch {};
        TtyConf.setColor(stderr, .bold) catch {};
        if (scope != .default) {
            stderr.print("({s})", .{@tagName(scope)}) catch return;
        }
        stderr.writeAll(": ") catch return;
        TtyConf.setColor(stderr, .reset) catch {};
        stderr.print(format ++ "\n", args) catch return;
        stderr.flush() catch {};
}

In case function that formats time is relevant:

fn currentTime(w: *std.Io.Writer) !void {
    var time = try w.writableSliceGreedy(64);
    var time_str: ctime.tm = undefined;
    var now: ctime.time_t = ctime.time(null);
    const timeinfo = ctime.localtime_r(&now, &time_str);
    const fmt = "%b %d %H:%M:%S"; // Example: "Oct 30 12:47:23"
    const time_len = ctime.strftime(time.ptr, time.len, fmt, timeinfo);
    w.advance(time_len);
}

and then I was playing around with something like this:

    std.debug.print("{s}\n", .{some_str.something ++ " " ++ some_str.something_else ++ " and " ++ some_str.long_string});
    std.log.info("something form log.", .{});
    std.log.info("something else form log.", .{});
    std.log.info("third line of something else form log.", .{});

This is how it should look like:

j.markovic@MacBook-Pro-2 ~/GIT/zig-playgorund % zig-out/bin/zig_playgorund
Hello World and Looooooooooooooooong string
Nov 21 20:47:52 [info]: something form log.
Nov 21 20:47:52 [info]: something else form log.
Nov 21 20:47:52 [info]: third line of something else form log.

But was getting something really weird:

j.markovic@MacBook-Pro-2 ~/GIT/zig-playgorund % zig-out/bin/zig_playgorund 2>test.err
j.markovic@MacBook-Pro-2 ~/GIT/zig-playgorund % cat test.err
Nov 21 20:48:16 [info]: third line of something else form log.
j.markovic@MacBook-Pro-2 ~/GIT/zig-playgorund % truncate -s 0 test.err
j.markovic@MacBook-Pro-2 ~/GIT/zig-playgorund % zig-out/bin/zig_playgorund 2>>test.err
j.markovic@MacBook-Pro-2 ~/GIT/zig-playgorund % cat test.err
Nov 21 20:48:36 [info]: third line of something else form log.
j.markovic@MacBook-Pro-2 ~/GIT/zig-playgorund % zig-out/bin/zig_playgorund 2>>test.err
j.markovic@MacBook-Pro-2 ~/GIT/zig-playgorund % cat test.err
Nov 21 20:48:48 [info]: third line of something else form log.
Hello World and Looooooooooooooooong string
j.markovic@MacBook-Pro-2 ~/GIT/zig-playgorund %

When I write to an empty file, I get last line consistently. If I use 2>>test.err on a file that contains the last string in it already, I get the first string?
If I echo some arbitrary string before the 2>>test.err, it gets deleted. Also odd behavior. It should not be deleted if I use append but it does .
Even if I have multiple lines written, and I write multiple appends I get overwrite of the echo lines, and I get a cut of from one of the zig’s lines:

j.markovic@MacBook-Pro-2 ~/GIT/zig-playgorund % truncate -s 0 test.err
j.markovic@MacBook-Pro-2 ~/GIT/zig-playgorund % echo "line from echo">>test.err
j.markovic@MacBook-Pro-2 ~/GIT/zig-playgorund % zig-out/bin/zig_playgorund 2>>test.err
j.markovic@MacBook-Pro-2 ~/GIT/zig-playgorund % cat test.err
Nov 21 20:49:31 [info]: third line of something else form log.
j.markovic@MacBook-Pro-2 ~/GIT/zig-playgorund % truncate -s 0 test.err
j.markovic@MacBook-Pro-2 ~/GIT/zig-playgorund % echo "line from echo">>test.err
j.markovic@MacBook-Pro-2 ~/GIT/zig-playgorund % echo "line from echo">>test.err
j.markovic@MacBook-Pro-2 ~/GIT/zig-playgorund % echo "line from echo">>test.err
j.markovic@MacBook-Pro-2 ~/GIT/zig-playgorund % cat test.err
line from echo
line from echo
line from echo
j.markovic@MacBook-Pro-2 ~/GIT/zig-playgorund % zig-out/bin/zig_playgorund 2>>test.err
j.markovic@MacBook-Pro-2 ~/GIT/zig-playgorund % cat test.err
Nov 21 20:49:50 [info]: third line of something else form log.
oooooooooooooooong string
j.markovic@MacBook-Pro-2 ~/GIT/zig-playgorund % zig-out/bin/zig_playgorund 2>>test.err
j.markovic@MacBook-Pro-2 ~/GIT/zig-playgorund % zig-out/bin/zig_playgorund 2>>test.err
j.markovic@MacBook-Pro-2 ~/GIT/zig-playgorund % zig-out/bin/zig_playgorund 2>>test.err
j.markovic@MacBook-Pro-2 ~/GIT/zig-playgorund % cat test.err
Nov 21 20:49:57 [info]: third line of something else form log.
oooooooooooooooong string
Hello World and Looooooooooooooooong string
Hello World and Looooooooooooooooong string
Hello World and Looooooooooooooooong string
j.markovic@MacBook-Pro-2 ~/GIT/zig-playgorund %

But none of that happens if I use debug.lockStderrWriter(); It respects appending to a file and overwriting with 2>test.err. And it writes the whole output like it’s shown directly in the CLI.

On Linux works as expected with 2>>test.err. It prints all output to a file correctly. In earlier versions of Zig, this was occurring on Linux as well but not anymore. I’m on latest dev

EDIT:
Maybe I’m not doing something correctly here? If not I guess it’s worth a bug report on Github?

Sounds to me like something I swear there was a topic posted here about but I can’t find for the life of me right now.

File.Writer is by default initialized in “positional” mode, which starts the position at 0 and keeps track of the pos internally. If positional writing fails, then it falls back to streaming mode.

So, when stderr is not a file, your log function will fall back to streaming mode and work correctly, but when stderr is a file, you’re creating a new File.Writer starting at position 0 on every log call, so it’s writing each message at position 0 in the file each time, overwriting the last message.

lockStderrWriter is a solution because it moves the File.Writer to global state, meaning that if it uses positional writing, the pos will persist between lockStderrWriter calls.

Another potential fix would be to always use “streaming” mode by calling writerStreaming instead of writer.

9 Likes