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.

Sign up for GitHub

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

Jump to bottom

[EXPORTER] Log SSL Connection Information #3113

Open
wants to merge 9 commits into
base: main
Choose a base branch
from
+117 −6
Open

[EXPORTER] Log SSL Connection Information #3113

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
9 commits
Select commit Hold shift + click to select a range
ae15206
Enable curl verbose output and add debug function callback
chusitoo Oct 28, 2024
b2e4069
Fix PR pipeline errors
chusitoo Oct 28, 2024
6c07132
Minor touchup to remove trailing newline
chusitoo Oct 29, 2024
7cdf2d4
Merge branch 'main' into Log_SSL_connection_info
lalitb Oct 31, 2024
ab2c39b
Add runtime flag
chusitoo Nov 1, 2024
3be305e
Add compile-time flag
chusitoo Nov 2, 2024
78f9a0b
Adhere to code and format requirements
chusitoo Nov 2, 2024
d0b8589
Version guard for callback
chusitoo Nov 2, 2024
5dc28ab
Align with naming conventions
chusitoo Nov 2, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
3 changes: 3 additions & 0 deletions CMakeLists.txt
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -215,6 +215,9 @@ option(
"Whether to include gzip compression for the OTLP http exporter in the SDK"
OFF)

option(WITH_CURL_LOGGING "Whether to enable select CURL verbosity in OTel logs"
OFF)

option(WITH_ZIPKIN "Whether to include the Zipkin exporter in the SDK" OFF)

option(WITH_PROMETHEUS "Whether to include the Prometheus Client in the SDK"
Expand Down
1 change: 1 addition & 0 deletions exporters/otlp/src/otlp_http_client.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -989,6 +989,7 @@ OtlpHttpClient::createSession(
request->SetBody(body_vec);
request->ReplaceHeader("Content-Type", content_type);
request->ReplaceHeader("User-Agent", options_.user_agent);
request->EnableLogging(options_.console_debug);

if (options_.compression == "gzip")
{
Expand Down
3 changes: 3 additions & 0 deletions ext/include/opentelemetry/ext/http/client/curl/http_client_curl.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -102,6 +102,8 @@ class Request : public opentelemetry::ext::http::client::Request
compression_ = compression;
}

void EnableLogging(bool is_log_enabled) noexcept override { is_log_enabled_ = is_log_enabled; }

public:
opentelemetry::ext::http::client::Method method_;
opentelemetry::ext::http::client::HttpSslOptions ssl_options_;
Expand All @@ -111,6 +113,7 @@ class Request : public opentelemetry::ext::http::client::Request
std::chrono::milliseconds timeout_ms_{5000}; // ms
opentelemetry::ext::http::client::Compression compression_{
opentelemetry::ext::http::client::Compression::kNone};
bool is_log_enabled_{false};
};

class Response : public opentelemetry::ext::http::client::Response
Expand Down
11 changes: 10 additions & 1 deletion ext/include/opentelemetry/ext/http/client/curl/http_operation_curl.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -102,6 +102,12 @@ class HttpOperation

static size_t ReadMemoryCallback(char *buffer, size_t size, size_t nitems, void *userp);

static int CurlLoggerCallback(const CURL * /* handle */,
curl_infotype type,
const char *data,
size_t size,
void * /* clientp */) noexcept;

#if LIBCURL_VERSION_NUM >= 0x075000
static int PreRequestCallback(void *clientp,
char *conn_primary_ip,
Expand Down Expand Up @@ -152,7 +158,8 @@ class HttpOperation
// Default connectivity and response size options
bool is_raw_response = false,
std::chrono::milliseconds http_conn_timeout = default_http_conn_timeout,
bool reuse_connection = false);
bool reuse_connection = false,
bool is_log_enabled = false);

