QA » openQA Project

Semi-related https://github.com/os-autoinst/os-autoinst/pull/2001

I still can't replicate the issue reliably, but i have a suspicion what it could be. The driver class dupes STDOUT/STDERR before and after forking a process, and that might be messing with the output buffers, perhaps unfortunately overlapping control characters from the log color highlighting. If that's the case autoflush on the log handle might resolve it. https://github.com/os-autoinst/os-autoinst/compare/k/backend_race

No new insights so far, but a smaller reproducer:

# runs=100 ./count_fail_ratio prove -I. t/29.t
% cat t/29.t
#!/usr/bin/perl
use Test::More;
use strict;
use warnings;
use Test::Output qw(combined_from stderr_from stdout_from);
use Mojo::IOLoop::ReadWriteProcess 'process';

for (1..30) {
    my ($out, $err);
    $out = stdout_from {
        $err = stderr_from { start() };
    };
#    diag "ERR: >>$err<<";
#    like $err, qr/Blocking SIGCHLD and SIGTERM/;
    like $err, qr/DEBUG.*channel_out.+channel_in/s, 'log output for backend driver creation'
        or do {
            diag "!!!!!!!!!!!! loop($_) OUT: >>$out<<";
            sleep 1;
        };
}

done_testing;

sub start {
    open(my $STDOUTPARENT, '>&', *STDOUT);
    open(my $STDERRPARENT, '>&', *STDERR);

    my $backend_process = process(
        sleeptime_during_kill => .1,
        total_sleeptime_during_kill => 30,
        max_kill_attempts => 1,
        kill_sleeptime => 0,
        blocking_stop => 1,
        separate_err => 0,
        subreaper => 1,
        code => sub {
            my $process = shift;
            open STDOUT, ">&", $STDOUTPARENT;
            open STDERR, ">&", $STDERRPARENT;
            print STDERR "Blocking SIGCHLD and SIGTERM\n"; # <-------- removing this makes it go away
            select undef, undef, undef, 0.05;
        });
    $backend_process->start;
    print STDERR "$$: DEBUG (STDERR)\nchannel_out channel_in\n";
    #print "$$: DEBUG (STDERR)\nchannel_out channel_in\n";
}

It's hard to tell how often it happens. It seems to me like I have to run it a few times, and then it starts happening more often.

The print to STDERR in the subprocess has to do with it. Parent and child seem to write to the same filehandle.

edit: also happens with a simple fork, without Mojo::IOLoop::ReadWriteProcess

tinita wrote:

No new insights so far, but a smaller reproducer

This is awesome news!

It's hard to tell how often it happens. It seems to me like I have to run it a few times, and then it starts happening more often.

I also ran it locally with runs=100 count_fail_ratio prove and got "## count_fail_ratio: Run: 100. Fails: 13. Fail ratio 13%". I also observed that two consecutive failures are happening but I would still not see it as significant.

print STDERR "Blocking SIGCHLD and SIGTERM\n"; # <-------- removing this makes it go away

I can confirm. So what would you say about just removing the print lines completely? Please see
https://github.com/os-autoinst/os-autoinst/pull/2022
and tell me what you think.

EDIT: So far 5000 runs without failures of the above reproducer with the print line removed.

Currently I would guess (hope) that this is only a problem when capturing output. Capture::Tiny (what Test::Output uses) docs say clearly that capturing output from parent and forked processes is not reliable.

Before taking any action I would first try to run the test without capturing and redirect into a file and see if the output there is complete or not.

If it's just a testing problem, the simplest solution could just mock the diag function to collect output in an array.

tinita wrote:

If it's just a testing problem, the simplest solution could just mock the diag function to collect output in an array.

Yes, that sounds like a good idea as well.

I double checked with this script:

#!/usr/bin/perl
use Test::More;
use strict;
use warnings;
use Test::Output qw(stderr_from stdout_from);

for (1..50) {
    my ($out, $err);
    if ($ENV{CAPTURE}) {
        # capture STDERR
        $out = stdout_from {
            $err = stderr_from { start() };
        };
        like $err, qr/DEBUG.*channel_out.+channel_in/s, 'log output for backend driver creation';
    }
    else {
        # Only cpature STDOUT
        $out = stdout_from { $err = start() };
    }
}
pass "ok";
done_testing;

sub start {
    open(my $STDOUTPARENT, '>&', *STDOUT);
    open(my $STDERRPARENT, '>&', *STDERR);
    my $child = sub {
        open STDOUT, ">&", $STDOUTPARENT;
        open STDERR, ">&", $STDERRPARENT;
        for (1 .. 300) {
            print STDERR "($$) (loop $_) Blocking SIGCHLD and SIGTERM\n";
            select undef, undef, undef, 0.001;
        }
    };
    my $pid = fork();
    if ($pid) {}
    else { $child->(); exit; }
    print STDERR "(parent $$) DEBUG STDERR\nchannel_out channel_in\n";
}

% CAPTURE=1 runs=100 ./count_fail_ratio prove -I. t/29.t
...
## Run 89                                                                                                                                                                                                                            
t/29.t .. 1/?                                                                                                                                                                                                                        
#   Failed test 'log output for backend driver creation'                                                          
#   at t/29.t line 14.                                                                                                                                                                                                               
#                   'l_in                                                                                         
# '                                                                                                                                                                                                                                  
#     doesn't match '(?^s:DEBUG.*channel_out.+channel_in)'                                                        
# Looks like you failed 1 test of 51.                    
t/29.t .. Dubious, test returned 1 (wstat 256, 0x100)                                                             
Failed 1/51 subtests                                     
...
## count_fail_ratio: Run: 100. Fails: 7. Fail ratio 7%
% runs=100 ./count_fail_ratio prove -I. t/29.t >log 2>&1
% grep "DEBUG STDERR" log | wc -l
5000
% grep "channel_out channel_in" log | wc -l
5000

I ran this a few times, and when not capturing, all output is there like expected.
So I assume this is a capturing problem only.

I will try to rewrite the test to mock diag and fctinfo.