Http request failes due to WinHTTP error code 87

[dabastynator]

Describe the bug

Sending a signed http request with content body (AddContentBody) fails.
The trace-log shows following suspicious error:
Send request failed: Windows/WinHTTP error code is 87:
I am able to send the request without setting the content body.
Therefore my assumption is that the content body stream might cause the issue, but i don't know how.

Expected Behavior

Sending an http request with content body should not fail.

Current Behavior

Sending an http request with content body fails with error Windows/WinHTTP error code is 87

Reproduction Steps

This is the way i set up sending the http request:

// Create the request
auto request = Aws::Http::CreateHttpRequest("https://some_id.execute-api.us-west-2.amazonaws.com/my_api",
    Aws::Http::HttpMethod::HTTP_PUT, []() {return new Aws::StringStream(); });

// Assign body by stream from content-string
std::shared_ptr<Aws::StringStream> contentStream = std::make_shared<Aws::StringStream>();
contentStream->write(content.c_str(), content.length());
request->AddContentBody(contentStream);

// Set some header
for (auto it : callback.header())
    request->SetHeaderValue(it.first, it.second);

// Sign the request
auto provider = std::make_shared<Aws::Auth::DefaultAWSCredentialsProviderChain>();
Aws::Client::AWSAuthV4Signer signer(provider, "execute-api", callback.region());
signer.SignRequest(*request.get());

// Create http client
Aws::Client::ClientConfiguration clientConfiguration;
std::shared_ptr<Aws::Http::HttpClient> client = Aws::Http::CreateHttpClient(clientConfiguration);

// Send the request
std::shared_ptr<Aws::Http::HttpResponse> response = client->MakeRequest(request);

if (response->HasClientError())
{
    // Always has following client error when setting content body:
    // "Encountered network error when sending http request"
}

Possible Solution

No response

Additional Information/Context

This is the trace-log:

