Importance of Logging
Logging in FIMS is important because it allows developers to understand what is happening within a model. It is especially useful when problems arise. The FIMS logging system has been designed to handle common issues, such as undefined modules, dimension issues, and software errors that may occur when a model is not properly defined. This logging system is accessible from both R and C++ and messages are provided using a JSON format.
How FIMS Logging works
At run time, logging messages are stored in a C++ structure called LogEntry in inst/include/common/def.hpp. This structure contains useful information, such as information regarding when the LogEntry was created and what portion of the code initiated its creation. For details regarding the contents of a LogEntry see the doxygen documentation. All of the LogEntry(s) are stored in a log file that can be accessed from within your R environment or written to the disk. Additionally, this file can automatically be written to the disk when R fails to successfully communicate with C++.
Backend C++ Specification
The logging system (specified in inst/include/common/def.hpp)
provides three useful macro functions for creating log entries,
FIMS_INFO_LOG, FIMS_WARNING_LOG, and
FIMS_ERROR_LOG. These macros take a single string value as
an argument, the rest is handled internally. Therefore, the developer
only needs to worry about specifying the message and the macros take
care of capturing all the other elements of the log entry. For example,
FIMS_INFO_LOG is used quite a bit in information.hpp to let
the user know that items were initialized appropriately. Developers can
specify the information contained within the string passed to the macro
to be generic or specific to values stored inside the C++ code. See
below for an example of a generic message that is completely specified
by the user and a more specific message that uses information stored
within C++ for part of the message. Also, note that the C++ function
fims::to_string converts a numeric value to a string,
making it additive to the message.
FIMS_INFO_LOG("Starting to initialize the fleet structures")
FIMS_INFO_LOG("Initializing fleet " + fims::to_string(f->id))Below is a real-world example of a log entry that was created while
running a FIMS model due to FIMS_INFO_LOG within selectivity
in information.hpp. The log entry specifies the line of the file
with the macro that led to the log entry. The screenshot below shows
what the user would see if this log entry were invoked.
Additionally, if FIMS has been compiled with the
-DFIMS_DEBUG pre-processing macro, output from the
FIMS_DEBUG_LOG macro will also be available in the log
file, allowing developers a more interactive developing experience. The
output from this macro is turned off in the main branch, and thus, the
macro is not available to the typical user to stop debugging statements
from polluting the log file.
Using the Logging System in R
The FIMS Logging System is also available from R, with a caveat! Logging from R gives less information than logging from C++. When a log entry originates from R, file, routine, and line information are absent. Further implementations may rectify this issue. Below are examples of adding log entries from R.
log_info("info entry from R script")
log_warning("warning entry from R script")
error <- log_error("error entry from R script")## before call.after call.
get_log_errors()## [1] "[\n{\n\"timestamp\" : \"Fri Jan 17 15:11:09 2025\",\n\"level\" : \"error\",\n\"message\" : \"error entry from R script\",\n\"id\" : \"0\",\n\"user\" : \"runner\",\n\"wd\" : \"/home/runner/work/FIMS/FIMS/vignettes\",\n\"file\" : \"/home/runner/work/FIMS/FIMS/vignettes/R_env\",\n\"routine\" : \"traceback: 41: .External(list(name = \\\"InternalFunction_invoke\\\", address = <pointer: 0x55f07488e2f0>, \\n dll = list(name = \\\"Rcpp\\\", path = \\\"/home/runner/work/_temp/Library/Rcpp/libs/Rcpp.so\\\", \\n dynamicLookup = TRUE, handle = <pointer: 0x55f077785ac0>, \\n info = <pointer: 0x55f0748796a0>, forceSymbols = FALSE), \\n numParameters = -1L), <pointer: 0x55f07c7f8bb0>, ...)\\n40: log_error(\\\"error entry from R script\\\")\\n39: eval(expr, envir)\\n38: eval(expr, envir)\\n37: withVisible(eval(expr, envir))\\n36: withCallingHandlers(code, message = function (cnd) \\n {\\n watcher$capture_plot_and_output()\\n if (on_message$capture) {\\n watcher$push(cnd)\\n }\\n if (on_message$silence) {\\n invokeRestart(\\\"muffleMessage\\\")\\n }\\n }, warning = function (cnd) \\n {\\n if (getOption(\\\"warn\\\") >= 2 || getOption(\\\"warn\\\") < 0) {\\n return()\\n }\\n watcher$capture_plot_and_output()\\n if (on_warning$capture) {\\n cnd <- sanitize_call(cnd)\\n watcher$push(cnd)\\n }\\n if (on_warning$silence) {\\n invokeRestart(\\\"muffleWarning\\\")\\n }\\n }, error = function (cnd) \\n {\\n watcher$capture_plot_and_output()\\n cnd <- sanitize_call(cnd)\\n watcher$push(cnd)\\n switch(on_error, continue = invokeRestart(\\\"eval_continue\\\"), \\n stop = invokeRestart(\\\"eval_stop\\\"), error = NULL)\\n })\\n35: eval(call)\\n34: eval(call)\\n33: with_handlers({\\n for (expr in tle$exprs) {\\n ev <- withVisible(eval(expr, envir))\\n watcher$capture_plot_and_output()\\n watcher$print_value(ev$value, ev$visible, envir)\\n }\\n TRUE\\n }, handlers)\\n32: doWithOneRestart(return(expr), restart)\\n31: withOneRestart(expr, restarts[[1L]])\\n30: withRestartList(expr, restarts[-nr])\\n29: doWithOneRestart(return(expr), restart)\\n28: withOneRestart(withRestartList(expr, restarts[-nr]), restarts[[nr]])\\n27: withRestartList(expr, restarts)\\n26: withRestarts(with_handlers({\\n for (expr in tle$exprs) {\\n ev <- withVisible(eval(expr, envir))\\n watcher$capture_plot_and_output()\\n watcher$print_value(ev$value, ev$visible, envir)\\n }\\n TRUE\\n }, handlers), eval_continue = function() TRUE, eval_stop = function() FALSE)\\n25: evaluate::evaluate(...)\\n24: evaluate(code, envir = env, new_device = FALSE, keep_warning = if (is.numeric(options$warning)) TRUE else options$warning, \\n keep_message = if (is.numeric(options$message)) TRUE else options$message, \\n stop_on_error = if (is.numeric(options$error)) options$error else {\\n if (options$error && options$include) \\n 0L\\n else 2L\\n }, output_handler = knit_handlers(options$render, options))\\n23: in_dir(input_dir(), expr)\\n22: in_input_dir(evaluate(code, envir = env, new_device = FALSE, \\n keep_warning = if (is.numeric(options$warning)) TRUE else options$warning, \\n keep_message = if (is.numeric(options$message)) TRUE else options$message, \\n stop_on_error = if (is.numeric(options$error)) options$error else {\\n if (options$error && options$include) \\n 0L\\n else 2L\\n }, output_handler = knit_handlers(options$render, options)))\\n21: eng_r(options)\\n20: block_exec(params)\\n19: call_block(x)\\n18: process_group(group)\\n17: withCallingHandlers(if (tangle) process_tangle(group) else process_group(group), \\n error = function(e) if (xfun::pkg_available(\\\"rlang\\\", \\\"1.0.0\\\")) rlang::entrace(e))\\n16: xfun:::handle_error(withCallingHandlers(if (tangle) process_tangle(group) else process_group(group), \\n error = function(e) if (xfun::pkg_available(\\\"rlang\\\", \\\"1.0.0\\\")) rlang::entrace(e)), \\n function(loc) {\\n setwd(wd)\\n write_utf8(res, output %n% stdout())\\n paste0(\\\"\\nQuitting from lines \\\", loc)\\n }, if (labels[i] != \\\"\\\") sprintf(\\\" [%s]\\\", labels[i]), get_loc)\\n15: process_file(text, output)\\n14: knitr::knit(knit_input, knit_output, envir = envir, quiet = quiet)\\n13: rmarkdown::render(envir = globalenv(), ...)\\n12: (function (..., seed = NULL) \\n {\\n if (!is.null(seed)) {\\n set.seed(seed)\\n if (requireNamespace(\\\"htmlwidgets\\\", quietly = TRUE)) {\\n htmlwidgets::setWidgetIdSeed(seed)\\n }\\n }\\n options(knitr.graphics.rel_path = FALSE)\\n rmarkdown::render(envir = globalenv(), ...)\\n })(input = base::quote(\\\"/home/runner/work/FIMS/FIMS/vignettes/fims-logging.Rmd\\\"), \\n output_file = base::quote(\\\"fims-logging.html\\\"), output_dir = base::quote(\\\"/tmp/RtmpCeq3yy/file1c86119bb609/articles\\\"), \\n intermediates_dir = base::quote(\\\"/tmp/RtmpCeq3yy\\\"), encoding = base::quote(\\\"UTF-8\\\"), \\n seed = base::quote(1014L), output_format = base::quote(list(\\n knitr = list(opts_knit = NULL, opts_chunk = list(dev = \\\"ragg_png\\\", \\n dpi = 96L, fig.width = 7.29166666666667, fig.height = 4.50659250103008, \\n fig.retina = 2L, dev.args = list(bg = NA), fig.ext = \\\"png\\\", \\n other.parameters = list()), knit_hooks = NULL, opts_hooks = NULL, \\n opts_template = NULL), pandoc = list(to = \\\"html\\\", \\n from = \\\"markdown+autolink_bare_uris+tex_math_single_backslash\\\", \\n args = c(\\\"--standalone\\\", \\\"--section-divs\\\", \\\"--template\\\", \\n \\\"/tmp/RtmpCeq3yy/pkgdown-rmd-template-1c8654c0a0ce.html\\\", \\n \\\"--highlight-style\\\", \\\"pygments\\\"), keep_tex = FALSE, \\n latex_engine = \\\"pdflatex\\\", ext = NULL, convert_fun = NULL, \\n lua_filters = c(\\\"/home/runner/work/_temp/Library/rmarkdown/rmarkdown/lua/pagebreak.lua\\\", \\n \\\"/home/runner/work/_temp/Library/rmarkdown/rmarkdown/lua/latex-div.lua\\\"\\n )), keep_md = FALSE, clean_supporting = FALSE, df_print = \\\"default\\\", \\n pre_knit = function (...) \\n {\\n options(width = width)\\n if (is.function(old_pre)) {\\n old_pre(...)\\n }\\n }, post_knit = function (...) \\n {\\n op(base(...), overlay(...))\\n }, pre_processor = function (...) \\n {\\n op(base(...), overlay(...))\\n }, intermediates_generator = function (original_input, \\n intermediates_dir) \\n {\\n copy_render_intermediates(original_input, intermediates_dir, \\n !self_contained)\\n }, post_processor = function (metadata, input_file, output_file, \\n ...) \\n {\\n original_output_file <- output_file\\n output_file <- overlay(metadata, input_file, output_file, \\n ...)\\n if (!is.null(attr(output_file, \\\"post_process_original\\\"))) \\n base(metadata, input_file, original_output_file, \\n ...)\\n base(metadata, input_file, output_file, ...)\\n }, file_scope = NULL, on_exit = function () \\n {\\n if (is.function(base)) \\n base()\\n if (is.function(overlay)) \\n overlay()\\n })), output_options = base::quote(NULL), quiet = base::quote(TRUE))\\n11: (function (what, args, quote = FALSE, envir = parent.frame()) \\n {\\n if (!is.list(args)) \\n stop(\\\"second argument must be a list\\\")\\n if (quote) \\n args <- lapply(args, enquote)\\n .Internal(do.call(what, args, envir))\\n })(base::quote(function (..., seed = NULL) \\n {\\n if (!is.null(seed)) {\\n set.seed(seed)\\n if (requireNamespace(\\\"htmlwidgets\\\", quietly = TRUE)) {\\n htmlwidgets::setWidgetIdSeed(seed)\\n }\\n }\\n options(knitr.graphics.rel_path = FALSE)\\n rmarkdown::render(envir = globalenv(), ...)\\n }), base::quote(list(input = \\\"/home/runner/work/FIMS/FIMS/vignettes/fims-logging.Rmd\\\", \\n output_file = \\\"fims-logging.html\\\", output_dir = \\\"/tmp/RtmpCeq3yy/file1c86119bb609/articles\\\", \\n intermediates_dir = \\\"/tmp/RtmpCeq3yy\\\", encoding = \\\"UTF-8\\\", \\n seed = 1014L, output_format = list(knitr = list(opts_knit = NULL, \\n opts_chunk = list(dev = \\\"ragg_png\\\", dpi = 96L, fig.width = 7.29166666666667, \\n fig.height = 4.50659250103008, fig.retina = 2L, dev.args = list(\\n bg = NA), fig.ext = \\\"png\\\", other.parameters = list()), \\n knit_hooks = NULL, opts_hooks = NULL, opts_template = NULL), \\n pandoc = list(to = \\\"html\\\", from = \\\"markdown+autolink_bare_uris+tex_math_single_backslash\\\", \\n args = c(\\\"--standalone\\\", \\\"--section-divs\\\", \\\"--template\\\", \\n \\\"/tmp/RtmpCeq3yy/pkgdown-rmd-template-1c8654c0a0ce.html\\\", \\n \\\"--highlight-style\\\", \\\"pygments\\\"), keep_tex = FALSE, \\n latex_engine = \\\"pdflatex\\\", ext = NULL, convert_fun = NULL, \\n lua_filters = c(\\\"/home/runner/work/_temp/Library/rmarkdown/rmarkdown/lua/pagebreak.lua\\\", \\n \\\"/home/runner/work/_temp/Library/rmarkdown/rmarkdown/lua/latex-div.lua\\\"\\n )), keep_md = FALSE, clean_supporting = FALSE, df_print = \\\"default\\\", \\n pre_knit = function (...) \\n {\\n options(width = width)\\n if (is.function(old_pre)) {\\n old_pre(...)\\n }\\n }, post_knit = function (...) \\n {\\n op(base(...), overlay(...))\\n }, pre_processor = function (...) \\n {\\n op(base(...), overlay(...))\\n }, intermediates_generator = function (original_input, \\n intermediates_dir) \\n {\\n copy_render_intermediates(original_input, intermediates_dir, \\n !self_contained)\\n }, post_processor = function (metadata, input_file, output_file, \\n ...) \\n {\\n original_output_file <- output_file\\n output_file <- overlay(metadata, input_file, output_file, \\n ...)\\n if (!is.null(attr(output_file, \\\"post_process_original\\\"))) \\n base(metadata, input_file, original_output_file, \\n ...)\\n base(metadata, input_file, output_file, ...)\\n }, file_scope = NULL, on_exit = function () \\n {\\n if (is.function(base)) \\n base()\\n if (is.function(overlay)) \\n overlay()\\n }), output_options = NULL, quiet = TRUE)), envir = base::quote(<environment>), \\n quote = base::quote(TRUE))\\n10: base::do.call(base::do.call, base::c(base::readRDS(\\\"/tmp/RtmpCeq3yy/callr-fun-1c864dbc3823\\\"), \\n base::list(envir = .GlobalEnv, quote = TRUE)), envir = .GlobalEnv, \\n quote = TRUE)\\n9: base::saveRDS(base::do.call(base::do.call, base::c(base::readRDS(\\\"/tmp/RtmpCeq3yy/callr-fun-1c864dbc3823\\\"), \\n base::list(envir = .GlobalEnv, quote = TRUE)), envir = .GlobalEnv, \\n quote = TRUE), file = \\\"/tmp/RtmpCeq3yy/callr-res-1c8669ed55d6\\\", \\n compress = FALSE)\\n8: base::withCallingHandlers({\\n NULL\\n base::saveRDS(base::do.call(base::do.call, base::c(base::readRDS(\\\"/tmp/RtmpCeq3yy/callr-fun-1c864dbc3823\\\"), \\n base::list(envir = .GlobalEnv, quote = TRUE)), envir = .GlobalEnv, \\n quote = TRUE), file = \\\"/tmp/RtmpCeq3yy/callr-res-1c8669ed55d6\\\", \\n compress = FALSE)\\n base::flush(base::stdout())\\n base::flush(base::stderr())\\n NULL\\n base::invisible()\\n }, error = function(e) {\\n {\\n callr_data <- base::as.environment(\\\"tools:callr\\\")$`__callr_data__`\\n err <- callr_data$err\\n if (FALSE) {\\n base::assign(\\\".Traceback\\\", base::.traceback(4), envir = callr_data)\\n utils::dump.frames(\\\"__callr_dump__\\\")\\n base::assign(\\\".Last.dump\\\", .GlobalEnv$`__callr_dump__`, \\n envir = callr_data)\\n base::rm(\\\"__callr_dump__\\\", envir = .GlobalEnv)\\n }\\n e <- err$process_call(e)\\n e2 <- err$new_error(\\\"error in callr subprocess\\\")\\n class <- base::class\\n class(e2) <- base::c(\\\"callr_remote_error\\\", class(e2))\\n e2 <- err$add_trace_back(e2)\\n cut <- base::which(e2$trace$scope == \\\"global\\\")[1]\\n if (!base::is.na(cut)) {\\n e2$trace <- e2$trace[-(1:cut), ]\\n }\\n base::saveRDS(base::list(\\\"error\\\", e2, e), file = base::paste0(\\\"/tmp/RtmpCeq3yy/callr-res-1c8669ed55d6\\\", \\n \\\".error\\\"))\\n }\\n }, interrupt = function(e) {\\n {\\n callr_data <- base::as.environment(\\\"tools:callr\\\")$`__callr_data__`\\n err <- callr_data$err\\n if (FALSE) {\\n base::assign(\\\".Traceback\\\", base::.traceback(4), envir = callr_data)\\n utils::dump.frames(\\\"__callr_dump__\\\")\\n base::assign(\\\".Last.dump\\\", .GlobalEnv$`__callr_dump__`, \\n envir = callr_data)\\n base::rm(\\\"__callr_dump__\\\", envir = .GlobalEnv)\\n }\\n e <- err$process_call(e)\\n e2 <- err$new_error(\\\"error in callr subprocess\\\")\\n class <- base::class\\n class(e2) <- base::c(\\\"callr_remote_error\\\", class(e2))\\n e2 <- err$add_trace_back(e2)\\n cut <- base::which(e2$trace$scope == \\\"global\\\")[1]\\n if (!base::is.na(cut)) {\\n e2$trace <- e2$trace[-(1:cut), ]\\n }\\n base::saveRDS(base::list(\\\"error\\\", e2, e), file = base::paste0(\\\"/tmp/RtmpCeq3yy/callr-res-1c8669ed55d6\\\", \\n \\\".error\\\"))\\n }\\n }, callr_message = function(e) {\\n base::try(base::signalCondition(e))\\n })\\n7: doTryCatch(return(expr), name, parentenv, handler)\\n6: tryCatchOne(expr, names, parentenv, handlers[[1L]])\\n5: tryCatchList(expr, names[-nh], parentenv, handlers[-nh])\\n4: doTryCatch(return(expr), name, parentenv, handler)\\n3: tryCatchOne(tryCatchList(expr, names[-nh], parentenv, handlers[-nh]), \\n names[nh], parentenv, handlers[[nh]])\\n2: tryCatchList(expr, classes, parentenv, handlers)\\n1: base::tryCatch(base::withCallingHandlers({\\n NULL\\n base::saveRDS(base::do.call(base::do.call, base::c(base::readRDS(\\\"/tmp/RtmpCeq3yy/callr-fun-1c864dbc3823\\\"), \\n base::list(envir = .GlobalEnv, quote = TRUE)), envir = .GlobalEnv, \\n quote = TRUE), file = \\\"/tmp/RtmpCeq3yy/callr-res-1c8669ed55d6\\\", \\n compress = FALSE)\\n base::flush(base::stdout())\\n base::flush(base::stderr())\\n NULL\\n base::invisible()\\n }, error = function(e) {\\n {\\n callr_data <- base::as.environment(\\\"tools:callr\\\")$`__callr_data__`\\n err <- callr_data$err\\n if (FALSE) {\\n base::assign(\\\".Traceback\\\", base::.traceback(4), envir = callr_data)\\n utils::dump.frames(\\\"__callr_dump__\\\")\\n base::assign(\\\".Last.dump\\\", .GlobalEnv$`__callr_dump__`, \\n envir = callr_data)\\n base::rm(\\\"__callr_dump__\\\", envir = .GlobalEnv)\\n }\\n e <- err$process_call(e)\\n e2 <- err$new_error(\\\"error in callr subprocess\\\")\\n class <- base::class\\n class(e2) <- base::c(\\\"callr_remote_error\\\", class(e2))\\n e2 <- err$add_trace_back(e2)\\n cut <- base::which(e2$trace$scope == \\\"global\\\")[1]\\n if (!base::is.na(cut)) {\\n e2$trace <- e2$trace[-(1:cut), ]\\n }\\n base::saveRDS(base::list(\\\"error\\\", e2, e), file = base::paste0(\\\"/tmp/RtmpCeq3yy/callr-res-1c8669ed55d6\\\", \\n \\\".error\\\"))\\n }\\n }, interrupt = function(e) {\\n {\\n callr_data <- base::as.environment(\\\"tools:callr\\\")$`__callr_data__`\\n err <- callr_data$err\\n if (FALSE) {\\n base::assign(\\\".Traceback\\\", base::.traceback(4), envir = callr_data)\\n utils::dump.frames(\\\"__callr_dump__\\\")\\n base::assign(\\\".Last.dump\\\", .GlobalEnv$`__callr_dump__`, \\n envir = callr_data)\\n base::rm(\\\"__callr_dump__\\\", envir = .GlobalEnv)\\n }\\n e <- err$process_call(e)\\n e2 <- err$new_error(\\\"error in callr subprocess\\\")\\n class <- base::class\\n class(e2) <- base::c(\\\"callr_remote_error\\\", class(e2))\\n e2 <- err$add_trace_back(e2)\\n cut <- base::which(e2$trace$scope == \\\"global\\\")[1]\\n if (!base::is.na(cut)) {\\n e2$trace <- e2$trace[-(1:cut), ]\\n }\\n base::saveRDS(base::list(\\\"error\\\", e2, e), file = base::paste0(\\\"/tmp/RtmpCeq3yy/callr-res-1c8669ed55d6\\\", \\n \\\".error\\\"))\\n }\\n }, callr_message = function(e) {\\n base::try(base::signalCondition(e))\\n }), error = function(e) {\\n NULL\\n if (FALSE) {\\n base::try(base::stop(e))\\n }\\n else {\\n base::invisible()\\n }\\n }, interrupt = function(e) {\\n NULL\\n if (FALSE) {\\n e\\n }\\n else {\\n base::invisible()\\n }\\n })\\n\",\n\"line\" : \"-1\"\n}\n]"In the above example of an error level log entry, notice the R stack
trace in the routine field. Sometimes this may contain useful
information, but most of the time the stack trace is to large to capture
the root cause of the error. For that reason, it’s advised to make the
error message as detailed as possible when calling
log_error(x) from R. Note that the formatting is better
when written to a file rather than printed to the screen as is done
here.
FIMS Logging Functions in R
There are several exported logging functions in the FIMS packages. To
find out more about each of the following functions, use
methods::show() to view the documentation.
ls("package:FIMS") |>
grep(pattern = "_log|log_", value = TRUE) |>
cli::cli_bullets()## get_log## get_log_errors## get_log_module## get_log_warnings## log_error## log_info## log_warning## set_log_throw_on_error
# Get documentation for log_error
methods::show(log_error)## internal C++ function <0x55f07c7f8bb0>
## docstring : Adds a error entry to the log from the R environment.
## signature : void log_error(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >)Example of FIMS logging from R
Assuming a model has already been defined in the object
default_parameters, below is an example of using the
logging system with FIMS in R.
fit <- default_parameters |>
initialize_fims(data = data_4_model) |>
fit_fims(optimize = TRUE)## ✔ Starting optimization ...
## ℹ Restarting optimizer 3 times to improve gradient.
## ℹ Maximum gradient went from 0.00298 to 0.00117 after 3 steps.
## ✔ Finished optimization
## ✔ Finished sdreport
## ℹ FIMS model version: 0.3.0.1
## ℹ Total run time was 0.7899 seconds
## ℹ Number of parameters: total=79, fixed_effects=79, and random_effects=0
## ℹ Maximum gradient= 0.00117
## ℹ Negative log likelihood (NLL):
## • Marginal NLL= 2146.10345
## • Total NLL= 2146.10345
## ℹ Terminal SB=
# get the log as a string in JSON format and parse into a list
log_str <- as.character(get_log())
write(log_str, "log.json")
log_json <- jsonlite::fromJSON(log_str)
# get log warnings only
log_warnings_str <- get_log_warnings()
# get log errors only
log_errors_str <- get_log_errors()
# get log entries from the information module
information_log <- get_log_module("information")Another useful option is set_throw_on_error(). If this
option is set to TRUE, FIMS will abort immediately when an error occurs
and if write_log(TRUE) was previously called, the log file
will be written before FIMS terminates the session. Below is an example
of how to throw on error.
set_log_throw_on_error(TRUE)
log_error("throwing now!")