Now we are getting rid of $ENV{DEBUG} and C4::Debug with the correct use of Koha::Logger, we need an easy way to make sure we don't get problems with log permissions in the context of tests and, why not, being able to test those $logger->debug calls.
Created attachment 122306 [details] [review] Bug 28615: Add a simple way to mock Koha::Logger This patch introduces a new method for mocking the Koha::Logger. As the POD says, it is used by calling t::lib::Mocks::mock_logger({ warn => 1 }); The warn parameter is optional, and controls wether any use of the logger will warn. The idea is that we can use that to write tests (that catch those warnings and thus the codepaths that trigger the call are properly tested, the same for the parameters to the call). I did a $ git grep 'Koha::Logger->get->debug' $ git grep 'Koha::Logger->get->warn' In order to find places in which we use the logger, and then find a test that would trigger it... to provide a useful test case. But I didn't... I tried with Overdues.t and Circulation.t and Export/Record.t but none worked [1]. So this is my test plan: 1. Apply this patch 2. Add the following line to t/db_dependent/Search.t just below the imports: t::lib::Mocks::mock_logger({ warn => 1 }); 3. Run: $ kshell k$ prove t/db_dependent/Search.t => SUCCESS: Suddenly every call to the logger is printing the parameter it got passed. 4. Sign off :-D [1] This is actually frustrating, because it means those codepaths are not traversed by the tests... Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Created attachment 122307 [details] [review] Bug 28615: Add POD Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Why do we need to mock the logger? Regarding log permissions, we'd just need to make sure to pass it the right configuration. I don't see why mocking would help in terms of testing $logger->debug calls?
(In reply to David Cook from comment #3) > Why do we need to mock the logger? > > Regarding log permissions, we'd just need to make sure to pass it the right > configuration. > > I don't see why mocking would help in terms of testing $logger->debug calls? How would you test a function call added a warning under certain conditions?
(In reply to Tomás Cohen Arazi from comment #4) > (In reply to David Cook from comment #3) > > Why do we need to mock the logger? > > > > Regarding log permissions, we'd just need to make sure to pass it the right > > configuration. > > > > I don't see why mocking would help in terms of testing $logger->debug calls? > > How would you test a function call added a warning under certain conditions? I'd re-create those certain conditions. I can understand mocking a third-party integration, but I don't see why it would be needed for the logger.
(In reply to David Cook from comment #5) > (In reply to Tomás Cohen Arazi from comment #4) > > (In reply to David Cook from comment #3) > > > Why do we need to mock the logger? > > > > > > Regarding log permissions, we'd just need to make sure to pass it the right > > > configuration. > > > > > > I don't see why mocking would help in terms of testing $logger->debug calls? > > > > How would you test a function call added a warning under certain conditions? > > I'd re-create those certain conditions. I can understand mocking a > third-party integration, but I don't see why it would be needed for the > logger. Of course you need to recreate the conditions. But would you prefer to set the logger in the tests and verify the file was written? Or better mock like this and catch the warn? The use case: you want to add a test (which is actually missing) to test C4::Acquisition::UpdateFine calls the logger with ->debug and passes some stuff to it. This is what I come up with. But I'm not attached to my ideas when better exist!
(In reply to Tomás Cohen Arazi from comment #6) > Of course you need to recreate the conditions. But would you prefer to set > the logger in the tests and verify the file was written? Or better mock like > this and catch the warn? I don't understand what you're asking here. I'd configure the logger to print to STDERR and capture that. I actually did that recently although I'm having trouble remembering where. I'll keep looking to see if I can find my example. > The use case: you want to add a test (which is actually missing) to test > C4::Acquisition::UpdateFine calls the logger with ->debug and passes some > stuff to it. This is what I come up with. But I'm not attached to my ideas > when better exist! I'll take a look for my code snippet and see if it helps.
Ah, here we go: https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=28477 That unit test code could be refined but it works without any mocking.
(In reply to David Cook from comment #8) > Ah, here we go: > > https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=28477 > > That unit test code could be refined but it works without any mocking. My goal is to make it trivial for devs to test behavior. There's nothing intrinsically bad about mocking the logger. Or doing it your way. You are actually mocking some other part of the same thing (the configuration) and manually capturing STDOUT/STDERR instead of 'the warn trick'. Your code is correct, and makes my point. Compare that boilerplate for just testing the logger is called, to just calling: t::lib::Mocks::mock_logger({warn=>1}); warning_is {}... Anyways, I always like different opinions and am open about this.
(In reply to Tomás Cohen Arazi from comment #9) > My goal is to make it trivial for devs to test behavior. There's nothing > intrinsically bad about mocking the logger. Or doing it your way. > > You are actually mocking some other part of the same thing (the > configuration) and manually capturing STDOUT/STDERR instead of 'the warn > trick'. I wouldn't refer to configuration as mocking. And you don't have to manually capture STDOUT/STDERR. You can use brian d foy's module Test::Output. I use that on other Perl projects for my unit tests. Koha doesn't require it, so I couldn't use it for my tests. > Your code is correct, and makes my point. Compare that boilerplate for just > testing the logger is called, to just calling: I was in a hurry to get that unit test done that day, but Test::Output can be used so that you don't have all that boiler plate. Using Test::Output and Test::Warn would be a more accurate test of how the code actually works in production. > Anyways, I always like different opinions and am open about this. Same. I like to avoid mocks wherever possible and use the real thing, but I figure code speaks louder than words, and I'm not planning on working on my logging testing any time soon or adding Test::Output as a dependency. I thought that I would offer an alternative though, especially since I think we really should stop using Log4Perl to log to files and instead log to STDERR. It'll solve log file permission issues and allow us to leverage built-in web server functionality for logging. But that's just my opinion.
Actually, if I recall correctly, we can't go with STDERR for Koha::Logger because Starman runs both the staff interface and the OPAC and it would put STDERR in just 1 file, so we'd lose the app separation by using STDERR. Right.
Wondering if we shouldn't use a mix of: * https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=120417 * what we have in t/Logger.t Basically it would mock log4perl_conf for the current prove command. But it needs to be "more global" or it won't work. Should not we actually copy $KOHA_CONF, modify it, and set KOHA_CONF to the new file for the current prove command?
(In reply to Jonathan Druart from comment #12) > Wondering if we shouldn't use a mix of: > * https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=120417 > * what we have in t/Logger.t > > Basically it would mock log4perl_conf for the current prove command. > > But it needs to be "more global" or it won't work. Should not we actually > copy $KOHA_CONF, modify it, and set KOHA_CONF to the new file for the > current prove command? I don't fully understand the added value of having a full blown log4perl setup when we only want to test if log4perl is called and how. Maybe we are thinking about different things. If we were to use something like that, I'd suggest using Test::Output as suggested by David so writing tests for those calls is less painful.
t/db_dependent/Koha/REST/Plugin/PluginRoutes.t my $logger = Test::MockModule->new('Koha::Logger'); $logger->mock('error', sub { shift; warn @_; });
t::lib::Mocks::mock_logger({ warn => 1 }); Koha::Logger->get->info('test'); Koha::Logger->get->warn('warn'); This does not seem to work, because we are too late. Do you expect users of mock_logger to mock in a BEGIN block?
There is Test::Log4perl, but we will need to adjust all our test files.
Since bug 28606 t/Auth_with_shibboleth.t is failing 12:06:13 koha_1 | Log::Log4perl configuration looks suspicious: No loggers defined at /usr/share/perl5/Log/Log4perl/Config.pm line 325.
(In reply to Jonathan Druart from comment #17) > Since bug 28606 t/Auth_with_shibboleth.t is failing > > 12:06:13 koha_1 | Log::Log4perl configuration looks suspicious: No > loggers defined at /usr/share/perl5/Log/Log4perl/Config.pm line 325. Tests in t/ should not depend on a setup (i.e. should be mocked).
The following line: t::lib::Mocks::mock_logger({ warn => 1 }); needs to be: my $m = t::lib::Mocks::mock_logger({ warn => 1 }); Or the module won't be mocked correctly.
I started refining this a bit to work a little more along the lines of Test::Warnings or Test::Mojo.. I've handed my work over to Tomas again now.. bit of teamwork going on in the background.
New revamped implementation coming
Created attachment 122480 [details] [review] Bug 28615: Add a simple way to mock Koha::Logger This patch introduces a new way to mock and test Koha::Logger. As the POD says, it is used by calling my $logger = t::lib::Mocks::Logger->new(); It then provides convenient methods for testing the logging itself per log-level: * warn_is * warn_like * debug_is * debug_like ... Methods for counting the logging activity and also for clearing the mock buffer are provided as well. This is covered in the POD and also on the follow-up, that makes use of this to fix Auth_with_shibboleth.t To test: 1. Run: $ kshell k$ prove t/Auth_with_shibboleth.t => FAIL: Tests fail! It expects some warns but they are not returned by the lib 2. Apply this patches 3. Repeat 1 => SUCCESS: Tests pass! The tests now use the new lib, and they correctly find the logging Auth_with_shibboleth.pm does on function calls. 4. Sign off :-D Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Created attachment 122481 [details] [review] Bug 28615: Fix t/Auth_with_shibboleth.t This patch makes t/Auth_with_shibboleth.t use the new t::lib::Mocks::Logger tools Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Created attachment 122484 [details] [review] Bug 28615: Add a simple way to mock Koha::Logger This patch introduces a new way to mock and test Koha::Logger. As the POD says, it is used by calling my $logger = t::lib::Mocks::Logger->new(); It then provides convenient methods for testing the logging itself per log-level: * warn_is * warn_like * debug_is * debug_like ... Methods for counting the logging activity and also for clearing the mock buffer are provided as well. This is covered in the POD and also on the follow-up, that makes use of this to fix Auth_with_shibboleth.t To test: 1. Run: $ kshell k$ prove t/Auth_with_shibboleth.t => FAIL: Tests fail! It expects some warns but they are not returned by the lib 2. Apply this patches 3. Repeat 1 => SUCCESS: Tests pass! The tests now use the new lib, and they correctly find the logging Auth_with_shibboleth.pm does on function calls. 4. Sign off :-D Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io> Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>
Created attachment 122485 [details] [review] Bug 28615: Fix t/Auth_with_shibboleth.t This patch makes t/Auth_with_shibboleth.t use the new t::lib::Mocks::Logger tools Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io> Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>
This is great and should lead to much simpler testing in the future.. I think we've arrived at a great end point. Thanks for taking the baton and completing the work Tomas. Signing off.
Created attachment 122488 [details] [review] Bug 28615: Add a simple way to mock Koha::Logger This patch introduces a new way to mock and test Koha::Logger. As the POD says, it is used by calling my $logger = t::lib::Mocks::Logger->new(); It then provides convenient methods for testing the logging itself per log-level: * warn_is * warn_like * debug_is * debug_like ... Methods for counting the logging activity and also for clearing the mock buffer are provided as well. This is covered in the POD and also on the follow-up, that makes use of this to fix Auth_with_shibboleth.t To test: 1. Run: $ kshell k$ prove t/Auth_with_shibboleth.t => FAIL: Tests fail! It expects some warns but they are not returned by the lib 2. Apply this patches 3. Repeat 1 => SUCCESS: Tests pass! The tests now use the new lib, and they correctly find the logging Auth_with_shibboleth.pm does on function calls. 4. Sign off :-D Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io> Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com> Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Created attachment 122489 [details] [review] Bug 28615: Fix t/Auth_with_shibboleth.t This patch makes t/Auth_with_shibboleth.t use the new t::lib::Mocks::Logger tools Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io> Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com> Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Pushed to master for 21.11, thanks to everybody involved!
Created attachment 122496 [details] [review] Bug 28615: (follow-up) Newer Test::MockModule forbid ->mock In strict mode, ->mock is forbidden and ->redefine needs to be used instead. I tested this on buster to see if it breaks something, but it doesn't. Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Created attachment 122497 [details] [review] Bug 28615: (follow-up) Disable strict mode explicitly So Debian 9's version of Test::MockModule doens't have ->redefine, and Ubuntu 20.04's doesn't recognise qw(nostrict). So the only solution is to just remove the keywords use completely and move back to using ->mock, as the rest of the codebase. FIXME: using ->mock might be hiding some errors (like a method not being defined/removed) and should be avoided. ->redefine will explode if the method doesn't already exist, which is what we want, to catch this kind of errors. That's why ->mock in strict mode is forbidden. We should try packaging a newer Test::MockModule ourselves. Tested on master-buster, master-stretch and master-focal. Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
I thought we would need to mock it for every test where Koha::Logger was used. But I added a Koha::Logger->get->warn call to AddIssue and t/db_dependent/Circulation.t is passing. Did you explain why t/Auth_with_shibboleth.t was failing with the following error/warning? t/Auth_with_shibboleth.t .. 1/17 Log::Log4perl configuration looks suspicious: No loggers defined at /usr/share/perl5/Log/Log4perl/Config.pm line 325.
(In reply to Jonathan Druart from comment #32) > I thought we would need to mock it for every test where Koha::Logger was > used. > > But I added a Koha::Logger->get->warn call to AddIssue and > t/db_dependent/Circulation.t is passing. Maybe we need to do something along this lines, so no call to the logger remains untested: https://metacpan.org/dist/Test-NoWarnings/source/lib/Test/NoWarnings.pm#L45 I thought about writing something like that but wasn't sure, and decided to see how things go with the implementation I proposed. > Did you explain why t/Auth_with_shibboleth.t was failing with the following > error/warning? > t/Auth_with_shibboleth.t .. 1/17 Log::Log4perl configuration looks > suspicious: No loggers defined at /usr/share/perl5/Log/Log4perl/Config.pm > line 325. That error points to an empty configuration. Not sure what you mean.
Enhancement not backported for 21.05