Bug 40910

Summary: Log pollution for undefined/empty barcodes
Product: Koha Reporter: Tomás Cohen Arazi (tcohen) <tomascohen>
Component: SIP2Assignee: Tomás Cohen Arazi (tcohen) <tomascohen>
Status: Failed QA --- QA Contact: Marcel de Rooy <m.de.rooy>
Severity: normal    
Priority: P5 - low CC: jesse, kyle, lisette, m.de.rooy, tomascohen
Version: unspecified   
Hardware: All   
OS: All   
See Also: https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=40911
GIT URL: Initiative type: ---
Sponsorship status: --- Comma delimited list of Sponsors:
Crowdfunding goal: 0 Patch complexity: Trivial patch
Documentation contact: Documentation submission:
Text to go in the release notes:
Version(s) released in:
Circulation function:
Attachments: Bug 40910: Regression tests
Bug 40910: Reduce log pollution for undefined/empty barcodes
Bug 40910: Regression tests
Bug 40910: Regression tests
Bug 40910: Reduce log pollution for undefined/empty barcodes

Description Tomás Cohen Arazi (tcohen) 2025-09-30 13:59:10 UTC
Noticed in production, when `C4::SIP::ILS::Item->new` is passed an `$item_id` that is not defined or empty -or barcodedecode makes it like that- (e.g. faulty plugins) logs get flooded with DBIx::Class errors when it should never reach the ORM with a query because there's nothing to search for.

If `barcodedecode` empties the barcode, a debug log should be printed because it might be a sign of a misconfiguration or faulty plugin.
Comment 1 Tomás Cohen Arazi (tcohen) 2025-09-30 14:17:41 UTC
Created attachment 187106 [details] [review]
Bug 40910: Regression tests

Signed-off-by: Tomás Cohen Arazi <tomascohen@theke.io>
Comment 2 Tomás Cohen Arazi (tcohen) 2025-09-30 14:17:44 UTC
Created attachment 187107 [details] [review]
Bug 40910: Reduce log pollution for undefined/empty barcodes

This patch prevents warnings and DBIx::Class errors when C4::SIP::ILS::Item->new()
receives undefined, empty, or whitespace-only item_id values that could occur
from faulty plugins or malformed SIP requests.

Changes:
- Add early validation for undefined/empty item_id before barcodedecode()
- Add validation for barcodedecode() result before Koha::Items->find()
- Add debug logging when barcodedecode empties a barcode (indicates misconfiguration)
- Prevent "Odd number of elements in anonymous hash" warnings
- Prevent DBIx::Class constraint validation errors
- No functional changes - behavior preserved for valid barcodes

Test plan:
1. Apply the regression tests
2. Run:
   $ ktd --shell
  k$ prove t/db_dependent/SIP/Item.t
=> FAIL: Tests fail!
3. Apply this patch
4. Repeat 2
=> SUCCESS: Tests pass!
5. Tests cover:
   - Valid barcode functionality (preserved)
   - Undefined item_id (no warnings)
   - Empty string item_id (no warnings)
   - Whitespace-only item_id (no warnings)
   - barcodedecode edge cases (tabs, newlines, mixed)
   - Nonexistent barcodes (expected warnings preserved)
6. Verify no warnings in SIP logs for malformed requests
7. Sign off :-D

