From ad74911e582877989d153c2629cff29e15b4e18e Mon Sep 17 00:00:00 2001 From: dasantiago Date: Tue, 17 Oct 2017 16:13:27 +0200 Subject: [PATCH 1/2] Log Uniformization This change will remove the ServerStartup, which is only used for log configuration. The FakeApp was extended to support the ServerStartup functionality. --- cpanfile | 1 + lib/OpenQA/FakeApp.pm | 72 ----------- lib/OpenQA/ResourceAllocator.pm | 9 +- lib/OpenQA/Scheduler.pm | 11 +- lib/OpenQA/{ServerStartup.pm => Setup.pm} | 146 +++++++++++++++------- lib/OpenQA/WebAPI.pm | 10 +- lib/OpenQA/WebSockets/Server.pm | 7 +- lib/OpenQA/Worker.pm | 5 +- t/04-scheduler.t | 17 ++- t/05-scheduler-full.t | 32 ++++- t/25-serverstartup.t | 19 +-- t/28-logging.t | 89 ++++++++++--- t/config.t | 12 +- 13 files changed, 248 insertions(+), 182 deletions(-) delete mode 100644 lib/OpenQA/FakeApp.pm rename lib/OpenQA/{ServerStartup.pm => Setup.pm} (63%) diff --git a/cpanfile b/cpanfile index 7c0bfed0b5f..f465a169d53 100644 --- a/cpanfile +++ b/cpanfile @@ -90,6 +90,7 @@ requires 'diagnostics'; requires 'namespace::clean'; requires 'strict'; requires 'warnings'; +requires 'File::Path'; on 'test' => sub { requires 'Perl::Tidy'; diff --git a/lib/OpenQA/FakeApp.pm b/lib/OpenQA/FakeApp.pm deleted file mode 100644 index 07345c4d7e7..00000000000 --- a/lib/OpenQA/FakeApp.pm +++ /dev/null @@ -1,72 +0,0 @@ -# Copyright (C) 2016 SUSE LLC -# -# This program is free software; you can redistribute it and/or modify -# it under the terms of the GNU General Public License as published by -# the Free Software Foundation; either version 2 of the License, or -# (at your option) any later version. -# -# This program is distributed in the hope that it will be useful, -# but WITHOUT ANY WARRANTY; without even the implied warranty of -# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the -# GNU General Public License for more details. -# -# You should have received a copy of the GNU General Public License along -# with this program; if not, see . - -package OpenQA::FakeApp; -use Mojo::Log; -use Mojo::Home; -use strict; -use warnings; -use Mojo::Base -base; -use Sys::Hostname; -use File::Spec::Functions 'catfile'; -use Mojo::File 'path'; - -has config => sub { {} }; - -has log => sub { Mojo::Log->new(handle => \*STDOUT, level => "debug"); }; - -has home => sub { Mojo::Home->new($ENV{MOJO_HOME} || '/') }; - -has mode => 'production'; - -has log_name => 'scheduler'; - -has level => 'info'; - -has instance => undef; - -has log_dir => undef; - -has schema => sub { OpenQA::Schema::connect_db() }; - -sub setup_log { - my ($self) = @_; - if ($self->log_dir) { - # So each worker from each host get it's own log (as the folder can be shared). Hopefully the machine hostname - # is already sanitized. Otherwise we need to check - my $logfile - = catfile($self->log_dir, hostname() . (defined $self->instance ? "-${\$self->instance}" : '') . ".log"); - - $self->log->handle(path($logfile)->open('>>')); - - $self->log->path($logfile); - } - - $self->log->format( - sub { - my ($time, $level, @lines) = @_; - return '[' . localtime($time) . "] [${\$self->log_name}:$level] " . join "\n", @lines, ''; - }); - - $self->log->level($self->level); -} - - -sub emit_event { - my ($self, $event, $data) = @_; - # nothing to see here, move along -} - -1; diff --git a/lib/OpenQA/ResourceAllocator.pm b/lib/OpenQA/ResourceAllocator.pm index a5cbbca9683..420cbf158e4 100644 --- a/lib/OpenQA/ResourceAllocator.pm +++ b/lib/OpenQA/ResourceAllocator.pm @@ -25,10 +25,9 @@ use Scalar::Util 'blessed'; use OpenQA::IPC; use OpenQA::Utils qw(log_debug wakeup_scheduler exists_worker safe_call); -use OpenQA::ServerStartup; use OpenQA::Resource::Jobs (); use OpenQA::Resource::Locks (); -use OpenQA::FakeApp; +use OpenQA::Setup; use sigtrap handler => \&normal_signals_handler, 'normal-signals'; my $singleton; @@ -59,9 +58,9 @@ sub new { sub run { my $self = shift; - my $fakeapp = OpenQA::FakeApp->new(log_name => 'resource-allocator'); - OpenQA::ServerStartup::read_config($fakeapp); - OpenQA::ServerStartup::setup_logging($fakeapp); + my $setup = OpenQA::Setup->new(log_name => 'resource-allocator'); + OpenQA::Setup::read_config($setup); + OpenQA::Setup::setup_log($setup); log_debug("Resource allocator started"); $self->{reactor}->run() if exists $self->{reactor} && blessed($self->{reactor}) && $self->{reactor}->isa("Net::DBus::Reactor"); diff --git a/lib/OpenQA/Scheduler.pm b/lib/OpenQA/Scheduler.pm index 4fae36bc139..e7dc3d133af 100644 --- a/lib/OpenQA/Scheduler.pm +++ b/lib/OpenQA/Scheduler.pm @@ -23,10 +23,9 @@ use Net::DBus::Reactor; use Data::Dump 'pp'; use OpenQA::IPC; -use OpenQA::FakeApp; +use OpenQA::Setup; use OpenQA::Utils 'log_debug'; -use OpenQA::ServerStartup; # How many jobs to allocate in one tick. Defaults to 50 ( set it to 0 for as much as possible) use constant MAX_JOB_ALLOCATION => $ENV{OPENQA_SCHEDULER_MAX_JOB_ALLOCATION} // 50; @@ -75,11 +74,11 @@ sub _is_method_allowed { return $ret; } -our $fakeapp; +our $setup; sub run { - $fakeapp = OpenQA::FakeApp->new; - OpenQA::ServerStartup::read_config($fakeapp); - OpenQA::ServerStartup::setup_logging($fakeapp); + $setup = OpenQA::Setup->new(log_name => 'scheduler'); + OpenQA::Setup::read_config($setup); + OpenQA::Setup::setup_log($setup); OpenQA::Scheduler->new(); log_debug("Scheduler started"); diff --git a/lib/OpenQA/ServerStartup.pm b/lib/OpenQA/Setup.pm similarity index 63% rename from lib/OpenQA/ServerStartup.pm rename to lib/OpenQA/Setup.pm index 02fba3d0237..d5efa16f7e9 100644 --- a/lib/OpenQA/ServerStartup.pm +++ b/lib/OpenQA/Setup.pm @@ -1,4 +1,4 @@ -# Copyright (C) 2015-2016 SUSE LLC +# Copyright (C) 2017 SUSE LLC # # This program is free software; you can redistribute it and/or modify # it under the terms of the GNU General Public License as published by @@ -13,20 +13,117 @@ # You should have received a copy of the GNU General Public License along # with this program; if not, see . -# This package contains shared functions between WebAPI and WebSockets -package OpenQA::ServerStartup; - +package OpenQA::Setup; +use Mojo::Log; +use Mojo::Home; use strict; use warnings; +use Mojo::Base -base; +use Sys::Hostname; +use File::Spec::Functions 'catfile'; +use Mojo::File 'path'; use Config::IniFiles; use db_profiler; use db_helpers; use OpenQA::Utils; -use Mojo::File 'path'; +use File::Path 'make_path'; -sub read_config { - my $app = shift; +has config => sub { {} }; + +has log => sub { Mojo::Log->new(handle => \*STDOUT, level => "debug"); }; + +has home => sub { Mojo::Home->new($ENV{MOJO_HOME} || '/') }; + +has mode => 'production'; + +has 'log_name'; + +has level => 'info'; + +has 'instance'; + +has 'log_dir'; + +has schema => sub { OpenQA::Schema::connect_db() }; + +sub setup_log { + my ($self) = @_; + my ($logfile, $logdir, $level, $log); + + if ($self->isa('OpenQA::Setup')) { + $logdir = $self->log_dir; + $level = $self->level; + if ($logdir && !-e $logdir) { + make_path($logdir); + } + elsif ($logdir && !-d $logdir) { + die "Please point the logs to a valid folder!"; + } + } + else { + $log = $self->log; + $level = $self->config->{logging}->{level} || 'debug'; + } + $logfile = $ENV{OPENQA_LOGFILE} || $self->config->{logging}->{file}; + + if ($logfile && $logdir) { + $logfile = catfile($logdir, $logfile); + $log = Mojo::Log->new( + handle => path($logfile)->open('>>'), + level => $self->level, + format => sub { return log_format($self->log_name, @_); }); + } + elsif ($logfile) { + $log = Mojo::Log->new( + handle => path($logfile)->open('>>'), + level => $level, + format => sub { return log_format($self->log_name, @_); }); + } + elsif ($logdir) { + # So each worker from each host get it's own log (as the folder can be shared). Hopefully the machine hostname + # is already sanitized. Otherwise we need to check + $logfile + = catfile($logdir, hostname() . (defined $self->instance ? "-${\$self->instance}" : '') . ".log"); + $log = Mojo::Log->new( + handle => path($logfile)->open('>>'), + level => $self->level, + format => sub { return log_format($self->log_name, @_); }); + } + else { + $log = Mojo::Log->new( + handle => \*STDOUT, + level => $level, + format => sub { + my ($time, $level, @lines) = @_; + return "[${\$self->log_name}:$level] " . join "\n", @lines, ''; + }); + } + + $self->log($log); + unless ($self->isa('OpenQA::Setup')) { + if ($ENV{OPENQA_SQL_DEBUG} // $self->config->{logging}->{sql_debug} // 'false' eq 'true') { + # avoid enabling the SQL debug unless we really want to see it + # it's rather expensive + db_profiler::enable_sql_debugging($self); + } + } + $OpenQA::Utils::app = $self; + return $log; +} + +sub log_format { + my ($logname, $time, $level, @lines) = @_; + return '[' . localtime($time) . "] [$logname:$level] " . join "\n", @lines, ''; +} + +sub emit_event { + my ($self, $event, $data) = @_; + # nothing to see here, move along +} + +sub read_config { + my $app = shift; my %defaults = ( global => { appname => 'openQA', @@ -123,41 +220,6 @@ sub read_config { $app->config->{auth}->{method} =~ s/\s//g; } -sub setup_logging { - my ($app) = @_; - - my $config = $app->config; - my $logfile = $ENV{OPENQA_LOGFILE} || $config->{logging}->{file}; - - if ($logfile) { - $app->log->handle(path($logfile)->open('>>')); - $app->log->path($logfile); - $app->log->format( - sub { - my ($time, $level, @lines) = @_; - return '[' . localtime($time) . "] [" . $app->log_name . ":$level] " . join "\n", @lines, ''; - }); - } - else { - $app->log->format( - sub { - my (undef, $level, @lines) = @_; - return '[' . $app->log_name . ":$level] " . join "\n", @lines, ''; - }); - } - - if ($config->{logging}->{level}) { - $app->log->level($config->{logging}->{level}); - } - if ($ENV{OPENQA_SQL_DEBUG} // $config->{logging}->{sql_debug} // 'false' eq 'true') { - # avoid enabling the SQL debug unless we really want to see it - # it's rather expensive - db_profiler::enable_sql_debugging($app); - } - - $OpenQA::Utils::app = $app; -} - # Update config definition from plugin requests sub update_config { my ($config, @namespaces) = @_; diff --git a/lib/OpenQA/WebAPI.pm b/lib/OpenQA/WebAPI.pm index a3ab55f098a..5e5f0eb3c67 100644 --- a/lib/OpenQA/WebAPI.pm +++ b/lib/OpenQA/WebAPI.pm @@ -21,8 +21,7 @@ use OpenQA::Schema; use OpenQA::WebAPI::Plugin::Helpers; use OpenQA::IPC; use OpenQA::Utils qw(log_warning job_groups_and_parents detect_current_version); -use OpenQA::ServerStartup; - +use OpenQA::Setup; use Mojo::IOLoop; use Mojolicious::Commands; use DateTime; @@ -69,9 +68,8 @@ sub log_name { # This method will run once at server start sub startup { my $self = shift; - - OpenQA::ServerStartup::read_config($self); - OpenQA::ServerStartup::setup_logging($self); + OpenQA::Setup::read_config($self); + OpenQA::Setup::setup_log($self); # Set some application defaults $self->defaults(appname => $self->app->config->{global}->{appname}); @@ -127,7 +125,7 @@ sub startup { } # Read configurations expected by plugins. - OpenQA::ServerStartup::update_config($self->config, @{$self->plugins->namespaces}, "OpenQA::WebAPI::Auth"); + OpenQA::Setup::update_config($self->config, @{$self->plugins->namespaces}, "OpenQA::WebAPI::Auth"); # End plugin loading/handling diff --git a/lib/OpenQA/WebSockets/Server.pm b/lib/OpenQA/WebSockets/Server.pm index 6fb21b595c6..f93875fe481 100644 --- a/lib/OpenQA/WebSockets/Server.pm +++ b/lib/OpenQA/WebSockets/Server.pm @@ -21,7 +21,7 @@ use Try::Tiny; use OpenQA::IPC; use OpenQA::Utils qw(log_debug log_warning log_error); use OpenQA::Schema; -use OpenQA::ServerStartup; +use OpenQA::Setup; use Data::Dumper; use Data::Dump 'pp'; use db_profiler; @@ -458,9 +458,8 @@ sub setup { app->helper(log_name => sub { return 'websockets' }); app->helper(schema => sub { return OpenQA::Schema::connect_db; }); - - OpenQA::ServerStartup::read_config(app); - OpenQA::ServerStartup::setup_logging(app); + OpenQA::Setup::read_config(app); + OpenQA::Setup::setup_log(app); # not really meaningful for websockets, but required for mode defaults app->defaults(appname => "openQA Websocket Server"); diff --git a/lib/OpenQA/Worker.pm b/lib/OpenQA/Worker.pm index 107aa57a065..008781db6ff 100644 --- a/lib/OpenQA/Worker.pm +++ b/lib/OpenQA/Worker.pm @@ -30,7 +30,7 @@ use OpenQA::Worker::Common; use OpenQA::Worker::Commands; use OpenQA::Worker::Pool qw(lockit clean_pool); use OpenQA::Worker::Jobs; -use OpenQA::FakeApp; +use OpenQA::Setup; sub init { my ($host_settings, $options) = @_; @@ -39,7 +39,7 @@ sub init { $nocleanup = $options->{"no-cleanup"}; my $logdir = $ENV{OPENQA_WORKER_LOGDIR} // $worker_settings->{LOG_DIR}; - my $app = OpenQA::FakeApp->new( + my $app = OpenQA::Setup->new( mode => 'production', log_name => 'worker', instance => $instance, @@ -48,7 +48,6 @@ sub init { $app->level($worker_settings->{LOG_LEVEL}) if $worker_settings->{LOG_LEVEL}; $app->setup_log(); - $OpenQA::Utils::app = $app; OpenQA::Worker::Common::api_init($host_settings, $options); OpenQA::Worker::Engines::isotovideo::set_engine_exec($options->{isotovideo}) if $options->{isotovideo}; } diff --git a/t/04-scheduler.t b/t/04-scheduler.t index 2862b953ddd..2b3a5dce449 100644 --- a/t/04-scheduler.t +++ b/t/04-scheduler.t @@ -429,15 +429,14 @@ is_deeply( my $asset = $schema->resultset('Assets')->register('iso', $settings{ISO}); is($asset->name, $settings{ISO}, "asset register returns same"); -subtest 'OpenQA::FakeApp object test' => sub { - use OpenQA::FakeApp; - use OpenQA::ServerStartup; - my $fakeapp = OpenQA::FakeApp->new; - OpenQA::ServerStartup::read_config($fakeapp); - OpenQA::ServerStartup::setup_logging($fakeapp); - isa_ok($fakeapp->home, 'Mojo::Home'); - isa_ok($fakeapp->schema, 'OpenQA::Schema'); - isa_ok($fakeapp->log, 'Mojo::Log'); +subtest 'OpenQA::Setup object test' => sub { + use OpenQA::Setup; + my $setup = OpenQA::Setup->new; + OpenQA::Setup::read_config($setup); + OpenQA::Setup::setup_log($setup); + isa_ok($setup->home, 'Mojo::Home'); + isa_ok($setup->schema, 'OpenQA::Schema'); + isa_ok($setup->log, 'Mojo::Log'); }; done_testing; diff --git a/t/05-scheduler-full.t b/t/05-scheduler-full.t index 2a83a117433..a230a427f3a 100644 --- a/t/05-scheduler-full.t +++ b/t/05-scheduler-full.t @@ -278,17 +278,18 @@ subtest 'Simulation of heavy unstable load' => sub { subtest 'Websocket server - close connection test' => sub { kill_service($wspid); - my $log_file = tempfile; + my $log_file = tempfile; + local $ENV{OPENQA_LOGFILE}; + local $ENV{MOJO_LOG_LEVEL}; my $unstable_ws_pid = create_websocket_server($mojoport + 1, 1); - my $w2_pid = create_worker($k->key, $k->secret, "http://localhost:$mojoport", 2, $log_file); - my $re = qr/\[.*?\]\sConnection turned off from .*?\- (.*?)\s\:(.*?) dead/; + my $w2_pid = create_worker($k->key, $k->secret, "http://localhost:$mojoport", 2, $log_file); + my $re = qr/\[.*?\]\sConnection turned off from .*?\- (.*?)\s\:(.*?) dead/; my $attempts = 800; do { sleep 1; $attempts--; } until ((() = $log_file->slurp() =~ m/$re/g) > 6 || $attempts <= 0); - kill_service($_) for ($unstable_ws_pid, $w2_pid); dead_workers($schema); my @matches = $log_file->slurp() =~ m/$re/g; @@ -299,6 +300,28 @@ subtest 'Websocket server - close connection test' => sub { "Connection was turned off by ws server correctly"; }; + +subtest 'Worker logs correctly' => sub { + kill_service($wspid); + my $log_file = tempfile; + local $ENV{OPENQA_LOGFILE}; + local $ENV{MOJO_LOG_LEVEL}; + my $worker_pid = create_worker($k->key, $k->secret, "http://bogushost:999999", 1, $log_file); + my @re = qr/\[worker:debug\] Using dir .*? for host .*/, + qr/\[worker:info\] registering worker with .*/, + qr/\[worker:error\] unable to connect to host .* retry in /, + qr/\[worker:debug\] ## adding timer register_worker-.*/; + sleep(5); + my $i = 0; + for my $re (@re) { + my @matches = $log_file->slurp() =~ m/$re/gm; + ok(1 == @matches, "Worker logs correctly @{[++$i]}"); + + } + + kill_service $worker_pid; +}; + # This test destroys almost everything. subtest 'Simulation of heavy failures' => sub { my $allocated; @@ -465,3 +488,4 @@ EOC done_testing; + diff --git a/t/25-serverstartup.t b/t/25-serverstartup.t index e286562b0a3..c1091383cb5 100644 --- a/t/25-serverstartup.t +++ b/t/25-serverstartup.t @@ -31,7 +31,7 @@ use strict; use warnings; use FindBin; use lib "$FindBin::Bin/lib"; -use OpenQA::ServerStartup; +use OpenQA::Setup; use OpenQA::Utils; use Test::More; use Mojolicious; @@ -41,7 +41,7 @@ subtest 'Setup logging to file' => sub { local $ENV{OPENQA_LOGFILE} = undef; my $tempfile = tempfile; my $app = Mojolicious->new(config => {logging => {file => $tempfile}}); - OpenQA::ServerStartup::setup_logging($app); + OpenQA::Setup::setup_log($app); $app->attr('log_name', sub { return "test"; }); my $log = $app->log; @@ -57,14 +57,15 @@ subtest 'Setup logging to file' => sub { like $content, qr/\[.*\] \[test:info\] Works too/, 'right info message'; }; -subtest 'Setup logging to STDERR' => sub { +subtest 'Setup logging to STDOUT' => sub { local $ENV{OPENQA_LOGFILE} = undef; my $buffer = ''; my $app = Mojolicious->new(); - OpenQA::ServerStartup::setup_logging($app); + OpenQA::Setup::setup_log($app); + $app->attr('log_name', sub { return "test"; }); { open my $handle, '>', \$buffer; - local *STDERR = $handle; + local *STDOUT = $handle; my $log = $app->log; $log->error('Just works'); $log->fatal('Fatal error'); @@ -80,7 +81,7 @@ subtest 'Setup logging to STDERR' => sub { subtest 'Setup logging to file (ENV)' => sub { local $ENV{OPENQA_LOGFILE} = tempfile; my $app = Mojolicious->new(config => {logging => {file => "/tmp/ignored_foo_bar"}}); - OpenQA::ServerStartup::setup_logging($app); + OpenQA::Setup::setup_log($app); $app->attr('log_name', sub { return "test"; }); my $log = $app->log; @@ -97,7 +98,7 @@ subtest 'Setup logging to file (ENV)' => sub { ok !-e "/tmp/ignored_foo_bar"; $app = Mojolicious->new(); - OpenQA::ServerStartup::setup_logging($app); + OpenQA::Setup::setup_log($app); $app->attr('log_name', sub { return "test"; }); $log = $app->log; @@ -152,7 +153,7 @@ subtest 'Update configuration from Plugin requirements' => sub { # inline packages declaration needs to appear as "loaded" $INC{"OpenQA/FakePlugin/Fuzz.pm"} = undef; $INC{"OpenQA/FakePlugin/Fuzzer.pm"} = undef; - OpenQA::ServerStartup::update_config($config, "OpenQA::FakePlugin"); + OpenQA::Setup::update_config($config, "OpenQA::FakePlugin"); ok exists($config->{auth}->{method}), "Config option exists for OpenQA::FakePlugin::Foo"; ok exists($config->{bar}->{foo}), "Config option exists for OpenQA::FakePlugin::FooBar"; @@ -171,7 +172,7 @@ subtest 'Update configuration from Plugin requirements' => sub { push @{$app->plugins->namespaces}, "OpenQA::FakePlugin"; $app->config->{ini_config} = $config->{ini_config}; $app->plugin("FooFoo"); - OpenQA::ServerStartup::update_config($app->config, "OpenQA::FakePlugin"); + OpenQA::Setup::update_config($app->config, "OpenQA::FakePlugin"); is $app->config->{foofoo}->{is_there}, "wohoo", "Right config option for OpenQA::FakePlugin::Foofoo"; }; done_testing(); diff --git a/t/28-logging.t b/t/28-logging.t index 978502baa8d..bab3642b78d 100644 --- a/t/28-logging.t +++ b/t/28-logging.t @@ -21,16 +21,17 @@ BEGIN { use Test::More; use Mojo::File qw(tempdir tempfile); use OpenQA::Utils qw(log_error log_warning log_fatal log_info log_debug); -use OpenQA::FakeApp; +use OpenQA::Setup; use File::Path qw(make_path remove_tree); use Sys::Hostname; use File::Spec::Functions 'catfile'; -my $re = qr/\[.*?\] \[worker:(.*)\] (.*) message/; +my $reFile = qr/\[.*?\] \[worker:(.*)\] (.*) message/; +my $reStdOut = qr/(?:.*?)\[worker:(.*)\] (.*) message/; subtest 'Logging to stdout' => sub { delete $ENV{OPENQA_WORKER_LOGDIR}; - + delete $ENV{OPENQA_LOGFILE}; # Capture STDOUT: # 1- dups the current STDOUT to $oldSTDOUT. This is used to restore the STDOUT later # 2- Closes the current STDOUT @@ -41,7 +42,7 @@ subtest 'Logging to stdout' => sub { open STDOUT, '>', \$output; ### Testing code here ### - my $app = OpenQA::FakeApp->new( + my $app = OpenQA::Setup->new( mode => 'production', log_name => 'worker', instance => 1, @@ -50,7 +51,7 @@ subtest 'Logging to stdout' => sub { ); $app->setup_log(); - $OpenQA::Utils::app = $app; + # $OpenQA::Utils::app = $app; log_debug('debug message'); log_error('error message'); log_info('info message'); @@ -59,9 +60,7 @@ subtest 'Logging to stdout' => sub { # Close the capture (current stdout) and restore STDOUT (by dupping the old STDOUT); close STDOUT; open(STDOUT, '>&', $oldSTDOUT) or die "Can't dup \$oldSTDOUT: $!"; - - # Tests - my @matches = ($output =~ m/$re/gm); + my @matches = ($output =~ m/$reStdOut/gm); ok(@matches / 2 == 3, 'Worker log matches'); for (my $i = 0; $i < @matches; $i += 2) { ok($matches[$i] eq $matches[$i + 1], "OK $matches[$i]"); @@ -69,10 +68,11 @@ subtest 'Logging to stdout' => sub { }; subtest 'Logging to file' => sub { + delete $ENV{OPENQA_LOGFILE}; $ENV{OPENQA_WORKER_LOGDIR} = tempdir; make_path $ENV{OPENQA_WORKER_LOGDIR}; - my $app = OpenQA::FakeApp->new( + my $app = OpenQA::Setup->new( mode => 'production', log_name => 'worker', instance => 1, @@ -80,15 +80,14 @@ subtest 'Logging to file' => sub { level => 'debug' ); my $output_logfile = catfile($ENV{OPENQA_WORKER_LOGDIR}, hostname() . '-1.log'); - $app->setup_log(); - $OpenQA::Utils::app = $app; + # $OpenQA::Utils::app = $app; log_debug('debug message'); log_error('error message'); log_info('info message'); # Tests - my @matches = (Mojo::File->new($output_logfile)->slurp =~ m/$re/gm); + my @matches = (Mojo::File->new($output_logfile)->slurp =~ m/$reFile/gm); ok(@matches / 2 == 3, 'Worker log matches'); for (my $i = 0; $i < @matches; $i += 2) { ok($matches[$i] eq $matches[$i + 1], "OK $matches[$i]"); @@ -100,6 +99,7 @@ subtest 'Logging to file' => sub { }; subtest 'log fatal to stderr' => sub { + delete $ENV{OPENQA_LOGFILE}; delete $ENV{OPENQA_WORKER_LOGDIR}; # Capture STDERR: # 1- dups the current STDERR to $oldSTDERR. This is used to restore the STDERR later @@ -111,7 +111,7 @@ subtest 'log fatal to stderr' => sub { open STDERR, '>', \$output; ### Testing code here ### - my $app = OpenQA::FakeApp->new( + my $app = OpenQA::Setup->new( mode => 'production', log_name => 'worker', instance => 1, @@ -136,6 +136,7 @@ subtest 'log fatal to stderr' => sub { subtest 'Checking log level' => sub { $ENV{OPENQA_WORKER_LOGDIR} = tempdir; delete $ENV{MOJO_LOG_LEVEL}; # The Makefile is overriding this variable + delete $ENV{OPENQA_LOGFILE}; make_path $ENV{OPENQA_WORKER_LOGDIR}; my $output_logfile = catfile($ENV{OPENQA_WORKER_LOGDIR}, hostname() . '-1.log'); @@ -144,7 +145,7 @@ subtest 'Checking log level' => sub { my $deathcounter = 0; my $counter = @loglevels; for (@loglevels) { - my $app = OpenQA::FakeApp->new( + my $app = OpenQA::Setup->new( mode => 'production', log_name => 'worker', instance => 1, @@ -153,7 +154,7 @@ subtest 'Checking log level' => sub { ); $app->setup_log(); - $OpenQA::Utils::app = $app; + # $OpenQA::Utils::app = $app; log_debug('debug message'); log_info('info message'); @@ -165,7 +166,7 @@ subtest 'Checking log level' => sub { $deathcounter++ if $@; - my %matches = map { $_ => 1 } (Mojo::File->new($output_logfile)->slurp =~ m/$re/gm); + my %matches = map { $_ => 1 } (Mojo::File->new($output_logfile)->slurp =~ m/$reFile/gm); ok(keys(%matches) == $counter--, "Worker log level $_ entry"); truncate $output_logfile, 0; } @@ -176,4 +177,60 @@ subtest 'Checking log level' => sub { delete $ENV{OPENQA_WORKER_LOGDIR}; }; +subtest 'Logging to right place' => sub { + delete $ENV{OPENQA_LOGFILE}; + $ENV{OPENQA_WORKER_LOGDIR} = tempdir; + make_path $ENV{OPENQA_WORKER_LOGDIR}; + + my $app = OpenQA::Setup->new( + mode => 'production', + log_name => 'worker', + instance => 1, + log_dir => $ENV{OPENQA_WORKER_LOGDIR}, + level => 'debug' + ); + my $output_logfile = catfile($ENV{OPENQA_WORKER_LOGDIR}, hostname() . '-1.log'); + $app->setup_log(); + log_debug('debug message'); + log_error('error message'); + log_info('info message'); + ok(-f $output_logfile, 'Log file defined in logdir'); + + local $ENV{OPENQA_LOGFILE} = 'test_log_file.log'; + $app = OpenQA::Setup->new( + mode => 'production', + log_name => 'worker', + instance => 1, + log_dir => $ENV{OPENQA_WORKER_LOGDIR}, + level => 'debug' + ); + $app->setup_log(); + log_debug('debug message'); + log_error('error message'); + log_info('info message'); + ok( + -f catfile($ENV{OPENQA_WORKER_LOGDIR}, $ENV{OPENQA_LOGFILE}), + 'Log file created defined in logdir and environment' + ); + + + local $ENV{OPENQA_LOGFILE} = catfile($ENV{OPENQA_WORKER_LOGDIR}, 'another_test_log_file.log'); + $app = OpenQA::Setup->new( + mode => 'production', + log_name => 'worker', + instance => 1, + level => 'debug' + ); + $app->setup_log(); + log_debug('debug message'); + log_error('error message'); + log_info('info message'); + ok(-f $ENV{OPENQA_LOGFILE}, 'Log file created defined in environment'); + + # clear the system + remove_tree $ENV{OPENQA_WORKER_LOGDIR}; + delete $ENV{OPENQA_WORKER_LOGDIR}; +}; + + done_testing; diff --git a/t/config.t b/t/config.t index b371db7f733..4f2e5f26ba6 100644 --- a/t/config.t +++ b/t/config.t @@ -23,14 +23,14 @@ use lib "$FindBin::Bin/lib"; use Test::More; use Test::Warnings; use Mojolicious; -use OpenQA::ServerStartup; +use OpenQA::Setup; subtest 'Test configuration default modes' => sub { local $ENV{OPENQA_CONFIG} = undef; my $app = Mojolicious->new(); $app->mode("test"); - OpenQA::ServerStartup::read_config($app); + OpenQA::Setup::read_config($app); my $config = $app->config; is(length($config->{_openid_secret}), 16, "config has openid_secret"); my $test_config = { @@ -76,7 +76,7 @@ subtest 'Test configuration default modes' => sub { # Test configuration generation with "development" mode $app = Mojolicious->new(); $app->mode("development"); - OpenQA::ServerStartup::read_config($app); + OpenQA::Setup::read_config($app); $config = $app->config; $test_config->{_openid_secret} = $config->{_openid_secret}; is_deeply $config, $test_config, 'right "development" configuration'; @@ -84,7 +84,7 @@ subtest 'Test configuration default modes' => sub { # Test configuration generation with an unknown mode (should fallback to default) $app = Mojolicious->new(); $app->mode("foo_bar"); - OpenQA::ServerStartup::read_config($app); + OpenQA::Setup::read_config($app); $config = $app->config; $test_config->{_openid_secret} = $config->{_openid_secret}; $test_config->{auth}->{method} = "OpenID"; @@ -95,7 +95,7 @@ subtest 'Test configuration default modes' => sub { # Test configuration generation with an unknown mode (should fallback to default) $app = Mojolicious->new(); $app->mode("foo_bar"); - OpenQA::ServerStartup::read_config($app); + OpenQA::Setup::read_config($app); $config = $app->config; $test_config->{_openid_secret} = $config->{_openid_secret}; $test_config->{auth}->{method} = "OpenID"; @@ -118,7 +118,7 @@ subtest 'Test configuration override from file' => sub { "blacklist = job_grab job_done\n" ); $t_dir->child("openqa.ini")->spurt(@data); - OpenQA::ServerStartup::read_config($app); + OpenQA::Setup::read_config($app); ok -e $t_dir->child("openqa.ini"); ok($app->config->{global}->{suse_mirror} eq 'http://blah/', 'suse mirror'); From 4f5469040103ee54ca486cb36fc17e63f031c07b Mon Sep 17 00:00:00 2001 From: dasantiago Date: Thu, 2 Nov 2017 16:29:31 +0100 Subject: [PATCH 2/2] Multiple loggings channels Sometimes it's required that we are able to log text to multiple files. Currently the default OpenQA::Setup::app only logs to the destination specified in the config files. With these changes if the developer wants or needs to log to another file/destination, just needs to call the normal logging functions with an extra parameter, which is the name of the "channel". Example: > log_debug($message, 'this is name of channel'); This will work as long as the "channel" already exists. Otherwise, it will use the default logging mechanism. To create a new "channel" just invoke add_log_channel with the **id** as first parameter. The rest of the parameters are the same as the ones required for Mojo::Log. Example: > add_log_channel('channel name', path=>'test.log', level=>'debug') > unless get_channel_handle('autoinst'); This will create a Mojo::Log object that will be associated with the name 'channel name' --- cpanfile | 1 - lib/OpenQA/Setup.pm | 2 +- lib/OpenQA/Utils.pm | 62 +++++++++++++++++++---- lib/OpenQA/Worker/Cache.pm | 28 +++++------ lib/OpenQA/Worker/Commands.pm | 4 +- lib/OpenQA/Worker/Engines/isotovideo.pm | 31 ++++++------ lib/OpenQA/Worker/Jobs.pm | 32 ++++-------- t/24-worker.t | 6 +-- t/25-cache.t | 1 + t/28-logging.t | 66 ++++++++++++++++++------- t/api/04-jobs.t | 56 +++++++++++++++++++++ t/full-stack.t | 49 +++++++++++++++++- 12 files changed, 249 insertions(+), 89 deletions(-) diff --git a/cpanfile b/cpanfile index f465a169d53..7c0bfed0b5f 100644 --- a/cpanfile +++ b/cpanfile @@ -90,7 +90,6 @@ requires 'diagnostics'; requires 'namespace::clean'; requires 'strict'; requires 'warnings'; -requires 'File::Path'; on 'test' => sub { requires 'Perl::Tidy'; diff --git a/lib/OpenQA/Setup.pm b/lib/OpenQA/Setup.pm index d5efa16f7e9..f21ef9f9f86 100644 --- a/lib/OpenQA/Setup.pm +++ b/lib/OpenQA/Setup.pm @@ -30,7 +30,7 @@ use File::Path 'make_path'; has config => sub { {} }; -has log => sub { Mojo::Log->new(handle => \*STDOUT, level => "debug"); }; +has log => sub { Mojo::Log->new(handle => \*STDOUT, level => "info"); }; has home => sub { Mojo::Home->new($ENV{MOJO_HOME} || '/') }; diff --git a/lib/OpenQA/Utils.pm b/lib/OpenQA/Utils.pm index 89d5bccdd2e..4f768a95dcb 100644 --- a/lib/OpenQA/Utils.pm +++ b/lib/OpenQA/Utils.pm @@ -25,6 +25,7 @@ use Mojo::File 'path'; use IO::Handle; use Scalar::Util 'blessed'; use Data::Dump 'pp'; +use Mojo::Log; require Exporter; our ($VERSION, @ISA, @EXPORT, @EXPORT_OK, %EXPORT_TAGS); @@ -46,6 +47,9 @@ $VERSION = sprintf "%d.%03d", q$Revision: 1.12 $ =~ /(\d+)/g; &log_info &log_error &log_fatal + add_log_channel + remove_log_channel + get_channel_handle &save_base64_png &run_cmd_with_log &run_cmd_with_log_return_error @@ -111,6 +115,8 @@ our $imagesdir = "$prjdir/images"; our $hostname = $ENV{SERVER_NAME}; our $app; +my %channels = (); + # the desired new folder structure is # $testcasedir/ # with "main.pm" and needles being in a productdir under @@ -219,8 +225,12 @@ sub needle_info { # logging helpers sub log_debug { - my ($msg) = @_; - if ($app && $app->log) { + my ($msg, $channel) = @_; + + if ($channel && $channels{$channel}) { + $channels{$channel}->debug($msg); + } + elsif ($app && $app->log) { $app->log->debug($msg); } else { @@ -229,8 +239,11 @@ sub log_debug { } sub log_info { - my ($msg) = @_; - if ($app && $app->log) { + my ($msg, $channel) = @_; + if ($channel && $channels{$channel}) { + $channels{$channel}->info($msg); + } + elsif ($app && $app->log) { $app->log->info($msg); } else { @@ -239,8 +252,11 @@ sub log_info { } sub log_warning { - my ($msg) = @_; - if ($app && $app->log) { + my ($msg, $channel) = @_; + if ($channel && $channels{$channel}) { + $channels{$channel}->warn($msg); + } + elsif ($app && $app->log) { $app->log->warn($msg); } else { @@ -249,8 +265,11 @@ sub log_warning { } sub log_error { - my ($msg) = @_; - if ($app && $app->log) { + my ($msg, $channel) = @_; + if ($channel && $channels{$channel}) { + $channels{$channel}->error($msg); + } + elsif ($app && $app->log) { $app->log->error($msg); } else { @@ -259,8 +278,11 @@ sub log_error { } sub log_fatal { - my ($msg) = @_; - if ($app && $app->log) { + my ($msg, $channel) = @_; + if ($channel && $channels{$channel}) { + $channels{$channel}->fatal($msg); + } + elsif ($app && $app->log) { $app->log->fatal($msg); } else { @@ -269,6 +291,26 @@ sub log_fatal { die $msg; } +sub add_log_channel { + my ($channel, @options) = @_; + $channels{$channel} = Mojo::Log->new(@options); +} + +sub remove_log_channel { + my ($channel) = @_; + delete $channels{$channel} if $channel; +} + +sub get_channel_handle { + my ($channel) = @_; + if ($channel) { + return $channels{$channel}->handle if $channels{$channel}; + } + elsif ($app) { + return $app->log->handle; + } +} + sub save_base64_png($$$) { my ($dir, $newfile, $png) = @_; return unless $newfile; diff --git a/lib/OpenQA/Worker/Cache.pm b/lib/OpenQA/Worker/Cache.pm index 852f2f0bb2d..3ee2546ef7c 100644 --- a/lib/OpenQA/Worker/Cache.pm +++ b/lib/OpenQA/Worker/Cache.pm @@ -20,7 +20,7 @@ use warnings; use File::Basename; use Fcntl ':flock'; use Mojo::UserAgent; -use OpenQA::Utils qw(log_error log_info log_debug); +use OpenQA::Utils qw(log_error log_info log_debug get_channel_handle add_log_channel); use OpenQA::Worker::Common; use List::MoreUtils; use File::Spec::Functions 'catdir'; @@ -82,12 +82,11 @@ sub init { sub download_asset { my ($id, $type, $asset, $etag) = @_; - open(my $log, '>>', "autoinst-log.txt") or die("Cannot open autoinst-log.txt"); - local $| = 1; + add_log_channel('autoinst', path => 'autoinst-log.txt', level => 'debug') unless get_channel_handle('autoinst'); my $ua = Mojo::UserAgent->new(max_redirects => 2); $ua->max_response_size(0); my $url = sprintf '%s/tests/%d/asset/%s/%s', $host, $id, $type, basename($asset); - print $log "Downloading " . basename($asset) . " from $url\n"; + log_debug("Downloading " . basename($asset) . " from $url", 'autoinst'); my $tx = $ua->build_tx(GET => $url); my $headers; @@ -115,7 +114,7 @@ sub download_asset { $last_updated = time; if ($progress < $current) { $progress = $current; - print $log "CACHE: Downloading $asset: ", $size == $len ? 100 : $progress . "%\n"; + log_debug("CACHE: Downloading $asset: ", $size == $len ? 100 : $progress . "%", 'autoinst'); } } }); @@ -126,20 +125,20 @@ sub download_asset { my $size; if ($code eq 304) { if (toggle_asset_lock($asset, 0)) { - print $log "CACHE: Content has not changed, not downloading the $asset but updating last use\n"; + log_debug("CACHE: Content has not changed, not downloading the $asset but updating last use", 'autoinst'); } else { - print $log "CACHE: Abnormal situation, code 304. Retrying download\n"; # poo#19270 might give a hint + log_debug("CACHE: Abnormal situation, code 304. Retrying download", 'autoinst'); $asset = 520; } } elsif ($tx->res->is_server_error) { if (toggle_asset_lock($asset, 0)) { - print $log "CACHE: Could not download the asset, triggering a retry for $code.\n"; + log_debug("CACHE: Could not download the asset, triggering a retry for $code.", 'autoinst'); $asset = $code; } else { - print $log "CACHE: Abnormal situation, server error. Retrying download\n"; + log_debug("CACHE: Abnormal situation, server error. Retrying download", 'autoinst'); $asset = $code; } } @@ -150,19 +149,18 @@ sub download_asset { if ($size == $headers->content_length) { check_limits($size); update_asset($asset, $etag, $size); - print $log "CACHE: Asset download successful to $asset, Cache size is: $cache_real_size\n"; + log_debug("CACHE: Asset download successful to $asset, Cache size is: $cache_real_size", 'autoinst'); } else { - print $log "CACHE: Size of $asset differs, Expected: " - . $headers->content_length - . " / Downloaded: " - . "$size \n"; + log_debug( + "CACHE: Size of $asset differs, Expected: " . $headers->content_length . " / Downloaded: " . "$size", + 'autoinst'); $asset = 598; # 598 (Informal convention) Network read timeout error } } else { my $message = $tx->res->error->{message}; - print $log "CACHE: Download of $asset failed with: $code - $message\n"; + log_debug("CACHE: Download of $asset failed with: $code - $message", 'autoinst'); purge_asset($asset); $asset = undef; } diff --git a/lib/OpenQA/Worker/Commands.pm b/lib/OpenQA/Worker/Commands.pm index c1e112034dd..ed357c8ec1b 100644 --- a/lib/OpenQA/Worker/Commands.pm +++ b/lib/OpenQA/Worker/Commands.pm @@ -17,7 +17,7 @@ package OpenQA::Worker::Commands; use 5.018; use warnings; -use OpenQA::Utils qw(log_error log_warning log_debug); +use OpenQA::Utils qw(log_error log_warning log_debug add_log_channel remove_log_channel); use OpenQA::Worker::Common; use OpenQA::Worker::Jobs; use POSIX ':sys_wait_h'; @@ -158,6 +158,8 @@ sub websocket_commands { if ($job && $job->{id}) { $OpenQA::Worker::Common::job = $job; + remove_log_channel('autoinst'); + add_log_channel('autoinst', path => 'autoinst-log.txt', level => 'debug'); log_debug("Job " . $job->{id} . " scheduled for next cycle"); Mojo::IOLoop->singleton->once( "start_job" => sub { diff --git a/lib/OpenQA/Worker/Engines/isotovideo.pm b/lib/OpenQA/Worker/Engines/isotovideo.pm index 9f4b47edd0f..65ddc639dc0 100644 --- a/lib/OpenQA/Worker/Engines/isotovideo.pm +++ b/lib/OpenQA/Worker/Engines/isotovideo.pm @@ -18,7 +18,7 @@ use strict; use warnings; use OpenQA::Worker::Common; -use OpenQA::Utils qw(locate_asset log_error log_info log_debug); +use OpenQA::Utils qw(locate_asset log_error log_info log_debug get_channel_handle); use POSIX qw(:sys_wait_h strftime uname _exit); use JSON 'to_json'; @@ -29,6 +29,7 @@ use Errno; use Cwd qw(abs_path getcwd); use OpenQA::Worker::Cache; use Time::HiRes 'sleep'; +use IO::Handle; my $isotovideo = "/usr/bin/isotovideo"; my $workerpid; @@ -119,13 +120,10 @@ sub detect_asset_keys { sub engine_workit { my ($job) = @_; - if (open(my $log, '>', "autoinst-log.txt")) { - print $log "+++ setup notes +++\n"; - printf $log "start time: %s\n", strftime("%F %T", gmtime); - my ($sysname, $hostname, $release, $version, $machine) = POSIX::uname(); - printf $log "running on $hostname:%d ($sysname $release $version $machine)\n", $instance; - close($log); - } + my ($sysname, $hostname, $release, $version, $machine) = POSIX::uname(); + log_debug('+++ setup notes +++', 'autoinst'); + log_debug(sprintf("start time: %s", strftime("%F %T", gmtime)), 'autoinst'); + log_debug(sprintf("running on $hostname:%d ($sysname $release $version $machine)", $instance), 'autoinst'); # set base dir to the one assigned with webui OpenQA::Utils::change_sharedir($hosts->{$current_host}{dir}); @@ -213,15 +211,14 @@ sub engine_workit { setpgrp(0, 0); $ENV{TMPDIR} = $tmpdir; log_info("$$: WORKING " . $job->{id}); - if (open(my $log, '>>', "autoinst-log.txt")) { - print $log "+++ worker notes +++\n"; - printf $log "start time: %s\n", strftime("%F %T", gmtime); - my ($sysname, $hostname, $release, $version, $machine) = POSIX::uname(); - printf $log "running on $hostname:%d ($sysname $release $version $machine)\n", $instance; - close($log); - } - open STDOUT, ">>", "autoinst-log.txt"; - open STDERR, ">&STDOUT"; + log_debug('+++ worker notes +++', 'autoinst'); + log_debug(sprintf("start time: %s", strftime("%F %T", gmtime)), 'autoinst'); + + my ($sysname, $hostname, $release, $version, $machine) = POSIX::uname(); + log_debug(sprintf("running on $hostname:%d ($sysname $release $version $machine)", $instance), 'autoinst'); + my $handle = get_channel_handle('autoinst'); + STDOUT->fdopen($handle, 'w'); + STDERR->fdopen($handle, 'w'); exec "perl", "$isotovideo", '-d'; die "exec failed: $!\n"; } diff --git a/lib/OpenQA/Worker/Jobs.pm b/lib/OpenQA/Worker/Jobs.pm index 70ecdb4de38..80f1f45d7f1 100644 --- a/lib/OpenQA/Worker/Jobs.pm +++ b/lib/OpenQA/Worker/Jobs.pm @@ -126,7 +126,6 @@ sub check_job { sub stop_job { my ($aborted, $job_id) = @_; - # we call this function in all situations, so better check if (!$job || $stop_job_running) { # In case there is no job, or if the job was asked to stop @@ -188,9 +187,7 @@ sub upload { # we need to open and close the log here as one of the files # might actually be autoinst-log.txt - open(my $log, '>>', "autoinst-log.txt"); - printf $log "uploading %s\n", $filename; - close $log; + log_debug("uploading $filename", 'autoinst'); log_debug("uploading $filename"); my $regular_upload_failed = 0; @@ -228,10 +225,8 @@ sub upload { # Just return if all upload retries have failed # this will cause the next group of uploads to be triggered - my $msg = "All $retry_limit upload attempts have failed for $filename\n"; - open(my $log, '>>', "autoinst-log.txt"); - print $log $msg; - close $log; + my $msg = "All $retry_limit upload attempts have failed for $filename"; + log_debug($msg, 'autoinst'); log_error($msg); return 0; } @@ -246,9 +241,7 @@ sub upload { else { $msg = sprintf "ERROR %s: Connection error: $err->{message}\n", $filename; } - open(my $log, '>>', "autoinst-log.txt"); - print $log $msg; - close $log; + log_debug($msg, 'autoinst'); log_error($msg); return 0; } @@ -267,15 +260,15 @@ sub upload { ($csum2, $size2) = split(/ /, <$cfd>); close($cfd); } - open(my $log, '>>', "autoinst-log.txt"); - print $log "Checksum comparison (actual:expected) $csum1:$csum2 with size (actual:expected) $size1:$size2\n"; + log_debug("Checksum comparison (actual:expected) $csum1:$csum2 with size (actual:expected) $size1:$size2", + 'autoinst'); if ($csum1 eq $csum2 && $size1 eq $size2) { my $ua_url = $hosts->{$current_host}{url}->clone; $ua_url->path("jobs/$job_id/ack_temporary"); $hosts->{$current_host}{ua}->post($ua_url => form => {temporary => $res->res->json->{temporary}}); } else { - print $log "Checksum/size comparison of $filename FAILED\n"; + log_debug("Checksum/size comparison of $filename FAILED", 'autoinst'); return 0; } } @@ -318,13 +311,9 @@ sub _stop_job_2 { $aborted ||= 'done'; my $job_done; # undef - - open(my $log, '>>', "autoinst-log.txt"); - print $log "+++ worker notes +++\n"; - printf $log "end time: %s\n", strftime("%F %T", gmtime); - print $log "result: $aborted\n"; - close $log; - + log_debug("+++ worker notes +++", 'autoinst'); + log_debug(sprintf("end time: %s", strftime("%F %T", gmtime)), 'autoinst'); + log_debug("result: $aborted", 'autoinst'); if ($aborted ne 'quit' && $aborted ne 'abort' && $aborted ne 'api-failure') { # collect uploaded logs my @uploaded_logfiles = glob "$pooldir/ulogs/*"; @@ -367,7 +356,6 @@ sub _stop_job_2 { } } } - for my $file (qw(video.ogv vars.json serial0 autoinst-log.txt virtio_console.log)) { next unless -e $file; # default serial output file called serial0 diff --git a/t/24-worker.t b/t/24-worker.t index e1826893eda..cb480052196 100644 --- a/t/24-worker.t +++ b/t/24-worker.t @@ -27,7 +27,7 @@ use OpenQA::Client; use Test::More; use Test::Mojo; use Test::Warnings; -use Test::Output qw(stdout_like stderr_like); +use Test::Output 'combined_like'; use Test::Fatal; use Mojo::File qw(tempdir path); #use Scalar::Utils 'refaddr'; @@ -97,7 +97,7 @@ test_via_io_loop sub { tries => 1, callback => sub { my $res = shift; is($res, undef, 'error ignored') }); - stderr_like( + combined_like( sub { OpenQA::Worker::Common::api_call( 'post', 'jobs/500/status', @@ -106,7 +106,7 @@ test_via_io_loop sub { callback => sub { my $res = shift; is($res, undef, 'error handled'); Mojo::IOLoop->stop() }); while (Mojo::IOLoop->is_running) { Mojo::IOLoop->singleton->reactor->one_tick } }, - qr/.*\[ERROR\] Connection error:.*(remaining tries: 0).*/i, + qr/.*\[ERROR\] Connection error:.*(remaining tries: 0).*\[DEBUG\] .* no job running.*/s, 'warning about 503 error' ); }; diff --git a/t/25-cache.t b/t/25-cache.t index 8c087d2bff5..1d221b017ea 100644 --- a/t/25-cache.t +++ b/t/25-cache.t @@ -69,6 +69,7 @@ sub truncate_log { my $logfile_ = ($new_log) ? $new_log : $logfile; open(my $f, '>', $logfile_) or die "OPENING $logfile_: $!\n"; truncate $f, 0 or warn("Could not truncate"); + close $f; } sub read_log { diff --git a/t/28-logging.t b/t/28-logging.t index bab3642b78d..6cab94b0e4d 100644 --- a/t/28-logging.t +++ b/t/28-logging.t @@ -20,18 +20,18 @@ BEGIN { } use Test::More; use Mojo::File qw(tempdir tempfile); -use OpenQA::Utils qw(log_error log_warning log_fatal log_info log_debug); +use OpenQA::Utils qw(log_error log_warning log_fatal log_info log_debug add_log_channel); use OpenQA::Setup; use File::Path qw(make_path remove_tree); use Sys::Hostname; use File::Spec::Functions 'catfile'; -my $reFile = qr/\[.*?\] \[worker:(.*)\] (.*) message/; -my $reStdOut = qr/(?:.*?)\[worker:(.*)\] (.*) message/; - +my $reFile = qr/\[.*?\] \[worker:(.*?)\] (.*?) message/; +my $reStdOut = qr/(?:.*?)\[worker:(.*?)\] (.*?) message/; +my $reChannel = qr/\[.*?\] \[(.*?)\] (.*?) message/; subtest 'Logging to stdout' => sub { - delete $ENV{OPENQA_WORKER_LOGDIR}; - delete $ENV{OPENQA_LOGFILE}; + local $ENV{OPENQA_WORKER_LOGDIR}; + local $ENV{OPENQA_LOGFILE}; # Capture STDOUT: # 1- dups the current STDOUT to $oldSTDOUT. This is used to restore the STDOUT later # 2- Closes the current STDOUT @@ -51,7 +51,7 @@ subtest 'Logging to stdout' => sub { ); $app->setup_log(); - # $OpenQA::Utils::app = $app; + log_debug('debug message'); log_error('error message'); log_info('info message'); @@ -81,7 +81,6 @@ subtest 'Logging to file' => sub { ); my $output_logfile = catfile($ENV{OPENQA_WORKER_LOGDIR}, hostname() . '-1.log'); $app->setup_log(); - # $OpenQA::Utils::app = $app; log_debug('debug message'); log_error('error message'); log_info('info message'); @@ -141,16 +140,17 @@ subtest 'Checking log level' => sub { my $output_logfile = catfile($ENV{OPENQA_WORKER_LOGDIR}, hostname() . '-1.log'); - my @loglevels = qw(debug info warn error fatal); - my $deathcounter = 0; - my $counter = @loglevels; - for (@loglevels) { + my @loglevels = qw(debug info warn error fatal); + my $deathcounter = 0; + my $counterFile = @loglevels; + my $counterChannel = @loglevels; + for my $level (@loglevels) { my $app = OpenQA::Setup->new( mode => 'production', log_name => 'worker', instance => 1, log_dir => $ENV{OPENQA_WORKER_LOGDIR}, - level => $_ + level => $level ); $app->setup_log(); @@ -161,16 +161,49 @@ subtest 'Checking log level' => sub { log_warning('warn message'); log_error('error message'); - my $exception = 0; eval { log_fatal('fatal message'); }; $deathcounter++ if $@; my %matches = map { $_ => 1 } (Mojo::File->new($output_logfile)->slurp =~ m/$reFile/gm); - ok(keys(%matches) == $counter--, "Worker log level $_ entry"); + ok(keys(%matches) == $counterFile, "Worker log level $level entry"); + + my $logging_test_file = tempfile; + + add_log_channel('test', path => $logging_test_file, level => $level); + log_debug("debug message", 'test'); + log_info("info message", 'test'); + log_warning("warn message", 'test'); + log_error("error message", 'test'); + + eval { log_fatal('fatal message', 'test'); }; + $deathcounter++ if $@; + + %matches = map { $_ => 1 } (Mojo::File->new($logging_test_file)->slurp =~ m/$reChannel/gm); + ok(keys(%matches) == $counterChannel--, "Worker channel log level $level entry"); # TODO + # use Data::Dumper; + # print Dumper(\%matches); + # unlink $logging_test_file; + + log_debug("debug message", 'no_channel'); + log_info("info message", 'no_channel'); + log_warning("warn message", 'no_channel'); + log_error("error", 'no_channel'); + + eval { log_fatal('fatal message', 'no_channel'); }; + + $deathcounter++ if $@; + + # print Mojo::File->new($output_logfile)->slurp; + + %matches = map { $_ => ($matches{$_} // 0) + 1 } (Mojo::File->new($output_logfile)->slurp =~ m/$reFile/gm); + my @vals = grep { $_ != 2 } (values(%matches)); + ok(keys(%matches) == $counterFile--, "Worker no existent channel log level $level entry"); + ok(@vals == 0, 'Worker no existent channel log level $level entry '); + truncate $output_logfile, 0; } - ok($deathcounter == @loglevels, "Worker dies when logs fatal"); + ok($deathcounter / 3 == @loglevels, "Worker dies when logs fatal"); # clear the system remove_tree $ENV{OPENQA_WORKER_LOGDIR}; @@ -232,5 +265,4 @@ subtest 'Logging to right place' => sub { delete $ENV{OPENQA_WORKER_LOGDIR}; }; - done_testing; diff --git a/t/api/04-jobs.t b/t/api/04-jobs.t index 9852aac8bc4..1d67b90dd7b 100644 --- a/t/api/04-jobs.t +++ b/t/api/04-jobs.t @@ -279,6 +279,62 @@ $get = $t->get_ok($query->path_query)->status_is(200); $res = $get->tx->res->json; ok(!@{$res->{jobs}}, 'no result for nonexising state'); +subtest 'Check job status and output' => sub { + $get = $t->get_ok('/api/v1/jobs'); + @new_jobs = @{$get->tx->res->json->{jobs}}; + my $running_job_id; + + local $ENV{MOJO_LOG_LEVEL} = 'debug'; + local $ENV{OPENQA_LOGFILE}; + local $ENV{OPENQA_WORKER_LOGDIR}; + $OpenQA::Utils::app->log(Mojo::Log->new(handle => \*STDOUT)); + + for my $job (@new_jobs) { + my $worker_id = $job->{assigned_worker_id}; + my $json = {}; + if ($worker_id) { + $json->{status} = {worker_id => $worker_id}; + $running_job_id = $job->{id}; + } + + open(my $oldSTDOUT, ">&", STDOUT) or die "Can't preserve STDOUT\n$!\n"; + close STDOUT; + my $output; + open STDOUT, '>', \$output; + + + $post = $t->post_ok("/api/v1/jobs/$job->{id}/status", json => $json); + $worker_id = 0; + close STDOUT; + open(STDOUT, '>&', $oldSTDOUT) or die "Can't dup \$oldSTDOUT: $!"; + if ($job->{id} == 99963) { + $post->status_is(200); + } + else { + $post->status_is(400); + ok($output =~ /\[.*info\] Got status update for job .*? but does not contain a worker id!/, + "Check status update for job $job->{id}"); + } + } + + open(my $oldSTDOUT, ">&", STDOUT) or die "Can't preserve STDOUT\n$!\n"; + close STDOUT; + my $output; + open STDOUT, '>', \$output; + # bogus job ID + my $bogus_job_post = $t->post_ok("/api/v1/jobs/9999999/status", json => {}); + # bogus worker ID + my $bogus_worker_post + = $t->post_ok("/api/v1/jobs/$running_job_id/status", json => {status => {worker_id => 999999}}); + close STDOUT; + open(STDOUT, '>&', $oldSTDOUT) or die "Can't dup \$oldSTDOUT: $!"; + + $bogus_job_post->status_is(400); + $bogus_worker_post->status_is(400); + ok($output =~ /\[.*info\] Got status update for non-existing job/, 'Check status update for non-existing job'); + ok($output =~ /\[.*info\] Got status update for job .* that does not belong to Worker/, + 'Got status update for job that doesnt belong to worker'); +}; # Test /jobs/cancel # TODO: cancelling jobs via API in tests doesn't work for some reason # diff --git a/t/full-stack.t b/t/full-stack.t index 1a94b0386cc..a4cae5a142b 100644 --- a/t/full-stack.t +++ b/t/full-stack.t @@ -280,11 +280,19 @@ wait_for_result_panel qr/Result: incomplete/, 'Test 4 crashed as expected'; # Slurp the whole file, it's not that big anyways my $filename = $resultdir . "/00000/00000004-$job_name/autoinst-log.txt"; +ok(-s $filename, 'Test 4 autoinst-log.txt file created'); open(my $f, '<', $filename) or die "OPENING $filename: $!\n"; my $autoinst_log = do { local ($/); <$f> }; close($f); like($autoinst_log, qr/result: setup failure/, 'Test 4 state correct: setup failure'); + +like((split(/\n/, $autoinst_log))[0], qr/\[debug\] \+\+\+ setup notes \+\+\+/, 'Test 4 correct autoinst setup notes'); +like( + (split(/\n/, $autoinst_log))[-1], + qr/\[debug\] uploading autoinst-log.txt/, + 'Test 4 correct autoinst uploading autoinst' +); kill_worker; # Ensure that the worker can be killed with TERM signal my $cache_location = path($ENV{OPENQA_BASEDIR}, 'cache')->make_path; @@ -341,7 +349,18 @@ subtest 'Cache tests' => sub { close($f); like($autoinst_log, qr/Downloading Core-7.2.iso/, 'Test 5, downloaded the right iso.'); - like($autoinst_log, qr/11116544/, 'Test 5 Core-7.2.iso size is correct.'); + like($autoinst_log, qr/11116544/, 'Test 5 Core-7.2.iso size is correct.'); + like($autoinst_log, qr/\[debug\] result: done/, 'Test 5 result done'); + like( + (split(/\n/, $autoinst_log))[0], + qr/\[debug\] \+\+\+ setup notes \+\+\+/, + 'Test 5 correct autoinst setup notes' + ); + like( + (split(/\n/, $autoinst_log))[-1], + qr/\[debug\] uploading autoinst-log.txt/, + 'Test 5 correct autoinst uploading autoinst' + ); my $dbh = DBI->connect("dbi:SQLite:dbname=$db_file", undef, undef, {RaiseError => 1, PrintError => 1, AutoCommit => 1}); @@ -401,21 +420,47 @@ subtest 'Cache tests' => sub { wait_for_result_panel qr/Result: passed/, 'test 7 is passed'; $filename = path($resultdir, '00000', "00000007-$job_name")->child("autoinst-log.txt"); + ok(-s $filename, 'Test 7 autoinst-log.txt file created'); + open($f, '<', $filename) or die "OPENING $filename: $!\n"; $autoinst_log = do { local ($/); <$f> }; close($f); like($autoinst_log, qr/Content has not changed/, 'Test 7 Core-7.2.iso has not changed.'); + like($autoinst_log, qr/\[debug\] \+\+\+\ worker notes \+\+\+/, 'Test 7 correct autoinst worker notes'); + like( + (split(/\n/, $autoinst_log))[0], + qr/\[debug\] \+\+\+ setup notes \+\+\+/, + 'Test 7 correct autoinst setup notes' + ); + like( + (split(/\n/, $autoinst_log))[-1], + qr/\[debug\] uploading autoinst-log.txt/, + 'Test 7 correct autoinst uploading autoinst' + ); client_call("jobs post $JOB_SETUP HDD_1=non-existent.qcow2"); $driver->get('/tests/8'); wait_for_result_panel qr/Result: incomplete/, 'test 8 is incomplete'; - $filename = path($resultdir, '00000', "00000008-$job_name")->child("autoinst-log.txt"); + ok(-s $filename, 'Test 8 autoinst-log.txt file created'); + open($f, '<', $filename) or die "OPENING $filename: $!\n"; $autoinst_log = do { local ($/); <$f> }; close($f); + like($autoinst_log, qr/\[debug\] \+\+\+\ worker notes \+\+\+/, 'Test 7 correct autoinst worker notes'); + like( + (split(/\n/, $autoinst_log))[0], + qr/\[debug\] \+\+\+ setup notes \+\+\+/, + 'Test 8 correct autoinst setup notes' + ); + like( + (split(/\n/, $autoinst_log))[-1], + qr/\[debug\] uploading autoinst-log.txt/, + 'Test 8 correct autoinst uploading autoinst' + ); + like($autoinst_log, qr/non-existent.qcow2 failed with: 404 - Not Found/, 'Test 8 failure message found in log.'); like($autoinst_log, qr/result: setup failure/, 'Test 8 state correct: setup failure');