[TRACE] 2024-05-14 11:16:46.986 FileSystem[724] Checking USERPROFILE for the home directory.
[DEBUG] 2024-05-14 11:16:46.995 FileSystem[724] Environment value for variable USERPROFILE is C:\Users\<user>
[INFO] 2024-05-14 11:16:46.995 Aws::Config::AWSConfigFileProfileConfigLoader[724] Initializing config loader against fileName C:\Users\<user>\.aws\credentials and using profilePrefix = 0
[TRACE] 2024-05-14 11:16:46.996 FileSystem[724] Checking USERPROFILE for the home directory.
[DEBUG] 2024-05-14 11:16:46.996 FileSystem[724] Environment value for variable USERPROFILE is C:\Users\<user>
[TRACE] 2024-05-14 11:16:46.997 FileSystem[724] Checking USERPROFILE for the home directory.
[DEBUG] 2024-05-14 11:16:46.998 FileSystem[724] Environment value for variable USERPROFILE is C:\Users\<user>
[INFO] 2024-05-14 11:16:46.998 ProfileConfigFileAWSCredentialsProvider[724] Setting provider to read credentials from C:\Users\<user>\.aws\credentials for credentials file and C:\Users\<user>\.aws\config for the config file , for use with profile default
[INFO] 2024-05-14 11:16:46.999 ProcessCredentialsProvider[724] Setting process credentials provider to read config from default
[WARN] 2024-05-14 11:16:47.000 STSAssumeRoleWithWebIdentityCredentialsProvider[724] Token file must be specified to use STS AssumeRole web identity creds provider.
[INFO] 2024-05-14 11:16:47.000 SSOBearerTokenProvider[724] Setting sso bearerToken provider to read config from default
[INFO] 2024-05-14 11:16:47.001 SSOCredentialsProvider[724] Setting sso credentials provider to read config from default
[DEBUG] 2024-05-14 11:16:47.001 DefaultAWSCredentialsProviderChain[724] The environment variable value AWS_CONTAINER_CREDENTIALS_RELATIVE_URI is 
[DEBUG] 2024-05-14 11:16:47.002 DefaultAWSCredentialsProviderChain[724] The environment variable value AWS_CONTAINER_CREDENTIALS_FULL_URI is 
[DEBUG] 2024-05-14 11:16:47.002 DefaultAWSCredentialsProviderChain[724] The environment variable value AWS_EC2_METADATA_DISABLED is 
[INFO] 2024-05-14 11:16:47.003 InstanceProfileCredentialsProvider[724] Creating Instance with default EC2MetadataClient and refresh rate 300000
[INFO] 2024-05-14 11:16:47.003 DefaultAWSCredentialsProviderChain[724] Added EC2 metadata service credentials provider to the provider chain.
[INFO] 2024-05-14 11:16:47.493 Aws::Config::ConfigFileProfileFSM[724] Unknown property: aws_access_key_id in the profile: default
[INFO] 2024-05-14 11:16:47.498 Aws::Config::ConfigFileProfileFSM[724] Unknown property: aws_secret_access_key in the profile: default
[INFO] 2024-05-14 11:16:47.499 Aws::Config::ConfigFileProfileFSM[724] Unknown property: aws_session_token in the profile: default
[DEBUG] 2024-05-14 11:16:47.499 Aws::Config::ConfigFileProfileFSM[724] found access key ASIATCKATLNCBZJJ67EX
[INFO] 2024-05-14 11:16:47.500 Aws::Config::AWSProfileConfigLoaderBase[724] Successfully reloaded configuration.
[TRACE] 2024-05-14 11:16:47.501 Aws::Config::AWSProfileConfigLoaderBase[724] reloaded config at 2024-05-14T11:16:47Z
[DEBUG] 2024-05-14 11:16:48.977 AWSAuthV4Signer[724] Calculated sha256 b9db6af57e863b6ee6dbf9fcc6d94bde1de88e04e84e6730c136710fa716ec9d for payload.
[DEBUG] 2024-05-14 11:16:49.015 AWSAuthV4Signer[724] Canonical Header String: content-type:application/json
host:some_id.execute-api.us-west-2.amazonaws.com
x-ads-das-engine:SomeData
x-ads-gateway-secret:<a-secret>
x-ads-token-data:{"access_token":{"client_id":"<client-id>"},"scope":"bucket:create bucket:read data:create data:write data:read","expires_in":3570,"client_id":"<client-id>"}
x-amz-content-sha256:b9db6af57e863b6ee6dbf9fcc6d94bde1de88e04e84e6730c136710fa716ec9d
x-amz-date:20240514T111649Z
x-amz-security-token:<a-token>
x-das-authorize:awssigv4(us-west-2)

