zatonovo / futile.logger Goto Github PK

One could color errors in red, warnings in yellow, debug messages in grey, etc.

The crayon package would seem to fit the bill to implement this kind of thing fairly nicely.

I was logging some messages including a percentage sign, which was working fine until the most recent (1.4) release. E.g. demo with futile.logger_1.3.7:

> flog.debug('%m')
DEBUG [2015-04-15 20:49:02] %m

But now with futile.logger_1.4:

> flog.debug('%m')
Error in (function (fmt, ...)  : unrecognised format specification '%m'
> flog.debug("%a")
Error in (function (fmt, ...)  : too few arguments

This is not really an issue, rather than question how to apply futile.logger as R package author:

I am looking for some references teaching me how to embed futile.logger functionality into an R package.

Use case:
The R package will provide funtions to the user.
The user of the package shall be able to define the file location and threshold of logging.

Thx for some helpful pointers.

For a custom json layout based on the package json.layout and layout.format functions, the first unnamed argument is passed as id.

custom.json <- function(level, msg, id='', ...) {

  if (!is.null(substitute(...))) msg <- sprintf(msg, ...)
  output_list <- list(
    level = jsonlite::unbox(names(level)),
    timestamp = jsonlite::unbox(format(Sys.time(), "%Y-%m-%d %H:%M:%S %z")),
    message = jsonlite::unbox(msg),
    func = jsonlite::unbox('unavailable') # haven't worked this out
)
return(sprintf("%s\n", jsonlite::toJSON(output_list, simplifyVector=TRUE)))

}

flog.layout(custom.json)
flog.info('%s ', 'test')
{"level":"INFO","timestamp":"2018-09-11 17:20:50 -0400", "message":"%s ","func":"unavailable"}
flog.info('%s ', 'test', 'test2')
{"level":"INFO","timestamp":"2018-09-11 17:20:56 -0400", "message":"test2 ", "func":"unavailable"}

Removing the id argument from the custom.json function resolves this issue, but I'm not sure why it works since the layout.format seems to be called without any issues using the same signature.

Hi Zatonovo,
I implemented python style logging in R using futile.logger. My log prints like below but i need some layout change on the logging
DEBUG[yyyy-mm-dd hh:mm:ss] message..
Will i be able to change the format to print the date first using futile.logger
[yyyy-mm-dd hh:mm:ss]DEBUG:Message
https://gist.github.com/jonathancallahan/a03b9ee7c1817d74803447856c64e518

I have some code in a package I'm writing (called "WindOps"), and I added some calls to flog.info() in a few functions. In my unit tests, I wanted to turn off the logging, so I put a call to flog.threshold(ERROR, "WindOps") in the tests. However, this didn't shut off the logging.

I discovered that the logger thinks it's in the devtools namespace by adding this code to a logger in a package function:

flog.info("Logging from %s", flog.namespace())

That emits:

INFO [2016-09-07 21:58:49] Logging from devtools

So it seems like flog.namespace() can be fooled somehow?

I use futile.logger a lot in my parallel scripts, all of which use package future to handle multiprocessing.
flog.* of course works well in this case when logging to a file, but does not for logging to the terminal: all messages are relayed at the end of the future.

Is there any way this could be accomplished?

If I use the current CRAN-version it appears that the appender.file2-function is missing.

When I use the current GitHub-version (using devtools::intstall_github("zatonovo/futile.logger")) everything works as expected.

Unfortunately, I am relying on a CRAN-installation, any way around this error?

The error should be reproduced by:

# install.packages("futile.logger")
library(futile.logger)
packageVersion("futile.logger")
#> [1] '1.4.3'

flog.appender(appender.file2("mylog.log", console=TRUE), name='mylogger')
#> Error in appender.file2("mylog.log", console = TRUE): could not find function "appender.file2"

Hi, Thanks for this great add-on.

Is it possible to support daily/periodically file logging rollover like other language logging framework (for example log4j)

Thanks

Hi Brian,

Would it be possible to have an easily accessible feature, such as a switch that can be toggled, to make futile.logger send the output to console concurrently with a file.

This feature can come in handy in cases when R crashes and you are unable to copy the log from screen.

Cheers!

Hi,

I often find myself writing code to catch the name of the executing function, e.g.:

flog.debug('made it past input checks in %s', as.character(match.call()[[1]]));

Would it be possible to have a shortcut to this, so perhaps something like:

flog.debug('Value of x in %f is %s', x)

First of all, thank you very much for this extremely useful package!

I am using it in several packages to auto-generate logs on what data transformations were done at my projects. Things are getting complicated as the number of functions grew, and it turned out that it might not be the best idea to flog.info the number of rows fetched from a database when such query occurs a dozen times in another function, where I'd like to focus on some other items to be logged as INFO, and keep the previous INFO messages as rather DEBUG. This is a simple example, but this can get complicated, believe me :)

In short, I'd like to check if I'm logging in nested or top-level function, and return messages of nested functions with a lower priority. Unfortunately it's not (easily) possible via the flog.info, flog.debug etc. functions -- can we have a flog function that takes the logs with the level specified as an argument?

I noticed that most of the time in flog.trace() etal is spent in flog.namespace(). For instance:

Testing the logger functions directly:

flog.threshold(INFO)

Default:

Rprof(line.profiling = TRUE)
for (i in 1:20000) { flog.trace("A message") }
Rprof(NULL)
summaryRprof(lines = "both") # 28.58 seconds

Avoiding flog.namespace():

Rprof(line.profiling = TRUE)
for (i in 1:20000) { flog.trace("A message", name = 'ROOT') }
Rprof(NULL)
summaryRprof(lines = "both") # 3.98 seconds

So 80-90 % of the time is spent in getting the name of the name space. Profiling flog.namespace() directly, indicated that it is in capture.output() and/or str() the time is spent. Looking into the code of str(), I saw that for environments, it basically does format(), so I tested with an alternative way of getting the string representation of the environment, i.e. instead of

s <- capture.output(str(topenv(environment(sys.function(where))), give.attr=FALSE))

I tried

s <- format(topenv(environment(sys.function(where))))

Profiling showed that the alternative implementation of flog.namespace() is much faster:

Testing flog.namespace() directly:

Rprof(line.profiling = TRUE)
for (i in 1:20000) { tmp <- flog.namespace() }
Rprof(NULL)
summaryRprof(lines = "both") # 14.82 seconds

Alternative flog.namespace() directly:

Rprof(line.profiling = TRUE)
for (i in 1:20000) { tmp <- flog.namespace2() }
Rprof(NULL)
summaryRprof(lines = "both") # 3.32 seconds

And when using the alternative flog.namespace() in flog.trace(), it ran about twice as fast as before:

With alternative flog.namespace():

Rprof(line.profiling = TRUE)
for (i in 1:20000) { flog.trace2("A message") }
Rprof(NULL)
summaryRprof(lines = "both") # 17.14 seconds.

My understanding of environments etc is not perfect, so I cannot guarantee that the alternative will work in all cases, but at least it seems to work for the cases I've tested.

The reason for suggesting the optimisation is that I tend to put a lot of trace messages in my code while developing it, and then increase the log level when actually using the code. Therefore I don't want too much overhead of logging calls, at least not when they don't print anything. (I had a case where 97 % of the time was spent inside flog.trace() when the threshold was INFO.)

I have a need to write to multiple log files which correspond to different threshold levels. We have log files that get progressively more detailed. So we have a log file for TRACE and higher, a log file for INFO and higher, and a log file for ERROR and higher.

I could build loggers for each of these like:

flog.logger(name='trace',threshold=TRACE, appender=appender.file('trace.txt'))
flog.logger(name='info',threshold=INFO, appender=appender.file('info.txt'))
flog.logger(name='error',threshold=ERROR, appender=appender.file('error.txt'))

but then I have to litter my code with a bunch of statements like:

flog.info('test', name = 'trace')
flog.info('test', name = 'info')
flog.info('test', name = 'error')

Ideally, I'd write one flog.info method and it logs to all of my appenders.

Maybe I'm doing it wrong. Can multiple appenders by added to a log based on thresholds? It looks like log4j supports that functionality but I cant figure it out with this package. Or is there another approach to take? Any help would be great.

Hi,

I'm using Futile Logger with the root logger, but with a tee.appender to both console and to a log file.

I've set R options so that console errors also get written to the log via:
options(error = function() { flog.error(geterrmessage()) ; traceback() ; stop() })

On a fresh install of my software an R system error would also generate a package error flog.logger not found

After some investigation is seems that using lambda.r_1.1.9 does not generate this error, but 1.2.x does.

I'm guessing it's some sort of namespace error?

Best
Alan

PS - thanks for the great package!

What's the best way to log a dataframe to a file? I found this question in SO and tried doing something like

    flog.logger(name = "logger", threshold = DEBUG,
                        appender = appender.tee(file.path(LOG_DIR, "transform.log")))
    flog.info(write.table(df, sep="\t"), name = "logger")

However I doesn't seem to do the trick. Thanks in advance

I can override the default R error handling for a non-interactive program by doing options(error = function() { flog.error(geterrmessage()) ; quit(runLast=FALSE)})

However I did not find how to do the same for warnings. Is this possible?

This stack overflow question basically poses the same question, but the accepted answer does not seem to work for me.

The conversion to roxygen2 has omitted the usage sections of the Rd files.

Makes life a whole lot easier. After this is implemented, simply update the .Rd files using roxygenize('.'). RStudio can do this automatically.

If a log message is below current threshold, exit early and avoid evaluation to improve performance.

Hi,

Awesome tool.

I am trying to log errors from within a function in a sourced script.

ftry(myfunction,error = 
       function(e) {
          call.stack <- sys.calls()   
          log.message <- e$message
          flog.error(log.message)
                         })

But in spite of errors, nothing is written to the log. Can you advise me on how to use FTRY in this context?

Thanks again for an awesome tool!

The DESCRIPTION file is a template as of revision 770683a. This is unfortunate, as this makes installation from GitHub using devtools's install_github() function impossible. I'm sure there is some magic that replaces the {date} and {version} placeholders with their values, but where?

Perhaps this could be replaced by an "update" magic: Always store the current value in the code, and provide a script that sets date and version to new values?

I want to configure the logging level based on strings, e.g. "WARN", but flog.threshold(..) only accepts the numbers that are accessible via the global constants such as futile.logger::TRACE. I wrote the following small helper function, but I'm sure you could also easily change flog.threshold to accept string values in the same way.

getLoglevelForName <- function(x) {
    name <- tolower(x)

    level <- switch(x, "trace" = futile.logger::TRACE,
                    "debug" = futile.logger::DEBUG,
                    "warn" = futile.logger::WARN,
                    "info" = futile.logger::INFO,
                    "error" = futile.logger::ERROR,
                    "fatal" = futile.logger::FATAL)
    if(is.null(level))
        return(futile.logger::INFO)
    return(level)
}

Am I missing a way that this is aready possible?

Would you accept a pull request adding this feature to flog.threshold?

This may not be so much a feature request as a question:

Is it possible to append to both file and console but to choose different thresholds for each? I.e. can I log errors to console but info to file?

We often find ourselves doing this:

msg <- "Something happened"
flog.error(msg)
stop(msg)

It would be great if this had some syntactic sugar in futile.logger, so we could just do this:

flog.throw("Something happened")

An additional enhancement could be to take a class argument indicating the type of error stop should create. Not sure how that should work, though.

I spent a few hours trying to figure out why my debug statements weren't being output after I set my logging threshold to DEBUG, as shown below:

flog.threshold(DEBUG);
flog.debug("this is my message"); # doesn't show up

After reviewing the source in logger.R, I can see the flog.debug statement appears to depend on the TRACE level, rather than a DEBUG level?

flog.debug <- function(msg, ..., name=get_namespace()) {
  .log_level(msg, ..., level=TRACE,name=name)
}

I think this is a bug, but noticed throughout the documentation that only trace, info, warn and error log levels are referred to, so I'm not sure. A debug level makes sense....

Matt.

> library(futile.logger)
Loading required package: lambda.r
Loading required package: futile.options
> flog.appender(appender.file("test.log"), name="test.out")
Error in as.character(function (line)  :
  cannot coerce type 'closure' to vector of type 'character'
> traceback()
5: sprintf("'%s(%s)'", fn.name, args)
4: use_error(.ERR_NO_MATCH, fn.name, raw.args)
3: stop(use_error(.ERR_NO_MATCH, fn.name, raw.args))
2: UseFunction("flog.appender", ...) at <text>#1
1: flog.appender(appender.file("test.log"), name = "test.out")
> sessionInfo()
R version 3.0.1 (2013-05-16)
Platform: x86_64-apple-darwin10.8.0 (64-bit)

locale:
[1] en_US.UTF-8/en_US.UTF-8/en_US.UTF-8/C/en_US.UTF-8/en_US.UTF-8

attached base packages:
[1] stats     graphics  grDevices utils     datasets  methods   base

other attached packages:
[1] futile.logger_1.3.3  futile.options_1.0.0 lambda.r_1.1.3
>

Brian said to reinstall futile.logger to fix the problem. Reinstalling the binary did not fix the problem, but reinstalling with type="source" did fix it. This makes me wonder whether a version bump would cause CRAN to produce binaries that would not have this problem. I don't know if it would but it's worth trying, probably.

Hi, is it possible to print in the log also the line number?

Thanks
Diego

The layout.json function is putting string interpolation arguments on the output as json fields instead of interpolating the message template.

library(futile.logger)
flog.info('test %s', 'interp')
INFO [2018-09-11 15:44:46] test interp

but after changing the layout:

flog.layout(layout.json)
flog.info('test %s', 'interp')
{"level":"INFO","timestamp":"2018-09-11 15:45:15 -0400","message":"test %s","func":"(shell)","5":["interp"]}

The interp argument shows up as field "5" on the output and the message template is unchanged.

I'm running futile.logger 1.4.3 on R 3.4.3.

I think it would be great if the message includes the logger name, like

> library(futile.logger)
> flog.info("foo", name="mylogger")
INFO | mylogger | 2018-01-11 17:41:13 : foo

At the beginning, I thought custom layout with "~n" (namespace) and "~f" (function) provides good information about where the logs come from, but when functions are nested, mere function names are not very helpful.

If this is already supported, please kindly let me know.

I am currently using futile.logger 1.3.3 and just upgraded lambda.r to 1.1.3 on a Mac OS X with R 3.0.1. This used to work perfectly but is now giving me an error message:

flog.layout(
  function(level, msg, ...) {
    the.time <- format(Sys.time(), "%Y-%m-%d %H:%M:%S %Z")
    if (!is.null(substitute(...)))  msg <- sprintf(msg, ...)
    sprintf("%s [%s] pid=%i %s\n", names(level), the.time, Sys.getpid(), msg)
  }
)

This is the error message:

Error in as.character(function (level, msg, ...)  (from <text>#1) : 
  cannot coerce type 'closure' to vector of type 'character'

Enter a frame number, or 0 to exit   

1: flog.layout(function(level, msg, ...) {
    the.time <- format(Sys.time(), "%Y-%m-%d %H:%M:%S
2: <text>#1: UseFunction("flog.layout", ...)
3: stop(use_error(.ERR_NO_MATCH, fn.name, raw.args))
4: use_error(.ERR_NO_MATCH, fn.name, raw.args)
5: sprintf("'%s(%s)'", fn.name, args)

Any ideas what might be going on?

There is one feature I'd really like to see in futile.logger, and that is the ability to capture the messages from message(), warning() and stop(). That would be a killer feature, IMO. It would make it very easy to add systematic logging to old code.

Is this something you could consider implementing in futile.logger?

I'm aware of one package that supports this (https://github.com/smbache/loggr).

I'm pretty sure the use of c(msg, parsed) here strings the arguments of their classes so for instance dates are printed as their integer value.

I'm not an R expert but maybe this could be resolved by using c(list(msg), parsed)

Would it be possible to add a tag to closed issues that indicates e. g. "implemented", "rejected", "work around"...?

This makes it e. g. easier to find newly implemented features by just browsing the closed tags.

Thx!

Might I suggest that you increment the version in DESCRIPTION?

 Package: futile.logger
 Type: Package
 Title: A Logging Utility for R
-Version: 1.4.3
+Version: 1.4.3.9000
 Date: 2016-07-10
 Author: Brian Lee Yung Rowe
 Maintainer: Brian Lee Yung Rowe <[email protected]>

I recently looked in your code and found functionality I was hoping to find (a PR you merged into layout.json). When I noticed that this version and the one on CRAN were the same, I installed from CRAN ... but lo-and-behold, it wasn't there.

My use of .9000 is a convention I've seen that indicates a development version, saving 1.4.4 for the next release to CRAN. Something that distinguishes it from the CRAN version is the important part.

Thank you!

We are using futile.logger in an R shiny application.
The logger writes user error messages from the application to a log file in the root directory of the application on our R server (linux).
As Shiny allows for multiple sessions to run concurrently we have a concern: if two application sessions would be writing to the same log file at the same time, would futile.logger handle this correctly? Or would the second session, that finds an open log file while trying to write, generate an error message?

We use the function flog.info to write to the log file.

Thanks.

If a warning occurs in ftry the evaluation of the expression is stopped due to establishing a warning handler in tryCatch (handled conditions in tryCatch do always stop the further evaluation).

try of base R behaves differently.

Proposal: Fix or document different semantics...

Example:

library(futile.logger)
sessionInfo()  # futile.logger_1.4.3

ftry({
       log(-1)   # throws a warning ("NaNs produced")
       print("warnings should not stop evaluation of this expression")
})
# WARN [2017-12-26 10:01:09] NaNs produced



# Compare:
try({
  log(-1)   # throws a warning ("NaNs produced")
  print("warnings should not stop evaluation of this expression")
})
# [1] "warnings should not stop evaluation of this expression"
# Warning message:
# In log(-1) : NaNs produced

The solution would establish a warning handler using withCallingHandlers within tryCatch...

It is related with the issue #21, and it works for me under RTMVS (R-Tools for Microsoft Visual Studio) when a select part of the script and execute it:

[INFO] [2017-02-14 17:58:01] [ROOT.(shell)] Begin
[INFO] [2017-02-14 17:58:01] [ROOT.f] Test
[INFO] [2017-02-14 17:58:01] [ROOT.(shell)] End

but, when I source the entire script: source("~/R-workspace/projects/RoR/RoR/sampleScript.R", encoding = "Windows-1252")

I get the following output:

[INFO] [2017-02-14 17:58:41] [base.source] Begin
[INFO] [2017-02-14 17:58:41] [base.source] Test
[INFO] [2017-02-14 17:58:41] [base.source] End

This is my sample script:

library(futile.logger) # The logger used
layout <- layout.format('[~l] [~t] [~n.~f] ~m')
flog.layout(layout)
flog.info("Begin")
f <- function() futile.logger::flog.info("Test")
f()
flog.info("End")

UPDATE
I also tested it under RStudio:

Using Run button for selected part of the source code:

> flog.info("Begin")
[INFO] [2017-03-03 09:18:14] [ROOT.(shell)] Begin
> f <- function() futile.logger::flog.info("Test")
> f()
[INFO] [2017-03-03 09:18:14] [ROOT.f] Test
> flog.info("End")
[INFO] [2017-03-03 09:18:14] [ROOT.(shell)] End
> 

but when using Source button:

> source('~/.active-rstudio-document')
[INFO] [2017-03-03 09:19:59] [base.source] Begin
[INFO] [2017-03-03 09:19:59] [base.source] Test
[INFO] [2017-03-03 09:19:59] [base.source] End
> 

I alo get the same result under R standard console (for windows).

What I am doing wrong here? is it a bug? Did not find any information in the documentation about how to use flog with the function source. Thanks.

Note: I have seen that for the majority of the bugs at least you provide some comment but not for this one, please can you provide some feedback. Thanks.

I often find myself to write

flog.trace("x: %s", x)

What do you think about supporting

flog.trace(x)

as a shortcut? This should be accompanied by a parameter to explicitly turn on or off this behavior:

flog.trace(msg, ..., name=get_namespace(), capture=FALSE, print.name=!is.character(msg))

The same holds for all other debug levels, of course.

Using 1.3.7:

flog.info('Here is a null object: %s', NULL)

>INFO [2014-05-07 17:03:09] Here is a null object: %s

opt <- list()
opt$foo
>NULL

flog.info('Here is a null object: %s', opt$foo)
(no output)

identical(opt$foo, NULL)

[1] TRUE

When I configure the log layout [~l] [~t] [~n.~f] ~m and then call the function explicitly as in

library("futile.logger")
futile.logger::flog.layout(layout.format("[~l] [~t] [~n.~f] ~m"))
futile.logger::flog.info("Test...")

I get the following warning:

[INFO] [2014-10-09 14:50:40] [futile.logger.::] Test...
Warning message:
In gsub("~f", the.function, message, fixed = TRUE) :
  argument 'replacement' has length > 1 and only the first element will be used

Probably an issue parsing the :: ?

I have a function that calls flog.warn under certain conditions, and I want to test those conditions. However, it looks like the warning doesn't go through the channels that testthat::expect_warning expects it to:

> expect_warning(
+     solution <- do.call(my.function, args),
+     regexp = 'Missing regime types .* offpeak'
+   )
WARN [2018-07-03 17:52:42] Missing regime types in 'last.period.peaks': offpeak; filling with zeroes
Error: `solution <- do.call(my.function, args)` did not produce any warnings.

So the warning makes it to STDOUT or STDERR, and doesn't get captured by expect_warning, so the test fails.

Is there some other way to accomplish this easily?

Is it true that flog.threshold(name='myLogger') is supposed to return the name of the custom logger? If so it does not seem to work. Using a cloned repository I tried the following additional tests:

 flog.threshold(ERROR)
 expect_that(flog.threshold() == "ERROR", is_true())  ### WORKS
 flog.threshold(DEBUG, name='my.package')
 expect_that(flog.threshold(name='my.package') == DEBUG, is_true())  ### FAILS

If this is not how this is supposed to work, is there some other way get this information?

Firstly, thanks for this great package- I'm a big user, it has met a real need for me!

I was wondering if you'd consider intercepting warning() statements with futile.logger? From email you suggested it would be hard as warning is low-level, but would be a great addition.

Use case:

When using foreach with parallel library (%dopar%) it would be nice to have the thread number ou process where it is executing.

It would be really useful if the package provided a default appender that submits logs to the local syslog process (if it exists) in a Mac OS X or *nix machine. :)

First of all, thanks for the great module. Simple, elegant and powerful.

I have a suggestion. I find that it is probably expected that logging a FATAL log entry will soon be followed by a call to stop with the exact same string. A sample code I've written:

if (condition) {
   message = sprintf("myFunc: invalid whatever %s", var)
   flog.fatal(message)
   stop(message)
}

I was hoping you could change the flog.fatal, flog.trace, etc functions to return the string value of the final message generated by the layout function. This way, the above code could be rewritten in a smaller and more readable form:

if (condition) stop(flog.fatal("myFunc: invalid whatever %s", var))

Hi,

1.3.3 seems to have changed the way captures are printed, for example in an interactive session:

1.3.3:

> flog.info('Alphabet', capture=TRUE, letters)
INFO [2013-07-30 17:19:40] Alphabet
 [1] "a" "b" "c" "d" "e" "f" "g" "h" "i" "j" "k" "l" "m" "n" "o" "p" "q" "r" "s" "t" "u" "v" "w" "x" "y" "z"> 

vs
1.3.1

> flog.info('Alphabet', capture=TRUE, letters)
INFO [2013-07-30 17:19:28] Alphabet

 [1] "a" "b" "c" "d" "e" "f" "g" "h" "i" "j" "k" "l" "m" "n" "o" "p" "q" "r" "s" "t" "u" "v" "w" "x" "y" "z"
> 

There is a new line missing before the capture (no problem), but the lack of a new line afterwards means my logs are much harder to read than before.