flaky test: HTTPClientTests.testRaceNewRequestsVsShutdown: Invalid number of leased connections (-1)

[weissi]

Test Case 'HTTPClientTests.testRaceNewRequestsVsShutdown' started at 2020-02-28 02:37:12.372
Assertion failed: Invalid number of leased connections (-1): file /code/Sources/AsyncHTTPClient/ConnectionPool.swift, line 467
Current stack trace:
0    libswiftCore.so                    0x00007f0b72f00830 _swift_stdlib_reportFatalErrorInFile + 115
1    libswiftCore.so                    0x00007f0b72e3b94c <unavailable> + 3463500
2    libswiftCore.so                    0x00007f0b72e3ba3e <unavailable> + 3463742
3    libswiftCore.so                    0x00007f0b72c3729a <unavailable> + 1348250
4    libswiftCore.so                    0x00007f0b72e0fa32 <unavailable> + 3283506
5    libswiftCore.so                    0x00007f0b72c36569 <unavailable> + 1344873
6    async-http-clientPackageTests.xctest 0x000055ff350c3b23 <unavailable> + 588579
7    async-http-clientPackageTests.xctest 0x000055ff350c3b67 <unavailable> + 588647
8    async-http-clientPackageTests.xctest 0x000055ff350bcf8e <unavailable> + 561038
9    async-http-clientPackageTests.xctest 0x000055ff350bc73a <unavailable> + 558906
10   async-http-clientPackageTests.xctest 0x000055ff350c8751 <unavailable> + 608081
11   async-http-clientPackageTests.xctest 0x000055ff350bd13a <unavailable> + 561466
12   async-http-clientPackageTests.xctest 0x000055ff350c879b <unavailable> + 608155
13   async-http-clientPackageTests.xctest 0x000055ff3551da3b <unavailable> + 5151291
14   async-http-clientPackageTests.xctest 0x000055ff350bc642 <unavailable> + 558658
15   async-http-clientPackageTests.xctest 0x000055ff350c2931 <unavailable> + 583985
16   async-http-clientPackageTests.xctest 0x000055ff350bd13a <unavailable> + 561466
17   async-http-clientPackageTests.xctest 0x000055ff350c297b <unavailable> + 584059
18   async-http-clientPackageTests.xctest 0x000055ff3551da3b <unavailable> + 5151291
19   async-http-clientPackageTests.xctest 0x000055ff350bbfb9 <unavailable> + 556985
20   async-http-clientPackageTests.xctest 0x000055ff350b5ab4 <unavailable> + 531124
21   async-http-clientPackageTests.xctest 0x000055ff350b7a12 <unavailable> + 539154
22   async-http-clientPackageTests.xctest 0x000055ff350f29e2 <unavailable> + 780770
23   async-http-clientPackageTests.xctest 0x000055ff350f29fc <unavailable> + 780796
24   async-http-clientPackageTests.xctest 0x000055ff350f2a0c <unavailable> + 780812
25   async-http-clientPackageTests.xctest 0x000055ff350f2a71 <unavailable> + 780913
26   async-http-clientPackageTests.xctest 0x000055ff35438d8c <unavailable> + 4214156
27   async-http-clientPackageTests.xctest 0x000055ff3543d7a0 <unavailable> + 4233120
28   async-http-clientPackageTests.xctest 0x000055ff3543a845 <unavailable> + 4220997
29   async-http-clientPackageTests.xctest 0x000055ff3543d805 <unavailable> + 4233221
30   async-http-clientPackageTests.xctest 0x000055ff35437b63 <unavailable> + 4209507
31   async-http-clientPackageTests.xctest 0x000055ff35437cc5 <unavailable> + 4209861
32   async-http-clientPackageTests.xctest 0x000055ff35438e3e <unavailable> + 4214334
33   async-http-clientPackageTests.xctest 0x000055ff35438bed <unavailable> + 4213741
34   async-http-clientPackageTests.xctest 0x000055ff350f2028 <unavailable> + 778280
35   async-http-clientPackageTests.xctest 0x000055ff350f2640 <unavailable> + 779840
36   async-http-clientPackageTests.xctest 0x000055ff350f2cb7 <unavailable> + 781495
37   async-http-clientPackageTests.xctest 0x000055ff350c0750 <unavailable> + 575312
38   async-http-clientPackageTests.xctest 0x000055ff350f2d11 <unavailable> + 781585
39   async-http-clientPackageTests.xctest 0x000055ff3543aecc <unavailable> + 4222668
40   async-http-clientPackageTests.xctest 0x000055ff3543da65 <unavailable> + 4233829
41   async-http-clientPackageTests.xctest 0x000055ff35433839 <unavailable> + 4192313
42   async-http-clientPackageTests.xctest 0x000055ff35434614 <unavailable> + 4195860
43   async-http-clientPackageTests.xctest 0x000055ff354344ea <unavailable> + 4195562
44   async-http-clientPackageTests.xctest 0x000055ff350bf9e4 <unavailable> + 571876
45   async-http-clientPackageTests.xctest 0x000055ff350c7cca <unavailable> + 605386
46   async-http-clientPackageTests.xctest 0x000055ff350c0750 <unavailable> + 575312
47   async-http-clientPackageTests.xctest 0x000055ff350c7d21 <unavailable> + 605473
48   async-http-clientPackageTests.xctest 0x000055ff3543aecc <unavailable> + 4222668
49   async-http-clientPackageTests.xctest 0x000055ff3543da65 <unavailable> + 4233829
50   async-http-clientPackageTests.xctest 0x000055ff35433839 <unavailable> + 4192313
51   async-http-clientPackageTests.xctest 0x000055ff35434614 <unavailable> + 4195860
52   async-http-clientPackageTests.xctest 0x000055ff354344ea <unavailable> + 4195562
53   async-http-clientPackageTests.xctest 0x000055ff35392b8c <unavailable> + 3533708
54   async-http-clientPackageTests.xctest 0x000055ff35399e3c <unavailable> + 3563068
55   async-http-clientPackageTests.xctest 0x000055ff354b5f5c <unavailable> + 4726620
56   async-http-clientPackageTests.xctest 0x000055ff354b9fa1 <unavailable> + 4743073
57   async-http-clientPackageTests.xctest 0x000055ff354b5f7c <unavailable> + 4726652
58   async-http-clientPackageTests.xctest 0x000055ff354b60e1 <unavailable> + 4727009
59   async-http-clientPackageTests.xctest 0x000055ff354b5fc7 <unavailable> + 4726727
60   async-http-clientPackageTests.xctest 0x000055ff354b6031 <unavailable> + 4726833
61   async-http-clientPackageTests.xctest 0x000055ff350b5456 <unavailable> + 529494
62   async-http-clientPackageTests.xctest 0x000055ff354b607b <unavailable> + 4726907
63   async-http-clientPackageTests.xctest 0x000055ff354af919 <unavailable> + 4700441
64   async-http-clientPackageTests.xctest 0x000055ff354b488b <unavailable> + 4720779
65   async-http-clientPackageTests.xctest 0x000055ff3542a3c2 <unavailable> + 4154306
66   async-http-clientPackageTests.xctest 0x000055ff3543196d <unavailable> + 4184429
67   async-http-clientPackageTests.xctest 0x000055ff3542accf <unavailable> + 4156623
68   async-http-clientPackageTests.xctest 0x000055ff35506ae1 <unavailable> + 5057249
69   async-http-clientPackageTests.xctest 0x000055ff35506fe8 <unavailable> + 5058536
70   async-http-clientPackageTests.xctest 0x000055ff355070a9 <unavailable> + 5058729
71   libpthread.so.0                    0x00007f0b728d66db <unavailable> + 30427
72   libc.so.6                          0x00007f0b70b5e850 clone + 63

