Bug 22433 - Add debug statements to understand why SIP/Transaction.t is failing randomly
Summary: Add debug statements to understand why SIP/Transaction.t is failing randomly
Status: RESOLVED FIXED
Alias: None
Product: Koha
Classification: Unclassified
Component: Test Suite (show other bugs)
Version: unspecified
Hardware: All All
: P5 - low normal (vote)
Assignee: Jonathan Druart
QA Contact: Testopia
URL:
Keywords:
Depends on:
Blocks: 23211
  Show dependency treegraph
 
Reported: 2019-02-28 13:58 UTC by Jonathan Druart
Modified: 2019-06-25 22:45 UTC (History)
2 users (show)

See Also:
Change sponsored?: ---
Patch complexity: ---
Who signed the patch off:
Text to go in the release notes:
Version(s) released in:
19.05.00, 18.11.06


Attachments
Bug 22433: Add debug statement to Transaction.t (1.33 KB, patch)
2019-05-09 18:06 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 22433: Add debug statement to Transaction.t (1.53 KB, patch)
2019-05-10 13:14 UTC, Martin Renvoize
Details | Diff | Splinter Review
Bug 22433: Use Data::Dumper instead of Data::Printer (1.27 KB, patch)
2019-05-10 17:32 UTC, Jonathan Druart
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Jonathan Druart 2019-02-28 13:58:09 UTC
On Master_D9:

koha_1       |     #   Failed test 'Bib has 1 holds remaining'
koha_1       |     #   at t/db_dependent/SIP/Transaction.t line 90.
koha_1       |     #          got: '2'
koha_1       |     #     expected: '1'
koha_1       |     # Looks like you failed 1 test of 5.
koha_1       | 
koha_1       | #   Failed test 'fill_holds_at_checkout'
koha_1       | #   at t/db_dependent/SIP/Transaction.t line 93.
koha_1       | # Looks like you failed 1 test of 4.
koha_1       | [21:17:57] t/db_dependent/SIP/Transaction.t
Comment 1 Jonathan Druart 2019-05-09 18:05:10 UTC
We got this failure a lot the last months.
Comment 2 Jonathan Druart 2019-05-09 18:06:31 UTC
Created attachment 89521 [details] [review]
Bug 22433: Add debug statement to Transaction.t

Hard to know what's going on here without more info. Adding this output
may help to investigate more.

Test plan:
Make sure the tests still pass

If it fails, please paste the output!!
Comment 3 Martin Renvoize 2019-05-10 13:14:58 UTC
Created attachment 89547 [details] [review]
Bug 22433: Add debug statement to Transaction.t

Hard to know what's going on here without more info. Adding this output
may help to investigate more.

Test plan:
Make sure the tests still pass

If it fails, please paste the output!!

Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>
Comment 4 Martin Renvoize 2019-05-10 13:17:42 UTC
Signing off as it's just a debugging addition.
Comment 5 Martin Renvoize 2019-05-10 13:18:13 UTC
Let's go straight for PQA.. no harm in it and it'll be helpful in finding the actual root of the issue.
Comment 6 Nick Clemens 2019-05-10 17:12:29 UTC
Data::Printer isn't in our deps - can you use Data::Dumper instead?
Comment 7 Jonathan Druart 2019-05-10 17:32:54 UTC
Created attachment 89564 [details] [review]
Bug 22433: Use Data::Dumper instead of Data::Printer

Data::Printer is not in our deps
Comment 8 Jonathan Druart 2019-05-10 17:33:18 UTC
(In reply to Nick Clemens from comment #6)
> Data::Printer isn't in our deps - can you use Data::Dumper instead?

Yup, good catch! :)
Comment 9 Nick Clemens 2019-05-10 17:43:56 UTC
Awesome work all!