/**
* Destroy CURL instance
Expand Down Expand Up @@ -300,6 +307,8 @@ class HttpOperation

const opentelemetry::ext::http::client::Compression &compression_;

const bool is_log_enabled_;

// Processed response headers and body
long response_code_;
std::vector<uint8_t> response_headers_;
Expand Down
2 changes: 2 additions & 0 deletions ext/include/opentelemetry/ext/http/client/http_client.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -245,6 +245,8 @@ class Request

virtual void SetCompression(const Compression &compression) noexcept = 0;

virtual void EnableLogging(bool is_log_enabled) noexcept = 0;

virtual ~Request() = default;
};

Expand Down
5 changes: 5 additions & 0 deletions ext/src/http/client/curl/CMakeLists.txt
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -24,6 +24,11 @@ else()
PRIVATE ${CURL_LIBRARIES})
endif()

if(WITH_CURL_LOGGING)
target_compile_definitions(opentelemetry_http_client_curl
PRIVATE ENABLE_CURL_LOGGING)
endif()

if(WITH_OTLP_HTTP_COMPRESSION)
if(TARGET ZLIB::ZLIB)
target_link_libraries(
Expand Down
8 changes: 4 additions & 4 deletions ext/src/http/client/curl/http_client_curl.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -116,10 +116,10 @@ void Session::SendRequest(
#endif
}

curl_operation_.reset(new HttpOperation(http_request_->method_, url, http_request_->ssl_options_,
callback_ptr, http_request_->headers_,
http_request_->body_, http_request_->compression_, false,
http_request_->timeout_ms_, reuse_connection));
curl_operation_.reset(new HttpOperation(
http_request_->method_, url, http_request_->ssl_options_, callback_ptr,
http_request_->headers_, http_request_->body_, http_request_->compression_, false,
http_request_->timeout_ms_, reuse_connection, http_request_->is_log_enabled_));
bool success =
CURLE_OK == curl_operation_->SendAsync(this, [this, callback](HttpOperation &operation) {
if (operation.WasAborted())
Expand Down
87 changes: 86 additions & 1 deletion ext/src/http/client/curl/http_operation_curl.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,7 @@
#include "opentelemetry/ext/http/client/curl/http_client_curl.h"
#include "opentelemetry/ext/http/client/curl/http_operation_curl.h"
#include "opentelemetry/ext/http/client/http_client.h"
#include "opentelemetry/nostd/string_view.h"
#include "opentelemetry/sdk/common/global_log_handler.h"
#include "opentelemetry/version.h"

Expand Down Expand Up @@ -261,7 +262,8 @@ HttpOperation::HttpOperation(opentelemetry::ext::http::client::Method method,
// Default connectivity and response size options
bool is_raw_response,
std::chrono::milliseconds http_conn_timeout,
bool reuse_connection)
bool reuse_connection,
bool is_log_enabled)
: is_aborted_(false),
is_finished_(false),
is_cleaned_(false),
Expand All @@ -281,6 +283,7 @@ HttpOperation::HttpOperation(opentelemetry::ext::http::client::Method method,
request_nwrite_(0),
session_state_(opentelemetry::ext::http::client::SessionState::Created),
compression_(compression),
is_log_enabled_(is_log_enabled),
response_code_(0)
{
/* get a curl handle */
Expand Down Expand Up @@ -569,8 +572,73 @@ CURLcode HttpOperation::SetCurlOffOption(CURLoption option, curl_off_t value)
return rc;
}

int HttpOperation::CurlLoggerCallback(const CURL * /* handle */,
curl_infotype type,
const char *data,
size_t size,
void * /* clientp */) noexcept
{
nostd::string_view text_to_log{data, size};

if (!text_to_log.empty() && text_to_log[size - 1] == '\n')
{
text_to_log = text_to_log.substr(0, size - 1);
}

if (type == CURLINFO_TEXT)
{
static const auto kTlsInfo = nostd::string_view("SSL connection using");
static const auto kFailureMsg = nostd::string_view("Recv failure:");

if (text_to_log.substr(0, kTlsInfo.size()) == kTlsInfo)
{
OTEL_INTERNAL_LOG_INFO(text_to_log);
}
else if (text_to_log.substr(0, kFailureMsg.size()) == kFailureMsg)
{
OTEL_INTERNAL_LOG_ERROR(text_to_log);
}
#ifdef CURL_DEBUG
else
{
OTEL_INTERNAL_LOG_DEBUG(text_to_log);
}
#endif // CURL_DEBUG
}
#ifdef CURL_DEBUG
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please clarify (with a comment) the intent of CURL_DEBUG, which is separate from ENABLE_CURL_LOGGING.

As I understand it, ENABLE_CURL_LOGGING is exposed in CMake, to add the new logging feature.

On top of that, CURL_DEBUG seem to be a private developer flag (not exposed in cmake), for a developper to debug the new logging feature itself, if needed.

So, ENABLE_CURL_LOGGING may be used optionally in production, but CURL_DEBUG should not be used in production.

Is this accurate ?

Copy link
Contributor Author

@chusitoo chusitoo Nov 5, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That is correct, CURL_DEBUG is a guard that comes in handy when debugging something, where the full verbosity would be required. However, making it controllable by the user is probably not desirable as it could lead to unintentionally logging too much / sensitive information, such as request body, auth tokens, other sensitive in/out headers, etc.

That said, though, if this is deemed necessary by future requirements, exposing additional logging should be as simple as "punching" a few more holes in the callback function, by simply adding the respective if / else if statements outside this guarded block.

So, in a way, the second use of CURL_DEBUG is to force the developer to have to explicitly opt-in for exposing more logging info from CURL, which hopefully also makes it easy to see what information the callback function is letting out into the wild.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for the clarifications.

Do not change any code then, just add a comment that CURL_DEBUG is for maintainers, and should not be used in production (information leak).

else if (type == CURLINFO_HEADER_OUT)
{
static const auto kHeaderSent = nostd::string_view("Send header => ");

while (!text_to_log.empty() && !std::iscntrl(text_to_log[0]))
{
const auto pos = text_to_log.find('\n');

if (pos != nostd::string_view::npos)
{
OTEL_INTERNAL_LOG_DEBUG(kHeaderSent << text_to_log.substr(0, pos - 1));
text_to_log = text_to_log.substr(pos + 1);
}
}
}
else if (type == CURLINFO_HEADER_IN)
{
static const auto kHeaderRecv = nostd::string_view("Recv header => ");
OTEL_INTERNAL_LOG_DEBUG(kHeaderRecv << text_to_log);
}
#endif // CURL_DEBUG

return 0;
}

