logging.qmd

# Logging {#sec-logging}

```{=html}
<!--
https://shiny.posit.co/r/articles/improve/debugging/
https://debruine.github.io/shinyintro/debugging.html
-->
```

```{r}
#| label: _common
#| eval: true 
#| echo: false 
#| include: false
source("_common.R")
library(lobstr)
```

```{r}
#| label: co_box_dev
#| echo: false
#| results: asis
#| eval: true
co_box(
  color = "r", 
  header = "Warning",
  contents = "The contents for this section are under development. Thank you for your patience."
)
```

```{r}
#| label: co_box_tldr
#| echo: false
#| results: asis
#| eval: true
co_box(
  color = "b",
  look = "default", hsize = "1.10", size = "1.05",
  header = "TLDR &emsp; Logging your Shiny app",
  fold = TRUE,
  contents = "

<br>
  
Logging plays a crucial role in... 

  "
)
```

Another proactive approach to debugging Shiny applications is implementing logging. Logs help with debugging, auditing, and monitoring and should be considered an essential feature while developing a Shiny app, especially when building an R package. This chapter introduces integrating logging in a Shiny app-package to make debugging and issue tracking more efficient.

```{r}
#| label: shinypak_apps
#| echo: false
#| results: asis
#| eval: true
shinypak_apps(regex = "13", branch = "13_logging")
```

## Why Use Logging? {#sec-logging-why}

Logging applications app-package lets us track the application flow and record user interactions and inputs, and can also be used to identify runtime errors and unexpected behaviors. Log messages are more structured, flexible, and configurable than print statements or the interactive debugger. Logging is particularly useful in production environments, where direct debugging may not be possible. Logs can also be saved for future analysis, even after the application has stopped running.

### Architecture {#sec-logging-arch-tidy-movies}

We're going to start logging the behaviors in the `inst/tidy-movies` application. The architecture of this application has been updated to include the two new input modules (see @sec-resources-inst-tidy-movies-app):

```{=html}

<style>

.codeStyle span:not(.nodeLabel) {
  font-family: monospace;
  font-size: 1.5em;
  font-weight: bold;
  color: #9753b8 !important;
  background-color: #f6f6f6;
  padding: 0.2em;
}

</style>
```

```{mermaid}
%%| fig-cap: 'Architecture of app functions in `inst/tidy-movies/` folder'
%%| fig-align: center
%%{init: {'theme': 'neutral', 'themeVariables': { 'fontFamily': 'monospace', "fontSize":"16px"}}}%%
flowchart LR
        subgraph R["<strong>R/ folder</strong>"]
            subgraph launch["launch_app('ggp2')"]
                display_type["display_type()"]
            end
                mod_aes_input_ui["mod_aes_input_ui()"]
                mod_aes_input_server["mod_aes_input_server"]
                mod_var_input_server["mod_var_input_server()"]
                scatter_plot["scatter_plot()"]
        end

        subgraph tidy_movies["<strong>tidy-movies/ folder</strong>"]
            subgraph app["app.R file"]
                subgraph SubR["<strong>R/ folder</strong>"]
                devUI["devUI()"]
                dev_mod_vars_ui["dev_mod_vars_ui()"]
                dev_mod_scatter_ui["dev_mod_scatter_ui()"]
                devUI -->|"<em>Calls</em>"|dev_mod_vars_ui & dev_mod_scatter_ui
                devServer["devServer()"]
                dev_mod_scatter_server["dev_mod_scatter_server()"]
                devServer -->|"<em>Calls</em>"|dev_mod_scatter_server
                end
            end
            data[("tidy_movies.fst")]
            img[/"imdb.png"\]
        end
        

        launch ==> |"<strong><code>shinyAppDir()</code></strong>"|app
        mod_aes_input_ui -.->|"<em>Called from</em>"|devUI
        mod_var_input_server & mod_aes_input_server -.->|"<em>Called from</em>"|devServer
        scatter_plot --> |"<em>Called from</em>"|dev_mod_scatter_server
        
        
    %% R/
    style R fill:#e8f0f5,stroke:#333,stroke-width:1px,rx:3,ry:3
    %% standalone app function
    style launch fill:#F6F6F6,color:#000,stroke:#333,stroke-width:1px,rx:10,ry:10
    %% modules 
    style mod_var_input_server color:#000,fill:#f5f5f5,stroke:#333,stroke-width:1px,rx:12,ry:12
    style mod_aes_input_ui color:#000,fill:#f5f5f5,stroke:#333,stroke-width:1px,rx:12,ry:12
    style mod_aes_input_server color:#000,fill:#f5f5f5,stroke:#333,stroke-width:1px,rx:12,ry:12
    %% utility functions
    style scatter_plot fill:#595959,color:#FFF,stroke:#333,stroke-width:1px,rx:25,ry:25
    style display_type fill:#595959,color:#FFF,stroke:#333,stroke-width:1px,rx:25,ry:25
    
    %% tidy-movies/ 
    style tidy_movies fill:#e8f0f5,stroke:#333,stroke-width:1px,rx:3,ry:3
    %% tidy-movies/R
    style SubR fill:#f7fafb,stroke:#333,stroke-width:1px,rx:3,ry:3
    %% tidy-movies/R/ files
    style devUI stroke:#333,stroke-width:1px,rx:6,ry:6
    style devServer stroke:#333,stroke-width:1px,rx:6,ry:6
    style dev_mod_scatter_server color:#000,fill:#f5f5f5,stroke:#333,stroke-width:1px,rx:12,ry:12
    style dev_mod_scatter_ui color:#000,fill:#f5f5f5,stroke:#333,stroke-width:1px,rx:12,ry:12
    style dev_mod_vars_ui color:#000,fill:#f5f5f5,stroke:#333,stroke-width:1px,rx:12,ry:12
    %% files 
    style app fill:#f8f6e7,color:#000
    style data fill:#f8f6e7,color:#000
    style img fill:#f8f6e7,color:#000
```

