tests/testthat/test-Logger.R

In SCDB: Easily Access and Maintain Time-Based Versioned Data (Slowly-Changing-Dimension)

# Ensure the options that can be set are NULL for these tests
withr::local_options("SCDB.log_table_id" = NULL, "SCDB.log_path" = NULL)

test_that("Logger: logging to console works", {

  # Create logger and test configuration
  expect_warning(
    logger <- Logger$new(),                                                                                             # nolint: implicit_assignment_linter
    regexp = "NO file or database logging will be done."
  )
  expect_null(logger$log_path)
  expect_null(logger$log_tbl)

  # Test logging to console has the right formatting and message type
  ts_str <- format(logger$start_time, "%F %R:%OS3")
  expect_message(
    logger$log_info("test console", tic = logger$start_time),
    glue::glue("{ts_str} - {Sys.info()[['user']]} - INFO - test console")
  )
  expect_warning(
    logger$log_warn("test console", tic = logger$start_time),
    glue::glue("{ts_str} - {Sys.info()[['user']]} - WARNING - test console")
  )
  expect_error(
    logger$log_error("test console", tic = logger$start_time),
    glue::glue("{ts_str} - {Sys.info()[['user']]} - ERROR - test console")
  )

  # Clean up
  rm(logger)
  invisible(gc())
})


test_that("Logger: all (non-warning, non-error) logging to console can be disabled", {

  # Create logger
  expect_warning(
    logger <- Logger$new(output_to_console = FALSE),                                                                    # nolint: implicit_assignment_linter
    regexp = "NO file or database logging will be done."
  )

  # Test INFO-logging to console is disabled
  ts_str <- format(logger$start_time, "%F %R:%OS3")
  expect_no_message(logger$log_info("test", tic = logger$start_time))

  # Clean up
  rm(logger)
  invisible(gc())
})


test_that("Logger: logging to file works", {

  # Set options for the test
  log_path <- tempdir(check = TRUE)
  db_table <- "test.SCDB_logger"


  # Create logger and test configuration
  # Empty logger should use default value from options
  withr::with_options(
    list("SCDB.log_path" = "local/path"),
    {
      logger <- Logger$new(db_table = db_table, warn = FALSE)
      expect_equal(logger$log_path, "local/path")

      rm(logger)
      invisible(gc())
    }
  )

  # Create logger and test configuration
  # Test file logging - with character timestamp
  timestamp <- "2022-01-01 09:00:00"
  logger <- Logger$new(
    db_table = db_table,
    timestamp = timestamp,
    log_path = log_path,
    output_to_console = FALSE,
    warn = FALSE
  )

  expect_equal(logger$log_path, log_path)
  expect_equal(
    logger$log_filename,
    glue::glue("{format(logger$start_time, '%Y%m%d.%H%M')}.",
               "{format(as.POSIXct(timestamp), '%Y_%m_%d')}.",
               "{db_table}.log")
  )


  # Test logging to file has the right formatting and message type
  logger$log_info("test filewriting", tic = logger$start_time)
  tryCatch(logger$log_warn("test filewriting", tic = logger$start_time), warning = \(w) NULL)
  tryCatch(logger$log_error("test filewriting", tic = logger$start_time), error = \(e) NULL)

  ts_str <- format(logger$start_time, "%F %R:%OS3")
  expect_true(logger$log_filename %in% dir(log_path))
  expect_equal(
    readLines(logger$log_realpath),
    c(
      glue::glue("{ts_str} - {Sys.info()[['user']]} - INFO - test filewriting"),
      glue::glue("{ts_str} - {Sys.info()[['user']]} - WARNING - test filewriting"),
      glue::glue("{ts_str} - {Sys.info()[['user']]} - ERROR - test filewriting")
    )
  )

  file.remove(logger$log_realpath)
  rm(logger)
  invisible(gc())


  # Create logger and test configuration
  # Test file logging - with POSIX timestamp
  timestamp <- as.POSIXct("2022-02-01 09:00:00")
  logger <- Logger$new(
    db_table = db_table,
    timestamp = timestamp,
    log_path = log_path,
    output_to_console = FALSE,
    warn = FALSE
  )

  expect_equal(logger$log_path, log_path)
  expect_equal(
    logger$log_filename,
    glue::glue("{format(logger$start_time, '%Y%m%d.%H%M')}.",
               "{format(as.POSIXct(timestamp), '%Y_%m_%d')}.",
               "{db_table}.log")
  )


  # Test logging to file still works
  logger$log_info("test filewriting", tic = logger$start_time)

  ts_str <- format(logger$start_time, "%F %R:%OS3")
  expect_true(logger$log_filename %in% dir(log_path))
  expect_equal(
    readLines(logger$log_realpath),
    glue::glue(
      "{ts_str} - {Sys.info()[['user']]} - INFO - test filewriting"
    )
  )

  # Clean up
  file.remove(logger$log_realpath)
  rm(logger)
  invisible(gc())
})


