Logging and Analyzing Events in Complex Shiny Apps

class: center, middle

## Logging and Analyzing Events in Complex Shiny Apps

## with __shinyEventLogger__

### Kamil Wais

UseR! - Toulouse - 2019

![:abs 16%, 30%, 73%](7n_logo.png)
_supported by_

![:abs 25%, 50%, 73%](roche_logo.jpg)

---
class: inverse, center, middle

# Why to log?

---
# Why to log?

* logging during development:

* shows which events are firing (or not)
   
   * shows in what sequence events are firing 
   
   * shows why events fired & within what context
   
   * helps with __debugging & development__

*  logging in production:

* shows how users use the app
   
   * helps to see usage patterns
   
   * helps with app __evaluation & optimization__

---
class: inverse, center, middle

# What do we need?

---
background-image: url(lifecycle-experimental-orange.svg)
background-position: 48% 60%
background-size: 20%

# What do we need?

* logging tool __dedicated to__ complex __shiny apps__
  
  * ability to see most recent events in __real-time__
  
  * quick & easy __access__ to eventlogs 
  
  * __permanent storage__ for eventlogs
  
  * tools to __analyse__ the eventlogs

## shinyEventLogger
R Package for Logging Events in Complex Shiny Apps

---
class: inverse, center, middle

# What type of events to log?

---
# Logging __generic events__

```r
library(shiny)
library(shinyEventLogger)
set_logging()
shinyApp(
 ui = fluidPage(log_init()),
 server = function(input, output) {
 set_logging_session()
* log_event("Event body", name = "Event name")
* log_event("Event without explicit name")
 x <- "123"
* log_event("Event", x)
 }
)
```

---

# Logging __values__

```r
set_logging()
shinyApp(
  ui = fluidPage(log_init(),
    selectInput("number", 
                "Select number", 
                choices = c(1, 2, 3), 
                selected = 2)),
  server = function(input, output) {
    set_logging_session()
*  log_value(NROW(mtcars))
  observe({ 
*    log_value(input$number)
  })
 })
```

```
|#1|VALUE|NROW(mtcars)|FIRED|
|#1|32
|#2|VALUE|input$number|FIRED|
|#2|2
```

![:abs 40%, 60%, 22%](log_value.gif)

---

# Logging function __outputs__

```r
set_logging()
shinyApp(
  ui = fluidPage(log_init()),
  server = function(input, output) {
    set_logging_session()
*  log_output(head(mtcars, 2))
*  log_output(str(mtcars[, 1:3]))
 })
```

```
|#1|OUTPUT|head(mtcars, 2)|FIRED|
|#1|              mpg cyl disp  hp drat    wt  qsec vs am gear carb
|#1|Mazda RX4      21   6  160 110  3.9 2.620 16.46  0  1    4    4
|#1|Mazda RX4 Wag  21   6  160 110  3.9 2.875 17.02  0  1    4    4
|#2|OUTPUT|str(mtcars[, 1:3])|FIRED|
|#2|'data.frame':	32 obs. of  3 variables:
|#2| $ mpg : num  21 21 22.8 21.4 18.7 18.1 14.3 24.4 22.8 19.2 ...
|#2| $ cyl : num  6 6 4 6 8 6 8 4 4 6 ...
|#2| $ disp: num  160 160 108 258 360 ...
```

---

# Logging outcomes of __unit tests__

```r
set_logging()
shinyApp(
  ui = fluidPage(log_init()),
  server = function(input, output) {
    set_logging_session()
*  log_test(testthat::expect_true(TRUE))
*  log_test(testthat::expect_true(FALSE))
 })
```

---

# Logging traditional __diagnostic messages__

```r
set_logging()
shinyApp(
  ui = fluidPage(log_init()),
  server = function(input, output) {
    set_logging_session()
*  log_message("Example of a message")
*  log_warning("Example of a warning")
*  log_error("Example of an error")
 })
```

---
class: inverse, center, middle

# Timing events

---

# Logging & __timing events__

```r
shinyApp(
  ui = shiny::fluidPage(log_init()),
  server = function(input, output) {
    set_logging_session()
*  log_started("Event 1")
      log_event("Sleeping for 3 secs...")
      Sys.sleep(3)
*  log_done("Event 1")
 })
```

---
# Logging & timing in __parallel R processes__

![:abs 90%, 5%, 30%](timings.jpg)

