Bug 16357 - Plack error logs are not time stamped
Summary: Plack error logs are not time stamped
Status: Needs Signoff
Alias: None
Product: Koha
Classification: Unclassified
Component: Architecture, internals, and plumbing (show other bugs)
Version: master
Hardware: All All
: P3 normal (vote)
Assignee: Mason James
QA Contact: Testopia
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2016-04-26 16:10 UTC by Barton Chittenden
Modified: 2018-08-14 20:35 UTC (History)
7 users (show)

See Also:
Change sponsored?: ---
Patch complexity: ---
Bot Control: ---
When did the bot last check this:
Who signed the patch off:
Text to go in the release notes:


Attachments
Bug 16357 - Plack error logs are not time stamped (2.34 KB, patch)
2018-02-16 13:17 UTC, Mason James
Details | Diff | Splinter Review
Bug 16357 - Plack error logs are not time stamped (follow up) fix typo in comment (1.33 KB, patch)
2018-02-16 13:28 UTC, Mason James
Details | Diff | Splinter Review
Bug 16357 - Plack error logs are not time stamped (follow up) enable UTF8 (1.35 KB, patch)
2018-02-17 03:15 UTC, Mason James
Details | Diff | Splinter Review
Bug 16357: (follow-up) Use Koha::Logger and add fatal errors (2.59 KB, patch)
2018-02-28 12:56 UTC, Lari Taskula
Details | Diff | Splinter Review
Bug 16357: (follow-up) Log and timestamp fatal errors (1.58 KB, patch)
2018-02-28 23:58 UTC, Mason James
Details | Diff | Splinter Review
Bug 16357 - Use Koha::Logger via Plack::Middleware::Log4perl (4.70 KB, patch)
2018-03-28 20:06 UTC, David Bourgault
Details | Diff | Splinter Review
Bug 16357 - Plack error logs are not time stamped (1.68 KB, patch)
2018-08-07 14:02 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 16357 - Plack error logs are not time stamped (follow up) fix typo in comment (831 bytes, patch)
2018-08-07 14:02 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 16357 - Plack error logs are not time stamped (follow up) enable UTF8 (839 bytes, patch)
2018-08-07 14:02 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 16357: (follow-up) Use Koha::Logger and add fatal errors (1.83 KB, patch)
2018-08-07 14:02 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 16357 - Use Koha::Logger via Plack::Middleware::Log4perl (3.36 KB, patch)
2018-08-07 14:02 UTC, Jonathan Druart
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Barton Chittenden 2016-04-26 16:10:35 UTC
The log /var/log/koha/<instance>/plack-error.log gives no indication of when the error occurred, making historical trouble-shooting very difficult.
Comment 1 Kyle M Hall 2016-10-28 16:26:52 UTC
I believe this would require submitting a patch to Plack::Middleware::AccessLog or starman to allow the format to be set via environment variable.
Comment 2 Kyle M Hall 2016-10-28 16:34:47 UTC
or possibly Plack::Runner
Comment 3 Mason James 2018-02-04 01:18:09 UTC
i finally have a working patch for this, will upload soon(TM)...
Comment 4 Mason James 2018-02-16 13:17:32 UTC
Created attachment 71752 [details] [review]
Bug 16357 - Plack error logs are not time stamped

to test this patch..

1/ start plack
$ sudo koha-plack --start mylib

2/ tail log file, notice error log has no timestamps :(

$ sudo tail -f /var/log/koha/mylib/plack-error.log
 ...
 Initiating an anonymous session... at /usr/share/koha/lib/C4/Auth.pm line 1294.
 Checking Auth at /usr/share/koha/lib/C4/Auth.pm line 815.

3/ apply patch

4 manually copy new plack file to live location
$ sudo cp ./debian/templates/plack.psgi  /etc/koha/

5/ restart plack
$ sudo koha-plack --restart mylib

6/ tail log file, notice error log now has timestamps :)
$ sudo tail -f /var/log/koha/mylib/plack-error.log
 ...
 2018/02/11 08:56:29 Initiating an anonymous session... at /usr/share/koha/lib/C4/Auth.pm line 1294.
 2018/02/11 08:56:33 Checking Auth at /usr/share/koha/lib/C4/Auth.pm line 815.
