Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix 2 capture output #16

Merged
merged 21 commits into from
Mar 25, 2022
Merged

Fix 2 capture output #16

merged 21 commits into from
Mar 25, 2022

Conversation

kodesiba
Copy link
Collaborator

@kodesiba kodesiba commented Mar 8, 2022

Add support for capturing messages, output, and results. Closes #2 and Closes #7

@kodesiba kodesiba requested review from bms63 and thomasp-b March 8, 2022 19:13
@codecov
Copy link

codecov bot commented Mar 8, 2022

Codecov Report

❗ No coverage uploaded for pull request base (dev@90c9d00). Click here to learn what that means.
The diff coverage is n/a.

❗ Current head c27f72c differs from pull request most recent head 6f00c49. Consider uploading reports for the commit 6f00c49 to get more accurate results

@@          Coverage Diff           @@
##             dev      #16   +/-   ##
======================================
  Coverage       ?   74.19%           
======================================
  Files          ?        7           
  Lines          ?      372           
  Branches       ?        0           
======================================
  Hits           ?      276           
  Misses         ?       96           
  Partials       ?        0           

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 90c9d00...6f00c49. Read the comment docs.

Copy link
Collaborator

@nicholas-masel nicholas-masel left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I've added update suggestions for your consideration.

I have one general comment/question as well.

Executinng a script with redirect give us this:

Rscript tests/testthat/ref/safely_quietly_test_file.R > tests/testthat/ref/safely_quietly_test_file.log 2>&1

[1] "log print"
[1] "log print 2"
log catlog cat 2log inform
log inform 2
log message
log message 2
Warning message:
log warning 
Warning message:
log warning2 
Error: log error
Execution halted

The order of messages, warnings and the error provide context for troubleshooting a batch submit.

The current approach breaks this up into pieces and reports them separately, so the context is lost.

Not sure how yet, but what are your thoughts about trying to put the exact output from this redirect under the timber header? So users still get exactly what they are used to getting, but with a nice timber header as a bonus.

