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

Co-authored-by: Charlie Gao <53399081+shikokuchuo@users.noreply.github.com>
This commit is contained in:
Barret Schloerke
2025-11-11 08:44:57 -05:00
committed by GitHub
parent 472a1cdba1
commit e3cf4fb089
6 changed files with 68 additions and 253 deletions

View File

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

View File

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

View File

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

View File

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

View File

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

View File

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