oqapi/webgui
2
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

use callback for log interception instead of on/off

Browse source
This commit is contained in:
Graham Knop 2010-06-17 09:18:50 -05:00
parent 8bfa022441
commit 18525e7c1b
9 changed files with 126 additions and 268 deletions
Download patch file Download diff file Expand all files Collapse all files

30
t/Asset/AssetLineage.t
View file

@ -519,24 +519,26 @@ my $vTag2 = WebGUI::VersionTag->getWorking($session);
$vTag2->set({name=>"deep addChild test"});
WebGUI::Test->addToCleanup($vTag2);
WebGUI::Test->interceptLogging();
WebGUI::Test->interceptLogging( sub {
my $log_data = shift;
my @deepAsset = ($root);
my @deepAsset = ($root);
for (1..42) {
$deepAsset[$_] = $deepAsset[$_-1]->addChild( {
className => "WebGUI::Asset::Snippet",
groupIdView => 7,
ownerUserId => 3, #For coverage on addChild properties
title => "Deep Snippet $_",
menuTitle => "Deep Snip $_",
});
}
for (1..42) {
$deepAsset[$_] = $deepAsset[$_-1]->addChild( {
className => "WebGUI::Asset::Snippet",
groupIdView => 7,
ownerUserId => 3, #For coverage on addChild properties
title => "Deep Snippet $_",
menuTitle => "Deep Snip $_",
});
}
$vTag2->commit;
$vTag2->commit;
is($deepAsset[41]->getParent->getId, $deepAsset[40]->getId, 'addChild will not create an asset with a lineage deeper than 42 levels');
like($WebGUI::Test::logger_warns, qr/Adding it as a sibling instead/, 'addChild logged a warning about deep assets');
is($deepAsset[41]->getParent->getId, $deepAsset[40]->getId, 'addChild will not create an asset with a lineage deeper than 42 levels');
like($log_data->{warn}, qr/Adding it as a sibling instead/, 'addChild logged a warning about deep assets');
});
{
my $tag = WebGUI::VersionTag->getWorking($session);

22
t/Asset/Template.t
View file

@ -166,17 +166,17 @@ my $brokenTemplate = $importNode->addChild({
template => q|<tmpl_if unclosedIf>If clause with no ending tag|,
});
WebGUI::Test->interceptLogging;
my $brokenOutput = $brokenTemplate->process({});
my $logError = $WebGUI::Test::logger_error;
my $brokenUrl = $brokenTemplate->getUrl;
my $brokenId = $brokenTemplate->getId;
like($brokenOutput, qr/^There is a syntax error in this template/, 'process: returned error output contains boilerplate');
like($brokenOutput, qr/$brokenUrl/, '... and the template url');
like($brokenOutput, qr/$brokenId/, '... and the template id');
like($logError, qr/$brokenUrl/, 'process: logged error has the url');
like($logError, qr/$brokenId/, '... and the template id');
WebGUI::Test->restoreLogging;
WebGUI::Test->interceptLogging( sub {
my $log_data = shift;
my $brokenOutput = $brokenTemplate->process({});
my $brokenUrl = $brokenTemplate->getUrl;
my $brokenId = $brokenTemplate->getId;
like($brokenOutput, qr/^There is a syntax error in this template/, 'process: returned error output contains boilerplate');
like($brokenOutput, qr/$brokenUrl/, '... and the template url');
like($brokenOutput, qr/$brokenId/, '... and the template id');
like($log_data->{error}, qr/$brokenUrl/, 'process: logged error has the url');
like($log_data->{error}, qr/$brokenId/, '... and the template id');
});
WebGUI::Test->addToCleanup(WebGUI::VersionTag->getWorking($session));

20
t/Asset/Wobject/DataForm.t
View file

@ -54,17 +54,19 @@ plan tests => 4; # Increment this number for each test you create
#----------------------------------------------------------------------------
# _createForm
WebGUI::Test->interceptLogging;
WebGUI::Test->interceptLogging( sub {
my $log_data = shift;
$df->_createForm(
{
name => 'test field',
type => 'MASSIVE FORM FAILURE',
},
'some value'
);
$df->_createForm(
{
name => 'test field',
type => 'MASSIVE FORM FAILURE',
},
'some value'
);
is($WebGUI::Test::logger_error, "Unable to load form control - MASSIVE FORM FAILURE", '_createForm logs when it cannot load a form type');
is($log_data->{error}, "Unable to load form control - MASSIVE FORM FAILURE", '_createForm logs when it cannot load a form type');
});
#----------------------------------------------------------------------------
# getContentLastModified

8
t/Session/DateTime.t
View file

@ -120,10 +120,12 @@ $session->user({userId => 1}); ##back to Visitor
my $wgBdayMail = 'Thu, 16 Aug 2001 08:00:00 -0500';
is ($dt->mailToEpoch($wgBdayMail), $wgbday, 'mailToEpoch');
WebGUI::Test->interceptLogging();
WebGUI::Test->interceptLogging( sub {
my $log_data = shift;
is ($dt->mailToEpoch(750), undef, 'mailToEpoch returns undef on failure to parse');
like($WebGUI::Test::logger_warns, qr{750 is not a valid date for email}, "DateTime logs a warning on failure to parse");
is ($dt->mailToEpoch(750), undef, 'mailToEpoch returns undef on failure to parse');
like($log_data->{warn}, qr{750 is not a valid date for email}, "DateTime logs a warning on failure to parse");
});
####################################################
#

227
t/Session/ErrorHandler.t
View file

@ -17,8 +17,9 @@ use WebGUI::Session;
use Test::More;
use Test::MockObject::Extends;
use Try::Tiny;
my $numTests = 39;
my $numTests = 13;
plan tests => $numTests;
@ -36,21 +37,19 @@ my $eh = $session->errorHandler;
#
####################################################
WebGUI::Test->interceptLogging();
WebGUI::Test->interceptLogging( sub {
my $log_data = shift;
my $accumulated_warn = "";
$eh->warn("This is a warning");
is($WebGUI::Test::logger_warns, "This is a warning", "warn: Log4perl called");
$accumulated_warn .= "This is a warning\n";
is($session->errorHandler->{_debug_warn}, $accumulated_warn, "warn: message internally appended");
$eh->warn("Second warning");
is($WebGUI::Test::logger_warns, "Second warning", "warn: Log4perl called again");
$accumulated_warn .= "Second warning\n";
is($session->errorHandler->{_debug_warn}, $accumulated_warn, "warn: second message appended");
$eh->security('Shields up, red alert');
my $security = sprintf '%s (%d) connecting from %s attempted to %s',
$session->user->username, $session->user->userId, $session->env->getIp, 'Shields up, red alert';
is($WebGUI::Test::logger_warns, $security, 'security: calls warn with username, userId and IP address');
my $accumulated_warn = "";
$eh->warn("This is a warning");
is($log_data->{warn}, "This is a warning", "warn: Log4perl called");
$eh->warn("Second warning");
is($log_data->{warn}, "Second warning", "warn: Log4perl called again");
$eh->security('Shields up, red alert');
my $security = sprintf '%s (%d) connecting from %s attempted to %s',
$session->user->username, $session->user->userId, $session->env->getIp, 'Shields up, red alert';
is($log_data->{warn}, $security, 'security: calls warn with username, userId and IP address');
});
####################################################
#
@ -58,50 +57,30 @@ is($WebGUI::Test::logger_warns, $security, 'security: calls warn with username,
#
####################################################
my $accumulated_info = '';
$eh->info("This is informative");
is($WebGUI::Test::logger_info, "This is informative", "info: Log4perl called");
$accumulated_info .= "This is informative\n";
is($session->errorHandler->{_debug_info}, $accumulated_info, "info: message internally appended");
$eh->info("More info");
is($WebGUI::Test::logger_info, "More info", "info: Log4perl called again");
$accumulated_info .= "More info\n";
is($session->errorHandler->{_debug_info}, $accumulated_info, "info: second message appended");
$eh->audit('Check this out');
my $audit = sprintf '%s (%d) %s', $session->user->username, $session->user->userId, 'Check this out';
is($WebGUI::Test::logger_info, $audit, 'audit: calls info with username and userId');
WebGUI::Test->interceptLogging( sub {
my $log_data = shift;
$eh->info("This is informative");
is($log_data->{info}, "This is informative", "info: Log4perl called");
$eh->info("More info");
is($log_data->{info}, "More info", "info: Log4perl called again");
$eh->audit('Check this out');
my $audit = sprintf '%s (%d) %s', $session->user->username, $session->user->userId, 'Check this out';
is($log_data->{info}, $audit, 'audit: calls info with username and userId');
});
####################################################
#
# debug, query
# debug
#
####################################################
$eh->{'_debug_debug'} = ''; ##Manually clean debug
$eh->debug("This is a bug");
is($WebGUI::Test::logger_debug, "This is a bug", "debug: Log4perl called");
is($eh->{'_debug_debug'}, "This is a bug\n", "debug: message internally appended");
$eh->debug("More bugs");
is($WebGUI::Test::logger_debug, "More bugs", "debug: Log4perl called again");
is($eh->{'_debug_debug'}, "This is a bug\nMore bugs\n", "debug: second message appended");
$eh->{'_debug_debug'} = ''; ##Manually clean debug
my $queryCount = $eh->{_queryCount};
$eh->query('select this');
++$queryCount;
is($WebGUI::Test::logger_debug, "query $queryCount:\n select this", "query: Log4perl called debug via query");
$eh->query('select that', 'literal');
++$queryCount;
is($WebGUI::Test::logger_debug, "query $queryCount:\n select that", "query: Log4perl called debug via query, literal placeholder");
$eh->query('select more', []);
++$queryCount;
is($WebGUI::Test::logger_debug, "query $queryCount:\n select more", "query: Log4perl called debug via query, empty placeholder");
$eh->query('select many', [1, 2]);
++$queryCount;
is($WebGUI::Test::logger_debug, "query $queryCount:\n select many\n with placeholders: [1,2]", "query: Log4perl called debug via query, empty placeholder");
WebGUI::Test->interceptLogging( sub {
my $log_data = shift;
$eh->debug("This is a bug");
is($log_data->{debug}, "This is a bug", "debug: Log4perl called");
$eh->debug("More bugs");
is($log_data->{debug}, "More bugs", "debug: Log4perl called again");
});
####################################################
#
@ -109,115 +88,13 @@ is($WebGUI::Test::logger_debug, "query $queryCount:\n select many\n with place
#
####################################################
$eh->{'_debug_debug'} = ''; ##Manually clean debug
$eh->error("ERROR");
is($WebGUI::Test::logger_error, "ERROR", "error: Log4perl called error");
like($WebGUI::Test::logger_debug, qr/^Stack trace for ERROR ERROR/, "error: Log4perl called debug");
is($eh->{'_debug_error'}, "ERROR\n", "error: message internally appended");
$eh->error("More errors");
is($WebGUI::Test::logger_error, "More errors", "error: Log4perl called error again");
is($eh->{'_debug_error'}, "ERROR\nMore errors\n", "error: new message internally appended");
####################################################
#
# getStackTrace
#
####################################################
is ($eh->getStackTrace, undef, 'no stack trace due to shallow depth, must be 2 deep for a stack trace');
like(&depth1(), qr/main(.*?)ErrorHandler\.t/, 'stack trace has correct information');
sub depth1 {
return &depth2();
}
sub depth2 {
return $eh->getStackTrace;
}
####################################################
#
# canShowBasedOnIP
#
####################################################
is($eh->canShowBasedOnIP(''), 0, 'canShowBasedOnIP: must send IP setting');
####################################################
#
# canShowDebug
#
####################################################
$session->setting->set('showDebug', 0);
delete $eh->{_canShowDebug};
ok(! $eh->canShowDebug, 'canShowDebug: returns 0 if not enabled');
$session->setting->set('showDebug', 1);
$session->http->setMimeType('audio/mp3');
delete $eh->{_canShowDebug};
ok(! $eh->canShowDebug, 'canShowDebug: returns 0 if mime type is wrong');
$session->http->setMimeType('text/html');
$session->setting->set('debugIp', '');
delete $eh->{_canShowDebug};
ok($eh->canShowDebug, 'canShowDebug: returns 1 if debugIp is empty string');
$session->setting->set('debugIp', '10.0.0.5/32, 192.168.0.4/30');
$env->{REMOTE_ADDR} ='172.17.0.5';
delete $eh->{_canShowDebug};
ok(! $eh->canShowDebug, 'canShowDebug: returns 0 if debugIp is set and IP address is out of filter');
$env->{REMOTE_ADDR} = '10.0.0.5';
delete $eh->{_canShowDebug};
ok($eh->canShowDebug, 'canShowDebug: returns 1 if debugIp is set and IP address matches filter');
$env->{REMOTE_ADDR} = '192.168.0.5';
delete $eh->{_canShowDebug};
ok($eh->canShowDebug, 'canShowDebug: returns 1 if debugIp is set and IP address matches filter');
####################################################
#
# canShowPerformanceIndicators
#
####################################################
$session->setting->set('showPerformanceIndicators', 0);
is($eh->canShowPerformanceIndicators, 0, 'canShowPerformanceIndicators: returns 0 if not enabled');
$session->setting->set('showPerformanceIndicators', 1);
$session->setting->set('debugIp', '');
is($eh->canShowPerformanceIndicators, 1, 'canShowPerformanceIndicators: returns 1 if debugIp is blank');
$session->setting->set('debugIp', '10.0.0.5/32, 192.168.0.4/30');
$env->{REMOTE_ADDR} = '172.17.0.5';
is($eh->canShowPerformanceIndicators, 0, 'canShowPerformanceIndicators: returns 0 if debugIp is set and IP address does not match');
$env->{REMOTE_ADDR} = '10.0.0.5';
is($eh->canShowPerformanceIndicators, 1, 'canShowPerformanceIndicators: returns 0 if debugIp is set and IP address matches exactly');
$env->{REMOTE_ADDR} = '192.168.0.5';
is($eh->canShowPerformanceIndicators, 1, 'canShowPerformanceIndicators: returns 0 if debugIp is set and IP address matches subnet');
####################################################
#
# showDebug
#
####################################################
my $form = $session->form;
$form = Test::MockObject::Extends->new($form);
$form->mock('paramsHashRef',
sub {
return {
password => 'passWord',
identifier => 'qwe123',
username => 'Admin',
};
});
foreach my $entry (qw/_debug_error _debug_warn _debug_info _debug_debug/) {
$eh->{$entry} = $entry . "\n";
}
my $showDebug = $eh->showDebug;
WebGUI::Test->interceptLogging( sub {
my $log_data = shift;
$eh->error("ERROR");
is($log_data->{error}, "ERROR", "error: Log4perl called error");
$eh->error("More errors");
is($log_data->{error}, "More errors", "error: Log4perl called error again");
});
####################################################
#
@ -225,17 +102,17 @@ my $showDebug = $eh->showDebug;
#
####################################################
my $newSession = WebGUI::Session->open(WebGUI::Test::file);
addToCleanup($newSession);
my $outputBuffer;
open my $outputHandle, '>', \$outputBuffer or die "Unable to create scalar filehandle: $!\n";
$newSession->output->setHandle($outputHandle);
WEBGUI_FATAL: {
$newSession->log->fatal('Bad things are happenning');
}
ok(1, 'fatal: recovered from fatal okay');
TODO: {
local $TODO = 'Validate the fatal output';
ok(0, 'output from fatal when there is a db handler and request present');
}
WebGUI::Test->interceptLogging( sub {
my $log_data = shift;
my $thrown = try {
$eh->fatal('Bad things are happenning');
fail 'fatal throws exception';
fail ' ... exception isa WebGUI::Exception::Fatal';
}
catch {
pass 'fatal throws exception';
isa_ok $_, 'WebGUI::Error::Fatal';
};
is $log_data->{fatal}, 'Bad things are happenning', 'fatal: logger called correctly';
});

2
t/Session/Stow.t
View file

@ -38,8 +38,6 @@ is($stow->get("Test1"), undef, "delete()");
$stow->deleteAll;
is($stow->get("Test2"), undef, "deleteAll()");
WebGUI::Test->interceptLogging();
is($session->stow->set('', 'null string'), undef, 'set returns undef when name is empty string');
is($session->stow->set(0, 'zero'), undef, 'set returns undef when name is zero');

23
t/Storage/Image.t
View file

@ -116,7 +116,8 @@ foreach my $extTest ( @{ $extensionTests } ) {
#
####################################################
WebGUI::Test->interceptLogging();
WebGUI::Test->interceptLogging(sub {
my $log_data = shift;
my $thumbStore = WebGUI::Storage->create($session);
WebGUI::Test->addToCleanup($thumbStore);
@ -124,9 +125,9 @@ my $square = WebGUI::Image->new($session, 500, 500);
$square->setBackgroundColor('#FF0000');
$square->saveToStorageLocation($thumbStore, 'square.png');
is($thumbStore->generateThumbnail(), 0, 'generateThumbnail returns 0 if no filename is supplied');
is($WebGUI::Test::logger_error, q/Can't generate a thumbnail when you haven't specified a file./, 'generateThumbnail logs an error message for not sending a filename');
is($log_data->{error}, q/Can't generate a thumbnail when you haven't specified a file./, 'generateThumbnail logs an error message for not sending a filename');
is($thumbStore->generateThumbnail('file.txt'), 0, 'generateThumbnail returns 0 if you try to thumbnail a non-image file');
is($WebGUI::Test::logger_warns, q/Can't generate a thumbnail for something that's not an image./, 'generateThumbnail logs a warning message for thumbnailing a non-image file.');
is($log_data->{warn}, q/Can't generate a thumbnail for something that's not an image./, 'generateThumbnail logs a warning message for thumbnailing a non-image file.');
chmod 0, $thumbStore->getPath('square.png');
SKIP: {
@ -135,7 +136,7 @@ SKIP: {
ok(! -r $thumbStore->getPath('square.png'), 'Made square.png not readable');
is($thumbStore->generateThumbnail('square.png'), 0,
'generateThumbnail returns 0 if there are errors reading the file');
like($WebGUI::Test::logger_error, qr/^Couldn't read image for thumbnail creation: (.+)$/,
like($log_data->{error}, qr/^Couldn't read image for thumbnail creation: (.+)$/,
'generateThumbnail when it cannot read the file for thumbnailing');
chmod oct(644), $thumbStore->getPath('square.png');
}
@ -155,13 +156,13 @@ cmp_bag([$thumbStore->getSizeInPixels('square.png')], [500,500], 'getSizeI
cmp_bag([$thumbStore->getSizeInPixels('thumb-square.png')], [50,50], 'getSizeInPixels on thumb');
is($thumbStore->getSizeInPixels(), 0, 'getSizeInPixels returns only a zero if no file is sent');
is($WebGUI::Test::logger_error, q/Can't check the size when you haven't specified a file./, 'getSizeInPixels logs an error message for not sending a filename');
is($log_data->{error}, q/Can't check the size when you haven't specified a file./, 'getSizeInPixels logs an error message for not sending a filename');
is($thumbStore->getSizeInPixels('noImage.txt'), 0, 'getSizeInPixels returns only a zero if sent a non-image file');
is($WebGUI::Test::logger_error, q/Can't check the size of something that's not an image./, 'getSizeInPixels logs an error message for sending a non-image filename');
is($log_data->{error}, q/Can't check the size of something that's not an image./, 'getSizeInPixels logs an error message for sending a non-image filename');
is($thumbStore->getSizeInPixels('noImage.gif'), 0, 'getSizeInPixels returns only a zero if sent a file that does not exist');
like($WebGUI::Test::logger_error, qr/^Couldn't read image to check the size of it./, 'getSizeInPixels logs an error message for reading a file that does not exist');
like($log_data->{error}, qr/^Couldn't read image to check the size of it./, 'getSizeInPixels logs an error message for reading a file that does not exist');
####################################################
#
@ -203,10 +204,10 @@ is($imageCopy->deleteFile('../../'), undef, 'deleteFile in Storage::Image also r
####################################################
is($thumbStore->getThumbnailUrl(), '', 'getThumbnailUrl returns undef if no file is sent');
is($WebGUI::Test::logger_error, q/Can't find a thumbnail url without a filename./, 'getThumbnailUrl logs an error message for not sending a filename');
is($log_data->{error}, q/Can't find a thumbnail url without a filename./, 'getThumbnailUrl logs an error message for not sending a filename');
is($thumbStore->getThumbnailUrl('round.png'), '', 'getThumbnailUrl returns undef if the requested file is not in the storage location');
is($WebGUI::Test::logger_error, q/Can't find a thumbnail for a file named 'round.png' that is not in my storage location./, 'getThumbnailUrl logs an error message for not sending a filename');
is($log_data->{error}, q/Can't find a thumbnail for a file named 'round.png' that is not in my storage location./, 'getThumbnailUrl logs an error message for not sending a filename');
is($thumbStore->getThumbnailUrl('square.png'), $thumbStore->getUrl('thumb-square.png'), 'getThumbnailUrl returns the correct url');
@ -216,8 +217,6 @@ is($thumbStore->getThumbnailUrl('square.png'), $thumbStore->getUrl('thumb-square
#
####################################################
my $origMaxImageSize = $session->setting->get('maxImageSize');
my $sizeTest = WebGUI::Storage->create($session);
WebGUI::Test->addToCleanup($sizeTest);
@ -275,7 +274,7 @@ foreach my $testImage (@testImages) {
);
}
$session->setting->set('maxImageSize', $origMaxImageSize );
});
TODO: {
local $TODO = "Methods that need to be tested";

15
t/Workflow/Instance.t
View file

@ -87,13 +87,14 @@ cmp_ok(abs ($instance->get('lastUpdate')-$dateUpdated), '<=', 3, 'Date updated f
my $otherInstance = WebGUI::Workflow::Instance->create($session, $properties);
is ($otherInstance, undef, 'create: only allows one instance of a singleton to be created');
WebGUI::Test->interceptLogging;
$instance->set({ 'parameters' => {session => 1}, });
$otherInstance = WebGUI::Workflow::Instance->create($session, {workflowId => $wf->getId, parameters => { session => 1,} });
is($otherInstance, undef, 'create: another singleton instance can not be created if it the same parameters as a currently existing instance');
my $expectedId = $wf->getId;
like($WebGUI::Test::logger_info, qr/An instance of singleton workflow $expectedId already exists/, 'create: Warning logged for trying to make another singleton');
WebGUI::Test->interceptLogging( sub {
my $log_data = shift;
$instance->set({ 'parameters' => {session => 1}, });
$otherInstance = WebGUI::Workflow::Instance->create($session, {workflowId => $wf->getId, parameters => { session => 1,} });
is($otherInstance, undef, 'create: another singleton instance can not be created if it the same parameters as a currently existing instance');
my $expectedId = $wf->getId;
like($log_data->{info}, qr/An instance of singleton workflow $expectedId already exists/, 'create: Warning logged for trying to make another singleton');
} );
$otherInstance = WebGUI::Workflow::Instance->create($session, {workflowId => $wf->getId, parameters => { session => 2,}});
isnt ($otherInstance, undef, 'create: another singleton instance can be created if it has different parameters');

47
t/lib/WebGUI/Test.pm
View file

@ -235,42 +235,19 @@ mock the isDebug flag so that debug output is always generated.
=cut
my $origLogger;
sub interceptLogging {
my $log = $CLASS->session->log;
$origLogger ||= $log->{_logger};
$log->{_logger} = sub {
my $info = shift;
my $level = $info->{level};
my $message = $info->{message};
if ($level eq 'warn') {
our $logger_warns = $message;
}
elsif ($level eq 'debug') {
our $logger_debug = $message;
}
elsif ($level eq 'info') {
our $logger_info = $message;
}
elsif ($level eq 'error') {
our $logger_error = $message;
}
sub interceptLogging (&) {
shift
if eval { $_[0]->isa($CLASS) };
my $sub = shift;
my @logged;
my $last_logged = {};
local $CLASS->session->log->{'_logger'} = sub {
my $to_log = shift;
push @logged, $to_log;
$last_logged->{$to_log->{level}} = $to_log->{message};
};
}
#----------------------------------------------------------------------------
=head2 restoreLogging
Restores's the logging object to its original state.
=cut
sub restoreLogging {
my $log = $CLASS->session->log;
$log->{_logger} = $origLogger;
undef $origLogger;
$sub->($last_logged);
return \@logged;
}
#----------------------------------------------------------------------------