Bug 24629 - SIP2 logs garbage
Summary: SIP2 logs garbage
Status: CLOSED FIXED
Alias: None
Product: Koha
Classification: Unclassified
Component: SIP2 (show other bugs)
Version: Main
Hardware: All All
: P5 - low normal
Assignee: Bugs List
QA Contact: Testopia
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2020-02-11 14:13 UTC by Magnus Enger
Modified: 2021-06-14 21:29 UTC (History)
4 users (show)

See Also:
Change sponsored?: ---
Patch complexity: Small patch
Documentation contact:
Documentation submission:
Text to go in the release notes:
Version(s) released in:
20.05.00
Circulation function:


Attachments
Bug 24629: SIP log - Display barcode instead of hash (943 bytes, patch)
2020-02-12 09:23 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 24629: SIP patron items contains an array of hashes (1.62 KB, patch)
2020-02-21 12:33 UTC, Nick Clemens (kidclamp)
Details | Diff | Splinter Review
Bug 24629: SIP log - Display barcode instead of hash (994 bytes, patch)
2020-02-24 09:23 UTC, Magnus Enger
Details | Diff | Splinter Review
Bug 24629: SIP patron items contains an array of hashes (1.79 KB, patch)
2020-02-24 09:24 UTC, Magnus Enger
Details | Diff | Splinter Review
Bug 24629: SIP log - Display barcode instead of hash (1.03 KB, patch)
2020-02-24 12:12 UTC, Martin Renvoize (ashimema)
Details | Diff | Splinter Review
Bug 24629: SIP patron items contains an array of hashes (1.74 KB, patch)
2020-02-24 12:12 UTC, Martin Renvoize (ashimema)
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Magnus Enger 2020-02-11 14:13:02 UTC
When looking at the messages SIP2 puts in syslog there are several messages where hashes are printed directly to the log, producing messages like these: 

Feb 11 09:00:23 koha koha_sip_koha[13575]: ILS::Checkout: patron 123 has checked out HASH(0x55a5b187f858), HASH(0x55a5b1896ad0), HASH(0x55a5b18a6cf0)

