Test::Mojo + prove leads to duplicate logging

Question

I have the following test script that utilizes Test::Mojo. When I run it from the command line using perl, it outputs correctly. However, when I run it through "prove -v", the Mojo logging is duplicated and one of them isn't piped through "on message".

#!/usr/bin/env perl

use strict;
use warnings;

use Test::More tests => 1;

use Mojolicious::Lite;
use Test::Mojo;

app->log->on(
    message => sub {
        my ( $log, $level, @lines ) = @_;
        note "MojoLog $level: @lines";
    }
);

get '/debug/mojo/req_url' => sub {
    my $c = shift;

    $c->render( text => $c->req->url );
};

subtest 'Mojo - $c->req->url' => sub {
    plan tests => 3;

    my $t = Test::Mojo->new;

    $t->get_ok('/debug/mojo/req_url')    #
        ->status_is(200)                 #
        ->content_is('/debug/mojo/req_url');
};

The output when run directly:

$ perl dup_logging.t
1..1
# Subtest: Mojo - $c->req->url
    1..3
    # MojoLog debug: GET "/debug/mojo/req_url"
    # MojoLog debug: Routing to a callback
    # MojoLog debug: 200 OK (0.000797s, 1254.705/s)
    ok 1 - GET /debug/mojo/req_url
    ok 2 - 200 OK
    ok 3 - exact match for content
ok 1 - Mojo - $c->req->url

And the output when run through prove:

$ prove -v dup_logging.t
dup_logging.t ..
1..1
# Subtest: Mojo - $c->req->url
    1..3
[Thu Mar  8 12:16:35 2018] [debug] GET "/debug/mojo/req_url"
    # MojoLog debug: GET "/debug/mojo/req_url"
[Thu Mar  8 12:16:35 2018] [debug] Routing to a callback
    # MojoLog debug: Routing to a callback
[Thu Mar  8 12:16:35 2018] [debug] 200 OK (0.000842s, 1187.648/s)
    # MojoLog debug: 200 OK (0.000842s, 1187.648/s)
    ok 1 - GET /debug/mojo/req_url
    ok 2 - 200 OK
    ok 3 - exact match for content
ok 1 - Mojo - $c->req->url
ok
All tests successful.
Files=1, Tests=1,  1 wallclock secs ( 0.03 usr  0.01 sys +  0.34 cusr  0.03 csys =  0.41 CPU)
Result: PASS

The following is my version information:

$ perl -MMojolicious -E 'say Mojolicious->VERSION'
7.14
$ prove --version
TAP::Harness v3.36 and Perl v5.16.3

I discovered that one way to avoid this problem is to set the MOJO_LOG_LEVEL environment variable at the top of the script.

$ENV{MOJO_LOG_LEVEL} = 'fatal';

Any other suggestions on how to get prove and Test::Mojo to play well together with regard to the logging?

Answer 1

The prove testrunner uses the TAP::Harness infrastructure. When you run prove -v, this will set the HARNESS_IS_VERBOSE environment variable.

Then, Mojo::Test picks up this environment variable:

# Silent or loud tests
$ENV{MOJO_LOG_LEVEL} ||= $ENV{HARNESS_IS_VERBOSE} ? 'debug' : 'fatal';

You therefore get Mojo's debug log messages when running prove -v.

It seems that manually setting the MOJO_LOG_LEVEL env variable is the best approach if you do not want this output.