RunCommand: create run logs for each execution

[?]

Nov 17, 2021, 8:04 PM

VYS5RV7Y6IDMT63P7X6Y2GSNJL722HYZPTK6K5WJAT6EXCJQABOAC

Dependencies

[2] YIZWKGFI tests: add jobsdir and testdir to ctx hash
[3] LZF7KS2S Result::TaskRetries: Teach about requeue
[4] 7FJKVZAN RunCommand: calculate all the commands to run against before starting
[5] 2GNJU4VF RunCommandLogs: init table
[*] 6ZXL5UOP Add a plugin to execute arbitrary commands when a build finishes
[*] 3AKZKWCR RunCommand: Test

Change contents

edit in src/lib/Hydra/Plugin/RunCommand.pm at line 153

[4.1342]

[7.3376]

# 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();
edit in src/lib/Hydra/Plugin/RunCommand.pm at line 165

[7.3492]

[7.3492]

$runlog->completed_with_child_error($?);
edit in src/lib/Hydra/Schema/Result/RunCommandLogs.pm at line 149

[5.2699]

[5.2699]

# 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()
});
}
edit in src/lib/Hydra/Schema/Result/RunCommandLogs.pm at line 169

[5.2700]

[5.2700]

=head2 completed_with_child_error
replacement in src/lib/Hydra/Schema/Result/RunCommandLogs.pm at line 171

[5.2701]→[5.2701:2843](∅→∅)

# Created by DBIx::Class::Schema::Loader v0.07049 @ 2021-11-18 12:35:52
# DO NOT MODIFY THIS OR ANYTHING ABOVE! md5sum:N0G71diB8DNDgkYgaSQrFA

[5.2701]

[5.2843]

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().
edit in src/lib/Hydra/Schema/Result/RunCommandLogs.pm at line 182

[5.2844]

[5.2844]

=item C<$errno>
edit in src/lib/Hydra/Schema/Result/RunCommandLogs.pm at line 184

[5.2845]

[5.2845]

The value of $! or $ERRNO (with use English) after calling system().
replacement in src/lib/Hydra/Schema/Result/RunCommandLogs.pm at line 186

[5.2846]→[5.2846:2945](∅→∅)

# You can replace this text with custom code or comments, and it will be preserved on regeneration

[5.2846]

[5.2945]

=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,
});
}
file addition: RunCommandLogs.t (----------)

[3.210]

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;
edit in t/plugins/RunCommand/basic.t at line 53

[8.5268]

[2.2001]

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.");
};