refactor(otel): Cache tracer and logger on init and on demand (#4315)

Co-authored-by: Charlie Gao <53399081+shikokuchuo@users.noreply.github.com>

Author: schloerke

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
-  }
-})

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
-}

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)
       })

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()

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)
     })

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()