Skip to content

Commit

Permalink
Zonemaster::CLI: don’t lose early log messages
Browse files Browse the repository at this point in the history 
Adding fake delegation by means of the --ns command-line option can
sometimes elicit early Zonemaster::Engine log messages that are lost
because the translator isn’t properly initialized at this stage. For
reasons that I do not understand fully yet, this situation causes a
condition where the zonemaster-cli script displays no message at all,
even though it should.

As a workaround for this problem, we set the callback to
Zonemaster::Engine::Logger twice. First, we set it to a closure that
simply appends them to a queue of yet-to-be-printed messages. Right
after the translator is initialized, we print the header and messages
stored by the first callback before switching the callback to the
function we actually wanted to use, which prints the messages on the
terminal.

A brief test shows no unintended side-effects with other output formats
such as JSON. But the run() method in Zonemaster::CLI is long and has a
high cyclomatic complexity, which doesn’t really help with testing!
  • Loading branch information
@marc-vanderwal
marc-vanderwal committed Feb 5, 2025
1 parent f99cf82 commit c3b90b7
Showing 1 changed file with 77 additions and 59 deletions.
136 changes: 77 additions & 59 deletions lib/Zonemaster/CLI.pm
View file
Original file line number Diff line number Diff line change
Expand Up @@ -394,87 +394,97 @@ sub run {
my %remaining_space = ();

# Callback defined here so it closes over the setup above.
Zonemaster::Engine->logger->callback(
sub {
my ( $entry ) = @_;
# But we can’t use it right now because the translator isn’t initialized.
my $message_printer = sub {
my ( $entry ) = @_;

print_spinner() if $show_progress;
print_spinner() if $show_progress;

$counter{ uc $entry->level } += 1;
$counter{ uc $entry->level } += 1;

if ( $numeric{ uc $entry->level } >= $numeric{$opt_level} ) {
$printed_something = 1;
if ( $numeric{ uc $entry->level } >= $numeric{$opt_level} ) {
$printed_something = 1;

if ( $opt_json and $opt_json_stream ) {
my %r;
if ( $opt_json and $opt_json_stream ) {
my %r;

$r{timestamp} = $entry->timestamp if $opt_time;
$r{module} = $entry->module if $opt_show_module;
$r{testcase} = $entry->testcase if $opt_show_testcase;
$r{tag} = $entry->tag;
$r{level} = $entry->level if $opt_show_level;
$r{args} = $entry->args if $entry->args;
$r{message} = $translator->translate_tag( $entry ) unless $opt_raw;
$r{timestamp} = $entry->timestamp if $opt_time;
$r{module} = $entry->module if $opt_show_module;
$r{testcase} = $entry->testcase if $opt_show_testcase;
$r{tag} = $entry->tag;
$r{level} = $entry->level if $opt_show_level;
$r{args} = $entry->args if $entry->args;
$r{message} = $translator->translate_tag( $entry ) unless $opt_raw;

say $JSON->encode( \%r );
}
elsif ( $opt_json and not $opt_json_stream ) {
# Don't do anything
say $JSON->encode( \%r );
}
elsif ( $opt_json and not $opt_json_stream ) {
# Don't do anything
}
else {
my $prefix = q{};
if ( $opt_time ) {
$prefix .= sprintf "%*.2f ", ${field_width{seconds}}, $entry->timestamp;
}
else {
my $prefix = q{};
if ( $opt_time ) {
$prefix .= sprintf "%*.2f ", ${field_width{seconds}}, $entry->timestamp;
}

if ( $opt_show_level ) {
$prefix .= $opt_raw ? $entry->level : translate_severity( $entry->level );
my $space_l10n =
${ field_width { level } } - length( decode_utf8( translate_severity( $entry->level ) ) ) + 1;
$prefix .= ' ' x $space_l10n;
}
if ( $opt_show_level ) {
$prefix .= $opt_raw ? $entry->level : translate_severity( $entry->level );
my $space_l10n =
${ field_width { level } } - length( decode_utf8( translate_severity( $entry->level ) ) ) + 1;
$prefix .= ' ' x $space_l10n;
}

if ( $opt_show_module ) {
$prefix .= sprintf "%-*s ", ${field_width{module}}, $entry->module;
}
if ( $opt_show_module ) {
$prefix .= sprintf "%-*s ", ${field_width{module}}, $entry->module;
}

if ( $opt_show_testcase ) {
$prefix .= sprintf "%-*s ", ${field_width{testcase}}, $entry->testcase;
}
if ( $opt_show_testcase ) {
$prefix .= sprintf "%-*s ", ${field_width{testcase}}, $entry->testcase;
}

if ( $opt_raw ) {
$prefix .= $entry->tag;
if ( $opt_raw ) {
$prefix .= $entry->tag;

my $message = $entry->argstr;
my @lines = split /\n/, $message;
my $message = $entry->argstr;
my @lines = split /\n/, $message;

printf "%s%s %s\n", $prefix, ' ', @lines ? shift @lines : '';
for my $line ( @lines ) {
printf "%s%s %s\n", $prefix, '>', $line;
printf "%s%s %s\n", $prefix, ' ', @lines ? shift @lines : '';
for my $line ( @lines ) {
printf "%s%s %s\n", $prefix, '>', $line;
}
}
else {
if ( $entry->level eq q{DEBUG3} and scalar( keys %{$entry->args} ) == 1 and defined $entry->args->{packet} ) {
my $packet = $entry->args->{packet};
my $padding = q{ } x length $prefix;
$entry->args->{packet} = q{};
printf "%s%s\n", $prefix, $translator->translate_tag( $entry );
foreach my $line ( split /\n/, $packet ) {
printf "%s%s\n", $padding, $line;
}
}
else {
if ( $entry->level eq q{DEBUG3} and scalar( keys %{$entry->args} ) == 1 and defined $entry->args->{packet} ) {
my $packet = $entry->args->{packet};
my $padding = q{ } x length $prefix;
$entry->args->{packet} = q{};
printf "%s%s\n", $prefix, $translator->translate_tag( $entry );
foreach my $line ( split /\n/, $packet ) {
printf "%s%s\n", $padding, $line;
}
}
else {
printf "%s%s\n", $prefix, $translator->translate_tag( $entry );
}
printf "%s%s\n", $prefix, $translator->translate_tag( $entry );
}
}
}
if ( $opt_stop_level and $numeric{ uc $entry->level } >= $numeric{$opt_stop_level} ) {
die( Zonemaster::Engine::Exception::NormalExit->new( { message => "Saw message at level " . $entry->level } ) );
}
}
if ( $opt_stop_level and $numeric{ uc $entry->level } >= $numeric{$opt_stop_level} ) {
die( Zonemaster::Engine::Exception::NormalExit->new( { message => "Saw message at level " . $entry->level } ) );
}
};

# Instead, hold early messages in a temporary queue and switch to the
# actual callback when we are ready.
my @held_messages;
Zonemaster::Engine->logger->callback(
sub {
my ( $entry ) = @_;
push @held_messages, @_;
}
);


if ( @argv > 1 ) {
say STDERR __(
"Only one domain can be given for testing. Did you forget to prepend an option with '--<OPTION>'?" );
Expand Down Expand Up @@ -534,6 +544,7 @@ sub run {
Zonemaster::Engine::Recursor->add_fake_addresses( '.', $hints_data );
}

# This can generate early log messages.
if ( @opt_ns ) {
local $@;
eval {
Expand Down Expand Up @@ -614,6 +625,13 @@ sub run {
add_fake_ds( $domain, @opt_ds );
}

# Now we are ready to actually print messages, including those that are
# currently in the hold queue.
while (my $entry = pop @held_messages) {
$message_printer->($entry);
}
Zonemaster::Engine->logger->callback($message_printer);

# Actually run tests!
eval {
if ( @opt_test ) {
Expand Down

0 comments on commit c3b90b7

Please sign in to comment.