Logging

Logging is a very important part of a server application - it allows to analyze workload, collect metrics and facilitates finding critical bugs.

RestRserve ships with basic (yet handy) logging utility - Logger. It can be used in the application code, but what is more important, it is integrated into Application class in order to print useful messages during app execution.

Each applications comes with built-in logger member:

library(RestRserve)
application = Application$new()
application$logger$info("hello from logger")
#> {"timestamp":"2022-06-09 13:42:21.678719","level":"INFO","name":"Application","pid":49398,"msg":"hello from logger"}

logger is an instance of Logger class. We believe it is important to have logs in a machine readable format, so by default logger writes messages to stdout in JSON format.

Amount of logging can be adjusted with set_log_level method:

application$logger$set_log_level("error")
application$logger$info("you won't see this message")

If you want to customize logger, you can tweak it with logger$set_printer() function or even swap it to your own (see ?Logger for details):

application$logger = Logger$new(level = "trace", name = "mylogger")

Moreover Logger mimics loggers from fully-featured lgr package - you can use them interchangeably.

application$logger object however is not designed to be called by end user to produce messages. It is used internally in the application to emit status messages along the request-response processing pipeline.

Consider following example. We develop a method which takes a square root of a number:

application = Application$new()
application$add_get("/sqrt", function(.req, .res) {
  .res$set_body(sqrt(x))
})

Now let’s query it:

# let's emulate query string "/sqrt?x=10"
request = Request$new(path = "/sqrt", method = "GET", parameters_query = list(x = "10")) 
response = application$process_request(request)
#> {"timestamp":"2022-06-09 13:42:21.718075","level":"ERROR","name":"Application","pid":49398,"msg":"","context":{"request_id":"75ce04e0-e7d8-11ec-b9c1-4c327594fb6f","message":{"error":"object 'x' not found","call":".res$set_body(sqrt(x))","traceback":["FUN(request, response)",".res$set_body(sqrt(x))"]}}}
response$body
#> [1] "500 Internal Server Error"

Surprise! (or not?)

All request query parameters are strings, but we forgot to convert x to a numeric value. This caused R interpreter to throw an error.

Note however how gracefully RestRserve handled this case:

• it hasn’t crashed and produced HTTP error with 500 code
• written error with expanded traceback to the log. This is particularly important as R’s traceback does not contain the full stack trace if you catch errors and warnings!

For example following code will just give you last error (but not a traceback):

fun2 = function(x) {
  sqrt(x)
}
fun1 = function(x) {
  fun2(x)
}
try(fun1('a'))
#> Error in sqrt(x) : non-numeric argument to mathematical function

Which is not very useful when you try to debug server application.

In contrast let’s call it within RestRserve application:

application$add_get("/sqrt2", function(.req, .res) {
  .res$set_body(fun1(x))
})
request = Request$new(path = "/sqrt2", method = "GET", parameters_query = list(x = "10")) 
response = application$process_request(request)
#> {"timestamp":"2022-06-09 13:42:21.746021","level":"ERROR","name":"Application","pid":49398,"msg":"","context":{"request_id":"75d0a0d8-e7d8-11ec-b9c1-4c327594fb6f","message":{"error":"object 'x' not found","call":"fun1(x)","traceback":["FUN(request, response)",".res$set_body(fun1(x))",".res$set_body(fun1(x))","fun2(x)"]}}}

Now we clearly see that error happens inside fun2