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"
Caused by commit 490a056f59d0aae52fde84e3450f29b3bc09c87d Bug 22678: Use Koha::Logger for Mojolicious API logger
Created attachment 147113 [details] [review] Bug 33020: Add test
(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).
*** Bug 32490 has been marked as a duplicate of this bug. ***
Created attachment 147116 [details] [review] Bug 33020: Add missing Koha::Logger->history
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
Not ready for testing, see last comment.
(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)
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 :)
Created attachment 147138 [details] [review] Bug 33020: Add test Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Created attachment 147139 [details] [review] Bug 33020: Add missing Koha::Logger->history Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
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>
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>
Created attachment 147404 [details] [review] Bug 33020: (QA follow-up) POD and chmod
Pushed to master for 23.05. Nice work everyone, thanks!
(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?
(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?
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.
(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?
(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
In master there is no TRACE, only the "GET 404" line.
(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.
(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.
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
(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.
Nice work everyone! Pushed to stable for 22.11.x
Missing dependencies for 22.05.x, no backport.
(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