Comment 5 Mason James 2018-02-16 13:22:08 UTC
(In reply to Mason James from comment #3)
> i finally have a working patch for this, will upload soon(TM)...

sorry about the delay..

i thought i'd test the patch for a few days on some demo servers - it seems to be working well :)
Comment 6 Mason James 2018-02-16 13:28:43 UTC
Created attachment 71753 [details] [review]
Bug 16357 - Plack error logs are not time stamped (follow up) fix typo in comment
Comment 7 Mason James 2018-02-17 03:15:04 UTC
Created attachment 71871 [details] [review]
Bug 16357 - Plack error logs are not time stamped (follow up) enable UTF8
Comment 8 Lari Taskula 2018-02-28 12:32:26 UTC
Hey! Great job! We have been scratching our head with the same problem.

Works nicely with warnings. What about fatal errors?

Could we use Koha::Logger and log4perl.conf with this?
Comment 9 Marcel de Rooy 2018-02-28 12:44:04 UTC
> Hey! Great job! We have been scratching our head with the same problem.
> 
> Works nicely with warnings. What about fatal errors?
> 
> Could we use Koha::Logger and log4perl.conf with this?

Mason: It seems to me that we should use Koha::Logger here and not add separate Log4Perl calls?
Comment 10 Lari Taskula 2018-02-28 12:56:02 UTC
Created attachment 72290 [details] [review]
Bug 16357: (follow-up) Use Koha::Logger and add fatal errors
Comment 11 Mason James 2018-02-28 18:47:09 UTC
(In reply to Marcel de Rooy from comment #9)
> > Hey! Great job! We have been scratching our head with the same problem.
> > 
> > Works nicely with warnings. What about fatal errors?
> > 
> > Could we use Koha::Logger and log4perl.conf with this?
> 
> Mason: It seems to me that we should use Koha::Logger here and not add
> separate Log4Perl calls?

yes, thats sounds fine to me

but i'm guessing that would require manually editing each instance's log4perl.conf file before that patch would work

i think without the manually editing each log4perl.conf file, Koha::Logger would probably not log anything? (which would be even worse than before)
Comment 12 Mason James 2018-02-28 18:52:22 UTC
(In reply to Lari Taskula from comment #10)
> Created attachment 72290 [details] [review] [review]
> Bug 16357: (follow-up) Use Koha::Logger and add fatal errors

hi Lari
i tested your patch, but could not get it to work

i manually edited an instance's log4perl.conf file, but all WARN messages stopped being added to the plack-error.log file


can someone else confirm Lari's patch?
Comment 13 Mason James 2018-02-28 23:58:38 UTC
Created attachment 72296 [details] [review]
Bug 16357: (follow-up) Log and timestamp fatal errors
Comment 14 Mason James 2018-03-01 00:08:22 UTC
(In reply to Mason James from comment #13)
> Created attachment 72296 [details] [review] [review]
> Bug 16357: (follow-up) Log and timestamp fatal errors

interestingly... after applying this patch some previously hidden errors are now revealed in the plack-error.log file

this new info looks useful for showing unidentified DBIx problems

2018/03/01 10:59:30 DBIx::Class::ResultSource::_minimal_valueset_satisfying_constraint(): Unable to satisfy requested constraint 'primary', missing values for column(s): 'borrowernumber' at /usr/share/koha/lib/Koha/Objects.pm line 92
2018/03/01 10:59:30 DBIx::Class::ResultSource::_minimal_valueset_satisfying_constraint(): Unable to satisfy requested constraint 'cardnumber', missing values for column(s): 'cardnumber' at /usr/share/koha/lib/Koha/Objects.pm line 92
Comment 15 Lari Taskula 2018-03-06 17:14:15 UTC
It seems that $SIG{__DIE__} catches dies inside eval blocks, thus generating a lot of useless "fatal" noise about missing modules inside some dependencies, such as Mojolicious.

Perhaps another approach needs to be considered. I'm currently looking at Plack::Middleware::Log4perl.
Comment 16 M. Tompsett 2018-03-15 01:27:04 UTC
Comment on attachment 72296 [details] [review]
Bug 16357: (follow-up) Log and timestamp fatal errors

Review of attachment 72296 [details] [review]:
-----------------------------------------------------------------

::: debian/templates/plack.psgi
@@ +41,5 @@
>  use Log::Log4perl qw(:easy);
>  Log::Log4perl->easy_init({ level => $WARN, utf8 => 1 });
>  my $logger = Log::Log4perl->get_logger(); # use the default logger style
> +$SIG{__WARN__} = sub { $logger->warn(shift) };
> +$SIG{__DIE__}  = sub { $logger->fatal(shift) };

I prefer using my ($message) = @_; because I believe it is less floody prone, though I could be wrong. And while I value vertical space too, I would have left the __WARN__ code unchanged, and mirrored that layout for __DIE__.

::: misc/plack/koha.psgi
@@ +9,5 @@
>  use Log::Log4perl qw(:easy);
>  Log::Log4perl->easy_init({ level => $WARN, utf8 => 1 });
>  my $logger = Log::Log4perl->get_logger(); # use the default logger style
> +$SIG{__WARN__} = sub { $logger->warn(shift) };
> +$SIG{__DIE__}  = sub { $logger->fatal(shift) };

If bug 20393 is valid, this change is unnecessary.
Comment 17 David Bourgault 2018-03-28 20:06:51 UTC
Created attachment 73404 [details] [review]
Bug 16357 - Use Koha::Logger via Plack::Middleware::Log4perl

Changes plack.psgi to use the Koha::Logger via Plack::Middleware::Log4perl.

Changes the log category to 'plack' to be more similar to the existing categories
Comment 18 Barton Chittenden 2018-07-25 23:06:12 UTC
Tried to test, patch does not apply on master.
Comment 19 Barton Chittenden 2018-08-01 20:20:54 UTC
Mason,

I'm really interested in having this, and I'd be happy to test and sign off if you can rebase.
Comment 20 Jonathan Druart 2018-08-07 14:02:10 UTC
Created attachment 77529 [details] [review]
Bug 16357 - Plack error logs are not time stamped

to test this patch..

1/ start plack
$ sudo koha-plack --start mylib

2/ tail log file, notice error log has no timestamps :(

$ sudo tail -f /var/log/koha/mylib/plack-error.log
 ...
 Initiating an anonymous session... at /usr/share/koha/lib/C4/Auth.pm line 1294.
 Checking Auth at /usr/share/koha/lib/C4/Auth.pm line 815.

3/ apply patch

4 manually copy new plack file to live location
$ sudo cp ./debian/templates/plack.psgi  /etc/koha/

5/ restart plack
$ sudo koha-plack --restart mylib

6/ tail log file, notice error log now has timestamps :)
$ sudo tail -f /var/log/koha/mylib/plack-error.log
 ...
 2018/02/11 08:56:29 Initiating an anonymous session... at /usr/share/koha/lib/C4/Auth.pm line 1294.
 2018/02/11 08:56:33 Checking Auth at /usr/share/koha/lib/C4/Auth.pm line 815.
Comment 21 Jonathan Druart 2018-08-07 14:02:15 UTC
Created attachment 77530 [details] [review]
Bug 16357 - Plack error logs are not time stamped (follow up) fix typo in comment
Comment 22 Jonathan Druart 2018-08-07 14:02:20 UTC
Created attachment 77531 [details] [review]
Bug 16357 - Plack error logs are not time stamped (follow up) enable UTF8
Comment 23 Jonathan Druart 2018-08-07 14:02:25 UTC
Created attachment 77532 [details] [review]
Bug 16357: (follow-up) Use Koha::Logger and add fatal errors
Comment 24 Jonathan Druart 2018-08-07 14:02:29 UTC
Created attachment 77533 [details] [review]
Bug 16357 - Use Koha::Logger via Plack::Middleware::Log4perl

Changes plack.psgi to use the Koha::Logger via Plack::Middleware::Log4perl.

Changes the log category to 'plack' to be more similar to the existing categories
Comment 25 Jonathan Druart 2018-08-07 14:02:48 UTC
Patches rebased.
Comment 26 Barton Chittenden 2018-08-14 20:12:32 UTC
It seems that the last patch in this set removed the signal handlers added by the previous patch, I'm not getting any fatals:

diff --git a/debian/templates/plack.psgi b/debian/templates/plack.psgi
index 2c65dc7..778befd 100644
--- a/debian/templates/plack.psgi
+++ b/debian/templates/plack.psgi
@@ -36,14 +36,8 @@ use Koha::Caches;
 use Koha::Cache::Memory::Lite;
 use Koha::Database;
 use Koha::DateUtils;
-
-#BZ 16357, add timestamps to warnings
 use Koha::Logger;
 
-my $logger = Koha::Logger->get({ interface => 'plack-error' });
-$SIG{__WARN__} = sub { $logger->warn(shift);  };
-$SIG{__DIE__}  = sub { $logger->fatal(shift); };
^^^^^^^^^^^^^^^
Comment 27 Jonathan Druart 2018-08-14 20:35:40 UTC
(In reply to Barton Chittenden from comment #26)
> It seems that the last patch in this set removed the signal handlers added
> by the previous patch, I'm not getting any fatals:

Previous patch did the same:
https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=73404