From 10967f0f79a33bc7a65860224028d76634b06440 Mon Sep 17 00:00:00 2001 From: David Nadoba Date: Fri, 8 Oct 2021 10:00:33 +0200 Subject: [PATCH 1/3] add test for issue #453 --- ...TTP1ClientChannelHandlerTests+XCTest.swift | 1 + .../HTTP1ClientChannelHandlerTests.swift | 50 +++++++++++++++++++ 2 files changed, 51 insertions(+) diff --git a/Tests/AsyncHTTPClientTests/HTTP1ClientChannelHandlerTests+XCTest.swift b/Tests/AsyncHTTPClientTests/HTTP1ClientChannelHandlerTests+XCTest.swift index 7781d0820..8d28c15c4 100644 --- a/Tests/AsyncHTTPClientTests/HTTP1ClientChannelHandlerTests+XCTest.swift +++ b/Tests/AsyncHTTPClientTests/HTTP1ClientChannelHandlerTests+XCTest.swift @@ -29,6 +29,7 @@ extension HTTP1ClientChannelHandlerTests { ("testWriteBackpressure", testWriteBackpressure), ("testClientHandlerCancelsRequestIfWeWantToShutdown", testClientHandlerCancelsRequestIfWeWantToShutdown), ("testIdleReadTimeout", testIdleReadTimeout), + ("testIdleReadTimeoutIsCanceledIfRequestIsCanceled", testIdleReadTimeoutIsCanceledIfRequestIsCanceled), ("testFailHTTPRequestWithContentLengthBecauseOfChannelInactiveWaitingForDemand", testFailHTTPRequestWithContentLengthBecauseOfChannelInactiveWaitingForDemand), ] } diff --git a/Tests/AsyncHTTPClientTests/HTTP1ClientChannelHandlerTests.swift b/Tests/AsyncHTTPClientTests/HTTP1ClientChannelHandlerTests.swift index 30a0a287c..62e42f94e 100644 --- a/Tests/AsyncHTTPClientTests/HTTP1ClientChannelHandlerTests.swift +++ b/Tests/AsyncHTTPClientTests/HTTP1ClientChannelHandlerTests.swift @@ -287,6 +287,56 @@ class HTTP1ClientChannelHandlerTests: XCTestCase { } } + func testIdleReadTimeoutIsCanceledIfRequestIsCanceled() { + let embedded = EmbeddedChannel() + var maybeTestUtils: HTTP1TestTools? + XCTAssertNoThrow(maybeTestUtils = try embedded.setupHTTP1Connection()) + guard let testUtils = maybeTestUtils else { return XCTFail("Expected connection setup works") } + + var maybeRequest: HTTPClient.Request? + XCTAssertNoThrow(maybeRequest = try HTTPClient.Request(url: "http://localhost/")) + guard let request = maybeRequest else { return XCTFail("Expected to be able to create a request") } + + let delegate = ResponseBackpressureDelegate(eventLoop: embedded.eventLoop) + var maybeRequestBag: RequestBag? + XCTAssertNoThrow(maybeRequestBag = try RequestBag( + request: request, + eventLoopPreference: .delegate(on: embedded.eventLoop), + task: .init(eventLoop: embedded.eventLoop, logger: testUtils.logger), + redirectHandler: nil, + connectionDeadline: .now() + .seconds(30), + requestOptions: .forTests(idleReadTimeout: .milliseconds(200)), + delegate: delegate + )) + guard let requestBag = maybeRequestBag else { return XCTFail("Expected to be able to create a request bag") } + + testUtils.connection.executeRequest(requestBag) + + XCTAssertNoThrow(try embedded.receiveHeadAndVerify { + XCTAssertEqual($0.method, .GET) + XCTAssertEqual($0.uri, "/") + XCTAssertEqual($0.headers.first(name: "host"), "localhost") + }) + XCTAssertNoThrow(try embedded.receiveEnd()) + + let responseHead = HTTPResponseHead(version: .http1_1, status: .ok, headers: HTTPHeaders([("content-length", "12")])) + + XCTAssertEqual(testUtils.readEventHandler.readHitCounter, 0) + embedded.read() + XCTAssertEqual(testUtils.readEventHandler.readHitCounter, 1) + XCTAssertNoThrow(try embedded.writeInbound(HTTPClientResponsePart.head(responseHead))) + + // canceling the request + requestBag.cancel() + XCTAssertThrowsError(try requestBag.task.futureResult.wait()) { + XCTAssertEqual($0 as? HTTPClientError, .cancelled) + } + + // the idle read timeout should be cleared because we canceled the request + // therefore advancing the time should not trigger a crash + embedded.embeddedEventLoop.advanceTime(by: .milliseconds(250)) + } + func testFailHTTPRequestWithContentLengthBecauseOfChannelInactiveWaitingForDemand() { let embedded = EmbeddedChannel() var maybeTestUtils: HTTP1TestTools? From 613ef01615aa5102745e5c75e387db8a6a953039 Mon Sep 17 00:00:00 2001 From: David Nadoba Date: Fri, 8 Oct 2021 10:42:59 +0200 Subject: [PATCH 2/3] cancel read timeout timer if request is set to nil --- .../HTTP1.1/HTTP1ClientChannelHandler.swift | 17 +++--- .../HTTP2/HTTP2ClientRequestHandler.swift | 14 ++--- ...TTP2ClientRequestHandlerTests+XCTest.swift | 1 + .../HTTP2ClientRequestHandlerTests.swift | 52 +++++++++++++++++++ 4 files changed, 70 insertions(+), 14 deletions(-) diff --git a/Sources/AsyncHTTPClient/ConnectionPool/HTTP1.1/HTTP1ClientChannelHandler.swift b/Sources/AsyncHTTPClient/ConnectionPool/HTTP1.1/HTTP1ClientChannelHandler.swift index 9c300b5e6..b3fcc2755 100644 --- a/Sources/AsyncHTTPClient/ConnectionPool/HTTP1.1/HTTP1ClientChannelHandler.swift +++ b/Sources/AsyncHTTPClient/ConnectionPool/HTTP1.1/HTTP1ClientChannelHandler.swift @@ -44,6 +44,7 @@ final class HTTP1ClientChannelHandler: ChannelDuplexHandler { } } else { self.logger = self.backgroundLogger + self.clearIdleReadTimeoutTimer() self.idleReadTimeoutStateMachine = nil } } @@ -307,17 +308,18 @@ final class HTTP1ClientChannelHandler: ChannelDuplexHandler { self.run(action, context: context) } - case .clearIdleReadTimeoutTimer: - if let oldTimer = self.idleReadTimeoutTimer { - self.idleReadTimeoutTimer = nil - oldTimer.cancel() - } - case .none: break } } + private func clearIdleReadTimeoutTimer() { + if let oldTimer = self.idleReadTimeoutTimer { + self.idleReadTimeoutTimer = nil + oldTimer.cancel() + } + } + // MARK: Private HTTPRequestExecutor private func writeRequestBodyPart0(_ data: IOData, request: HTTPExecutableRequest) { @@ -415,7 +417,6 @@ struct IdleReadStateMachine { enum Action { case startIdleReadTimeoutTimer(TimeAmount) case resetIdleReadTimeoutTimer(TimeAmount) - case clearIdleReadTimeoutTimer case none } @@ -465,7 +466,7 @@ struct IdleReadStateMachine { return .resetIdleReadTimeoutTimer(self.timeAmount) case .end: self.state = .responseEndReceived - return .clearIdleReadTimeoutTimer + return .none } case .responseEndReceived: diff --git a/Sources/AsyncHTTPClient/ConnectionPool/HTTP2/HTTP2ClientRequestHandler.swift b/Sources/AsyncHTTPClient/ConnectionPool/HTTP2/HTTP2ClientRequestHandler.swift index 281287750..d6594cd36 100644 --- a/Sources/AsyncHTTPClient/ConnectionPool/HTTP2/HTTP2ClientRequestHandler.swift +++ b/Sources/AsyncHTTPClient/ConnectionPool/HTTP2/HTTP2ClientRequestHandler.swift @@ -38,6 +38,7 @@ final class HTTP2ClientRequestHandler: ChannelDuplexHandler { if let newRequest = self.request, let idleReadTimeout = newRequest.requestOptions.idleReadTimeout { self.idleReadTimeoutStateMachine = .init(timeAmount: idleReadTimeout) } else { + self.clearIdleReadTimeoutTimer() self.idleReadTimeoutStateMachine = nil } } @@ -238,17 +239,18 @@ final class HTTP2ClientRequestHandler: ChannelDuplexHandler { self.run(action, context: context) } - case .clearIdleReadTimeoutTimer: - if let oldTimer = self.idleReadTimeoutTimer { - self.idleReadTimeoutTimer = nil - oldTimer.cancel() - } - case .none: break } } + private func clearIdleReadTimeoutTimer() { + if let oldTimer = self.idleReadTimeoutTimer { + self.idleReadTimeoutTimer = nil + oldTimer.cancel() + } + } + // MARK: Private HTTPRequestExecutor private func writeRequestBodyPart0(_ data: IOData, request: HTTPExecutableRequest) { diff --git a/Tests/AsyncHTTPClientTests/HTTP2ClientRequestHandlerTests+XCTest.swift b/Tests/AsyncHTTPClientTests/HTTP2ClientRequestHandlerTests+XCTest.swift index 53be47f01..a0facdb65 100644 --- a/Tests/AsyncHTTPClientTests/HTTP2ClientRequestHandlerTests+XCTest.swift +++ b/Tests/AsyncHTTPClientTests/HTTP2ClientRequestHandlerTests+XCTest.swift @@ -28,6 +28,7 @@ extension HTTP2ClientRequestHandlerTests { ("testResponseBackpressure", testResponseBackpressure), ("testWriteBackpressure", testWriteBackpressure), ("testIdleReadTimeout", testIdleReadTimeout), + ("testIdleReadTimeoutIsCanceledIfRequestIsCanceled", testIdleReadTimeoutIsCanceledIfRequestIsCanceled), ] } } diff --git a/Tests/AsyncHTTPClientTests/HTTP2ClientRequestHandlerTests.swift b/Tests/AsyncHTTPClientTests/HTTP2ClientRequestHandlerTests.swift index c1fbced67..7bbb30105 100644 --- a/Tests/AsyncHTTPClientTests/HTTP2ClientRequestHandlerTests.swift +++ b/Tests/AsyncHTTPClientTests/HTTP2ClientRequestHandlerTests.swift @@ -233,4 +233,56 @@ class HTTP2ClientRequestHandlerTests: XCTestCase { XCTAssertEqual($0 as? HTTPClientError, .readTimeout) } } + + func testIdleReadTimeoutIsCanceledIfRequestIsCanceled() { + let embedded = EmbeddedChannel() + let readEventHandler = ReadEventHitHandler() + let requestHandler = HTTP2ClientRequestHandler(eventLoop: embedded.eventLoop) + XCTAssertNoThrow(try embedded.pipeline.syncOperations.addHandlers([readEventHandler, requestHandler])) + XCTAssertNoThrow(try embedded.connect(to: .makeAddressResolvingHost("localhost", port: 0)).wait()) + let logger = Logger(label: "test") + + var maybeRequest: HTTPClient.Request? + XCTAssertNoThrow(maybeRequest = try HTTPClient.Request(url: "http://localhost/")) + guard let request = maybeRequest else { return XCTFail("Expected to be able to create a request") } + + let delegate = ResponseBackpressureDelegate(eventLoop: embedded.eventLoop) + var maybeRequestBag: RequestBag? + XCTAssertNoThrow(maybeRequestBag = try RequestBag( + request: request, + eventLoopPreference: .delegate(on: embedded.eventLoop), + task: .init(eventLoop: embedded.eventLoop, logger: logger), + redirectHandler: nil, + connectionDeadline: .now() + .seconds(30), + requestOptions: .forTests(idleReadTimeout: .milliseconds(200)), + delegate: delegate + )) + guard let requestBag = maybeRequestBag else { return XCTFail("Expected to be able to create a request bag") } + + embedded.write(requestBag, promise: nil) + + XCTAssertNoThrow(try embedded.receiveHeadAndVerify { + XCTAssertEqual($0.method, .GET) + XCTAssertEqual($0.uri, "/") + XCTAssertEqual($0.headers.first(name: "host"), "localhost") + }) + XCTAssertNoThrow(try embedded.receiveEnd()) + + let responseHead = HTTPResponseHead(version: .http1_1, status: .ok, headers: HTTPHeaders([("content-length", "12")])) + + XCTAssertEqual(readEventHandler.readHitCounter, 0) + embedded.read() + XCTAssertEqual(readEventHandler.readHitCounter, 1) + XCTAssertNoThrow(try embedded.writeInbound(HTTPClientResponsePart.head(responseHead))) + + // canceling the request + requestBag.cancel() + XCTAssertThrowsError(try requestBag.task.futureResult.wait()) { + XCTAssertEqual($0 as? HTTPClientError, .cancelled) + } + + // the idle read timeout should be cleared because we canceled the request + // therefore advancing the time should not trigger a crash + embedded.embeddedEventLoop.advanceTime(by: .milliseconds(250)) + } } From f234e0158baaab97672d63ac0c8b4be0f017ebe4 Mon Sep 17 00:00:00 2001 From: David Nadoba Date: Fri, 8 Oct 2021 15:55:47 +0200 Subject: [PATCH 3/3] fix review comments --- .../HTTP1.1/HTTP1ClientChannelHandler.swift | 28 +++++++++++++------ .../HTTP2/HTTP2ClientRequestHandler.swift | 17 +++++------ 2 files changed, 28 insertions(+), 17 deletions(-) diff --git a/Sources/AsyncHTTPClient/ConnectionPool/HTTP1.1/HTTP1ClientChannelHandler.swift b/Sources/AsyncHTTPClient/ConnectionPool/HTTP1.1/HTTP1ClientChannelHandler.swift index b3fcc2755..fcd59bc3d 100644 --- a/Sources/AsyncHTTPClient/ConnectionPool/HTTP1.1/HTTP1ClientChannelHandler.swift +++ b/Sources/AsyncHTTPClient/ConnectionPool/HTTP1.1/HTTP1ClientChannelHandler.swift @@ -44,7 +44,6 @@ final class HTTP1ClientChannelHandler: ChannelDuplexHandler { } } else { self.logger = self.backgroundLogger - self.clearIdleReadTimeoutTimer() self.idleReadTimeoutStateMachine = nil } } @@ -53,6 +52,11 @@ final class HTTP1ClientChannelHandler: ChannelDuplexHandler { private var idleReadTimeoutStateMachine: IdleReadStateMachine? private var idleReadTimeoutTimer: Scheduled? + /// Cancelling a task in NIO does *not* guarantee that the task will not execute under certain race conditions. + /// We therefore give each timer an ID and increase the ID every time we reset or cancel it. + /// We check in the task if the timer ID has changed in the meantime and do not execute any action if has changed. + private var currentIdleReadTimeoutTimerID: Int = 0 + private let backgroundLogger: Logger private var logger: Logger @@ -254,6 +258,7 @@ final class HTTP1ClientChannelHandler: ChannelDuplexHandler { let oldRequest = self.request! self.request = nil + self.runTimeoutAction(.clearIdleReadTimeoutTimer, context: context) switch finalAction { case .close: @@ -272,6 +277,7 @@ final class HTTP1ClientChannelHandler: ChannelDuplexHandler { // see comment in the `succeedRequest` case. let oldRequest = self.request! self.request = nil + self.runTimeoutAction(.clearIdleReadTimeoutTimer, context: context) switch finalAction { case .close: @@ -293,7 +299,9 @@ final class HTTP1ClientChannelHandler: ChannelDuplexHandler { case .startIdleReadTimeoutTimer(let timeAmount): assert(self.idleReadTimeoutTimer == nil, "Expected there is no timeout timer so far.") + let timerID = self.currentIdleReadTimeoutTimerID self.idleReadTimeoutTimer = self.eventLoop.scheduleTask(in: timeAmount) { + guard self.currentIdleReadTimeoutTimerID == timerID else { return } let action = self.state.idleReadTimeoutTriggered() self.run(action, context: context) } @@ -303,23 +311,24 @@ final class HTTP1ClientChannelHandler: ChannelDuplexHandler { oldTimer.cancel() } + self.currentIdleReadTimeoutTimerID &+= 1 + let timerID = self.currentIdleReadTimeoutTimerID self.idleReadTimeoutTimer = self.eventLoop.scheduleTask(in: timeAmount) { + guard self.currentIdleReadTimeoutTimerID == timerID else { return } let action = self.state.idleReadTimeoutTriggered() self.run(action, context: context) } - + case .clearIdleReadTimeoutTimer: + if let oldTimer = self.idleReadTimeoutTimer { + self.idleReadTimeoutTimer = nil + self.currentIdleReadTimeoutTimerID &+= 1 + oldTimer.cancel() + } case .none: break } } - private func clearIdleReadTimeoutTimer() { - if let oldTimer = self.idleReadTimeoutTimer { - self.idleReadTimeoutTimer = nil - oldTimer.cancel() - } - } - // MARK: Private HTTPRequestExecutor private func writeRequestBodyPart0(_ data: IOData, request: HTTPExecutableRequest) { @@ -417,6 +426,7 @@ struct IdleReadStateMachine { enum Action { case startIdleReadTimeoutTimer(TimeAmount) case resetIdleReadTimeoutTimer(TimeAmount) + case clearIdleReadTimeoutTimer case none } diff --git a/Sources/AsyncHTTPClient/ConnectionPool/HTTP2/HTTP2ClientRequestHandler.swift b/Sources/AsyncHTTPClient/ConnectionPool/HTTP2/HTTP2ClientRequestHandler.swift index d6594cd36..48419d01a 100644 --- a/Sources/AsyncHTTPClient/ConnectionPool/HTTP2/HTTP2ClientRequestHandler.swift +++ b/Sources/AsyncHTTPClient/ConnectionPool/HTTP2/HTTP2ClientRequestHandler.swift @@ -38,7 +38,6 @@ final class HTTP2ClientRequestHandler: ChannelDuplexHandler { if let newRequest = self.request, let idleReadTimeout = newRequest.requestOptions.idleReadTimeout { self.idleReadTimeoutStateMachine = .init(timeAmount: idleReadTimeout) } else { - self.clearIdleReadTimeoutTimer() self.idleReadTimeoutStateMachine = nil } } @@ -197,11 +196,13 @@ final class HTTP2ClientRequestHandler: ChannelDuplexHandler { case .failRequest(let error, let finalAction): self.request!.fail(error) self.request = nil + self.runTimeoutAction(.clearIdleReadTimeoutTimer, context: context) self.runFinalAction(finalAction, context: context) case .succeedRequest(let finalAction, let finalParts): self.request!.succeedRequest(finalParts) self.request = nil + self.runTimeoutAction(.clearIdleReadTimeoutTimer, context: context) self.runFinalAction(finalAction, context: context) } } @@ -225,6 +226,7 @@ final class HTTP2ClientRequestHandler: ChannelDuplexHandler { assert(self.idleReadTimeoutTimer == nil, "Expected there is no timeout timer so far.") self.idleReadTimeoutTimer = self.eventLoop.scheduleTask(in: timeAmount) { + guard self.idleReadTimeoutTimer != nil else { return } let action = self.state.idleReadTimeoutTriggered() self.run(action, context: context) } @@ -235,22 +237,21 @@ final class HTTP2ClientRequestHandler: ChannelDuplexHandler { } self.idleReadTimeoutTimer = self.eventLoop.scheduleTask(in: timeAmount) { + guard self.idleReadTimeoutTimer != nil else { return } let action = self.state.idleReadTimeoutTriggered() self.run(action, context: context) } + case .clearIdleReadTimeoutTimer: + if let oldTimer = self.idleReadTimeoutTimer { + self.idleReadTimeoutTimer = nil + oldTimer.cancel() + } case .none: break } } - private func clearIdleReadTimeoutTimer() { - if let oldTimer = self.idleReadTimeoutTimer { - self.idleReadTimeoutTimer = nil - oldTimer.cancel() - } - } - // MARK: Private HTTPRequestExecutor private func writeRequestBodyPart0(_ data: IOData, request: HTTPExecutableRequest) {