RunCommand: create run logs for each execution

src/lib/Hydra/Plugin/RunCommand.pm

@@ -150,8 +150,20 @@ sub buildFinished {
 
     foreach my $commandToRun (@{$commandsToRun}) {
         my $command = $commandToRun->{command};
+
+        # todo: make all the to-run jobs "unstarted" in a batch, then start processing
+        my $runlog = $self->{db}->resultset("RunCommandLogs")->create({
+            job_matcher => $commandToRun->{matcher},
+            build_id => $build->get_column('id'),
+            command => $command
+        });
+
+        $runlog->started();
+
         system("$command") == 0
             or warn "notification command '$command' failed with exit status $?\n";
+
+        $runlog->completed_with_child_error($?);
     }
 }
 

src/lib/Hydra/Schema/Result/RunCommandLogs.pm

@@ -148,10 +148,82 @@ __PACKAGE__->belongs_to(
 );
 
 
-# Created by DBIx::Class::Schema::Loader v0.07049 @ 2021-11-18 12:35:52
-# DO NOT MODIFY THIS OR ANYTHING ABOVE! md5sum:N0G71diB8DNDgkYgaSQrFA
+# Created by DBIx::Class::Schema::Loader v0.07049 @ 2021-11-19 15:15:36
+# DO NOT MODIFY THIS OR ANYTHING ABOVE! md5sum:9AIzlQl1RjRXrs9gQCZKVw
+
+use POSIX qw(WEXITSTATUS WIFEXITED WIFSIGNALED WTERMSIG);
+
+=head2 started
+
+Update the row with the current timestamp as the start time.
+
+=cut
+sub started {
+    my ($self) = @_;
+
+    return $self->update({
+      start_time => time()
+    });
+}
+
+=head2 completed_with_child_error
+
+Update the row with the current timestamp, exit code, core dump, errno,
+and signal status.
+
+Arguments:
+
+=over 2
+
+=item C<$child_error>
+
+The value of $? or $CHILD_ERROR (with use English) after calling system().
+
+=item C<$errno>
+
+The value of $! or $ERRNO (with use English) after calling system().
+
+=back
+
+=cut
+sub completed_with_child_error {
+    my ($self, $child_error, $reported_errno) = @_;
+
+    my $errno = undef;
+    my $exit_code = undef;
+    my $signal = undef;
+    my $core_dumped = undef;
+
+    if ($child_error == -1) {
+      # -1 indicates `exec` failed, and this is the only
+      # case where the reported errno is valid.
+      $errno = $reported_errno;
+    }
+
+    if (WIFEXITED($child_error)) {
+      # The exit status bits are only meaningful if the process exited
+      $exit_code = WEXITSTATUS($child_error);
+    }
+
+    if (WIFSIGNALED($child_error)) {
+      # The core dump and signal bits are only meaningful if the
+      # process was terminated via a signal
+      $signal = WTERMSIG($child_error);
+
+      # This `& 128` comes from where Perl constructs the CHILD_ERROR
+      # value:
+      # https://github.com/Perl/perl5/blob/a9d7a07c2ebbfd8ee992f1d27ef4cfbed53085b6/perl.h#L3609-L3621
+      $core_dumped = ($child_error & 128) == 128;
+    }
+
+    return $self->update({
+      end_time => time(),
+      error_number => $errno,
+      exit_code => $exit_code,
+      signal => $signal,
+      core_dumped => $core_dumped,
+    });
+}
 
 
-
-# You can replace this text with custom code or comments, and it will be preserved on regeneration
 1;

t/Schema/Result/RunCommandLogs.t

