Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

improve http client traces for CURL and add traces for WinHTTP client #2676

Merged
merged 12 commits into from
Mar 28, 2024
2 changes: 1 addition & 1 deletion .cspell.json
Original file line number Diff line number Diff line change
Expand Up @@ -11,7 +11,7 @@
"Bodyless", "HTTPGET", "ratelimiter", "Ratelimiter", "STDMETHODCALLTYPE", "CANTSAVE", "OLECHAR", "DISPID",
"UNKNOWNNAME", "DISPPARAMS", "XMLHTTP", "comptr", "Metadataservice", "Streamfn", "HWAVEOUT", "matdesc",
"Presigner", "xindex", "errortype", "waveout", "WAVEOUTCAPSA", "ALLOWSYNC", "WAVEHDR", "MMSYSERR",
"WAVEFORMATEX", "Unprepare", "DDISABLE_IMDSV1", "threadpool",
"WAVEFORMATEX", "Unprepare", "DDISABLE_IMDSV1", "SENDREQUEST", "threadpool",
// AWS general
"Arns", "AMZN", "amzn", "Paulo", "Ningxia", "ISOB", "isob", "AWSXML", "IMDSV",
// AWS Signature
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -316,6 +316,12 @@ namespace Aws
*/
Aws::Crt::Optional<bool> enableEndpointDiscovery;

/**
* Enable http client (WinHTTP or CURL) traces.
* Defaults to false, it's an optional feature.
*/
bool enableHttpClientTrace = false;

/**
* profileName in config file that will be used by this object to resolve more configurations.
*/
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -69,6 +69,7 @@ class AWS_CORE_API CurlHttpClient: public HttpClient
Aws::String m_proxyCaFile;
bool m_disableExpectHeader = false;
bool m_allowRedirects = false;
bool m_enableHttpClientTrace = false;
static std::atomic<bool> isInit;
std::shared_ptr<smithy::components::tracing::TelemetryProvider> m_telemetryProvider;
};
Expand Down
1 change: 1 addition & 0 deletions src/aws-cpp-sdk-core/source/client/ClientConfiguration.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -140,6 +140,7 @@ void setLegacyClientConfigurationParameters(ClientConfiguration& clientConfig)
clientConfig.disableExpectHeader = false;
clientConfig.enableClockSkewAdjustment = true;
clientConfig.enableHostPrefixInjection = true;
clientConfig.enableHttpClientTrace = false;
clientConfig.profileName = Aws::Auth::GetConfigProfileName();