CC @adtrevor

[PopFlamingo]

@weissi Thank you, this is the diff of the commit that may have introduced the bug:
https://gist.github.com/adtrevor/7c365cbd963ccba5534a98e8f4671a98

Will try to see what is wrong exactly

[weissi]

@adtrevor was that really already merged at 2020-02-28 02:37:12.372 ?

[PopFlamingo]

@weissi I think it was, I committed it on 2020-02-25: PopFlamingo@eee7223

[PopFlamingo]

(This was squashed into the single commit for pooling)

[weissi]

@adtrevor wrote a 100% repro with just 2 requests by accident: If you apply this patch on master, it reproes 100% for me

diff --git a/Tests/AsyncHTTPClientTests/HTTPClientInternalTests.swift b/Tests/AsyncHTTPClientTests/HTTPClientInternalTests.swift
index 9288814..be5db27 100644
--- a/Tests/AsyncHTTPClientTests/HTTPClientInternalTests.swift
+++ b/Tests/AsyncHTTPClientTests/HTTPClientInternalTests.swift
@@ -111,6 +111,7 @@ class HTTPClientInternalTests: XCTestCase {
             XCTAssertNoThrow(try httpBin.shutdown())
         }
 
+        let requestDone = httpClient.eventLoopGroup.next().makePromise(of: Void.self)
         let body: HTTPClient.Body = .stream(length: 50) { writer in
             do {
                 var request = try Request(url: "http://localhost:\(httpBin.port)/events/10/1")
@@ -119,13 +120,16 @@ class HTTPClientInternalTests: XCTestCase {
                 let delegate = HTTPClientCopyingDelegate { part in
                     writer.write(.byteBuffer(part))
                 }
-                return httpClient.execute(request: request, delegate: delegate).futureResult
+                let requestFuture = httpClient.execute(request: request, delegate: delegate).futureResult
+                requestFuture.cascade(to: requestDone)
+                return requestFuture
             } catch {
                 return httpClient.eventLoopGroup.next().makeFailedFuture(error)
             }
         }
 
         let upload = try! httpClient.post(url: "http://localhost:\(httpBin.port)/post", body: body).wait()
+        XCTAssertNoThrow(try requestDone.futureResult.wait())
         let bytes = upload.body.flatMap { $0.getData(at: 0, length: $0.readableBytes) }
         let data = try! JSONDecoder().decode(RequestInfo.self, from: bytes!)
 
diff --git a/Tests/AsyncHTTPClientTests/HTTPClientTestUtils.swift b/Tests/AsyncHTTPClientTests/HTTPClientTestUtils.swift
index 62e5fe9..37b8c6f 100644
--- a/Tests/AsyncHTTPClientTests/HTTPClientTestUtils.swift
+++ b/Tests/AsyncHTTPClientTests/HTTPClientTestUtils.swift
@@ -164,7 +164,7 @@ enum TemporaryFileHelpers {
 }
 
 internal final class HTTPBin {
-    let group = MultiThreadedEventLoopGroup(numberOfThreads: 1)
+    let group = MultiThreadedEventLoopGroup(numberOfThreads: 3)
     let serverChannel: Channel
     let isShutdown: NIOAtomic<Bool> = .makeAtomic(value: false)
     var connectionCount: NIOAtomic<Int> = .makeAtomic(value: 0)

just run testProxyStreaming

[adam-fowler]

When ever I've seen this is was caused by Task.releaseAssociatedConnection being called twice on the same Task. Already had a chat with @adtrevor about protecting against this. Unless @artemredkin's changes protect against this, I doubt they'll fix this.

Edit:
Task.fail<> gets called twice on the same task.