Bug 41707 - The DIE handler in C4::SIP::Trapper is logging non-SIP errors, causing log flooding
Summary: The DIE handler in C4::SIP::Trapper is logging non-SIP errors, causing log fl...
Status: Signed Off
Alias: None
Product: Koha
Classification: Unclassified
Component: SIP2 (show other bugs)
Version: Main
Hardware: All All
: P5 - low enhancement
Assignee: Johanna Räisä
QA Contact: Testopia
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2026-01-26 09:05 UTC by Johanna Räisä
Modified: 2026-03-10 08:21 UTC (History)
5 users (show)

See Also:
GIT URL:
Initiative type: ---
Sponsorship status: ---
Comma delimited list of Sponsors:
Crowdfunding goal: 0
Crowdfunding committed: 0
Crowdfunding contact:
Patch complexity: ---
Documentation contact:
Documentation submission:
Text to go in the release notes:
Version(s) released in:
Circulation function:


Attachments
Bug 41707: Modify C4::SIP::Trapper DIE handling for better logging (4.93 KB, patch)
2026-01-27 11:50 UTC, Johanna Räisä
Details | Diff | Splinter Review
Bug 41707: Modify C4::SIP::Trapper DIE handling for better logging (4.98 KB, patch)
2026-03-06 13:32 UTC, Jan Kissig
Details | Diff | Splinter Review
Bug 41707: Modify C4::SIP::Trapper DIE handling for better logging (5.02 KB, patch)
2026-03-06 16:03 UTC, David Nind
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Johanna Räisä 2026-01-26 09:05:52 UTC
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)
Comment 1 Johanna Räisä 2026-01-27 11:50:13 UTC
Created attachment 192093 [details] [review]
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
Comment 2 David Nind 2026-03-05 18:15:23 UTC
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)
Comment 3 Jan Kissig 2026-03-06 13:32:03 UTC
Created attachment 194719 [details] [review]
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>
Comment 4 Jan Kissig 2026-03-06 13:42:14 UTC
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.
Comment 5 David Nind 2026-03-06 16:03:14 UTC
Created attachment 194762 [details] [review]
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>
Comment 6 David Nind 2026-03-06 16:04:35 UTC
Thanks Jan!

I've added my sign off in case you are able to do the QA.

David
Comment 7 Jan Kissig 2026-03-10 08:21:40 UTC
(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.