diff --git a/DESCRIPTION b/DESCRIPTION index cc51781a..fa8efac7 100644 --- a/DESCRIPTION +++ b/DESCRIPTION @@ -39,6 +39,8 @@ Suggests: knitr, later (>= 1.4.0), nanonext, + otel (>= 0.2.0), + otelsdk (>= 0.2.0), paws.common, promises, rmarkdown, @@ -55,3 +57,5 @@ Config/testthat/start-first: resp-stream, req-perform Encoding: UTF-8 Roxygen: list(markdown = TRUE) RoxygenNote: 7.3.2 +Remotes: + r-lib/otelsdk diff --git a/NEWS.md b/NEWS.md index 416821d2..3e253431 100644 --- a/NEWS.md +++ b/NEWS.md @@ -3,6 +3,9 @@ * Refactor `url_modify()` to better retain exact formatting of URL components that are not modified. (#788, #794) +* httr2 will now emit OpenTelemetry traces for all requests when tracing is + enabled. Requires the `otelsdk` package (@atheriel, #729). + # httr2 1.2.1 * Colons in paths are no longer escaped. diff --git a/R/otel.R b/R/otel.R new file mode 100644 index 00000000..6afdbf9d --- /dev/null +++ b/R/otel.R @@ -0,0 +1,114 @@ +# 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 = get_tracer(), + activation_scope = parent.frame(), + activate = TRUE +) { + if (!is_tracing(tracer)) { + cli::cli_abort( + "Cannot create request span; tracing is not enabled", + .internal = TRUE + ) + } + 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_get_method(req) + # Set required (and some recommended) attributes, especially those 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 + )) + span <- tracer$start_span( + name = method, + options = list(kind = "CLIENT"), + attributes = attributes + ) + if (activate) { + span$activate(activation_scope, end_on_exit = TRUE) + } + req <- req_headers(req, !!!otel::pack_http_context()) + req$state$span <- span + req +} + +req_record_span_status <- function(req, resp = NULL) { + span <- req$state$span + if (is.null(span) || !span$is_recording()) { + return() + } + # For more accurate span timing, we end the span after the response has been + # received, rather than at the end of the associated scope. + on.exit(span$end()) + if (is.null(resp)) { + 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]) + 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") + } +} + +get_tracer <- function() { + if (!is.null(the$tracer)) { + return(the$tracer) + } + if (!is_installed("otel")) { + return(NULL) + } + if (is_testing()) { + # Don't cache the tracer in unit tests. It interferes with tracer provider + # injection in otelsdk::with_otel_record(). + return(otel::get_tracer("httr2")) + } + the$tracer <- otel::get_tracer("httr2") + the$tracer +} + +is_tracing <- function(tracer = get_tracer()) { + !is.null(tracer) && tracer$is_enabled() +} diff --git a/R/pooled-request.R b/R/pooled-request.R index bb659e88..64572040 100644 --- a/R/pooled-request.R +++ b/R/pooled-request.R @@ -66,6 +66,19 @@ PooledRequest <- R6Class( private$req_prep <- req_prepare(req) private$handle <- req_handle(private$req_prep) + if (is_tracing()) { + # Note: we need to do this before we call handle_preflight() so that + # request signing works correctly with the added headers. + # + # TODO: Support resend_count. + private$req_prep <- req_with_span( + private$req_prep, + # Pooled request spans should not become the active span; we want + # subsequent requests to be siblings rather than parents. + activate = FALSE + ) + } + handle_preflight(private$req_prep, private$handle) curl::multi_add( handle = private$handle, @@ -83,6 +96,9 @@ PooledRequest <- R6Class( if (!is.null(private$handle)) { curl::multi_cancel(private$handle) } + if (!is.null(private$req_prep)) { + req_record_span_status(private$req_prep) + } } ), private = list( @@ -114,6 +130,7 @@ PooledRequest <- R6Class( } resp <- create_response(self$req, curl_data, body) + req_record_span_status(private$req_prep, resp) resp <- cache_post_fetch(self$req, resp, path = private$path) private$handle_response(resp, self$req) }, @@ -136,6 +153,7 @@ PooledRequest <- R6Class( curl_error <- error_cnd(message = msg, class = error_class, call = NULL) error <- curl_cnd(curl_error, call = private$error_call) error$request <- self$req + req_record_span_status(private$req_prep, error) private$on_error(error) } ) diff --git a/R/req-dry-run.R b/R/req-dry-run.R index c4fd15dc..69a0fd98 100644 --- a/R/req-dry-run.R +++ b/R/req-dry-run.R @@ -61,7 +61,7 @@ req_dry_run <- function( req <- req_prepare(req) handle <- req_handle(req) - curl::handle_setopt(handle, url = req$url) + handle_preflight(req, handle) resp <- curl::curl_echo(handle, progress = FALSE) headers <- new_headers( as.list(resp$headers), diff --git a/R/req-perform-connection.R b/R/req-perform-connection.R index 3dbfb664..beaf8a9c 100644 --- a/R/req-perform-connection.R +++ b/R/req-perform-connection.R @@ -84,7 +84,13 @@ req_perform_connection <- function( if (!is.null(resp)) { close(resp) } - resp <- req_perform_connection1(req, handle, blocking = blocking) + resp <- req_perform_connection1( + req, + req_prep, + handle, + blocking = blocking, + resend_count = tries + 1L + ) if (retry_is_transient(req, resp)) { tries <- tries + 1 @@ -95,7 +101,7 @@ req_perform_connection <- function( break } } - req_completed(req) + req_completed(req_prep) if (!is_error(resp) && error_is_error(req, resp)) { # Read full body if there's an error @@ -135,10 +141,22 @@ req_verbosity_connection <- function( req } -req_perform_connection1 <- function(req, handle, blocking = TRUE) { +req_perform_connection1 <- function( + req, + req_prep, + handle, + blocking = TRUE, + resend_count = 0 +) { the$last_request <- req the$last_response <- NULL signal(class = "httr2_perform_connection") + if (is_tracing()) { + # Note: we need to do this before we call handle_preflight() so that request + # signing works correctly with the added headers. + req_prep <- req_with_span(req_prep, resend_count = resend_count) + } + handle_preflight(req_prep, handle) err <- capture_curl_error({ conn <- curl::curl(req$url, handle = handle) @@ -151,11 +169,14 @@ req_perform_connection1 <- function(req, handle, blocking = TRUE) { body <- StreamingBody$new(conn) }) if (is_error(err)) { + req_record_span_status(req, err) return(err) } curl_data <- curl::handle_data(handle) - create_response(req, curl_data, body) + resp <- create_response(req, curl_data, body) + req_record_span_status(req, resp) + resp } # Make open mockable diff --git a/R/req-perform.R b/R/req-perform.R index 3793b103..01900058 100644 --- a/R/req-perform.R +++ b/R/req-perform.R @@ -109,7 +109,13 @@ req_perform <- function( sys_sleep(delay, "for retry backoff") n <- n + 1 - resp <- req_perform1(req, path = path, handle = handle) + resp <- req_perform1( + req, + req_prep, + path = path, + handle = handle, + resend_count = n + ) req_completed(req_prep) if (retry_is_transient(req, resp)) { @@ -174,15 +180,28 @@ resp_failure_cnd <- function(req, resp, error_call = caller_env()) { )) } -req_perform1 <- function(req, path = NULL, handle = NULL) { +req_perform1 <- function( + req, + req_prep, + path = NULL, + handle = NULL, + resend_count = 0 +) { the$last_request <- req the$last_response <- NULL signal(class = "httr2_perform") + if (is_tracing()) { + # Note: we need to do this before we call handle_preflight() so that request + # signing works correctly with the added headers. + req_prep <- req_with_span(req_prep, resend_count = resend_count) + } + handle_preflight(req_prep, handle) err <- capture_curl_error({ fetch <- curl_fetch(handle, req$url, path) }) if (is_error(err)) { + req_record_span_status(req, err) return(err) } @@ -190,7 +209,9 @@ req_perform1 <- function(req, path = NULL, handle = NULL) { curl::handle_setopt(handle, cookielist = "FLUSH") curl::handle_setopt(handle, cookiefile = NULL, cookiejar = NULL) - create_response(req, fetch$curl_data, fetch$body) + resp <- create_response(req, fetch$curl_data, fetch$body) + req_record_span_status(req_prep, resp) + resp } curl_fetch <- function(handle, url, path) { @@ -222,26 +243,17 @@ req_verbosity <- function(req, verbosity, error_call = caller_env()) { # Must call req_prepare(), then req_handle(), then after the request has been # performed, req_completed() (on the prepared requests) req_prepare <- function(req) { - req <- auth_sign(req) req <- req_method_apply(req) req <- req_body_apply(req) - - # Save actually request headers so that req_verbose() can use them - req$state$headers <- req$headers - - req -} -req_handle <- function(req) { if (!req_has_user_agent(req)) { req <- req_user_agent(req) } + req +} +req_handle <- function(req) { handle <- curl::new_handle() curl::handle_setopt(handle, url = req$url) - curl::handle_setheaders( - handle, - .list = headers_flatten(req$headers, redact = FALSE) - ) curl::handle_setopt(handle, .list = req$options) if (length(req$fields) > 0) { curl::handle_setform(handle, .list = req$fields) @@ -249,6 +261,19 @@ req_handle <- function(req) { handle } + +# Called right before the request is sent, when the final headers are in place. +handle_preflight <- function(req, handle) { + req <- auth_sign(req) + curl::handle_setheaders( + handle, + .list = headers_flatten(req$headers, redact = FALSE) + ) + # Save final request headers so that req_verbose() can use them + req$state$headers <- req$headers + invisible(handle) +} + req_completed <- function(req) { req_policy_call(req, "done", list(), NULL) } diff --git a/tests/testthat/test-req-perform-connection.R b/tests/testthat/test-req-perform-connection.R index 3f75ad73..fa5f07a1 100644 --- a/tests/testthat/test-req-perform-connection.R +++ b/tests/testthat/test-req-perform-connection.R @@ -110,3 +110,92 @@ test_that("can access fdset", { body <- StreamingBody$new(con) expect_length(body$get_fdset()$reads, 1) }) + +# otel ----------------------------------------------------------------------- + +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_connection(request("")), silent = TRUE) + + # A regular request. + resp <- req_perform_connection(request_test("/headers")) + + # Verify that context propagation works as expected. + expect_true("traceparent" %in% names(resp_body_json(resp)[["headers"]])) + close(resp) + + # A request with an HTTP error. + try( + req_perform_connection(request_test("/status/:status", status = 404)), + silent = TRUE + ) + + # A request with basic credentials that we should redact. + parsed <- url_parse(example_url()) + parsed$username <- "user" + parsed$password <- "secret" + req_perform_connection(request(url_build(parsed))) + + # A request with a curl error. + with_mocked_bindings( + try(req_perform_connection(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_connection() |> + 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_match( + spans[[3]]$attributes$url.full, + regexp = "http://REDACTED:REDACTED@127.0.0.1:[0-9]+/", + ) + + # And for spans with curl errors. + expect_equal(spans[[4]]$status, "error") + expect_equal(spans[[4]]$attributes$error.type, "simpleError") + + # 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") +}) diff --git a/tests/testthat/test-req-perform-parallel.R b/tests/testthat/test-req-perform-parallel.R index 11fca536..be7c8f1e 100644 --- a/tests/testthat/test-req-perform-parallel.R +++ b/tests/testthat/test-req-perform-parallel.R @@ -335,6 +335,68 @@ test_that("mocking works", { expect_s3_class(resps[[2]], "httr2_http_404") }) +# otel ----------------------------------------------------------------------- + +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_parallel(list(request(""))), silent = TRUE) + + # A request with an HTTP error. + try( + req_perform_parallel(list(request_test("/status/:status", status = 404))), + silent = TRUE + ) + + # 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") + ) + + # Three regular requests, nested inside a parent span. + parent <- otel::start_span("parent", tracer = "test") + otel::with_active_span(parent, { + resp <- req_perform_parallel(list( + request_test("/headers"), + request_test("/headers"), + request_test("/headers") + )) + }) + parent$end() + + # Verify that context propagation works as expected. + expect_true( + "traceparent" %in% names(resp_body_json(resp[[1]])[["headers"]]) + ) + })[["traces"]] + + expect_length(spans, 6L) + + # And for requests with HTTP errors. + expect_equal(spans[[1]]$status, "error") + expect_equal(spans[[1]]$description, "Not Found") + expect_equal(spans[[1]]$attributes$http.response.status_code, 404L) + expect_equal(spans[[1]]$attributes$error.type, "404") + + # And for spans with curl errors. + expect_equal(spans[[2]]$status, "error") + expect_equal(spans[[2]]$attributes$error.type, "rlang_error") + + # We should have attached the curl error as an event. + expect_length(spans[[2]]$events, 1L) + expect_equal(spans[[2]]$events[[1]]$name, "exception") + + # Verify that the parent span is the same for parallel requests (that is, + # they are siblings). + expect_equal(spans[[3]]$parent, spans[[6]]$span_id) + expect_equal(spans[[4]]$parent, spans[[6]]$span_id) + expect_equal(spans[[5]]$parent, spans[[6]]$span_id) + expect_equal(spans[[6]]$parent, "0000000000000000") +}) + # Pool helpers ---------------------------------------------------------------- test_that("wait for deadline waits after pool complete", { diff --git a/tests/testthat/test-req-perform.R b/tests/testthat/test-req-perform.R index 00234e43..e7cb2fb1 100644 --- a/tests/testthat/test-req-perform.R +++ b/tests/testthat/test-req-perform.R @@ -219,3 +219,95 @@ test_that("checks input types", { req_perform(req, mock = 7) }) }) + +# otel ----------------------------------------------------------------------- + +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. + resp <- req_perform(request_test("/headers")) + + # Verify that context propagation works as expected. + expect_true("traceparent" %in% names(resp_body_json(resp)[["headers"]])) + + # 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. + parsed <- url_parse(example_url()) + parsed$username <- "user" + parsed$password <- "secret" + req_perform(request(url_build(parsed))) + + # 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_match( + spans[[3]]$attributes$url.full, + regexp = "http://REDACTED:REDACTED@127.0.0.1:[0-9]+/", + ) + + # 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) +}) diff --git a/tests/testthat/test-req-promise.R b/tests/testthat/test-req-promise.R index 3fb17fb5..cfd07868 100644 --- a/tests/testthat/test-req-promise.R +++ b/tests/testthat/test-req-promise.R @@ -169,3 +169,68 @@ test_that("mocking works", { class = "httr2_http_404" ) }) + +# otel ----------------------------------------------------------------------- + +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_promise(request("")), silent = TRUE) + + # A request with an HTTP error. + p <- req_perform_promise(request_test("/status/:status", status = 404)) + try(extract_promise(p), silent = TRUE) + + # A request with a curl error. + with_mocked_bindings( + { + p <- req_perform_promise(request("http://127.0.0.1")) + try(extract_promise(p), silent = TRUE) + }, + curl_fetch = function(...) abort("Failed to connect") + ) + + # A request with no parent context. + p <- req_perform_promise(request_test("/headers")) + + # A request nested inside a parent span. + parent <- otel::start_span("parent", tracer = "test") + otel::with_active_span(parent, { + child <- req_perform_promise(request_test()) + # Resolve the earlier request with a different session; this should not + # affect its parent. + resp <- extract_promise(p) + }) + extract_promise(child) + parent$end() + + # Verify that context propagation works as expected. + expect_true( + "traceparent" %in% names(resp_body_json(resp)[["headers"]]) + ) + })[["traces"]] + + expect_length(spans, 5L) + + # And for requests with HTTP errors. + expect_equal(spans[[1]]$status, "error") + expect_equal(spans[[1]]$description, "Not Found") + expect_equal(spans[[1]]$attributes$http.response.status_code, 404L) + expect_equal(spans[[1]]$attributes$error.type, "404") + + # And for spans with curl errors. + expect_equal(spans[[2]]$status, "error") + expect_equal(spans[[2]]$attributes$error.type, "curl_error_couldnt_connect") + + # We should have attached the curl error as an event. + expect_length(spans[[2]]$events, 1L) + expect_equal(spans[[2]]$events[[1]]$name, "exception") + + # Verify that the spans for requests resolved later still have the parent + # context in which they were submitted. + expect_equal(spans[[3]]$parent, "0000000000000000") + expect_equal(spans[[4]]$parent, spans[[5]]$span_id) + expect_equal(spans[[5]]$parent, "0000000000000000") +})