Std.log double printing, manual bufferedwrite works fine

poopiepants · July 17, 2024, 5:13am

i rewrote logging in my app to use std.log, scoped on various files

in main.zig, I have something like

pub const std_options: std.Options = .{
    // .log_level = std.log.Level.info,
    .log_scope_levels = &[_]std.log.ScopeLevel{
        .{ .scope = .gb, .level = .info },
        .{ .scope = .cpu, .level = .debug },
        .{ .scope = .gpu, .level = .info },
        .{ .scope = .mbc, .level = .info },
        .{ .scope = .timer, .level = .info },
        .{ .scope = .joy, .level = .info },
        .{ .scope = .bus, .level = .info },
    },
};

cpu is at debug, as i want to test something specific to it

in cpu.zig,

const log = std.log.scoped(.cpu);

with a function

fn beeg_print(self: *CPU) void {
// if (self.pc <= 0x100) {
// return;
// }
log.debug(“A: {X:0>2} F: {X:0>2} B: {X:0>2} C: {X:0>2} D: {X:0>2} E: {X:0>2} H: {X:0>2} L: {X:0>2} SP: {X:0>4} PC: 00:{X:0>4} ({X:0>2} {X:0>2} {X:0>2} {X:0>2})\n”, .{
self.registers.A,
@as(u8, @bitCast(self.registers.F)),
self.registers.B,
self.registers.C,
self.registers.D,
self.registers.E,
self.registers.H,
self.registers.L,
self.sp,
self.pc,
self.bus.read_byte(self.pc),
self.bus.read_byte(self.pc +% 1),
self.bus.read_byte(self.pc +% 2),
self.bus.read_byte(self.pc +% 3),
});

The code is single threaded and I use the function once per loop. I’m tracing cpu emulator output, so it’s printing a lot. I’ve tested switching between a bufferedwriter written myself and std.log and observe double printing when using std.log. from reading source, stdlog uses bufferedwriter with little else added. any idea what im missing?

cancername · July 17, 2024, 6:56pm

Can you describe the problem more clearly? What do you mean by “double printing”?

poopiepants · July 17, 2024, 7:11pm

the output of my program looks like this

A: 3A F: 00 B: 68 C: 44 D: 00 E: 39 H: FF L: 3A SP: FDFF PC: 00:6E05 (EA 7C C1 FE)
A: 3A F: 00 B: 68 C: 44 D: 00 E: 39 H: FF L: 3A SP: FDFF PC: 00:6E05 (EA 7C C1 FE)
A: 3A F: 00 B: 68 C: 44 D: 00 E: 39 H: FF L: 3A SP: FDFF PC: 00:6E08 (FE 3A 28 17)
A: 3A F: C0 B: 68 C: 44 D: 00 E: 39 H: FF L: 3A SP: FDFF PC: 00:6E0A (28 17 BD 38)
A: 3A F: 00 B: 68 C: 44 D: 00 E: 39 H: FF L: 3A SP: FDFF PC: 00:6E08 (FE 3A 28 17)
A: 3A F: C0 B: 68 C: 44 D: 00 E: 39 H: FF L: 3A SP: FDFF PC: 00:6E0A (28 17 BD 38)
A: 3A F: C0 B: 68 C: 44 D: 00 E: 39 H: FF L: 3A SP: FDFF PC: 00:6E23 (F0 97 E0 42)
A: 3A F: C0 B: 68 C: 44 D: 00 E: 39 H: FF L: 3A SP: FDFF PC: 00:6E23 (F0 97 E0 42)
A: 6F F: C0 B: 68 C: 44 D: 00 E: 39 H: FF L: 3A SP: FDFF PC: 00:6E25 (E0 42 FA 97)
A: 6F F: C0 B: 68 C: 44 D: 00 E: 39 H: FF L: 3A SP: FDFF PC: 00:6E25 (E0 42 FA 97)
A: 6F F: C0 B: 68 C: 44 D: 00 E: 39 H: FF L: 3A SP: FDFF PC: 00:6E27 (FA 97 DB E0)
A: 6F F: C0 B: 68 C: 44 D: 00 E: 39 H: FF L: 3A SP: FDFF PC: 00:6E27 (FA 97 DB E0)
A: C9 F: C0 B: 68 C: 44 D: 00 E: 39 H: FF L: 3A SP: FDFF PC: 00:6E2A (E0 47 C9 F0)
A: C9 F: C0 B: 68 C: 44 D: 00 E: 39 H: FF L: 3A SP: FDFF PC: 00:6E2A (E0 47 C9 F0)
A: C9 F: C0 B: 68 C: 44 D: 00 E: 39 H: FF L: 3A SP: FDFF PC: 00:6E2C (C9 F0 CC E6)
A: C9 F: C0 B: 68 C: 44 D: 00 E: 39 H: FF L: 3A SP: FDFF PC: 00:6E2C (C9 F0 CC E6)

note the PC value. there’s two prints per instruction when there should only be one. i’ve narrowed down the issue a little more I think

using

const stderr = std.io.getStdErr();
pub var buf = std.io.bufferedWriter(stderr.writer());

pub const buflog = buf.writer();

fn beeg_print(self: *CPU) void {
    buflog.print("A: {X:0>2} F: {X:0>2} B: {X:0>2} C: {X:0>2} D: {X:0>2} E: {X:0>2} H: {X:0>2} L: {X:0>2} SP: {X:0>4} PC: 00:{X:0>4} ({X:0>2} {X:0>2} {X:0>2} {X:0>2})\n", .{
        self.registers.A,
        @as(u8, @bitCast(self.registers.F)),
        self.registers.B,
        self.registers.C,
        self.registers.D,
        self.registers.E,
        self.registers.H,
        self.registers.L,
        self.sp,
        self.pc,
        self.bus.read_byte(self.pc),
        self.bus.read_byte(self.pc +% 1),
        self.bus.read_byte(self.pc +% 2),
        self.bus.read_byte(self.pc +% 3),
    }) catch unreachable;
    buf.flush() catch unreachable;

if I remove the flush(), things print correctly. with flush(), everything prints twice.

IntegratedQuantum · July 17, 2024, 8:11pm

Since you have less than 4kB of data printed in total here, a buffered writer without flush wouldn’t actually print anything. The only thing I can think of is that you might be printing the same thing a second time somewhere else in your program.

Other than that I cannot really help much without being able to look at the complete program or, preferably, a minimal reproducible.

IntegratedQuantum · July 18, 2024, 7:05am

I think your best bet is to try and reduce the error.
Does it still happen if you only print simple things, like just a static string, instead of printing all attributes?
Also did you built it in debug mode?

poopiepants · July 20, 2024, 2:29am

pub fn main() void {
    var i: usize = 0;
    while (true) : (i += 1) {
        buflog.print("{d}\n", .{i}) catch unreachable;
        buf.flush() catch unreachable;
    }
}

a few odd repetitions in there. this is in debug mode, but release=safe looks no better

squeek502 · July 20, 2024, 4:50am

I can’t reproduce this on Windows. Here’s what I’m running:

const std = @import("std");

pub fn main() !void {
    const stderr = std.io.getStdErr();
    var buf_writer = std.io.bufferedWriter(stderr.writer());
    const writer = buf_writer.writer();

    var i: usize = 0;
    while (true) : (i += 1) {
        try writer.print("{d}\n", .{i});
        try buf_writer.flush();
        if (i == 1000) break;
    }
}

It outputs the numbers perfectly sequentially. Do you see the same buggy behavior if you run this code?

IntegratedQuantum · July 20, 2024, 8:09am

I also cannot reproduce it on linux.
What operating system are you on? What version of zig are you using?

dude_the_builder · July 20, 2024, 1:12pm

Can’t reproduce on macOS either.

poopiepants · July 20, 2024, 5:41pm

squeek502:

const std = @import("std");

pub fn main() !void {
    const stderr = std.io.getStdErr();
    var buf_writer = std.io.bufferedWriter(stderr.writer());
    const writer = buf_writer.writer();

    var i: usize = 0;
    while (true) : (i += 1) {
        try writer.print("{d}\n", .{i});
        try buf_writer.flush();
        if (i == 1000) break;
    }
}

➜  GBEMU git:(main) ✗ system_profiler SPSoftwareDataType SPHardwareDataType


Software:

    System Software Overview:

      System Version: macOS 14.5 (23F79)
      Kernel Version: Darwin 23.5.0
      Boot Volume: Macintosh HD
      Boot Mode: Normal
      Secure Virtual Memory: Enabled
      System Integrity Protection: Enabled
      Time since boot: 48 days, 4 hours, 25 minutes

Hardware:

    Hardware Overview:

      Model Name: MacBook Pro
      Model Identifier: Mac14,5
      Model Number: MPHG3LL/A
      Chip: Apple M2 Max
      Total Number of Cores: 12 (8 performance and 4 efficiency)
      Memory: 32 GB
      System Firmware Version: 10151.121.1
      OS Loader Version: 10151.121.1


➜  GBEMU git:(main) ✗ zig version                                                                  
0.13.0

brodeuralexis · July 20, 2024, 8:02pm

There is no macos specific code in std.io.BufferedReader and the code [std.io.getStdErr] for (zig/lib/std/io.zig at master · ziglang/zig · GitHub) and its file handle uses POSIX, so any problem in both of those places would also appear for users on Linux.

At this point, I don’t believe this is an issue with Zig.

What terminal emulator are you using? The default Terminal.app on macos, the VSCode one, Alacritty, etc.?

Are you also able to reproduce the problem with stdout, or does it happen only with stderr?

Your computer has also been booted for 48 days straight. Does restarting it make any difference?

poopiepants · July 20, 2024, 8:24pm

i misremembered redirecting stderr to a file. i was doing &2> instead of 2>.

sorry folks!