Aws::String disableCompressionConfig = clientConfig.LoadConfigFromEnvOrProfile(
Expand Down
25 changes: 20 additions & 5 deletions src/aws-cpp-sdk-core/source/http/curl/CurlHttpClient.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -574,7 +574,12 @@ int CurlDebugCallback(CURL *handle, curl_infotype type, char *data, size_t size,

if(type == CURLINFO_SSL_DATA_IN || type == CURLINFO_SSL_DATA_OUT)
{
AWS_LOGSTREAM_DEBUG("CURL", "(" << CurlInfoTypeToString(type) << ") " << size << "bytes");
AWS_LOGSTREAM_DEBUG("CURL", "(" << CurlInfoTypeToString(type) << ") " << size << " bytes");
}
else if (type == CURLINFO_DATA_IN || type == CURLINFO_DATA_OUT)
{
//for curl data (in/out) traces, print only the data size, as it contains user private data.
AWS_LOGSTREAM_TRACE("CURL", "(" << CurlInfoTypeToString(type) << ") " << size << " bytes");
}
else
{
Expand All @@ -585,6 +590,12 @@ int CurlDebugCallback(CURL *handle, curl_infotype type, char *data, size_t size,
return 0;
}

#if defined(ENABLE_CURL_LOGGING)
const bool FORCE_ENABLE_CURL_LOGGING = true;
#else
const bool FORCE_ENABLE_CURL_LOGGING = false;
#endif


CurlHttpClient::CurlHttpClient(const ClientConfiguration& clientConfig) :
Base(),
Expand All @@ -598,6 +609,7 @@ CurlHttpClient::CurlHttpClient(const ClientConfiguration& clientConfig) :
m_proxyPort(clientConfig.proxyPort), m_verifySSL(clientConfig.verifySSL), m_caPath(clientConfig.caPath),
m_caFile(clientConfig.caFile), m_proxyCaPath(clientConfig.proxyCaPath), m_proxyCaFile(clientConfig.proxyCaFile),
m_disableExpectHeader(clientConfig.disableExpectHeader),
m_enableHttpClientTrace(clientConfig.enableHttpClientTrace || FORCE_ENABLE_CURL_LOGGING),
m_telemetryProvider(clientConfig.telemetryProvider)
{
if (clientConfig.followRedirects == FollowRedirectsPolicy::NEVER ||
Expand Down Expand Up @@ -744,10 +756,13 @@ std::shared_ptr<HttpResponse> CurlHttpClient::MakeRequest(const std::shared_ptr<
curl_easy_setopt(connectionHandle, CURLOPT_FOLLOWLOCATION, 0L);
}

#ifdef ENABLE_CURL_LOGGING
jmklix marked this conversation as resolved.
Show resolved Hide resolved
curl_easy_setopt(connectionHandle, CURLOPT_VERBOSE, 1);
curl_easy_setopt(connectionHandle, CURLOPT_DEBUGFUNCTION, CurlDebugCallback);
#endif
if (m_enableHttpClientTrace)
{
AWS_LOGSTREAM_TRACE(CURL_HTTP_CLIENT_TAG, "Activating CURL traces");
curl_easy_setopt(connectionHandle, CURLOPT_VERBOSE, 1);
curl_easy_setopt(connectionHandle, CURLOPT_DEBUGFUNCTION, CurlDebugCallback);
}

if (m_isUsingProxy)
{
Aws::StringStream ss;
Expand Down
213 changes: 208 additions & 5 deletions src/aws-cpp-sdk-core/source/http/windows/WinHttpSyncHttpClient.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -51,7 +51,7 @@ DWORD ConvertHttpVersionToWinHttpVersion(const Aws::Http::Version version)
return 0x0;
}
#ifdef WINHTTP_HAS_H2
else if (version == Version::HTTP_VERSION_2_0 ||
else if (version == Version::HTTP_VERSION_2_0 ||
version == Version::HTTP_VERSION_2TLS)
{
return WINHTTP_PROTOCOL_FLAG_HTTP2;
Expand All @@ -63,7 +63,7 @@ DWORD ConvertHttpVersionToWinHttpVersion(const Aws::Http::Version version)
}
#endif
#ifdef WINHTTP_HAS_H3
else if (version == Version::HTTP_VERSION_3)
else if (version == Version::HTTP_VERSION_3)
{
return WINHTTP_PROTOCOL_FLAG_HTTP3;
}
Expand All @@ -75,12 +75,12 @@ DWORD ConvertHttpVersionToWinHttpVersion(const Aws::Http::Version version)
#endif

#ifdef WINHTTP_HAS_H2
AWS_LOGSTREAM_WARN("WinHttpHttp2", "Unable to map requested HTTP Version: (raw enum value) "
AWS_LOGSTREAM_WARN("WinHttpHttp2", "Unable to map requested HTTP Version: (raw enum value) "
<< static_cast<std::underlying_type<Aws::Http::Version>::type>(version) << " defaulting to WINHTTP_PROTOCOL_FLAG_HTTP2");
return WINHTTP_PROTOCOL_FLAG_HTTP2;
#else
AWS_LOGSTREAM_WARN("WinHttpHttp2", "Unable to map requested HTTP Version: (raw enum value) "
<< static_cast<std::underlying_type<Aws::Http::Version>::type>(version) << " defaulting to None (aka 1.1 and below)");
<< static_cast<std::underlying_type<Aws::Http::Version>::type>(version) << " defaulting to None (aka 1.1 and below)");
return 0x0;
#endif
}
Expand All @@ -98,6 +98,201 @@ static void WinHttpSetHttpVersion(void* handle, const Aws::Http::Version version
}
}

static void GetDataErrorBuffer(char* moreDataBuffer,
size_t moreDataBufferSize,
DWORD_PTR dwResult,
DWORD dwError)
{
int ignoreError = 0;
char resultBuffer[128] = "";
char errorBuffer[128] = "";
char descriptionBuffer[256] = "";

#if _WIN64
_snprintf_s(resultBuffer, _TRUNCATE, "dwResult is %lld.", dwResult);
#elif _WIN32
_snprintf_s(resultBuffer, _TRUNCATE, "dwResult is %ld.", dwResult);
#endif

switch (dwResult)
{
case API_RECEIVE_RESPONSE:
_snprintf_s(descriptionBuffer, _TRUNCATE, "The error occurred during a call to WinHttpReceiveResponse.");
break;

case API_QUERY_DATA_AVAILABLE:
_snprintf_s(descriptionBuffer, _TRUNCATE, "The error occurred during a call to WinHttpQueryDataAvailable.");
break;

case API_READ_DATA:
_snprintf_s(descriptionBuffer, _TRUNCATE, "The error occurred during a call to WinHttpReadData.");
break;

case API_WRITE_DATA:
_snprintf_s(descriptionBuffer, _TRUNCATE, "The error occurred during a call to WinHttpWriteData");
break;

case API_SEND_REQUEST:
_snprintf_s(descriptionBuffer, _TRUNCATE, "The error occurred during a call to WinHttpSendRequest.");
break;

case API_GET_PROXY_FOR_URL:
_snprintf_s(descriptionBuffer, _TRUNCATE, "The error occurred during a call to ... API_GET_PROXY_FOR_URL.");
ignoreError = 1;
break;
default:
ignoreError = 1;
break;
}
if (!ignoreError)
_snprintf_s(errorBuffer, _TRUNCATE, "error code is %d", dwError);
else
_snprintf_s(errorBuffer, _TRUNCATE, "error code (shall be ignored?) is %d", dwError);
_snprintf_s(moreDataBuffer, moreDataBufferSize, _TRUNCATE, "%s%s%s", resultBuffer, descriptionBuffer, errorBuffer);
}

static void GetDataErrorForTlsError(DWORD dwFlags,
char* moreDataBuffer,
size_t moreDataBufferSize)
{
char flagsBuffer[128] = "";
char detailedBuffer[512] = "";
_snprintf_s(flagsBuffer, _TRUNCATE, "TLS error occurred. dwFlags is %d.", dwFlags);
if (dwFlags & WINHTTP_CALLBACK_STATUS_FLAG_CERT_REV_FAILED)
_snprintf_s(detailedBuffer, _TRUNCATE, "Certification revocation checking has been enabled, but the revocation check failed to verify whether a certificate has been revoked. The server used to check for revocation might be unreachable.");
if (dwFlags & WINHTTP_CALLBACK_STATUS_FLAG_INVALID_CERT)
_snprintf_s(detailedBuffer, _TRUNCATE, "SSL certificate is invalid.");
if (dwFlags & WINHTTP_CALLBACK_STATUS_FLAG_CERT_REVOKED)
_snprintf_s(detailedBuffer, _TRUNCATE, "SSL certificate was revoked.");
if (dwFlags & WINHTTP_CALLBACK_STATUS_FLAG_INVALID_CA)
_snprintf_s(detailedBuffer, _TRUNCATE, "The function is unfamiliar with the Certificate Authority that generated the server's certificate.");
if (dwFlags & WINHTTP_CALLBACK_STATUS_FLAG_CERT_CN_INVALID)
_snprintf_s(detailedBuffer, _TRUNCATE, "SSL certificate common name (host name field) is incorrect, for example, if you entered www.microsoft.com and the common name on the certificate says www.msn.com.");
if (dwFlags & WINHTTP_CALLBACK_STATUS_FLAG_CERT_DATE_INVALID)
_snprintf_s(detailedBuffer, _TRUNCATE, "SSL certificate date that was received from the server is bad. The certificate is expired.");
if (dwFlags & WINHTTP_CALLBACK_STATUS_FLAG_CERT_WRONG_USAGE)
_snprintf_s(detailedBuffer, _TRUNCATE, "WINHTTP_CALLBACK_STATUS_FLAG_CERT_WRONG_USAGE");
if (dwFlags & WINHTTP_CALLBACK_STATUS_FLAG_SECURITY_CHANNEL_ERROR)
_snprintf_s(detailedBuffer, _TRUNCATE, "The application experienced an internal error loading the SSL libraries.");
_snprintf_s(moreDataBuffer, moreDataBufferSize, _TRUNCATE, "%s%s", flagsBuffer, detailedBuffer);
}


static void CALLBACK WinHttpSyncLogCallback(HINTERNET hInternet,
DWORD_PTR context,
DWORD dwInternetStatus,
LPVOID statusInformation,
DWORD dwStatusInformationLength)
{
AWS_UNREFERENCED_PARAM(context);
AWS_UNREFERENCED_PARAM(hInternet);

typedef enum
{
MORE_DATA_NULL,
MORE_DATA_STRING,
MORE_DATA_DWORD,
MORE_DATA_HINTERNET,
MORE_DATA_BUFFER,//shall use dwStatusInformationLength
MORE_DATA_ERROR,
MORE_DATA_ERROR_TLS,
}DATA_FLAGS;
struct STATUS_DATA
{
DWORD status;
const char* statusString;
DATA_FLAGS moreDataFlag;
const char* moreDataFormat;
} KNOWN_STATUSES[] = {
{ WINHTTP_CALLBACK_STATUS_CLOSING_CONNECTION, "Closing the connection to the server.", MORE_DATA_NULL, "" },
{ WINHTTP_CALLBACK_STATUS_CONNECTED_TO_SERVER, "Successfully connected to the server.", MORE_DATA_STRING, "IP address is %S" },
{ WINHTTP_CALLBACK_STATUS_CONNECTING_TO_SERVER, "Connecting to the server.", MORE_DATA_STRING, "IP address is %S" },
{ WINHTTP_CALLBACK_STATUS_CONNECTION_CLOSED, "Successfully closed the connection to the server", MORE_DATA_NULL, "" },
{ WINHTTP_CALLBACK_STATUS_DATA_AVAILABLE, "Data is available to be retrieved with WinHttpReadData.", MORE_DATA_DWORD, "Data size is %d" },
{ WINHTTP_CALLBACK_STATUS_HANDLE_CREATED, "An HINTERNET handle has been created.", MORE_DATA_HINTERNET, "" },
{ WINHTTP_CALLBACK_STATUS_HANDLE_CLOSING, "An HINTERNET handle has been terminated.", MORE_DATA_HINTERNET, "" },
{ WINHTTP_CALLBACK_STATUS_HEADERS_AVAILABLE, "The response header has been received and is available with WinHttpQueryHeaders.", MORE_DATA_NULL, "" },
{ WINHTTP_CALLBACK_STATUS_INTERMEDIATE_RESPONSE, "Received an intermediate (100 level) status code message from the server.", MORE_DATA_DWORD, "http status is %d" },
{ WINHTTP_CALLBACK_STATUS_NAME_RESOLVED, "Successfully found the IP address of the server.", MORE_DATA_STRING, "Name resolved is %S" },
{ WINHTTP_CALLBACK_STATUS_READ_COMPLETE, "Data was successfully read from the server.", MORE_DATA_BUFFER, "Buffer size read is %d" },
{ WINHTTP_CALLBACK_STATUS_RECEIVING_RESPONSE, "Waiting for the server to respond to a request.", MORE_DATA_NULL, "" },
{ WINHTTP_CALLBACK_STATUS_REDIRECT, "An HTTP request is about to automatically redirect the request.", MORE_DATA_STRING, "Redirect target is %S" },
{ WINHTTP_CALLBACK_STATUS_REQUEST_ERROR, "An error occurred while sending an HTTP request.", MORE_DATA_ERROR, "An error occurred ... to be formatted ..." },
{ WINHTTP_CALLBACK_STATUS_REQUEST_SENT, "Successfully sent the information request to the server.", MORE_DATA_DWORD, "Sent %d bytes" },
{ WINHTTP_CALLBACK_STATUS_RESOLVING_NAME, "Looking up the IP address of a server name.", MORE_DATA_STRING, "Trying to resolve '%S'" },
{ WINHTTP_CALLBACK_STATUS_RESPONSE_RECEIVED, "Successfully received a response from the server.", MORE_DATA_DWORD, "Received %d bytes" },
{ WINHTTP_CALLBACK_STATUS_SECURE_FAILURE, "One or more errors were encountered while retrieving a Secure Sockets Layer (SSL) certificate from the server.", MORE_DATA_ERROR_TLS, "TO BE CHECKED" },
{ WINHTTP_CALLBACK_STATUS_SENDING_REQUEST, "Sending the information request to the server.", MORE_DATA_NULL, "" },
{ WINHTTP_CALLBACK_STATUS_SENDREQUEST_COMPLETE, "The request completed successfully.", MORE_DATA_NULL, "" },
{ WINHTTP_CALLBACK_STATUS_WRITE_COMPLETE, "Data was successfully written to the server.", MORE_DATA_DWORD, "Written %d bytes" },
{ WINHTTP_CALLBACK_STATUS_CLOSE_COMPLETE, "The connection was successfully closed via a call to WinHttpWebSocketClose.", MORE_DATA_NULL, "" },
{ WINHTTP_CALLBACK_STATUS_SHUTDOWN_COMPLETE, "The connection was successfully shut down via a call to WinHttpWebSocketShutdown.", MORE_DATA_NULL, "" }
};

bool found = false;
int i;
for (i = 0; i < sizeof(KNOWN_STATUSES) / sizeof(KNOWN_STATUSES[0]) && !found; i++)
{
if (dwInternetStatus == KNOWN_STATUSES[i].status)
sbiscigl marked this conversation as resolved.
Show resolved Hide resolved
{
struct STATUS_DATA* data = &(KNOWN_STATUSES[i]);
DWORD_PTR dwResult = 0;
DWORD dwError = 0;
DWORD tlsErrorFlags = 0;

static const size_t MORE_DATA_BUFFER_SZ = 1024;
char moreDataBuffer[MORE_DATA_BUFFER_SZ] = "";
switch (data->moreDataFlag)
{
case MORE_DATA_NULL:
break;
case MORE_DATA_STRING:
_snprintf_s(moreDataBuffer, _TRUNCATE, data->moreDataFormat, (wchar_t*)statusInformation);
break;
case MORE_DATA_DWORD:
_snprintf_s(moreDataBuffer, _TRUNCATE, data->moreDataFormat, *((DWORD*)statusInformation));
break;
case MORE_DATA_HINTERNET:
break;
case MORE_DATA_BUFFER:
_snprintf_s(moreDataBuffer, _TRUNCATE, data->moreDataFormat, dwStatusInformationLength);
break;
case MORE_DATA_ERROR:
dwResult = ((WINHTTP_ASYNC_RESULT*)statusInformation)->dwResult;
dwError = ((WINHTTP_ASYNC_RESULT*)statusInformation)->dwError;
GetDataErrorBuffer(moreDataBuffer,
MORE_DATA_BUFFER_SZ,
dwResult,
dwError);
break;
case MORE_DATA_ERROR_TLS:
tlsErrorFlags = *(DWORD*)statusInformation;
GetDataErrorForTlsError(tlsErrorFlags, moreDataBuffer, MORE_DATA_BUFFER_SZ);
break;
default:
_snprintf_s(moreDataBuffer,
_TRUNCATE,
"unknown more data flag %d",
data->moreDataFlag);
break;
}//switch more data
if (moreDataBuffer[0])
{
AWS_LOGSTREAM_TRACE("WinHttp", data->statusString << " " << moreDataBuffer);
}
else
{
AWS_LOGSTREAM_TRACE("WinHttp", data->statusString);
}
found = true;
}//found handler
}
if (!found)
{
AWS_LOGSTREAM_DEBUG("WinHttp", "got unrecognized internet status " << dwInternetStatus);
}
}

WinHttpSyncHttpClient::WinHttpSyncHttpClient(const ClientConfiguration& config) :
Base(),
m_usingProxy(!config.proxyHost.empty()),
Expand Down Expand Up @@ -153,7 +348,15 @@ WinHttpSyncHttpClient::WinHttpSyncHttpClient(const ClientConfiguration& config)

Aws::WString openString = StringUtils::ToWString(config.userAgent.c_str());
// WinhttpOpen will create a session handle
SetOpenHandle(WinHttpOpen(openString.c_str(), winhttpFlags, proxyString.c_str(), nullptr, 0));
HINTERNET hHttpSession = WinHttpOpen(openString.c_str(), winhttpFlags, proxyString.c_str(), nullptr, 0);

if (config.enableHttpClientTrace)
{
AWS_LOGSTREAM_DEBUG(GetLogTag(), "Enabling WinHttp traces");
WinHttpSetStatusCallback(hHttpSession, WinHttpSyncLogCallback, WINHTTP_CALLBACK_FLAG_ALL_NOTIFICATIONS, (DWORD_PTR)NULL);
}

SetOpenHandle(hHttpSession);

if (!WinHttpSetTimeouts(GetOpenHandle(), config.connectTimeoutMs, config.connectTimeoutMs, -1, config.requestTimeoutMs))
{
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -209,7 +209,7 @@ void WinSyncHttpClient::LogRequestInternalFailure() const

DWORD error = GetLastError();

char messageBuffer[WINDOWS_ERROR_MESSAGE_BUFFER_SIZE];
char messageBuffer[WINDOWS_ERROR_MESSAGE_BUFFER_SIZE] = { 0 };

FormatMessageA(
FORMAT_MESSAGE_FROM_HMODULE |
Expand All @@ -220,7 +220,7 @@ void WinSyncHttpClient::LogRequestInternalFailure() const
messageBuffer,
WINDOWS_ERROR_MESSAGE_BUFFER_SIZE,
nullptr);
AWS_LOGSTREAM_WARN(GetLogTag(), "Send request failed: " << messageBuffer);
AWS_LOGSTREAM_WARN(GetLogTag(), "Send request failed: Windows/WinHTTP error code is " << error << ": " << messageBuffer);

}

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -175,6 +175,7 @@ class TableOperationTest : public ::testing::Test {
config.httpLibOverride = transferType;
config.executor = Aws::MakeShared<Aws::Utils::Threading::PooledThreadExecutor>(ALLOCATION_TAG, 4);
config.disableExpectHeader = true;
config.enableHttpClientTrace = true;

//to test proxy functionality, uncomment the next two lines.
//config.proxyHost = "localhost";
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -178,6 +178,7 @@ namespace
config.readRateLimiter = Limiter;
config.writeRateLimiter = Limiter;
config.executor = Aws::MakeShared<Aws::Utils::Threading::PooledThreadExecutor>(ALLOCATION_TAG, 4);
config.enableHttpClientTrace = true;

//to use a proxy, uncomment the next two lines.
if (USE_PROXY_FOR_TESTS)
Expand Down
1 change: 1 addition & 0 deletions tests/aws-cpp-sdk-s3-integration-tests/S3ExpressTest.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -300,6 +300,7 @@ namespace {
void SetUp() override {
S3ClientConfiguration configuration;
configuration.region = "us-east-1";
configuration.enableHttpClientTrace = true;
client = Aws::MakeShared<S3Client>(ALLOCATION_TAG, configuration);
}

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -51,6 +51,7 @@ class TranscribeStreamingTests : public Aws::Testing::AwsCppSdkGTestSuite
}

Aws::Client::ClientConfiguration config;
config.enableHttpClientTrace = true;
#ifdef _WIN32
// TODO: remove this once we get H2 working with WinHttp client
config.httpLibOverride = Aws::Http::TransferLibType::WIN_INET_CLIENT;
Expand Down
Loading