Skip to content
Snippets Groups Projects
Commit 625fb392 authored by Guillaume ROUSSE's avatar Guillaume ROUSSE
Browse files

kill custom logger code, use Log::Any instead

parent 896de06a
No related branches found
No related tags found
No related merge requests found
......@@ -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',
......
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;
......@@ -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;
}
......
......@@ -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;
}
......
......@@ -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
......
#!/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()
}
0% Loading or .
You are about to add 0 people to the discussion. Proceed with caution.
Please register or to comment