---
class: inverse, center, middle

# Logging the context of the events

---

# Logging events with parameters

```r
*set_logging(app = "demo")
shinyApp(
  ui = fluidPage(log_init(),
    selectInput("number", "Select number", choices = c(1, 2)),
  server = function(input, output) {
*    set_logging_session(unique_id = runif(1))
    observe({
*      log_event("number changed", 
*                  params = list(number = input$number))
})})
```

---

# Logging events with parameters

![:abs 100%, 0%, 20%](log_parameters.gif)
(scope-specific, session-wide, event-specific)

---
class: inverse, center, middle

# Where to log?

---

# Demo app with event logging
![:abs 100%, 0%, 20%](demo_app.gif)

---

# R console

![:abs 71%, 30%, 0%](log_r_console.gif)

---

# JavaScript console

![:abs 120%, -5%, 20%](log_js_console.gif)

---

# Text file

![:abs 150%, 0%, 50%](log_text_file.gif)

```
|#1|EVENT|App (re)started|FIRED|list(build = 139L)|186706c08e00bd118152e7b70c0ab64e|2019-01-29 07:15:13||
|#2|EVENT|Dataset was selected|FIRED|list(dataset = "iris", fun = "observer", resource = "input$dataset", build = 139L)|186706c08e00bd118152e7b70c0ab64e|2019-01-29 07:15:13|iris|
|#3|VALUE|input$dataset|FIRED|list(dataset = "iris", fun = "observer", resource = "input$dataset", build = 139L)|186706c08e00bd118152e7b70c0ab64e|2019-01-29 07:15:13|iris|
|#4|EVENT|Loading dataset|STARTED|list(dataset = "iris", fun = "reactive", resource = "dataset", build = 139L)|186706c08e00bd118152e7b70c0ab64e|2019-01-29 07:15:13||
|#4|EVENT|Loading dataset|DONE|list(secs = 0.05, dataset = "iris", fun = "reactive", resource = "dataset", build = 139L)|186706c08e00bd118152e7b70c0ab64e|2019-01-29 07:15:13||
|#5|VALUE|NROW(dataset)|FIRED|list(n_rows = 150L, dataset = "iris", fun = "reactive", resource = "dataset", build = 139L)|186706c08e00bd118152e7b70c0ab64e|2019-01-29 07:15:14|150|
```

---

# MongoDB

![:abs 70%, 10%, 20%](log_mongo_db.gif)

---
class: inverse, center, middle

# How to analyze the eventlog?
with process-mining techniques (bupaR package)

---

# Process maps

* patterns and paths in end-users' behaviors

![:abs 100%, 00%, 30%](analysis_process_map.gif)

---

# Time analysis

* throughput, idle, and processing time per dataset

![:abs 70%, 15%, 30%](analysis_time.gif)

---

# Sequence analysis

![:abs 80%, 10%, 15%](analysis_sequence.gif)

---

# Resource analysis

![:abs 60%, 20%, 20%](analysis_resource.gif)

---

# Top users' actions

![:abs 80%, 10%, 20%](analysis_top.gif)

---

class: inverse, center, middle

# What's next?

---

# Roadmap

* adding catching and logging __unexpected errors__

* adding __JSON__ as default serialization format for storing events   
(also in a file)

* improving integration with __MongoDB__

* adding ability to __show or hide__ selected part of event data

* adding a method for dynamically selecting which events should be logged __where and when__  
  * permanently to a database __vs.__ temporarily to a console
  * during developing & debugging __vs.__ in production environment
 
---
class:

# Thank you!

.footnote[
   
]

![:abs 25%, 65%, 65%](7n_logo.png)

* [github.com/kalimu/shinyEventLogger](https://github.com/kalimu/shinyEventLogger) - package repository
* [kalimu.github.io/shinyEventLogger/](https://kalimu.github.io/shinyEventLogger/index.html) - package documentation

## Contact:

* [kalimu.github.io](https://kalimu.github.io/)
* [www.linkedin.com/in/kamilwais](https://www.linkedin.com/in/kamilwais/)
* [kamil.wais@gmail.com](kamil.wais@gmail.com)

## [shinyapps.dev](https://www.shinyapps.dev/) blog
<div style = "font-size: 1.0em; display: block; margin-top: -30px">Developing Web Data Products in R & Shiny</div>

[7N.com](https://www.7n.com/) - Leading Agent for High-End IT Specialist