Control runtime log level via environment variable (#33)

Author: philipp94831

README.md

@@ -231,6 +231,10 @@ See `awspack/` for an example.
 The `build.sh` script is used to run the docker container and copy sources to your machine.
 The `entrypoint.sh` script is used for installing packages inside the container.
 
+### Debugging
+
+In order to make the runtime log debugging messages, you can set the environment variable `LOGLEVEL` to `DEBUG`.
+
 ## Limitations
 
 AWS Lambda is limited to running with 3GB RAM and must finish within 15 minutes.

runtime/src/bootstrap.R

@@ -3,6 +3,7 @@ tryCatch({
     function_name <- initializeRuntime()
     while (TRUE) {
         handle_request(function_name)
+        logReset()
         rm(list=ls())
         source('/opt/runtime.R')
         function_name <- initializeRuntime()

runtime/src/runtime.R

@@ -7,12 +7,12 @@ error_to_payload <- function(error) {
 }
 
 post_error <- function(error, url) {
-    logerror(error)
+    logerror(error, logger = 'runtime')
     res <- POST(url,
                 add_headers("Lambda-Runtime-Function-Error-Type" = "Unhandled"),
                 body = error_to_payload(error),
                 encode = "json")
-    logdebug("Posted result:\n%s", to_str(res))
+    logdebug("Posted result:\n%s", to_str(res), logger = 'runtime')
 }
 
 get_source_file_name <- function(file_base_name) {
@@ -28,22 +28,33 @@ get_source_file_name <- function(file_base_name) {
 
 invoke_lambda <- function(EVENT_DATA, function_name) {
     params <- fromJSON(EVENT_DATA)
-    logdebug("Invoking function '%s' with parameters:\n%s", function_name, to_str(params))
+    logdebug("Invoking function '%s' with parameters:\n%s", function_name, to_str(params), logger = 'runtime')
     result <- do.call(function_name, params)
-    logdebug("Function returned:\n%s", to_str(result))
+    logdebug("Function returned:\n%s", to_str(result), logger = 'runtime')
     return(result)
 }
 
+initializeLogging <- function() {
+    library(logging)
+
+    basicConfig()
+    addHandler(writeToConsole, logger='runtime')
+    log_level <- Sys.getenv('LOGLEVEL', unset = NA)
+    if (!is.na(log_level)) {
+        setLevel(log_level, 'runtime')
+    }
+}
+
 initializeRuntime <- function() {
     library(httr)
     library(jsonlite)
-    library(logging)
 
+    initializeLogging()
     HANDLER <- Sys.getenv("_HANDLER")
     HANDLER_split <- strsplit(HANDLER, ".", fixed = TRUE)[[1]]
     file_base_name <- HANDLER_split[1]
     file_name <- get_source_file_name(file_base_name)
-    logdebug("Sourcing '%s'", file_name)
+    logdebug("Sourcing '%s'", file_name, logger = 'runtime')
     source(file_name)
     function_name <- HANDLER_split[2]
     if (!exists(function_name, mode = "function")) {
@@ -69,7 +80,7 @@ throwRuntimeError <- function(error, REQUEST_ID) {
 postResult <- function(result, REQUEST_ID) {
     url <- paste0(API_ENDPOINT, "invocation/", REQUEST_ID, "/response")
     res <- POST(url, body = toJSON(result, auto_unbox = TRUE), encode = "raw", content_type_json())
-    logdebug("Posted result:\n%s", to_str(res))
+    logdebug("Posted result:\n%s", to_str(res), logger = 'runtime')
 }
 
 handle_request <- function(function_name) {

test-template.yaml

@@ -58,6 +58,9 @@ Resources:
     Properties:
       Handler: script.handler_with_debug_logging
       CodeUri: tests/R/
+      Environment:
+        Variables:
+          LOGLEVEL: DEBUG
       FunctionName: !Sub LoggingFunction-${Version}
   MatrixFunction:
     Type: 'AWS::Serverless::Function'

tests/R/script.R

@@ -13,6 +13,5 @@ handler_with_variable_arguments <- function(...) {
 handler_as_variable <- "foo"
 
 handler_with_debug_logging <- function(x) {
-    basicConfig(level='DEBUG')
     return(1)
 }

tests/test_runtime.py

@@ -61,9 +61,10 @@ def test_debug_logging(self):
         result = json.loads(raw_payload)
         self.assertEqual(1, result)
         log = base64.b64decode(response['LogResult']).decode('utf-8')
-        self.assertIn("Invoking function 'handler_with_debug_logging' with parameters:\n$x\n[1] 1", log)
-        self.assertIn("Function returned:\n[1] 1", log)
-        self.assertIn("Sourcing 'script.R'", log)
+        self.assertIn("runtime:Sourcing 'script.R'", log)
+        self.assertIn("runtime:Invoking function 'handler_with_debug_logging' with parameters:\n$x\n[1] 1", log)
+        self.assertIn("runtime:Function returned:\n[1] 1", log)
+        self.assertIn("runtime:Posted result:\n", log)
 
     @unittest.skipIf(is_local(), 'Lambda local does not support log retrieval')
     def test_no_debug_logging(self):
@@ -76,9 +77,10 @@ def test_no_debug_logging(self):
         result = json.loads(raw_payload)
         self.assertEqual(2, result)
         log = base64.b64decode(response['LogResult']).decode('utf-8')
-        self.assertNotIn("Invoking function 'handler_with_debug_logging' with parameters:\n$x\n[1] 1", log)
-        self.assertNotIn("Function returned:\n[1] 1", log)
-        self.assertNotIn("Sourcing 'script.R'", log)
+        self.assertNotIn("Sourcing ", log)
+        self.assertNotIn("Invoking function ", log)
+        self.assertNotIn("Function returned:", log)
+        self.assertNotIn("Posted result:", log)
 
     @unittest.skipIf(is_local(), 'Lambda local does not pass errors properly')
     def test_missing_source_file(self):