Skip to content

Commit

Permalink
Item993: made the log system more rational. Logging is now done via a…
Browse files Browse the repository at this point in the history
…n abstract interface that is independent of the underlying log implementation. Logs can be reviewed. Log date stamps have been changed to time stamps, accurate to the second.

git-svn-id: http://svn.foswiki.org/trunk@2621 0b4bb1d4-4e5a-0410-9cc4-b2b747904278
  • Loading branch information
CrawfordCurrie authored and CrawfordCurrie committed Feb 23, 2009
1 parent 71035a5 commit 9c32b6a
Show file tree
Hide file tree
Showing 19 changed files with 349 additions and 118 deletions.
10 changes: 6 additions & 4 deletions TWikiCompatibilityPlugin/lib/TWiki/Func.pm
Original file line number Diff line number Diff line change
Expand Up @@ -88,13 +88,15 @@ sub expandTemplate { Foswiki::Func::expandTemplate(@_) }
# * =$length= - *DEPRECATED* The content length
sub writeHeader {
my ($query, $length) = @_;
if ($query && $query != $TWiki::Plugins::SESSION->{response}) {
$Foswiki::Plugins::SESSION->writeWarning(join(' ', caller).<<MESS);
called TWiki::Func::writeHeader called with a query parameter that does not match the current query. This could result in unpredictable behaviour.
if ($query && $query != Foswiki::Func::getCgiQuery()) {
Foswiki::Func::writeWarning(
join(' ', caller).<<MESS);
called TWiki::Func::writeHeader with a query parameter that does not match the current query. This could result in unpredictable behaviour.
MESS
}
if ($length) {
$Foswiki::Plugins::SESSION->writeWarning(join(' ', caller).<<MESS);
Foswiki::Func::writeWarning(
join(' ', caller).<<MESS);
called TWiki::Func::writeHeader with a length parameter. This parameter is deprecated, and will be ignored.
MESS
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -88,7 +88,7 @@ sub new {
if ( $this->{passwords}->readOnly()
&& ( $Foswiki::cfg{PasswordManager} ne 'none' ) )
{
$session->writeWarning(
$session->logger->log('warning',
'TopicUserMapping has TURNED OFF EnableNewUserRegistration, because the password file is read only.'
);
$Foswiki::cfg{Register}{EnableNewUserRegistration} = 0;
Expand Down Expand Up @@ -804,7 +804,6 @@ sub getEmails {
}
}
}

return keys %emails;
}

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -41,6 +41,7 @@ test/unit/FuncUsersTests.pm 0644
test/unit/HierarchicalWebsTests.pm 0644
test/unit/InitFormTests.pm 0644
test/unit/Iterator.pm 0755
test/unit/Logger.pm 0755
test/unit/ManageDotPmTests.pm 0644
test/unit/MergeTests.pm 0644
test/unit/MetaTests.pm 0644
Expand Down
166 changes: 166 additions & 0 deletions UnitTestContrib/test/unit/Logger.pm
Original file line number Diff line number Diff line change
@@ -0,0 +1,166 @@
# tests for Foswiki::Logger

package Logger;
use base qw( FoswikiTestCase );

use strict;
use File::Temp;
use Foswiki::Logger::PlainFile;

# NOTE: Test logs are created in the test web so they get torn down when the
# web is torn down in the superclass.

sub set_up {
my $this = shift;
$this->SUPER::set_up();

$Foswiki::cfg{DebugFileName} = "DebugFileName$$";
$Foswiki::cfg{WarningFileName} = "WarningFileName$$";
$Foswiki::cfg{LogFileName} = "LogFileName$$";
}

sub tear_down {
my $this = shift;

unlink($Foswiki::cfg{DebugFileName});
unlink($Foswiki::cfg{WarningFileName});
unlink($Foswiki::cfg{LogFileName});
$this->SUPER::tear_down();
}

sub fixture_groups {
my %algs;
foreach my $dir (@INC) {
if ( opendir( D, "$dir/Foswiki/Logger" ) ) {
foreach my $alg ( readdir D ) {
next unless $alg =~ /^(\w+)\.pm$/;
$algs{$1} = 1;
}
closedir(D);
}
}
my @groups;
foreach my $alg ( keys %algs ) {
my $fn = $alg . 'Logger';
push( @groups, $fn );
next if ( defined(&$fn) );
my $class = "Foswiki::Logger::$alg";
eval <<HERE;
sub $fn {
my \$this = shift;
require $class;
\$this->{logger} = new $class();
}
HERE
die $@ if $@;
}

return \@groups;
}

sub verify_simpleWriteAndReplay {
my $this = shift;
my $time = time;
# Verify the three levels used by Foswiki; debug, info and warning
foreach my $level qw(debug info warning) {
$this->{logger}->log(
$level,
$level, "Green", "Eggs", "and", "Ham");
}
foreach my $level qw(debug info warning) {
my $it = $this->{logger}->eachEventSince($time, $level);
$this->assert($it->hasNext(), $level);
my $data = $it->next();
my $t = shift( @$data );
$this->assert($t >= $time, "$t $time");
$this->assert_str_equals(
"$level.Green.Eggs.and.Ham", join('.', @$data));
$this->assert(!$it->hasNext());
}
}

sub verify_eachEventSinceOnEmptyLog {
my $this = shift;
foreach my $level qw(debug info warning) {
my $it = $this->{logger}->eachEventSince(0, $level);
$this->assert(!$it->hasNext());
}
}

my $plainFileTestTime;
sub PlainFileTestTime {
return $plainFileTestTime;
}

# Test specific to PlainFile logger
sub test_eachEventSinceOnSeveralLogs {
my $this = shift;
my $logger = new Foswiki::Logger::PlainFile();
my $cache = \&Foswiki::Logger::PlainFile::_time;
no warnings 'redefine';
*Foswiki::Logger::PlainFile::_time = \&PlainFileTestTime;
$plainFileTestTime = 3600; # 1am on 1st Jan 1970
$logger->log('info', "Seal");
my $firstTime = time - 2*32*24*60*60;
$plainFileTestTime = $firstTime; # 2 months ago
$logger->log('info', "Dolphin");
$plainFileTestTime += 32*24*60*60; # 1 month ago
$logger->log('info', "Whale");
$plainFileTestTime = time; # today
$logger->log('info', "Porpoise");

my $it = $logger->eachEventSince(0, 'info');
my $data;
$this->assert($it->hasNext()); $data = $it->next();
$this->assert_equals(3600, $data->[0]);
$this->assert_str_equals("Seal", $data->[1]);
$this->assert($it->hasNext()); $data = $it->next();
$this->assert_equals($firstTime, $data->[0]);
$this->assert_str_equals("Dolphin", $data->[1]);
$this->assert($it->hasNext()); $data = $it->next();
$this->assert_str_equals("Whale", $data->[1]);
$this->assert($it->hasNext()); $data = $it->next();
$this->assert_equals($plainFileTestTime, $data->[0]);
$this->assert_str_equals("Porpoise", $data->[1]);
$this->assert(!$it->hasNext());

# Check the date filter
$it = $logger->eachEventSince($firstTime, 'info');
$this->assert($it->hasNext()); $data = $it->next();
$this->assert_equals($firstTime, $data->[0]);
$this->assert_str_equals("Dolphin", $data->[1]);
$this->assert($it->hasNext()); $data = $it->next();
$this->assert_str_equals("Whale", $data->[1]);
$this->assert($it->hasNext()); $data = $it->next();
$this->assert_equals($plainFileTestTime, $data->[0]);
$this->assert_str_equals("Porpoise", $data->[1]);
$this->assert(!$it->hasNext());

*Foswiki::Logger::PlainFile::_time = $cache;
use warnings 'redefine';
}

sub test_filter {
# with PlainFile, warning up are all crammed into one logfile
my $this = shift;
my $logger = new Foswiki::Logger::PlainFile();
$logger->log('warning', "Shark");
$logger->log('error', "Dolphin");
$logger->log('critical', "Injury");
$logger->log('warning', "Bite");
$logger->log('alert', "Ram");
$logger->log('warning', "Hurts");
$logger->log('critical', "Doctors");

my $it = $logger->eachEventSince(0, 'warning');
my $data;
$this->assert($it->hasNext()); $data = $it->next();
$this->assert_str_equals("Shark", $data->[1]);
$this->assert($it->hasNext()); $data = $it->next();
$this->assert_str_equals("Bite", $data->[1]);
$this->assert($it->hasNext()); $data = $it->next();
$this->assert_str_equals("Hurts", $data->[1]);
$this->assert(!$it->hasNext());
}

1;
3 changes: 1 addition & 2 deletions core/data/System/DevelopingPlugins.txt
Original file line number Diff line number Diff line change
Expand Up @@ -11,7 +11,7 @@ To be robust, extensions must avoid using any unpublished functionality from the
* =[[%SCRIPTURL{view}%/%SYSTEMWEB%/PerlDoc?module=Foswiki::AccessControlException][Foswiki::AccessControlException]]= - access control exception
* =[[%SCRIPTURL{view}%/%SYSTEMWEB%/PerlDoc?module=Foswiki::Attrs][Foswiki::Attrs]]= - parser and storage object for macro parameters
* =[[%SCRIPTURL{view}%/%SYSTEMWEB%/PerlDoc?module=Foswiki::Time][Foswiki::Time]]= - time parsing and formatting
* =[[%SCRIPTURL{view}%/%SYSTEMWEB%/PerlDoc?module=Foswiki::Sandbox][Foswiki::Sandbox]]= - safe server-side program execution
* =[[%SCRIPTURL{view}%/%SYSTEMWEB%/PerlDoc?module=Foswiki::Sandbox][Foswiki::Sandbox]]= - safe server-side program execution, used for calling external programs.
* Iterators - these are classes that implement the =[[%SCRIPTURL{view}%/%SYSTEMWEB%/PerlDoc?module=Foswiki::Iterator][Foswiki::Iterator]]= specification
* =[[%SCRIPTURL{view}%/%SYSTEMWEB%/PerlDoc?module=Foswiki::ListIterator][Foswiki::ListIterator]]= - utility class for iterator objects that iterate over list contents
* =[[%SCRIPTURL{view}%/%SYSTEMWEB%/PerlDoc?module=Foswiki::LineIterator][Foswiki::LineIterator]]= - utility class for iterator objects that iterate over lines in a block of text
Expand All @@ -21,7 +21,6 @@ In addition the following global variables may be referred to:
* =$Foswiki::Plugins::SESSION= - reference to =Foswiki= singleton object
* =$Foswiki::cfg= - reference to configuration hash
* =$Foswiki::regex= - see [[#StReEx][Standard Regular Expressions]], below
* =$Foswiki::sandbox= - reference to the static sandbox object (type =Foswiki::Sandbox=), used for calling external programs.
%I% Foswiki:Development.GettingStarted is the starting point for more comprehensive documentation on developing for Foswiki.

*Note* the APIs are available to all extensions, but rely on a
Expand Down
8 changes: 4 additions & 4 deletions core/lib/Assert.pm
Original file line number Diff line number Diff line change
Expand Up @@ -25,7 +25,7 @@ BEGIN {
$VERSION = '0.01';
$DIRTY = $ENV{PATH}; # Used in TAINT

$EXPORT_TAGS{NDEBUG} = [qw(ASSERT UNTAINTED TAINT DEBUG)];
$EXPORT_TAGS{NDEBUG} = ['ASSERT', 'UNTAINTED', 'TAINT', 'DEBUG'];
$EXPORT_TAGS{DEBUG} = $EXPORT_TAGS{NDEBUG};
Exporter::export_tags(qw(NDEBUG DEBUG));
}
Expand All @@ -34,10 +34,10 @@ BEGIN {
sub ASSERTS_ON { 1 } # CONSTANT
sub ASSERTS_OFF { 0 } # CONSTANT

sub noop { return $_[0] }

# Export the proper DEBUG flag if FOSWIKI_ASSERTS is set,
# otherwise export noop versions of our routines
sub noop { }

sub import {
no warnings 'redefine';
no strict 'refs';
Expand All @@ -48,7 +48,7 @@ sub import {
else {
my $caller = caller;
*{ $caller . '::ASSERT' } = \&noop;
*{ $caller . '::TAINT' } = sub { $_[0] };
*{ $caller . '::TAINT' } = \&noop;
*{ $caller . '::DEBUG' } = \&ASSERTS_OFF;
}
use strict 'refs';
Expand Down
86 changes: 86 additions & 0 deletions core/lib/Foswiki/Logger.pm
Original file line number Diff line number Diff line change
@@ -0,0 +1,86 @@
# See bottom of file for license and copyright information
package Foswiki::Logger;

use strict;

use Assert;

=begin TML
---+ package Foswiki::Logger
Object that interfaces to whatever records Foswiki log files.
This is a pure virtual base class which must be implemented by a
subclass in the Logger subdirectory and selected by $Foswiki::cfg{Log}{Implementation}
Note that the implementation has to provide a way for the log to be replayed.
Unfortunately this means that the simpler CPAN loggers are not suitable,
nor is
=cut

=begin TML
---++ ObjectMethod log($level, @fields)
Adds a log message to a log.
* =$level= - level of the event - one of =debug=, =info=,
=warning=, =error=, =critical=, =alert=, =emergency=.
* =@fields= - an arbitrary list of fields to output to the log.
These fields are recoverable when the log is enumerated using the
=eachEventSince= method.
The levels are chosen to be compatible with Log::Dispatch.
=cut

sub log {
ASSERT('Pure virtual method called') if DEBUG;
}

=begin TML
---++ ObjectMethod eachEventSince($time, $level) -> $iterator
* =$time= - a time in the past
* =$level= - log level to return events for.
Get an iterator over the list of all the events at the given level
between =$time= and now.
Events are returned in *oldest-first* order.
Each event is returned as a reference to an array. The first element
of this array is always the date of the event (seconds since the epoch).
Subsequent elements are the fields passed to =log=.
Note that a log implementation may choose to collapse several log levels
into a single log. In this case, all messages in the same set as the
requested level will be returned if any of the collapsed levels is selected.
=cut

sub eachEventSince {
ASSERT('Pure virtual method called') if DEBUG;
}

1;
__END__
# Module of Foswiki - The Free and Open Source Wiki, http://foswiki.org/
#
# Copyright (C) 2008-2009 Foswiki Contributors. Foswiki Contributors
# are listed in the AUTHORS file in the root of this distribution.
# NOTE: Please extend that file, not this notice.
#
# This program is free software; you can redistribute it and/or
# modify it under the terms of the GNU General Public License
# as published by the Free Software Foundation; either version 2
# of the License, or (at your option) any later version. For
# more details read LICENSE in the root of this distribution.
#
# This program is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.
#
# As per the GPL, removal of this notice is prohibited.
4 changes: 2 additions & 2 deletions core/lib/Foswiki/LoginManager.pm
Original file line number Diff line number Diff line change
Expand Up @@ -374,7 +374,7 @@ sub loadSession {

if ($sudoUser) {
_trace( $this, "User is logging out to $sudoUser" );
$session->writeLog( 'sudo logout', '',
$session->logEvent('sudo logout', '',
'from ' . ( $authUser || '' ), $sudoUser );
$this->{_cgisession}->clear('SUDOFROMAUTHUSER');
$authUser = $sudoUser;
Expand Down Expand Up @@ -556,7 +556,7 @@ sub userLoggedIn {
if ( defined( $session->{remoteUser} )
&& $session->inContext('sudo_login') )
{
$session->writeLog( 'sudo login', '',
$session->logEvent('sudo login', '',
'from ' . ( $session->{remoteUser} || '' ), $authUser );
$this->{_cgisession}
->param( 'SUDOFROMAUTHUSER', $session->{remoteUser} );
Expand Down
5 changes: 3 additions & 2 deletions core/lib/Foswiki/Net.pm
Original file line number Diff line number Diff line change
Expand Up @@ -260,7 +260,7 @@ sub _installMailHandler {
require Net::SMTP;
};
if ($@) {
$this->{session}->writeWarning("SMTP not available: $@")
$this->{session}->logger->log('warning', "SMTP not available: $@")
if ( $this->{session} );
}
else {
Expand Down Expand Up @@ -332,7 +332,7 @@ sub sendEmail {
}
catch Error::Simple with {
my $e = shift->stringify();
$this->{session}->writeWarning($e);
$this->{session}->logger->log('warning', $e);

# be nasty to errors that we didn't throw. They may be
# caused by SMTP or perl, and give away info about the
Expand All @@ -349,6 +349,7 @@ sub sendEmail {
unless $retries;
};
}

return $errors;
}

Expand Down
Loading

0 comments on commit 9c32b6a

Please sign in to comment.