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
10

Hi everyone, sorry to reopen this, but is this behaviour fix or subject to change?

I’m asking, because I stumble across this every now and then. I typically log an error message (let’s say an OpenGL error) via std.log.error and return an error. But then, as described by the OP above, all my negative test cases fail.

I’m not sure if I want to change all log messages into warn, but commenting out negative test cases doesn’t seem to be a good solution either.

Apart from that, I’m wondering why there are only very few topics on this subject. Is it somehow bad style to log error messages and return error or do only few people write lots of (negative) test cases?

1 Like
11

See Integrate std.log with std.testing - Issue #5738
and issue comment Allow controlling “fail on log.err calls” behavior for tests

2 Likes
12

Great, thank you for the fast response and good to see that there is still discussions! The workaround you linked seems quite useful, thanks again.

2 Likes
13

Boiling it down to the absolute minimum looks like this:

const logger = std.log.scoped(.the_module);

fn logError(comptime fmt: []const u8, args: anytype) void {
    if (!builtin.is_test) {
        logger.err(fmt, args);
    } else {
        logger.warn(fmt, args);
    }
}

I wouldn’t even call this a workaround: using comptime-known information to specialize Zig programs is core to using the language, and something like this also means you can use logger.err directly if the error should be considered a test failure.

builtin.is_test can be used for a lot of things: I have it in a few places to make the size of certain types smaller during testing, so it’s easier to trigger code pathways which handle queues getting filled which aren’t supposed to run out of room during normal operation, but which do need to handle that condition correctly.

2 Likes
14

Thank you for the even shorter workaround :wink:.

I understand what you’re saying, but I’d say it’s a workaround nevertheless, since I do not expect my negative test cases to fail if I log an error (if that error occurs, which I want to test, when I test for correct error handling).

But again, I’m fine with the solutions mentioned and linked in this thread, so that log warnings is a comptime adjustment for tests and I can keep the negative test cases.

1 Like
15

Agreed, it’s far from clear that it’s the correct behavior. It’s hard to satisfy everyone, because it’s useful to be able to fail a test by logging an error, but on the flip side errors are explicitly triggered to test error pathways. Arguably if you’re test-triggering an error, the ideal is if (!builtin.is_test) logger.err("the error", .{}); because whatever is getting logged, you shouldn’t need that log in a test context.

You can also perform the same is_test um, test, inside a custom logging function, thus turning off all types of logging when in a test. I don’t know how that interacts with the “logger.err is a test error” logic, because I haven’t tried it.

The more general premise, that Zig is designed so that we can tune code to work as we wish in specific contexts, is sound. There’s work towards things like adding std.testing.expectPanic so I’m optimistic that a more fine-grained interaction between logger.err and testing may be forthcoming.

1 Like
16

Yes, I also like this aspect and the topic of this thread was far from a blocker, and not even really annoying to me. As the OP, I was just wondering why this is to be expected behaviour, whenever I ran into this.
The replies here really shed some light onto this for me, regarding the why and the how :+1:

1 Like