From f878525b5e20e4312cb1113465af3817db30927a Mon Sep 17 00:00:00 2001 From: daroczig Date: Thu, 22 Aug 2024 20:04:10 +0000 Subject: [PATCH] =?UTF-8?q?Deploying=20to=20gh-pages=20from=20@=20daroczig?= =?UTF-8?q?/logger@59b1544830424638a21ba66aae0a92ff7a604377=20=F0=9F=9A=80?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- articles/Intro.html | 38 ++++++------- articles/anatomy.html | 10 ++-- articles/customize_logger.html | 76 +++++++++++++------------- articles/migration.html | 84 ++++++++++++++--------------- articles/r_packages.html | 2 +- pkgdown.yml | 2 +- reference/grapes-except-grapes.html | 14 ++--- reference/layout_glue_colors.html | 16 +++--- reference/log_separator.html | 8 +-- reference/log_with_separator.html | 6 +-- reference/logger-package.html | 84 +++++++++++++++++++++++++++++ search.json | 2 +- sitemap.xml | 1 + 13 files changed, 214 insertions(+), 129 deletions(-) create mode 100644 reference/logger-package.html diff --git a/articles/Intro.html b/articles/Intro.html index aee42c0..18695c7 100644 --- a/articles/Intro.html +++ b/articles/Intro.html @@ -87,15 +87,15 @@
 library(logger)
 log_info("Loading data")
-#> INFO [2024-08-22 20:01:51] Loading data
+#> INFO [2024-08-22 20:03:54] Loading data
 data(mtcars)
 log_info("The dataset includes {nrow(mtcars)} rows")
-#> INFO [2024-08-22 20:01:51] The dataset includes 32 rows
+#> INFO [2024-08-22 20:03:54] The dataset includes 32 rows
 if (max(mtcars$hp) < 1000) {
   log_warn("Oh, no! There are no cars with more than 1K horsepower in the dataset :/")
   log_debug("The most powerful car is {rownames(mtcars)[which.max(mtcars$hp)]} with {max(mtcars$hp)} hp")
 }
-#> WARN [2024-08-22 20:01:51] Oh, no! There are no cars with more than 1K horsepower in the dataset :/
+#> WARN [2024-08-22 20:03:54] Oh, no! There are no cars with more than 1K horsepower in the dataset :/

Interestingly, the most powerful car was not being logged – because by default the logger prints messages with at least the INFO log level:

@@ -109,16 +109,16 @@

The rerunning the above code chunk:

 log_info("Loading data")
-#> INFO [2024-08-22 20:01:51] Loading data
+#> INFO [2024-08-22 20:03:54] Loading data
 data(mtcars)
 log_info("The dataset includes {nrow(mtcars)} rows")
-#> INFO [2024-08-22 20:01:51] The dataset includes 32 rows
+#> INFO [2024-08-22 20:03:54] The dataset includes 32 rows
 if (max(mtcars$hp) < 1000) {
   log_warn("Oh, no! There are no cars with more than 1K horsepower in the dataset :/")
   log_debug("The most powerful car is {rownames(mtcars)[which.max(mtcars$hp)]} with {max(mtcars$hp)} hp")
 }
-#> WARN [2024-08-22 20:01:51] Oh, no! There are no cars with more than 1K horsepower in the dataset :/
-#> DEBUG [2024-08-22 20:01:51] The most powerful car is Maserati Bora with 335 hp
+#> WARN [2024-08-22 20:03:54] Oh, no! There are no cars with more than 1K horsepower in the dataset :/ +#> DEBUG [2024-08-22 20:03:54] The most powerful car is Maserati Bora with 335 hp

You may also find the ?log_eval function useful to log both an R expression and its result in the same log record:

@@ -126,7 +126,7 @@
 g <- mean
 x <- 1:31
 log_eval(y <- f(g(x)), level = INFO)
-#> INFO [2024-08-22 20:01:51] 'y <- f(g(x))' => '4'
+#> INFO [2024-08-22 20:03:54] 'y <- f(g(x))' => '4'
 str(y)
 #>  num 4

Sometimes, it may be reasonable to log R objects as markdown, e.g. a @@ -136,17 +136,17 @@

 log_formatter(formatter_pander)
 log_info(head(iris))
