Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

A collection of minor test style improvements #192

Merged
merged 6 commits into from
Aug 18, 2024
Merged

A collection of minor test style improvements #192

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
5e7e9d0
WS + move eval_outside to helpers
hadley Aug 8, 2024
2ed62f5
Skip test on CRAN
hadley Aug 8, 2024
e087acd
Remove package loading
hadley Aug 8, 2024
4b315e6
Make tests self-contained
hadley Aug 8, 2024
2de83f1
More test tidying
hadley Aug 8, 2024
c061bc6
Fix buglet
hadley Aug 8, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
17 changes: 17 additions & 0 deletions tests/testthat/helper.R
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -18,3 +18,20 @@ local_test_logger <- function(threshold = INFO,
withr::defer(namespaces[[namespace]] <- old, frame)
invisible()
}

eval_outside <- function(...) {
input <- normalizePath(withr::local_tempfile(lines = character()), winslash = "/")
output <- normalizePath(withr::local_tempfile(lines = character()), winslash = "/")
writeLines(con = input, c(
"library(logger)",
"log_layout(layout_glue_generator('{level} {msg}'))",
paste0("log_appender(appender_file('", output, "'))"),
...
))
path <- file.path(R.home("bin"), "Rscript")
if (Sys.info()[["sysname"]] == "Windows") {
path <- paste0(path, ".exe")
}
suppressWarnings(system2(path, input, stdout = TRUE, stderr = TRUE))
readLines(output)
}
2 changes: 2 additions & 0 deletions tests/testthat/test-CRANSKIP-appenders.R
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,4 +1,6 @@
test_that("async logging", {
skip_on_cran()

t <- withr::local_tempfile()
local_test_logger(
layout = layout_blank,
Expand Down
3 changes: 0 additions & 3 deletions tests/testthat/test-CRANSKIP-helpers.R
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,6 +1,3 @@
library(logger)
library(testthat)

test_that("tictoc", {
expect_match(capture.output(log_tictoc(), type = "message"), "timer tic 0 secs")
## let time pass a bit
Expand Down
97 changes: 38 additions & 59 deletions tests/testthat/test-CRANSKIP-hooks.R
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,20 +1,3 @@
eval_outside <- function(...) {
input <- normalizePath(withr::local_tempfile(lines = character()), winslash = "/")
output <- normalizePath(withr::local_tempfile(lines = character()), winslash = "/")
writeLines(con = input, c(
"library(logger)",
"log_layout(layout_glue_generator('{level} {msg}'))",
paste0("log_appender(appender_file('", output, "'))"),
...
))
path <- file.path(R.home("bin"), "Rscript")
if (Sys.info()[["sysname"]] == "Windows") {
path <- paste0(path, ".exe")
}
suppressWarnings(system2(path, input, stdout = TRUE, stderr = TRUE))
readLines(output)
}

test_that("log_messages", {
expect_snapshot({
writeLines(eval_outside("log_messages()", "message(42)"))
Expand All @@ -36,59 +19,55 @@ test_that("log_errors", {
})

test_that("shiny input initialization is detected", {
obs <-
eval_outside("
.globals <- shiny:::.globals
.globals$appState <- new.env(parent = emptyenv())
server <- function(input, output, session) {
logger::log_shiny_input_changes(input)
}
shiny::testServer(server, {})
")
obs <- eval_outside("
.globals <- shiny:::.globals
.globals$appState <- new.env(parent = emptyenv())
server <- function(input, output, session) {
logger::log_shiny_input_changes(input)
}
shiny::testServer(server, {})
")
expect_snapshot(writeLines(obs))
})

test_that("shiny input initialization is detected with different log-level", {
obs <-
eval_outside("
.globals <- shiny:::.globals
.globals$appState <- new.env(parent = emptyenv())
server <- function(input, output, session) {
logger::log_shiny_input_changes(input, level = logger::ERROR)
}
shiny::testServer(server, {})
")
obs <- eval_outside("
.globals <- shiny:::.globals
.globals$appState <- new.env(parent = emptyenv())
server <- function(input, output, session) {
logger::log_shiny_input_changes(input, level = logger::ERROR)
}
shiny::testServer(server, {})
")
expect_snapshot(writeLines(obs))
})

test_that("shiny input change is detected", {
obs <-
eval_outside("
.globals <- shiny:::.globals
.globals$appState <- new.env(parent = emptyenv())
server <- function(input, output, session) {
logger::log_shiny_input_changes(input)
x <- shiny::reactive(input$a)
}
shiny::testServer(server, {
session$setInputs(a = 2)
})
")
obs <- eval_outside("
.globals <- shiny:::.globals
.globals$appState <- new.env(parent = emptyenv())
server <- function(input, output, session) {
logger::log_shiny_input_changes(input)
x <- shiny::reactive(input$a)
}
shiny::testServer(server, {
session$setInputs(a = 2)
})
")
expect_snapshot(writeLines(obs))
})

test_that("shiny input change is logged with different level", {
obs <-
eval_outside("
.globals <- shiny:::.globals
.globals$appState <- new.env(parent = emptyenv())
server <- function(input, output, session) {
logger::log_shiny_input_changes(input, level = logger::ERROR)
x <- shiny::reactive(input$a)
}
shiny::testServer(server, {
session$setInputs(a = 2)
})
")
obs <- eval_outside("
.globals <- shiny:::.globals
.globals$appState <- new.env(parent = emptyenv())
server <- function(input, output, session) {
logger::log_shiny_input_changes(input, level = logger::ERROR)
x <- shiny::reactive(input$a)
}
shiny::testServer(server, {
session$setInputs(a = 2)
})
")
expect_snapshot(writeLines(obs))
})
62 changes: 29 additions & 33 deletions tests/testthat/test-formatters.R
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,13 +1,6 @@
everything <- 42
g <- function() {
log_info("Hi {everything}")
}
f <- function() {
log_info("Hi %s", everything)
}

test_that("glue works", {
local_test_logger(formatter = formatter_glue)
a <- 43

Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

so what's the meaning of 43? 😅

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Haha, I just changed it because I think it's good to use a different value than 42 to hint that we're testing a different mechanism. And while it doesn't really apply here, there's always some risk to reusing the same test value too many times, because it won't catch bugs where the previous value bleeds through to the next expectation.

expect_equal(formatter_glue("Hi"), "Hi")
expect_equal(formatter_glue(" Hi"), " Hi")
Expand All @@ -16,15 +9,16 @@ test_that("glue works", {
expect_equal(formatter_glue("pi is {round(pi, 2)}"), "pi is 3.14")
expect_equal(formatter_glue("Hi {42}"), "Hi 42")
expect_equal(formatter_glue("Hi {a}", a = 42), "Hi 42")
expect_equal(formatter_glue("Hi {everything}"), "Hi 42")
expect_equal(formatter_glue("Hi {1:2}"), paste("Hi", 1:2))

expect_output(do.call(logger, namespaces$global[[1]])(INFO, 42), "42")
expect_output(do.call(logger, namespaces$global[[1]])(INFO, "Hi {everything}"), "42")
expect_output(do.call(logger, namespaces$global[[1]])(INFO, "Hi {a}"), "43")

expect_output(log_info("Hi {everything}"), "42")
expect_output(log_warn("Hi {everything}"), "42")
expect_output(g(), "42")
expect_equal(formatter_glue("Hi {a}"), "Hi 43")
expect_output(log_info("Hi {a}"), "43")
expect_output(log_warn("Hi {a}"), "43")
f <- function() log_info("Hi {a}")
expect_output(f(), "43")

local_test_logger(
formatter = formatter_glue,
Expand Down Expand Up @@ -52,11 +46,13 @@ test_that("glue_safe works", {
expect_equal(formatter_glue_safe("Hi"), "Hi")
expect_equal(formatter_glue_safe(" Hi"), " Hi")
expect_equal(formatter_glue_safe("Hi {a}", a = 42), "Hi 42")
expect_equal(formatter_glue_safe("Hi {everything}"), "Hi 42")

expect_output(log_info("Hi {everything}"), "42")
expect_output(log_warn("Hi {everything}"), "42")
expect_output(g(), "42")
a <- 43
expect_equal(formatter_glue_safe("Hi {a}"), "Hi 43")
expect_output(log_info("Hi {a}"), "43")
expect_output(log_warn("Hi {a}"), "43")
f <- function() log_info("Hi {a}")
expect_output(f(), "43")

expect_error(formatter_glue_safe("Hi {42}"))
expect_error(formatter_glue_safe("malformed {"))
Expand All @@ -68,7 +64,6 @@ test_that("sprintf works", {

expect_equal(formatter_sprintf("Hi"), "Hi")
expect_equal(formatter_sprintf("Hi %s", 42), "Hi 42")
expect_equal(formatter_sprintf("Hi %s", everything), "Hi 42")
expect_equal(formatter_sprintf("Hi %s", 1:2), paste("Hi", 1:2))
expect_equal(formatter_sprintf("1 + %s", 1), "1 + 1")
expect_equal(formatter_sprintf("=>%2i", 2), "=> 2")
Expand All @@ -79,17 +74,20 @@ test_that("sprintf works", {
expect_error(formatter_sprintf("%s and %i", 1))
expect_equal(formatter_sprintf("%s and %i", 1, 2), "1 and 2")

expect_output(log_info("Hi %s", everything), "42")
expect_output(f(), "42")
a <- 43
expect_output(log_info("Hi %s", a), "43")
expect_equal(formatter_sprintf("Hi %s", a), "Hi 43")
f <- function() log_info("Hi %s", a)
expect_output(f(), "43")
})


result <- c(
"Hi foo, did you know that 2*4=8?",
"Hi bar, did you know that 2*4=8?"
)

test_that("glue+sprintf works", {
result <- c(
"Hi foo, did you know that 2*4=8?",
"Hi bar, did you know that 2*4=8?"
)

expect_equal(formatter_glue_or_sprintf("Hi ", "{c('foo', 'bar')}, did you know that 2*4={2*4}?"), result)
expect_equal(formatter_glue_or_sprintf("Hi {c('foo', 'bar')}, did you know that 2*4={2*4}?"), result)
expect_equal(formatter_glue_or_sprintf("Hi {c('foo', 'bar')}, did you know that 2*4=%s?", 2 * 4), result)
Expand Down Expand Up @@ -125,12 +123,14 @@ test_that("formatter_logging works", {
})

test_that("special chars in the text work", {
expect_equal(formatter_glue("JSON: {jsonlite::toJSON(1:4)}"), "JSON: [1,2,3,4]")
expect_equal(formatter_glue("JSON: {jsonlite::toJSON(iris[1:2, ], auto_unbox = TRUE)}"), 'JSON: [{"Sepal.Length":5.1,"Sepal.Width":3.5,"Petal.Length":1.4,"Petal.Width":0.2,"Species":"setosa"},{"Sepal.Length":4.9,"Sepal.Width":3,"Petal.Length":1.4,"Petal.Width":0.2,"Species":"setosa"}]') # nolint
array <- "[1, 2, 3, 4]"
object <- '{"x": 1, "y": 2}'
expect_equal(formatter_glue("JSON: {array}"), paste0("JSON: ", array))
expect_equal(formatter_glue("JSON: {object}"), paste0("JSON: ", object))

local_test_logger()
expect_output(log_info("JSON: {jsonlite::toJSON(1:4)}"), "[1,2,3,4]")
expect_output(log_info("JSON: {jsonlite::toJSON(iris[1:2, ], auto_unbox = TRUE)}"), '[{"Sepal.Length":5.1,"Sepal.Width":3.5,"Petal.Length":1.4,"Petal.Width":0.2,"Species":"setosa"},{"Sepal.Length":4.9,"Sepal.Width":3,"Petal.Length":1.4,"Petal.Width":0.2,"Species":"setosa"}]') # nolint
expect_output(log_info("JSON: {array}"), paste0("JSON: ", array), fixed = TRUE)
expect_output(log_info("JSON: {object}"), paste0("JSON: ", object), fixed = TRUE)
})

test_that("pander formatter", {
Expand All @@ -144,10 +144,6 @@ test_that("pander formatter", {
expect_output(log_info(lm(hp ~ wt, mtcars)), "Fitting linear model")
})

## cleanup
rm(everything)
rm(f)

test_that("paste formatter in actual logs", {
local_test_logger(formatter = formatter_paste)
expect_output(log_info("hi", 5), "hi 5")
Expand Down
36 changes: 10 additions & 26 deletions tests/testthat/test-layout.R
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -13,41 +13,25 @@ test_that("colorized layout", {
})

test_that("metavars", {
local_test_logger(layout = layout_glue_generator("{level} {ans} {fn} {msg}"))
expect_output((function() {
log_info(42)
})(), "INFO")
expect_output((function() {
log_warn(42)
})(), "WARN")
expect_output((function() {
log_info(42)
})(), "log_info")
local_test_logger(layout = layout_glue_generator("{level} {ans} {fn}"))

local_test_logger(layout = layout_glue_generator("{fn}"))
expect_output(
{
fun42 <- function() {
log_info(42)
}
fun42()
rm(fun42)
},
"fun42"
)
f_info <- function() log_info()
expect_output(f_info(), "INFO global f_info()")

f_warn <- function() log_warn()
expect_output(f_warn(), "WARN global f_warn()")
})

test_that("JSON layout", {
local_test_logger(layout = layout_json())
local_test_logger(layout = layout_json(fields = c("level", "msg")))

expect_equal(jsonlite::fromJSON(capture.output(log_info("foobar")))$level, "INFO")
expect_equal(jsonlite::fromJSON(capture.output(log_info("foobar")))$msg, "foobar")
out <- jsonlite::fromJSON(capture.output(log_info("foobar")))
expect_equal(out, list(level = "INFO", msg = "foobar"))
})

test_that("JSON parser layout", {
local_test_logger(layout = layout_json_parser(fields = c()))
expect_output(log_info(skip_formatter('{"x": 4}')), '\\{"x":4\\}')
expect_equal(capture.output(log_info(skip_formatter('{"x": 4}'))), '{"x":4}')
expect_output(log_info(skip_formatter('{"x": 4}')), '{"x":4}', fixed = TRUE)
})

test_that("must throw errors", {
Expand Down
3 changes: 1 addition & 2 deletions tests/testthat/test-logger.R
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -127,7 +127,7 @@ test_that("print.level", {
test_that("config setter called from do.call", {
local_test_logger()

t <- tempfile()
t <- withr::local_tempfile()
expect_error(do.call(log_appender, list(appender_file(t))), NA)
log_info(42)
expect_length(readLines(t), 1)
Expand All @@ -140,7 +140,6 @@ test_that("config setter called from do.call", {
expect_error(do.call(log_layout, list(formatter_paste)), NA)
log_info(42)
expect_length(readLines(t), 3)
unlink(t)
})

test_that("providing log_level() args to wrappers diretly is OK", {
Expand Down
9 changes: 3 additions & 6 deletions tests/testthat/test-utils.R
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -16,10 +16,7 @@ test_that("catch_base_log", {
local_test_logger(layout = layout_blank)
expect_true(nchar(catch_base_log(INFO, NA_character_)) == 0)

local_test_logger(
layout = layout_glue_generator(format = "{namespace}/{fn} {level}: {msg}"),
namespace = "TEMP"
)
expect_true(nchar(catch_base_log(INFO, "TEMP", .topcall = NA)) == 14)
expect_true(nchar(catch_base_log(INFO, "TEMP", .topcall = call("5char"))) == 17)
local_test_logger(layout = layout_glue_generator(format = "{namespace}/{fn}"))
expect_equal(catch_base_log(INFO, "TEMP", .topcall = NA), "global/NA")
expect_equal(catch_base_log(INFO, "TEMP", .topcall = quote(f())), "global/f")
})
Loading