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

Improve handling and logging of unexpected errors #44

Merged
merged 2 commits into from
Oct 10, 2023
Merged

Conversation

bpbond
Copy link
Member

@bpbond bpbond commented Oct 4, 2023

As noted by @stephpenn1 in #43 , currently if an unexpected error occurs during a Quarto render it's printed to the console but the driver.R log file has nothing.

If an unexpected error occurs — e.g. stop("An unexpected error!") — the console still has more detailed information:

Quitting from lines 34-51 [init] (L0.qmd)
Error:
! An unexpected error!

...but now with this PR the driver log file shows:

2023-10-04 15:23:45 WARNING: An error occurred! 
2023-10-04 15:23:45 Error in "processx::run(quarto_bin, args, echo = TRUE)": [33m![39m System command 'quarto' failed

In addition, an ERROR_OCCURRED flag is set in the driver script. This should help with current debugging and future automation. It's not ideal, but an improvement; I'm not sure how to capture that original error message without sink'ing the entire process, which would be a drag.

@bpbond
Copy link
Member Author

bpbond commented Oct 8, 2023

@stephpenn1

The data processing workflow currently has two types of logs: the rendered HTMLs generated by each Quarto file, and a text file written by driver.R. Information about this driver log is passed into the Quarto files, so they can write to it as well.

When an error occurs (is thrown) in this or any program, it propagates up the call stack--that is, it goes from the function where it first occurred, to the calling function, to the function that called that one, etc., all the way back to the user. At each level, the code may catch the error, i.e. do something special to handle it and then return to normal execution; but if it doesn't, the error signal continues upward.

For example, say an error occurs in function C():

Program flow:
Main program -> A() -> B() -> C()

Error signal:
C() -> B() -> A() -> Main program

When we catch the error, usually via R's tryCatch, then we get information about what happened and where.

The problem here is that we're calling Quarto, which creates an entirely separate R instance, which means that the driver is walled off from details of the error. The driver can tell that the Quarto render process failed, but nothing more than that.

I think we have three options to deal with this:

  1. Not catch errors at all. In this case, we'll only know that the driver failed.
  2. Have the driver tryCatch the Quarto render call. At least this lets us know that an error occurred at a particular step, and the driver can log that fact. That's what this PR does.
  3. Do 2, but also have a tryCatch inside each Quarto file code. This would let us write details about the error to the driver log (easy, since we're already passing that in). It would then re-throw the error, because we still want to signal to the driver that a problem occurred.

@stephpenn1
Copy link
Member

stephpenn1 commented Oct 9, 2023

Notes from 10/9 meeting: (@bpbond)

  • add a tryCatch to the quarto files (e.g. the lapply call in L1_normalize) to capture potential error messages and print them in the driver file

this will give us information on where and what is happening in an error is thrown in one place

@bpbond
Copy link
Member Author

bpbond commented Oct 9, 2023

@stephpenn1 OK in db84e6e am pushing changes that give this behavior:

If an unexpected error occurs, for example due to a syntax error

    basefn <- basename(fn, kjjkh=1)

...the driver log now shows

2023-10-09 16:33:35 About to L0 
2023-10-09 16:33:35 WARNING: L0: an error occurred! 
2023-10-09 16:33:35 Error in basename(fn, kjjkh = 1): unused argument (kjjkh = 1)
 
2023-10-09 16:33:36 WARNING: Driver: an error occurred! 
2023-10-09 16:33:36 Error in "processx::run(quarto_bin, args, echo = TRUE)": [33m![39m System command 'quarto' failed

So both the Quarto file (with a specific message, that there's a problem with the basename call) and the driver (saying that the Quarto render failed) log errors in the driver's log.

@stephpenn1
Copy link
Member

Looks great!

Screenshot 2023-10-10 at 2 33 26 PM

@bpbond
Copy link
Member Author

bpbond commented Oct 10, 2023

Oh yay! Cool. Thanks.

@bpbond bpbond merged commit 3e9a32f into portage Oct 10, 2023
1 check passed
@bpbond bpbond deleted the errorhandling branch October 10, 2023 19:08
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.

2 participants