To launch the `inst/tidy-movies` app, load, document, and install `sap` and run:

```{r}
#| label: hot_key_01
#| echo: false
#| results: asis
#| eval: true
hot_key(fun = "all")
```

```{r}
#| eval: false 
#| code-fold: false
launch_app("ggp2")
```

![Launching `inst/tidy-movies` app with `launch_app()`](images/log_ggp2_initial_launch.png){width="100%" fig-align="center"}

The reactive values from the `R/mod_var_input.R` are printed to the **Console** from the previous chapter (See @sec-debug-ui).

### Validating inputs {#sec-logging-validate}

`shiny::validate()` can be used to prevent unexpected errors by preventing execution of subsequent code if the provided validation conditions fail. 

- `need()` is used inside `validate()` to check if a condition is met, and `try()` catches errors that might occur if inputs are `NULL` or missing. 

- If an error occurs, `try()` prevents the application from crashing and instead returns an error object.

For example, the `alpha` and `size` inputs can validated with `try()` and `need()`:

```{r}
#| eval: false 
#| code-fold: false
validate(
  need(
    try(input$alpha >= 0 & input$alpha <= 1),
    "Alpha must be between 0 and 1"
  )
)
```

| `input$alpha`     | Behavior                                    |
|:------------------|:--------------------------------------------|
| `0.5` (valid)     | ✅ Passes validation                        |
| `1.5` (invalid)   | ❌ Error: `"Alpha must be between 0 and 1"` |
| `NULL`            | ❌ Error: `"Alpha must be between 0 and 1"` |
| `NA`              | ❌ Error: `"Alpha must be between 0 and 1"` |
| `"high"` (string) | ❌ Error: `"Alpha must be between 0 and 1"` |

```{r}
#| eval: false 
#| code-fold: false
validate(
  need(
    try(input$size > 0),
    "Size must be positive"
  )
)
```

| `input$size`       | Behavior                            |
|:-------------------|:------------------------------------|
| `3` (valid)        | ✅ Passes validation                |
| `-2` (invalid)     | ❌ Error: `"Size must be positive"` |
| `NULL`             | ❌ Error: `"Size must be positive"` |
| `NA`               | ❌ Error: `"Size must be positive"` |
| `"large"` (string) | ❌ Error: `"Size must be positive"` |


### Handling errors {#sec-logging-trycatch}

The `tryCatch` function can be used by itself to log unexpected errors gracefully. Below is an example of using it with `reactive()` and combining it `message()`:

```{r}
#| eval: false 
#| code-fold: false
safe_reactive <- reactive({
    tryCatch({
        # Code that might throw an error
        
    }, error = function(e) {
        message(paste0("An error occurred:", e$message))
    })
})
```

## Custom logging functions {#sec-logging-funs}

Logging can be implemented without any dependencies. The `base` package has many tools we can use to write a custom logging function. Below is an example logging utility function we could add to the `R/` folder and use in our app(s):

```{r}
#| eval: false 
#| code-fold: false
#' Log Application Behaviors
#'
#' A simple logging function for logging Shiny events and behaviors.
#' 
#' @param message log message
#' @param log_file name of log file (defaults to "app_log.txt")
#' @param save print or save log file
#'
#' @return A log message to the console and the `log_file`.
#'
#' @family **Utility Functions**
#' 
#' @examples
#' if (interactive()) {
#'   log_message("message")
#' }
#' 
#' @export
log_message <- function(message, log_file = "logs/app_log.txt", save = FALSE) {
  
  log_dir <- dirname(log_file) # <1>
  
  if (!dir.exists(log_dir)) { # <2>
    dir.create(log_dir, recursive = TRUE)
  } # <2>
  
  timestamp <- format(Sys.time(), "%Y-%m-%d %H:%M:%S")
  log_entry <- sprintf("[%s] %s", timestamp, message) # <3>
  
  if (save) {
    tryCatch({ # <4>
        cat(log_entry, "\n", file = log_file, append = TRUE) # <5>
      },
      error = function(e) {
        warning(sprintf("Failed to write to log file '%s': %s", log_file, e$message)) 
      }) # <4>
  }
  
  message(log_entry) # <6>
}
```

1.  This function uses `dirname()` to dynamically extract the directory path from `log_file`.\
2.  `dir.exists()` and `dir.create()` ensure the folder exists (`recursive = TRUE` is for nested directories).\
3.  The `sprintf()` function is preferred over `cat()` or `paste0()` for clearer and faster string formatting.\
4.  The file-writing logic is wrapped in `tryCatch()` to gracefully handle errors (e.g., file permission issues), and we've added a `warning()` if writing to the log file fails.\
5.  We explicitly add the newline (`\n`) directly in the `cat()` function, ensuring the log entry is written properly even if message lacks a newline.\
6.  Finally, the `message()` is preferred here instead of `print()` for consistent output formatting.

