From 625fb392e5647241a9766e9f4e0a9c6f5d2b2cee Mon Sep 17 00:00:00 2001 From: Guillaume Rousse <guillaume.rousse@renater.fr> Date: Mon, 6 Nov 2017 17:04:13 +0100 Subject: [PATCH] kill custom logger code, use Log::Any instead --- bin/account-manager-client.pl.in | 11 +- lib/IdPAccountManager/Logger.pm | 92 ---------------- lib/IdPAccountManager/Tools.pm | 19 +--- lib/IdPAccountManager/WebRequest.pm | 163 ++++++++-------------------- lib/Makefile.am | 1 - t/logger.t | 146 ------------------------- 6 files changed, 57 insertions(+), 375 deletions(-) delete mode 100644 lib/IdPAccountManager/Logger.pm delete mode 100755 t/logger.t diff --git a/bin/account-manager-client.pl.in b/bin/account-manager-client.pl.in index 8459707..5076fb7 100755 --- a/bin/account-manager-client.pl.in +++ b/bin/account-manager-client.pl.in @@ -10,6 +10,7 @@ no warnings 'experimental::smartmatch'; use Data::Dumper; use English qw(-no_match_vars); use Getopt::Long qw(:config auto_help); +use Log::Any::Adapter; use Pod::Usage; use IdPAccountManager::Data::AuthenticationToken; @@ -19,7 +20,6 @@ use IdPAccountManager::Data::ServiceProvider::Manager; use IdPAccountManager::Data::TestAccount; use IdPAccountManager::Data::TestAccount::Manager; use IdPAccountManager::Configuration; -use IdPAccountManager::Logger; use IdPAccountManager::SAMLMetadata; my %options; @@ -337,11 +337,14 @@ sub send_notice { -verbose => 0 ) unless $options{email_address}; - my $logger = IdPAccountManager::Logger->new( - file => $configuration->{log_file}, - verbosity => $configuration->{log_level} + Log::Any::Adapter->set( + 'File', + $self->{configuration}->{log_file}, + log_level => $self->{configuration}->{log_level} ); + my $logger = Log::Any->get_logger(); + die "Failed to send mail notice to $options{email_address}\n" unless IdPAccountManager::Tools::mail_notice( template => 'templates/mail/notification_generic_error.tt2.eml', diff --git a/lib/IdPAccountManager/Logger.pm b/lib/IdPAccountManager/Logger.pm deleted file mode 100644 index 80d5541..0000000 --- a/lib/IdPAccountManager/Logger.pm +++ /dev/null @@ -1,92 +0,0 @@ -package IdPAccountManager::Logger; - -use strict; -use warnings; - -use base qw(Exporter); - -use English qw(-no_match_vars); -use POSIX qw(strftime); - -use constant { - LOG_DEBUG => 0, - LOG_INFO => 1, - LOG_TRACE => 1, - LOG_NOTICE => 2, - LOG_ERROR => 3, -}; - -our @EXPORT = qw(LOG_DEBUG LOG_INFO LOG_TRACE LOG_NOTICE LOG_ERROR); - -my @value2name = qw(DEBUG INFO NOTICE ERROR); - -my %name2value = ( - debug => LOG_DEBUG, - info => LOG_INFO, - trace => LOG_TRACE, - notice => LOG_NOTICE, - error => LOG_ERROR, -); - -sub new { - my ($pkg, %args) = @_; - - die "missing argument 'file'" unless defined $args{file}; - die "missing argument 'verbosity'" unless defined $args{verbosity}; - die "invalid argument 'verbosity'" unless exists $name2value{$args{verbosity}}; - - my $handle; - open($handle, '>>', $args{file}) or die "failed to open $args{file}: $ERRNO"; - - my $self = { - handle => $handle, - verbosity => $name2value{$args{verbosity}}, - }; - - bless $self, $pkg; - - return $self; -} - -sub log { - my ($self, %args) = @_; - - die "missing argument 'message'" unless defined $args{message}; - die "missing argument 'level'" unless defined $args{level}; - - return if $args{level} < $self->{verbosity}; - - ## Determine calling function and parameters - ## If in 'err' level, build a stack trace - my $caller_string; - if ($args{level} == LOG_ERROR) { - my $go_back = 1; - my @calls; - while (my @call = caller($go_back)) { - unshift @calls, $call[3] . '#' . $call[2]; - $go_back++; - } - - $caller_string = join(' > ', @calls); - } else { - my @call = caller(1); - $caller_string = $call[3] . '()'; - } - - my $level = $value2name[$args{level}]; - my $address = $ENV{REMOTE_ADDR} || 'NOIP'; - my $user = $ENV{mail} || 'NOEMAIL'; - my $date = POSIX::strftime("%Y:%m:%d %H:%M:%S", localtime(time)); - - print - {$self->{handle}} - "$date - ($level) - $address - $user - $caller_string $args{message}\n"; -} - -sub DESTROY { - my ($self) = @_; - - close $self->{handle}; -} - -1; diff --git a/lib/IdPAccountManager/Tools.pm b/lib/IdPAccountManager/Tools.pm index e77bcb5..ff1c86b 100644 --- a/lib/IdPAccountManager/Tools.pm +++ b/lib/IdPAccountManager/Tools.pm @@ -136,20 +136,16 @@ sub mail_notice { } if ($change_rcpt) { - $logger->log( - level => LOG_INFO, - message => sprintf( - "no_mail_outside option set; notification for %s rerouted to admins ; ", - $notice_email - ) + $logger->infof( + "no_mail_outside option set; notification for %s rerouted to admins ; ", + $notice_email ); $notice_email = $args{admin_email}; } } - $logger->log( - level => LOG_TRACE, - message => sprintf('(template=%s, to=%s)', $in{template}, $mail_data->{to}) + $logger->tracef( + sprintf('(template=%s, to=%s)', $in{template}, $mail_data->{to}) ); open SENDMAIL, @@ -159,10 +155,7 @@ sub mail_notice { my $tt2 = Template->new(FILTERS => { qencode => [ \qencode, 0 ] }); unless ($tt2->process($tt2_file, $mail_data, \*SENDMAIL)) { - $logger->log( - level => LOG_ERROR, - message => sprintf("Error TT2 : %s", $tt2->error()) - ); + $logger->errorf("Error TT2 : %s", $tt2->error()); } close SENDMAIL; } diff --git a/lib/IdPAccountManager/WebRequest.pm b/lib/IdPAccountManager/WebRequest.pm index 4032dcd..5665ee5 100755 --- a/lib/IdPAccountManager/WebRequest.pm +++ b/lib/IdPAccountManager/WebRequest.pm @@ -6,11 +6,11 @@ use warnings; use CGI; use English qw(-no_match_vars); use Template; +use Log::Any::Adapter; use IdPAccountManager::Data::TestAccount; use IdPAccountManager::Data::AuthenticationToken; use IdPAccountManager::Data::ServiceProvider; -use IdPAccountManager::Logger; use IdPAccountManager::SAMLMetadata; ## Defining parameters format @@ -41,23 +41,14 @@ sub new { configuration => $args{configuration}, }; - eval { - $self->{logger} = IdPAccountManager::Logger->new( - file => $self->{configuration}->{log_file}, - verbosity => $self->{configuration}->{log_level} - ); - }; - if ($EVAL_ERROR) { - $self->{logger} = IdPAccountManager::Logger->new( - file => '/dev/null', - verbosity => $self->{configuration}->{log_level} - ); - } - $self->{logger}->log( - level => LOG_INFO, - message => '' + Log::Any::Adapter->set( + 'File', + $self->{configuration}->{log_file}, + log_level => $self->{configuration}->{log_level} ); + $self->{logger} = Log::Any->get_logger(); + IdPAccountManager::DB->register_db( driver => $self->{configuration}->{database_type}, database => $self->{configuration}->{database_name}, @@ -83,7 +74,6 @@ sub run { ## Execute a web request sub execute { my ($self) = @_; - $self->{logger}->log(level => LOG_DEBUG, message => ""); my $status; @@ -103,9 +93,8 @@ sub execute { && !ref($format{$parameter})) { if ($parameters{$parameter} !~ /^$format{$parameter}$/) { push @{ $self->{out}->{errors} }, "format_$parameter"; - $self->{logger}->log( - level => LOG_ERROR, - message => "Incorrect parameter format : $parameter" + $self->{logger}->error( + "Incorrect parameter format : $parameter" ); return undef; } @@ -154,10 +143,7 @@ sub execute { } else { ## inknown action push @{ $self->{out}->{errors} }, "unknown_action"; - $self->{logger}->log( - level => LOG_ERROR, - message => "Unknown action '$action'" - ); + $self->{logger}->error( "Unknown action '$action'"); } @@ -167,7 +153,6 @@ sub execute { ## Return HTML content sub respond { my ($self) = @_; - $self->{logger}->log(level => LOG_DEBUG, message => ""); ## Parse template my $tt2 = Template->new({ @@ -185,10 +170,7 @@ sub respond { unless ($tt2->process($template, $self->{out}, \*STDOUT)) { printf "Content-type: text/plain\n\n Error: %s", $tt2->error(); - $self->{logger}->log( - level => LOG_ERROR, - message => sprintf("Web parser error : %s", $tt2->error()) - ); + $self->{logger}->errorf("Web parser error : %s", $tt2->error()); } ## Ignore some type of errors @@ -218,7 +200,6 @@ sub respond { ## Return the list of known SPs first sub req_account_wizard { my ($self) = @_; - $self->{logger}->log(level => LOG_INFO, message => ""); my $federation_metadata = IdPAccountManager::SAMLMetadata->new(); @@ -230,10 +211,7 @@ sub req_account_wizard { }; if ($EVAL_ERROR) { push @{ $self->{out}->{errors} }, "internal"; - $self->{logger}->log( - level => LOG_ERROR, - message => "Failed to load federation metadata: $EVAL_ERROR" - ); + $self->{logger}->error("Failed to load federation metadata: $EVAL_ERROR"); return undef; } @@ -242,10 +220,7 @@ sub req_account_wizard { }; if ($EVAL_ERROR) { push @{ $self->{out}->{errors} }, "internal"; - $self->{logger}->log( - level => LOG_ERROR, - message => "Failed to parse federation metadata: $EVAL_ERROR" - ); + $self->{logger}->error("Failed to parse federation metadata: $EVAL_ERROR"); return undef; } @@ -258,12 +233,10 @@ sub req_account_wizard { ## Sample URL : https://dev-edugain.renater.fr/accountmanager?action=select_sp&sp_entityid=http%3A%2F%2Fsp.lat.csc.fi sub req_select_sp { my ($self) = @_; - $self->{logger}->log(level => LOG_INFO, message => ""); unless ($self->{in}->{sp_entityid}) { push @{ $self->{out}->{errors} }, "missing_sp_entityid"; - $self->{logger} - ->log(level => LOG_ERROR, message => "Missing parameter sp_entityid"); + $self->{logger}->error("Missing parameter sp_entityid"); return undef; } @@ -276,10 +249,7 @@ sub req_select_sp { }; if ($EVAL_ERROR) { push @{ $self->{out}->{errors} }, "internal"; - $self->{logger}->log( - level => LOG_ERROR, - message => "Failed to load federation metadata: $EVAL_ERROR" - ); + $self->{logger}->error("Failed to load federation metadata: $EVAL_ERROR"); return undef; } @@ -338,20 +308,14 @@ sub req_select_sp { ); unless (defined $service_provider) { push @{ $self->{out}->{errors} }, "internal"; - $self->{logger}->log( - level => LOG_ERROR, - message => "Failed to create serviceprovider object" - ); + $self->{logger}->error("Failed to create serviceprovider object"); return undef; } } unless ($service_provider->save()) { push @{ $self->{out}->{errors} }, "internal"; - $self->{logger}->log( - level => LOG_ERROR, - message => "Failed to save serviceprovider object" - ); + $self->{logger}->error("Failed to save serviceprovider object"); return undef; } @@ -367,21 +331,16 @@ sub req_select_sp { ## Sample call : dev-edugain.renater.fr/accountmanager?action=generate_token&style=nobanner&sp_entityid=https%3A%2F%2Fsourcesup.cru.fr%2Fshibboleth&email_address=support%40renater.fr sub req_generate_token { my ($self) = @_; - $self->{logger}->log(level => LOG_INFO, message => ""); unless ($self->{in}->{sp_entityid}) { push @{ $self->{out}->{errors} }, "missing_sp_entityid"; - $self->{logger} - ->log(level => LOG_ERROR, message => "Missing parameter sp_entityid"); + $self->{logger}->error("Missing parameter sp_entityid"); return undef; } unless ($self->{in}->{email_address}) { push @{ $self->{out}->{errors} }, "email_address"; - $self->{logger}->log( - level => LOG_ERROR, - message => "Missing parameter email_address" - ); + $self->{logger}->error("Missing parameter email_address"); return undef; } @@ -395,11 +354,7 @@ sub req_generate_token { # Try loading DB object first unless ($service_provider->load(speculative => 1)) { push @{ $self->{out}->{errors} }, "internal"; - $self->{logger}->log( - level => LOG_ERROR, - message => "Failed to load SP with entityid '%s'", - $self->{in}->{sp_entityid} - ); + $self->{logger}->errorf("Failed to load SP with entityid '%s'", $self->{in}->{sp_entityid}); return undef; } @@ -407,10 +362,8 @@ sub req_generate_token { unless ($service_provider->is_contact($self->{in}->{email_address})) { push @{ $self->{out}->{errors} }, "internal"; - $self->{logger}->log( - level => LOG_ERROR, - message => - "Requested a token for %s for an unautorized address '%s'", + $self->{logger}->errorf( + "Requested a token for %s for an unautorized address '%s'", $self->{in}->{sp_entityid}, $self->{in}->{email_address} ); @@ -424,10 +377,7 @@ sub req_generate_token { ); unless (defined $authentication_token) { push @{ $self->{out}->{errors} }, "internal"; - $self->{logger}->log( - level => LOG_ERROR, - message => "Failed to create authentication token" - ); + $self->{logger}->error("Failed to create authentication token"); return undef; } @@ -435,12 +385,9 @@ sub req_generate_token { if ($authentication_token->load(speculative => 1)) { unless ($authentication_token->delete()) { push @{ $self->{out}->{errors} }, "internal"; - $self->{logger}->log( - level => LOG_ERROR, - message => sprintf( - "Failed to delete previous authentication token with ID %s", - $authentication_token->get('id') - ) + $self->{logger}->errorf( + "Failed to delete previous authentication token with ID %s", + $authentication_token->get('id') ); return undef; } @@ -452,20 +399,14 @@ sub req_generate_token { ); unless (defined $authentication_token) { push @{ $self->{out}->{errors} }, "internal"; - $self->{logger}->log( - level => LOG_ERROR, - message => "Failed to create authentication token" - ); + $self->{logger}->error("Failed to create authentication token"); return undef; } } unless ($authentication_token->save()) { push @{ $self->{out}->{errors} }, "internal"; - $self->{logger}->log( - level => LOG_ERROR, - message => "Failed to save authentication token" - ); + $self->{logger}->error("Failed to save authentication token"); return undef; } @@ -484,9 +425,8 @@ sub req_generate_token { logger => $self->{logger} ); - $self->{logger}->log( - level => LOG_INFO, - message => "Token send to %s for sp_entityid=%s;token=%s", + $self->{logger}->infof( + "Token send to %s for sp_entityid=%s;token=%s", $self->{in}->{email_address}, $self->{in}->{sp_entityid}, $self->{out}->{authentication_token} @@ -500,23 +440,17 @@ sub req_generate_token { ## Sample call : dev-edugain.renater.fr/accountmanager?action=validate_token&style=nobanner&sp_entityid=https%3A%2F%2Fsourcesup.cru.fr%2Fshibboleth&authentication_token=c1cfecb51ea40d39a695 sub req_validate_token { my ($self) = @_; - $self->{logger}->log(level => LOG_INFO, message => ""); unless ($self->{in}->{sp_entityid}) { push @{ $self->{out}->{errors} }, "missing_sp_entityid"; - $self->{logger}->log( - level => LOG_ERROR, message => "Missing parameter sp_entityid" - ); + $self->{logger}->error("Missing parameter sp_entityid"); return undef; } unless ($self->{in}->{authentication_token}) { push @{ $self->{out}->{errors} }, "missing_authentication_token"; - $self->{logger}->log( - level => LOG_ERROR, - message => "Missing parameter authentication_token" - ); + $self->{logger}->error("Missing parameter authentication_token"); return undef; } @@ -526,10 +460,8 @@ sub req_validate_token { unless ($authentication_token->load()) { push @{ $self->{out}->{errors} }, "wrong_token"; - $self->{logger}->log( - level => LOG_ERROR, - message => - "Failed to validate authentication token %s for sp_entityid %s", + $self->{logger}->errorf( + "Failed to validate authentication token %s for sp_entityid %s", $self->{in}->{authentication_token}, $self->{in}->{sp_entityid} ); @@ -540,10 +472,8 @@ sub req_validate_token { $self->{in}->{sp_entityid}) { push @{ $self->{out}->{errors} }, "wrong_token_for_sp"; - $self->{logger}->log( - level => LOG_ERROR, - message => - "Authentication token %s cannot be used for SP with entityid %s", + $self->{logger}->errorf( + "Authentication token %s cannot be used for SP with entityid %s", $self->{in}->{authentication_token}, $self->{in}->{sp_entityid} ); @@ -552,9 +482,8 @@ sub req_validate_token { ## delete the token unless ($authentication_token->delete()) { - $self->{logger}->log( - level => LOG_ERROR, - message => "Failed to delete authentication token %s", + $self->{logger}->errorf( + "Failed to delete authentication token %s", $self->{in}->{authentication_token} ); } @@ -575,9 +504,8 @@ sub req_validate_token { unless (@test_accounts) { push @{ $self->{out}->{errors} }, "accounts_creation_failed"; - $self->{logger}->log( - level => LOG_ERROR, - message => "Failed to create test accounts for SP with entityid %s", + $self->{logger}->errorf( + "Failed to create test accounts for SP with entityid %s", $self->{in}->{sp_entityid} ); return undef; @@ -589,16 +517,14 @@ sub req_validate_token { $self->{configuration} )) { push @{ $self->{out}->{errors} }, "accounts_creation_failed"; - $self->{logger}->log( - level => LOG_ERROR, - message => "Failed to create simpleSAMLphp configuration file" + $self->{logger}->error( + "Failed to create simpleSAMLphp configuration file" ); return undef; } - $self->{logger}->log( - level => LOG_INFO, - message => "Token validated for sp_entityid=%s;token=%s", + $self->{logger}->infof( + "Token validated for sp_entityid=%s;token=%s", $self->{in}->{sp_entityid}, $self->{in}->{authentication_token} ); @@ -613,7 +539,6 @@ sub req_validate_token { ## Return the homepage of the service sub req_home { my ($self) = @_; - $self->{logger}->log(level => LOG_INFO, message => ""); return 1; } diff --git a/lib/Makefile.am b/lib/Makefile.am index e3d61b8..525a6da 100644 --- a/lib/Makefile.am +++ b/lib/Makefile.am @@ -10,7 +10,6 @@ nobase_modules_DATA = \ IdPAccountManager/Data/TestAccount/Manager.pm \ IdPAccountManager/DB.pm \ IdPAccountManager/DB/Object.pm \ - IdPAccountManager/Logger.pm \ IdPAccountManager/SAMLMetadata.pm \ IdPAccountManager/Tools.pm \ IdPAccountManager/WebRequest.pm diff --git a/t/logger.t b/t/logger.t deleted file mode 100755 index fab10a7..0000000 --- a/t/logger.t +++ /dev/null @@ -1,146 +0,0 @@ -#!/usr/bin/perl - -use strict; -use warnings; - -use English qw(-no_match_vars); -use Fcntl qw(:seek); -use File::stat; -use File::Temp; -use Test::More; -use Test::Exception; - -use IdPAccountManager::Logger; - -plan tests => 14; - -my $logger; - -throws_ok { - $logger = IdPAccountManager::Logger->new(); -} qr/^missing argument 'file'/, -'instanciation: no file argument'; - -throws_ok { - $logger = IdPAccountManager::Logger->new( - file => '/no/such/file' - ); -} qr/^missing argument 'verbosity'/, -'instanciation: no verbosity argument'; - -throws_ok { - $logger = IdPAccountManager::Logger->new( - file => '/no/such/file', - verbosity => LOG_DEBUG - ); -} qr/^invalid argument 'verbosity'/, -'instanciation: invalid verbosity argument'; - -throws_ok { - $logger = IdPAccountManager::Logger->new( - file => '/no/such/file', - verbosity => 'debug' - ); -} qr/^failed to open \/no\/such\/file/, -'instanciation: invalid file argument'; - -my $logfile = File::Temp->new(UNLINK => $ENV{TEST_DEBUG} ? 0 : 1, SUFFIX => '.log'); - -lives_ok { - $logger = IdPAccountManager::Logger->new( - file => $logfile->filename(), - verbosity => 'debug' - ); -} 'instanciation with debug level verbosity: ok'; - -is( - getFileOutput($logfile, \&logDebugMessage), - POSIX::strftime("%Y:%m:%d %H:%M:%S", localtime(time)) . - ' - (DEBUG) - NOIP - NOEMAIL - main::logDebugMessage() message', - 'debug message formating' -); - -is( - getFileOutput($logfile, \&logInfoMessage), - POSIX::strftime("%Y:%m:%d %H:%M:%S", localtime(time)) . - ' - (INFO) - NOIP - NOEMAIL - main::logInfoMessage() message', - 'info message formating' -); - -is( - getFileOutput($logfile, \&logNoticeMessage), - POSIX::strftime("%Y:%m:%d %H:%M:%S", localtime(time)) . - ' - (NOTICE) - NOIP - NOEMAIL - main::logNoticeMessage() message', - 'notice message formating' -); - - -is( - getFileOutput($logfile, \&logErrorMessage), - POSIX::strftime("%Y:%m:%d %H:%M:%S", localtime(time)) . - ' - (ERROR) - NOIP - NOEMAIL - main::getFileOutput#78 > main::logErrorMessage#120 message', - 'error message formating' -); - -lives_ok { - $logger = IdPAccountManager::Logger->new( - file => $logfile->filename(), - verbosity => 'error' - ); -} 'instanciation with error level verbosity: ok'; - -ok( - !defined(getFileOutput($logfile, \&logDebugMessage)), - 'no debug message' -); - -ok( - !defined(getFileOutput($logfile, \&logInfoMessage)), - 'no info message' -); - -ok( - !defined(getFileOutput($logfile, \&logNoticeMessage)), - 'no notice message' -); - - -is( - getFileOutput($logfile, \&logErrorMessage), - POSIX::strftime("%Y:%m:%d %H:%M:%S", localtime(time)) . - ' - (ERROR) - NOIP - NOEMAIL - main::getFileOutput#108 > main::logErrorMessage#120 message', - 'error message formating' -); - -sub getFileOutput { - my ($handle, $callback) = @_; - - my $stat = stat $handle; - - $callback->(); - - seek $handle, $stat->size(), SEEK_SET; - my $line = $handle->getline(); - - chomp $line if $line; - return $line; -} - -sub logDebugMessage { - $logger->log(level => LOG_DEBUG, message => 'message'); - $logger->{handle}->flush() -} - -sub logInfoMessage { - $logger->log(level => LOG_INFO, message => 'message'); - $logger->{handle}->flush() -} -sub logNoticeMessage { - $logger->log(level => LOG_NOTICE, message => 'message'); - $logger->{handle}->flush() -} - -sub logErrorMessage { - $logger->log(level => LOG_ERROR, message => 'message'); - $logger->{handle}->flush() -} -- GitLab