-#> INFO [2024-08-22 20:01:51] 
-#> INFO [2024-08-22 20:01:51] 
-#> INFO [2024-08-22 20:01:51]  Sepal.Length   Sepal.Width   Petal.Length   Petal.Width   Species 
-#> INFO [2024-08-22 20:01:51] -------------- ------------- -------------- ------------- ---------
-#> INFO [2024-08-22 20:01:51]      5.1            3.5           1.4            0.2       setosa  
-#> INFO [2024-08-22 20:01:51]      4.9             3            1.4            0.2       setosa  
-#> INFO [2024-08-22 20:01:51]      4.7            3.2           1.3            0.2       setosa  
-#> INFO [2024-08-22 20:01:51]      4.6            3.1           1.5            0.2       setosa  
-#> INFO [2024-08-22 20:01:51]       5             3.6           1.4            0.2       setosa  
-#> INFO [2024-08-22 20:01:51]      5.4            3.9           1.7            0.4       setosa  
-#> INFO [2024-08-22 20:01:51]
+#> INFO [2024-08-22 20:03:54] +#> INFO [2024-08-22 20:03:54] +#> INFO [2024-08-22 20:03:54] Sepal.Length Sepal.Width Petal.Length Petal.Width Species +#> INFO [2024-08-22 20:03:54] -------------- ------------- -------------- ------------- --------- +#> INFO [2024-08-22 20:03:54] 5.1 3.5 1.4 0.2 setosa +#> INFO [2024-08-22 20:03:54] 4.9 3 1.4 0.2 setosa +#> INFO [2024-08-22 20:03:54] 4.7 3.2 1.3 0.2 setosa +#> INFO [2024-08-22 20:03:54] 4.6 3.1 1.5 0.2 setosa +#> INFO [2024-08-22 20:03:54] 5 3.6 1.4 0.2 setosa +#> INFO [2024-08-22 20:03:54] 5.4 3.9 1.7 0.4 setosa +#> INFO [2024-08-22 20:03:54]