[DEBUG] 2024-05-14 11:16:49.020 AWSAuthV4Signer[724] Signed Headers value:content-type;host;x-ads-das-engine;x-ads-gateway-secret;x-ads-token-data;x-amz-content-sha256;x-amz-date;x-amz-security-token;x-das-authorize
[DEBUG] 2024-05-14 11:16:49.026 AWSAuthV4Signer[724] Canonical Request String: PUT
/my_api
content-type:application/json
host:some_id.execute-api.us-west-2.amazonaws.com
x-ads-das-engine:SomeData
x-ads-gateway-secret:<a-secret>
x-ads-token-data:{"access_token":{"client_id":"<client-id>"},"scope":"bucket:create bucket:read data:create data:write data:read","expires_in":3570,"client_id":"<client-id>"}
x-amz-content-sha256:b9db6af57e863b6ee6dbf9fcc6d94bde1de88e04e84e6730c136710fa716ec9d
x-amz-date:20240514T111649Z
x-amz-security-token:<a-token>
x-das-authorize:awssigv4(us-west-2)
content-type;host;x-ads-das-engine;x-ads-gateway-secret;x-ads-token-data;x-amz-content-sha256;x-amz-date;x-amz-security-token;x-das-authorize
b9db6af57e863b6ee6dbf9fcc6d94bde1de88e04e84e6730c136710fa716ec9d
[DEBUG] 2024-05-14 11:16:49.064 AWSAuthV4Signer[724] Final String to sign: AWS4-HMAC-SHA256
20240514T111649Z
20240514/us-west-2/execute-api/aws4_request
b6784ea19b2f3efee4d6a50448c1a983296c1dc7002da26e0d719f0cab87b303
[DEBUG] 2024-05-14 11:16:49.065 AWSAuthV4Signer[724] Final computed signing hash: <a-signature>
[DEBUG] 2024-05-14 11:16:49.066 AWSAuthV4Signer[724] Signing request with: AWS4-HMAC-SHA256 Credential=ASIATCKATLNCBZJJ67EX/20240514/us-west-2/execute-api/aws4_request, SignedHeaders=content-type;host;x-ads-das-engine;x-ads-gateway-secret;x-ads-token-data;x-amz-content-sha256;x-amz-date;x-amz-security-token;x-das-authorize, Signature=<a-signature>
[TRACE] 2024-05-14 11:16:50.294 event-loop[33000] id=0000018DC5102720: running scheduled tasks.
[DEBUG] 2024-05-14 11:16:50.296 ClientConfiguration[724] Request Compression enabled
[TRACE] 2024-05-14 11:16:50.296 event-loop[26240] id=0000018DC5101C70: running scheduled tasks.
[TRACE] 2024-05-14 11:16:50.303 event-loop[26240] id=0000018DC5101C70: no more scheduled tasks using default timeout.
[TRACE] 2024-05-14 11:16:50.304 event-loop[26240] id=0000018DC5101C70: waiting for a maximum of 100000 ms
[DEBUG] 2024-05-14 11:16:50.303 ClientConfiguration[724] ClientConfiguration will use MinReqCompression: 10240
[TRACE] 2024-05-14 11:16:50.296 event-loop[24224] id=0000018DC5101880: running scheduled tasks.
[TRACE] 2024-05-14 11:16:50.307 event-loop[24224] id=0000018DC5101880: no more scheduled tasks using default timeout.
[DEBUG] 2024-05-14 11:16:50.306 ClientConfiguration[724] ClientConfiguration will use SDK Auto Resolved profile:[default] if not specified by users.
[TRACE] 2024-05-14 11:16:50.302 event-loop[33000] id=0000018DC5102720: no more scheduled tasks using default timeout.
[TRACE] 2024-05-14 11:16:50.309 event-loop[33000] id=0000018DC5102720: waiting for a maximum of 100000 ms
[INFO] 2024-05-14 11:16:50.308 ClientConfiguration[724] Retry Strategy will use the default max attempts.
[TRACE] 2024-05-14 11:16:50.308 event-loop[24224] id=0000018DC5101880: waiting for a maximum of 100000 ms
[TRACE] 2024-05-14 11:16:51.485 event-loop[15916] id=0000018DC51019A0: running scheduled tasks.
[INFO] 2024-05-14 11:16:51.489 WinHttpSyncHttpClient[724] Creating http client with user agent with max connections 25 request timeout 3000,and connect timeout 1000
[TRACE] 2024-05-14 11:16:51.489 event-loop[13052] id=0000018DC5102840: running scheduled tasks.
[TRACE] 2024-05-14 11:16:51.496 event-loop[13052] id=0000018DC5102840: no more scheduled tasks using default timeout.
[TRACE] 2024-05-14 11:16:51.495 event-loop[15916] id=0000018DC51019A0: no more scheduled tasks using default timeout.
[DEBUG] 2024-05-14 11:16:51.496 WinHttpSyncHttpClient[724] API handle 0000018DC8333CF0
[TRACE] 2024-05-14 11:16:51.489 event-loop[31792] id=0000018DC5101490: running scheduled tasks.
[TRACE] 2024-05-14 11:16:51.499 event-loop[31792] id=0000018DC5101490: no more scheduled tasks using default timeout.
[TRACE] 2024-05-14 11:16:51.500 event-loop[31792] id=0000018DC5101490: waiting for a maximum of 100000 ms
[INFO] 2024-05-14 11:16:51.498 ConnectionPoolMgr[724] Creating connection pool mgr with handle 0000018DC8333CF0, and max connections per host 25, request timeout 3000 ms, and connect timeout in 1000 ms, enabling TCP keep-alive.
[TRACE] 2024-05-14 11:16:51.497 event-loop[13052] id=0000018DC5102840: waiting for a maximum of 100000 ms
[TRACE] 2024-05-14 11:16:51.498 event-loop[15916] id=0000018DC51019A0: waiting for a maximum of 100000 ms
[TRACE] 2024-05-14 11:16:54.249 WinHttpSyncHttpClient[724] Making PUT request to uri https://some_id.execute-api.us-west-2.amazonaws.com/my_api
[INFO] 2024-05-14 11:16:54.278 WinHttpConnectionPoolMgr[724] Attempting to acquire connection for some_id.execute-api.us-west-2.amazonaws.com:443
[DEBUG] 2024-05-14 11:16:54.278 WinHttpConnectionPoolMgr[724] Pool doesn't exist for endpoint, creating...
[DEBUG] 2024-05-14 11:16:54.278 WinHttpConnectionPoolMgr[724] Pool has no available existing connections for endpoint, attempting to grow pool.
[INFO] 2024-05-14 11:16:54.279 WinConnectionContainer[724] Pool grown by 2
[INFO] 2024-05-14 11:16:54.279 WinHttpConnectionPoolMgr[724] Connection now available, continuing.
[DEBUG] 2024-05-14 11:16:54.280 WinHttpConnectionPoolMgr[724] Returning connection handle 0000018DBD54E360
[DEBUG] 2024-05-14 11:16:54.280 WinHttpSyncHttpClient[724] Acquired connection 0000018DBD54E360
[WARN] 2024-05-14 11:16:54.281 WinHttpSyncHttpClient[724] Failed setting TCP keep-alive interval with error code: 12018
[DEBUG] 2024-05-14 11:16:54.281 WinHttpSyncHttpClient[724] AllocateWindowsHttpRequest returned handle 0000018D9412F7A0
[DEBUG] 2024-05-14 11:16:54.282 WinHttpSyncHttpClient[724] with headers:
[DEBUG] 2024-05-14 11:16:54.282 WinHttpSyncHttpClient[724] authorization: AWS4-HMAC-SHA256 Credential=ASIATCKATLNCBZJJ67EX/20240514/us-west-2/execute-api/aws4_request, SignedHeaders=content-type;host;x-ads-das-engine;x-ads-gateway-secret;x-ads-token-data;x-amz-content-sha256;x-amz-date;x-amz-security-token;x-das-authorize, Signature=<a-signature>
content-type: application/json
host: some_id.execute-api.us-west-2.amazonaws.com
x-ads-das-engine: SomeData
x-ads-gateway-secret: <a-secret>
x-ads-token-data: {"access_token":{"client_id":"<client-id>"},"scope":"bucket:create bucket:read data:create data:write data:read","expires_in":3570,"client_id":"<client-id>"}
x-amz-content-sha256: b9db6af57e863b6ee6dbf9fcc6d94bde1de88e04e84e6730c136710fa716ec9d
x-amz-date: 20240514T111649Z
x-amz-security-token: <a-token>
x-das-authorize: awssigv4(us-west-2)

