Bug 28615 - Add a simple way to mock Koha::Logger
Summary: Add a simple way to mock Koha::Logger
Status: CLOSED FIXED
Alias: None
Product: Koha
Classification: Unclassified
Component: Test Suite (show other bugs)
Version: master
Hardware: All All
: P5 - low enhancement (vote)
Assignee: Tomás Cohen Arazi
QA Contact: Testopia
URL:
Keywords:
Depends on: 28572
Blocks: 28618
  Show dependency treegraph
 
Reported: 2021-06-22 20:12 UTC by Tomás Cohen Arazi
Modified: 2022-06-06 20:25 UTC (History)
6 users (show)

See Also:
Change sponsored?: ---
Patch complexity: ---
Documentation contact:
Documentation submission:
Text to go in the release notes:
Version(s) released in:


Attachments
Bug 28615: Add a simple way to mock Koha::Logger (3.61 KB, patch)
2021-06-22 20:58 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 28615: Add POD (2.24 KB, patch)
2021-06-22 20:58 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 28615: Add a simple way to mock Koha::Logger (8.49 KB, patch)
2021-06-28 18:33 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 28615: Fix t/Auth_with_shibboleth.t (12.08 KB, patch)
2021-06-28 18:34 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 28615: Add a simple way to mock Koha::Logger (8.55 KB, patch)
2021-06-29 08:10 UTC, Martin Renvoize
Details | Diff | Splinter Review
Bug 28615: Fix t/Auth_with_shibboleth.t (12.14 KB, patch)
2021-06-29 08:10 UTC, Martin Renvoize
Details | Diff | Splinter Review
Bug 28615: Add a simple way to mock Koha::Logger (8.62 KB, patch)
2021-06-29 12:43 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 28615: Fix t/Auth_with_shibboleth.t (12.21 KB, patch)
2021-06-29 12:43 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 28615: (follow-up) Newer Test::MockModule forbid ->mock (967 bytes, patch)
2021-06-29 15:30 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 28615: (follow-up) Disable strict mode explicitly (1.63 KB, patch)
2021-06-29 15:30 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Tomás Cohen Arazi 2021-06-22 20:12:11 UTC
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.
Comment 1 Tomás Cohen Arazi 2021-06-22 20:58:10 UTC
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>
Comment 2 Tomás Cohen Arazi 2021-06-22 20:58:15 UTC
Created attachment 122307 [details] [review]
Bug 28615: Add POD

Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Comment 3 David Cook 2021-06-22 23:43:50 UTC
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?
Comment 4 Tomás Cohen Arazi 2021-06-22 23:46:07 UTC
(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?
Comment 5 David Cook 2021-06-22 23:48:18 UTC
(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.
Comment 6 Tomás Cohen Arazi 2021-06-22 23:51:47 UTC
(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!
Comment 7 David Cook 2021-06-23 00:04:34 UTC
(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.
Comment 8 David Cook 2021-06-23 00:09:35 UTC
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.
Comment 9 Tomás Cohen Arazi 2021-06-23 00:25:50 UTC
(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.
Comment 10 David Cook 2021-06-23 02:33:47 UTC
(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.
Comment 11 David Cook 2021-06-23 04:37:27 UTC
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.
Comment 12 Jonathan Druart 2021-06-23 08:17:38 UTC
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?
Comment 13 Tomás Cohen Arazi 2021-06-23 11:37:29 UTC
(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.
Comment 14 Marcel de Rooy 2021-06-23 12:55:49 UTC
t/db_dependent/Koha/REST/Plugin/PluginRoutes.t

my $logger = Test::MockModule->new('Koha::Logger');
$logger->mock('error', sub {
    shift;
    warn @_;
});
Comment 15 Marcel de Rooy 2021-06-23 12:58:37 UTC
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?
Comment 16 Jonathan Druart 2021-06-23 13:29:21 UTC
There is Test::Log4perl, but we will need to adjust all our test files.
Comment 17 Jonathan Druart 2021-06-24 10:51:07 UTC
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.
Comment 18 Tomás Cohen Arazi 2021-06-24 11:33:22 UTC
(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).
Comment 19 Jonathan Druart 2021-06-24 12:57:08 UTC
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.
Comment 20 Martin Renvoize 2021-06-28 13:37:08 UTC
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.
Comment 21 Tomás Cohen Arazi 2021-06-28 18:31:02 UTC
New revamped implementation coming
Comment 22 Tomás Cohen Arazi 2021-06-28 18:33:57 UTC
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>
Comment 23 Tomás Cohen Arazi 2021-06-28 18:34:03 UTC
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>
Comment 24 Martin Renvoize 2021-06-29 08:10:33 UTC
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>
Comment 25 Martin Renvoize 2021-06-29 08:10:38 UTC
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>
Comment 26 Martin Renvoize 2021-06-29 08:11:33 UTC
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.
Comment 27 Kyle M Hall 2021-06-29 12:43:24 UTC
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>
Comment 28 Kyle M Hall 2021-06-29 12:43:35 UTC
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>
Comment 29 Tomás Cohen Arazi 2021-06-29 13:09:56 UTC
Pushed to master for 21.11, thanks to everybody involved!
Comment 30 Tomás Cohen Arazi 2021-06-29 15:30:06 UTC
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>
Comment 31 Tomás Cohen Arazi 2021-06-29 15:30:11 UTC
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>
Comment 32 Jonathan Druart 2021-07-06 08:09:30 UTC
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.
Comment 33 Tomás Cohen Arazi 2021-07-06 12:03:12 UTC
(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.
Comment 34 Kyle M Hall 2021-07-09 14:46:20 UTC
Enhancement not backported for 21.05