diff --git a/components/Blueprints/class-runner.php b/components/Blueprints/class-runner.php index 1daa3495a..f3ae44b3e 100644 --- a/components/Blueprints/class-runner.php +++ b/components/Blueprints/class-runner.php @@ -121,7 +121,17 @@ public function __construct( RunnerConfiguration $configuration ) { $this->configuration = $configuration; $this->validate_configuration( $configuration ); - $this->client = apply_filters( 'blueprint.http_client', new Client() ); + // Plugin and theme zips can take minutes to download on slow connections, + // so only fail downloads that stall rather than ones that take long. + $this->client = apply_filters( + 'blueprint.http_client', + new Client( + array( + 'timeout_ms' => 0, + 'idle_timeout_ms' => 30000, + ) + ) + ); $this->main_tracker = new Tracker(); // Set up progress logging. diff --git a/components/HttpClient/Middleware/class-httpmiddleware.php b/components/HttpClient/Middleware/class-httpmiddleware.php index 3af226b43..9a2a063c0 100644 --- a/components/HttpClient/Middleware/class-httpmiddleware.php +++ b/components/HttpClient/Middleware/class-httpmiddleware.php @@ -113,7 +113,10 @@ public function await_next_event( $requests_ids ): bool { $this->state->response_body_chunk = null; // Give the requests an opportunity to time out; 10% more, but at least 300ms. - $timeout_ms = $this->state->request_timeout_ms + max( 300, $this->state->request_timeout_ms * 0.1 ); + // With both timeouts disabled, wait for the next event indefinitely. + $limits_ms = array_filter( array( $this->state->request_timeout_ms, $this->state->idle_timeout_ms ) ); + $limit_ms = $limits_ms ? min( $limits_ms ) : 0; + $timeout_ms = $limit_ms ? $limit_ms + max( 300, $limit_ms * 0.1 ) : 0; $start_time = microtime( true ); do { diff --git a/components/HttpClient/Tests/ClientTestBase.php b/components/HttpClient/Tests/ClientTestBase.php index 78a467692..ca7a9751b 100644 --- a/components/HttpClient/Tests/ClientTestBase.php +++ b/components/HttpClient/Tests/ClientTestBase.php @@ -364,6 +364,46 @@ public function test_streaming( $type, $cmp, $expectedChunks ) { }, 'stream' ); } + /** + * stream/slow takes ~3s in total but never pauses for more than 600ms. + */ + public function test_idle_timeout_lets_a_slow_response_complete_while_data_flows() { + $this->withServer( function ( $url ) { + $client = $this->createClient( [ 'timeout_ms' => 0, 'idle_timeout_ms' => 1500 ] ); + $request = new Request( "$url/stream/slow" ); + $started = microtime( true ); + $body = $this->consume_entire_body( $client, $request ); + + $this->assertGreaterThan( 1.5, microtime( true ) - $started ); + $this->assertSame( 'sssss', $body ); + }, 'stream' ); + } + + public function test_total_timeout_still_applies_alongside_idle_timeout() { + $this->withServer( function ( $url ) { + $request = new Request( "$url/stream/slow" ); + $this->expectClientError( $request, 1500, [ + 'idle_timeout_ms' => 1500, + 'message' => [ 'Request timed out', 'cURL error' ], + ] ); + }, 'stream' ); + } + + /** + * error/timeout-read-body sends part of the body, then stalls for 5s. + */ + public function test_idle_timeout_fails_a_stalled_response() { + $this->withServer( function ( $url ) { + $request = new Request( "$url/error/timeout-read-body" ); + $started = microtime( true ); + $this->expectClientError( $request, 0, [ + 'idle_timeout_ms' => 500, + 'message' => 'without network activity', + ] ); + $this->assertLessThan( 4, microtime( true ) - $started ); + }, 'error' ); + } + public function streamingProvider() { return [ // This should take multiple polls and return at least 5 chunks. diff --git a/components/HttpClient/Transport/class-curltransport.php b/components/HttpClient/Transport/class-curltransport.php index 71b9f93a5..bbd630027 100644 --- a/components/HttpClient/Transport/class-curltransport.php +++ b/components/HttpClient/Transport/class-curltransport.php @@ -69,6 +69,9 @@ public function event_loop_tick(): bool { } $this->poll_active_curl_requests(); + // Checked after polling so data that arrived while the caller was busy + // counts as activity instead of tripping the timeout. + $this->fail_idle_requests(); foreach ( $this->state->get_active_requests( array( Request::STATE_RECEIVED ) ) as $request ) { $this->mark_finished( $request ); @@ -92,10 +95,27 @@ private function open_nonblocking_curl_handles( $requests ) { continue; } $this->state->connections[ $request->id ]->http_socket = $ch; + $this->state->connections[ $request->id ]->started_at = microtime( true ); $this->handle_map[ (int) $ch ] = $request->id; } } + private function fail_idle_requests() { + if ( ! $this->state->idle_timeout_ms ) { + return; + } + foreach ( $this->handle_map as $request_id ) { + $request = $this->state->get_request_by_id( $request_id ); + if ( ! $request || Request::STATE_FAILED === $request->state || Request::STATE_FINISHED === $request->state ) { + continue; + } + $idle_time_ms = $this->state->connections[ $request_id ]->idle_time_ms(); + if ( $idle_time_ms > $this->state->idle_timeout_ms ) { + $this->set_error( $request, new HttpError( sprintf( 'Request timed out after %d ms without network activity.', (int) $idle_time_ms ) ) ); + } + } + } + private function poll_active_curl_requests() { $running = 0; do { @@ -166,6 +186,7 @@ function ( $ch, $fp, $length ) use ( $request ) { while ( ! $stream->reached_end_of_data() ) { $got_bytes = $stream->pull( $length ); if ( $got_bytes > 0 ) { + $this->state->connections[ $request->id ]->mark_activity(); return $stream->consume( $got_bytes ); } } @@ -220,6 +241,7 @@ private function handle_header_line( $ch, $header_line ) { throw new HttpClientException( 'Received header data for an unknown request ' . ( $ch ? (int) $ch : 'unknown' ) ); } $connection = $this->state->connections[ $request->id ]; + $connection->mark_activity(); if ( 0 === strlen( $connection->response_buffer ) ) { $request->state = Request::STATE_RECEIVING_HEADERS; } @@ -258,7 +280,8 @@ private function handle_body_data( $ch, $data ) { if ( null === $request ) { throw new HttpClientException( 'Received body data for an unknown request ' . ( $ch ? (int) $ch : 'unknown' ) ); } - $this->state->connections[ $request->id ]->response_buffer .= $data; + $this->state->connections[ $request->id ]->response_buffer .= $data; + $this->state->connections[ $request->id ]->mark_activity(); $this->state->events[ $request->id ][ Client::EVENT_BODY_CHUNK_AVAILABLE ] = true; return strlen( $data ); diff --git a/components/HttpClient/Transport/class-sockettransport.php b/components/HttpClient/Transport/class-sockettransport.php index c93b6acf2..dcf5e1828 100644 --- a/components/HttpClient/Transport/class-sockettransport.php +++ b/components/HttpClient/Transport/class-sockettransport.php @@ -56,7 +56,7 @@ public function event_loop_tick(): bool { ) ) as $request ) { $time_elapsed_ms = $this->state->connections[ $request->id ]->time_elapsed_ms(); - if ( $time_elapsed_ms > $this->state->request_timeout_ms ) { + if ( $this->state->request_timeout_ms && $time_elapsed_ms > $this->state->request_timeout_ms ) { $this->set_error( $request, new HttpError( sprintf( 'Request timed out after %d ms.', (int) $time_elapsed_ms ) ) ); } } @@ -109,9 +109,45 @@ public function event_loop_tick(): bool { $this->state->get_active_requests( Request::STATE_RECEIVING_BODY ) ); + // Checked after reading so data that arrived while the caller was busy + // counts as activity instead of tripping the timeout. + $this->fail_idle_requests(); + return true; } + private function connect_timeout_seconds() { + if ( $this->state->request_timeout_ms ) { + return $this->state->request_timeout_ms / 1000; + } + if ( $this->state->idle_timeout_ms ) { + return $this->state->idle_timeout_ms / 1000; + } + return (float) ini_get( 'default_socket_timeout' ); + } + + private function fail_idle_requests() { + if ( ! $this->state->idle_timeout_ms ) { + return; + } + foreach ( $this->state->get_active_requests( + array( + Request::STATE_WILL_ENABLE_CRYPTO, + Request::STATE_WILL_SEND_HEADERS, + Request::STATE_WILL_SEND_BODY, + Request::STATE_SENT, + Request::STATE_RECEIVING_HEADERS, + Request::STATE_RECEIVING_BODY, + Request::STATE_RECEIVED, + ) + ) as $request ) { + $idle_time_ms = $this->state->connections[ $request->id ]->idle_time_ms(); + if ( $idle_time_ms > $this->state->idle_timeout_ms ) { + $this->set_error( $request, new HttpError( sprintf( 'Request timed out after %d ms without network activity.', (int) $idle_time_ms ) ) ); + } + } + } + /** * Opens HTTP or HTTPS streams using stream_socket_client() without blocking, * and returns nearly immediately. @@ -158,7 +194,7 @@ protected function open_nonblocking_http_sockets( $requests ) { 'tcp://' . $host . ':' . $port, $errno, $errstr, - $this->state->request_timeout_ms / 1000, + $this->connect_timeout_seconds(), STREAM_CLIENT_CONNECT | STREAM_CLIENT_ASYNC_CONNECT, $context ); @@ -295,6 +331,7 @@ protected function send_request_headers( array $requests ) { ); continue; } + $this->state->connections[ $request->id ]->mark_activity(); if ( $request->upload_body_stream ) { $request->state = Request::STATE_WILL_SEND_BODY; @@ -341,6 +378,7 @@ protected function send_request_body( array $requests ) { $this->set_error( $request, new HttpError( 'Failed to write request bytes: ' . $last_error_message ) ); continue; } + $this->state->connections[ $request->id ]->mark_activity(); } } @@ -387,6 +425,7 @@ protected function receive_response_headers( $requests ) { break; } $connection->response_buffer .= $header_byte; + $connection->mark_activity(); $buffer_size = strlen( $connection->response_buffer ); if ( @@ -444,7 +483,8 @@ protected function receive_response_body( $requests ) { if ( $available_bytes > 0 ) { $body_chunk = $stream->consume( $available_bytes ); $request->response->received_bytes += $available_bytes; - $this->state->connections[ $request->id ]->response_buffer .= $body_chunk; + $this->state->connections[ $request->id ]->response_buffer .= $body_chunk; + $this->state->connections[ $request->id ]->mark_activity(); $this->state->events[ $request->id ][ Client::EVENT_BODY_CHUNK_AVAILABLE ] = true; break; // Process one chunk per loop iteration. } elseif ( $stream->reached_end_of_data() ) { diff --git a/components/HttpClient/class-clientstate.php b/components/HttpClient/class-clientstate.php index 12d28ed22..484ff67c4 100644 --- a/components/HttpClient/class-clientstate.php +++ b/components/HttpClient/class-clientstate.php @@ -56,11 +56,25 @@ class ClientState { public $event = null; public $request = null; public $response_body_chunk = null; - public $request_timeout_ms = null; + /** + * Maximum total time a request may take, in milliseconds. 0 disables it. + * + * @var int + */ + public $request_timeout_ms = null; + /** + * Maximum time a request may go without sending or receiving any bytes, + * in milliseconds. Unlike $request_timeout_ms, it lets slow transfers finish + * as long as data keeps flowing. 0 (the default) disables it. + * + * @var int + */ + public $idle_timeout_ms = null; public function __construct( $options = array() ) { $this->concurrency = $options['concurrency'] ?? 10; $this->request_timeout_ms = $options['timeout_ms'] ?? 30000; + $this->idle_timeout_ms = $options['idle_timeout_ms'] ?? 0; } public function has_pending_event( $request, $event_type ) { diff --git a/components/HttpClient/class-connection.php b/components/HttpClient/class-connection.php index 630c0c13e..4dc61692f 100644 --- a/components/HttpClient/class-connection.php +++ b/components/HttpClient/class-connection.php @@ -9,6 +9,7 @@ class Connection { public $response_buffer = ''; public $decoded_response_stream = null; public $started_at = null; + public $last_activity_at = null; public function __construct( Request $request ) { $this->request = $request; @@ -24,6 +25,22 @@ public function consume_buffer( $length = null ) { return $buffer; } + public function mark_activity() { + $this->last_activity_at = microtime( true ); + } + + /** + * Milliseconds since the connection last sent or received bytes, + * or since it was opened if no bytes have moved yet. + */ + public function idle_time_ms() { + $since = null !== $this->last_activity_at ? $this->last_activity_at : $this->started_at; + if ( null === $since ) { + return 0; + } + return ( microtime( true ) - $since ) * 1000; + } + public function time_elapsed_ms() { if ( null === $this->started_at ) { return 0;