Merge pull request #115 from pbchase/specify_objects_in_unnest_job_su…

…mmary_data_json_object

Add objects_to_include param to unnest_job_summary_data_json_object()

R/unnest_job_summary_data_json_object.R

@@ -7,13 +7,19 @@
 #' frames into a JSON object, so this has become the common practice.
 #'
 #' Yet using the data can be a bit more complex because `jsonlite::fromJSON` is
-#' not vectorized. If you need read multiple job log records, iteration is
+#' not vectorized. If you need to read multiple job log records, iteration is
 #' required to use JSON object in `job_summary_data`.
 #'
 #' This function addresses that need accepting a dataframe of job summary logs
-#' and unnesting the JSON object(s) in `job_summary_data` into the equivalent R objects.
+#' and unnesting the JSON object(s) in `job_summary_data` into the equivalent
+#' R objects.
+#'
+#' Use `objects_to_include` to limit the unnested objects to those with similar
+#' geometry. Dissimilar objects cannot be unnested together.
 #'
 #' @param log_data - a dataframe of job summary logs
+#' @param objects_to_include - an optional vector of JSON objects in the
+#'   job_summary_data to be un-nested
 #'
 #' @return - the input dataframe of job summary logs with `job_summary_data`
 #'   replaced by the R objects that were JSON-encoded therein.
@@ -32,18 +38,40 @@
 #' log_conn <- get_package_scope_var("log_con")
 #'
 #' log_data <- tbl(log_conn, "rcc_job_log") %>%
-#'   dplyr::filter(script_name == "warn_owners_of_impending_bill") %>%
+#'   dplyr::filter(script_name == "warn_owners_of_impending_bill") |>
 #'   collect()
 #'
 #' unnest_job_summary_data_json_object(log_data)
+#'
+#' # Read a more complex object
+#' log_data_2 <- tbl(log_conn, "rcc_job_log") |>
+#'   dplyr::filter(
+#'     script_name == "create_and_send_new_redcap_prod_per_project_line_items" &
+#'       level == "SUCCESS"
+#'   ) %>%
+#'   collect()
+#'
+#' # Fails due to dissimilar objects
+#' unnest_job_summary_data_json_object(log_data_2)
+#' # error is "Can't recycle `service_instance` (size 27) to match `invoice_line_item` (size 79)."
+#'
+#' # When separated, the objects can be unnested
+#' unnest_job_summary_data_json_object(log_data_2, objects_to_include = c("service_instance"))
+#' unnest_job_summary_data_json_object(log_data_2, objects_to_include = c("invoice_line_item"))
 #' }