Pushed to master for 19.05
Comment 10 Martin Renvoize 2019-05-24 13:24:24 UTC
Pushed to 18.11.x for 18.11.06
Comment 11 Martin Renvoize 2019-06-25 18:23:44 UTC
Current failures on U18 and D9 are both this one.. with all the debugging output.. too much to paste here directly
Comment 13 Nick Clemens 2019-06-25 18:37:24 UTC
(In reply to Martin Renvoize from comment #11)
> Current failures on U18 and D9 are both this one.. with all the debugging
> output.. too much to paste here directly

The checkout failed - ok => 0, due => undef

Could we be missing maxissueqty? or some other circ variable? We only set the one IssuingRule
Comment 14 Jonathan Druart 2019-06-25 22:37:47 UTC
(In reply to Nick Clemens from comment #13)
> (In reply to Martin Renvoize from comment #11)
> > Current failures on U18 and D9 are both this one.. with all the debugging
> > output.. too much to paste here directly
> 
> The checkout failed - ok => 0, due => undef
> 
> Could we be missing maxissueqty? or some other circ variable? We only set
> the one IssuingRule

Nope, this is the relevant line:
koha_1       |     #                  'screen_msg' => 'Issue failed : STATS',

Patron's category is 'X' (statistics)
Comment 15 Jonathan Druart 2019-06-25 22:45:38 UTC
(In reply to Martin Renvoize from comment #11)
> Current failures on U18 and D9 are both this one.. with all the debugging
> output.. too much to paste here directly

At least we won't lose it :)

koha_1       |     #   Failed test 'Bib has 1 holds remaining'
koha_1       |     #   at t/db_dependent/SIP/Transaction.t line 91.
koha_1       |     #          got: '2'
koha_1       |     #     expected: '1'
koha_1       |     # $VAR1 = bless( {
koha_1       |     #                  'renew_ok' => 0,
koha_1       |     #                  'item' => bless( {
koha_1       |     #                                     'biblionumber' => 797,
koha_1       |     #                                     'barcode' => 'barcode4test',
koha_1       |     #                                     'replacementpricedate' => '2019-06-25',
koha_1       |     #                                     'replacementprice' => '729968.08',
koha_1       |     #                                     'damaged' => 120,
koha_1       |     #                                     'datelastseen' => '2019-06-25',
koha_1       |     #                                     'homebranch' => 'xszWxdJW',
koha_1       |     #                                     'datelastborrowed' => '2019-06-25',
koha_1       |     #                                     'biblioitemnumber' => 654,
koha_1       |     #                                     'ccode' => 'nudtLfXyidGZJTrQZe0pW2Q1BctKWCgvr5i8PJ1nwi8z6XFX8d4c',
koha_1       |     #                                     'stocknumber' => 'r9E6GvbIjzGOGiMsS',
koha_1       |     #                                     'call_number' => 'uKI5ZXnl6AB7wapbXEzkWdgFE3nULdnJ8NuUaWMNbOiYCeK5YCmqYynwyG45V21FeuoCq4fQ8vpC14z0lwraKd3PEq4KJuW0uytUG74OxRqB6fgPr01YhLKvclXE9AYTFaSfbyxt8fTfX9IQq',
koha_1       |     #                                     'withdrawn' => 0,
koha_1       |     #                                     'itemnotes_nonpublic' => 'inA9bNB_FY',
koha_1       |     #                                     'paidfor' => 'vpaH7O0f',
koha_1       |     #                                     'withdrawn_on' => '2019-06-25 17:00:29',
koha_1       |     #                                     'itemnotes' => 'nwc2FMvPa7',
koha_1       |     #                                     'pending_queue' => [
koha_1       |     #                                                          {
koha_1       |     #                                                            'biblionumber' => 797,
koha_1       |     #                                                            'borrowernumber' => 361,
koha_1       |     #                                                            'item_level_hold' => 0,
koha_1       |     #                                                            'reservenotes' => undef,
koha_1       |     #                                                            'expirationdate' => undef,
koha_1       |     #                                                            'waitingdate' => undef,
koha_1       |     #                                                            'itemtype' => undef,
koha_1       |     #                                                            'found' => undef,
koha_1       |     #                                                            'reminderdate' => undef,
koha_1       |     #                                                            'reserve_id' => 84,
koha_1       |     #                                                            'notificationdate' => undef,
koha_1       |     #                                                            'timestamp' => '2019-06-25 17:00:30',
koha_1       |     #                                                            'lowestPriority' => 0,
koha_1       |     #                                                            'priority' => 1,
koha_1       |     #                                                            'itemnumber' => undef,
koha_1       |     #                                                            'cancellationdate' => undef,
koha_1       |     #                                                            'branchcode' => 'xszWxdJW',
koha_1       |     #                                                            'suspend_until' => undef,
koha_1       |     #                                                            'reservedate' => '2019-06-25',
koha_1       |     #                                                            'suspend' => 0
koha_1       |     #                                                          },
koha_1       |     #                                                          {
koha_1       |     #                                                            'notificationdate' => undef,
koha_1       |     #                                                            'timestamp' => '2019-06-25 17:00:30',
koha_1       |     #                                                            'lowestPriority' => 0,
koha_1       |     #                                                            'priority' => 2,
koha_1       |     #                                                            'found' => undef,
koha_1       |     #                                                            'reminderdate' => undef,
koha_1       |     #                                                            'reserve_id' => 83,
koha_1       |     #                                                            'branchcode' => 'xszWxdJW',
koha_1       |     #                                                            'suspend_until' => undef,
koha_1       |     #                                                            'reservedate' => '2019-06-25',
koha_1       |     #                                                            'suspend' => 0,
koha_1       |     #                                                            'itemnumber' => undef,
koha_1       |     #                                                            'cancellationdate' => undef,
koha_1       |     #                                                            'item_level_hold' => 0,
koha_1       |     #                                                            'borrowernumber' => 361,
koha_1       |     #                                                            'biblionumber' => 797,
koha_1       |     #                                                            'reservenotes' => undef,
koha_1       |     #                                                            'expirationdate' => undef,
koha_1       |     #                                                            'itemtype' => undef,
koha_1       |     #                                                            'waitingdate' => undef
koha_1       |     #                                                          }
koha_1       |     #                                                        ],
koha_1       |     #                                     'holdingbranch' => 'xszWxdJW',
koha_1       |     #                                     'dateaccessioned' => '2019-06-25',
koha_1       |     #                                     'hold_shelf' => [],
koha_1       |     #                                     'sip_media_type' => 'dqM',
koha_1       |     #                                     'damaged_on' => '2019-06-25 17:00:29',
koha_1       |     #                                     'copynumber' => 'hEC8C8bmV3f6qw6ZFkL0cA',
koha_1       |     #                                     'notforloan' => 0,
koha_1       |     #                                     'stack' => 80,
koha_1       |     #                                     'cn_sort' => 'p_GYsej_UskNJtmWE5zdmH2CcD0BoGSS9OeM1wEzgLFwkln1JzvyJfgI9wDjJJlCqv1DOPVN1lJB_aALnQSZwvJfOOh0LVP8tw0haRDw3tmdJ6SWFimcD1JaLgEhxG7af4dF7MiFPlJRX',
koha_1       |     #                                     'price' => '933513.75',
koha_1       |     #                                     'itype' => 'zB1TfuD_C5',
koha_1       |     #                                     'permanent_location' => 'xszWxdJW',
koha_1       |     #                                     'materials' => 'zfQsTWnb6D',
koha_1       |     #                                     'onloan' => '2019-06-25',
koha_1       |     #                                     'collection_code' => 'nudtLfXyidGZJTrQZe0pW2Q1BctKWCgvr5i8PJ1nwi8z6XFX8d4c',
koha_1       |     #                                     'itemlost_on' => '2019-06-25 17:00:29',
koha_1       |     #                                     'coded_location_qualifier' => 'YzA3DSk',
koha_1       |     #                                     'enumchron' => 'MNsB1X409N',
koha_1       |     #                                     'itemcallnumber' => 'uKI5ZXnl6AB7wapbXEzkWdgFE3nULdnJ8NuUaWMNbOiYCeK5YCmqYynwyG45V21FeuoCq4fQ8vpC14z0lwraKd3PEq4KJuW0uytUG74OxRqB6fgPr01YhLKvclXE9AYTFaSfbyxt8fTfX9IQq',
koha_1       |     #                                     'restricted' => 0,
koha_1       |     #                                     'itemlost' => 0,
koha_1       |     #                                     'uri' => 'coBcdDTdKz4TU96GH21_ZbIzsA2xW8Tol63Dq5Qv2jGFZm0Uo_VDIiV01Jz67CoczHo40BtKjpZPBYgD1BCxhvhOefGPHOFjpPCWYAm6a5ZlPdKY_oX0BhkPWeaXMeH4muOkKm_FC5CR9QJXFk3p0HSi0z9NHil2fbecCLzdwnT3h8V4Yk1JbnDkB4K3yA2ygTAlbkhbAmerJDX3QTJZfWBByJr',
koha_1       |     #                                     'author' => 'HUtlSmqexi',
koha_1       |     #                                     'more_subfields_xml' => undef,
koha_1       |     #                                     'booksellerid' => 'JlgxqDO',
koha_1       |     #                                     'reserves' => 17068,
koha_1       |     #                                     'location' => 'mEZLGmXYJYYq32EcoZlV6DpPiUwHsiWdoPPzveFdBrgl7pBysTwUkY8HXuzP',
koha_1       |     #                                     'issues' => 31743,
koha_1       |     #                                     'timestamp' => '2019-06-25 17:00:29',
koha_1       |     #                                     'itemnumber' => 1185,
koha_1       |     #                                     'cn_source' => 'wdjN_odBQK',
koha_1       |     #                                     'hold_queue' => [
koha_1       |     #                                                       $VAR1->{'item'}{'pending_queue'}[0],
koha_1       |     #                                                       $VAR1->{'item'}{'pending_queue'}[1]
koha_1       |     #                                                     ],
koha_1       |     #                                     'id' => 'barcode4test',
koha_1       |     #                                     'new_status' => 'uTICQ9KSpDZZV6meCMKmC',
koha_1       |     #                                     'title' => 'vRzwBGyPhh',
koha_1       |     #                                     'renewals' => 21477
koha_1       |     #                                   }, 'C4::SIP::ILS::Item' ),
koha_1       |     #                  'fee_amount' => undef,
koha_1       |     #                  'renewed' => [],
koha_1       |     #                  '_permitted' => {
koha_1       |     #                                    'sip_fee_type' => '01',
koha_1       |     #                                    'due' => undef,
koha_1       |     #                                    'screen_msg' => '',
koha_1       |     #                                    'print_line' => '',
koha_1       |     #                                    'sip_currency' => 'USD',
koha_1       |     #                                    'patron' => undef,
koha_1       |     #                                    'security_inhibit' => 0,
koha_1       |     #                                    'unrenewed' => [],
koha_1       |     #                                    'transaction_id' => undef,
koha_1       |     #                                    'renewed' => $VAR1->{'renewed'},
koha_1       |     #                                    'alert' => '',
koha_1       |     #                                    'item' => undef,
koha_1       |     #                                    'fee_amount' => undef,
koha_1       |     #                                    'renew_ok' => 0,
koha_1       |     #                                    'desensitize' => 0,
koha_1       |     #                                    'ok' => 0,
koha_1       |     #                                    'fee_ack' => 'N',
koha_1       |     #                                    'renewal_ok' => 0
koha_1       |     #                                  },
koha_1       |     #                  'alert' => '',
koha_1       |     #                  'transaction_id' => undef,
koha_1       |     #                  'unrenewed' => $VAR1->{'_permitted'}{'unrenewed'},
koha_1       |     #                  'fee_ack' => 'N',
koha_1       |     #                  'renewal_ok' => 0,
koha_1       |     #                  'desensitize' => 0,
koha_1       |     #                  'ok' => 0,
koha_1       |     #                  'sip_fee_type' => '01',
koha_1       |     #                  'due' => undef,
koha_1       |     #                  'screen_msg' => 'Issue failed : STATS',
koha_1       |     #                  'security_inhibit' => 0,
koha_1       |     #                  'patron' => bless( {
koha_1       |     #                                       'inet' => 1,
koha_1       |     #                                       'charge_ok' => 1,
koha_1       |     #                                       'renew_ok' => 1,
koha_1       |     #                                       'birthdate_iso' => '2019-06-25',
koha_1       |     #                                       'password' => 'QvP_QLVcA5umlnO8sagDtrkdWTeDj_XNOBMA',
koha_1       |     #                                       'ptype' => 'BL6PFt',
koha_1       |     #                                       'hold_items' => undef,
koha_1       |     #                                       'recall_items' => [],
koha_1       |     #                                       'borrowernumber' => 361,
koha_1       |     #                                       'userid' => 'haPVIUg98IU37r3JLQP5JyF07Vn93MvOK4Z2341Nji',
koha_1       |     #                                       'items' => [],
koha_1       |     #                                       'branchcode' => 'xszWxdJW',
koha_1       |     #                                       'fee_limit' => 5,
koha_1       |     #                                       'expired' => 0,
koha_1       |     #                                       'fine_items' => [],
koha_1       |     #                                       'screen_msg' => 'Greetings from Koha. hS_sXNI',
koha_1       |     #                                       'fines' => 0,
koha_1       |     #                                       'overdue_items' => undef,
koha_1       |     #                                       'address' => 'mdNK9vS E5u_snT jLgbxSTiZ uX1X17lnX EaANLC1X1r ivxV9LlloJcir BqFI9VWu',
koha_1       |     #                                       'hold_ok' => 1,
koha_1       |     #                                       'home_phone' => 'AJvXxyWDSZ',
koha_1       |     #                                       'fees' => 0,
koha_1       |     #                                       'dateexpiry_iso' => '2019-06-25',
koha_1       |     #                                       'claims_returned' => 0,
koha_1       |     #                                       'recall_overdue' => 0,
koha_1       |     #                                       'recall_ok' => 1,
koha_1       |     #                                       'dateexpiry' => '20190625',
koha_1       |     #                                       'name' => 'Qf77Rj4G IIe1zb3',
koha_1       |     #                                       'id' => 'ZG1AS5oEWi5f0P2jJK2Pt1rC',
koha_1       |     #                                       'birthdate' => '20190625',
koha_1       |     #                                       'library_name' => '',
koha_1       |     #                                       'items_billed' => 0,
koha_1       |     #                                       'card_lost' => undef,
koha_1       |     #                                       'email_addr' => 'hs0okh',
koha_1       |     #                                       'unavail_holds' => [
koha_1       |     #                                                            {
koha_1       |     #                                                              'found' => undef,
koha_1       |     #                                                              'reminderdate' => undef,
koha_1       |     #                                                              'reserve_id' => 83,
koha_1       |     #                                                              'lowestPriority' => 0,
koha_1       |     #                                                              'timestamp' => '2019-06-25 17:00:30',
koha_1       |     #                                                              'notificationdate' => undef,
koha_1       |     #                                                              'priority' => 2,
koha_1       |     #                                                              'cancellationdate' => undef,
koha_1       |     #                                                              'itemnumber' => undef,
koha_1       |     #                                                              'reservedate' => '2019-06-25',
koha_1       |     #                                                              'suspend_until' => undef,
koha_1       |     #                                                              'branchcode' => 'xszWxdJW',
koha_1       |     #                                                              'suspend' => 0,
koha_1       |     #                                                              'biblionumber' => 797,
koha_1       |     #                                                              'borrowernumber' => 361,
koha_1       |     #                                                              'item_level_hold' => 0,
koha_1       |     #                                                              'barcode' => 'barcode4test',
koha_1       |     #                                                              'expirationdate' => undef,
koha_1       |     #                                                              'reservenotes' => undef,
koha_1       |     #                                                              'waitingdate' => undef,
koha_1       |     #                                                              'itemtype' => undef
koha_1       |     #                                                            },
koha_1       |     #                                                            {
koha_1       |     #                                                              'itemnumber' => undef,
koha_1       |     #                                                              'cancellationdate' => undef,
koha_1       |     #                                                              'suspend' => 0,
koha_1       |     #                                                              'branchcode' => 'xszWxdJW',
koha_1       |     #                                                              'reservedate' => '2019-06-25',
koha_1       |     #                                                              'suspend_until' => undef,
koha_1       |     #                                                              'reserve_id' => 84,
koha_1       |     #                                                              'found' => undef,
koha_1       |     #                                                              'reminderdate' => undef,
koha_1       |     #                                                              'priority' => 1,
koha_1       |     #                                                              'timestamp' => '2019-06-25 17:00:30',
koha_1       |     #                                                              'notificationdate' => undef,
koha_1       |     #                                                              'lowestPriority' => 0,
koha_1       |     #                                                              'waitingdate' => undef,
koha_1       |     #                                                              'itemtype' => undef,
koha_1       |     #                                                              'reservenotes' => undef,
koha_1       |     #                                                              'expirationdate' => undef,
koha_1       |     #                                                              'borrowernumber' => 361,
koha_1       |     #                                                              'biblionumber' => 797,
koha_1       |     #                                                              'barcode' => 'barcode4test',
koha_1       |     #                                                              'item_level_hold' => 0
koha_1       |     #                                                            }
koha_1       |     #                                                          ],
koha_1       |     #                                       'print_line' => ''
koha_1       |     #                                     }, 'C4::SIP::ILS::Patron' ),
koha_1       |     #                  'print_line' => '',
koha_1       |     #                  'sip_currency' => 'USD'
koha_1       |     #                }, 'C4::SIP::ILS::Transaction::Checkout' );
koha_1       |     # Looks like you failed 1 test of 6.
koha_1       | 
koha_1       | #   Failed test 'fill_holds_at_checkout'
koha_1       | #   at t/db_dependent/SIP/Transaction.t line 97.
koha_1       | # Looks like you failed 1 test of 4.
koha_1       | [17:00:30] t/db_dependent/SIP/Transaction.t ........................................ 
koha_1       | Dubious, test returned 1 (wstat 256, 0x100)
koha_1       | Failed 1/4 subtests