[Bug 41707] New: The DIE handler in C4::SIP::Trapper is logging non-SIP errors, causing log flooding.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41707 Bug ID: 41707 Summary: The DIE handler in C4::SIP::Trapper is logging non-SIP errors, causing log flooding. Initiative type: --- Sponsorship --- status: Product: Koha Version: Main Hardware: All OS: All Status: NEW Severity: enhancement Priority: P5 - low Component: SIP2 Assignee: koha-bugs@lists.koha-community.org Reporter: johanna.raisa@koha-suomi.fi QA Contact: testopia@bugs.koha-community.org The DIE handler should be more restrictive and only log errors where the call stack clearly originates from SIP modules (e.g., C4::SIP::*). The current implementation is not strict enough or may have edge cases. Found this kind of errors from our logs: [2026/01/23 13:42:47] [493898] [ERROR] [undef]@[undef]: commandline was not set during initialization at /usr/share/perl5/Net/Server.pm line 100. C4::SIP::Trapper::__ANON__ /home/koha/Koha/C4/SIP/Trapper.pm (70) -- You are receiving this mail because: You are watching all bug changes. You are the assignee for the bug.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41707 Katrin Fischer <katrin.fischer@bsz-bw.de> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |cornelius.hertfelder@bsz-bw | |.de -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41707 David Cook <dcook@prosentient.com.au> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |dcook@prosentient.com.au -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41707 Johanna Räisä <johanna.raisa@koha-suomi.fi> changed: What |Removed |Added ---------------------------------------------------------------------------- Assignee|koha-bugs@lists.koha-commun |johanna.raisa@koha-suomi.fi |ity.org | Status|NEW |Needs Signoff --- Comment #1 from Johanna Räisä <johanna.raisa@koha-suomi.fi> --- Created attachment 192093 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=192093&action=edit Bug 41707: Modify C4::SIP::Trapper DIE handling for better logging This patch improves the error handling in the SIP Trapper module by logging only SIP-related errors as errors and non-SIP errors as warnings. This change aims to reduce noise in the logs and make it easier to identify genuine SIP-related issues. Test plan: 1. Apply the patch 2. prove -lv t/db_dependent/SIP/Trapper.t 3. Ensure all tests pass without errors 4. Start the server: perl C4/SIP/SIPServer.pm /etc/koha/SIPconfig.xml 5. misc/sip_cli_emulator.pl -a 127.0.0.1 -p 6001 -su koha -sp koha -l MPL --patron koha -m patron_information 6. Verify that only SIP-related errors are logged as errors and non-SIP errors are warned. Sponsored-by: Koha-Suomi Oy -- You are receiving this mail because: You are watching all bug changes. You are the assignee for the bug.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41707 Lari Taskula <lari.taskula@hypernova.fi> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |lari.taskula@hypernova.fi -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41707 David Nind <david@davidnind.com> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |david@davidnind.com --- Comment #2 from David Nind <david@davidnind.com> --- I attempted to test (using KTD, so step 4 is not required as the SIP server is running), but I'm not really sure about step 6 and what I should be seeing. Tests pass. There are only log entries in sip-output.log and nothing in sip-error.log. So will leave for someone else who is more familiar with SIP to sign off. Here is what is in the sip-output.log after issuing the command in step 5: 118 [2026/03/05 18:08:17] [10534] [WARN] [undef]@[undef]: Setting gid to "1000 1000" Net::Server::log /usr/share/perl5/Net/Server.pm (962) 119 [2026/03/05 18:09:05] [10615] [WARN] [undef]@[undef]: Couldn't find sip2_resource_last_modified, considering configuration not up to date C4::SIP::Sip::siplo g /kohadevbox/koha/C4/SIP/Sip.pm (327) 120 [2026/03/05 18:09:05] [10615] [ERROR] [undef]@[undef]: ERROR: Institution kohalibrary does does not match a branchcode. This can cause unexpected behavior. C 4::SIP::Sip::siplog /kohadevbox/koha/C4/SIP/Sip.pm (327) 121 [2026/03/05 18:09:05] [10615] [ERROR] [undef]@[undef]: ERROR: Institution MAIN does does not match a branchcode. This can cause unexpected behavior. C4::SIP: :Sip::siplog /kohadevbox/koha/C4/SIP/Sip.pm (327) 122 [2026/03/05 18:09:05] [10615] [ERROR] [undef]@[undef]: ERROR: Institution kohalibrary2 does does not match a branchcode. This can cause unexpected behavior. C4::SIP::Sip::siplog /kohadevbox/koha/C4/SIP/Sip.pm (327) 123 [2026/03/05 18:09:05] [10615] [DEBUG] [undef]@[undef]: Configuration::find_service: Trying 6001/tcp C4::SIP::Sip::siplog /kohadevbox/koha/C4/SIP/Sip.pm (327) 124 [2026/03/05 18:09:05] [10615] [DEBUG] [undef]@[undef]: Configuration::find_service: Trying *:6001/tcp C4::SIP::Sip::siplog /kohadevbox/koha/C4/SIP/Sip.pm (32 7) 125 [2026/03/05 18:09:05] [10615] [DEBUG] [undef]@[undef]: Configuration::find_service: Trying 127.0.0.1:6001/tcp C4::SIP::Sip::siplog /kohadevbox/koha/C4/SIP/Si p.pm (327) 126 [2026/03/05 18:09:05] [10615] [DEBUG] [undef]@[undef]: raw_transport: timeout is 60 C4::SIP::Sip::siplog /kohadevbox/koha/C4/SIP/Sip.pm (327) 127 [2026/03/05 18:09:05] [10615] [INFO] [undef]@[undef]: INPUT MSG: '9300CNkoha|CO***|CPMPL|' C4::SIP::Sip::siplog /kohadevbox/koha/C4/SIP/Sip.pm (327) 128 [2026/03/05 18:09:05] [10615] [DEBUG] [undef]@[undef]: Sip::MsgType::new('C4::SIP::Sip::MsgType', '9300CNkoha...', '93'): seq.no '0', protocol 2 C4::SIP::Sip ::siplog /kohadevbox/koha/C4/SIP/Sip.pm (327) 129 [2026/03/05 18:09:05] [10615] [DEBUG] [undef]@[undef]: Sip::MsgType::_initialize('Login', '00CNkoha|CO***|CPMPL|', 'A1A1', '2', ...) C4::SIP::Sip::siplog /ko hadevbox/koha/C4/SIP/Sip.pm (327) 130 [2026/03/05 18:09:05] [10615] [INFO] [undef]@[undef]: Successful login/auth for 'koha' of 'kohalibrary' C4::SIP::Sip::siplog /kohadevbox/koha/C4/SIP/Sip.pm ( 327) 131 [2026/03/05 18:09:05] [10615] [DEBUG] [undef]@[undef]: login_core: $VAR1 = 'ILS'; C4::SIP::Sip::siplog /kohadevbox/koha/C4/SIP/Sip.pm (327) 132 [2026/03/05 18:09:05] [10615] [DEBUG] [undef]@[undef]: new ILS 'kohalibrary' C4::SIP::Sip::siplog /kohadevbox/koha/C4/SIP/Sip.pm (327) 133 [2026/03/05 18:09:05] [10615] [INFO] [undef]@[undef]: OUTPUT MSG: '941' C4::SIP::Sip::siplog /kohadevbox/koha/C4/SIP/Sip.pm (327) 134 [2026/03/05 18:09:05] [10615] [DEBUG] koha@127.0.0.1: raw_transport: uname/inst: 'koha/kohalibrary' C4::SIP::Sip::siplog /kohadevbox/koha/C4/SIP/Sip.pm (327) 135 [2026/03/05 18:09:05] [10615] [DEBUG] koha@127.0.0.1: read_request trimmed 1 character(s) C4::SIP::Sip::siplog /kohadevbox/koha/C4/SIP/Sip.pm (327) 136 [2026/03/05 18:09:05] [10615] [INFO] koha@127.0.0.1: INPUT MSG: '6300120260305 180905 AOMPL|AAkoha|AC***|' C4::SIP::Sip::siplog /kohadevbox/koha/ C4/SIP/Sip.pm (327) 137 [2026/03/05 18:09:05] [10615] [DEBUG] koha@127.0.0.1: Sip::MsgType::new('C4::SIP::Sip::MsgType', '6300120260...', '63'): seq.no '0', protocol 2 C4::SIP::Sip: :siplog /kohadevbox/koha/C4/SIP/Sip.pm (327) 138 [2026/03/05 18:09:05] [10615] [DEBUG] koha@127.0.0.1: Sip::MsgType::_initialize('Patron Info', '00120260305 180905 AOMPL|AAkoha|AC***|', 'A3A18A1 0', '31', ...) C4::SIP::Sip::siplog /kohadevbox/koha/C4/SIP/Sip.pm (327) 139 [2026/03/05 18:09:05] [10615] [DEBUG] koha@127.0.0.1: Debarred = undef : C4::SIP::Sip::siplog /kohadevbox/koha/C4/SIP/Sip.pm (327) 140 [2026/03/05 18:09:05] [10615] [DEBUG] koha@127.0.0.1: new ILS::Patron(koha): found patron '42' C4::SIP::Sip::siplog /kohadevbox/koha/C4/SIP/Sip.pm (327) 141 [2026/03/05 18:09:05] [10615] [DEBUG] koha@127.0.0.1: patron_status_string: 42 charge_ok: 1 C4::SIP::Sip::siplog /kohadevbox/koha/C4/SIP/Sip.pm (327) 142 [2026/03/05 18:09:05] [10615] [INFO] koha@127.0.0.1: OUTPUT MSG: '64 00120260305 180905000000000000000000000000AOkohalibrary|AA42|AE koha|BLY |BHUSD|BV0|CC5|PCS|PIY|AFGreetings from Koha. |' C4::SIP::Sip::siplog /kohadevbox/koha/C4/SIP/Sip.pm (327) 143 [2026/03/05 18:09:05] [10615] [DEBUG] koha@127.0.0.1: read_request trimmed 1 character(s) C4::SIP::Sip::siplog /kohadevbox/koha/C4/SIP/Sip.pm (327) 144 [2026/03/05 18:09:05] [10615] [INFO] koha@127.0.0.1: INPUT MSG: '' C4::SIP::Sip::siplog /kohadevbox/koha/C4/SIP/Sip.pm (327) 145 [2026/03/05 18:09:05] [10615] [INFO] koha@127.0.0.1: raw_transport: shutting down C4::SIP::Sip::siplog /kohadevbox/koha/C4/SIP/Sip.pm (327) -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41707 Jan Kissig <bibliothek@th-wildau.de> changed: What |Removed |Added ---------------------------------------------------------------------------- Status|Needs Signoff |Signed Off -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41707 Jan Kissig <bibliothek@th-wildau.de> changed: What |Removed |Added ---------------------------------------------------------------------------- Attachment #192093|0 |1 is obsolete| | --- Comment #3 from Jan Kissig <bibliothek@th-wildau.de> --- Created attachment 194719 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=194719&action=edit Bug 41707: Modify C4::SIP::Trapper DIE handling for better logging This patch improves the error handling in the SIP Trapper module by logging only SIP-related errors as errors and non-SIP errors as warnings. This change aims to reduce noise in the logs and make it easier to identify genuine SIP-related issues. Test plan: 1. Apply the patch 2. prove -lv t/db_dependent/SIP/Trapper.t 3. Ensure all tests pass without errors 4. Start the server: perl C4/SIP/SIPServer.pm /etc/koha/SIPconfig.xml 5. misc/sip_cli_emulator.pl -a 127.0.0.1 -p 6001 -su koha -sp koha -l MPL --patron koha -m patron_information 6. Verify that only SIP-related errors are logged as errors and non-SIP errors are warned. Sponsored-by: Koha-Suomi Oy Signed-off-by: Jan Kissig <bibliothek@th-wildau.de> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41707 Jan Kissig <bibliothek@th-wildau.de> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |bibliothek@th-wildau.de --- Comment #4 from Jan Kissig <bibliothek@th-wildau.de> --- Remarks for testing: before applying the patch when running f.e. misc/sip_cli_emulator.pl -a 127.0.0.1 -p 6001 -su term1 -sp term1 -l MPL --patron koha -m patron_information there were a lot of output lines like [2026/03/06 13:33:02] [14661] [ERROR] [undef]@[undef]: DBIx::Class::ResultSource::_minimal_valueset_satisfying_constraint(): Unable to satisfy requested constraint 'primary', missing values for column(s): 'borrowernumber' at /kohadevbox/koha/Koha/Objects.pm line 95 C4::SIP::Trapper::__ANON__ /kohadevbox/koha/C4/SIP/Trapper.pm (70) After applying these errors starting with 'DBIx' were gone and only SIP2 related errors/warnings were left. -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41707 David Nind <david@davidnind.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Attachment #194719|0 |1 is obsolete| | --- Comment #5 from David Nind <david@davidnind.com> --- Created attachment 194762 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=194762&action=edit Bug 41707: Modify C4::SIP::Trapper DIE handling for better logging This patch improves the error handling in the SIP Trapper module by logging only SIP-related errors as errors and non-SIP errors as warnings. This change aims to reduce noise in the logs and make it easier to identify genuine SIP-related issues. Test plan: 1. Apply the patch 2. prove -lv t/db_dependent/SIP/Trapper.t 3. Ensure all tests pass without errors 4. Start the server: perl C4/SIP/SIPServer.pm /etc/koha/SIPconfig.xml 5. misc/sip_cli_emulator.pl -a 127.0.0.1 -p 6001 -su koha -sp koha -l MPL --patron koha -m patron_information 6. Verify that only SIP-related errors are logged as errors and non-SIP errors are warned. Sponsored-by: Koha-Suomi Oy Signed-off-by: Jan Kissig <bibliothek@th-wildau.de> Signed-off-by: David Nind <david@davidnind.com> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41707 --- Comment #6 from David Nind <david@davidnind.com> --- Thanks Jan! I've added my sign off in case you are able to do the QA. David -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41707 Jan Kissig <bibliothek@th-wildau.de> changed: What |Removed |Added ---------------------------------------------------------------------------- See Also| |https://bugs.koha-community | |.org/bugzilla3/show_bug.cgi | |?id=40915 -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41707 David Nind <david@davidnind.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Summary|The DIE handler in |The DIE handler in |C4::SIP::Trapper is logging |C4::SIP::Trapper is logging |non-SIP errors, causing log |non-SIP errors, causing log |flooding. |flooding -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41707 --- Comment #7 from Jan Kissig <bibliothek@th-wildau.de> --- (In reply to David Nind from comment #6)
Thanks Jan!
I've added my sign off in case you are able to do the QA.
David
Thanks David, but I would leave this to someone more capable. -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41707 Johanna Räisä <johanna.raisa@koha-suomi.fi> changed: What |Removed |Added ---------------------------------------------------------------------------- Text to go in the| |The SIP Trapper module's release notes| |error handling has been | |enhanced to distinguish | |between SIP-related and | |non-SIP errors. SIP-related | |errors are now logged at | |the ERROR level, while | |non-SIP errors are logged | |as warnings. | | | |This improvement reduces | |log noise and makes it | |easier for system | |administrators to quickly | |identify and respond to | |genuine SIP connectivity | |and protocol issues, | |improving the overall | |maintainability of SIP | |services. -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41707 --- Comment #8 from Katrin Fischer <katrin.fischer@bsz-bw.de> --- Still seeing these, giving it a little nudge :) -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41707 Katrin Fischer <katrin.fischer@bsz-bw.de> changed: What |Removed |Added ---------------------------------------------------------------------------- See Also| |https://bugs.koha-community | |.org/bugzilla3/show_bug.cgi | |?id=40911 -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41707 Tomás Cohen Arazi (tcohen) <tomascohen@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |kyle@bywatersolutions.com, | |tomascohen@gmail.com --- Comment #9 from Tomás Cohen Arazi (tcohen) <tomascohen@gmail.com> --- Are we sure we want to hide warnings? I would instead revisit why we use this trapper class entirely. Maybe it was a means to an end and we moved past that situation. Adding our SIP guru (kyle) to the conversation. (In reply to Jan Kissig from comment #4)
[2026/03/06 13:33:02] [14661] [ERROR] [undef]@[undef]: DBIx::Class::ResultSource::_minimal_valueset_satisfying_constraint(): Unable to satisfy requested constraint 'primary', missing values for column(s): 'borrowernumber' at /kohadevbox/koha/Koha/Objects.pm line 95 C4::SIP::Trapper::__ANON__ /kohadevbox/koha/C4/SIP/Trapper.pm (70)
This one is probably a mix of a DBIC bad decision [1] and our use of `__DIE__`. [1] I submitted a fix to the (long abandoned) DBIx::Class project and now to the active fork we should move to: DBIO [here](https://codeberg.org/dbio/dbio/pulls/14) -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41707 --- Comment #10 from Kyle M Hall (khall) <kyle@bywatersolutions.com> --- Created attachment 202527 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=202527&action=edit Bug 41707: (QA follow-up) Remove the SIP DIE handler, log fatal errors where they are caught instead The root of the log flooding is that a __DIE__ handler fires for every die, including exceptions that are thrown and caught as part of normal operation deep inside DBIC and Net::Server. The stack walk added by the previous patch stops after 10 frames, which is why it filters the DBIC noise, but it would also silently drop a genuine fatal error thrown more than 10 frames from the nearest C4::SIP frame, such as a lost database connection inside DBIC. That brings back the problem bug 39911 was written to fix. The reason fatal errors were invisible in the first place (the problem bug 39911 worked around) is that sip_protocol_loop wraps all message handling in an eval and silently discards every non-timeout error. This patch removes the DIE handler entirely and instead logs errors at the two places they are actually caught. sip_protocol_loop now logs the error it has been throwing away before shutting down the connection. The transport dispatch in process_request is wrapped in an eval to catch anything fatal outside the protocol loop, such as the login phase, where the error is logged and rethrown. Handled exceptions never reach the log. Test Plan: 1) Apply this patch 2) prove t/db_dependent/SIP/Trapper.t 3) Restart the SIP server 4) Run: misc/sip_cli_emulator.pl -a 127.0.0.1 -p 6001 -su term1 -sp term1 -l MPL --patron koha -m patron_information 5) Note the DBIx::Class errors from comment 4 no longer flood the SIP logs 6) Add a "die 'TEST';" to handle_patron_info in C4/SIP/Sip/MsgType.pm, restart the SIP server 7) Repeat step 4 8) Note "TEST" is logged as an error in the SIP logs! -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41707 --- Comment #11 from Kyle M Hall (khall) <kyle@bywatersolutions.com> --- Created attachment 202533 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=202533&action=edit Bug 41707: (QA follow-up) Log the actual error when the telnet login dies The catch below the telnet login eval assumes any error is a timeout, logging the fixed string "Login timed out" and discarding the real error text. A fatal error thrown during the login, such as a lost database connection inside login_core, was only visible as a bogus timeout message. This patch logs the actual error when it isn't the login timeout, matching what sip_protocol_loop and process_request do. -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41707 --- Comment #12 from Kyle M Hall (khall) <kyle@bywatersolutions.com> --- Created attachment 202534 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=202534&action=edit Bug 41707: (QA follow-up) Add missing license header to Trapper.t Patch from commit b630aba -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41707 --- Comment #13 from Kyle M Hall (khall) <kyle@bywatersolutions.com> --- Created attachment 202535 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=202535&action=edit Bug 41707: (QA follow-up) Add unit tests Test Plan: 1) Apply this patch 2) prove t/db_dependent/SIP/SIPServer.t -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41707 --- Comment #14 from David Nind <david@davidnind.com> --- Does the status need changing to "Passed QA"? -- You are receiving this mail because: You are watching all bug changes.
participants (1)
-
bugzilla-daemon＠bugs.koha-community.org