Create, close, cancel, Purchase Orders (UXPROD-1141)

[MODORDSTOR-57] Loading reference records fails Created: 13/Feb/19  Updated: 17/Mar/21  Resolved: 19/Feb/19

Status: Closed
Project: mod-orders-storage
Components: None
Affects versions: None
Fix versions: 3.0.0
Parent: Create, close, cancel, Purchase Orders

Type: Bug Priority: P1
Reporter: Marc Johnson Assignee: Varun Javalkar
Resolution: Done Votes: 0
Labels: back-end, ci, environments
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original estimate: Not Specified

Attachments: PNG File Screen Shot 2019-02-19 at 4.23.04 PM.png     PNG File TestingEnv.png     PNG File recreatedIssue.png     PNG File runAfterFix.png    
Issue links:
Blocks
blocks FOLIO-1804 Reference environment builds fail due... Closed
Sprint: ACQ Sprint 57
Story Points: 2
Development Team: Thunderjet
Tester Assignee: Craig McNally
Epic Link: Create, close, cancel, Purchase Orders

 Description   

Symptoms

Snapshot

RUNNING HANDLER [folio-ansible/roles/okapi-deploy-config : Build tenant parameter list] ***
ok: [10.36.1.64] => (item={'value': [{u'name': u'loadSample', u'value': u'true'}], 'key': u'mod-orders-storage'})
ok: [10.36.1.64] => (item={'value': [{u'name': u'loadReference', u'value': u'true'}], 'key': u'mod-inventory-storage'})

RUNNING HANDLER [folio-ansible/roles/okapi-deploy-config : Discard duplicates in tenant parameter list] ***
ok: [10.36.1.64]

RUNNING HANDLER [folio-ansible/roles/okapi-deploy-config : Convert tenant parameter list to query string] ***
ok: [10.36.1.64] => (item={u'name': u'loadSample', u'value': u'true'})
ok: [10.36.1.64] => (item={u'name': u'loadReference', u'value': u'true'})

RUNNING HANDLER [folio-ansible/roles/okapi-deploy-config : Perform module installation] ***
FATAL: command execution failed
hudson.AbortException: Ansible playbook execution failed
	at org.jenkinsci.plugins.ansible.AnsiblePlaybookBuilder.perform(AnsiblePlaybookBuilder.java:262)

Testing

TASK [folio-ansible/roles/okapi-tenant-deploy : Post install list for deployment and enabling] ***
fatal: [10.36.1.212]: FAILED! => {"changed": false, "content": "", "msg": "Status code was -1 and not [200]: Connection failure: timed out", "redirected": false, "status": -1, "url": "http://10.36.1.212:9130/_/proxy/tenants/diku/install?deploy=true&tenantParameters=loadReference%3Dtrue%2CloadSample%3Dtrue"}
	to retry, use: --limit @/home/jenkins/workspace/Automation/folio-testing-backend01/CI/ansible/folio-testing-backend.retry

Environments Affected

It did not seem to affect the folio-snapshot-core build