-unnest_job_summary_data_json_object <- function(log_data) {
+unnest_job_summary_data_json_object <- function(log_data, objects_to_include = NA) {
   log_ids <- log_data$id
   names(log_ids) <- log_ids
 
-  result <- purrr::map2_dfr(log_ids, log_data$job_summary_data, ~ jsonlite::fromJSON(.y), .id = "id") %>%
-    dplyr::mutate(id = as.integer(.data$id)) %>%
-    dplyr::left_join(log_data %>% dplyr::select(-"job_summary_data"), by = "id")
+  if (is.na(objects_to_include[1]) & length(objects_to_include) == 1) {
+    result <- purrr::map2_dfr(log_ids, log_data$job_summary_data, ~ jsonlite::fromJSON(.y), .id = "id") %>%
+      dplyr::mutate(id = as.integer(.data$id)) %>%
+      dplyr::left_join(log_data %>% dplyr::select(-"job_summary_data"), by = "id")
+  } else {
+    result <- purrr::map2_dfr(log_ids, log_data$job_summary_data, ~ jsonlite::fromJSON(.y)[objects_to_include], .id = "id") %>%
+      dplyr::mutate(id = as.integer(.data$id)) %>%
+      dplyr::left_join(log_data %>% dplyr::select(-"job_summary_data"), by = "id")
+  }
 
   return(result)
 }

tests/testthat/test-unnest_job_summary_data_json_object.R

@@ -2,21 +2,21 @@ testthat::test_that("unnest_job_summary_data_json_object works", {
   test_data_dir <- "unnest_job_summary_data_json_object"
   log_data <- readRDS(testthat::test_path(test_data_dir, "log_data.rds"))
 
-  sample_size <- 3
-  ncols_in_unnested_data <- 3
+  ncols_in_unnested_data <- 5
 
-  output <- unnest_job_summary_data_json_object(log_data)
+  output <- unnest_job_summary_data_json_object(log_data, objects_to_include = "iris")
 
   testthat::expect_equal(
     output %>%
       dplyr::distinct(id) %>%
       nrow(),
-    sample_size
+    1
     )
 
   testthat::expect_equal(
     output %>%
       dplyr::select(-dplyr::any_of(names(log_data))) %>%
+      pull(iris) %>%
       ncol(),
     ncols_in_unnested_data
   )

tests/testthat/unnest_job_summary_data_json_object/make_test_data.R

@@ -5,35 +5,31 @@ library(lubridate)
 library(dotenv)
 
 # unnest_job_summary_data_json_object/make_test_data.R
-# This script is designed to extract a sample of records from a redcapcustodian log table
-# cycle from each of the 9 redcap_log_event tables.
 #
-# Create a .env file according to the specs of
-# redcapcustodian::connect_to_redcap_db with credentials. Save it at the root
-# of this R Project.
+# Create a .env file according to the specs of redcapcustodian
+# Assure it defines a log database.
+# Save it at the root of this R Project.
 #
-# The redcap system read should be reasonably complex so that the returned
-# data is similarly complex.
-#
-# With that in mind, you can run
 library(redcapcustodian)
 library(RMariaDB)
 library(DBI)
 library(tidyverse)
 library(dotenv)
-load_dot_env("../rcc.billing/prod.env")
+load_dot_env(".env")
+
+init_etl("test_unnest")
 
-init_etl("pbc_scratch")
+# Write some log data for us to read back
+log_list <- lst(mtcars, iris)
+log_job_success(jsonlite::toJSON(log_list))
 
 log_conn <- get_package_scope_var("log_con")
 
 test_data_dir <- "unnest_job_summary_data_json_object"
-sample_size <- 3
 
 log_data <-
   tbl(log_conn, "rcc_job_log") %>%
-  dplyr::filter(script_name == "update_project_billable_attribute") %>%
-  dplyr::collect() %>%
-  dplyr::sample_n(size = sample_size)
+  dplyr::filter(script_name == "test_unnest") %>%
+  dplyr::collect()
 
 log_data %>% saveRDS(testthat::test_path(test_data_dir, "log_data.rds"))

vignettes/job_logging.Rmd

@@ -0,0 +1,151 @@
+---
+title: "Job Logging"
+output: rmarkdown::html_vignette
+vignette: >
+  %\VignetteIndexEntry{Job Logging}
+  %\VignetteEngine{knitr::rmarkdown}
+  %\VignetteEncoding{UTF-8}
+---
+
+```{r, include = FALSE}
+knitr::opts_chunk$set(
+  collapse = TRUE,
+  comment = "#>"
+)
+```
+
+```{r setup, eval = T, include = F }
+library(redcapcustodian)
+library(tidyverse)
+library(kableExtra)
+dotenv::load_dot_env(here::here(".env"))
+```
+
+REDCap Custodian includes its own job logging facility. The system is designed to log each job run to a single row in a MYSQL database. With as little a four lines of code, you can log job success or failure along with a message. e.g.,
+
+```{r minimal-example-of-success, eval = F, include = T, fig.cap = "A minimal example of logging a successful job"}
+library(redcapcustodian)
+library(dotenv)
+
+init_etl("my_useful_script", log_db_drv = duckdb::duckdb())
+# do some stuff ...
+
+log_job_success("It worked!")
+```
+
+The code in above would produce a row in the logging database like that shown in below.
+
+```{r mock_db_duckdb, eval = T, include = F}
+init_etl("my_useful_script", log_db_drv = duckdb::duckdb())
+log_job_success("It worked!")
+```
+
+```{r read-log-data, eval = T, include = F}
+log_conn <- get_package_scope_var("log_con")
+
+log_data <-
+  dplyr::tbl(log_conn, "rcc_job_log") |>
+  dplyr::filter(script_name == "my_useful_script") |>
+  dplyr::collect()
+```
+
+```{r minimal-example-of-success-output, eval = T, echo = F, fig.cap = "Data written by `my_useful_script`"}
+log_data |>
+  kbl() |>
+  kable_styling()
+```
+
+## Behind the scenes
+
+That's a tiny script, but a lot is happening. Let's decode what's going on in those few lines. 
+
+### `library(dotenv)`
+
+REDCap Custodian uses the `dotenv` package to read files of name-value pairs into the environment of the script. By default it reads `.env` from the current directory. To make logging work correctly, that `.env` file will need a stanza like this:
+
+``` ini
+LOG_DB_NAME=rcc_log
+LOG_DB_HOST=127.0.0.1
+LOG_DB_USER=rcc_log
+LOG_DB_PASSWORD=password
+LOG_DB_PORT=9000
+```
+
+The "LOG_DB\_\*" strings are the environment variable names `redcapcustodian` uses to locate the MySQL DB where it stores the logging data. You need to use these names and the values need to point at a MySQL table on a MySQL server.
+
+### `init_etl()`
+
+`init_etl("my_useful_script")` sets the `script_name` env variable to "my_useful_script", sets the `script_run_time` env variable to the current date and time, and it verifies the connection to the database described by the "LOG_DB\_\*" environment variables. If the database is there, `init_etl()` quietly exits. If the database is not there you will see
+
+``` r
+Warning: Failed to connect to log DB: rcc_log_bad
+The reason given was:
+ Error: Failed to connect: Access denied for user 'rcc_log'@'%' to database 'rcc_log_bad'
+```
+
+### `log_job_success()`
+
+`log_job_success("It worked!")` writes a row to the logging database like the example above.
+
+## Failed jobs
+
+When jobs fail you might want to log that condition, for that, call `log_job_failure()`. As with `log_job_success()`, you can provide a message to give more detail about what went wrong.
+
+```r
+log_job_failure("input dataframe was empty")
+```
+
+## More detailed messages
+
+Logging "It worked!" or "input dataframe was empty" is fine, but often, you want to provide more detail about a job's activities. Chances are you have some useful facts in R objects already. It is a simple matter to assemble those objects into a list, convert the list object into a text string with using JSON libraries, and use that string as the job's message. If you wanted report some updates you made to the 'iris' database, you might log it like this:
+
+```{r iris-updates, eval = T, echo = T}
+init_etl("iris_updater")
+# Do some stuff
+# ...
+iris_updates <- iris |> dplyr::sample_n(3) |> select(Sepal.Length, Species)
+# ...
+# success!
+log_message <- dplyr::lst(iris_updates)
+log_job_success(jsonlite::toJSON(log_message))
+```
+
+The `summary` value can contain any number of JSON-encoded objects. That said, plan them carefully. Ask what questions you will want to answer later after a job has run. The package authors have found the most common questions posed are "Why did this value change?", "Who (or what) set the value?", and "When did this change?" Store as little information as is needed to answer those questions succinctly. If you provide lots of different objects, it might make for a pile of log data to sift through later. We've found we can usually meet these needs by including minimal dataframes of the data written by the job. 
+
+If you have multiple jobs writing to the same dataset, consider the value of self-consistency across those jobs. If every update operation of the _invoice_ table is logged in an object named _invoice_updates_, you can more easily search across those jobs.
+
+## Reading back log data
+
+Reading back the log data presents a few challenges. When you are answering the "Who? What? When? Why?" questions you often have to search across multiple log events to find the job run that made the change. You can filter the log data to the time frame or jobs of interest, but you will still have to search multiple job summaries to find the one that made the change you care about. 
+
+If you encoded the job summary data with JSON, you'll need to decode it, but `jsonlite::fromJSON` is not vectorized. You'll have to iterate over the log records. Also, you'll want to unnest the job summary objects returned by `jsonlite::fromJSON`. REDCap Custodian provides the function `unnest_job_summary_data_json_object()` to help with these operations. e.g.,
+
+```{r mock-updates-to-iris, eval = T, echo = F}
+make_updates <- function() {
+  Sys.sleep(1)
+  iris_updates <- iris |> dplyr::sample_n(3) |> select(Sepal.Length, Species)
+  log_job_success(jsonlite::toJSON(dplyr::lst(iris_updates)))  
+}
+
+make_updates()
+make_updates()
+```
+
+```{r }
+log_conn <- get_package_scope_var("log_con")
+
+log_data <-
+  dplyr::tbl(log_conn, "rcc_job_log") |>
+  dplyr::filter(script_name == "iris_updater") |>
+  dplyr::collect() |>
+  dplyr::slice_tail(n = 3)
+  
+unnest_job_summary_data_json_object(log_data) |>
+  unnest(cols = "iris_updates") |>
+  kbl() |>
+  kable_styling()
+```
+
+```{r, eval = T, include = F}
+DBI::dbDisconnect(log_conn)
+```