-
Notifications
You must be signed in to change notification settings - Fork 1.1k
Description
Describe the bug
We are the maintainers of runai-model-streamer, which uses this SDK for loading models to vLLM.
Our application is using S3CrtClient for sending GET object ranged request.
In the logs below it can be seen that the backend answers with a valid 206 response with the expected headers such as Content-Range.
In the logs it can be seen that the meta request was sent.
However, if the server does not keep the connection intact, the meta request fails consistently since the Content-Range header is not found.
It seems that although the correct response was received, the response is released before being processed if the server requested to close the connection.
See the following trace logs:
[TRACE] 2025-07-22 08:19:14.858 channel [139683560412736] id=0x7f0a38002d50: sending read message of size 464, from slot 0x7f0a38014160 to slot 0x7f0a38002990 with handler 0x7f0a38017418.
[TRACE] 2025-07-22 08:19:14.858 http-connection [139683560412736] id=0x7f0a38017410: Incoming message of size 464.
[TRACE] 2025-07-22 08:19:14.858 http-stream [139683560412736] id=0x7f0a38017b90: Incoming response status: 206 (Partial Content).
[TRACE] 2025-07-22 08:19:14.858 http-stream [139683560412736] id=0x7f0a38017b90: Incoming header: accept-ranges: bytes
[TRACE] 2025-07-22 08:19:14.858 http-stream [139683560412736] id=0x7f0a38017b90: Incoming header: content-length: 8
[TRACE] 2025-07-22 08:19:14.858 http-stream [139683560412736] id=0x7f0a38017b90: Incoming header: content-range: bytes=0-7/3957900840
[TRACE] 2025-07-22 08:19:14.858 http-stream [139683560412736] id=0x7f0a38017b90: Incoming header: content-type: binary/octet-stream
[TRACE] 2025-07-22 08:19:14.858 http-stream [139683560412736] id=0x7f0a38017b90: Incoming header: etag: "2d25d604909136e2bb32a78b43e9f529-472"
[TRACE] 2025-07-22 08:19:14.858 http-stream [139683560412736] id=0x7f0a38017b90: Incoming header: last-modified: Mon, 21 Jul 2025 07:02:53 GMT
[TRACE] 2025-07-22 08:19:14.858 http-stream [139683560412736] id=0x7f0a38017b90: Incoming header: x-amz-id-2: ZDRhNTAyNTE2MjAzMTRkODMzZjA1OGQ2NWM4YjBhOWVkYzkzMTgwYjUwNDAwMzM1MGJlNWZkOGJjYzI2MzVmZg==
[TRACE] 2025-07-22 08:19:14.858 http-stream [139683560412736] id=0x7f0a38017b90: Incoming header: x-amz-request-id: 9884a66a-80ca-4c59-81f7-e44bfd8a6c70
[TRACE] 2025-07-22 08:19:14.858 http-stream [139683560412736] id=0x7f0a38017b90: Incoming header: date: Tue, 22 Jul 2025 08:19:20 GMT
[TRACE] 2025-07-22 08:19:14.858 http-stream [139683560412736] id=0x7f0a38017b90: Incoming header: server: Ncloud Storage
[TRACE] 2025-07-22 08:19:14.858 http-stream [139683560412736] id=0x7f0a38017b90: Main header block done.
[TRACE] 2025-07-22 08:19:14.858 http-stream [139683560412736] id=0x7f0a38017b90: Incoming body: 8 bytes received.
[TRACE] 2025-07-22 08:19:14.858 S3MetaRequest [139683560412736] id=0x7f0a90357ca0 Incoming body for request 0x7f09d80022a0. Response status: 206. Data Size: 8. connection: 0x7f0a900afdc0.
[DEBUG] 2025-07-22 08:19:14.858 http-stream [139683560412736] id=0x7f0a38017b90: Client request complete, response status: 206 (Partial Content).
[DEBUG] 2025-07-22 08:19:14.858 S3MetaRequest [139683560412736] id=0x7f0a90357ca0: Request 0x7f09d80022a0 finished with error code 0 (aws-c-common: AWS_ERROR_SUCCESS, Success.) and response status 206, x-amz-request-id: 9884a66a-80ca-4c59-81f7-e44bfd8a6c70, x-amz-id-2: ZDRhNTAyNTE2MjAzMTRkODMzZjA1OGQ2NWM4YjBhOWVkYzkzMTgwYjUwNDAwMzM1MGJlNWZkOGJjYzI2MzVmZg==
[TRACE] 2025-07-22 08:19:14.858 http-stream [139683560412736] id=0x7f0a38017b90: Stream refcount released, 1 remaining.
[DEBUG] 2025-07-22 08:19:14.858 standard-retry-strategy [139683560412736] token_id=0x7f09d8003150: partition=kr-naver-dev-internal.ncloudstorage.com: recording successful operation and adding 1 units of capacity back to the bucket.
[TRACE] 2025-07-22 08:19:14.858 standard-retry-strategy [139683560412736] bucket_id=0x7f09d8003150: partition=kr-naver-dev-internal.ncloudstorage.com : new capacity is 500.
[TRACE] 2025-07-22 08:19:14.858 standard-retry-strategy [139683560412736] id=0x7f09d8003150: releasing token
[TRACE] 2025-07-22 08:19:14.858 event-loop [139683560412736] id=0x7f0a900afce0: Scheduling s3_client_process_work_task task 0x7f0a90395458 cross-thread for timestamp 0
[TRACE] 2025-07-22 08:19:14.858 event-loop [139683560412736] id=0x7f0a900afce0: Waking up event-loop thread
[ERROR] 2025-07-22 08:19:14.858 S3MetaRequest [139683560412736] id=0x7f0a90357ca0 Could not find content-range header for request 0x7f09d80022a0
[TRACE] 2025-07-22 08:19:14.858 event-loop [139683560412736] id=0x7f0a903a4a00: Scheduling s3_meta_request_event_delivery task 0x7f0a90357e18 cross-thread for timestamp 0
[TRACE] 2025-07-22 08:19:14.858 event-loop [139683560412736] id=0x7f0a903a4a00: Waking up event-loop thread
[DEBUG] 2025-07-22 08:19:14.858 S3MetaRequest [139683560412736] id=0x7f0a90357ca0: 1 out of 0 parts have completed.
[TRACE] 2025-07-22 08:19:14.858 event-loop [139680876041792] id=0x7f0a900afce0: wake up with 1 events to process.
[DEBUG] 2025-07-22 08:19:14.858 connection-manager [139683560412736] id=0x7f0a903be550: User releasing connection (id=0x7f0a38017410)
[TRACE] 2025-07-22 08:19:14.858 event-loop [139680876041792] id=0x7f0a900afce0: activity on fd 155, invoking handler.
[TRACE] 2025-07-22 08:19:14.858 event-loop [139680876041792] id=0x7f0a900afce0: notified of cross-thread tasks to schedule
[TRACE] 2025-07-22 08:19:14.858 event-loop [139680876041792] id=0x7f0a900afce0: processing cross-thread tasks
[DEBUG] 2025-07-22 08:19:14.858 connection-manager [139683560412736] id=0x7f0a903be550: snapshot - state=1, idle_connection_count=1, pending_acquire_count=0, pending_settings_count=0, pending_connect_count=0, vended_connection_count=0, open_connection_count=1, ref_count=1
[TRACE] 2025-07-22 08:19:14.858 http-stream [139683560412736] id=0x7f0a38017b90: Final stream refcount released.
[TRACE] 2025-07-22 08:19:14.858 event-loop [139680876041792] id=0x7f0a900afce0: task s3_client_process_work_task 0x7f0a90395458 pulled to event-loop, scheduling now.
[TRACE] 2025-07-22 08:19:14.858 http-connection [139683560412736] id=0x7f0a38017410: Connection refcount released, 1 remaining.
[TRACE] 2025-07-22 08:19:14.858 task-scheduler [139680876041792] id=0x7f0a90395458: Scheduling s3_client_process_work_task task for immediate execution
[TRACE] 2025-07-22 08:19:14.858 http-connection [139683560412736] id=0x7f0a38017410: Current incoming stream is now (nil).
[TRACE] 2025-07-22 08:19:14.858 event-loop [139680876041792] id=0x7f0a900afce0: running scheduled tasks.
[TRACE] 2025-07-22 08:19:14.858 http-connection [139683560412736] id=0x7f0a38017410: Decoded 464 bytes of message, 0 bytes remain.
[TRACE] 2025-07-22 08:19:14.858 task-scheduler [139680876041792] id=0x7f0a90395458: Running s3_client_process_work_task task with status
[TRACE] 2025-07-22 08:19:14.858 event-loop [139676128097856] id=0x7f0a903a4a00: wake up with 1 events to process.
[TRACE] 2025-07-22 08:19:14.858 channel [139683560412736] id=0x7f0a38002d50: acquired message 0x7f0a3800b810 of capacity 16384 from pool 0x7f0a38003520. Requested size was 18446744073709551151
[TRACE] 2025-07-22 08:19:14.858 event-loop [139676128097856] id=0x7f0a903a4a00: activity on fd 278, invoking handler.
[DEBUG] 2025-07-22 08:19:14.858 S3Client [139680876041792] id=0x7f0a90395240 s_s3_client_process_work_default - Moving relevant synced_data into threaded_data.
[TRACE] 2025-07-22 08:19:14.858 event-loop [139676128097856] id=0x7f0a903a4a00: notified of cross-thread tasks to schedule
[TRACE] 2025-07-22 08:19:14.858 tls-handler [139683560412736] id=0x7f0a38014230: Bytes read -1
[DEBUG] 2025-07-22 08:19:14.858 S3Client [139680876041792] id=0x7f0a90395240 s_s3_client_process_work_default - Processing any new meta requests.
[TRACE] 2025-07-22 08:19:14.858 event-loop [139676128097856] id=0x7f0a903a4a00: processing cross-thread tasks
[TRACE] 2025-07-22 08:19:14.858 tls-handler [139683560412736] id=0x7f0a38014230: Remaining window for this event-loop tick: 18446744073709551151
[DEBUG] 2025-07-22 08:19:14.858 S3Client [139680876041792] id=0x7f0a90395240 Updating meta requests.
[TRACE] 2025-07-22 08:19:14.858 channel [139683560412736] id=0x7f0a38002d50: acquired message 0x7f0a3800b810 of capacity 15898 from pool 0x7f0a38003520. Requested size was 15898
[TRACE] 2025-07-22 08:19:14.858 event-loop [139676128097856] id=0x7f0a903a4a00: task s3_meta_request_event_delivery 0x7f0a90357e18 pulled to event-loop, scheduling now.
[TRACE] 2025-07-22 08:19:14.858 task-scheduler [139676128097856] id=0x7f0a90357e18: Scheduling s3_meta_request_event_delivery task for immediate execution
[DEBUG] 2025-07-22 08:19:14.858 S3Client [139680876041792] id=0x7f0a90395240 Updating connections, assigning requests where possible.
[TRACE] 2025-07-22 08:19:14.858 event-loop [139676128097856] id=0x7f0a903a4a00: running scheduled tasks.
[TRACE] 2025-07-22 08:19:14.858 socket [139683560412736] id=0x7f0a38001bf0 fd=313: read of -1
[TRACE] 2025-07-22 08:19:14.858 task-scheduler [139676128097856] id=0x7f0a90357e18: Running s3_meta_request_event_delivery task with status
[TRACE] 2025-07-22 08:19:14.858 socket [139683560412736] id=0x7f0a38001bf0 fd=313: read would block
[TRACE] 2025-07-22 08:19:14.858 socket-handler [139683560412736] id=0x7f08740023f0: total read on this tick 486
[INFO] 2025-07-22 08:19:14.858 S3ClientStats [139680876041792] id=0x7f0a90395240 Requests-in-flight(approx/exact):1/0 Requests-preparing:0 Requests-queued:0 Requests-network(get/put/default/total):0/0/0/0 Requests-streaming-waiting:0 Requests-streaming-response:1 Endpoints(in-table/allocated):1/1
[TRACE] 2025-07-22 08:19:14.858 socket-handler [139683560412736] id=0x7f08740023f0: out of data to read on socket. Waiting on event-loop notification.
[TRACE] 2025-07-22 08:19:14.858 event-loop [139680876041792] id=0x7f0a900afce0: detected more scheduled tasks with the next occurring at 4882612502, using timeout of 4882.
[TRACE] 2025-07-22 08:19:14.858 socket [139683560412736] id=0x7f0a38001bf0 fd=313: is writable
[TRACE] 2025-07-22 08:19:14.858 socket [139683560412736] id=0x7f0a38001bf0 fd=313: processing write requests, invoked by the event-loop
[TRACE] 2025-07-22 08:19:14.858 event-loop [139680876041792] id=0x7f0a900afce0: waiting for a maximum of 4882 ms
[TRACE] 2025-07-22 08:19:14.858 event-loop [139683560412736] id=0x7f0a900a74c0: running scheduled tasks.
[TRACE] 2025-07-22 08:19:14.858 event-loop [139683560412736] id=0x7f0a900a74c0: detected more scheduled tasks with the next occurring at 883402451, using timeout of 883.
[TRACE] 2025-07-22 08:19:14.858 event-loop [139683560412736] id=0x7f0a900a74c0: waiting for a maximum of 883 ms
[TRACE] 2025-07-22 08:19:14.858 event-loop [139676128097856] id=0x7f0a900afce0: Scheduling s3_client_process_work_task task 0x7f0a90395458 cross-thread for timestamp 0
[TRACE] 2025-07-22 08:19:14.858 event-loop [139676128097856] id=0x7f0a900afce0: Waking up event-loop thread
[TRACE] 2025-07-22 08:19:14.858 event-loop [139676128097856] id=0x7f0a903a4a00: no more scheduled tasks using default timeout.
[TRACE] 2025-07-22 08:19:14.858 event-loop [139676128097856] id=0x7f0a903a4a00: waiting for a maximum of 100000 ms
[TRACE] 2025-07-22 08:19:14.858 event-loop [139680876041792] id=0x7f0a900afce0: wake up with 1 events to process.
[TRACE] 2025-07-22 08:19:14.858 event-loop [139680876041792] id=0x7f0a900afce0: activity on fd 155, invoking handler.
[TRACE] 2025-07-22 08:19:14.858 event-loop [139680876041792] id=0x7f0a900afce0: notified of cross-thread tasks to schedule
[TRACE] 2025-07-22 08:19:14.858 event-loop [139680876041792] id=0x7f0a900afce0: processing cross-thread tasks
[TRACE] 2025-07-22 08:19:14.858 event-loop [139680876041792] id=0x7f0a900afce0: task s3_client_process_work_task 0x7f0a90395458 pulled to event-loop, scheduling now.
[TRACE] 2025-07-22 08:19:14.858 task-scheduler [139680876041792] id=0x7f0a90395458: Scheduling s3_client_process_work_task task for immediate execution
[TRACE] 2025-07-22 08:19:14.858 event-loop [139680876041792] id=0x7f0a900afce0: running scheduled tasks.
[TRACE] 2025-07-22 08:19:14.858 task-scheduler [139680876041792] id=0x7f0a90395458: Running s3_client_process_work_task task with status
[DEBUG] 2025-07-22 08:19:14.858 S3Client [139680876041792] id=0x7f0a90395240 s_s3_client_process_work_default - Moving relevant synced_data into threaded_data.
[DEBUG] 2025-07-22 08:19:14.858 S3Client [139680876041792] id=0x7f0a90395240 s_s3_client_process_work_default - Processing any new meta requests.
[DEBUG] 2025-07-22 08:19:14.858 S3Client [139680876041792] id=0x7f0a90395240 Updating meta requests.
[DEBUG] 2025-07-22 08:19:14.858 S3MetaRequest [139680876041792] id=0x7f0a90357ca0 Meta request finished with error code 14337 (Response contains invalid Content-Range header.)
[DEBUG] 2025-07-22 08:19:14.858 S3MetaRequest [139680876041792] id=0x7f0a90357ca0 Cleaning up meta request
[TRACE] 2025-07-22 08:19:14.858 S3MetaRequest [139680876041792] id=0x7f0a90357ca0 Calling virtual meta request destroy function.
[TRACE] 2025-07-22 08:19:14.858 S3MetaRequest [139680876041792] id=0x7f0a90357ca0 Calling meta request shutdown callback.
[DEBUG] 2025-07-22 08:19:14.858 S3CrtClient [139680876041792] Request returned error. Attempting to generate appropriate error codes from response
[ERROR] 2025-07-22 08:19:14.858 AWSXmlClient [139680876041792] HTTP response code: -1
Resolved remote host IP address:
Request ID:
Exception name:
Error message: Response contains invalid Content-Range header. (aws-c-s3: AWS_ERROR_S3_INVALID_CONTENT_RANGE_HEADER)
Regression Issue
- Select this option if this issue appears to be a regression.
Expected Behavior
It is expected that the response headers would not be released before the meta request is processed, even if the connection is closed.
Current Behavior
The request fails with AWS_ERROR_S3_INVALID_CONTENT_RANGE_HEADER
Reproduction Steps
The issue happens if the server does not requests to close the connection instead of keep alive
Possible Solution
No response
Additional Information/Context
No response
AWS CPP SDK version used
1.11.584
Compiler and Version used
gcc (Ubuntu 9.4.0-1ubuntu1~20.04.2) 9.4.0
Operating System and version
Ubuntu 20.4