This also affected the Vagrant builds for snapshot and testing backend. The snapshot core backend build failure seems unrelated (but I'm far from sure).

Initial Investigation

I was unable to discover much from the error messages in the builds except maybe that a long running operation timed out or was aborted.

It might happen during the activation of modules that load reference or sample records during tenant activation, based upon this snippet:

RUNNING HANDLER [folio-ansible/roles/okapi-deploy-config : Build tenant parameter list] ***
ok: [10.36.1.64] => (item={'value': [{u'name': u'loadSample', u'value': u'true'}], 'key': u'mod-orders-storage'})
ok: [10.36.1.64] => (item={'value': [{u'name': u'loadReference', u'value': u'true'}], 'key': u'mod-inventory-storage'})

RUNNING HANDLER [folio-ansible/roles/okapi-deploy-config : Discard duplicates in tenant parameter list] ***
ok: [10.36.1.64]

RUNNING HANDLER [folio-ansible/roles/okapi-deploy-config : Convert tenant parameter list to query string] ***
ok: [10.36.1.64] => (item={u'name': u'loadSample', u'value': u'true'})
ok: [10.36.1.64] => (item={u'name': u'loadReference', u'value': u'true'})

Folio-snapshot-core seems unaffected. Given that builds differently that might narrow down what could have caused that.

I briefly investigated the recent changes to mod-inventory-storage, mod-orders-storage and folio-ansible but didn't spot anything obvious from yesterday that might have caused this.

I've repeated the builds to check whether it is transient.



 Comments   
Comment by Piotr Kalashuk [ 13/Feb/19 ]

The issue is caused by the incorrect usage of the transaction mechanism introduced in MODORDSTOR-45 Closed . The logic created transaction but the DB connection associated with the transaction was not actually used.
The changes applied in PR#86 are to use DB connection created for transaction for both Order and POL number sequence creation. Also some debug logging added to investigate the issue.

Here is sample output of the debug messages when the issue is recreated:

2019-02-13T16:24:24,360 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Creating a new purchase order
2019-02-13T16:24:24,361 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Start transaction
2019-02-13T16:24:24,363 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Creating new order with id=589a6016-3463-49f6-8aa2-dc315d0665fd
2019-02-13T16:24:24,365 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Creating a new purchase order
2019-02-13T16:24:24,365 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Start transaction
2019-02-13T16:24:24,365 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Creating new order with id=55b97a4a-6601-4488-84e1-8b0d47a3f523
2019-02-13T16:24:24,365 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Creating a new purchase order
2019-02-13T16:24:24,365 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Start transaction
2019-02-13T16:24:24,365 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Creating new order with id=9447d062-89ec-486e-a14b-572f3efb9f8c
2019-02-13T16:24:24,366 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Creating a new purchase order
2019-02-13T16:24:24,366 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Start transaction
2019-02-13T16:24:24,366 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Creating new order with id=8c328a18-5761-4329-95f6-599412c32310
2019-02-13T16:24:24,367 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Creating a new purchase order
2019-02-13T16:24:24,367 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Start transaction
2019-02-13T16:24:24,367 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Creating new order with id=1ab7ef6a-d1d4-4a4f-90a2-882aed18af14

There is nothing else after this and the response is not coming back to client.

Here is Postman screen which produced log messages above

Once the DB connection associated with transaction is used to create order and sequence, the log output is like following:

2019-02-13T16:38:25,491 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Creating a new purchase order
2019-02-13T16:38:25,493 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Start transaction
2019-02-13T16:38:25,495 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Creating new order with id=589a6016-3463-49f6-8aa2-dc315d0665fd
2019-02-13T16:38:25,496 DEBUG [vert.x-eventloop-thread-0]: PostgresClient  save (with connection and id) called on purchase_order
2019-02-13T16:38:25,527 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  New order with id=589a6016-3463-49f6-8aa2-dc315d0665fd successfully created
2019-02-13T16:38:25,527 DEBUG [vert.x-eventloop-thread-0]: PostgresClient  save timer: purchase_order took 31 ms
2019-02-13T16:38:25,528 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Creating POL number sequence for order with id=589a6016-3463-49f6-8aa2-dc315d0665fd
2019-02-13T16:38:25,541 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  POL number sequence for order with id=589a6016-3463-49f6-8aa2-dc315d0665fd successfully created
2019-02-13T16:38:25,541 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  End transaction
2019-02-13T16:38:25,543 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Creating a new purchase order
2019-02-13T16:38:25,544 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Start transaction
2019-02-13T16:38:25,544 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Creating new order with id=55b97a4a-6601-4488-84e1-8b0d47a3f523
2019-02-13T16:38:25,544 DEBUG [vert.x-eventloop-thread-0]: PostgresClient  save (with connection and id) called on purchase_order
2019-02-13T16:38:25,549 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  New order with id=55b97a4a-6601-4488-84e1-8b0d47a3f523 successfully created
2019-02-13T16:38:25,549 DEBUG [vert.x-eventloop-thread-0]: PostgresClient  save timer: purchase_order took 5 ms
2019-02-13T16:38:25,549 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Creating POL number sequence for order with id=55b97a4a-6601-4488-84e1-8b0d47a3f523
2019-02-13T16:38:25,552 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  POL number sequence for order with id=55b97a4a-6601-4488-84e1-8b0d47a3f523 successfully created
2019-02-13T16:38:25,553 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  End transaction
2019-02-13T16:38:25,554 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Creating a new purchase order
2019-02-13T16:38:25,554 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Start transaction
2019-02-13T16:38:25,554 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Creating new order with id=9447d062-89ec-486e-a14b-572f3efb9f8c
2019-02-13T16:38:25,554 DEBUG [vert.x-eventloop-thread-0]: PostgresClient  save (with connection and id) called on purchase_order
2019-02-13T16:38:25,556 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Creating a new purchase order
2019-02-13T16:38:25,557 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Start transaction
2019-02-13T16:38:25,558 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Creating new order with id=8c328a18-5761-4329-95f6-599412c32310
2019-02-13T16:38:25,558 DEBUG [vert.x-eventloop-thread-0]: PostgresClient  save (with connection and id) called on purchase_order
2019-02-13T16:38:25,559 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Creating a new purchase order
2019-02-13T16:38:25,561 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Start transaction
2019-02-13T16:38:25,561 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Creating new order with id=1ab7ef6a-d1d4-4a4f-90a2-882aed18af14
2019-02-13T16:38:25,561 DEBUG [vert.x-eventloop-thread-0]: PostgresClient  save (with connection and id) called on purchase_order
2019-02-13T16:38:25,569 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  New order with id=1ab7ef6a-d1d4-4a4f-90a2-882aed18af14 successfully created
2019-02-13T16:38:25,569 DEBUG [vert.x-eventloop-thread-0]: PostgresClient  save timer: purchase_order took 8 ms
2019-02-13T16:38:25,569 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Creating POL number sequence for order with id=1ab7ef6a-d1d4-4a4f-90a2-882aed18af14
2019-02-13T16:38:25,572 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  POL number sequence for order with id=1ab7ef6a-d1d4-4a4f-90a2-882aed18af14 successfully created
2019-02-13T16:38:25,572 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  End transaction
2019-02-13T16:38:25,579 DEBUG [vert.x-eventloop-thread-0]: PurchaseOrdersAPI  Preparing response to client
2019-02-13T16:38:25,582 INFO  [vert.x-eventloop-thread-0]: LogUtil  org.folio.rest.RestVerticle start  invoking postOrdersStoragePurchaseOrders
2019-02-13T16:38:25,583 INFO  [vert.x-eventloop-thread-0]: LogUtil  127.0.0.1:40503 POST /orders-storage/purchase_orders null HTTP_1_1 201 761 291 tid=diku Created {
...

Comment by Piotr Kalashuk [ 15/Feb/19 ]

FOLIO-1804 Closed is closed, folio-testing-backend01 latest builds are successful.
Testing environment has sample data:

Comment by Varun Javalkar [ 19/Feb/19 ]

I was able to verify this story through UI(http://folio-testing.aws.indexdata.com/orders/view?sort=id) and backend by ssh into the database in the folio-testing vagrant box:
Frontend:

Backend:

okapi_modules=# select * from diku_mod_orders_storage.
diku_mod_orders_storage.adjustment              diku_mod_orders_storage.details                 diku_mod_orders_storage.location                diku_mod_orders_storage.po_number               diku_mod_orders_storage.rmb_internal
diku_mod_orders_storage.alert                   diku_mod_orders_storage.eresource               diku_mod_orders_storage.physical                diku_mod_orders_storage.purchase_order          diku_mod_orders_storage.rmb_internal_id_seq
diku_mod_orders_storage.claim                   diku_mod_orders_storage.fund_distribution       diku_mod_orders_storage.pieces                  diku_mod_orders_storage.receiving_history_view  diku_mod_orders_storage.source
diku_mod_orders_storage.cost                    diku_mod_orders_storage.license                 diku_mod_orders_storage.po_line                 diku_mod_orders_storage.reporting_code          diku_mod_orders_storage.vendor_detail
okapi_modules=# select count(*) from diku_mod_orders_storage.purchase_order; 
 count 
-------
    26
(1 row)

okapi_modules=# select count(*) from diku_mod_orders_storage.po_line; 
 count 
-------
    35
(1 row)

okapi_modules=# select count(*) from diku_mod_orders_storage.po_number; 
 count 
-------
     1
(1 row)
Generated at Thu Feb 08 23:16:02 UTC 2024 using Jira 1001.0.0-SNAPSHOT#100246-sha1:7a5c50119eb0633d306e14180817ddef5e80c75d.