@@ -0,0 +1,111 @@
+use strict;
+use warnings;
+use Setup;
+
+my %ctx = test_init();
+
+require Hydra::Schema;
+require Hydra::Model::DB;
+
+use Test2::V0;
+
+my $db = Hydra::Model::DB->new;
+hydra_setup($db);
+
+my $project = $db->resultset('Projects')->create({name => "tests", displayname => "", owner => "root"});
+my $jobset = createBaseJobset("basic", "basic.nix", $ctx{jobsdir});
+ok(evalSucceeds($jobset),               "Evaluating jobs/basic.nix should exit with return code 0");
+is(nrQueuedBuildsForJobset($jobset), 3, "Evaluating jobs/basic.nix should result in 3 builds");
+
+my ($build, @_) = queuedBuildsForJobset($jobset);
+
+sub new_run_log {
+    return $db->resultset('RunCommandLogs')->create({
+        job_matcher => "*:*:*",
+        build_id => $build->get_column('id'),
+        command => "bogus",
+    });
+}
+
+
+subtest "Not yet started" => sub {
+    my $runlog = new_run_log();
+
+    is($runlog->start_time, undef, "The start time is undefined.");
+    is($runlog->end_time, undef, "The start time is undefined.");
+    is($runlog->exit_code, undef, "The exit code is undefined.");
+    is($runlog->signal, undef, "The signal is undefined.");
+    is($runlog->core_dumped, undef, "The core dump status is undefined.");
+};
+
+subtest "Completing a process before it is started is invalid" => sub {
+    my $runlog = new_run_log();
+
+    like(
+        dies {
+            $runlog->completed_with_child_error(0, 0);
+        },
+        qr/runcommandlogs_end_time_has_start_time/,
+        "It is invalid to complete the process before it started"
+    );
+};
+
+subtest "Starting a process" => sub {
+    my $runlog = new_run_log();
+    $runlog->started();
+    is($runlog->start_time, within(time() - 1, 2), "The start time is recent.");
+    is($runlog->end_time, undef, "The end time is undefined.");
+    is($runlog->exit_code, undef, "The exit code is undefined.");
+    is($runlog->signal, undef, "The signal is undefined.");
+    is($runlog->core_dumped, undef, "The core dump status is undefined.");
+};
+
+subtest "The process completed (success)" => sub {
+    my $runlog = new_run_log();
+    $runlog->started();
+    $runlog->completed_with_child_error(0, 123);
+    is($runlog->start_time, within(time() - 1, 2), "The start time is recent.");
+    is($runlog->end_time, within(time() - 1, 2), "The end time is recent.");
+    is($runlog->error_number, undef, "The error number is undefined");
+    is($runlog->exit_code, 0, "The exit code is 0.");
+    is($runlog->signal, undef, "The signal is undefined.");
+    is($runlog->core_dumped, undef, "The core dump is undefined.");
+};
+
+subtest "The process completed (errored)" => sub {
+    my $runlog = new_run_log();
+    $runlog->started();
+    $runlog->completed_with_child_error(21760, 123);
+    is($runlog->start_time, within(time() - 1, 2), "The start time is recent.");
+    is($runlog->end_time, within(time() - 1, 2), "The end time is recent.");
+    is($runlog->error_number, undef, "The error number is undefined");
+    is($runlog->exit_code, 85, "The exit code is 85.");
+    is($runlog->signal, undef, "The signal is undefined.");
+    is($runlog->core_dumped, undef, "The core dump is undefined.");
+};
+
+subtest "The process completed (signaled)" => sub {
+    my $runlog = new_run_log();
+    $runlog->started();
+    $runlog->completed_with_child_error(393, 234);
+    is($runlog->start_time, within(time() - 1, 2), "The start time is recent.");
+    is($runlog->end_time, within(time() - 1, 2), "The end time is recent.");
+    is($runlog->error_number, undef, "The error number is undefined");
+    is($runlog->exit_code, undef, "The exit code is undefined.");
+    is($runlog->signal, 9, "The signal is 9.");
+    is($runlog->core_dumped, 1, "The core dumped.");
+};
+
+subtest "The process failed to start" => sub {
+    my $runlog = new_run_log();
+    $runlog->started();
+    $runlog->completed_with_child_error(-1, 2);
+    is($runlog->start_time, within(time() - 1, 2), "The start time is recent.");
+    is($runlog->end_time, within(time() - 1, 2), "The end time is recent.");
+    is($runlog->error_number, 2, "The error number is saved");
+    is($runlog->exit_code, undef, "The exit code is undefined.");
+    is($runlog->signal, undef, "The signal is undefined.");
+    is($runlog->core_dumped, undef, "The core dumped is not defined.");
+};
+
+done_testing;

t/plugins/RunCommand/basic.t

@@ -50,4 +50,13 @@ subtest "Validate the file parsed and at least one field matches" => sub {
     is($dat->{build}, $newbuild->id, "The build event matches our expected ID.");
 };
 
+subtest "Validate a run log was created" => sub {
+    my $runlog = $build->runcommandlogs->find({});
+    is($runlog->job_matcher, "*:*:*", "An unspecified job matcher is defaulted to *:*:*");
+    is($runlog->command, 'cp "$HYDRA_JSON" "$HYDRA_DATA/joboutput.json"', "The executed command is saved.");
+    is($runlog->start_time, within(time() - 1, 2), "The start time is recent.");
+    is($runlog->end_time, within(time() - 1, 2), "The end time is also recent.");
+    is($runlog->exit_code, 0, "This command should have succeeded.");
+};
+
 done_testing;