For more details, check the function reference in the manual, or start with the The Anatomy of a Log Request and Customizing diff --git a/articles/anatomy.html b/articles/anatomy.html index ec4deb8..8403c3f 100644 --- a/articles/anatomy.html +++ b/articles/anatomy.html @@ -117,7 +117,7 @@ #> [1] "f()" #> #> $time -#> [1] "2024-08-22 20:01:44 UTC" +#> [1] "2024-08-22 20:03:47 UTC" #> #> $levelr #> Log level: INFO @@ -126,7 +126,7 @@ #> [1] "INFO" #> #> $pid -#> [1] 7670 +#> [1] 7711 #> #> $r_version #> [1] "4.4.1" @@ -135,7 +135,7 @@ #> [1] NA #> #> $node -#> [1] "fv-az1121-872" +#> [1] "fv-az566-657" #> #> $arch #> [1] "x86_64" @@ -166,7 +166,7 @@ ERROR <= INFO #> [1] TRUE log_error("Oops") -#> ERROR [2024-08-22 20:01:44] Oops +#> ERROR [2024-08-22 20:03:47] Oops

  • formatter function, which takes R objects and @@ -211,7 +211,7 @@ log_appender(appender_stdout) log_debug("I am a low level log message that will not be printed with a high log level threshold") log_warn("I am a higher level log message that is very likely to be printed") -#> WARN [2024-08-22 20:01:44] I am a higher level log message that is very likely to be printed +#> WARN [2024-08-22 20:03:47] I am a higher level log message that is very likely to be printed

    Note, that all logger definitions and requests are tied to a logging namespace, and one log request might trigger multiple logger definitions as well (stacking). Find more diff --git a/articles/customize_logger.html b/articles/customize_logger.html index c6376d6..e6afb1b 100644 --- a/articles/customize_logger.html +++ b/articles/customize_logger.html @@ -87,13 +87,13 @@

    What gets logged?
     log_info("Hi, there!")
    -#> INFO [2024-08-22 20:01:47] Hi, there!
    +#> INFO [2024-08-22 20:03:51] Hi, there!
     log_debug("How are you doing today?")
     log_threshold()
     #> Log level: INFO
     log_threshold(TRACE)
     log_debug("How are you doing today?")
    -#> DEBUG [2024-08-22 20:01:47] How are you doing today?
    +#> DEBUG [2024-08-22 20:03:51] How are you doing today?

    So the ?log_threshold function can both get and set the log level threshold for all future log requests.

    For the full list of all supported log levels and so thus the @@ -102,19 +102,19 @@

    What gets logged??log_level, eg

     log_level(INFO, "Hi, there!")
    -#> INFO [2024-08-22 20:01:47] Hi, there!
    +#> INFO [2024-08-22 20:03:51] Hi, there!

    To temporarily update the log level threshold, you may also find the ?with_log_threshold function useful:

     log_threshold(INFO)
     log_debug("pst, can you hear me?")
     log_info("no")
    -#> INFO [2024-08-22 20:01:47] no
    +#> INFO [2024-08-22 20:03:51] no
     
     with_log_threshold(log_debug("pst, can you hear me?"), threshold = TRACE)
    -#> DEBUG [2024-08-22 20:01:47] pst, can you hear me?
    +#> DEBUG [2024-08-22 20:03:51] pst, can you hear me?
     log_info("yes")
    -#> INFO [2024-08-22 20:01:47] yes
    +#> INFO [2024-08-22 20:03:51] yes
     
     with_log_threshold(
       {
    @@ -123,8 +123,8 @@ 

    What gets logged? }, threshold = TRACE ) -#> DEBUG [2024-08-22 20:01:47] pst, can you hear me? -#> INFO [2024-08-22 20:01:47] yes

    +#> DEBUG [2024-08-22 20:03:51] pst, can you hear me? +#> INFO [2024-08-22 20:03:51] yes

    You can also define your own log level(s) if needed, for example introducing an extra level between DEBUG and INFO:

    @@ -133,9 +133,9 @@

    What gets logged?log_threshold(FYI) log_debug("ping") log_level(FYI, "ping") -#> FYI [2024-08-22 20:01:47] ping +#> FYI [2024-08-22 20:03:51] ping log_info("pong") -#> INFO [2024-08-22 20:01:47] pong +#> INFO [2024-08-22 20:03:51] pong

    Log namespaces @@ -153,16 +153,16 @@

    Log namespaceslog_threshold(INFO) log_trace("Hi, there!", namespace = "kitchensink") log_info("Hi, there!", namespace = "kitchensink") -#> INFO [2024-08-22 20:01:47] Hi, there!

    +#> INFO [2024-08-22 20:03:51] Hi, there!

    But once you start customizing that namespace, it gets forked from the global settings and live on its own without modifying the original namespace:

     log_threshold(TRACE, namespace = "kitchensink")
     log_trace("Hi, there!", namespace = "kitchensink")
    -#> TRACE [2024-08-22 20:01:48] Hi, there!
    +#> TRACE [2024-08-22 20:03:51] Hi, there!
     log_info("Hi, there!", namespace = "kitchensink")
    -#> INFO [2024-08-22 20:01:48] Hi, there!
    +#> INFO [2024-08-22 20:03:51] Hi, there!
     log_trace("Hi, there!")
    @@ -177,9 +177,9 @@

    Log message formatter functions
     log_formatter(formatter_glue)
     log_info("There are {nrow(mtcars)} cars in the mtcars dataset")
    -#> INFO [2024-08-22 20:01:48] There are 32 cars in the mtcars dataset
    +#> INFO [2024-08-22 20:03:51] There are 32 cars in the mtcars dataset
     log_info("2 + 2 = {2+2}")
    -#> INFO [2024-08-22 20:01:48] 2 + 2 = 4

    +#> INFO [2024-08-22 20:03:51] 2 + 2 = 4

    If you don’t like this syntax, or want to save a dependency, you can use other formatter functions as well, such as ?formatter_sprintf (being the default in eg the logging @@ -196,15 +196,15 @@

    Log message layouts
     log_info(42)
    -#> INFO [2024-08-22 20:01:48] 42
    +#> INFO [2024-08-22 20:03:51] 42
     log_info("The answer is {42}")
    -#> INFO [2024-08-22 20:01:48] The answer is 42
    +#> INFO [2024-08-22 20:03:51] The answer is 42
     log_info("The answers are {1:5}")
    -#> INFO [2024-08-22 20:01:48] The answers are 1
    -#> INFO [2024-08-22 20:01:48] The answers are 2
    -#> INFO [2024-08-22 20:01:48] The answers are 3
    -#> INFO [2024-08-22 20:01:48] The answers are 4
    -#> INFO [2024-08-22 20:01:48] The answers are 5
    +#> INFO [2024-08-22 20:03:51] The answers are 1 +#> INFO [2024-08-22 20:03:51] The answers are 2 +#> INFO [2024-08-22 20:03:51] The answers are 3 +#> INFO [2024-08-22 20:03:51] The answers are 4 +#> INFO [2024-08-22 20:03:51] The answers are 5

    In the above example, first, 42 was converted to a string by the ?formatter_glue message formatter, then the message was passed to the ?layout_simple layout function to @@ -214,15 +214,15 @@

    Log message layouts
     log_layout(layout_json())
     log_info(42)
    -#> {"time":"2024-08-22 20:01:48","level":"INFO","ns":"global","ans":"global","topenv":"R_GlobalEnv","fn":"eval","node":"fv-az1121-872","arch":"x86_64","os_name":"Linux","os_release":"6.5.0-1025-azure","os_version":"#26~22.04.1-Ubuntu SMP Thu Jul 11 22:33:04 UTC 2024","pid":7741,"user":"runner","msg":"42"}
    +#> {"time":"2024-08-22 20:03:51","level":"INFO","ns":"global","ans":"global","topenv":"R_GlobalEnv","fn":"eval","node":"fv-az566-657","arch":"x86_64","os_name":"Linux","os_release":"6.5.0-1025-azure","os_version":"#26~22.04.1-Ubuntu SMP Thu Jul 11 22:33:04 UTC 2024","pid":7781,"user":"runner","msg":"42"}
     log_info("The answer is {42}")
    -#> {"time":"2024-08-22 20:01:48","level":"INFO","ns":"global","ans":"global","topenv":"R_GlobalEnv","fn":"eval","node":"fv-az1121-872","arch":"x86_64","os_name":"Linux","os_release":"6.5.0-1025-azure","os_version":"#26~22.04.1-Ubuntu SMP Thu Jul 11 22:33:04 UTC 2024","pid":7741,"user":"runner","msg":"The answer is 42"}
    +#> {"time":"2024-08-22 20:03:51","level":"INFO","ns":"global","ans":"global","topenv":"R_GlobalEnv","fn":"eval","node":"fv-az566-657","arch":"x86_64","os_name":"Linux","os_release":"6.5.0-1025-azure","os_version":"#26~22.04.1-Ubuntu SMP Thu Jul 11 22:33:04 UTC 2024","pid":7781,"user":"runner","msg":"The answer is 42"}
     log_info("The answers are {1:5}")
    -#> {"time":"2024-08-22 20:01:48","level":"INFO","ns":"global","ans":"global","topenv":"R_GlobalEnv","fn":"eval","node":"fv-az1121-872","arch":"x86_64","os_name":"Linux","os_release":"6.5.0-1025-azure","os_version":"#26~22.04.1-Ubuntu SMP Thu Jul 11 22:33:04 UTC 2024","pid":7741,"user":"runner","msg":"The answers are 1"}
    -#> {"time":"2024-08-22 20:01:48","level":"INFO","ns":"global","ans":"global","topenv":"R_GlobalEnv","fn":"eval","node":"fv-az1121-872","arch":"x86_64","os_name":"Linux","os_release":"6.5.0-1025-azure","os_version":"#26~22.04.1-Ubuntu SMP Thu Jul 11 22:33:04 UTC 2024","pid":7741,"user":"runner","msg":"The answers are 2"}
    -#> {"time":"2024-08-22 20:01:48","level":"INFO","ns":"global","ans":"global","topenv":"R_GlobalEnv","fn":"eval","node":"fv-az1121-872","arch":"x86_64","os_name":"Linux","os_release":"6.5.0-1025-azure","os_version":"#26~22.04.1-Ubuntu SMP Thu Jul 11 22:33:04 UTC 2024","pid":7741,"user":"runner","msg":"The answers are 3"}
    -#> {"time":"2024-08-22 20:01:48","level":"INFO","ns":"global","ans":"global","topenv":"R_GlobalEnv","fn":"eval","node":"fv-az1121-872","arch":"x86_64","os_name":"Linux","os_release":"6.5.0-1025-azure","os_version":"#26~22.04.1-Ubuntu SMP Thu Jul 11 22:33:04 UTC 2024","pid":7741,"user":"runner","msg":"The answers are 4"}
    -#> {"time":"2024-08-22 20:01:48","level":"INFO","ns":"global","ans":"global","topenv":"R_GlobalEnv","fn":"eval","node":"fv-az1121-872","arch":"x86_64","os_name":"Linux","os_release":"6.5.0-1025-azure","os_version":"#26~22.04.1-Ubuntu SMP Thu Jul 11 22:33:04 UTC 2024","pid":7741,"user":"runner","msg":"The answers are 5"}
    +#> {"time":"2024-08-22 20:03:51","level":"INFO","ns":"global","ans":"global","topenv":"R_GlobalEnv","fn":"eval","node":"fv-az566-657","arch":"x86_64","os_name":"Linux","os_release":"6.5.0-1025-azure","os_version":"#26~22.04.1-Ubuntu SMP Thu Jul 11 22:33:04 UTC 2024","pid":7781,"user":"runner","msg":"The answers are 1"} +#> {"time":"2024-08-22 20:03:51","level":"INFO","ns":"global","ans":"global","topenv":"R_GlobalEnv","fn":"eval","node":"fv-az566-657","arch":"x86_64","os_name":"Linux","os_release":"6.5.0-1025-azure","os_version":"#26~22.04.1-Ubuntu SMP Thu Jul 11 22:33:04 UTC 2024","pid":7781,"user":"runner","msg":"The answers are 2"} +#> {"time":"2024-08-22 20:03:51","level":"INFO","ns":"global","ans":"global","topenv":"R_GlobalEnv","fn":"eval","node":"fv-az566-657","arch":"x86_64","os_name":"Linux","os_release":"6.5.0-1025-azure","os_version":"#26~22.04.1-Ubuntu SMP Thu Jul 11 22:33:04 UTC 2024","pid":7781,"user":"runner","msg":"The answers are 3"} +#> {"time":"2024-08-22 20:03:51","level":"INFO","ns":"global","ans":"global","topenv":"R_GlobalEnv","fn":"eval","node":"fv-az566-657","arch":"x86_64","os_name":"Linux","os_release":"6.5.0-1025-azure","os_version":"#26~22.04.1-Ubuntu SMP Thu Jul 11 22:33:04 UTC 2024","pid":7781,"user":"runner","msg":"The answers are 4"} +#> {"time":"2024-08-22 20:03:51","level":"INFO","ns":"global","ans":"global","topenv":"R_GlobalEnv","fn":"eval","node":"fv-az566-657","arch":"x86_64","os_name":"Linux","os_release":"6.5.0-1025-azure","os_version":"#26~22.04.1-Ubuntu SMP Thu Jul 11 22:33:04 UTC 2024","pid":7781,"user":"runner","msg":"The answers are 5"}

    If you need colorized logs highlighting the important log messages, check out ?layout_glue_colors, and for other formatter and layout functions, see the manual of the above mentioned functions that @@ -255,14 +255,14 @@

    Custom log record layout
     log_info("foo")
    -#> fv-az1121-872/7741/global/eval 2024-08-22 20:01:48.401558 INFO: foo
    +#> fv-az566-657/7781/global/eval 2024-08-22 20:03:51.771529 INFO: foo

  • check what’s being logged when called from a custom function:

     f <- function() log_info("foo")
     f()
    -#> fv-az1121-872/7741/global/f 2024-08-22 20:01:48.466931 INFO: foo
    +#> fv-az566-657/7781/global/f 2024-08-22 20:03:51.837484 INFO: foo
  • check what’s being logged when called from a package:

    @@ -270,7 +270,7 @@

    Custom log record layoutdevtools::load_all(system.file("demo-packages/logger-tester-package", package = "logger")) #> Loading logger.tester logger_tester_function(INFO, "hi from tester package") -#> fv-az1121-872/7741/logger.tester/logger_tester_function 2024-08-22 20:01:48.645798 INFO: hi from tester package 0.0807501375675201 +#> fv-az566-657/7781/logger.tester/logger_tester_function 2024-08-22 20:03:52.022768 INFO: hi from tester package 0.0807501375675201

  • suppress messages in a namespace:

    @@ -280,9 +280,9 @@

    Custom log record layoutlog_threshold(WARN, namespace = "logger.tester") logger_tester_function(INFO, "hi from tester package") logger_tester_function(WARN, "hi from tester package") -#> fv-az1121-872/7741/logger.tester/logger_tester_function 2024-08-22 20:01:48.716606 WARN: hi from tester package 0.0807501375675201 +#> fv-az566-657/7781/logger.tester/logger_tester_function 2024-08-22 20:03:52.095184 WARN: hi from tester package 0.0807501375675201 log_info("I am still working in the global namespace") -#> fv-az1121-872/7741/global/eval 2024-08-22 20:01:48.718426 INFO: I am still working in the global namespace +#> fv-az566-657/7781/global/eval 2024-08-22 20:03:52.096981 INFO: I am still working in the global namespace

  • Another example of making use of the generator function is to update @@ -349,7 +349,7 @@

    Delivering log records to t log_appender() #> appender_file(file = t) readLines(t) -#> [1] "INFO [2024-08-22 20:01:48] where is this message going?" +#> [1] "INFO [2024-08-22 20:03:52] where is this message going?" unlink(t)

    There’s a similar generator function that returns an appender function delivering log messages to Slack channels:

    @@ -403,12 +403,12 @@

    Stacking loggers ## test both loggers log_info("info msg") -#> INFO [2024-08-22 20:01:49] info msg +#> INFO [2024-08-22 20:03:52] info msg log_debug("info msg") readLines(t) -#> [1] "INFO [2024-08-22 20:01:49] info msg" -#> [2] "DEBUG [2024-08-22 20:01:49] info msg" +#> [1] "INFO [2024-08-22 20:03:52] info msg" +#> [2] "DEBUG [2024-08-22 20:03:52] info msg" unlink(t)