Adapted to use in the `inst/tidy-movies/` app, the `tryCatch()` function might look like:

```{r}
#| eval: false 
#| code-fold: false
    all_data <- tryCatch({
      
      log_message(message = "Loading fst data", # <1>
        log_file = "_logs/ggp2_log.txt", save = TRUE) # <1>
      
      fst::read_fst("tidy_movies.fst")
      
    }, error = function(e) {
      
      log_message(message = sprintf("Error loading fst data: %s", e$message), # <2>
        log_file = "_logs/ggp2_log.txt", save = TRUE) # <2>
      
      stop("Data loading failed.") # <3>

    })
```

1.  Saving to `_logs` because it's easier to separate from other app folders.  
2.  Print error message from `tryCatch()`   
3.  Stop creation of reactive.  

After loading and installing our package, the output from the log is saved in the log file (and printed to the **Console**) when our app stops running:

![Logging data upload with `log_message()`](images/log_ggp2_logr_message_all_data.png){width="100%" fig-align="center"}

### Logging events  {#sec-logging-events}

We'll continue to integrate log messages into the `inst/tidy-movies` app by inserting `log_message()` at critical points, such creating reactive expressions. For example, `dev_mod_scatter_server()` creates the `graph_data()` reactive based on the missing data checkbox user input:

```{r}
#| eval: false 
#| code-fold: false
graph_data <- reactive({
  if (input$missing) {
    graph_data <- tidyr::drop_na(data = all_data)
  } else {
    graph_data <- all_data
  }
}) |>
  bindEvent(input$missing)
```



We'll add `validate()` and `tryCatch()` with a `log_message()` to log if 1) `graph_data()` contains all of the observations or the missing values have been removed, and 2) if the reactive was created successfully.

```{r}
#| eval: false 
#| code-fold: false
graph_data <- reactive({
  
  validate( # <1>
    need(try(is.logical(input$missing)), 
          "Missing must be logical")
  ) # <1>
  
    tryCatch({
      if (input$missing) {
        
        log_message(message = "Removing missing values.", # <2>
                    log_file = "_logs/ggp2_log.txt", save = TRUE)
        graph_data <- tidyr::drop_na(data = all_data) # <2>
        
      } else {
        
        log_message(message = "Using all data.", # <3>
                    log_file = "_logs/ggp2_log.txt", save = TRUE)
        graph_data <- all_data # <3>
        
      }
      
      graph_data
      
    }, error = function(e) {
      
      log_message(message = sprintf("Error processing graph data: %s", e$message), #<4>
        log_file = "_logs/ggp2_log.txt", save = TRUE) #<4>
      NULL #<5>
      
    })
}) |> 
  bindEvent(input$missing)

```
1. Validation for missing checkbox input  
2. Confirm missing values and create `graph_data`  
3. Use all data and create `graph_data`  
4. Print and log message is error occurs 
5. Return null value for error

These logs will tell us the application loaded the `.fst` data and removed the missing values, but we should also check what happens when we change something, so we'll adapt the code used to create our `inputs()` reactive with the `log_message()` function:

```{r}
#| eval: false 
#| code-fold: false
inputs <- reactive({

  tryCatch({
    plot_title <- tools::toTitleCase(aes_inputs()$plot_title)
    
    if (nchar(plot_title) > 0) { # <1>
      log_message(
        sprintf("Processing plot title: '%s'", plot_title), 
        log_file = "_logs/ggp2_log.txt")
    } # <1>
    
      input_list <- list(
        x = var_inputs()$x,
        y = var_inputs()$y,
        z = var_inputs()$z,
        alpha = aes_inputs()$alpha,
        size = aes_inputs()$size,
        plot_title = plot_title
      )
    
    log_message( # <2>
      sprintf("Inputs: %s", 
              paste(
                names(input_list), input_list, sep = " = ", collapse = ", ")
              ),
            log_file = "_logs/ggp2_log.txt", save = TRUE) # <2>
    
    input_list
  }, error = function(e) {
    
    log_message( # <3>
      sprintf("Error in processing inputs: %s", conditionMessage(e)),
      log_file = "_logs/ggp2_log.txt", save = TRUE)  # <3>
    
    NULL  # <4>
  })
})
```
1.  Log the plot title.\
2.  Log the final input list.\
3.  Log the error if anything goes wrong.\
4.  Return `NULL` on error to prevent breaking downstream dependencies.

After loading and installing sap, we launch the `inst/tidy-movies` app again, but this time we un-check the remove missing checkbox and add a new title before stopping the application.

```{r}
#| eval: false 
#| code-fold: false
launch_app("ggp2")
```

![Log messages from `inputs()`](images/log_ggp2_log_reactive_inputs_base.png){width="100%" fig-align="center"}

To view the log file, we need to use `system.file()` (we're launching the app from the *installed* location, not the version we're developing in the `inst/tidy-movies/` folder). I've added `readLines()` and `writeLines()` so it prints nicely to the **Console**:

