Bug 33020

Summary: Unsupported method history
Product: Koha Reporter: Jonathan Druart <jonathan.druart>
Component: REST APIAssignee: David Cook <dcook>
Status: CLOSED FIXED QA Contact:
Severity: major    
Priority: P5 - low CC: dcook, lucas, m.de.rooy, martin.renvoize, pedro.amorim, tomascohen
Version: unspecified   
Hardware: All   
OS: All   
Change sponsored?: --- Patch complexity: Small patch
Documentation contact: Documentation submission:
Text to go in the release notes:
Version(s) released in:
23.05.00,22.11.04
Bug Depends on: 22678    
Bug Blocks:    
Attachments: Bug 33020: Add test
Bug 33020: Add missing Koha::Logger->history
Bug 33020: Add test
Bug 33020: Add missing Koha::Logger->history
Bug 33020: Add test
Bug 33020: Add missing Koha::Logger->history
Bug 33020: (QA follow-up) POD and chmod

Description Jonathan Druart 2023-02-21 09:38:19 UTC
I am seeing something weird for a couple of weeks. I've noticed it when working on the REST API but that may be related to something else as well.

To recreate:
curl -u koha:koha --request GET 'http://localhost:8081/api/v1/acquisition/vendors' 

Note that this route does not exist, it's acquisition*s*

Then the client is receiving:
Can't use an undefined value as an ARRAY reference at template mojo/debug.html.ep line 288.

and a mojo stacktrace

