From e3cf4fb0892e091689f07fcf35b16da27e363f20 Mon Sep 17 00:00:00 2001 From: Barret Schloerke Date: Tue, 11 Nov 2025 08:44:57 -0500 Subject: [PATCH] refactor(otel): Cache tracer and logger on init and on demand (#4315) Co-authored-by: Charlie Gao <53399081+shikokuchuo@users.noreply.github.com> --- R/otel-shiny.R | 141 ++++++++++++-------------- R/shiny-package.R | 6 -- tests/testthat/test-otel-error.R | 4 +- tests/testthat/test-otel-label.R | 4 +- tests/testthat/test-otel-mock.R | 2 +- tests/testthat/test-otel-shiny.R | 164 ------------------------------- 6 files changed, 68 insertions(+), 253 deletions(-) diff --git a/R/otel-shiny.R b/R/otel-shiny.R index 513d2cbab..345a1cbb2 100644 --- a/R/otel-shiny.R +++ b/R/otel-shiny.R @@ -1,9 +1,71 @@ - # Used by otel to identify the tracer and logger for this package # https://github.com/r-lib/otel/blob/afc31bc1f4bd177870d44b051ada1d9e4e685346/R/tracer-name.R#L33-L49 # DO NOT CHANGE THIS VALUE without understanding the implications for existing telemetry data! otel_tracer_name <- "co.posit.r-package.shiny" +init_otel <- function() { + .globals$otel_tracer <- otel::get_tracer() + .globals$otel_is_tracing_enabled <- otel::is_tracing_enabled(.globals$otel_tracer) + + .globals$otel_logger <- otel::get_logger() + # .globals$otel_is_logging_enabled <- otel::is_logging_enabled() +} +on_load({init_otel()}) + +#' Run expr within a Shiny OpenTelemetry recording context +#' +#' Reset the OpenTelemetry tracer and logger for Shiny. +#' Used for testing purposes only. +#' @param expr Expression to evaluate within the recording context +#' @return The result of evaluating `otelsdk::with_otel_record(expr)` with freshly enabled Shiny otel tracer and logger +#' @noRd +with_shiny_otel_record <- function(expr) { + # Only use within internal testthat tests + stopifnot(testthat__is_testing()) + withr::defer({ init_otel() }) + + otelsdk::with_otel_record({ + init_otel() + + force(expr) + }) +} + +#' Check if OpenTelemetry tracing is enabled +#' +#' @param tracer The OpenTelemetry tracer to check (default: Shiny otel tracer) +#' @return `TRUE` if tracing is enabled, `FALSE` otherwise +#' @noRd +otel_is_tracing_enabled <- function() { + .globals[["otel_is_tracing_enabled"]] +} + +#' Shiny OpenTelemetry logger +#' +#' Used for logging OpenTelemetry events via `otel_log()` +#' @return An OpenTelemetry logger +#' @noRd +shiny_otel_logger <- function() { + .globals[["otel_logger"]] +} + + + +#' Shiny OpenTelemetry tracer +#' +#' Used for creating OpenTelemetry spans via `with_otel_span()` and +#' `start_otel_span()` +#' +#' Inspired by httr2:::get_tracer(). +#' @return An OpenTelemetry tracer +#' @noRd +shiny_otel_tracer <- function() { + .globals[["otel_tracer"]] +} + + + + #' Create and use a Shiny OpenTelemetry span #' #' If otel is disabled, the span will not be created, @@ -63,80 +125,3 @@ otel_log <- function( ) { otel::log(msg, ..., severity = severity, logger = logger) } - -#' Check if OpenTelemetry tracing is enabled -#' -#' @param tracer The OpenTelemetry tracer to check (default: Shiny otel tracer) -#' @return `TRUE` if tracing is enabled, `FALSE` otherwise -#' @noRd -otel_is_tracing_enabled <- function(tracer = shiny_otel_tracer()) { - otel::is_tracing_enabled(tracer) -} - -#' Shiny OpenTelemetry logger -#' -#' Used for logging OpenTelemetry events via `otel_log()` -#' @return An OpenTelemetry logger -#' @noRd -shiny_otel_logger <- local({ - logger <- NULL - - # For internal testing purposes only - reset_logger <- function() { - logger <<- NULL - } - - function() { - if (!is.null(logger)) { - return(logger) - } - - this_logger <- otel::get_logger() - - if (testthat__is_testing()) { - # Don't cache the logger in unit tests. It interferes with logger provider - # injection in otelsdk::with_otel_record(). - return(this_logger) - } - logger <<- this_logger - logger - } -}) - - - -#' Shiny OpenTelemetry tracer -#' -#' Used for creating OpenTelemetry spans via `with_otel_span()` and -#' `start_otel_span()` -#' -#' Inspired by httr2:::get_tracer(). -#' @return An OpenTelemetry tracer -#' @noRd -shiny_otel_tracer <- local({ - # Using local scope avoids an environment object lookup on each call. - - tracer <- NULL - - # For internal testing purposes only - reset_tracer <- function() { - tracer <<- NULL - } - - function() { - if (!is.null(tracer)) { - return(tracer) - } - - this_tracer <- otel::get_tracer() - - if (testthat__is_testing()) { - # Don't cache the tracer in unit tests. It interferes with tracer provider - # injection in otelsdk::with_otel_record(). - return(this_tracer) - } - - tracer <<- this_tracer - tracer - } -}) diff --git a/R/shiny-package.R b/R/shiny-package.R index c2a3efaee..391bc78f3 100644 --- a/R/shiny-package.R +++ b/R/shiny-package.R @@ -42,9 +42,3 @@ release_bullets <- function() { "Update static imports: `staticimports::import()`" ) } - - -# To get around R CMD check lint -`_ignore` <- function() { - otelsdk::with_otel_record -} diff --git a/tests/testthat/test-otel-error.R b/tests/testthat/test-otel-error.R index f99db5d50..552488786 100644 --- a/tests/testthat/test-otel-error.R +++ b/tests/testthat/test-otel-error.R @@ -34,7 +34,7 @@ test_server_with_otel_error <- function(session, server, expr, sanitize = FALSE, stopifnot(inherits(session, "MockShinySession")) stopifnot(is.function(server)) - traces <- otelsdk::with_otel_record({ 42 })$traces + traces <- with_shiny_otel_record({ 42 })$traces expect_length(traces, 0) withr::with_options( @@ -43,7 +43,7 @@ test_server_with_otel_error <- function(session, server, expr, sanitize = FALSE, shiny.otel.sanitize.errors = sanitize ), { - info <- otelsdk::with_otel_record({ + info <- with_shiny_otel_record({ # rlang quosure magic to capture and pass through `expr` testServer(server, {{ expr }}, args = args, session = session) }) diff --git a/tests/testthat/test-otel-label.R b/tests/testthat/test-otel-label.R index 5b494de6d..aa66b9c1c 100644 --- a/tests/testthat/test-otel-label.R +++ b/tests/testthat/test-otel-label.R @@ -70,7 +70,7 @@ test_that("reactive bindCache labels are created", { test_that("ExtendedTask otel labels are created", { ex_task <- ExtendedTask$new(function() { promises::then(promises::promise_resolve(42), force) }) - info <- otelsdk::with_otel_record({ + info <- with_shiny_otel_record({ ex_task$invoke() while(!later::loop_empty()) { later::run_now() @@ -88,7 +88,7 @@ test_that("ExtendedTask otel labels are created", { withReactiveDomain(MockShinySession$new(), { ex2_task <- ExtendedTask$new(function() { promises::then(promises::promise_resolve(42), force) }) - info <- otelsdk::with_otel_record({ + info <- with_shiny_otel_record({ ex2_task$invoke() while(!later::loop_empty()) { later::run_now() diff --git a/tests/testthat/test-otel-mock.R b/tests/testthat/test-otel-mock.R index 7d9672e41..1b8d6c183 100644 --- a/tests/testthat/test-otel-mock.R +++ b/tests/testthat/test-otel-mock.R @@ -47,7 +47,7 @@ test_server_with_otel <- function(session, server, expr, bind = "all", args = li stopifnot(is.function(server)) withr::with_options(list(shiny.otel.bind = bind), { - info <- otelsdk::with_otel_record({ + info <- with_shiny_otel_record({ # rlang quosure magic to capture and pass through `expr` testServer(server, {{ expr }}, args = args, session = session) }) diff --git a/tests/testthat/test-otel-shiny.R b/tests/testthat/test-otel-shiny.R index b91e4b874..d5eaa0fe3 100644 --- a/tests/testthat/test-otel-shiny.R +++ b/tests/testthat/test-otel-shiny.R @@ -140,170 +140,6 @@ test_that("otel_log uses default severity and logger", { expect_true(log_called) }) -test_that("otel_is_tracing_enabled calls otel::is_tracing_enabled", { - mock_tracer <- create_mock_tracer() - is_tracing_called <- FALSE - - local_mocked_bindings( - is_tracing_enabled = function(tracer) { - is_tracing_called <<- TRUE - expect_equal(tracer, mock_tracer) - TRUE - }, - .package = "otel" - ) - local_mocked_bindings( - shiny_otel_tracer = function() mock_tracer, - ) - - result <- otel_is_tracing_enabled() - expect_true(is_tracing_called) - expect_true(result) -}) - -test_that("otel_is_tracing_enabled accepts custom tracer", { - custom_tracer <- create_mock_tracer() - is_tracing_called <- FALSE - - local_mocked_bindings( - is_tracing_enabled = function(tracer) { - is_tracing_called <<- TRUE - expect_equal(tracer, custom_tracer) - FALSE - }, - .package = "otel" - ) - - result <- otel_is_tracing_enabled(custom_tracer) - expect_true(is_tracing_called) - expect_false(result) -}) - -test_that("shiny_otel_logger caches logger in non-test environment", { - mock_logger <- create_mock_logger() - get_logger_call_count <- 0 - - fn_env <- environment(shiny_otel_logger) - # Reset cached logger now and when test ends - fn_env$reset_logger() - withr::defer({ fn_env$reset_logger() }) - - local_mocked_bindings( - get_logger = function(...) { - get_logger_call_count <<- get_logger_call_count + 1 - mock_logger - }, - .package = "otel" - ) - - with_mocked_bindings( - testthat__is_testing = function() TRUE, - { - # First call - logger1 <- shiny_otel_logger() - expect_equal(logger1, mock_logger) - expect_equal(get_logger_call_count, 1) - - # Second call should call otel::get_logger again (no caching in tests) - logger2 <- shiny_otel_logger() - expect_equal(logger2, mock_logger) - expect_equal(get_logger_call_count, 2) # Incremented - } - ) - - with_mocked_bindings( - testthat__is_testing = function() FALSE, - { - # First call should call otel::get_logger - logger1 <- shiny_otel_logger() - expect_equal(logger1, mock_logger) - expect_equal(get_logger_call_count, 3) - - # Second call should use cached logger - logger2 <- shiny_otel_logger() - expect_equal(logger2, mock_logger) - expect_equal(get_logger_call_count, 3) # Still 3, not incremented - } - ) -}) - - -test_that("shiny_otel_tracer caches tracer in non-test environment", { - mock_tracer <- create_mock_tracer() - get_tracer_call_count <- 0 - - fn_env <- environment(shiny_otel_tracer) - # Reset cached tracer now and when test ends - fn_env$reset_tracer() - withr::defer({ fn_env$reset_tracer() }) - - local_mocked_bindings( - get_tracer = function(...) { - get_tracer_call_count <<- get_tracer_call_count + 1 - mock_tracer - }, - .package = "otel" - ) - - with_mocked_bindings( - testthat__is_testing = function() TRUE, - { - # First call - tracer1 <- shiny_otel_tracer() - expect_equal(tracer1, mock_tracer) - expect_equal(get_tracer_call_count, 1) - - # Second call should call otel::get_tracer again (no caching in tests) - tracer2 <- shiny_otel_tracer() - expect_equal(tracer2, mock_tracer) - expect_equal(get_tracer_call_count, 2) # Incremented - } - ) - - with_mocked_bindings( - testthat__is_testing = function() FALSE, - { - # First call should call otel::get_tracer - tracer1 <- shiny_otel_tracer() - expect_equal(tracer1, mock_tracer) - expect_equal(get_tracer_call_count, 3) - - # Second call should use cached tracer - tracer2 <- shiny_otel_tracer() - expect_equal(tracer2, mock_tracer) - expect_equal(get_tracer_call_count, 3) # Still 3, not incremented - } - ) -}) - -test_that("integration test - with_otel_span uses cached tracer", { - mock_tracer <- create_mock_tracer() - get_tracer_call_count <- 0 - - fn_env <- environment(shiny_otel_tracer) - # Reset cached tracer now and when test ends - fn_env$reset_tracer() - withr::defer({ fn_env$reset_tracer() }) - - local_mocked_bindings( - get_tracer = function() { - get_tracer_call_count <<- get_tracer_call_count + 1 - mock_tracer - }, - .package = "otel" - ) - local_mocked_bindings( - testthat__is_testing = function() FALSE, - ) - - # First call to with_otel_span - with_otel_span("span1", { "result1" }) - expect_equal(get_tracer_call_count, 1) - - # Second call should use cached tracer - with_otel_span("span2", { "result2" }) - expect_equal(get_tracer_call_count, 1) # Still 1, tracer was cached -}) test_that("integration test - start_otel_span with custom parameters", { mock_tracer <- create_mock_tracer()