duplicated lines with command output are shown when opening the testcase log file.
eg:
test case commands:
rlRun "nc -l $LISTEN &>listen.log &" LISTEN_PID=$! rlWaitForSocket $LISTEN -t $TIMEOUT
log saved:
:: [ 14:17:10 ] :: [ BEGIN ] :: Running 'nc -l 6903 &>listen.log &' :: [ 14:17:10 ] :: [ PASS ] :: Command 'nc -l 6903 &>listen.log &' (Expected 0, got 0) :: [ 14:17:10 ] :: [ PASS ] :: Command 'nc -l 6903 &>listen.log &' (Expected 0, got 0) :: [ 14:17:10 ] :: [ INFO ] :: rlWaitForSocket: Waiting max 5s for socket `6903' to start listening :: [ 14:17:10 ] :: [ INFO ] :: rlWaitForSocket: Waiting max 5s for socket `6903' to start listening :: [ 14:17:12 ] :: [ INFO ] :: rlWaitForSocket: Wait successful! :: [ 14:17:12 ] :: [ INFO ] :: rlWaitForSocket: Wait successful!
As near as I can tell, this comes down to the output that comes out of tests written with beakerlib and what we're doing with that output.
We're basically merging stdout, stderr and the logoutput into a single file and there's a decent amount of duplication between stderr and logoutput.
As near as I can tell, beaker outputs all three streams into separate files, is that what we want to be doing instead of mashing everything together into a single file?
Examples:
We could remove merging of streams from tasks/main.yml line 78,
tasks/main.yml
77 logfile={{ remote_artifacts }}/test.$(echo {{ item }} | sed -e 's/\//-/g').log 78 exec 2>>$logfile 1>>$logfile 79 cd {{ tenv_workdir }}
and redirect stderr to separate file:
stderr
77 logfile={{ remote_artifacts }}/test.$(echo {{ item }} | sed -e 's/\//-/g').log 78 logfile_stderr={{ remote_artifacts }}/test.$(echo {{ item }} | sed -e 's/\//-/g').stderr 79 exec 1>>$logfile 80 exec 2>>$logfile_stderr 81 cd {{ tenv_workdir }}
which produces reasonable output with most of the information about test run (missing is TEST PROTOCOL summary and outputs from commands called in the test - basically journal.txt without Test protocol and Test description)
:: [ 08:23:41 ] :: [ WARNING ] :: POSIX mode detected and switched off :: [ 08:23:41 ] :: [ WARNING ] :: Please fix your test to have /bin/bash shebang :::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::: :: Setup :::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::: :: [ 08:23:41 ] :: [ PASS ] :: Checking for the presence of bash rpm :: [ 08:23:41 ] :: [ LOG ] :: Package versions: :: [ 08:23:41 ] :: [ LOG ] :: bash-4.4.19-1.fc27.x86_64 :: [ 08:23:41 ] :: [ PASS ] :: Binary 'bash' should belong to: bash :: [ 08:23:41 ] :: [ BEGIN ] :: Creating tmp directory :: actually running 'TmpDir=$(mktemp -d)' :: [ 08:23:41 ] :: [ PASS ] :: Creating tmp directory (Expected 0, got 0) :: [ 08:23:41 ] :: [ BEGIN ] :: Copying additional test files :: actually running 'cp t_* /tmp/tmp.7ebdxKx1D2/.' :: [ 08:23:41 ] :: [ PASS ] :: Copying additional test files (Expected 0, got 0) :: [ 08:23:41 ] :: [ BEGIN ] :: Running 'pushd /tmp/tmp.7ebdxKx1D2' :: [ 08:23:41 ] :: [ PASS ] :: Command 'pushd /tmp/tmp.7ebdxKx1D2' (Expected 0, got 0) :::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::: :: Duration: 0s :: Assertions: 5 good, 0 bad :: RESULT: PASS :::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::: :: Test :::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::: :: [ 08:23:41 ] :: [ LOG ] :: Commandline options :: [ 08:23:41 ] :: [ BEGIN ] :: Testing -c option :: actually running 'bash -c 'echo OK' | grep OK' :: [ 08:23:41 ] :: [ PASS ] :: Testing -c option (Expected 0, got 0) :: [ 08:23:41 ] :: [ LOG ] :: Assorted tests :: [ 08:23:41 ] :: [ BEGIN ] :: Testing command substitution :: actually running 'bash -c 'echo `echo OK`' | grep OK' :: [ 08:23:41 ] :: [ PASS ] :: Testing command substitution (Expected 0, got 0) :: [ 08:23:41 ] :: [ BEGIN ] :: Testing alias :: actually running 'bash -i t_alias | grep OK' :: [ 08:23:41 ] :: [ PASS ] :: Testing alias (Expected 0, got 0) :: [ 08:23:41 ] :: [ BEGIN ] :: Arithmetic expansion :: actually running 'bash -c 'echo $((1+1))' | grep 2' :: [ 08:23:41 ] :: [ PASS ] :: Arithmetic expansion (Expected 0, got 0) :: [ 08:23:41 ] :: [ BEGIN ] :: Testing function :: actually running 'bash -c 'writedown(){ echo $1; }; writedown OK' | grep OK' :: [ 08:23:41 ] :: [ PASS ] :: Testing function (Expected 0, got 0) :: [ 08:23:41 ] :: [ LOG ] :: Variables :: [ 08:23:41 ] :: [ BEGIN ] :: Testing variable assignment :: actually running 'bash -c 'testvar1="OK"; echo "$testvar1"' | grep OK' :: [ 08:23:41 ] :: [ PASS ] :: Testing variable assignment (Expected 0, got 0) :: [ 08:23:41 ] :: [ BEGIN ] :: Testing variable substitution :: actually running 'bash t_variables | grep 'default,OK'' :: [ 08:23:41 ] :: [ PASS ] :: Testing variable substitution (Expected 0, got 0) :: [ 08:23:41 ] :: [ BEGIN ] :: Testing predefined variable $? :: actually running 'bash -c "cat nonexistent; echo $?" | grep 1' cat: nonexistent: No such file or directory :: [ 08:23:41 ] :: [ PASS ] :: Testing predefined variable $? (Expected 0, got 0) :: [ 08:23:41 ] :: [ LOG ] :: File expansion :: [ 08:23:41 ] :: [ BEGIN ] :: Creating test file :: actually running 'touch testfile' :: [ 08:23:41 ] :: [ PASS ] :: Creating test file (Expected 0, got 0) :: [ 08:23:41 ] :: [ BEGIN ] :: Testing expansion to the test file name :: actually running 'bash -c 'echo test*' | grep testfile' :: [ 08:23:41 ] :: [ PASS ] :: Testing expansion to the test file name (Expected 0, got 0) :: [ 08:23:41 ] :: [ LOG ] :: Builtins :: [ 08:23:41 ] :: [ BEGIN ] :: Testing test builtin :: actually running 'bash -c 'test -e testfile'' :: [ 08:23:41 ] :: [ PASS ] :: Testing test builtin (Expected 0, got 0) :: [ 08:23:41 ] :: [ LOG ] :: Redirection and pipeline :: [ 08:23:41 ] :: [ BEGIN ] :: Testing pipeline :: actually running 'bash -c "echo 'aBc' | grep B >redirection_out"' :: [ 08:23:41 ] :: [ PASS ] :: Testing pipeline (Expected 0, got 0) :: [ 08:23:41 ] :: [ BEGIN ] :: Testing redirection :: actually running 'grep 'aBc' redirection_out' :: [ 08:23:41 ] :: [ PASS ] :: Testing redirection (Expected 0, got 0) :: [ 08:23:41 ] :: [ LOG ] :: Control structures :: [ 08:23:41 ] :: [ BEGIN ] :: Testing cycle for :: actually running 'bash -c 'for i in 1 2 3; do echo -n $i; done' | grep 123' :: [ 08:23:41 ] :: [ PASS ] :: Testing cycle for (Expected 0, got 0) :: [ 08:23:41 ] :: [ BEGIN ] :: Testing if and it's && operator shorthand :: actually running 'bash t_conditionals | grep 'operator,if,else,test'' :: [ 08:23:41 ] :: [ PASS ] :: Testing if and it's && operator shorthand (Expected 0, got 0) :::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::: :: Duration: 0s :: Assertions: 15 good, 0 bad :: RESULT: PASS :::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::: :: Cleanup :::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::: :: [ 08:23:41 ] :: [ BEGIN ] :: Running 'popd' :: [ 08:23:41 ] :: [ PASS ] :: Command 'popd' (Expected 0, got 0) :: [ 08:23:41 ] :: [ BEGIN ] :: Removing tmp directory :: actually running 'rm -r /tmp/tmp.7ebdxKx1D2' :: [ 08:23:41 ] :: [ PASS ] :: Removing tmp directory (Expected 0, got 0) :::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::: :: Duration: 0s :: Assertions: 2 good, 0 bad :: RESULT: PASS :: [ 08:23:41 ] :: [ LOG ] :: JOURNAL XML: /var/tmp/beakerlib-nj6keyO/journal.xml :: [ 08:23:41 ] :: [ LOG ] :: JOURNAL TXT: /var/tmp/beakerlib-nj6keyO/journal.txt :::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::: :: Duration: 0s :: Phases: 3 good, 0 bad :: OVERALL RESULT: PASS
Yeah, I don't think this is going to take much to solve from a technical perspective - it's more of a question of what we want the output to look like and/or which file we want to make the "primary" output.
I suspect that this comes from the standard test interface talking about the "main readable output" existing in a single file.
I'm going to start a thread on ci@ to get the discussion going - hopefully we'll be able to come to some conclusion before too long.
Metadata Update from @astepano: - Issue assigned to astepano
we discussed double output with Jakub Heger. Hi said it was STR bug. Why to mix STDERR and STDOUT ? I do not see any benefits. It will more complicate things. All should be strict and all expected. HTTPD server has 3 kinds of logs, systemd has levels. Please do not mix. Reading STDERR can easily understand what is wrong.
This should definitely get fixed, as it makes Beakerlib logs less readable and more confusing, especially in case of tests with dozens of phases.
This is fixed, now beakerlib saves STDERR and STDOUT in different files.
Metadata Update from @bgoncalv: - Issue close_status updated to: SOLVED - Issue status updated to: Closed (was: Open)
Login to comment on this ticket.