```{r}
#| eval: false 
#| code-fold: false
system.file('tidy-movies', '_logs', 'ggp2_log.txt', 
            package = 'sap') |> 
            readLines() |> 
            writeLines()
```

```{verbatim}
[2025-01-29 11:34:40] Loading fst data 
[2025-01-29 11:34:40] Removing missing values. 
[2025-01-29 11:34:40] Inputs: x = year, y = budget, z = mpaa, alpha = 0.5, size = 2, plot_title =  
[2025-01-29 11:35:46] Loading fst data 
[2025-01-29 11:35:46] Removing missing values. 
[2025-01-29 11:35:46] Inputs: x = year, y = budget, z = mpaa, alpha = 0.5, size = 2, plot_title =  
[2025-01-29 11:35:52] Loading fst data 
[2025-01-29 11:35:52] Removing missing values. 
[2025-01-29 11:35:52] Inputs: x = year, y = budget, z = mpaa, alpha = 0.5, size = 2, plot_title =  
[2025-01-29 11:35:57] Inputs: x = year, y = budget, z = mpaa, alpha = 0.5, size = 2, plot_title = Title 
```

In practice, we'd insert logging messages with `log_message()` and `tryCatch()` for application startup, loading data/connecting to databases, API calls, and when using Shiny's internal validation/error handling functions. In the next section, we're going to explore using add-on packages to implement logging in our app-package.

## App logs with [`logger`]{style="font-size: 1.05em;"}  {#sec-logging-logger}

```{r}
#| label: co_box_log_frameworks
#| echo: false
#| results: asis
#| eval: true
#| include: true
co_box(
  color = "b", fold = FALSE,
  look = "default", hsize = "1.15", size = "1.10",
  header = "Logging frameworks", 
  contents = "
The R ecosystem offers several libraries for logging. 

The most popular options are:

- [`futile.logger`](https://github.com/zatonovo/futile.logger): A lightweight and flexible logging package.

- [`logger`](https://daroczig.github.io/logger/index.html): A modern, extensible, and user-friendly library.

- [`log4r`](https://github.com/r-lib/log4r): Inspired by the [Java `log4j` library](https://logging.apache.org/log4j/2.x/index.html), suitable for structured logging.
")

```