Signed-off-by: Tomás Cohen Arazi <tomascohen@theke.io>
Comment 3 Kyle M Hall (khall) 2025-10-01 12:09:05 UTC
I would recommend running barcode decode *after* doing all your checks on item_id, as barcodedecode can trigger plugins that will *generate* a new barcode if passed an empty barcode string ( https://github.com/bywatersolutions/koha-plugin-barcode-prefixer ) for example. 

By testing $item_id and returning if it's empty *before* running barcodedecode on it, we can ensure we don't accidentally generate a non-existent barcode for the message!
Comment 4 Kyle M Hall (khall) 2025-10-01 14:25:03 UTC
(In reply to Kyle M Hall (khall) from comment #3)
> I would recommend running barcode decode *after* doing all your checks on
> item_id, as barcodedecode can trigger plugins that will *generate* a new
> barcode if passed an empty barcode string (
> https://github.com/bywatersolutions/koha-plugin-barcode-prefixer ) for
> example. 
> 
> By testing $item_id and returning if it's empty *before* running
> barcodedecode on it, we can ensure we don't accidentally generate a
> non-existent barcode for the message!

My entire comment is invalid as Tomas already added a return on line 88.
I think the log level is good as well, we should be able to scroll back in the logs to see the message that triggered the error.
Comment 5 Kyle M Hall (khall) 2025-10-01 14:28:04 UTC
Created attachment 187195 [details] [review]
Bug 40910: Regression tests

Signed-off-by: Tomás Cohen Arazi <tomascohen@theke.io>

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 6 Kyle M Hall (khall) 2025-10-01 14:29:46 UTC
Created attachment 187196 [details] [review]
Bug 40910: Regression tests

Signed-off-by: Tomás Cohen Arazi <tomascohen@theke.io>

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 7 Kyle M Hall (khall) 2025-10-01 14:29:54 UTC
Created attachment 187197 [details] [review]
Bug 40910: Reduce log pollution for undefined/empty barcodes

This patch prevents warnings and DBIx::Class errors when C4::SIP::ILS::Item->new()
receives undefined, empty, or whitespace-only item_id values that could occur
from faulty plugins or malformed SIP requests.

Changes:
- Add early validation for undefined/empty item_id before barcodedecode()
- Add validation for barcodedecode() result before Koha::Items->find()
- Add debug logging when barcodedecode empties a barcode (indicates misconfiguration)
- Prevent "Odd number of elements in anonymous hash" warnings
- Prevent DBIx::Class constraint validation errors
- No functional changes - behavior preserved for valid barcodes

Test plan:
1. Apply the regression tests
2. Run:
   $ ktd --shell
  k$ prove t/db_dependent/SIP/Item.t
=> FAIL: Tests fail!
3. Apply this patch
4. Repeat 2
=> SUCCESS: Tests pass!
5. Tests cover:
   - Valid barcode functionality (preserved)
   - Undefined item_id (no warnings)
   - Empty string item_id (no warnings)
   - Whitespace-only item_id (no warnings)
   - barcodedecode edge cases (tabs, newlines, mixed)
   - Nonexistent barcodes (expected warnings preserved)
6. Verify no warnings in SIP logs for malformed requests
7. Sign off :-D

Signed-off-by: Tomás Cohen Arazi <tomascohen@theke.io>

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 8 Marcel de Rooy 2025-10-17 07:53:36 UTC
(In reply to Tomás Cohen Arazi (tcohen) from comment #0)
> Noticed in production, when `C4::SIP::ILS::Item->new` is passed an
> `$item_id` that is not defined or empty -or barcodedecode makes it like
> that- (e.g. faulty plugins) logs get flooded with DBIx::Class errors when it
> should never reach the ORM with a query because there's nothing to search
> for.

You probably mean:
DBIx::Class::Storage::DBI::select_single(): Query returned more than one row.  SQL that returns multiple rows is DEPRECATED for ->find and ->single at /usr/share/koha/Koha/Objects.pm line 95

This only seems to occur when we look for undef. Not for empty string.
Skipping a db search for undef or empty string is a good thing though.
But do we really need 153 lines for that?
 t/db_dependent/SIP/Item.t | 153 ++++++++++++++++++++++++++++++++++++++

And if the argument is flooding the logs, we are still doing that here.
Comment 9 Marcel de Rooy 2025-10-24 07:58:54 UTC
Needs feedback. Changing status
Comment 10 Tomás Cohen Arazi (tcohen) 2025-12-01 02:20:45 UTC
(In reply to Marcel de Rooy from comment #9)
> Needs feedback. Changing status

Fair. It is hard for me, because you arrive to an area lacking some behavior tests, and constraining it to just the small thing you’re fixing seems lame too, as you need to build the entire scenario anyway.

I’ll revisit my tendency to write full test coverage when touching an untested/partially tested sub, but cannot promise to not do it. Will do my best.

I need to come back to this soon, and the other one. The dependency is not defined but there was some.
Comment 11 Marcel de Rooy 2025-12-01 10:16:41 UTC
(In reply to Tomás Cohen Arazi (tcohen) from comment #10)
> (In reply to Marcel de Rooy from comment #9)
> > Needs feedback. Changing status
> 
> Fair. It is hard for me, because you arrive to an area lacking some behavior
> tests, and constraining it to just the small thing you’re fixing seems lame
> too, as you need to build the entire scenario anyway.
> 
> I’ll revisit my tendency to write full test coverage when touching an
> untested/partially tested sub, but cannot promise to not do it. Will do my
> best.

Full test coverage is fine obviously. But you could always ask how far should you go? Do you need to test every trivial return? etc.