[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: |
|
||||||||||||
| 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! |