test_that("Logger: log_tbl is not set when conn = NULL", {

  # Set options for the test
  db_table <- "test.SCDB_logger"
  timestamp <- "2022-03-01 09:00:00"

  # Create logger and test configuration
  # Empty logger should use default value
  logger <- Logger$new(db_table = db_table, timestamp = timestamp, warn = FALSE)
  expect_null(logger$log_tbl) # log_table_id is NOT defined here, despite the option existing
  # the logger does not have the connection, so cannot pull the table from conn

  # Clean up
  rm(logger)
  invisible(gc())
})


test_that("Logger: logging to database works", {
  for (conn in get_test_conns()) {

    # Set options for the test
    db_table <- "test.SCDB_logger"
    timestamp <- "2022-04-01 09:00:00"

    # Create logger and test configuration
    logger <- Logger$new(db_table = db_table,
                         timestamp = timestamp,
                         log_table_id = db_table,
                         log_conn = conn,
                         warn = FALSE)

    log_table_id <- dplyr::tbl(conn, id(db_table, conn))
    expect_equal(logger$log_tbl, log_table_id)


    # Test Logger has pre-filled some information in the logs
    db_table_id <- id(db_table, conn)
    expect_identical(as.character(dplyr::pull(log_table_id, "date")), timestamp)
    if ("catalog" %in% purrr::pluck(db_table_id, "name", names)) {
      expect_identical(dplyr::pull(log_table_id, "catalog"), purrr::pluck(db_table_id, "name", "catalog"))
    }
    expect_identical(dplyr::pull(log_table_id, "schema"), purrr::pluck(db_table_id, "name", "schema"))
    expect_identical(dplyr::pull(log_table_id, "table"), purrr::pluck(db_table_id, "name", "table"))
    expect_identical( # Transferring start_time to database can have some loss of information that we need to match
      format(as.POSIXct(dplyr::pull(log_table_id, "start_time")), "%F %R:%S"),
      format(logger$start_time, "%F %R:%S")
    )


    # Test logging to database writes to the correct fields
    logger$log_to_db(n_insertions = 42)
    expect_equal(nrow(log_table_id), 1)
    expect_equal(dplyr::pull(log_table_id, "n_insertions"), 42)

    logger$log_to_db(n_deactivations = 60)
    expect_equal(nrow(log_table_id), 1)
    expect_equal(dplyr::pull(log_table_id, "n_deactivations"), 60)


    # Clean up
    rm(logger)
    invisible(gc())

    connection_clean_up(conn)
  }
})


test_that("Logger: all logging simultaneously works", {
  for (conn in get_test_conns()) {

    # Set options for the test
    log_path <- tempdir(check = TRUE)
    db_table <- "test.SCDB_logger"
    timestamp <- "2022-05-01 09:00:00"

    # Create logger and test configuration
    logger <- Logger$new(db_table = db_table, timestamp = timestamp, log_path = log_path,
                         log_table_id = db_table, log_conn = conn, warn = FALSE)

    log_table_id <- dplyr::tbl(conn, id(db_table, conn))
    expect_equal(logger$log_path, log_path)
    expect_equal(logger$log_tbl, log_table_id)
    expect_equal(
      logger$log_filename,
      glue::glue("{format(logger$start_time, '%Y%m%d.%H%M')}.",
                 "{format(as.POSIXct(timestamp), '%Y_%m_%d')}.",
                 "{id(db_table, conn)}.log")
    )

    # Test logging to console has the right formatting and message type
    ts_str <- format(logger$start_time, "%F %R:%OS3")
    expect_message(
      logger$log_info("test console and filewriting", tic = logger$start_time),
      glue::glue("{ts_str} - {Sys.info()[['user']]} - INFO - test console and filewriting")
    )
    expect_warning(
      logger$log_warn("test console and filewriting", tic = logger$start_time),
      glue::glue("{ts_str} - {Sys.info()[['user']]} - WARNING - test console and filewriting")
    )
    expect_error(
      logger$log_error("test console and filewriting", tic = logger$start_time),
      glue::glue("{ts_str} - {Sys.info()[['user']]} - ERROR - test console and filewriting")
    )


    # Test logging to file has the right formatting and message type
    expect_true(logger$log_filename %in% dir(log_path))
    expect_equal(
      readLines(logger$log_realpath),
      c(
        glue::glue("{ts_str} - {Sys.info()[['user']]} - INFO - test console and filewriting"),
        glue::glue("{ts_str} - {Sys.info()[['user']]} - WARNING - test console and filewriting"),
        glue::glue("{ts_str} - {Sys.info()[['user']]} - ERROR - test console and filewriting")
      )
    )


    # Test logging to database writes to the correct fields
    logger$log_to_db(n_insertions = 13)
    expect_equal(nrow(log_table_id), 2)
    expect_equal(dplyr::pull(log_table_id, "n_insertions"), c(42, 13))

    logger$log_to_db(n_deactivations = 37)
    expect_equal(nrow(log_table_id), 2)
    expect_equal(dplyr::pull(log_table_id, "n_deactivations"), c(60, 37))


    # Clean up
    file.remove(logger$log_realpath)
    rm(logger)
    invisible(gc())

    connection_clean_up(conn)
  }
})


