Create, close, cancel, Purchase Orders
(UXPROD-1141)
|
|
| 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: |
|
||||||||
| Issue links: |
|
||||||||
| 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
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 ] |
|
|
| 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:
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)
|