Add basic Open Telemetry instrumentation for all requests.

This commit wraps all requests in an Open Telemetry span that abides by
the semantic conventions for HTTP clients [0] (insofar as I understand
them). We also propagate the trace context [1] when there is one.

Right now this instrumentation is opt in: `otel` is in `Suggests`, and
tracing must be enabled (e.g. via the `OTEL_TRACES_EXPORTER` environment
variable). Otherwise this is costless at runtime.

For example:

    library(otelsdk)

    Sys.setenv(OTEL_TRACES_EXPORTER = "stderr")

    request("https://google.com") |>
      req_perform()

I'm not sure that `otel` needs to move to `Imports`, because by design
users actually need the `otelsdk` package to enable tracing anyway.

Unit tests are included.

[0]: https://opentelemetry.io/docs/specs/semconv/http/http-spans/#http-client-span
[1]: https://www.w3.org/TR/trace-context/

Signed-off-by: Aaron Jacobs <[email protected]>

Author: atheriel

DESCRIPTION

@@ -39,6 +39,7 @@ Suggests:
     knitr,
     later (>= 1.4.0),
     nanonext,
+    otel (>= 0.0.0.9000),
     paws.common,
     promises,
     rmarkdown,
@@ -56,4 +57,5 @@ Encoding: UTF-8
 Roxygen: list(markdown = TRUE)
 RoxygenNote: 7.3.2
 Remotes:  
-    r-lib/webfakes
+    r-lib/webfakes,
+    r-lib/otel

NEWS.md

