[FOLIO-1521] folio-testing-backend01 build failure Created: 20/Sep/18  Updated: 12/Nov/18  Resolved: 04/Oct/18

Status: Closed
Project: FOLIO
Components: None
Affects versions: None
Fix versions: None

Type: Bug Priority: P2
Reporter: Wayne Schneider Assignee: Wayne Schneider
Resolution: Done Votes: 0
Labels: ci, sprint47, sprint48
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original estimate: Not Specified

Issue links:
Blocks
is blocked by MODAT-38 Missing module token when calling /to... Closed
is blocked by MODAT-39 Missing module token when auth filter... Closed
Sprint:
Development Team: Prokopovych

 Description   

The folio-testing-backend01 build failed tonight with this error:

failed: [10.36.1.183] (item=loans/girl-on-the-train-item-2.json) => {"changed": false, "connection": "close", "content": "Failed to contact storage module: io.vertx.core.VertxException: Connection was closed", "content_type": "text/plain; charset=ISO-8859-1", "failed": true, "item": "loans/girl-on-the-train-item-2.json", "msg": "Status code was not [201, 422]: HTTP Error 500: Internal Server Error", "redirected": false, "status": 500, "transfer_encoding": "chunked", "url": "http://10.36.1.183:9130/circulation/loans", "x_okapi_trace": "POST mod-authtoken-2.0.2-SNAPSHOT.28 http://10.36.1.183:9131/circulation/loans : 202 845us, POST mod-audit-filter-0.0.2-SNAPSHOT.8 http://10.36.1.183:9160/circulation/loans : 200 347us, POST mod-circulation-12.0.1-SNAPSHOT.171 http://10.36.1.183:9142/circulation/loans : 500 440819us, POST mod-audit-filter-0.0.2-SNAPSHOT.8 http://10.36.1.183:9160/circulation/loans : 200 4171us"}

Loans before and after both succeeded.

Okapi log shows:

2018-09-20 02:03:02,905 INFO  DockerModuleHandle   mod-circulation-12.0.1-SNAPSHOT.171 02:03:02 INFO  OkapiHttpClient      POST http://10.36.1.183:9130/loan-storage/loans, Request: {
2018-09-20 02:03:02,905 INFO  DockerModuleHandle   mod-circulation-12.0.1-SNAPSHOT.171   "itemId" : "459afaba-5b39-468d-9072-eb1685e0ddf4",
2018-09-20 02:03:02,905 INFO  DockerModuleHandle   mod-circulation-12.0.1-SNAPSHOT.171   "status" : {
2018-09-20 02:03:02,905 INFO  DockerModuleHandle   mod-circulation-12.0.1-SNAPSHOT.171     "name" : "Open"
2018-09-20 02:03:02,906 INFO  DockerModuleHandle   mod-circulation-12.0.1-SNAPSHOT.171   },
2018-09-20 02:03:02,906 INFO  DockerModuleHandle   mod-circulation-12.0.1-SNAPSHOT.171   "loanDate" : "2017-10-06T08:43:15Z",
2018-09-20 02:03:02,906 INFO  DockerModuleHandle   mod-circulation-12.0.1-SNAPSHOT.171   "action" : "checkedout",
2018-09-20 02:03:02,906 INFO  DockerModuleHandle   mod-circulation-12.0.1-SNAPSHOT.171   "renewalCount" : 0,
2018-09-20 02:03:02,906 INFO  DockerModuleHandle   mod-circulation-12.0.1-SNAPSHOT.171   "userId" : "e611ef88-6232-4014-930b-8dc21876446e",
2018-09-20 02:03:02,906 INFO  DockerModuleHandle   mod-circulation-12.0.1-SNAPSHOT.171   "id" : "c335374f-ce36-4ab0-a543-00eb447258e6",
2018-09-20 02:03:02,906 INFO  DockerModuleHandle   mod-circulation-12.0.1-SNAPSHOT.171   "dueDate" : "2017-10-17T08:43:15Z",
2018-09-20 02:03:02,906 INFO  DockerModuleHandle   mod-circulation-12.0.1-SNAPSHOT.171   "itemStatus" : "Checked out",
2018-09-20 02:03:02,906 INFO  DockerModuleHandle   mod-circulation-12.0.1-SNAPSHOT.171   "loanPolicyId" : "43198de5-f56a-4a53-a0bd-5a324418967a"
2018-09-20 02:03:02,906 INFO  DockerModuleHandle   mod-circulation-12.0.1-SNAPSHOT.171 }
2018-09-20 02:03:02,910 INFO  DockerModuleHandle   mod-circulation-12.0.1-SNAPSHOT.171 02:03:02 ERROR ConnectionBase       invalid version format: 0
2018-09-20 02:03:02,911 INFO  ProxyContext         290625/circulation RES 500 440824us mod-circulation-12.0.1-SNAPSHOT.171 http://10.36.1.183:9142/circulation/loans


 Comments   
