Log output of optipng when it fails

* Remove the `-quiet` parameter
* Use `run_cmd_with_log_return_error` for logging the command output in the
  error case
* Improve error messages in `run_cmd_with_log_return_error` to include the
  program name so the error message is also useful on its own (without the
  prior `Running cmd: …` message)
* Make `run_cmd_with_log_return_error` return the error message so it can
  be passed as reason when using it to run `optipng`
* See https://progress.opensuse.org/issues/190920

Author: Martchus

lib/OpenQA/Utils.pm

@@ -305,6 +305,7 @@ sub run_cmd_with_log_return_error ($cmd, %args) {
     my $stdout_level = $args{stdout} // 'debug';
     my $stderr_level = $args{stderr} // 'debug';
     my $output_file = $args{output_file};
+    my $program = $cmd->[0] // 'cmd';
     log_info('Running cmd: ' . join(' ', @$cmd));
     try {
         my ($stdin, $stdout, $stderr) = ('') x 3;
@@ -314,8 +315,8 @@ sub run_cmd_with_log_return_error ($cmd, %args) {
         my $return_code = ($error_code & 127) ? (undef) : ($error_code >> 8);
         my $message
           = defined $return_code
-          ? ("cmd returned $return_code")
-          : sprintf('cmd died with signal %d', $error_code & 127);
+          ? ("$program returned $return_code")
+          : sprintf('%s died with signal %d', $program, $error_code & 127);
         my $expected_return_codes = $args{expected_return_codes};
         chomp $stderr;
         if (
@@ -337,6 +338,7 @@ sub run_cmd_with_log_return_error ($cmd, %args) {
             return_code => $return_code,
             stdout => $stdout,
             stderr => $stderr,
+            message => $message,
         };
     }
     catch ($e) {
@@ -345,6 +347,7 @@ sub run_cmd_with_log_return_error ($cmd, %args) {
             return_code => undef,
             stderr => 'an internal error occurred',
             stdout => '',
+            message => "failed to execute $program",
         };
     }
 }

lib/OpenQA/Worker/Job.pm

@@ -11,7 +11,7 @@ use OpenQA::Jobs::Constants;
 use OpenQA::Worker::Engines::isotovideo;
 use OpenQA::Worker::Isotovideo::Client;
 use OpenQA::Log qw(log_error log_warning log_debug log_info redact_settings_in_file);
-use OpenQA::Utils qw(find_video_files usleep_backoff);
+use OpenQA::Utils qw(find_video_files usleep_backoff run_cmd_with_log_return_error);
 
 use Digest::MD5;
 use Fcntl;
@@ -1243,14 +1243,14 @@ sub _optimize_image ($image, $job_settings, $optipng_bin = 'optipng', $pngquant_
     my @command
       = $job_settings->{USE_PNGQUANT}
       ? ($pngquant_bin, '--force', '--output', $image, $image)
-      : ($optipng_bin, '-quiet', '-o2', $image);
+      : ($optipng_bin, '-o2', $image);
+    my $res;
     for (1 .. OPTIMIZE_ATTEMPTS) {
-        last if system(@command) == 0 || $? == -1;
+        $res = run_cmd_with_log_return_error \@command, stdout => 'trace', stderr => 'trace';
+        last if $res->{status};
         sleep OPTIMIZE_RETRY_DELAY;
     }
-    die "$OPTIMIZE_ERROR failed to execute $command[0]: $!\n" if $? == -1;
-    die sprintf("$OPTIMIZE_ERROR %s failed with signal %d\n", $command[0], $? & 127) if $? & 127;
-    die sprintf("$OPTIMIZE_ERROR %s exited with non-zero return code %d\n", $command[0], $? >> 8) if $?;
+    die "$OPTIMIZE_ERROR $res->{message}\n" unless $res->{status};
     return 1;
 }
 

t/16-utils-runcmd.t

@@ -50,17 +50,17 @@ subtest 'run (arbitrary) command' => sub {
     ok $res->{status}, 'status ok';
     is $res->{stdout}, "Hallo Welt\n", 'cmd output returned';
 
-    stdout_like { $res = run_cmd_with_log_return_error([qw(false)]) } qr/.*\[error\].*cmd returned [1-9][0-9]*/i;
+    stdout_like { $res = run_cmd_with_log_return_error([qw(false)]) } qr/.*\[error\].*false returned [1-9][0-9]*/i;
     is $res->{return_code}, 1, 'correct non-zero exit code returned ($? >> 8)';
     ok !$res->{status}, 'status not ok (non-zero status returned)';
 
-    stdout_unlike { $res = run_cmd_with_log_return_error([qw(falße)]) } qr/.*cmd returned [1-9][0-9]*/i;
+    stdout_unlike { $res = run_cmd_with_log_return_error([qw(falße)]) } qr/.*falße returned [1-9][0-9]*/i;
     is $res->{return_code}, undef, 'no exit code returned if command cannot be executed';
     is $res->{stderr}, 'an internal error occurred', 'error message returned as stderr';
     ok !$res->{status}, 'status not ok if command cannot be executed';
 
     stdout_like { $res = run_cmd_with_log_return_error(['bash', '-c', 'kill -s KILL $$']) }
-    qr/.*cmd died with signal 9\n.*/i;
+    qr/.*bash died with signal 9\n.*/i;
     is $res->{return_code}, undef, 'no exit code returned if command dies with a signal';
     ok !$res->{status}, 'status not ok if command dies with a signal';
 };
@@ -81,29 +81,29 @@ subtest 'invoke Git commands for real testing error handling' => sub {
         combined_like {
             throws_ok { $git->check_sha('this-sha-does-not-exist') } qr/internal Git error/i,
             'check throws an exception'
-        } qr/\[error\].*cmd returned [1-9][0-9]*/, 'Git error logged for check as well';
+        } qr/\[error\].*git returned [1-9][0-9]*/, 'Git error logged for check as well';
     };
 
     combined_like {
         $git->invoke_command($_) for ['init'], ['config', 'user.email', 'foo@bar'], ['config', 'user.name', 'Foo'];
     }
-    qr/\[info\].*cmd returned 0\n/, 'initialized Git repo; successful command exit logged as info';
+    qr/\[info\].*git returned 0\n/, 'initialized Git repo; successful command exit logged as info';
 
     subtest 'error handling when checking sha' => sub {
         stdout_like { ok !$git->check_sha('this-sha-does-not-exist'), 'return code 1 interpreted correctly' }
-          qr/\[info\].*cmd returned 1\n/i,
+          qr/\[info\].*git returned 1\n/i,
           'no error logged if check returns false (despite Git returning 1)';
     };
 
     subtest 'error handling when checking whether working directory is clean' => sub {
         my $test_file = $empty_tmp_dir->child('foo')->touch;
-        combined_like { $git->commit({add => ['foo'], message => 'test'}) } qr/commit.*foo.*cmd returned 0/is,
+        combined_like { $git->commit({add => ['foo'], message => 'test'}) } qr/commit.*foo.*git returned 0/is,
           'commit created';
         stdout_like { ok $git->is_workdir_clean, 'return code 0 interpreted correctly' }
-        qr/\[info\].*cmd returned 0\n/i, 'no error (only info) logged if check returns true';
+        qr/\[info\].*git returned 0\n/i, 'no error (only info) logged if check returns true';
         $test_file->spew('test');
         stdout_like { ok !$git->is_workdir_clean, 'return code 1 interpreted correctly' }
-          qr/\[info\].*cmd returned 1\n/i,
+          qr/\[info\].*git returned 1\n/i,
           'no error (only info) logged if check returns false (despite Git returning 1)';
     };
 

t/24-worker-jobs.t

@@ -1244,11 +1244,9 @@ subtest 'image optimization' => sub {
     combined_like {
         is $opt->('foo', {OPTIMIZE_IMAGES => 0}), 0, 'image optimization can be skipped';
         throws_ok { $opt->('foo', {}) }
-        qr/(failed to execute optipng|optipng exited with non-zero return code)/,
-          'failing to run optipng is a hard error';
+        qr/(failed to execute optipng|optipng returned)/, 'failing to run optipng is a hard error';
         throws_ok { $opt->('foo', {USE_PNGQUANT => 1}) }
-        qr/(failed to execute pngquant|pngquant exited with non-zero return code)/,
-          'failing to run pngquant is a hard error';
+        qr/(failed to execute pngquant|pngquant returned)/, 'failing to run pngquant is a hard error';
         is $opt->('bar', {}, 'true'), 1, 'successful optimization';
     }
     qr/Optimizing foo.*Optimizing bar/s, 'optimizing logged';