new register_handlers function

[pawelru]

close https://github.com/insightsengineering/coredev-tasks/issues/502 #69

I tried to use logger::log_messages() (and similar functions for warnings and errors) but I have encounter following problems:

• this is logging into the global logger namespace whereas we want particular (package) namespace instead - created an issue
• I cloned logger locally and fixed / enhanced the above but then I realized that the (global) message / warning / stop calls from the outside of a package will also log to that package logger namespace. In other words, these are global handlers for all the warnings and not only warnings created inside teal e.g.

r$> warning(1)
[WARN] 2024-01-26 15:58:17.0061 pid:83248 token:[] teal 1
Warning message:
1

Therefore I have decided to implement own register handlers mechanism. I initially started doing this separately inside each package but then I realised that it's not so DRY and decided to extend core teal.logger functionality.

This is not a reprex as I modified teal and teal.slice namespaces in a following way:

• added register_handlers(<pkg>) in both packages
• For debugging: added following definitions:
  • teal.slice:
    • teal_s_message calling message()
    • teal_s_warning calling warning()
    • teal_s_stop calling stop()
  • in teal:
    • teal_message calling message()
    • teal_warning calling warning()
    • teal_stop calling stop()
    • teal_message_nested calling teal_s_message() (so as to simulate teal calling teal.slice)
    • teal_warning_nested calling teal_s_warning()
    • teal_stop_nested calling teal_s_stop()

The outcome:

r$> devtools::load_all("teal.logger")
r$> devtools::load_all("teal.slice")
r$> devtools::load_all("teal")

r$> message(1)
1
r$> teal_message(1)
[INFO] 2024-01-26 15:57:40.8901 pid:83248 token:[] teal 1
1
r$> teal_s_message(1)
[INFO] 2024-01-26 15:57:42.1464 pid:83248 token:[] teal.slice 1
1
r$> teal_message_nested(1)
[INFO] 2024-01-26 15:57:50.9231 pid:83248 token:[] teal 1
[INFO] 2024-01-26 15:57:50.9257 pid:83248 token:[] teal.slice 1
1

r$> warning(2)
Warning message:
2 
r$> teal_s_warning(2)
[WARN] 2024-01-26 15:58:17.0061 pid:83248 token:[] teal.slice In ‘teal_s_warning(2)’: 2
Warning message:
In teal_s_warning(2) : 2
r$> teal_warning(2)
[WARN] 2024-01-26 15:58:18.4165 pid:83248 token:[] teal In ‘teal_warning(2)’: 2
Warning message:
In teal_warning(2) : 2
r$> teal_warning_nested(2)
[WARN] 2024-01-26 15:58:20.8666 pid:83248 token:[] teal In ‘teal.slice:::teal_s_warning(message)’: 2
[WARN] 2024-01-26 15:58:20.8685 pid:83248 token:[] teal.slice In ‘teal.slice:::teal_s_warning(message)’: 2
Warning message:
In teal.slice:::teal_s_warning(message) : 2

r$> stop(3)
Error: 3
r$> teal_s_stop(3)
[ERROR] 2024-01-26 15:58:32.9558 pid:83248 token:[] teal.slice In ‘teal_s_stop(3)’: 3
Error in teal_s_stop(3) : 3
r$> teal_stop(3)
[ERROR] 2024-01-26 15:58:33.5246 pid:83248 token:[] teal In ‘teal_stop(3)’: 3
Error in teal_stop(3) : 3
r$> teal_stop_nested(3)
[ERROR] 2024-01-26 15:58:34.0213 pid:83248 token:[] teal In ‘teal.slice:::teal_s_stop(message)’: 3
[ERROR] 2024-01-26 15:58:34.0226 pid:83248 token:[] teal.slice In ‘teal.slice:::teal_s_stop(message)’: 3
Error in teal.slice:::teal_s_stop(message) : 3

Interpretation (where "m/w/s" stands for "message / warning / stop"):

• global m/w/s is not impacted - we only capture m/w/s called from inside the package
• capturing m/w/s in the appropriate logger namespace - see it as a part of logger produced string - second last part
• the case of nested calls looks odd at the very first glance but I think it's correct. Each (package) logger instance might have its own log threshold, appender function, layout etc. It's expected to have duplicated logs for each of the registered package namespace found on the stack of calls. I'm interested in hearing your thoughts on this

PRs:

• register teal.logger handlers; replace few loggers with base teal#1081
• register teal.logger handlers; replace few loggers with base teal.goshawk#258
• register teal.logger handlers; replace log_info with message teal.modules.clinical#1010
• register teal.logger handlers teal.modules.general#628
• register teal.logger handlers teal.modules.hermes#354
• register teal.logger handlers teal.osprey#252
• register teal.logger handlers teal.slice#551
• register teal.logger handlers teal.transform#175

(I'll keep them as draft as this is conflicting with release plans because teal.logger would have to be released first)

TODO: tests - however I'm not yet sure how to make them "clean"

[pawelru]

Note to myself: this still requires some thinking. Both testthat2 as well as R CMD BUILD doesn't like this functionality and fail with the following: error: should not be called with handlers on the stack.

See also: https://cran.r-project.org/web/packages/progressr/vignettes/progressr-intro.html#:~:text=conditions%20are%20signaled.-,Because,-tryCatch()%20and

[github-actions]

Code Coverage Summary

Filename                 Stmts    Miss  Cover    Missing
---------------------  -------  ------  -------  ---------
R/register_handlers.R       39       0  100.00%
R/register_logger.R         56       1  98.21%   115
R/supress_logs.R             5       5  0.00%    17-21
R/utils.R                   20       0  100.00%
TOTAL                      120       6  95.00%

Diff against main

Filename                 Stmts    Miss  Cover
---------------------  -------  ------  --------
R/register_handlers.R      +39       0  +100.00%
R/utils.R                   +3       0  +100.00%
TOTAL                      +42       0  +5.00%

Results for commit: d99e6c6

Minimum allowed coverage is 80%

♻️ This comment has been updated with latest results

[github-actions]

Unit Tests Summary

 1 files   3 suites   0s ⏱️
25 tests 25 ✅ 0 💤 0 ❌
37 runs  37 ✅ 0 💤 0 ❌

Results for commit d99e6c6.

♻️ This comment has been updated with latest results.

[pawelru]

Note to myself: this still requires some thinking. Both testthat2 as well as R CMD BUILD doesn't like this functionality and fail with the following: error: should not be called with handlers on the stack.

See also: https://cran.r-project.org/web/packages/progressr/vignettes/progressr-intro.html#:~:text=conditions%20are%20signaled.-,Because,-tryCatch()%20and

Re: this. It's not super easy to identify when it's forbidden. After additional research I have found out that also pkgdown complains about this (so it's not only build and test). Therefore it would be difficult to specify a condition when this could be safely called. I decided to introduce a try block instead (and document it accordingly). This is not a solution that I am super proud of but it does the trick.

[gogonzo]

teal.goshawk and tmh still have logger::log_info feel free to create an issue and put it to our backlog if you have too much to do now

[pawelru]

teal.goshawk and tmh still have logger::log_info feel free to create an issue and put it to our backlog if you have too much to do now

I got it covered. Please have a look at the parent issue. It has all the PRs linked so it's easily findable.

UPDATE: actually they are also linked here in the top-message as well

[pawelru]

Hi @gogonzo
Please have a look at the latest commit. I made several changes focused on avoid the repetition you detected. These includes:

• have a new (private) registered_handlers_namespaces object storing name of packages registered - this is created in zzz.R and then used in the handler function itself
• create universal handler function as opposed to separate ones for each registered package. This should more efficient I believe as each of the condition (message / warning / error) will go through just one handler.
• Inside a handler function we loop through the bottom (!) of the stack and stop on a very first function that comes from pre-registered package - this will essentially prevent repetitions

An example (with not pushed test functions):

r$> setwd("teal")

r$> devtools::load_all("../teal.logger")
ℹ Loading teal.logger

r$> devtools::load_all("../teal.slice")
ℹ Loading teal.slice

r$> devtools::load_all(".")
ℹ Loading teal
Loading required package: shiny
Loading required package: teal.data
Loading required package: teal.code
Registered S3 method overwritten by 'teal':
  method        from      
  c.teal_slices teal.slice
[INFO] 2024-03-19 17:42:12.8201 pid:31547 token:[] teal You are using teal version 0.15.2.9004

r$> message(1)
1

r$> test_message()
[INFO] 2024-03-19 17:42:30.2534 pid:31547 token:[] teal This is a teal message.

r$> teal.slice:::test_message()
[INFO] 2024-03-19 17:42:48.5948 pid:31547 token:[] teal.slice This is a teal.slice message.

r$> test_nested_message()
[INFO] 2024-03-19 17:42:59.7324 pid:31547 token:[] teal.slice This is a teal.slice message.

r$> test_nested_message
function() {
  teal.slice:::test_message()
}
<environment: namespace:teal>

[gogonzo]

Thanks for addressing my old issue. I've tested on teal.gallery apps, everything looks good. Only this "plotly warning" somehow gets through - I hope someday we will get rid of this ;)