@@ -1,6 +1,7 @@
 # httr2 (development version)
 
 * `req_url_query()` now re-calculates n lengths when using `.multi = "explode"` to avoid select/recycling issues (@Kevanness, #719).
+* httr2 will now emit OpenTelemetry traces for all requests when tracing is enabled. Requires the `otelsdk` package (@atheriel, #729).
 
 # httr2 1.1.2
 

R/otel.R

@@ -0,0 +1,113 @@
+# Attaches an Open Telemetry span that abides by the semantic conventions for
+# HTTP clients to the request, including the associated W3C trace context
+# headers.
+#
+# See: https://opentelemetry.io/docs/specs/semconv/http/http-spans/#http-client-span
+req_with_span <- function(
+  req,
+  resend_count = 0,
+  tracer = NULL,
+  scope = parent.frame()
+) {
+  if (!is_installed("otel")) {
+    return(req)
+  }
+  tracer <- tracer %||% otel::get_tracer("httr2")
+  if (!tracer$is_enabled()) {
+    return(req)
+  }
+  parsed <- tryCatch(url_parse(req$url), error = function(cnd) NULL)
+  if (is.null(parsed)) {
+    # Don't create spans for invalid URLs.
+    return(req)
+  }
+  if (!req_has_user_agent(req)) {
+    req <- req_user_agent(req)
+  }
+  default_port <- 443L
+  if (parsed$scheme == "http") {
+    default_port <- 80L
+  }
+  # Follow the semantic conventions and redact credentials in the URL, when
+  # present.
+  if (!is.null(parsed$username)) {
+    parsed$username <- "REDACTED"
+  }
+  if (!is.null(parsed$password)) {
+    parsed$password <- "REDACTED"
+  }
+  method <- req_method_get(req)
+  span <- tracer$start_span(
+    name = method,
+    options = list(kind = "CLIENT"),
+    # Ensure we set attributes relevant to sampling at span creation time.
+    attributes = compact(list(
+      "http.request.method" = method,
+      "server.address" = parsed$hostname,
+      "server.port" = parsed$port %||% default_port,
+      "url.full" = url_build(parsed),
+      "http.request.resend_count" = if (resend_count > 1) resend_count,
+      "user_agent.original" = req$options$useragent
+    )),
+    scope = scope
+  )
+  ctx <- span$get_context()
+  req <- req_headers(req, !!!ctx$to_http_headers())
+  req$state$span <- span
+  req
+}
+
+# Ends the Open Telemetry span associated with this request, if any.
+req_end_span <- function(req, resp = NULL) {
+  span <- req$state$span
+  if (is.null(span) || !span$is_recording()) {
+    return()
+  }
+  if (is.null(resp)) {
+    span$end()
+    return()
+  }
+  if (is_error(resp)) {
+    span$record_exception(resp)
+    span$set_status("error")
+    # Surface the underlying curl error class.
+    span$set_attribute("error.type", class(resp$parent)[1])
+    span$end()
+    return()
+  }
+  span$set_attribute("http.response.status_code", resp_status(resp))
+  if (error_is_error(req, resp)) {
+    desc <- resp_status_desc(resp)
+    if (is.na(desc)) {
+      desc <- NULL
+    }
+    span$set_status("error", desc)
+    # The semantic conventions recommend using the status code as a string for
+    # these cases.
+    span$set_attribute("error.type", as.character(resp_status(resp)))
+  } else {
+    span$set_status("ok")
+  }
+  span$end()
+}
+
+# Replaces the existing Open Telemetry span on a request with a new one. Used
+# for retries.
+req_reset_span <- function(
+  req,
+  handle,
+  resend_count = 0,
+  tracer = NULL,
+  scope = parent.frame()
+) {
+  req <- req_with_span(req, resend_count, tracer, scope)
+  if (is.null(req$state$span)) {
+    return(req)
+  }
+  # Because the headers have changed, we need to re-sign the request and update
+  # stateful components (like the handle).
+  req <- auth_sign(req)
+  curl::handle_setheaders(handle, .list = headers_flatten(req$headers))
+  req$state$headers <- req$headers
+  req
+}

R/req-perform-connection.R

@@ -54,6 +54,7 @@ req_perform_connection <- function(req, blocking = TRUE, verbosity = NULL) {
   # verbosity checked in req_verbosity_connection
 
   req <- req_verbosity_connection(req, verbosity %||% httr2_verbosity())
+  req <- req_with_span(req)
   req_prep <- req_prepare(req)
   handle <- req_handle(req_prep)
   the$last_request <- req
@@ -71,7 +72,14 @@ req_perform_connection <- function(req, blocking = TRUE, verbosity = NULL) {
     if (!is.null(resp)) {
       close(resp)
     }
+
+    if (tries != 0) {
+      # Start a new span for retried requests.
+      req_prep <- req_reset_span(req_prep, handle, resend_count = tries)
+    }
+
     resp <- req_perform_connection1(req, handle, blocking = blocking)
+    req_completed(req_prep, resp)
 
     if (retry_is_transient(req, resp)) {
       tries <- tries + 1
@@ -82,7 +90,6 @@ req_perform_connection <- function(req, blocking = TRUE, verbosity = NULL) {
       break
     }
   }
-  req_completed(req)
 
   if (!is_error(resp) && error_is_error(req, resp)) {
     # Read full body if there's an error

R/req-perform.R

@@ -79,6 +79,8 @@ req_perform <- function(
   verbosity <- verbosity %||% httr2_verbosity()
 
   if (!is.null(mock)) {
+    # Allow us to use with_mock() to confirm context propagation.
+    req <- req_with_span(req)
     mock <- as_function(mock)
     mock_resp <- mock(req)
     if (!is.null(mock_resp)) {
@@ -93,6 +95,9 @@ req_perform <- function(
     return(req)
   }
 
+  sys_sleep(throttle_delay(req), "for throttling delay")
+
+  req <- req_with_span(req)
   req_prep <- req_prepare(req)
   handle <- req_handle(req_prep)
   max_tries <- retry_max_tries(req)
@@ -101,17 +106,19 @@ req_perform <- function(
   n <- 0
   tries <- 0
   reauthed <- FALSE # only ever re-authenticate once
-
-  sys_sleep(throttle_delay(req), "for throttling delay")
-
   delay <- 0
   while (tries < max_tries && Sys.time() < deadline) {
     retry_check_breaker(req, tries, error_call = error_call)
     sys_sleep(delay, "for retry backoff")
     n <- n + 1
 
+    if (n != 1) {
+      # Start a new span for retried requests.
+      req_prep <- req_reset_span(req_prep, handle, resend_count = n)
+    }
+
     resp <- req_perform1(req, path = path, handle = handle)
-    req_completed(req_prep)
+    req_completed(req_prep, resp)
 
     if (retry_is_transient(req, resp)) {
       tries <- tries + 1
@@ -270,7 +277,8 @@ req_handle <- function(req) {
 
   handle
 }
-req_completed <- function(req) {
+req_completed <- function(req, resp = NULL) {
+  req_end_span(req, resp)
   req_policy_call(req, "done", list(), NULL)
 }
 

tests/testthat/test-req-perform.R

@@ -196,3 +196,97 @@ test_that("checks input types", {
     req_perform(req, mock = 7)
   })
 })
+
+test_that("tracing works as expected", {
+  skip_if_not_installed("otelsdk")
+
+  spans <- otelsdk::with_otel_record({
+    # A request with no URL (which shouldn't create a span).
+    try(req_perform(request("")), silent = TRUE)
+
+    # A regular request.
+    req_perform(request_test())
+
+    # A request with an HTTP error.
+    try(
+      req_perform(request_test("/status/:status", status = 404)),
+      silent = TRUE
+    )
+
+    # A request with basic credentials that we should redact.
+    with_mocked_responses(
+      function(req) {
+        # Verify that the traceparent header is present when tracing while
+        # we're in here.
+        expect_false(is.null(req$headers$traceparent))
+        response(status_code = 200)
+      },
+      req_perform(request("https://test:[email protected]"))
+    )
+
+    # A request with a curl error.
+    with_mocked_bindings(
+      try(req_perform(request("http://127.0.0.1")), silent = TRUE),
+      curl_fetch = function(...) abort("Failed to connect")
+    )
+
+    # A request that triggers retries, generating three individual spans.
+    request_test("/status/:status", status = 429) %>%
+      req_retry(max_tries = 3, backoff = ~0) %>%
+      req_perform() %>%
+      try(silent = TRUE)
+  })[["traces"]]
+
+  expect_length(spans, 7L)
+
+  # Validate the span for regular requests.
+  expect_equal(spans[[1]]$status, "ok")
+  expect_named(
+    spans[[1]]$attributes,
+    c(
+      "http.response.status_code",
+      "user_agent.original",
+      "url.full",
+      "server.address",
+      "server.port",
+      "http.request.method"
+    )
+  )
+  expect_equal(spans[[1]]$attributes$http.request.method, "GET")
+  expect_equal(spans[[1]]$attributes$http.response.status_code, 200L)
+  expect_equal(spans[[1]]$attributes$server.address, "127.0.0.1")
+  expect_match(spans[[1]]$attributes$user_agent.original, "^httr2/")
+
+  # And for requests with HTTP errors.
+  expect_equal(spans[[2]]$status, "error")
+  expect_equal(spans[[2]]$description, "Not Found")
+  expect_equal(spans[[2]]$attributes$http.response.status_code, 404L)
+  expect_equal(spans[[2]]$attributes$error.type, "404")
+
+  # And for spans with redacted credentials.
+  expect_equal(spans[[3]]$attributes$server.address, "example.com")
+  expect_equal(spans[[3]]$attributes$server.port, 443L)
+  expect_equal(
+    spans[[3]]$attributes$url.full,
+    "https://REDACTED:[email protected]/"
+  )
+
+  # And for spans with curl errors.
+  expect_equal(spans[[4]]$status, "error")
+  expect_equal(spans[[4]]$attributes$error.type, "rlang_error")
+
+  # We should have attached the curl error as an event.
+  expect_length(spans[[4]]$events, 1L)
+  expect_equal(spans[[4]]$events[[1]]$name, "exception")
+
+  # For spans with retries, we expect the parent context to be the same for
+  # each span. (In this case, there is no parent span, so it should be empty.)
+  # It is important that they not be children of one another.
+  expect_equal(spans[[5]]$parent, "0000000000000000")
+  expect_equal(spans[[6]]$parent, "0000000000000000")
+  expect_equal(spans[[7]]$parent, "0000000000000000")
+
+  # Verify that we set resend counts correctly.
+  expect_equal(spans[[6]]$attributes$http.request.resend_count, 2L)
+  expect_equal(spans[[7]]$attributes$http.request.resend_count, 3L)
+})