Testing errors, and std.log.err

Help
,
1

I have noticed that having std.log.err() called when the function I’m testing returns an error causes additional output, and it gives the impression the test has failed (at least to me).
Case in point - the following test runs successfully:

const std = @import("std");

const MyErrors = error
{
    SomeError,
};

fn ham() !u32
{
    //std.log.err("SomeError happened!", .{});
    return MyErrors.SomeError;
}

test
{
    try std.testing.expectError(error.SomeError, ham());
}

The output is:

$ zig test expect_error.zig 
All 1 tests passed.

But once std.log.err("SomeError happened!", .{}); is uncommented, the output becomes this:

$ zig test expect_error.zig 
Test [1/1] test_0... [default] (err): SomeError happened!
All 1 tests passed.
1 errors were logged.
error: the following test command failed with exit code 1:
/home/archie/.cache/zig/o/0f6166f344a680d395d4f0e2c922f772/test

It still does say “All 1 tests passed.”, but also “1 errors were logged” and “error: the following test command failed with exit code 1”. I do agree this is rather a question of presentation, but it does leave the impression of a failed test.

Am I the only one who thinks this is an issue? Am I using std.log.err where I should not?

I would like my tests to run smoothly and still be able to log errors if they arrive, at least in debug builds.

2 Likes
2

Log levels are either dependent on the optimization level (default) or if you’ve provided a log level as a std_options struct in your source file. It looks like you’re not prohibiting this from happening (in this case, I think you may want to go with an errdefer outside of the calling function). Looks like there’s quite a few more things to consider before it does what you want.

Check this out if you already haven’t: Quick overview of Zig's `std.log` · GitHub

Digging into the source a bit more, we’ll find this:

    pub const Level = enum {
    /// Error: something has gone wrong. This might be recoverable or might
    /// be followed by the program exiting.
    err,
    /// Warning: it is uncertain if something has gone wrong or not, but the
    /// circumstances would be worth investigating.
    warn,
    /// Info: general messages about the state of the program.
    info,
    /// Debug: messages only useful for debugging.
    debug,

    /// Returns a string literal of the given level in full text form.
    pub fn asText(comptime self: Level) []const u8 {
        return switch (self) {
            .err => "error",
            .warn => "warning",
            .info => "info",
            .debug => "debug",
        };
    }
};

Then to determine if the log function is enabled, we’ll also see this:

/// Determine if a specific log message level and scope combination are enabled for logging.
pub fn logEnabled(comptime message_level: Level, comptime scope: @Type(.EnumLiteral)) bool {
    inline for (scope_levels) |scope_level| {
        if (scope_level.scope == scope) return @intFromEnum(message_level) <= @intFromEnum(scope_level.level);
    }
    return @intFromEnum(message_level) <= @intFromEnum(level);
}

Basically it’s saying that if you have a message level higher than the designated level, it will return false and bypass logging. You’ll notice that in the scope levels, err is the lowest enum value. That seems to imply that you’ll almost always be logging errors. I think the best thing to do is only log errors on a failed try or using a catch (or even explicitly checking with an if statement)… that’s why I’m recommending errdefer or explicit checks here.

Essentially, the test passing and invoking a logging function with a specific level are independent operations. They both succeeded.

2 Likes
3

Well, that was the plan.

I’m not sure I understood you correctly, so please fix me if I’m wrong, but do you mean the calling side should do the logging?

My idea was to have the called function, which may encounter different types of errors, log them before returning to the caller.

This way the caller doesn’t have to add any logging related to this function, and the program still prints additional information about the error, e.g. what exactly was being processed, should it happen.

Having just the error code is not always enough, I’m afraid. I wish there was a way to add some information to errors, like a string.

This is true, of course. What I was saying was that those messages saying “error” and “test command failed” were leaving the impression that the tests had failed.

Anyway, I’ve since switched to std.log.warn.

4

Have you looked at @errorName?

Here’s some code so we can speak directly to the issue at hand:

const std = @import("std");

const ErrorCode = error { err1, err2 };

// some function from some library
fn foo(arg: bool) !void {
    if (arg) {
        return ErrorCode.err1;
    }
}

pub fn bar(arg: bool) !void {
    foo(arg) catch |e| {
        std.log.err("foo() returned ErrorCode: {s}", .{ @errorName(e) });
        return e;
    };    
}

pub fn main() !void  {
    try bar(true); // log error
}

So in this case, bar just dispatches to foo, logs something and returns the error e. In this case, it’s just a logging wrapper.

In the case you’ve presented, the logging statement is independent from any error condition. It’s unguarded whether or not an error occurred. Presumably, if that function was called at all, then an error occurred.

I think what I’m trying to convey is that it should be tied to some conditional - this can be proactive or reactive.

For instance, on the proactive side:

fn foo(n: usize) !usize {
    if (n > 42) {
        std.log.err("N greater than 42.", .{});
        return ErrorCode.GreaterThan42;
    }
    // do stuff...
}

and the reactive case…

foo(43) catch |e| {
   std.log.err("foo() returned ErrorCode: {s}", .{ @errorName(e) });
   return e;
}
5

This is not what I meant.
@errorName gets you, well, the name of the error as a string.

I was talking about being able to attach more information to the error, e.g. as a string.

In Java, for example, you when you throw an exception, you can add a message string, describing what happened in detail:

throw new Exception(String.format("Could not process message '%s'", msg));

(see fxJx5x - Online Java Compiler & Debugging Tool - Ideone.com)

And then the caller can print this message.

Also in Python:

raise ValueError('A very specific bad thing happened', 'foo', 'bar', 'baz')

But in Zig, if the called function doesn’t do the logging (as in your reactive example), the only information available at the calling side is the type of the error (which you can also get as a string).

I guess I should just set up a pre-allocated buffer for these error descriptions, replicating Windows’ GetLastError() functionality, but for strings rather than error codes.

1 Like
6

This is not a problem with the log package, but a a design in the build runner:
https://github.com/ziglang/zig/blob/master/lib/test_runner.zig#L226
https://github.com/ziglang/zig/blob/master/lib/test_runner.zig#L208

3 Likes
7

Thank you.
This is what I suspected, since when I switched to std.log.warn, these messages disappeared:

1 errors were logged.
error: the following test command failed with exit code 1:
8

Okay - I think I get what you’re looking for. I’ve seen this request show up twice now so I’m wondering if we should take a crack at designing payload error messages (or something like getLastError).

1 Like
9

In my opinion getting a failed test message when all tests pass is confusing and should not be the default and only behavior of the test runner. It should at least be configurable.
Edit: It seems like the reason it was designed like this in the first place was to fail GeneralPurposeAllocator tests based on logged errors as described in the commit message:

I wonder if this is still required or could be removed.

1 Like