This section will focus on the [`logger` package](https://daroczig.github.io/logger/index.html) because it is simple, easy to integrate with Shiny, and extensible.

```{r}
#| eval: false 
#| code-fold: false
install.packages("pak")
pak::pak("daroczig/logger")
```

Add `logger` to the package dependencies in the `DESCRIPTION` file and use the `logger::fun()` syntax to avoid adding `@import` or `@importFrom` `roxygen` tags.

```{r}
#| eval: false 
#| code-fold: false
usethis::use_package('logger')
```

### Log levels {#sec-logging-levels}

The `logger` package has a few configurations that can be very helpful for app-package development. We'll start with a basic example using `logger::log_info()`:

```{r}
#| eval: false 
#| code-fold: false
name <- "world"
logger::log_info('Hello, {name}')
```

```{verbatim}
INFO [2025-01-22 11:07:52] Hello, world
```

The output is a nicely formatted log message, and by default `logger` supports [`glue` syntax](https://daroczig.github.io/logger/articles/customize_logger.html#log-message-formatter-functions). However, the following function (`logger::log_debug()`) doesn't return a log message to the Console:

```{r}
#| eval: false 
#| code-fold: false
logger::log_debug('Hello, {name}')
```

This is because the logger package has a threshold configuration that controls the 'verbosity' of the logs printed to the **Console**. If we check the `log_threshold()`, we see it's set to `INFO`:

```{r}
#| eval: false 
#| code-fold: false
logger::log_threshold()
```

```{verbatim}
Log level: INFO
```

If we reset the `logger::log_threshold()` to `DEBUG`, we will see the call in the **Console**.

```{r}
#| eval: false 
#| code-fold: false
logger::log_threshold('DEBUG')
logger::log_debug('Hello, {name}')
```

```{verbatim}
DEBUG [2025-01-22 11:08:36] Hello, world
```

We can set the log threshold dynamically to control the verbosity of logs:

```{r}
#| eval: false 
#| code-fold: false
logger::log_threshold('TRACE') # fine-grained, verbose logging for development
logger::log_threshold('DEBUG') # verbose logging for development
logger::log_threshold('WARN')  # only warnings and errors for production
```

While developing app-packages, I recommend broadly characterizing the `logger` log levels into the following categories:

::: {layout="[30,70]" layout-valign="top"}

### Development {.unnumbered}

*Descriptive messages for easier debugging*

| Level   | Details                                                                             |
|:--------|:------------------------------------------------------------------------------------|
| `TRACE` | Fine-grained tracking for debugging flows (e.g., reactive updates, function calls). |
| `DEBUG` | Diagnostic information for inputs, intermediate states, and outputs.                |

:::

::: {layout="[30,70]" layout-valign="top"}

### Production {.unnumbered}

*Lower verbosity levels*

| Level   | Details                                                                         |
|:--------|:--------------------------------------------------------------------------------|
| `INFO`  | Session-level events and significant actions (e.g., app startup, data loading). |
| `WARN`  | Suspicious but non-fatal conditions (e.g., unusual input values or data sizes). |
| `ERROR` | Handled errors with appropriate messaging and graceful recovery.                |
| `FATAL` | Critical failures leading to app crashes or irrecoverable states.               |

:::


### Storing log files {#sec-logging-files}

By default, `logger` logs are written to the console, but the `logger::appender_file()` function can direct log messages to a file (or to a database or external logging system).[^logging-1]

[^logging-1]: Integrate with external logging systems (e.g., [Syslog](https://daroczig.github.io/logger/reference/appender_syslog.html) or [Telegram](https://daroczig.github.io/logger/reference/appender_telegram.html)) using custom appenders.

We also want to periodically archive old logs to prevent storage issues. Storing log messages as JSON objects is sometimes preferred because JSON files are structured, machine-readable, and can easily integrate with logging tools like [Logstash](https://www.elastic.co/logstash), [Kibana (ELK Stack)](https://www.elastic.co/elastic-stack) or other log management solutions.

### Custom [`logger`]{style="font-size: 1.05em;"} functions {#sec-logging-logr_msg}

We'll write a custom logging function with `logger` to so our app logs are formatted and managed a consistent manner. Below is a `logr_msg()` utility function for inserting `logger`-style logs in our application.

```{r}
#| eval: false 
#| code-fold: false
logr_msg <- function(message, level = "INFO", log_file = NULL, json = FALSE) {
  
  logger::log_appender(appender = logger::appender_console) # <1>
  
  if (!is.null(log_file)) {
    if (json) { # <2>
      logger::log_layout(layout = logger::layout_json())  # <2>
    } else { # <3>
      logger::log_appender(appender = logger::appender_tee(log_file))
    } # <3>
  }
  
  logger::log_formatter(formatter = logger::formatter_glue) # <4>
  
  switch( # <5>
    level,
    "FATAL" = logger::log_fatal("{message}"),
    "ERROR" = logger::log_error("{message}"),
    "WARN" = logger::log_warn("{message}"),
    "SUCCESS" = logger::log_success("{message}"),
    "INFO" = logger::log_info("{message}"),
    "DEBUG" = logger::log_debug("{message}"),
    "TRACE" = logger::log_trace("{message}"), # <5>
    logger::log_info("{message}") # <6>
  )
}
```

1.  All logs print to console
2.  Write logs to JSON if the `json = TRUE`\
3.  Default `appender_tee` for plain text logs\
4.  Set the default formatter\
5.  Handle all log levels\
6.  Default to `INFO`

[`log_appender`](https://daroczig.github.io/logger/reference/log_appender.html) controls where the log messages go. It specifies the "destination" for each log message, whether that's the **Console**, a file, or both.

[`log_formatter`](https://daroczig.github.io/logger/reference/log_formatter.html) is like a template for log messages--it determines how log each message is structured and displayed. We can control what information is included in each message (like the timestamp, log level, and the actual message), and how this information is formatted. Predefined formatters (like `formatter_glue`) uses `glue` syntax to create flexible and readable formats.

We'll demonstrate `logr_msg()` with the `mod_var_input_server()` function, which returns the variable inputs from the UI. The `message` in `logr_msg()` is built with `glue::glue()` and includes the three reactive inputs from this module. We're also appending the log output to a new log file (`_logs/app_log.txt`).

```{r}
#| eval: false 
#| code-fold: false
mod_var_input_server <- function(id) {
  moduleServer(id, function(input, output, session) {
    
    logr_msg("mod_var_input_server started", #<1>
      level = "TRACE", log_file = "_logs/app_log.txt")  #<1>
    
    observe({
        logr_msg( #<2>
          glue::glue("Reactive inputs: 
                      x = {input$x}, y = {input$y}, z = {input$z}"),
          level = "DEBUG", log_file = "_logs/app_log.txt") #<2>
    }) |> 
      bindEvent(c(input$x, input$y, input$z))

    return(
      reactive({
        logr_msg(#<3>
          glue::glue("Reactive inputs returned: 
                      x = {input$x}, y = {input$y}, z = {input$z}"),
          level = "DEBUG", log_file = "_logs/app_log.txt") #<3>
        list(
          "x" = input$x,
          "y" = input$y,
          "z" = input$z
        )
      })
    )
  })
}
```

1.  `TRACE` log for starting the module\
2.  `DEBUG` log for collecting inputs
3.  `DEBUG` log for returning inputs

An advantage to using the `logger` package is that our log messages are automatically printed to the Console while the application is launched, although when we load and install `sap` and launch the `inst/tidy-movies` app, we don't see any logs:

```{r}
#| label: hot_key_02
#| echo: false
#| results: asis
#| eval: true
hot_key(fun = "all")
```

```{r}
#| eval: false 
#| code-fold: false
launch_app("ggp2")
```

![Initial messages from `logr_msg()`](images/log_ggp2_logr_message_var_input.png){width="100%" fig-align="center"}

To view the log in our app, we need to set the log threshold:

```{r}
#| eval: false 
#| code-fold: false
logger::log_threshold('TRACE')
launch_app("ggp2")
```

The logs are now printed to the console and we can see the level, timestamp, and message:

![Updates from `logr_msg()`](images/log_ggp2_logr_message_var_input_update.png){width="100%" fig-align="center"}

## Logging and debugging {#sec-logging-debugging}

Our primary application (i.e. the app launched with `launch_app()`) is currently displaying and error message:

![Error message in `launch_app()`](images/log_error_in_launch_app.png){width="100%" fig-align="center"}

### Architecture {#sec-logging-arch-movies}

Let's try to visualize the call stack and namespaces in this app. The diagram below shows how the variable and aesthetic input modules communicate the user selections across the namespaces in UI and server functions.

```{=html}

<style>

.codeStyle span:not(.nodeLabel) {
  font-family: monospace;
  font-size: 1.5em;
  font-weight: bold;
  color: #9753b8 !important;
  background-color: #f6f6f6;
  padding: 0.2em;
}

</style>
```

```{mermaid}
%%| fig-align: center
%%| fig-cap: 'Primary `launch_app()` app'
%%{init: {'theme': 'neutral', 'themeVariables': { 'fontFamily': 'monospace', "fontSize":"16px"}}}%%
flowchart TD
    subgraph Launch["<strong>launch_app()</strong>"]
        subgraph Server["<strong>movies_server()</strong>"]
            subgraph VarServerNS["<strong>Variable Namespace<strong>"]
                VarInpuServer["Server Module:<br><code>mod_var_input_server()</code>"]
            end
            subgraph AesServerNS["<strong>Aesthetics Namespace<strong>"]
                AesInpuServer["Server Module:<br><code>mod_aes_input_server()</code>"]
            end
            subgraph GraphServerNS["<strong>Graph Namespace<strong>"]
                DisplayServer["Server Module:<br><code>mod_scatter_display_server()</code>"]
                PlotUtil["Utility Function:<br><code>scatter_plot()</code>"]
            end
        end
        subgraph UI["<strong>movies_ui()</strong>"]
            subgraph VarUINS["<strong>Variable Namespace<strong>"]
                VarInpuUI["UI Module:<br><code>mod_var_input_ui()</code>"]
            end
            subgraph AesUINS["<strong>Aesthetics Namespace<strong>"]
                AesInpuUI["UI Module:<br><code>mod_aes_input_ui()</code>"]
            end
            subgraph GraphUINS["<strong>Graph Namespace<strong>"]
                DisplayUI["UI Module:<br><code>mod_scatter_display_ui()</code>"]
            end
        end

        VarInpuUI <==> |"shared namespace"|VarInpuServer
        AesInpuUI <==> |"shared namespace"|AesInpuServer
        DisplayServer <--> PlotUtil <==> |"shared namespace"|DisplayUI
    end

    VarInpuServer <-.->|"Communicates <code>selected_vars</code><br>across namespaces"| DisplayServer
    AesInpuServer <-.->|"Communicate <code>selected_aes</code><br>across namespaces"| DisplayServer
    
    %% standalone app function 
    style Launch fill:#F6F6F6,color:#000,stroke:#333
    %% modules
    style VarInpuUI color:#000,fill:#f5f5f5,stroke-width:2px,rx:3,ry:3
    style AesInpuServer color:#000,fill:#f5f5f5,stroke-width:2px,rx:3,ry:3
    style AesInpuUI color:#000,fill:#f5f5f5,stroke-width:2px,rx:3,ry:3
    style DisplayServer color:#000,fill:#f5f5f5,stroke-width:2px,rx:3,ry:3
    style DisplayUI color:#000,fill:#f5f5f5,stroke-width:2px,rx:3,ry:3
    %% Utility Functions
    style PlotUtil fill:#595959,color:#FFF,stroke:#333,stroke-width:1px,rx:25,ry:25
    %% namespaces
    style VarServerNS fill:#f8f6e7,stroke-width:1px,rx:6,ry:6
    style VarUINS fill:#f8f6e7,stroke-width:1px,rx:6,ry:6
    style AesServerNS fill:#f8f6e7,stroke-width:1px,rx:6,ry:6
    style AesUINS fill:#f8f6e7,stroke-width:1px,rx:6,ry:6
    style GraphServerNS fill:#f8f6e7,stroke-width:1px,rx:6,ry:6
    style GraphUINS fill:#f8f6e7,stroke-width:1px,rx:6,ry:6
    %% UI and Server
    style Server fill:#e8f0f5,stroke-width:1px,rx:12,ry:12
    style UI fill:#e8f0f5,stroke-width:1px,rx:12,ry:12
```

Below are examples of various log levels using `logr_msg()` to help us debug the error in the primary application.

### [`TRACE`]{style="font-size: 1.05em;"} logs

1. In `movies_server()`, add a `TRACE` log message for signaling the server function has executed.

```{r}
#| eval: false 
#| code-fold: false
  logr_msg(message = "Server function execution completed", 
           level = "TRACE", log_file = "_logs/app_log.txt")
```


2.  In `mod_scatter_display_server()`, add a `TRACE` log messages for initiating the scatterplot graph

```{r}
#| eval: false 
#| code-fold: false
logr_msg("Preparing scatterplot in mod_scatter_display_server", 
          level = "TRACE", log_file = "_logs/app_log.txt")
```

### [`INFO`]{style="font-size: 1.05em;"} logs

1.  In `launch_app()`, add an `INFO` log message to print the application being launched with the `app` argument

```{r}
#| eval: false 
#| code-fold: false
  logr_msg(glue::glue("Launching app: {app}"), level = "INFO",
    log_file = "_logs/app_log.txt")
```

2.  In `movies_ui()`, add an `INFO` log message with the value of the `bslib` argument

```{r}
#| eval: false 
#| code-fold: false
  logr_msg(
    glue::glue("Launching UI with bslib = {bslib}"),
    level = "INFO", log_file = "_logs/app_log.txt")
```

### [`WARN`]{style="font-size: 1.05em;"} logs

1. In `mod_aes_input_server()`, add a `WARN` log message (with validate) for input warnings. 

```{r}
#| eval: false 
#| code-fold: false
      validate(
        need(try(input$alpha >= 0 & input$alpha <= 1), 
              "Alpha must be between 0 and 1")
      )
      if (input$alpha < 0 || input$alpha > 1) {
        logr_msg(message = "Alpha value out of range: {alpha}", 
        level = "WARN", log_file = "_logs/app_log.txt")
      }
```


### [`ERROR`]{style="font-size: 1.05em;"} logs

1.  In `movies_ui()`, Add logic and an `ERROR` log message to monitor the format of the `bslib` argument

```{r}
#| eval: false 
#| code-fold: false
if (!is.logical(bslib)) {
  logr_msg("Argument 'bslib' must be a logical value", 
    level = "ERROR", log_file = "_logs/app_log.txt")
    stop("Invalid argument: 'bslib' must be TRUE or FALSE.")
  }
```

2.  In `mod_scatter_display_server()`, add an `ERROR` log messages (with `tryCatch()`) to monitor the rendered output

```{r}
#| eval: false 
#| code-fold: false
  tryCatch({
    plot <- scatter_plot(
      # data --------------------
      df = movies,
      x_var = inputs()$x,
      y_var = inputs()$y,
      col_var = inputs()$z,
      alpha_var = inputs()$alpha,
      size_var = inputs()$size
    )
    plot +
      ggplot2::labs(
        title = inputs()$plot_title,
          x = stringr::str_replace_all(tools::toTitleCase(inputs()$x), "_", " "),
          y = stringr::str_replace_all(tools::toTitleCase(inputs()$y), "_", " ")
      ) +
      ggplot2::theme_minimal() +
      ggplot2::theme(legend.position = "bottom")
  }, error = function(e) {
  
  logr_msg(glue::glue("Failed to render scatterplot. Reason: {e$message}"), 
           level = "ERROR", log_file = "_logs/app_log.txt")
  
  })
```

### [`FATAL`]{style="font-size: 1.05em;"} logs

1. In `launch_app()`, add a `FATAL` log message (along with `tryCatch()` and `stop()`) to monitor the application being launched

```{r}
#| eval: false 
#| code-fold: false
  tryCatch({
    
    if (app == "bslib") {
      shinyApp(
        ui = movies_ui(bslib = TRUE),
        server = movies_server,
        options = options
      )
    } else if (app == "ggp2") {
      shinyAppDir(
        appDir = system.file("tidy-movies", package = "sap"),
        options = options
      )
    } else if (app == "quarto") {
      quarto::quarto_preview(
        system.file("quarto", "index.qmd", package = "sap"), 
        render = "all"
      )
    } else {
      app <- "movies"
      shinyApp(
        ui = movies_ui(...),
        server = movies_server,
        options = options
      )
    }
    
  }, error = function(e) {
    
    logr_msg(glue::glue("Application failed to launch. Reason: {e$message}"), 
             level = "FATAL",
             log_file = "_logs/app_log.txt")
    
    stop("Application launch failed. Check logs for details.")
    
  })
```

To use logs during development to trace the flow of our application, we need to set the threshold to `TRACE` or `DEBUG` after loading and install.

```{r}
#| label: hot_key_03
#| echo: false
#| results: asis
#| eval: true
hot_key(fun = "all")
```

```{r}
#| eval: false 
#| code-fold: false
logger::log_threshold('TRACE')
launch_app()
```

![Log error message in `launch_app()`](images/log_error_info_threshold.png){width="100%" fig-align="center"}

While developing our application, we can run the app interactively and monitor the logs in the console. If the application has been deployed, we can search the log files using R (or the command line):

In R:

```{r}
#| eval: false 
#| code-fold: false
readLines("_logs/app_log.txt") |> 
  stringr::str_view("ERROR")
```

```{verbatim}
│ <ERROR> [2025-01-29 13:55:36] Failed to render scatterplot. 
  Reason: 'text' must be a character vector
```

Command line:

``` sh
cat _logs/app_log.txt | grep "ERROR"
```

```{verbatim}
ERROR [2025-01-29 13:55:36] Failed to render scatterplot. 
  Reason: 'text' must be a character vector
```

```{r}
#| label: co_box_log_init
#| echo: false
#| results: asis
#| eval: true
#| include: true
co_box(
  color = "g", fold = FALSE,
  look = "default", 
  hsize = "1.15",
  size = "1.10",
  header = "Initialize logging with `.onLoad()`", 
  contents = "

We can set up `logger`'s logging configuration in an `onLoad` function of the `zzz.R` file:

\`\`\`r
.onLoad <- function(libname, pkgname) {
    # configure logger log messages to console
    logger::log_appender(logger::appender_console)
    # configure logger log messages to file
    logger::log_appender(logger::appender_file('sap_apps.log'))
    # set default log level to DEBUG
    logger::log_threshold('DEBUG') 
}
\`\`\`

This setup ensures that logging is ready as soon as your package is loaded.
")
```

## Package startup messages {#sec-logging-pkg-startup-msg}

Package startup messages help create a welcoming and professional impression when users load your app-package. These messages can also inform users of any specific requirements, dependencies, or potential conflicts. Package startup messages can also include the logging system (i.e., `logger`) being used, which can be helpful for debugging or monitoring during development or runtime.

### [`.onAttach()`]{style="font-size: 1.05em;"} {#sec-logging-on-attach}

Write package startup messages in the `.onAttach()` function (stored in `R/zzz.R`).[^logging-2] The example below includes a welcome message, the current Git branch, dependencies (imports, depends, and suggests), and the path where this package is loaded *from*.

[^logging-2]: Read more in the ['Hooks for Namespace Events' documentation](https://stat.ethz.ch/R-manual/R-devel/library/base/html/ns-hooks.html).

```{r}
#| eval: false 
#| code-fold: false
.onAttach <- function(libname, pkgname) {
  
    branch <- if (isTRUE(system("git rev-parse --is-inside-work-tree", intern = TRUE) == "true")) { # <1>
    tryCatch({ # <2>
      system("git rev-parse --abbrev-ref HEAD", intern = TRUE)
    }, error = function(e) "unknown")
  } else { # <2>
    "not a Git repository"
  }

  version <- utils::packageVersion(pkgname) # <3>

  description <- utils::packageDescription(pkgname) # <4>
  imports <- description$Imports
  suggests <- description$Suggests
  depends <- description$Depends # <4>

  parse_dependencies <- function(dep_string) { # <5> 
    if (is.null(dep_string)) return("None")
    deps <- strsplit(dep_string, ",\\s*")[[1]]
    paste(deps, collapse = ", ")
  } # <5> 

  imports <- parse_dependencies(imports) # <6>
  suggests <- parse_dependencies(suggests) # <6>
  depends <- parse_dependencies(depends) # <6>
  
  cli::cli_inform("{.strong Welcome to the {.pkg {pkgname}} package (version {version}) {cli::symbol$smiley}!}", # <7>
    class = "packageStartupMessage") # <7>
  
  cli::cli_inform("{.strong Current branch:}", class = "packageStartupMessage") # <8>
  cli::cli_inform("{.emph {cli::symbol$pointer} {branch}}", class = "packageStartupMessage") # <8>

  cli::cli_inform("{.strong Dependencies:}", class = "packageStartupMessage") # <9>
  cli::cli_inform("{.emph {cli::symbol$pointer} Imports: {imports}}", class = "packageStartupMessage") # <10>
  cli::cli_inform("{.emph {cli::symbol$pointer} Suggests: {suggests}}", class = "packageStartupMessage")# <11>
  cli::cli_inform("{.emph {cli::symbol$pointer} Depends: {depends}}", class = "packageStartupMessage")# <12>

  cli::cli_inform("{.strong Loaded from:}", class = "packageStartupMessage") # <13>
  cli::cli_inform("{.emph {cli::symbol$pointer} {libname}}", class = "packageStartupMessage") # <14>
}
```
1.  Check if the current folder is a Git repo.\
2.  Capture the current branch if it's a Git repo.\
3.  Package version.\
4.  Dependencies from `DESCRIPTION`.\
5.  Parse and format dependencies function.\
6.  Cleaned dependencies.\
7.  Welcome message.\
8.  Git branch.\
9.  Dependencies (header).\
10. Dependencies (`Imports` from `DESCRIPTION`).\
11. Dependencies (`Suggests` from `DESCRIPTION`).\
12. Dependencies (`Depends` from `DESCRIPTION`).\
13. Source of installed packages.\
14. `libname` (*a character string giving the library directory where the package defining the namespace was found.*)\

When we loading `sap`, we see the output from our startup message:

![Package startup message in `sap`](images/log_pkg_startup_load_all.png){width="100%" fig-align="center"}

Including a startup message is a helpful tool, but it should be thoughtfully crafted to enhance the user experience without being intrusive. Avoid including a startup message if the app-package if the message doesn’t add meaningful value and becomes unnecessary "noise" for users.

Also, be sure to allow users to disable the message if possible (e.g., using `suppressPackageStartupMessages()`):

```{r}
#| eval: false 
#| code-fold: false
install.packages('pak')
pak::pak('mjfrigaard/sap')
suppressPackageStartupMessages(library(sap))
```

## Recap {.unnumbered}

The techniques discussed in this chapter will help you efficiently diagnose and resolve issues, making your Shiny app-package more robust and reliable.

```{r}
#| label: co_box_recap
#| echo: false
#| results: asis
#| eval: true
co_box(
  color = "g", 
  fold = FALSE,
  look = "default", 
  hsize = "1.10", 
  size = "1.05", 
  header = "Recap: Logging",
  contents = "Logging is an invaluable tool for debugging Shiny app-packages. By strategically placing log messages and configuring log levels, you can gain deep insights into your application’s behavior. 
  
- Use log levels to differentiate between logs. 

- Configure log settings with `.onLoad()` (stored in `R/zzz.R`)

- Store package startup messages in `onAttach()` (stored in `R/zzz.R`)
  
Be selective with logging and avoid exposing or storing sensitive data.")
```