[WARN] 2024-05-14 11:16:54.884 WinHttpSyncHttpClient[724] Send request failed: Windows/WinHTTP error code is 87: 
[DEBUG] 2024-05-14 11:16:54.890 WinHttpSyncHttpClient[724] Closing http request handle 0000018D9412F7A0
[DEBUG] 2024-05-14 11:16:54.890 WinHttpSyncHttpClient[724] Releasing connection handle 0000018DBD54E360
[DEBUG] 2024-05-14 11:16:54.891 WinHttpConnectionPoolMgr[724] Releasing connection to endpoint some_id.execute-api.us-west-2.amazonaws.com:443
Encountered network error when sending http request
[DEBUG] 2024-05-14 11:17:01.738 WinSyncHttpClient[724] Cleaning up client with handle 0000000000000000
[INFO] 2024-05-14 11:17:01.742 WinHttpConnectionPoolMgr[724] Cleaning up connection pool mgr.
[DEBUG] 2024-05-14 11:17:01.742 WinHttpConnectionPoolMgr[724] Closing handle 0000018DBD54D4C0
[DEBUG] 2024-05-14 11:17:01.743 WinHttpConnectionPoolMgr[724] Closing handle 0000018DBD54E360

AWS CPP SDK version used

1.11.305

Compiler and Version used