The server is logging:
/var/log/koha/kohadev/plack-api-error.log <==                                                         
[2023/02/21 09:35:02] [ERROR] Can't use an undefined value as an ARRAY reference at template mojo/debug.html.ep line 288.
Context:                                                                                                  
  283:               </div>                                                                               
  284:               <div class="tap tap-border-top">tap for more</div>                              
  285:             </div>                                                                                 
  286:           </div>                                                                                   
  287:           <div class="row">                                                                        
  288:             % if (@{app->log->history}) {                                                          
  289:                 % my $log = join '', map { scalar app->log->format->(@$_) } @{app->log->history};
  290:                 <pre class="mojo-terminal"><code class="nohighlight"><%= $log %></code></pre>
  291:             % }                                                                                    
  292:             % else {                                                                               
  293:               <div class="alert alert-warning wide" role="alert">            
Traceback (most recent call first):                                                                       
  File "template mojo/debug.html.ep", line 288, in "Mojo::Template::Sandbox::a05f7134cc0618f09495937a2bcc8996"
  File "/usr/share/perl5/Mojo/Template.pm", line 160, in "Mojo::Template"           
  File "/usr/share/perl5/Mojo/Template.pm", line 160, in "Mojo::Template"
  File "/usr/share/perl5/Mojo/Template.pm", line 163, in "Mojo::Template"  
  File "/usr/share/perl5/Mojo/Template.pm", line 173, in "Mojo::Template"                
  File "/usr/share/perl5/Mojolicious/Plugin/EPLRenderer.pm", line 40, in "Mojolicious::Plugin::EPLRenderer"
  File "/usr/share/perl5/Mojolicious/Plugin/EPRenderer.pm", line 39, in "Mojolicious::Plugin::EPRenderer"
  File "/usr/share/perl5/Mojolicious/Renderer.pm", line 225, in "Mojolicious::Renderer"
  File "/usr/share/perl5/Mojolicious/Renderer.pm", line 106, in "Mojolicious::Renderer"
  File "/usr/share/perl5/Mojolicious/Controller.pm", line 147, in "Mojolicious::Controller"
  File "/usr/share/perl5/Mojolicious/Controller.pm", line 159, in "Mojolicious::Controller"
  File "/usr/share/perl5/Mojolicious/Plugin/DefaultHelpers.pm", line 131, in "Mojolicious::Plugin::DefaultHelpers"
  File "/usr/share/perl5/Mojolicious/Plugin/DefaultHelpers.pm", line 112, in "Mojolicious::Plugin::DefaultHelpers"
  File "/usr/share/perl5/Mojolicious/Plugin/DefaultHelpers.pm", line 52, in "Mojolicious::Plugin::DefaultHelpers"
  File "/usr/share/perl5/Mojolicious/Renderer.pm", line 74, in "Mojolicious::Renderer"                                                                                                                               
  File "/usr/share/perl5/Mojolicious.pm", line 125, in "Mojolicious"
  File "/usr/share/perl5/Mojolicious.pm", line 134, in "Mojolicious"
  File "/usr/share/perl5/Mojolicious/Plugins.pm", line 15, in "Mojolicious::Plugins"
  File "/usr/share/perl5/Mojolicious.pm", line 200, in "Mojolicious"                                 
  File "/usr/share/perl5/Mojolicious.pm", line 200, in "Mojolicious"        
  File "/usr/share/perl5/Mojolicious/Plugins.pm", line 15, in "Mojolicious::Plugins"               
  File "/usr/share/perl5/Mojolicious/Plugins.pm", line 18, in "Mojolicious::Plugins"
  File "/usr/share/perl5/Mojolicious.pm", line 139, in "Mojolicious"
  File "/usr/share/perl5/Mojo/Server.pm", line 70, in "Mojo::Server"
  File "/usr/share/perl5/Mojo/EventEmitter.pm", line 15, in "Mojo::EventEmitter"
  File "/usr/share/perl5/Mojo/Server/PSGI.pm", line 20, in "Mojo::Server::PSGI"
  File "/usr/share/perl5/Mojo/Server/PSGI.pm", line 38, in "Mojo::Server::PSGI"
  File "/usr/share/perl5/Plack/Middleware/LogWarn.pm", line 22, in "Plack::Middleware::LogWarn"
  File "/usr/share/perl5/Plack/Component.pm", line 50, in "Plack::Component"
  File "/usr/share/perl5/Plack/Middleware/Log4perl.pm", line 30, in "Plack::Middleware::Log4perl"
  File "/usr/share/perl5/Plack/Component.pm", line 50, in "Plack::Component"
  File "/usr/share/perl5/Plack/App/URLMap.pm", line 71, in "Plack::App::URLMap"
  File "/usr/share/perl5/Plack/Component.pm", line 50, in "Plack::Component"
  File "/kohadevbox/koha/Koha/Middleware/RealIP.pm", line 64, in "Koha::Middleware::RealIP"
  File "/usr/share/perl5/Plack/Component.pm", line 50, in "Plack::Component"
  File "/kohadevbox/koha/Koha/Middleware/SetEnv.pm", line 105, in "Koha::Middleware::SetEnv"
  File "/usr/share/perl5/Plack/Component.pm", line 50, in "Plack::Component"
  File "/usr/share/perl5/Plack/Middleware/Static.pm", line 18, in "Plack::Middleware::Static"
  File "/usr/share/perl5/Plack/Component.pm", line 50, in "Plack::Component"
  File "/usr/share/perl5/Plack/Middleware/ReverseProxy.pm", line 68, in "Plack::Middleware::ReverseProxy"
  File "/usr/share/perl5/Plack/Component.pm", line 50, in "Plack::Component"
  File "/usr/share/perl5/Plack/Middleware/Lint.pm", line 24, in "Plack::Middleware::Lint"
  File "/usr/share/perl5/Plack/Component.pm", line 50, in "Plack::Component"
  File "/usr/share/perl5/Plack/Middleware/StackTrace.pm", line 38, in "Plack::Middleware::StackTrace"
  File "/usr/share/perl5/Try/Tiny.pm", line 100, in "Try::Tiny"
  File "/usr/share/perl5/Try/Tiny.pm", line 93, in "Try::Tiny"
  File "/usr/share/perl5/Plack/Middleware/StackTrace.pm", line 42, in "Plack::Middleware::StackTrace"
  File "/usr/share/perl5/Plack/Component.pm", line 50, in "Plack::Component"
  File "/usr/share/perl5/Plack/Middleware/AccessLog.pm", line 27, in "Plack::Middleware::AccessLog"
  File "/usr/share/perl5/Plack/Component.pm", line 50, in "Plack::Component"
  File "/usr/share/perl5/Plack/Util.pm", line 145, in "Plack::Util"
  File "/usr/share/perl5/Plack/Util.pm", line 145, in "Plack::Util"
  File "/usr/share/perl5/Starman/Server.pm", line 195, in "Starman::Server"
  File "/usr/share/perl5/Starman/Server.pm", line 298, in "Starman::Server"
  File "/usr/share/perl5/Net/Server.pm", line 72, in "Net::Server"
  File "/usr/share/perl5/Net/Server/PreFork.pm", line 225, in "Net::Server::PreFork"
  File "/usr/share/perl5/Net/Server/PreFork.pm", line 225, in "Net::Server::PreFork"
  File "/usr/share/perl5/Net/Server/PreFork.pm", line 183, in "Net::Server::PreFork"
  File "/usr/share/perl5/Net/Server/PreFork.pm", line 373, in "Net::Server::PreFork"
  File "/usr/share/perl5/Net/Server/PreFork.pm", line 292, in "Net::Server::PreFork"
  File "/usr/share/perl5/Starman/Server.pm", line 164, in "Starman::Server"
  File "/usr/share/perl5/Net/Server/PreFork.pm", line 109, in "Net::Server::PreFork"
  File "/usr/share/perl5/Net/Server.pm", line 58, in "Net::Server"
  File "/usr/share/perl5/Starman/Server.pm", line 106, in "Starman::Server"
  File "/usr/share/perl5/Plack/Handler/Starman.pm", line 25, in "Plack::Handler::Starman"
  File "/usr/share/perl5/Plack/Loader/Delayed.pm", line 20, in "Plack::Loader::Delayed"
  File "/usr/share/perl5/Plack/Runner.pm", line 279, in "Plack::Runner"
  File "/usr/bin/starman", line 38, in "main"

==> /var/log/koha/kohadev/plack-error.log <==
ERROR: Unsupported method history at /kohadevbox/koha/Koha/Logger.pm line 139.
ERROR: Unsupported method history at /kohadevbox/koha/Koha/Logger.pm line 139.

==> /var/log/koha/kohadev/plack.log <==
172.18.0.1 - - [21/Feb/2023:09:35:02 +0000] "GET /api/v1/app.pl/api/v1/acquisition/vendors HTTP/1.1" 500 5645 "-" "curl/7.68.0"
Comment 1 Jonathan Druart 2023-02-22 08:38:18 UTC
Caused by
  commit 490a056f59d0aae52fde84e3450f29b3bc09c87d
  Bug 22678: Use Koha::Logger for Mojolicious API logger
Comment 2 Jonathan Druart 2023-02-22 09:21:09 UTC
Created attachment 147113 [details] [review]
Bug 33020: Add test
Comment 3 Jonathan Druart 2023-02-22 09:25:53 UTC
(In reply to Jonathan Druart from comment #2)
> Created attachment 147113 [details] [review] [review]
> Bug 33020: Add test

Note that www tests will need to export KOHA_INTRANET_URL because of temporary ktd's issue (see #335).
Comment 4 Jonathan Druart 2023-02-22 09:29:01 UTC
*** Bug 32490 has been marked as a duplicate of this bug. ***
Comment 5 Jonathan Druart 2023-02-22 10:02:55 UTC
Created attachment 147116 [details] [review]
Bug 33020: Add missing Koha::Logger->history
Comment 6 Jonathan Druart 2023-02-22 10:04:41 UTC
This patch is fixing the problem and makes the test passes. However we lost some debug info we had before.

Prior to 22678 we had

==> /var/log/koha/kohadev/plack-error.log <==
[2023-02-22 10:03:14.20431] [4790] [trace] [Ez_NLp-F8prN] GET "/api/v1/acquisition/vendors"
[2023-02-22 10:03:14.21279] [4790] [trace] [Ez_NLp-F8prN] Template "not_found.development.html.ep" not found
[2023-02-22 10:03:14.21307] [4790] [trace] [Ez_NLp-F8prN] Template "not_found.html.ep" not found
[2023-02-22 10:03:14.21327] [4790] [trace] [Ez_NLp-F8prN] Rendering template "mojo/debug.html.ep"
[2023-02-22 10:03:14.39498] [4790] [trace] [Ez_NLp-F8prN] 404 Not Found (0.190631s, 5.246/s)

==> /var/log/koha/kohadev/plack.log <==
172.19.0.1 - - [22/Feb/2023:10:03:14 +0000] "GET /api/v1/app.pl/api/v1/acquisition/vendors HTTP/1.1" 404 - "-" "curl/7.68.0"

Now we only see the 404 from plack.log
Comment 7 Jonathan Druart 2023-02-22 12:44:29 UTC
Not ready for testing, see last comment.
Comment 8 Marcel de Rooy 2023-02-22 13:07:05 UTC
(In reply to Jonathan Druart from comment #7)
> Not ready for testing, see last comment.

[2023/02/22 12:53:13] [WARN] ERROR: Unsupported method history at /usr/share/koha/Koha/Logger.pm line 135.
[2023/02/22 13:06:22] [TRACE] GET "/api/v1/doesnt"
[2023/02/22 13:06:22] [TRACE] Template "not_found.development.html.ep" not found
[2023/02/22 13:06:22] [TRACE] Template "not_found.html.ep" not found
[2023/02/22 13:06:22] [TRACE] Rendering template "mojo/debug.html.ep"
[2023/02/22 13:06:22] [TRACE] 404 Not Found (0.273781s, 3.653/s)
Comment 9 Marcel de Rooy 2023-02-22 13:07:56 UTC
Check your log4perl.conf

log4perl.logger.plack-api = TRACE, PLACKAPI
log4perl.appender.PLACKAPI=Log::Log4perl::Appender::File
log4perl.appender.PLACKAPI.filename=/var/log/koha/myclone/plack-api-error.log
log4perl.appender.PLACKAPI.mode=append
log4perl.appender.PLACKAPI.layout=PatternLayout
log4perl.appender.PLACKAPI.layout.ConversionPattern=[%d] [%p] %m%n
log4perl.appender.PLACKAPI.utf8=1

When I set trace, I get trace :)
Comment 10 Marcel de Rooy 2023-02-22 13:11:39 UTC
Created attachment 147138 [details] [review]
Bug 33020: Add test

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 11 Marcel de Rooy 2023-02-22 13:11:42 UTC
Created attachment 147139 [details] [review]
Bug 33020: Add missing Koha::Logger->history

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 12 Nick Clemens 2023-02-24 21:02:48 UTC
Created attachment 147402 [details] [review]
Bug 33020: Add test

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Signed-off-by: Nick Clemens <nick@bywatersolutions.com>
Comment 13 Nick Clemens 2023-02-24 21:02:50 UTC
Created attachment 147403 [details] [review]
Bug 33020: Add missing Koha::Logger->history

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Signed-off-by: Nick Clemens <nick@bywatersolutions.com>
Comment 14 Nick Clemens 2023-02-24 21:02:52 UTC
Created attachment 147404 [details] [review]
Bug 33020: (QA follow-up) POD and chmod
Comment 15 Tomás Cohen Arazi 2023-02-27 14:42:44 UTC
Pushed to master for 23.05.

Nice work everyone, thanks!
Comment 16 Jonathan Druart 2023-02-28 08:23:04 UTC
(In reply to Marcel de Rooy from comment #9)
> Check your log4perl.conf
> 
> log4perl.logger.plack-api = TRACE, PLACKAPI
> log4perl.appender.PLACKAPI=Log::Log4perl::Appender::File
> log4perl.appender.PLACKAPI.filename=/var/log/koha/myclone/plack-api-error.log
> log4perl.appender.PLACKAPI.mode=append
> log4perl.appender.PLACKAPI.layout=PatternLayout
> log4perl.appender.PLACKAPI.layout.ConversionPattern=[%d] [%p] %m%n
> log4perl.appender.PLACKAPI.utf8=1
> 
> When I set trace, I get trace :)

This then was the behaviour before this patch. Shouldn't we have it back for dev installs?
Comment 17 Marcel de Rooy 2023-02-28 09:43:26 UTC
(In reply to Jonathan Druart from comment #16)
> (In reply to Marcel de Rooy from comment #9)
> > Check your log4perl.conf
> > 
> > log4perl.logger.plack-api = TRACE, PLACKAPI
> > log4perl.appender.PLACKAPI=Log::Log4perl::Appender::File
> > log4perl.appender.PLACKAPI.filename=/var/log/koha/myclone/plack-api-error.log
> > log4perl.appender.PLACKAPI.mode=append
> > log4perl.appender.PLACKAPI.layout=PatternLayout
> > log4perl.appender.PLACKAPI.layout.ConversionPattern=[%d] [%p] %m%n
> > log4perl.appender.PLACKAPI.utf8=1
> > 
> > When I set trace, I get trace :)
> 
> This then was the behaviour before this patch. Shouldn't we have it back for
> dev installs?

We relied on Mojo for that. I do not really see the need of building it into Koha personally, since you can adjust it very easily (just one sed line in your Dockerfile or so). But you are welcome to open a new report. This does not only pertain to this PLACKAPI setting but probably for others too?
Comment 18 Jonathan Druart 2023-02-28 10:23:54 UTC
I am just saying there is a behaviour change caused by this patch, we lost debug info. That was not expected, and that's actually why I didn't want to push the patches.
Comment 19 Marcel de Rooy 2023-02-28 11:13:10 UTC
(In reply to Jonathan Druart from comment #18)
> I am just saying there is a behaviour change caused by this patch, we lost
> debug info. That was not expected, and that's actually why I didn't want to
> push the patches.

I dont understand. Compare comment8 and comment9. What is missing?
Comment 20 Marcel de Rooy 2023-02-28 11:13:43 UTC
(In reply to Marcel de Rooy from comment #19)
> (In reply to Jonathan Druart from comment #18)
> > I am just saying there is a behaviour change caused by this patch, we lost
> > debug info. That was not expected, and that's actually why I didn't want to
> > push the patches.
> 
> I dont understand. Compare comment8 and comment9. What is missing?

comment6 and comment8
Comment 21 Jonathan Druart 2023-02-28 11:23:32 UTC
In master there is no TRACE, only the "GET 404" line.
Comment 22 Marcel de Rooy 2023-02-28 11:55:29 UTC
(In reply to Jonathan Druart from comment #21)
> In master there is no TRACE, only the "GET 404" line.

I give up :) We are not on the same page here.
Comment 23 Tomás Cohen Arazi 2023-02-28 12:36:22 UTC
(In reply to Marcel de Rooy from comment #22)
> (In reply to Jonathan Druart from comment #21)
> > In master there is no TRACE, only the "GET 404" line.
> 
> I give up :) We are not on the same page here.

I've made KTD set TRACE by default for the API. Hope it helps.
Comment 24 Tomás Cohen Arazi 2023-02-28 13:13:35 UTC
I have reverted my patch for KTD for now. I'm getting this:

ERROR: you didn't tell me how to implement your appender 'TRACE' at /usr/share/perl5/Log/Log4perl/Config.pm line 367.

Can you clarify?

Look here for reference on what I tried (now commented out):

https://gitlab.com/koha-community/koha-testing-docker/-/commit/85e3e54f89a7b3341e948311a904ac875776d9ba
Comment 25 Marcel de Rooy 2023-02-28 13:17:01 UTC
(In reply to Tomás Cohen Arazi from comment #24)
> I have reverted my patch for KTD for now. I'm getting this:
> 
> ERROR: you didn't tell me how to implement your appender 'TRACE' at
> /usr/share/perl5/Log/Log4perl/Config.pm line 367.
> 
> Can you clarify?
> 
> Look here for reference on what I tried (now commented out):
> 
> https://gitlab.com/koha-community/koha-testing-docker/-/commit/
> 85e3e54f89a7b3341e948311a904ac875776d9ba

Does not look good. You should specifiy one level. This level and higher you will get. So TRACE includes WARN. Not the other way around.
Comment 26 Matt Blenkinsop 2023-03-01 09:32:32 UTC
Nice work everyone!

Pushed to stable for 22.11.x
Comment 27 Lucas Gass 2023-03-08 14:11:24 UTC
Missing dependencies for 22.05.x, no backport.
Comment 28 Tomás Cohen Arazi 2023-03-17 11:30:10 UTC
(In reply to Marcel de Rooy from comment #25)
> (In reply to Tomás Cohen Arazi from comment #24)
> > I have reverted my patch for KTD for now. I'm getting this:
> > 
> > ERROR: you didn't tell me how to implement your appender 'TRACE' at
> > /usr/share/perl5/Log/Log4perl/Config.pm line 367.
> > 
> > Can you clarify?
> > 
> > Look here for reference on what I tried (now commented out):
> > 
> > https://gitlab.com/koha-community/koha-testing-docker/-/commit/
> > 85e3e54f89a7b3341e948311a904ac875776d9ba
> 
> Does not look good. You should specifiy one level. This level and higher you
> will get. So TRACE includes WARN. Not the other way around.

Thanks, I added TRACE now, hope it works for everyone:

https://gitlab.com/koha-community/koha-testing-docker/-/commit/28af8d92b92b1e9ed0daae144ca5c6e9154a05f2#f8e5d7813c78b88a7f843779149fcc428aded6bf_147_144