diff --git a/bin/account-manager-client.pl b/bin/account-manager-client.pl index 2c9173c3fa3dd8716bcefc80177faf41dce13c99..2c4aa8ab0031d3b03519179016781a6ed75459d2 100755 --- a/bin/account-manager-client.pl +++ b/bin/account-manager-client.pl @@ -19,6 +19,7 @@ use IdPAccountManager::TestAccount; use IdPAccountManager::SAMLMetadata; use IdPAccountManager::ServiceProvider; use IdPAccountManager::AuthenticationToken; +use IdPAccountManager::Logger; my %options; unless ( @@ -41,8 +42,15 @@ unless ( ); } + + if ($options{'add_test_account'}) { + my $logger = IdPAccountManager::Logger->new( + file => $Conf::global{'log_file'}, + verbosity => $Conf::global{'log_level'} + ); + unless ($options{'account_profile'}) { die "Missing account_profile option"; } @@ -56,14 +64,12 @@ if ($options{'add_test_account'}) { sp_entityid => $options{'sp_entityid'} ); unless (defined $test_account) { - IdPAccountManager::Tools::do_log('error', - "Failed to create test account"); + $logger->log(level => LOG_ERROR, message => "Failed to create test account"); exit -1; } unless ($test_account->save()) { - IdPAccountManager::Tools::do_log('error', - "Failed to create test account"); + $logger->log(level => LOG_ERROR, message => "Failed to create test account"); exit -1; } @@ -72,6 +78,11 @@ if ($options{'add_test_account'}) { } elsif ($options{'list_test_accounts'}) { + my $logger = IdPAccountManager::Logger->new( + file => $Conf::global{'log_file'}, + verbosity => $Conf::global{'log_level'} + ); + my %args; if ($options{'sp_entityid'}) { push @{ $args{'query'} }, 'sp_entityid' => $options{'sp_entityid'}; @@ -102,7 +113,12 @@ if ($options{'add_test_account'}) { ## Update simpleSamlPhp configuration file printf "Update simpleSamlPhp configuration file...\n"; - IdPAccountManager::Tools::update_ssp_authsources(); + unless(IdPAccountManager::Tools::update_ssp_authsources()) { + $logger->log( + level => LOG_ERROR, + message => "Failed to create simpleSAMLphp configuration file" + ); + } } } elsif ($options{'parse_federation_metadata'}) { @@ -137,6 +153,11 @@ if ($options{'add_test_account'}) { } elsif ($options{'add_service_provider'}) { + my $logger = IdPAccountManager::Logger->new( + file => $Conf::global{'log_file'}, + verbosity => $Conf::global{'log_level'} + ); + unless ($options{'sp_entityid'}) { die "Missing sp_entityid option"; } @@ -164,15 +185,13 @@ if ($options{'add_test_account'}) { displayname => $options{'displayname'} ); unless (defined $service_provider) { - IdPAccountManager::Tools::do_log('error', - "Failed to create service provider"); + $logger->log(level => LOG_ERROR, message => "Failed to create service provider"); exit -1; } } unless ($service_provider->save()) { - IdPAccountManager::Tools::do_log('error', - "Failed to create service provider"); + $logger->log(level => LOG_ERROR, message => "Failed to create service provider"); exit -1; } @@ -249,6 +268,11 @@ if ($options{'add_test_account'}) { } elsif ($options{'add_authentication_token'}) { + my $logger = IdPAccountManager::Logger->new( + file => $Conf::global{'log_file'}, + verbosity => $Conf::global{'log_level'} + ); + unless ($options{'email_address'}) { die "Missing email_address option"; } @@ -262,15 +286,14 @@ if ($options{'add_test_account'}) { 'sp_entityid' => $options{'sp_entityid'} ); unless (defined $authentication_token) { - IdPAccountManager::Tools::do_log('error', - "Failed to create token object"); + $logger->log(level => LOG_ERROR, message => "Failed to create token object"); exit -1; } ## First remove token if on exist for this email+SP if ($authentication_token->load()) { unless ($authentication_token->delete()) { - IdPAccountManager::Tools::do_log('error', "Failed to delete token"); + $logger->log(level => LOG_ERROR, message => "Failed to delete token"); exit -1; } @@ -279,14 +302,13 @@ if ($options{'add_test_account'}) { 'sp_entityid' => $options{'sp_entityid'} ); unless (defined $authentication_token) { - IdPAccountManager::Tools::do_log('error', - "Failed to create token object"); + $logger->log(level => LOG_ERROR, message => "Failed to create token object"); exit -1; } } unless ($authentication_token->save()) { - IdPAccountManager::Tools::do_log('error', "Failed to create token"); + $logger->log(level => LOG_ERROR, message => "Failed to create token"); exit -1; } @@ -302,6 +324,7 @@ if ($options{'add_test_account'}) { 'template' => 'templates/mail/notification_generic_error.tt2.eml', 'data' => {}, 'to' => $options{'email_address'} + 'logger' => $logger ) ) { diff --git a/conf/Conf.pm b/conf/Conf.pm index 27f31b8be33fccfbc274a83b9b3da4e699b6fcca..37021d28fd44b758a075a3bf2a71678ccc4bf54f 100644 --- a/conf/Conf.pm +++ b/conf/Conf.pm @@ -53,7 +53,7 @@ our %global = ( 'log_file' => '/opt/testidp/IdPAccountManager/log/manager.log', ## Log level : debug, info, trace, notice, error - 'log-level' => 'info', + 'log_level' => 'info', ## email address to contact admins 'admin_email' => 'john@my.fqdn', diff --git a/lib/IdPAccountManager/Logger.pm b/lib/IdPAccountManager/Logger.pm new file mode 100644 index 0000000000000000000000000000000000000000..80d5541e9008970ecbcb16f393c005837faa3774 --- /dev/null +++ b/lib/IdPAccountManager/Logger.pm @@ -0,0 +1,92 @@ +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/SAMLMetadata.pm b/lib/IdPAccountManager/SAMLMetadata.pm index dabec015d437f2a1d6b26945ef0b34c5f2d4e69e..2ae3782426b937e8b91e2b77cb99d44aec5776a0 100644 --- a/lib/IdPAccountManager/SAMLMetadata.pm +++ b/lib/IdPAccountManager/SAMLMetadata.pm @@ -8,6 +8,7 @@ use strict; use warnings; use IdPAccountManager::Tools; +use IdPAccountManager::Logger; use Conf; use XML::LibXML; @@ -18,7 +19,7 @@ sub new { my ($pkg) = shift; my %args = @_; - my $self = {}; + my $self = { logger => $args{logger} }; ## Bless SAMLMetadata object bless $self, $pkg; @@ -32,8 +33,10 @@ sub load { my %in = @_; unless ($in{'federation_metadata_file_path'}) { - IdPAccountManager::Tools::do_log('error', - "Missing parameter 'federation_metadata_file_path'"); + $self->{logger}->log( + level => LOG_ERROR, + message => "Missing parameter 'federation_metadata_file_path'" + ); return undef; } @@ -41,25 +44,32 @@ sub load { $in{'federation_metadata_file_path'}; unless (-r $self->{'federation_metadata_file_path'}) { - IdPAccountManager::Tools::do_log('error', - "Failed to read $in{'federation_metadata_file_path'} : $!"); + $self->{logger}->log( + level => LOG_ERROR, + message => + "Failed to read $in{'federation_metadata_file_path'} : $!" + ); return undef; } unless ($self->{'federation_metadata_as_xml'} = - _get_xml_object($in{'federation_metadata_file_path'})) + $self->_get_xml_object($in{'federation_metadata_file_path'})) { - IdPAccountManager::Tools::do_log('error', - "Failed to parse file $in{'metadata_file'} : $!"); + $self->{logger}->log( + level => LOG_ERROR, + message => "Failed to parse file $in{'metadata_file'} : $!" + ); return undef; } my $root = $self->{'federation_metadata_as_xml'}->documentElement(); unless ($root->nodeName() =~ /EntitiesDescriptor$/) { - IdPAccountManager::Tools::do_log( - 'error', -"Root element of file $in{'federation_metadata_file_path'} is of type '%s'; should be 'EntitiesDescriptor'", - $root->nodeName() + $self->{logger}->( + level => LOG_ERROR, + message => sprintf( + "Root element of file $in{'federation_metadata_file_path'} is of type '%s'; should be 'EntitiesDescriptor'", + $root->nodeName() + ) ); return undef; } @@ -82,10 +92,12 @@ sub parse { } $self->{'federation_metadata_as_hashref'} = - _parse_saml_metadata(%parser_args); + $self->_parse_saml_metadata(%parser_args); unless (defined $self->{'federation_metadata_as_hashref'}) { - IdPAccountManager::Tools::do_log('error', - "Failed to parse federation metadata"); + $self->{logger}->log( + level => LOG_ERROR, + message => "Failed to parse federation metadata" + ); return undef; } @@ -106,25 +118,32 @@ sub print { ## Internal function ## returns a Lib::XML représenting an XML file sub _get_xml_object { + my $self = shift; my $metadata_file = shift; - IdPAccountManager::Tools::do_log('debug', ""); + $self->{logger}->log(level => LOG_DEBUG, message => ""); unless (-f $metadata_file) { - IdPAccountManager::Tools::do_log('error', - "File $metadata_file not found: $!"); + $self->{logger}->log( + level => LOG_ERROR, + message => "File $metadata_file not found: $!" + ); return undef; } unless (open FH, $metadata_file) { - IdPAccountManager::Tools::do_log('error', - "Failed to open file $metadata_file: $!"); + $self->{logger}->log( + level => LOG_ERROR, + message => "Failed to open file $metadata_file: $!" + ); return undef; } my $parser; unless ($parser = XML::LibXML->new()) { - IdPAccountManager::Tools::do_log('error', - "Failed to initialize XML parser"); + $self->{logger}->log( + level => LOG_ERROR, + message => "Failed to initialize XML parser" + ); return undef; } @@ -134,14 +153,18 @@ sub _get_xml_object { ## Eval() prevents the parsing from killing the main process eval { $doc = $parser->parse_fh(\*FH) }; if ($@) { - IdPAccountManager::Tools::do_log('error', - "Failed to parse file $metadata_file : $@"); + $self->{logger}->log( + level => LOG_ERROR, + message => "Failed to parse file $metadata_file : $@" + ); return undef; } unless ($doc) { - IdPAccountManager::Tools::do_log('error', - "Failed to parse file $metadata_file : $!"); + $self->{logger}->log( + level => LOG_ERROR, + message => "Failed to parse file $metadata_file : $!" + ); return undef; } @@ -150,14 +173,15 @@ sub _get_xml_object { ## Parse a SAML federation metadata file sub _parse_saml_metadata { + my $self = shift; my %options = @_; - #IdPAccountManager::Tools::do_log('trace', "%s", join(',',%options)); + #$self->{logger}->log(level => LOG_TRACE, message => join(',',%options)); - #unless ($options{'filter_entity_type'}) { - #IdPAccountManager::Tools::do_log('error', "paramètre entity_type manquant"); - #return undef; - #} +#unless ($options{'filter_entity_type'}) { +#$self->{logger}->log(level => LOG_ERROR, message => "paramètre entity_type manquant"); +#return undef; +#} my $root = $options{'metadata_as_xml'}; @@ -178,13 +202,13 @@ sub _parse_saml_metadata { if ($options{'filter_entity_id'} && ($options{'filter_entity_id'} ne $extracted_data->{'entityid'})); -#IdPAccountManager::Tools::do_log('trace', "EntityId: %s - Cherche %s", $extracted_data->{'entityid'}, $options{'filter_entity_id'}); +#$self->{logger}->log(level => LOG_TRACE, message => "EntityId: %s - Cherche %s", $extracted_data->{'entityid'}, $options{'filter_entity_id'}); $extracted_data->{'xml_md'} = IdPAccountManager::Tools::escape_xml($EntityDescriptor->toString()); -#IdPAccountManager::Tools::do_log('trace', "EntityId: %s", $extracted_data->{'entityid'}); -#IdPAccountManager::Tools::do_log('trace', "Entity dump: %s", $EntityDescriptor->toString()); +#$self->{logger}->log(level => LOG_TRACE, message => "EntityId: %s", $extracted_data->{'entityid'}); +#$self->{logger}->log(level => LOG_TRACE, message => "Entity dump: %s", $EntityDescriptor->toString()); foreach my $child ($EntityDescriptor->childNodes()) { @@ -242,7 +266,16 @@ sub _parse_saml_metadata { ) }; -#IdPAccountManager::Tools::do_log('trace', "Endpoint: type:%s ; binding=%s ; location=%s ; index=%s ; isdefault=%s", 'AssertionConsumerService', $sso->getAttribute('Binding'), $sso->getAttribute('Location'), $sso->getAttribute('index'), $sso->getAttribute('isDefault')); + #$self->{logger}->log( + # level => LOG_TRACE, + # message => sprintf( + # "Endpoint: type:%s ; binding=%s ; location=%s ; index=%s ; isdefault=%s", 'AssertionConsumerService', + # $sso->getAttribute('Binding'), + # $sso->getAttribute('Location'), + # $sso->getAttribute('index'), + # $sso->getAttribute('isDefault') + # ) + #); } foreach my $requestedattribute ( @@ -268,7 +301,7 @@ sub _parse_saml_metadata { } elsif ($child->nodeName =~ /Extensions$/) { -#IdPAccountManager::Tools::do_log('trace', "Extensions for %s", $extracted_data->{'entityid'}); +#$self->{logger}->log(level => LOG_TRACE, message => "Extensions for %s", $extracted_data->{'entityid'}); foreach my $registrationinfo ( $child->getElementsByLocalName('RegistrationInfo')) { @@ -340,14 +373,18 @@ sub _parse_saml_metadata { foreach my $contact ($child->getElementsByLocalName('ContactPerson')) { - IdPAccountManager::Tools::do_log('trace', "ContactPerson"); + $self->{logger} + ->log(level => LOG_TRACE, message => "ContactPerson"); my %contact_details; $contact_details{'type'} = $contact->getAttribute('contactType'); foreach my $contact_child ($EntityDescriptor->childNodes()) { - IdPAccountManager::Tools::do_log('trace', "Contact : %s", - $contact_child->localName); + $self->{logger}->log( + level => LOG_TRACE, + message => "Contact : %s", + $contact_child->localName + ); $contact_details{ $contact_child->localName } = IdPAccountManager::Tools::encode_utf8( $contact_child->textContent()); @@ -371,7 +408,7 @@ sub _parse_saml_metadata { } ## Filter entities based on type -#IdPAccountManager::Tools::do_log('trace', "Entity type : %s", $extracted_data->{'type'}); +#$self->{logger}->log(level => LOG_TRACE, message => "Entity type : %s", $extracted_data->{'type'}); next if (defined $options{'filter_entity_type'} && ($options{'filter_entity_type'} ne $extracted_data->{'type'})); @@ -381,7 +418,7 @@ sub _parse_saml_metadata { if ($extracted_data->{'domain'}); $extracted_data->{'domain'} = $domains; - #IdPAccountManager::Tools::do_log('debug', "Scopes : %s", $domains); + #$self->{logger}->log(level => LOG_DEBUG, message => "Scopes : %s", $domains); push @extracted_array, $extracted_data; } diff --git a/lib/IdPAccountManager/Tools.pm b/lib/IdPAccountManager/Tools.pm index 61c054dcd0376d5561cc893b2288e1a0fe9f4468..e911d46eadd12d2e5e4b5aca1821c8166ff27f69 100644 --- a/lib/IdPAccountManager/Tools.pm +++ b/lib/IdPAccountManager/Tools.pm @@ -11,10 +11,6 @@ use Template::Stash; use Digest::SHA; use Encode; -use POSIX qw(strftime); - -my %log_levels = - ('debug' => 0, 'info' => 1, 'trace' => 1, 'notice' => 2, 'error' => 3); INIT { ## a TT2 virtual method to get a variable type @@ -110,9 +106,6 @@ sub update_ssp_authsources { #printf "Trace : in=%s, out=%s\n", $template_file, $output_file; unless ($tt2->process($template_file, \%args, $output_file)) { - IdPAccountManager::Tools::do_log('error', - "Failed to update valid-accounts.php: %s", - $tt2->error()); return undef; } @@ -149,42 +142,6 @@ sub dump_var { } } -sub do_log { - my $level = shift; - my $message = shift; - - unless ($log_levels{$level} < $log_levels{ $Conf::global{'log_level'} }) { - - ## Determine calling function and parameters - ## If in 'err' level, build a stack trace - my $caller_string; - if ($level eq '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] . '()'; - } - - $level = uc($level); - my $ip = $ENV{'REMOTE_HOST'} . '/' . $ENV{'REMOTE_ADDR'} || 'NOIP'; - my $date = POSIX::strftime("%Y:%m:%d %H:%M:%S", localtime(time)); - my $user = lc($ENV{'mail'}) || 'NOEMAIL'; - open LOG, ">>" . $Conf::global{'log_file'}; - printf LOG "$date - ($level) - $ip - $user - $caller_string $message\n", - @_; - close LOG; - } - return 1; -} - ## Send a mail notice ## Default is to send email to the manager admins, unless other recipients are specified ## mail_notice(IN) @@ -195,6 +152,7 @@ sub mail_notice { my %in = @_; my $tt2_file = $in{'template'}; my $mail_data = $in{'data'}; + my $logger = $in{'logger'}; $mail_data->{'conf'} ||= \%Conf::global; @@ -221,17 +179,21 @@ sub mail_notice { } if ($change_rcpt) { - do_log( - 'info', -"no_mail_outside option set; notification for %s rerouted to admins ; ", - $notice_email + $logger->log( + level => LOG_INFO, + message => sprintf( + "no_mail_outside option set; notification for %s rerouted to admins ; ", + $notice_email + ) ); $notice_email = $Conf::global{'admin_email'}; } } - do_log('trace', '(template=%s, to=%s)', - $in{'template'}, $mail_data->{'to'}); + $logger->log( + level => LOG_TRACE, + message => sprintf('(template=%s, to=%s)', $in{'template'}, $mail_data->{'to'}) + ); open SENDMAIL, "|/usr/sbin/sendmail -f " @@ -240,7 +202,10 @@ sub mail_notice { my $tt2 = Template->new(FILTERS => { qencode => [ \qencode, 0 ] }); unless ($tt2->process($tt2_file, $mail_data, \*SENDMAIL)) { - do_log('error', "Error TT2 : %s", $tt2->error()); + $logger->log( + level => LOG_ERROR, + message => sprintf("Error TT2 : %s", $tt2->error()) + ); } close SENDMAIL; } @@ -320,10 +285,6 @@ This module gathers a set of usefull subroutines. Dumps a complex perl data structure. $var is a reference to the variable to dump. $level should be set to 0 (subroutine called recursively). $fd is the file descriptor for the output (default is STDOUT). -=item C<do_log ($level, $message)> - -Write $message to the log file. $level sets the log level (debug, info, trace, notice, error). - =item C<encode_utf8 ($string)> Return a UTF8 encoded version of $string. diff --git a/lib/IdPAccountManager/WebRequest.pm b/lib/IdPAccountManager/WebRequest.pm index de1c370f94904d88c8da31eaeabcda76f149211e..02c96b3b5c06dbd0051942b4f2151fb01f407b81 100755 --- a/lib/IdPAccountManager/WebRequest.pm +++ b/lib/IdPAccountManager/WebRequest.pm @@ -1,10 +1,20 @@ package IdPAccountManager::WebRequest; +use IdPAccountManager::Logger; + ## New web request sub new { my $pkg = shift; my $request = {}; - IdPAccountManager::Tools::do_log('info', ""); + + $request->{logger} = IdPAccountManager::Logger->new( + file => $Conf::global{'log_file'}, + verbosity => $Conf::global{'log_level'} + ); + $request->{logger}->log( + level => LOG_INFO, + message => '' + ); my $http_query = new CGI; @@ -32,7 +42,7 @@ sub new { ## Clean input vars foreach my $key (keys %{ $request->{'param_in'} }) { -#IdPAccountManager::Tools::do_log('trace', "PARAM_ENTREE: %s=%s", $key, $request->{'param_in'}{$key}); +#$self->{logger}->log(level => LOG_TRACE, message => "PARAM_ENTREE: %s=%s", $key, $request->{'param_in'}{$key}); ## Removing all ^M (0D) $request->{'param_in'}{$key} =~ s/\r//g; @@ -48,7 +58,7 @@ sub new { ## Usefull to have sementicless values in submit forms if ($key =~ /^action_(\w+)$/) { - #IdPAccountManager::Tools::do_log('trace', "ACTION $key"); + #$self->{logger}->log(level => LOG_TRACE, message => "ACTION $key"); $request->{'param_in'}{'action'} = $1; } } @@ -58,7 +68,7 @@ sub new { $request->{'action'} = $request->{'param_in'}{'action'}; } else { ## Default action - IdPAccountManager::Tools::do_log('info', "Default action"); + $request->{logger}->log(level => LOG_INFO, message => 'Default action'); $request->{'action'} = 'home'; } @@ -70,7 +80,7 @@ sub new { ## Execute a web request sub execute { my $self = shift; - IdPAccountManager::Tools::do_log('debug', ""); + $self->{logger}->log(level => LOG_DEBUG, message => ""); my $status; @@ -82,8 +92,10 @@ sub execute { { unless ($self->{'param_in'}{$key} =~ /^$format{$key}$/) { push @{ $self->{'param_out'}{'errors'} }, "format_$key"; - IdPAccountManager::Tools::do_log('error', - "Incorrect parameter format : $key"); + $self->{logger}->log( + level => LOG_ERROR, + message => "Incorrect parameter format : $key" + ); return undef; } } @@ -102,8 +114,11 @@ sub execute { } else { ## Inknown action push @{ $self->{'param_out'}{'errors'} }, "unknown_action"; - IdPAccountManager::Tools::do_log('error', "Unknown action '%s'", - $self->{'action'}); + $self->{logger}->log( + level => LOG_ERROR, + message => "Unknown action '%s'", + $self->{'action'} + ); } @@ -117,7 +132,7 @@ sub execute { ## Return HTML content sub respond { my $self = shift; - IdPAccountManager::Tools::do_log('debug', ""); + $self->{logger}->log(level => LOG_DEBUG, message => ""); ## Dump output data #open TMP, ">/tmp/account_registry.out"; IdPAccountManager::Tools::dump_var($self->{'param_out'}, 0, \*TMP); close TMP; @@ -128,7 +143,7 @@ sub respond { ## Automatic pass object entries to the output hash foreach my $key (keys %{$self}) { - #IdPAccountManager::Tools::do_log('trace', "Passing $key"); + #$self->{logger}->log(level => LOG_TRACE, message => "Passing $key"); $self->{'param_out'}{$key} ||= $self->{$key} unless ($key eq 'param_out'); } @@ -136,7 +151,7 @@ sub respond { ## An action may redirect to an external URL if ($self->{'url_redirection'}) { -#IdPAccountManager::Tools::do_log('trace', "URL Redirect : $self->{'url_redirection'}"); +#$self->{logger}->log(level => LOG_TRACE, message => "URL Redirect : $self->{'url_redirection'}"); printf "Location: %s\n\n", $self->{'url_redirection'}; } else { @@ -174,8 +189,10 @@ sub respond { unless ($tt2->process($template, $self->{'param_out'}, \*STDOUT)) { printf "Content-type: text/plain\n\n Error: %s", $tt2->error(); - IdPAccountManager::Tools::do_log('error', "Web parser error : %s", - $tt2->error()); + $self->{logger}->log( + level => LOG_ERROR, + message => sprintf("Web parser error : %s", $tt2->error()) + ); } } @@ -192,7 +209,8 @@ sub respond { $self->{'param_out'}{'subject'} = 'Error notification - web interface'; IdPAccountManager::Tools::mail_notice( 'template' => 'templates/mail/notification_generic_error.tt2.eml', - 'data' => $self->{'param_out'} + 'data' => $self->{'param_out'}, + 'logger' => $self->{'logger'} ); } } @@ -200,9 +218,12 @@ sub respond { ## Return the list of known SPs first sub req_account_wizard { my $self = shift; - IdPAccountManager::Tools::do_log('info', ""); + $self->{logger}->log(level => LOG_INFO, message => ""); + + my $federation_metadata = new IdPAccountManager::SAMLMetadata( + logger => $self->{logger} + ); - my $federation_metadata = new IdPAccountManager::SAMLMetadata; unless ( $federation_metadata->load( federation_metadata_file_path => @@ -211,15 +232,19 @@ sub req_account_wizard { ) { push @{ $self->{'param_out'}{'errors'} }, "internal"; - IdPAccountManager::Tools::do_log('error', - "Failed to load federation metadata : $!"); + $self->{logger}->log( + level => LOG_ERROR, + message => "Failed to load federation metadata : $!" + ); return undef; } unless ($federation_metadata->parse()) { push @{ $self->{'param_out'}{'errors'} }, "internal"; - IdPAccountManager::Tools::do_log('error', - "Failed to parse federation metadata : $!"); + $self->{logger}->log( + level => LOG_ERROR, + message => "Failed to parse federation metadata : $!" + ); return undef; } @@ -233,16 +258,19 @@ 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 = shift; - IdPAccountManager::Tools::do_log('info', ""); + $self->{logger}->log(level => LOG_INFO, message => ""); unless ($self->{'param_in'}{'sp_entityid'}) { push @{ $self->{'param_out'}{'errors'} }, "missing_sp_entityid"; - IdPAccountManager::Tools::do_log('error', - "Missing parameter sp_entityid"); + $self->{logger} + ->log(level => LOG_ERROR, message => "Missing parameter sp_entityid"); return undef; } - my $federation_metadata = new IdPAccountManager::SAMLMetadata; + my $federation_metadata = new IdPAccountManager::SAMLMetadata( + logger => $self->{logger} + ); + unless ( $federation_metadata->load( federation_metadata_file_path => @@ -251,8 +279,10 @@ sub req_select_sp { ) { push @{ $self->{'param_out'}{'errors'} }, "internal"; - IdPAccountManager::Tools::do_log('error', - "Failed to load federation metadata : $!"); + $self->{logger}->log( + level => LOG_ERROR, + message => "Failed to load federation metadata : $!" + ); return undef; } @@ -263,8 +293,10 @@ sub req_select_sp { ) { push @{ $self->{'param_out'}{'errors'} }, "internal"; - IdPAccountManager::Tools::do_log('error', - "Failed to parse federation metadata : $!"); + $self->{logger}->log( + level => LOG_ERROR, + message => "Failed to parse federation metadata : $!" + ); return undef; } @@ -294,7 +326,6 @@ sub req_select_sp { foreach my $lang (keys %{ $sp_metadata_as_hashref->{'display_name'} }) { -#IdPAccountManager::Tools::do_log('TRACE', "Display name(%s): %s", $lang, $sp_metadata_as_hashref->{'display_name'}{$lang}); $display_name = $sp_metadata_as_hashref->{'display_name'}{$lang}; last; @@ -316,16 +347,20 @@ sub req_select_sp { ); unless (defined $service_provider) { push @{ $self->{'param_out'}{'errors'} }, "internal"; - IdPAccountManager::Tools::do_log('error', - "Failed to create serviceprovider object"); + $self->{logger}->log( + level => LOG_ERROR, + message => "Failed to create serviceprovider object" + ); return undef; } } unless ($service_provider->save()) { push @{ $self->{'param_out'}{'errors'} }, "internal"; - IdPAccountManager::Tools::do_log('error', - "Failed to save serviceprovider object"); + $self->{logger}->log( + level => LOG_ERROR, + message => "Failed to save serviceprovider object" + ); return undef; } @@ -340,19 +375,21 @@ 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 = shift; - IdPAccountManager::Tools::do_log('info', ""); + $self->{logger}->log(level => LOG_INFO, message => ""); unless ($self->{'param_in'}{'sp_entityid'}) { push @{ $self->{'param_out'}{'errors'} }, "missing_sp_entityid"; - IdPAccountManager::Tools::do_log('error', - "Missing parameter sp_entityid"); + $self->{logger} + ->log(level => LOG_ERROR, message => "Missing parameter sp_entityid"); return undef; } unless ($self->{'param_in'}{'email_address'}) { push @{ $self->{'param_out'}{'errors'} }, "email_address"; - IdPAccountManager::Tools::do_log('error', - "Missing parameter email_address"); + $self->{logger}->log( + level => LOG_ERROR, + message => "Missing parameter email_address" + ); return undef; } @@ -363,9 +400,9 @@ sub req_generate_token { # Try loading DB object first unless ($service_provider->load(speculative => 1)) { push @{ $self->{'param_out'}{'errors'} }, "internal"; - IdPAccountManager::Tools::do_log( - 'error', - "Failed to load SP with entityid '%s'", + $self->{logger}->log( + level => LOG_ERROR, + message => "Failed to load SP with entityid '%s'", $self->{'param_in'}{'sp_entityid'} ); return undef; @@ -375,9 +412,10 @@ sub req_generate_token { unless ($service_provider->is_contact($self->{'param_in'}{'email_address'})) { push @{ $self->{'param_out'}{'errors'} }, "internal"; - IdPAccountManager::Tools::do_log( - 'error', - "Requested a token for %s for an unautorized address '%s'", + $self->{logger}->log( + level => LOG_ERROR, + message => + "Requested a token for %s for an unautorized address '%s'", $self->{'param_in'}{'sp_entityid'}, $self->{'param_in'}{'email_address'} ); @@ -390,8 +428,10 @@ sub req_generate_token { ); unless (defined $authentication_token) { push @{ $self->{'param_out'}{'errors'} }, "internal"; - IdPAccountManager::Tools::do_log('error', - "Failed to create authentication token"); + $self->{logger}->log( + level => LOG_ERROR, + message => "Failed to create authentication token" + ); return undef; } @@ -399,10 +439,12 @@ sub req_generate_token { if ($authentication_token->load()) { unless ($authentication_token->delete()) { push @{ $self->{'param_out'}{'errors'} }, "internal"; - IdPAccountManager::Tools::do_log( - 'error', - "Failed to delete previous authentication token with ID %s", - $authentication_token->get('id') + $self->{logger}->log( + level => LOG_ERROR, + message => sprintf( + "Failed to delete previous authentication token with ID %s", + $authentication_token->get('id') + ) ); return undef; } @@ -413,16 +455,20 @@ sub req_generate_token { ); unless (defined $authentication_token) { push @{ $self->{'param_out'}{'errors'} }, "internal"; - IdPAccountManager::Tools::do_log('error', - "Failed to create authentication token"); + $self->{logger}->log( + level => LOG_ERROR, + message => "Failed to create authentication token" + ); return undef; } } unless ($authentication_token->save()) { push @{ $self->{'param_out'}{'errors'} }, "internal"; - IdPAccountManager::Tools::do_log('error', - "Failed to save authentication token"); + $self->{logger}->log( + level => LOG_ERROR, + message => "Failed to save authentication token" + ); return undef; } @@ -437,12 +483,13 @@ sub req_generate_token { IdPAccountManager::Tools::mail_notice( 'template' => 'templates/mail/send_authentication_token.tt2.eml', 'to' => $self->{'param_in'}{'email_address'}, - 'data' => $self->{'param_out'} + 'data' => $self->{'param_out'}, + 'logger' => $self->{'logger'} ); - IdPAccountManager::Tools::do_log( - 'info', - "Token send to %s for sp_entityid=%s;token=%s", + $self->{logger}->log( + level => LOG_INFO, + message => "Token send to %s for sp_entityid=%s;token=%s", $self->{'param_in'}{'email_address'}, $self->{'param_in'}{'sp_entityid'}, $self->{'param_out'}{'authentication_token'} @@ -456,20 +503,22 @@ 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 = shift; - IdPAccountManager::Tools::do_log('info', ""); + $self->{logger}->log(level => LOG_INFO, message => ""); unless ($self->{'param_in'}{'sp_entityid'}) { push @{ $self->{'param_out'}{'errors'} }, "missing_sp_entityid"; - IdPAccountManager::Tools::do_log('error', - "Missing parameter sp_entityid"); + $self->{logger} + ->log(level => LOG_ERROR, message => "Missing parameter sp_entityid"); return undef; } unless ($self->{'param_in'}{'authentication_token'}) { push @{ $self->{'param_out'}{'errors'} }, "missing_authentication_token"; - IdPAccountManager::Tools::do_log('error', - "Missing parameter authentication_token"); + $self->{logger}->log( + level => LOG_ERROR, + message => "Missing parameter authentication_token" + ); return undef; } @@ -478,9 +527,10 @@ sub req_validate_token { unless ($authentication_token->load()) { push @{ $self->{'param_out'}{'errors'} }, "wrong_token"; - IdPAccountManager::Tools::do_log( - 'error', - "Failed to validate authentication token %s for sp_entityid %s", + $self->{logger}->log( + level => LOG_ERROR, + message => + "Failed to validate authentication token %s for sp_entityid %s", $self->{'param_in'}{'authentication_token'}, $self->{'param_in'}{'sp_entityid'} ); @@ -491,9 +541,10 @@ sub req_validate_token { $self->{'param_in'}{'sp_entityid'}) { push @{ $self->{'param_out'}{'errors'} }, "wrong_token_for_sp"; - IdPAccountManager::Tools::do_log( - 'error', - "Authentication token %s cannot be used for SP with entityid %s", + $self->{logger}->log( + level => LOG_ERROR, + message => + "Authentication token %s cannot be used for SP with entityid %s", $self->{'param_in'}{'authentication_token'}, $self->{'param_in'}{'sp_entityid'} ); @@ -502,9 +553,9 @@ sub req_validate_token { ## delete the token unless ($authentication_token->delete()) { - IdPAccountManager::Tools::do_log( - 'error', - "Failed to delete authentication token %s", + $self->{logger}->log( + level => LOG_ERROR, + message => "Failed to delete authentication token %s", $self->{'param_in'}{'authentication_token'} ); } @@ -516,25 +567,27 @@ sub req_validate_token { unless (@test_accounts) { push @{ $self->{'param_out'}{'errors'} }, "accounts_creation_failed"; - IdPAccountManager::Tools::do_log( - 'error', - "Failed to create test accounts for SP with entityid %s", + $self->{logger}->log( + level => LOG_ERROR, + message => "Failed to create test accounts for SP with entityid %s", $self->{'param_in'}{'sp_entityid'} ); return undef; } ## Update simpleSAMLphp configuration to enable test accounts - unless (IdPAccountManager::Tools::update_ssp_authsources()) { + unless (IdPAccountManager::Tools::update_ssp_authsources() { push @{ $self->{'param_out'}{'errors'} }, "accounts_creation_failed"; - IdPAccountManager::Tools::do_log('error', - "Failed to create simpleSAMLphp configuration file"); + $self->{logger}->log( + level => LOG_ERROR, + message => "Failed to create simpleSAMLphp configuration file" + ); return undef; } - IdPAccountManager::Tools::do_log( - 'info', - "Token validated for sp_entityid=%s;token=%s", + $self->{logger}->log( + level => LOG_INFO, + message => "Token validated for sp_entityid=%s;token=%s", $self->{'param_in'}{'sp_entityid'}, $self->{'param_in'}{'authentication_token'} ); @@ -548,7 +601,7 @@ sub req_validate_token { ## Return the homepage of the service sub req_home { my $self = shift; - IdPAccountManager::Tools::do_log('info', ""); + $self->{logger}->log(level => LOG_INFO, message => ""); return 1; } diff --git a/t/logger.t b/t/logger.t new file mode 100755 index 0000000000000000000000000000000000000000..fab10a7c3c905131a7b6f0cfbaeb34d0ef843413 --- /dev/null +++ b/t/logger.t @@ -0,0 +1,146 @@ +#!/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() +}