Comment by Wayne Schneider [ 20/Sep/18 ]

Retrying the build in case of a transient error.

Comment by Wayne Schneider [ 20/Sep/18 ]

Apparently the same error on rebuild, in the same place. Attempting to reproduce error locally.

Comment by Wayne Schneider [ 20/Sep/18 ]

Extremely odd – I can build a system locally using the same Ansible roles.

Comment by Wayne Schneider [ 21/Sep/18 ]

The backend build completed successfully this evening. It is possible that today's update to mod-audit-filter made a difference, but that's mostly speculation at this point. Closing this issue for now.

Comment by Wayne Schneider [ 24/Sep/18 ]

Reopening issue. The same failure at the same point surfaced again on 22 September.

Comment by Wayne Schneider [ 24/Sep/18 ]

Omitting the single loan record results in a successful build.

Comment by Wayne Schneider [ 26/Sep/18 ]

The build failed last night with a different loan record.

I don't have logs available, but I had noticed a number of 500 errors coming from mod-audit-filter. I removed both audit modules from the build, added the original suspect loan record back, and had a successful build.

Hongwei Ji – I don't think there is enough here to go on yet. I will investigate more fully next week (after the Q3 release is more or less finalized). For right now, mod-audit and mod-audit-filter are removed from the folio-testing AWS build, but they remain in the Vagrant folio/testing and folio/testing-backend daily builds.

Comment by Hongwei Ji [ 26/Sep/18 ]

Wayne Schneider, I'd like to try it out and research the cause. What are the steps to reproduce? Git clone folio-ansible and then do something? Also, which version of audit modules are you using? The released version or the latest from master?

Comment by Wayne Schneider [ 26/Sep/18 ]

Hongwei Ji – I haven't been able to reproduce the error locally. It only surfaces in our AWS builds, not in our packer builds using the same build script or locally running folio-ansible.

You may want to try using the latest folio/testing-backend build (or folio/testing) from Vagrant Cloud, running some transactions, and examining the logs – that was going to be my next step.

The audit modules are running from HEAD of master, as with all modules in folio-testing.

Comment by Wayne Schneider [ 01/Oct/18 ]

Last night (30 Sept) the folio/testing-backend Vagrant build (which still includes the audit subsystem) failed with a similar error:

testing-backend: failed: [default] (item=loans/interesting-times-item-2.json) => {"changed": false, "connection": "close", "content": "Failed to contact storage module: io.vertx.core.http.impl.HttpClientRequestBase$1: The timeout period of 5000ms has been exceeded while executing POST /loan-storage/loans for host 10.0.2.15", "content_type": "text/plain; charset=ISO-8859-1", "item": "loans/interesting-times-item-2.json", "msg": "Status code was not [201, 422]: HTTP Error 500: Internal Server Error", "redirected": false, "status": 500, "transfer_encoding": "chunked", "url": "http://10.0.2.15:9130/circulation/loans", "x_okapi_trace": "POST mod-authtoken-2.0.2-SNAPSHOT.30 http://10.0.2.15:9131/circulation/loans : 202 523us, POST mod-audit-filter-0.0.2-SNAPSHOT.10 http://10.0.2.15:9160/circulation/loans : 200 776us, POST mod-circulation-12.0.1-SNAPSHOT.172 http://10.0.2.15:9142/circulation/loans : 500 5634726us, POST mod-audit-filter-0.0.2-SNAPSHOT.10 http://10.0.2.15:9160/circulation/loans : 200 1610us"}

The folio/testing Vagrant build succeeded.

Comment by Wayne Schneider [ 04/Oct/18 ]

The latest updates to mod-audit-filter and mod-authtoken have resolved this issue. Thanks, Hongwei Ji!

Generated at Thu Feb 08 23:13:57 UTC 2024 using Jira 1001.0.0-SNAPSHOT#100246-sha1:7a5c50119eb0633d306e14180817ddef5e80c75d.