R/writer.R Outdated
@@ -107,7 +107,7 @@ write_log_header <- function(title_string){
write_errors <- function() {
errors <- get_log_element("errors")

paste0("errors:\n\t",
paste0("Errors:\n\t",
capture.output(errors))
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
capture.output(errors))
capture.output(errors$message))

tests/testthat/ref/safely_quietly_test_file.R Outdated Show resolved Hide resolved
R/writer.R Outdated Show resolved Hide resolved
R/writer.R Show resolved Hide resolved
#' @return A formatted vector of results
#' @export
#'
write_result <- function() {
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do we have a use case where the script returns a result rather than writing out a file to capture the results. If so, this might be good to highlight in documentation.

R/writer.R Outdated
Comment on lines 158 to 159
paste0("\nResult:\n",
paste0(result, collapse = "\n\t"))
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This can get tricky since result could be anything; dataframe, model object, etc. What do you think about letting print for each object handle how we present it in the log?

Suggested change
paste0("\nResult:\n",
paste0(result, collapse = "\n\t"))
capture.output(print(result$value))

tests/testthat/test-writer.R Show resolved Hide resolved
kodesiba and others added 7 commits March 10, 2022 11:07
Co-authored-by: nicholas-masel <61123199+nicholas-masel@users.noreply.github.com>
Co-authored-by: nicholas-masel <61123199+nicholas-masel@users.noreply.github.com>
Co-authored-by: nicholas-masel <61123199+nicholas-masel@users.noreply.github.com>
Co-authored-by: nicholas-masel <61123199+nicholas-masel@users.noreply.github.com>
@kodesiba
Copy link
Collaborator Author

@nicholas-masel I updated the safely/quietly piece to correctly use the purrr adverbs here as well per your previous comment

@kodesiba kodesiba changed the base branch from main to dev March 18, 2022 19:04
Nathan Kosiba added 3 commits March 18, 2022 19:49
Merge branch 'dev' of github.com:atorus-research/timber into fix-2_capture_output

# Conflicts:
#	NAMESPACE
#	R/zzz.R
#	tests/testthat/test-log.R
@nicholas-masel
Copy link
Collaborator

@kodesiba, So I've got a proposal to get around the warning and sink by creating a custom purrr::capture_output. I have copied the function here and updated the following:

  1. Commented out both invokeRestart() calls. This will make sure the warning and messages are stored by purrr and written out to the console/log.
  2. Added split = TRUE to sink(). This will make sure the output are stored by purrr and written out to the console/log.
  3. The last puzzle piece, set options(warn = 1). This will make the warnings immediately print, rather than print out of order.
options(warn = 1)

capture_output <- function(code) {
  warnings <- character()
  wHandler <- function(w) {
    warnings <<- c(warnings, w$message)
    # invokeRestart("muffleWarning")
  }
  
  messages <- character()
  mHandler <- function(m) {
    messages <<- c(messages, m$message)
    # invokeRestart("muffleMessage")
  }
  
  temp <- file()
  # sink(temp)
  sink(temp, split = TRUE)
  on.exit({
    sink()
    close(temp)
  })
  
  result <- withCallingHandlers(
    code,
    warning = wHandler,
    message = mHandler
  )
  
  output <- paste0(readLines(temp, warn = FALSE), collapse = "\n")
  
  list(
    result = result,
    output = output,
    warnings = warnings,
    messages = messages
  )
}

@nicholas-masel
Copy link
Collaborator

@kodesiba Or we put in a PR to extent purrr with a new functionloudly(), that captures results, outputs, warnings and messages in a list, but still puts them in the console/log for everyone.

@kodesiba
Copy link
Collaborator Author

@nicholas-masel I think that making our own internal function to do it would be a solid fix for now. we could definitely put in a PR to purrr but not sure what their turnaround time is. I would love to do that at some point as this might actually be an interesting new case for purrr adverbs

I've been looking at the same thing as this actually and I think your solution is great. We can set the option in our zzz.R so it gets loaded at the beginning. Happy to implement this in this branch today.

Merge branch 'dev' of github.com:atorus-research/timber into fix-2_capture_output

# Conflicts:
#	NAMESPACE
@kodesiba
Copy link
Collaborator Author

@nicholas-masel this is finally ready for review. The way that purrr does the adverbs looks to mean that we just have to write one function due to how the package gets build. Let me know if you have any other comments or suggestions for this PR

#'
#' @importFrom purrr as_mapper
#'
#' @param code all code to be run loudly
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
#' @param code all code to be run loudly
#' @param code All code to be run loudly

#'
#' @param code all code to be run loudly
#'
#' @return wrapped function returns a list with components
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
#' @return wrapped function returns a list with components
#' @return wrapped Function returns a list with components

@@ -8,9 +8,6 @@
#' @return formatted element including prefix
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
#' @return formatted element including prefix
#' @return Formatted element including prefix

R/zzz.R Show resolved Hide resolved
log_config(file = scriptPath)

run_safely_n_quietly(scriptPath)
run_safely_loudly(fp)

testthat::expect_true(!is.null(getOption("timber.log")[["warnings"]]))
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do we need the directs calls to testthat:: if that package is loaded when you Run the Tests?

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not necessarily, we will need to do a cleaning and include checking consistency with stuff like this. It can be either way we'll just want to pick one at some point.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

admiral doesn't have these calls so we should remove them to keep in line with what they are doing. I can make a separate issue for us to address?

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yeah, go ahead and log an issue for that as well as one for checking Roxygen docs for consistency (not sure if Admiral had a style guide or anything)

Copy link
Collaborator

@bms63 bms63 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hey Nathan. Looks good. I just had a few minor comments. Looking forward to testings this out wants this and the other PR gets merged into dev

@kodesiba
Copy link
Collaborator Author

@nicholas-masel this is ready for final review. Adding checks for zzz.R don't do anything since testthat loads timber at the beginning and that stuff isn't really checkable within the testthat framework

Copy link
Collaborator

@nicholas-masel nicholas-masel left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@kodesiba Nicely done!

@kodesiba kodesiba merged commit 842da57 into dev Mar 25, 2022
@bms63 bms63 deleted the fix-2_capture_output branch April 1, 2022 20:53
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Add stdout logging support capture message, warnings, and (possibly?) errors in {timber} log
3 participants