test_that("Logger: file logging stops if file exists", {

  # Set options for the test
  log_path <- tempdir(check = TRUE)
  db_table <- "test.SCDB_logger"
  timestamp <- Sys.time()

  # Create logger1 and logger2 which uses the same file
  # Since start_time is the same for both
  logger1 <- Logger$new(
    db_table = db_table,
    timestamp = timestamp,
    start_time = timestamp,
    log_path = log_path,
    output_to_console = FALSE
  )

  logger2 <- Logger$new(
    db_table = db_table,
    timestamp = timestamp,
    start_time = timestamp,
    log_path = log_path,
    output_to_console = FALSE
  )


  # logger1 should be able to successfully write
  logger1$log_info("test message")


  # whereas logger2 should fail since the log file now exists
  expect_error(
    logger2$log_info("test message"),
    glue::glue("Log file '{logger1$log_filename}' already exists!")
  )

  # .. and it should do it persistently
  expect_error(
    logger2$log_info("test message"),
    glue::glue("Log file '{logger1$log_filename}' already exists!")
  )

  # Clean up
  file.remove(logger1$log_realpath)
  rm(logger1, logger2)
  invisible(gc())
})


test_that("Logger: console output may be disabled", {

  # First test cases with output_to_console == FALSE
  # Here, only print when explicitly stated
  expect_warning(
    logger <- Logger$new(output_to_console = FALSE),                                                                    # nolint: implicit_assignment_linter
    regexp = "NO file or database logging will be done."
  )

  expect_no_message(logger$log_info("Whoops! This should not have been printed!"))

  expect_no_message(logger$log_info("Whoops! This should not have been printed either!", output_to_console = FALSE))

  expect_message(
    logger$log_info("This line should be printed", output_to_console = TRUE),
    "This line should be printed"
  )

  rm(logger)

  # ...and now, only suppress printing when explicitly stated
  expect_warning(
    logger <- Logger$new(output_to_console = TRUE),                                                                     # nolint: implicit_assignment_linter
    regexp = "NO file or database logging will be done."
  )

  expect_message(
    logger$log_info("This line should be printed"),
    "This line should be printed"
  )
  expect_message(
    logger$log_info("This line should also be printed", output_to_console = TRUE),
    "This line should also be printed"
  )

  expect_no_message(logger$log_info("Whoops! This should not have been printed at all!", output_to_console = FALSE))
})


test_that("Logger: log_file is NULL in database if not writing to file", {
  for (conn in get_test_conns()) {

    # Set options for the test
    db_table <- "test.SCDB_logger"
    timestamp <- "2022-06-01 09:00:00"

    # Create logger and test configuration
    logger <- Logger$new(db_table = db_table, timestamp = timestamp, log_conn = conn, log_table_id = "test.SCDB_logger")

    # While logger is active, log_file should be set as the random generated
    db_log_file <- dplyr::pull(dplyr::filter(logger$log_tbl, log_file == !!logger$log_filename))
    expect_length(db_log_file, 1)
    expect_match(db_log_file, "^.+$")

    # When finalising, log_file should be set to NULL
    logger$finalize()

    db_log_file <- dplyr::pull(dplyr::filter(logger$log_tbl, log_file == !!logger$log_filename))
    expect_length(db_log_file, 0)

    # Test that an error is thrown if the database record has been finalized
    expect_error(
      logger$log_to_db(message = "This should produce an error"),
      r"{Logger has already been finalized\. Cannot write to database log table\.}"
    )


    # Clean up
    rm(logger)
    invisible(gc())

    connection_clean_up(conn)
  }
})


