Commit d1dd1a94 authored by Benjamin Rokseth's avatar Benjamin Rokseth
Browse files

koha: move warns to proper logging Log4Perl

And remove some
parent 7ac325c4
......@@ -38,6 +38,9 @@ use C4::Stats;
use C4::RotatingCollections;
use C4::Circulation;
use C4::Context;
use Log::Log4perl ();
use Log::Log4perl::Level ();
use parent qw(Core::Main);
=head
......@@ -54,15 +57,15 @@ use parent qw(Core::Main);
=cut
sub new {
my ($class, $args) = @_;
Log::Log4perl->initialized() or Log::Log4perl->easy_init({ level => $ENV{LOG_LEVEL} // "WARN", layout => '%d{ISO8601} %-5p %m%n'});
($args->{item} and $args->{library}) or Core::Exception::Circulation::ArgumentError->throw("Missing item or library");
warn "Called Core::Circulation\n";
my $self = $class->SUPER::new();
$self = { %$self, # Inherent anything from parent
error => undef, # Error return
item => $args->{item}, # Mandatory
library => $args->{library}, # Mandatory
patron => $args->{patron}, # Mandatory for checkouts
debug => $args->{debug},
logger => Log::Log4perl->get_logger(),
};
$self->{library} or Core::Exception::Circulation::ArgumentError->throw("Missing library");
......@@ -82,7 +85,8 @@ sub new {
# Dummy override for testing
sub testOverride {
print "TEST: Core::Circulation called without overrides";
my ($self) = @_;
$self->{logger}->debug("Core::Circulation called without overrides");
}
=head
......@@ -92,7 +96,7 @@ sub testOverride {
=cut
sub Checkin {
my ($self, $returnDate) = @_;
$self->{debug} and warn "Checking in item " . $self->{item}->itemnumber . "\n";
$self->{logger}->debug("Checking in item " . $self->{item}->itemnumber . "\n");
my $t0 = Time::HiRes::time();
$returnDate ||= _today();
......@@ -188,6 +192,7 @@ sub Checkin {
my $deleted = $self->{checkout}->delete();
if ($deleted != 1) {
$self->{error} = Core::Exception::Circulation::Checkin::Failed->new();
$self->{logger}->error($self->{error});
$self->{messages}->{WasReturned} = 0;
$self->{messages}->{DataCorrupted} = 1;
} else {
......@@ -248,7 +253,7 @@ sub Checkin {
})->store;
my $dt = Time::HiRes::time() - $t0;
$self->{debug} and printf STDERR "[%s] Checkin called : %s - elapsed %.3fs\n", ref $self, scalar(gmtime()), $dt;
$self->{logger}->debug(sprintf "[%s] Checkin called : %s - elapsed %.3fs\n", ref $self, scalar(gmtime()), $dt);
return $self;
}
......@@ -266,7 +271,7 @@ sub Checkout {
}
my $t0 = Time::HiRes::time();
$self->{debug} and warn "Checking out item " . $self->{item}->barcode . " for patron " . $self->{patron}->borrowernumber . "\n";
$self->{logger}->debug("Checking out item " . $self->{item}->barcode . " for patron " . $self->{patron}->borrowernumber . "\n");
$issueDate ||= _today();
$issueDate = _ymd2dt($issueDate);
......@@ -310,8 +315,8 @@ sub Checkout {
$hold->SetFound();
$hold->Delete() # This moves it to old_reserves Merge tables - PLEASE!
} catch {
warn $_;
$self->{error} = Core::Exception::Circulation::Checkout->new();
$self->{logger}->error($_);
};
} else {
# TODO: Checkout should be aborted here?
......@@ -378,7 +383,7 @@ sub Checkout {
$self->removeOverdueDebarments($self->{patron});
my $dt = Time::HiRes::time() - $t0;
$self->{debug} and printf STDERR "[%s] Checkout called : %s - elapsed %.3fs\n", ref $self, scalar(gmtime()), $dt;
$self->{logger}->debug(sprintf "[%s] Checkout called : %s - elapsed %.3fs\n", ref $self, scalar(gmtime()), $dt);
return $self;
}
......@@ -386,11 +391,12 @@ sub Checkout {
sub Renew {
my ($self, $dateDue, $lastRenewedDate, $override) = @_; # Probably can skip most of these
$self->{patron} and $self->{library} or Core::Exception::Circulation::ArgumentError->throw();
$self->{debug} and warn "Renewing item " . $self->{item}->itemnumber . " for patron " . $self->{patron}->borrowernumber . "\n";
$self->{logger}->debug("Renewing item " . $self->{item}->itemnumber . " for patron " . $self->{patron}->borrowernumber . "\n");
my $t0 = Time::HiRes::time();
if ( !$self->{checkout}) {
$self->{error} = Core::Exception::Circulation::Checkout::NotFound->new();
$self->{logger}->error("Trying to renew a non checked out item: " . $self->{item}->itemnumber);
return $self;
}
$lastRenewedDate ||= _today();
......@@ -412,6 +418,7 @@ sub Renew {
# based on the value of the RenewalPeriodBase syspref.
if ( defined $dateDue and ref $dateDue ne "DateTime" ) {
$self->{error} = Core::Exception::Circulation::Renew::InvalidDate->new();
$self->{logger}->error($self->{error});
return $self;
}
if (not $dateDue) {
......@@ -448,7 +455,7 @@ sub Renew {
ccode => $self->{item}->ccode,
});
my $dt = Time::HiRes::time() - $t0;
$self->{debug} and printf STDERR "[%s] Renew called : %s - elapsed %.3fs\n", ref $self, scalar(gmtime()), $dt;
$self->{logger}->debug(sprintf "[%s] Renew called : %s - elapsed %.3fs\n", ref $self, scalar(gmtime()), $dt);
return $self;
}
......@@ -485,7 +492,7 @@ sub getCircRule {
itemtype => $self->{item}->itype,
branchcode => $branch,
});
$self->{debug} and printf STDERR "[%s] getCircRule : %s - elapsed %.3fs\n", ref $self, scalar(gmtime()), Time::HiRes::time() - $t0;
$self->{logger}->debug(sprintf "[%s] getCircRule : %s - elapsed %.3fs\n", ref $self, scalar(gmtime()), Time::HiRes::time() - $t0);
return $circ_rule;
}
......@@ -581,7 +588,7 @@ sub fixOverduesOnReturn {
}
)->next();
$accountline and $accountline->accounttype("F")->store;
$self->{debug} and printf STDERR "[%s] fixOverduesOnReturn called : %s - elapsed %.3fs\n", ref $self, scalar(gmtime()), Time::HiRes::time() - $t0;
$self->{logger}->debug(sprintf "[%s] fixOverduesOnReturn called : %s - elapsed %.3fs\n", ref $self, scalar(gmtime()), Time::HiRes::time() - $t0);
return $self;
}
......@@ -800,7 +807,7 @@ sub canItemBeIssued {
}
}
}
$self->{debug} and printf STDERR "[%s] canItemBeIssued called : %s - elapsed %.3fs\n", ref $self, scalar(gmtime()), Time::HiRes::time() - $t0;
$self->{logger}->debug(sprintf "[%s] canItemBeIssued called : %s - elapsed %.3fs\n", ref $self, scalar(gmtime()), Time::HiRes::time() - $t0);
return ( $issuingimpossible, $needsconfirmation, $alerts, $messages );
}
......@@ -878,7 +885,7 @@ sub canItemBeRenewed {
return $self;
}
}
$self->{debug} and printf STDERR "[%s] canItemBeRenewed called : %s - elapsed %.3fs\n", ref $self, scalar(gmtime()), Time::HiRes::time() - $t0;
$self->{logger}->debug(sprintf "[%s] canItemBeRenewed called : %s - elapsed %.3fs\n", ref $self, scalar(gmtime()), Time::HiRes::time() - $t0);
return $self;
}
......@@ -971,7 +978,7 @@ sub calcDateDue {
my $t0 = Time::HiRes::time();
$isRenewal ||= 0;
if ( defined $startDate && ref $startDate ne "DateTime" ) {
warn "Invalid date passed to calcDateDue: $startDate";
$self->{logger}->error("Invalid date passed to calcDateDue: $startDate");
return undef;
}
my $circ_rule = $self->getCircRule();
......@@ -1029,7 +1036,7 @@ sub calcDateDue {
}
}
}
$self->{debug} and printf STDERR "[%s] calcDateDue called : %s - elapsed %.3fs\n", ref $self, scalar(gmtime()), Time::HiRes::time() - $t0;
$self->{logger}->debug(sprintf "[%s] calcDateDue called : %s - elapsed %.3fs\n", ref $self, scalar(gmtime()), Time::HiRes::time() - $t0);
return $dateDue;
}
......@@ -1078,7 +1085,7 @@ sub getPendingHold {
$hold = Deichman::Patron::Reserve->new()->Get($bh->{reserve_id});
}
} catch {
warn $_;
$self->{logger}->error($_);
};
# my $itemholds = $self->{item}->current_holds;
# my $biblioholds = Koha::Holds->search({biblionumber => $self->{item}->biblionumber, found => undef, suspend => 0}, { order_by => { -asc => "priority" }});
......@@ -1137,7 +1144,6 @@ sub _today {
sub sendCirculationAlert {
my ($self, $action) = @_;
$action or return;
warn "SENDING CIRCULATION ALERT";
$self->{deichPatron} or return;
try {
$self->{deichPatron}->LoadMessagePreferences();
......@@ -1165,7 +1171,7 @@ sub sendCirculationAlert {
$self->{deichPatron}->Deichman::Patron::MessageQueue::AddToMsgQueue($msg);
}
} catch {
warn $_;
$self->{logger}->error($_);
};
return;
}
......
......@@ -18,11 +18,13 @@ use parent "Core::Deichman::Circulation";
# OVERRIDES
sub testOverride {
warn "TEST: Core::Circulation overridden from Core::Deichman::Circulation::SIP\n";
my ( $self ) = @_;
$self->{logger}->debug("Core::Circulation overridden from Core::Deichman::Circulation::SIP");
}
sub getIssuingCharges {
warn "Core::Deichman::Circulation::SIP OVERRIDE getIssuingCharges";
my ( $self ) = @_;
$self->{logger}->debug("Override: Core::Deichman::Circulation::SIP::getIssuingCharges");
return 0, undef; # (fee, itemtype)
}
......
......@@ -43,7 +43,6 @@ sub new {
# Top level Auth method
sub Auth {
my ($self) = @_;
warn "AUTH CALLED";
my $session = $self->{session};
my $req = $self->{req};
......@@ -58,10 +57,10 @@ sub Auth {
# validate session
my $auth = $session->get("auth");
if ($auth) {
warn "GOT AUTHENTICATED SESSION";
$self->{logger}->debug("Got authenticated session: " . $auth->{user}->{userid});
return;
} else {
warn "NO AUTH SESSION - TRYING TO CREATE ONE";
$self->{logger}->debug("Session not authenticated, creating new");
# Run all auth methods
$auth = $self->checkAuthMethods();
$auth or Deichman::Exception::Auth::InvalidSession->throw();
......@@ -75,7 +74,8 @@ sub Auth {
$session->put(branch => $lib->{branchcode});
$session->put(branchname => $lib->{branchname});
} catch {
warn $_->description;
$self->{logger}->warn("Failed setting session branch");
$self->{logger}->warn($_->description;);
$session->put(branch => "NO_LIBRARY_SET");
$session->put(branchname => "NO_LIBRARY_SET");
};
......@@ -99,7 +99,7 @@ sub Auth {
sub LogOut {
my ($self) = @_;
warn "LOGOUT CALLED";
$self->{logger}->debug("Deichman::Auth->LogOut Logging out of session");
$self->{session}->clear();
return $self;
}
......@@ -117,10 +117,9 @@ sub checkAuthMethods {
Deichman::Auth::CAS
/) {
try {
warn $class;
$auth = $class->new()->DoAuth($session, $req);
} catch {
warn $_->description;
$self->{logger}->info("Session auth failed: ". warn $_->description);
};
$auth->{auth} and return $auth->{auth};
}
......@@ -159,7 +158,6 @@ sub getAllPermissions {
# this is where CGI scripts ask for permissions
sub templateAndPermissions {
my ($self, $in) = @_;
warn "TEMPLATE_AND_PERMISSIONS";
my $name = $in->{template_name} or Deichman::Exception::Auth::MissingTemplate->throw();
$name =~ m{^[a-zA-Z0-9_\-\/]+.tt$} or Deichman::Exception::Auth::InvalidTemplate->throw($name);
......@@ -204,7 +202,7 @@ sub setTemplatePermissions {
my $id = $self->{session}->get("id");
if ($self->{session}->get("admin")) {
# Admin user login should be removed!
warn "TEMPLATE CALLED WITH ADMINUSER - BETTER REMOVE THIS";
$self->{logger}->info("Template called with adminuser - better remove this");
$auth->{permissions} = { superlibrarian => 1 };
$template->param(loggedinusername => $id);
$template->param(adminWarning => 1);
......
......@@ -19,7 +19,7 @@ sub new {
sub DoAuth {
my ($self, $session, $req) = @_;
warn "LDAP AUTH CALLED";
$self->{logger}->debug("LDAP auth called");
true or return; # Replace with some config setting to activate
my $userid = $req->param("userid") or Deichman::Exception::Auth::ArgumentError->throw();
my $password = $req->param("password") or Deichman::Exception::Auth::ArgumentError->throw();
......@@ -41,7 +41,7 @@ sub DoAuth {
# auth magic here
$ldap->unbind;
if ($ldapAuth->{resultCode} == 0) {
warn "Authenticated!";
$self->{logger}->info("LDAP session authenticated");
$self->{auth}->{user} = $self->userToKohaPatronAttributes();
$self->{auth}->{permissions} = $self->processKohaPermissions();
my $kohaPatron = $self->syncToKoha();
......@@ -54,7 +54,6 @@ sub DoAuth {
sub getAuthenticationObject {
my ($self) = @_;
warn "GETAUTHENTICATIONOBJECT LDAP";
return $self->{auth};
};
......@@ -94,17 +93,17 @@ sub updateSessionAuthFromKohaPatron {
sub syncToKoha {
my ($self) = @_;
warn "SYNCING USER TO KOHA";
$self->{logger}->info("LDAP syncing user to koha: " . $self->{auth}->{user}->{borrowernumber});
my $patron = $self->{auth}->{user};
my $kohaPatron;
try {
$kohaPatron = Deichman::Patron->new()->GetByUserId($patron->{email});
warn "UPDATING PATRON FROM LDAP";
$self->{logger}->info("LDAP updating patron: " . $patron->{email});
$kohaPatron->Update($patron);
return $kohaPatron;
} catch {
warn $_;
warn "LDAP USER NOT FOUND: ADDING NEW PATRON";
#warn $_;
$self->{logger}->info("LDAP user not found: adding new patron: " . $patron->{email});
$self->addDefaultPatronAttributes();
$kohaPatron = $self->addNewKohaPatron();
};
......@@ -123,7 +122,9 @@ sub addNewKohaPatron {
try {
my $kohaPatron = Deichman::Patron->new()->Add($self->{auth}->{user});
} catch {
warn $_;
$self->{logger}->info("LDAP failed adding new patron: " . $patron->{email});
$self->{logger}->error($_);
#warn $_;
Deichman::Exception::Auth::FailedCreatingKohaPatron->throw();
};
return $self;
......
......@@ -33,13 +33,14 @@ sub DoAuth {
my $APIParams = $req->{"raisin.parameters"};
my $password = $req->param("password") // $APIParams->{password} or Deichman::Exception::Auth::ArgumentError->throw();
my $userid = $req->param("userid") // $APIParams->{userid} or Deichman::Exception::Auth::ArgumentError->throw();
use Data::Dumper; warn $userid;
$self->{logger}->info("Simple auth: login from user: ". $userid);
my ($user, $lib);
try {
$user = $self->checkAuthInternal( $userid, $password, 1 );
} catch {
# TODO: remove failure dump stack when done
use Data::Dumper; warn Dumper($_->description);
#use Data::Dumper; warn Dumper($_->description);
$self->{logger}->error("Simple auth failed: ". $_->description);
if ($_->isa("Deichman::Exception::Auth::FailedLogin")) {
C4::Context->_unset_userenv( $session->id ); # I don't think this is needed
Deichman::Exception::Auth::InvalidCredentials->throw();
......@@ -62,12 +63,12 @@ sub DoAuth {
$session->get(id => $user->{userid});
$session->get(emailaddress => $user->{email});
}
warn "Authenticated (SIMPLE AUTH)";
$self->{logger}->error("Simple auth succeeded: ". $session->{id});
$self->{auth}->{user} = $user;
$self->{auth}->{permissions} = $self->processKohaPermissions();
return $self;
}
}
sub checkAuthInternal {
my ( $self, $userid, $password, $no_set_userenv ) = @_; # TODO: remove no_set_userenv ?
$password = Encode::encode( "UTF-8", $password ) if Encode::is_utf8($password);
......@@ -114,7 +115,6 @@ sub checkPwHash {
# return auth session object
sub getAuthenticationObject {
my ($self) = @_;
warn "GETAUTHENTICATIONOBJECT SIMPLE";
return $self->{auth};
}
......
......@@ -3,7 +3,9 @@ package Deichman::Main;
use strict;
use warnings;
# Inherit from DB handle
# Inherit from DB handle
use Log::Log4perl;
use Log::Log4perl::Level;
use parent "Core::DB";
# Placeholder top object for Deichman namespace
......@@ -11,6 +13,8 @@ use parent "Core::DB";
sub new {
my $class = shift;
my $self = $class->SUPER::new();
Log::Log4perl->initialized() or Log::Log4perl->easy_init({ level => $ENV{LOG_LEVEL} // "WARN", layout => '%d{ISO8601} %-5p %m%n'});
$self->{logger} = Log::Log4perl->get_logger();
return bless $self, $class;
}
......
......@@ -80,7 +80,7 @@ sub cgi_subprocess {
local *STDOUT;
open STDOUT, '>', \$out or die "can't redirect stdout: $!";
warn "exec $file";
#warn "exec $file";
require $file;
}
......@@ -185,7 +185,7 @@ sub call {
my ( $file, $path_info ) = $self->locate_file($env);
$file or die "404 Not Found";
use Data::Dumper; warn Dumper($file);
#use Data::Dumper; warn Dumper($file);
#warn "APP[$file] with $env->{SESSION}";
Koha::Caches->flush_L1_caches();
......
......@@ -177,7 +177,7 @@ sub call {
my $dt = Time::HiRes::time() - $t0;
# log timing
printf STDERR "%s [%d] [%s %s] %s %.2f %s\n",
$ENV{LOG_LEVEL} eq "DEBUG" and printf STDERR "%s [%d] [%s %s] %s %.2f %s\n",
scalar(gmtime),
$$,
($session->id // "-"),
......
......@@ -135,7 +135,7 @@ CREATE TABLE `favourites` (
FOREIGN KEY (borrowernumber) REFERENCES borrowers(borrowernumber) ON DELETE CASCADE ON UPDATE CASCADE
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4;
--- api_keys
-- api_keys
DROP TABLE IF EXISTS `api_keys`;
CREATE TABLE `api_keys` (
`token` VARCHAR(128) NOT NULL,
......@@ -143,3 +143,6 @@ CREATE TABLE `api_keys` (
`valid_until` TIMESTAMP NOT NULL DEFAULT CURRENT_TIMESTAMP,
PRIMARY KEY `token` (`token`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_unicode_ci;
-- letters
-- deichman-letters.sql
......@@ -30,7 +30,6 @@ use Mojo::Server::PSGI;
$ENV{DEV_INSTALL} = 1;
$ENV{KOHA_HOME} = "/koha";
# Pre-load libraries
use C4::Boolean;
use C4::Koha;
......@@ -114,7 +113,7 @@ builder {
my $res = $app->($env);
my $dt = Time::HiRes::time() - $t0;
printf STDERR "%s %s elapsed %.3fs\n", scalar(gmtime()), $env->{REQUEST_URI}, $dt;
$ENV{LOG_LEVEL} eq "DEBUG" and printf STDERR "%s %s elapsed %.3fs\n", scalar(gmtime()), $env->{REQUEST_URI}, $dt;
my $path = $env->{PATH_INFO};
$path =~ m{/api/v1/app.pl(/api/\w+/\w+)} and $path = $1;
Koha::Util::InfluxDB::metric(plack => elapsed => $dt, { path => $path });
......
Markdown is supported
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment