new register_handlers function

pawelru commented 9 months ago

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:

(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 commented 8 months ago

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.

github-actions[bot] commented 8 months ago

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: d99e6c6cb076cee2962251d6c79c67d060bd5fc4

Minimum allowed coverage is 80%

:recycle: This comment has been updated with latest results

github-actions[bot] commented 8 months ago

Unit Tests Summary

1 files 3 suites 0s :stopwatch: 25 tests 25 :white_check_mark: 0 :zzz: 0 :x: 37 runs 37 :white_check_mark: 0 :zzz: 0 :x:

Results for commit d99e6c6c.

:recycle: This comment has been updated with latest results.

pawelru commented 8 months ago

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.

github-actions[bot] commented 7 months ago

Unit Test Performance Difference

Test Suite	$Status$	Time on `main`	$±Time$	$±Tests$	$±Skipped$	$±Failures$	$±Errors$
register_handlers	👶		$+0.15$	$+20$	$0$	$0$	$0$
utils	👶		$+0.03$	$+7$	$0$	$0$	$0$

Additional test case details

| Test Suite | $Status$ | Time on `main` | $±Time$ | Test Case | |:-----|:----:|:----:|:----:|:-----| | register_handlers | 👶 | | $+0.05$ | parse_logger_message_correctly_works_on_condition_object | | register_handlers | 👶 | | $+0.01$ | parse_logger_message_includes_call_on_warnings_and_errors | | register_handlers | 👶 | | $+0.01$ | parse_logger_message_throws_if_not_supported_class_of_argument | | register_handlers | 👶 | | $+0.01$ | register_handlers_has_no_effect_if_called_multiple_times | | register_handlers | 👶 | | $+0.00$ | register_handlers_is_not_called_when_within_a_try_block | | register_handlers | 👶 | | $+0.00$ | register_handlers_is_not_called_when_within_a_withCallingHandlers_block | | register_handlers | 👶 | | $+0.01$ | register_handlers_modifies_global_handlers | | register_handlers | 👶 | | $+0.01$ | register_handlers_throws_if_not_pre_registered_logger_namespace | | register_handlers | 👶 | | $+0.02$ | register_handlers_throws_on_incorrect_namespace_argument_value | | register_handlers | 👶 | | $+0.02$ | register_handlers_throws_on_incorrect_package_argument_value | | register_logger | 👶 | | $+0.01$ | register_logger_accepts_a_character | | register_logger | 💀 | $0.01$ | $-0.01$ | register_logger_accepts_a_scalar_character | | utils | 👶 | | $+0.01$ | get_val_correctly_reads_envvar | | utils | 👶 | | $+0.01$ | get_val_default_accepts_different_types_of_data | | utils | 👶 | | $+0.00$ | get_val_uses_envvar_if_both_envvar_and_option_are_available | | utils | 👶 | | $+0.00$ | get_val_uses_option_if_envvar_is_missing | | utils | 👶 | | $+0.00$ | get_val_uses_the_default_if_both_envvar_and_option_are_missing |

Results for commit a1f43e8a79ab601213eff87369e3c96a5b5e66eb

♻️ This comment has been updated with latest results.

pawelru commented 7 months ago

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 commented 7 months ago

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>

insightsengineering / teal.logger