Visual Studio Version 17.9.5

Operating System and version

Windows 10.0.19045

[dabastynator]

Turns out that the aws-sdk always calls WinHttpSendRequest with dwTotalLength of zero (second to last parameter):
WinHttpSendRequest(hHttpRequest, NULL, NULL, 0, 0, 0, NULL)
However, when passing the actual size of the content-body-stream, the request can be processed successfully, like this:
WinHttpSendRequest(hHttpRequest, NULL, NULL, 0, 0, bodySize, NULL)
Shouldn't that be a common problem?

[jmklix]

It looks like your using this in an untested way. When this was written they probably didn't expect it to be used this way. Looking into a possible fix for this

[andersco]

@jmklix would you please elaborate on how this is being used in an unexpected way and if/how it should be used differently?

[DmitriyMusatkin]

What Joseph is referring to is that signers and http client wrappers are CPP SDK internal helper classes and we dont expect them to be used directly by majority of users, so they might not be as thoroughly tested to work with all sorts of input combinations.

In this particular case, Windows doc does seem to imply that dwTotalLength is required (unless Transfer-Encoding: chunked is used). My guess for why its not a bigger issue is probably because SDK will add Content-Length manually after signing and WinHttpSendRequest will use that instead, somehow.
But agree in general, we should default it to correct value instead of 0.

[andersco]

@DmitriyMusatkin okay is there a different way to make a signed request that is recommended over this? What we are trying to do is make a request to an API Gateway endpoint that is using IAM authorization. We didn't find a built-in way to do this with the SDK.

[SergeyRyabinin]

Hi,

while I agree that SDK does not set the body size in WinHttpSendRequest,
there are some things that could explain why it is not set, such as it is a legacy code and we simply don't know yet at the current moment of execution the exact body size (such as due to chunk-encoding and/or payload hash calculation/insertion being done later).
Normally it works fine with both payload-present and payload-less requests for different AWS service clients.

I'd suggest to check what payload is actually being read/sent to the remote here: WinSyncHttpClient::StreamPayloadToRequest, for example, by adding such trace before each DoWriteData call:

std::cout << "StreamPayloadToRequest: " << Aws::String(streamBuffer, streamBuffer+bytesRead) << "\n";

Additionally, please enable enableHttpClientTrace on the client configuration. (and set logging level to Trace). This will enable the WinHTTP callback that will trace some additional information provided by the WinHTTP client.
These will provide more information why WinHTTP is rejecting the given configuration.

Another option would be try to use SDK built with libCurl on Windows.

We can also check and provide an example how to make API Gateway calls using the SDK, however, we can't give any estimation here.

Best regards,
Sergey

[github-actions]

Greetings! It looks like this issue hasn’t been active in longer than a week. We encourage you to check if this is still an issue in the latest release. Because it has been longer than a week since the last update on this, and in the absence of more information, we will be closing this issue soon. If you find that this is still a problem, please feel free to provide a comment or add an upvote to prevent automatic closure, or if the issue is already closed, please feel free to open a new one.

[dabastynator]

Hi all,
One workaround that seems to solve the issue on our side is to cache the body-size in WinHttpSyncHttpClient::OpenRequest(). And later use that body-size in WinHttpSyncHttpClient::DoSendRequest()
Thank you for the insight and your suggestions.

[github-actions]

This issue is now closed. Comments on closed issues are hard for our team to see.
If you need more assistance, please open a new issue that references this one.