test_that("Logger: $finalize() handles log table is at some point deleted", {
  for (conn in get_test_conns()) {

    # Set options for the test
    db_table <- "test.SCDB_logger"
    timestamp <- "2022-06-01 09:00:00"

    log_table_id <- "expendable_log_table"
    logger <- Logger$new(db_table = db_table, timestamp = timestamp, log_conn = conn, log_table_id = log_table_id)

    DBI::dbRemoveTable(conn, id(log_table_id, conn))

    expect_no_error(logger$log_to_db(n_insertions = 42))

    expect_no_error(logger$finalize())

    # Clean up
    rm(logger)
    invisible(gc())

    connection_clean_up(conn)
  }
})

test_that("Logger: custom timestamp_format works", {

  # Create logger and test configuration
  expect_warning(
    logger <- Logger$new(),                                                                                             # nolint: implicit_assignment_linter
    regexp = "NO file or database logging will be done."
  )

  # Test logging to console has the right formatting and message type
  ts_str <- format(logger$start_time, "%F %R:%OS3")
  expect_message(
    logger$log_info("test console", tic = logger$start_time),
    glue::glue("{ts_str} - {Sys.info()[['user']]} - INFO - test console")
  )

  ts_str <- format(logger$start_time, "%F %R")
  expect_message(
    logger$log_info("test console", tic = logger$start_time, timestamp_format = "%F %R"),
    glue::glue("{ts_str} - {Sys.info()[['user']]} - INFO - test console")
  )

  ts_str <- format(logger$start_time, "%F")
  withr::local_options("SCDB.log_timestamp_format" = "%F")
  expect_message(
    logger$log_info("test console", tic = logger$start_time),
    glue::glue("{ts_str} - {Sys.info()[['user']]} - INFO - test console")
  )

  # Clean up
  rm(logger)
  invisible(gc())
})


test_that("LoggerNull: no console logging occurs", {

  # Create logger and test configuration
  logger <- expect_no_message(LoggerNull$new())

  ts_str <- format(logger$start_time, "%F %R:%OS3")
  expect_no_message(logger$log_info("test console", tic = logger$start_time))

  # Test logging to console has the right formatting and message type
  ts_str <- format(logger$start_time, "%F %R:%OS3")
  expect_no_message(
    logger$log_info("test console", tic = logger$start_time)
  )
  expect_warning(
    logger$log_warn("test console", tic = logger$start_time),
    glue::glue("{ts_str} - {Sys.info()[['user']]} - WARNING - test console")
  )
  expect_error(
    logger$log_error("test console", tic = logger$start_time),
    glue::glue("{ts_str} - {Sys.info()[['user']]} - ERROR - test console")
  )

  # Clean up
  rm(logger)
  invisible(gc())
})


test_that("LoggerNull: no file logging occurs", {
  withr::local_options("SCDB.log_path" = tempdir())

  # Create logger and test configuration
  logger <- expect_no_message(LoggerNull$new())

  expect_no_message(logger$log_info("test filewriting", tic = logger$start_time))
  expect_false(logger$log_filename %in% dir(getOption("SCDB.log_path")))

  # Clean up
  rm(logger)
  invisible(gc())
})


test_that("LoggerNull: no database logging occurs", {
  for (conn in get_test_conns()) {

    # Set options for the test
    db_table <- "test.SCDB_logger"
    timestamp <- "2022-06-01 09:00:00"

    # Count entries in log
    n_log_entries <- nrow(dplyr::tbl(conn, id("test.SCDB_logger", conn)))

    # Create LoggerNull and test configuration
    logger <- LoggerNull$new(
      db_table = db_table, timestamp = timestamp,
      log_conn = conn, log_table_id = "test.SCDB_logger"
    )

    expect_no_message(logger$log_to_db(n_insertions = 42))
    expect_no_message(logger$finalize_db_entry())
    expect_identical(nrow(dplyr::tbl(conn, id("test.SCDB_logger", conn))), n_log_entries)

    # Clean up
    rm(logger)
    invisible(gc())

    close_connection(conn)
  }
})