Feb 11 09:00:25 koha koha_sip_koha[13575]: summary_info: list = (HASH(0x55a5b18aea60), HASH(0x55a5b18ae718), HASH(0x55a5b184ef48)...

Not very useful?
Comment 1 Jonathan Druart 2020-02-11 15:52:34 UTC
They are debug messages, if syslog is not configured to log "debug" I would not expect them to be in the logs.
Comment 2 Magnus Enger 2020-02-11 20:28:54 UTC
(In reply to Jonathan Druart from comment #1)
> They are debug messages, if syslog is not configured to log "debug" I would
> not expect them to be in the logs.

Are they useful in any way? To me it just says "there were x number of hashes here", not sure if that makes me much wiser?
Comment 3 Jonathan Druart 2020-02-12 09:23:18 UTC
Indeed Magnus, I was missing your point (read too fast).
Comment 4 Jonathan Druart 2020-02-12 09:23:33 UTC Comment hidden (obsolete)
Comment 5 Jonathan Druart 2020-02-12 09:25:15 UTC
(In reply to Magnus Enger from comment #0)

> Feb 11 09:00:23 koha koha_sip_koha[13575]: ILS::Checkout: patron 123 has
> checked out HASH(0x55a5b187f858), HASH(0x55a5b1896ad0), HASH(0x55a5b18a6cf0)

This one is weird, it seems that sometimes we have hash and itemnumber:

Few lines before the syslog statement:
167             push( @{ $patron->{items} }, $item_id );

But, in renew:
458         foreach my $i (@{$patron->{items}}) { 

> Feb 11 09:00:25 koha koha_sip_koha[13575]: summary_info: list =
> (HASH(0x55a5b18aea60), HASH(0x55a5b18ae718), HASH(0x55a5b184ef48)...

Fixed with the patch.
Comment 6 Jonathan Druart 2020-02-12 09:27:01 UTC
(In reply to Jonathan Druart from comment #5)
> (In reply to Magnus Enger from comment #0)
> 
> > Feb 11 09:00:23 koha koha_sip_koha[13575]: ILS::Checkout: patron 123 has
> > checked out HASH(0x55a5b187f858), HASH(0x55a5b1896ad0), HASH(0x55a5b18a6cf0)
> 
> This one is weird, it seems that sometimes we have hash and itemnumber:
> 
> Few lines before the syslog statement:
> 167             push( @{ $patron->{items} }, $item_id );
> 
> But, in renew:
> 458         foreach my $i (@{$patron->{items}}) { 

then we are using $i->{barcode}, so it is supposed to be a hashref.
Comment 7 Magnus Enger 2020-02-14 12:25:18 UTC
The patch is an improvement, but there are still some HASH'es left. 

This one is interesting:

Feb 14 12:40:05 kohaserver koha_sip[19050]: ILS::Checkout: patron x has checked out 52450820597
Feb 14 12:40:05 kohaserver koha_sip[19050]: ILS::Checkout: patron x has checked out HASH(0x5635b7193418), 80062844366
Feb 14 12:40:07 kohaserver koha_sip[19050]: ILS::Checkout: patron x has checked out HASH(0x5635b6f1ab80), HASH(0x5635b6f1a2c8), 80062908790
Feb 14 12:40:07 kohaserver koha_sip[19050]: ILS::Checkout: patron x has checked out HASH(0x5635b718c6c8), HASH(0x5635b6f31900), HASH(0x5635b6f20f20), 80059004255

x is the same in all 4 lines. I think this comes from ILS.pm, line 171.
Comment 8 Nick Clemens (kidclamp) 2020-02-21 12:33:08 UTC Comment hidden (obsolete)
Comment 9 Magnus Enger 2020-02-24 09:23:02 UTC Comment hidden (obsolete)
Comment 10 Magnus Enger 2020-02-24 09:23:23 UTC
Created attachment 99478 [details] [review]
Bug 24629: SIP log - Display barcode instead of hash

Signed-off-by: Magnus Enger <magnus@libriotech.no>
Comment 11 Magnus Enger 2020-02-24 09:24:39 UTC
Created attachment 99480 [details] [review]
Bug 24629: SIP patron items contains an array of hashes

$patron->{items} contains the borrowers checkouts as an array of hashes
{ barcode => $item->barcode }

When printing to log we assumed these were only barcodes

This patch pushes the current checkout as a hash and maps the values retrieved to a string

To test:
1 - Enable SIP debug mode
2 - Perform multiple checkouts for a patron
3 - Note the messages like:
    koha koha_sip_koha[13575]: ILS::Checkout: patron 123 has checked out HASH(0x55a5b187f858), HASH(0x55a5b1896ad0), HASH(0x55a5b18a6cf0), 7826832
4 - Apply patch
5 - Restart all the things
6 - Do some checkouts via SIP
6 - Messages should now have barcodes

Signed-off-by: Magnus Enger <magnus@libriotech.no>
This patch and the one from Jonathan taken together seems to solve
the problem, I no longer see messages with HASH(...).
Comment 12 Martin Renvoize (ashimema) 2020-02-24 12:12:48 UTC
Created attachment 99487 [details] [review]
Bug 24629: SIP log - Display barcode instead of hash

Signed-off-by: Magnus Enger <magnus@libriotech.no>
Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>
Comment 13 Martin Renvoize (ashimema) 2020-02-24 12:12:51 UTC
Created attachment 99488 [details] [review]
Bug 24629: SIP patron items contains an array of hashes

$patron->{items} contains the borrowers checkouts as an array of hashes
{ barcode => $item->barcode }

When printing to log we assumed these were only barcodes

This patch pushes the current checkout as a hash and maps the values retrieved to a string

To test:
1 - Enable SIP debug mode
2 - Perform multiple checkouts for a patron
3 - Note the messages like:
    koha koha_sip_koha[13575]: ILS::Checkout: patron 123 has checked out HASH(0x55a5b187f858), HASH(0x55a5b1896ad0), HASH(0x55a5b18a6cf0), 7826832
4 - Apply patch
5 - Restart all the things
6 - Do some checkouts via SIP
6 - Messages should now have barcodes

Signed-off-by: Magnus Enger <magnus@libriotech.no>
Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>
Comment 14 Martin Renvoize (ashimema) 2020-02-24 12:13:09 UTC
Trivial fix, thanks guys..

PQA
Comment 15 Jonathan Druart 2020-02-24 12:48:48 UTC
(In reply to Martin Renvoize from comment #14)
> Trivial fix, thanks guys..
> 
> PQA

That is not that trivial in my opinion.
We should track down a bit where does come from (and the possible problems) the 2 different types in the item list (scalar vs hashref).

I think I asked Nick last Friday but cannot remember the conclusion.
Comment 16 Martin Renvoize (ashimema) 2020-02-24 13:22:09 UTC
Nice work everyone!

Pushed to master for 20.05
Comment 17 Katrin Fischer 2020-02-24 21:31:34 UTC
(In reply to Jonathan Druart from comment #15)
> (In reply to Martin Renvoize from comment #14)
> > Trivial fix, thanks guys..
> > 
> > PQA
> 
> That is not that trivial in my opinion.
> We should track down a bit where does come from (and the possible problems)
> the 2 different types in the item list (scalar vs hashref).
> 
> I think I asked Nick last Friday but cannot remember the conclusion.

Did you manage to clear this one up?
Comment 18 Nick Clemens (kidclamp) 2020-02-25 14:49:31 UTC
(In reply to Katrin Fischer from comment #17)
> (In reply to Jonathan Druart from comment #15)
> > (In reply to Martin Renvoize from comment #14)
> > > Trivial fix, thanks guys..
> > > 
> > > PQA
> > 
> > That is not that trivial in my opinion.
> > We should track down a bit where does come from (and the possible problems)
> > the 2 different types in the item list (scalar vs hashref).
> > 
> > I think I asked Nick last Friday but cannot remember the conclusion.
> 
> Did you manage to clear this one up?

I added a second patch, it was another place where we had a more complex object than assumed