CURLcode HttpOperation::Setup()
{
#ifdef ENABLE_CURL_LOGGING
static constexpr auto kEnableCurlLogging = true;
#else
static constexpr auto kEnableCurlLogging = false;
#endif // ENABLE_CURL_LOGGING

if (!curl_resource_.easy_handle)
{
return CURLE_FAILED_INIT;
Expand All @@ -581,11 +649,28 @@ CURLcode HttpOperation::Setup()
curl_error_message_[0] = '\0';
curl_easy_setopt(curl_resource_.easy_handle, CURLOPT_ERRORBUFFER, curl_error_message_);

// Support for custom debug function callback was added in version 7.9.6 so we guard against
// exposing the default CURL output by keeping verbosity always disabled in lower versions.
#if LIBCURL_VERSION_NUM < CURL_VERSION_BITS(7, 9, 6)
rc = SetCurlLongOption(CURLOPT_VERBOSE, 0L);
if (rc != CURLE_OK)
{
return rc;
}
#else
rc = SetCurlLongOption(CURLOPT_VERBOSE, static_cast<long>(is_log_enabled_ || kEnableCurlLogging));
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Two concerns here:

  • not sure if casting a boolean to a long will always give 0L / 1L, so a plain if statement to set a verbose local variable will be safer
  • should it be is_log_enabled && kEnableCurlLogging instead ?

Copy link
Contributor Author

@chusitoo chusitoo Nov 5, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Regarding the explicit cast, it looked fairly safe given that the CURL API seems to only care about the value being 0 (disabled) or otherwise. Will update to a good ol' if statement, as requested.

As for the logic, my impression was that we wanted to have the runtime drive this behavior regardless of what is set at compile-time, but if omitting console_debug, it would still output logs provided WITH_CURL_LOGGING option was set.

If, what is ultimately needed is that the compile-time flag dictate the runtime behavior, then I guess it would need to be AND'ed, instead.

Let me know what is the preferred approach with respect to the above and I will push all the required changes at the same time.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Regarding the OR (||) or AND (&&) logic for the test:

  • using the patch as written (OR), one can set the default at compile time to log details, without having to change the console_debug attribute for each exporter, which requires an application change.
  • this sounds "easier" to use, but I think there is a twist.

Assume an application has a trace exporter and a metric exporter, both using OTLP HTTP to different endpoints.

By setting WITH_CURL_LOGGING=ON, both exporter are now traced, always. There is no way to turn off any of this tracing, even when debugging is no longer needed.

For this reason, I think the AND logic is better.

For people who wants to trace everything, it forces the application to use something like:

OtlpHttpExporterOptions opt;
#ifdef MY_OWN_DEBUG_FLAG
opt.console_debug = true; // or read from an application specific configuration
#else
opt.console_debug = false;
#endif

so in effect, the logic that was present in http_operation_curl.cc is moved to the application space, where the application (not opentelemetry-cpp) decides if/how it wants tracing to be done.

Yes, it is a code change for the application, to benefit from the feature.

However, this also allows to trace a metric exporter independently of a trace exporter, which I think is much more convenient to debug things, compared to the OR logic, especially when exporters points to different endpoints.

And when debugging is no longer needed ("or read from an application specific configuration"), tracing can be turned off, without having to recompile.

Please change the logic to AND then.

if (rc != CURLE_OK)
{
return rc;
}

rc = SetCurlPtrOption(CURLOPT_DEBUGFUNCTION,
reinterpret_cast<void *>(&HttpOperation::CurlLoggerCallback));
if (rc != CURLE_OK)
{
return rc;
}
#endif

// Specify target URL
rc = SetCurlStrOption(CURLOPT_URL, url_.c_str());
Expand Down
3 changes: 3 additions & 0 deletions test_common/include/opentelemetry/test_common/ext/http/client/nosend/http_client_nosend.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -69,6 +69,8 @@ class Request : public opentelemetry::ext::http::client::Request
compression_ = compression;
}

void EnableLogging(bool is_log_enabled) noexcept override { is_log_enabled_ = is_log_enabled; }

public:
opentelemetry::ext::http::client::Method method_;
opentelemetry::ext::http::client::HttpSslOptions ssl_options_;
Expand All @@ -78,6 +80,7 @@ class Request : public opentelemetry::ext::http::client::Request
std::chrono::milliseconds timeout_ms_{5000}; // ms
opentelemetry::ext::http::client::Compression compression_{
opentelemetry::ext::http::client::Compression::kNone};
bool is_log_enabled_{false};
};

class Response : public opentelemetry::ext::http::client::Response
Expand Down
Loading