IT failed `TestE2ENonFungibleTokensSync` with PostgreSQL

[peterbroadhurst]

https://github.com/hyperledger/firefly/runs/5045461824?check_suite_focus=true

2022-02-03T01:02:12.6363086Z     --- FAIL: TestEthereumE2ESuite/TestE2ENonFungibleTokensSync (7.47s)

2022-02-03T01:02:08.6698741Z     restclient.go:72: <== 500
2022-02-03T01:02:08.6699986Z     restclient.go:74: <!! {"error":"FF10274: Error from tokens service: : Post \"http://tokens_1:3000/api/v1/burn\": readfrom tcp 172.18.0.15:45520-\u003e172.18.0.12:3000: write tcp 172.18.0.15:45520-\u003e172.18.0.12:3000: use of closed network connection"}
2022-02-03T01:02:08.6702073Z     restclient.go:75: Headers: map[Content-Length:[233] Content-Type:[application/json] Date:[Thu, 03 Feb 2022 01:02:08 GMT] Vary:[Origin]]
2022-02-03T01:02:08.6702709Z     restclient.go:411: 
2022-02-03T01:02:08.6703203Z         	Error Trace:	restclient.go:411
2022-02-03T01:02:08.6704428Z         	            				tokens_test.go:284
2022-02-03T01:02:08.6704751Z         	Error:      	Not equal: 
2022-02-03T01:02:08.6705258Z         	            	expected: 200
2022-02-03T01:02:08.6705636Z         	            	actual  : 500
2022-02-03T01:02:08.6706075Z         	Test:       	TestEthereumE2ESuite/TestE2ENonFungibleTokensSync
2022-02-03T01:02:08.6707921Z         	Messages:   	POST /namespaces/default/tokens/burn [500]: {"error":"FF10274: Error from tokens service: : Post \"http://tokens_1:3000/api/v1/burn\": readfrom tcp 172.18.0.15:45520-\u003e172.18.0.12:3000: write tcp 172.18.0.15:45520-\u003e172.18.0.12:3000: use of closed network connection"}
2022-02-03T01:02:08.6709814Z     e2e_test.go:269: Websocket 127.0.0.1:5000 closing, error: read tcp 127.0.0.1:54208->127.0.0.1:5000: use of closed network connection

[peterbroadhurst]

Here's the sequence of calls in the logs for that token connector:

firefly_core_1_1  | [2022-02-03T01:01:54.566Z]  INFO ==> POST http://tokens_1:3000/api/v1/activatepool breq=xWSFXGzk pid=1 proto=fftokens
firefly_core_1_1  | [2022-02-03T01:01:54.597Z]  INFO <== POST http://tokens_1:3000/api/v1/activatepool [204] (30.20ms) breq=xWSFXGzk pid=1 proto=fftokens
firefly_core_1_1  | [2022-02-03T01:01:59.637Z]  INFO ==> POST http://tokens_1:3000/api/v1/burn breq=H_ilMd0n pid=1 proto=fftokens
firefly_core_1_1  | [2022-02-03T01:01:59.662Z]  INFO <== POST http://tokens_1:3000/api/v1/burn [202] (24.39ms) breq=H_ilMd0n pid=1 proto=fftokens
firefly_core_1_1  | [2022-02-03T01:02:03.601Z]  INFO ==> POST http://tokens_1:3000/api/v1/activatepool breq=z4tQHojn pid=1 proto=fftokens
firefly_core_1_1  | [2022-02-03T01:02:03.638Z]  INFO <== POST http://tokens_1:3000/api/v1/activatepool [204] (37.67ms) breq=z4tQHojn pid=1 proto=fftokens
firefly_core_1_1  | [2022-02-03T01:02:08.641Z]  INFO ==> POST http://tokens_1:3000/api/v1/burn breq=a9jxKAcK pid=1 proto=fftokens
firefly_core_1_1  | [2022-02-03T01:02:08.667Z]  INFO <-- POST /api/v1/namespaces/default/tokens/burn [500] (30.69ms): FF10274: Error from tokens service: : Post "http://tokens_1:3000/api/v1/burn": readfrom tcp 172.18.0.15:45520->172.18.0.12:3000: write tcp 172.18.0.15:45520->172.18.0.12:3000: use of closed network connection httpreq=YGTULNha pid=1 req=xthgvmne

[peterbroadhurst]

The last log entry from the token connector itself is here - so it might have terminated while servicing the request if there was no output captured for that (but it's very hard to tell):

tokens_1_1        | [Nest] 24  - 02/03/2022, 1:02:07 AM     LOG [EventStreamProxyGateway] Sending ack for batch

[peterbroadhurst]

I'm re-running the test to see if it's a persistent issue, or this was something timing related (maybe connection pooling/keepalive related, but there's nothing I can see in the timing to suggest that at this point - looked like one connection only being used for a few seconds).

[peterbroadhurst]

The default Node.js keepalive timeout for HTTP is 5s: https://nodejs.org/api/http.html#serverkeepalivetimeout

[peterbroadhurst]

So actually, that matches up! ... looking at what Go's default HTTP keepalive retention time is.