Merge pull request #40 from bakdata/feature/debug-logging-in-runtime

philipp94831 · web-flow · commit fd664b3027e5 · 2019-06-14T09:51:20.000+02:00
Use debug logging in runtime
diff --git a/README.md b/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.
diff --git a/runtime/src/bootstrap.R b/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()
diff --git a/runtime/src/runtime.R b/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")
-    loginfo("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)
-    loginfo("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)
-    loginfo("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)
-    loginfo("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())
-    loginfo("Posted result:\n%s", to_str(res))
+    logdebug("Posted result:\n%s", to_str(res), logger = 'runtime')
 }
 
 handle_request <- function(function_name) {
diff --git a/test-template.yaml b/test-template.yaml
@@ -6,7 +6,7 @@ Parameters:
 Globals:
   Function:
     Runtime: provided
-    Timeout: 300
+    Timeout: 900
     MemorySize: 3008
     Layers:
       - !Ref RuntimeLayer
@@ -53,6 +53,15 @@ Resources:
       Handler: script.handler_with_variable_arguments
       CodeUri: tests/R/
       FunctionName: !Sub VariableArgumentsFunction-${Version}
+  LoggingFunction:
+    Type: 'AWS::Serverless::Function'
+    Properties:
+      Handler: script.handler_with_debug_logging
+      CodeUri: tests/R/
+      Environment:
+        Variables:
+          LOGLEVEL: DEBUG
+      FunctionName: !Sub LoggingFunction-${Version}
   MatrixFunction:
     Type: 'AWS::Serverless::Function'
     Properties:
diff --git a/tests/R/script.R b/tests/R/script.R
@@ -10,4 +10,8 @@ handler_with_variable_arguments <- function(...) {
     return(1)
 }
 
-handler_as_variable <- "foo"
+handler_as_variable <- "foo"
+
+handler_with_debug_logging <- function(x) {
+    return(1)
+}
diff --git a/tests/sam.py b/tests/sam.py
@@ -72,7 +72,7 @@ def __init__(self,
 
     def get_client(self):
         config = botocore.client.Config(signature_version=botocore.UNSIGNED,
-                                        read_timeout=300,
+                                        read_timeout=900,
                                         retries={'max_attempts': 0},
                                         )
         return boto3.client('lambda',
diff --git a/tests/test_aws.py b/tests/test_aws.py
@@ -26,8 +26,8 @@ def test_s3_get_object(self):
         response = lambda_client.invoke(FunctionName=get_function_name("AWSFunction"))
         raw_payload = response['Payload'].read().decode('utf-8')
         result = json.loads(raw_payload)
-        self.assertEqual(len(result), 1)
-        self.assertDictEqual(result[0], {
+        self.assertEqual(1, len(result))
+        self.assertDictEqual({
             "DRG.Definition": "039 - EXTRACRANIAL PROCEDURES W/O CC/MCC",
             "Provider.Id": "10001",
             "Provider.Name": "SOUTHEAST ALABAMA MEDICAL CENTER",
@@ -40,7 +40,7 @@ def test_s3_get_object(self):
             "Average.Covered.Charges": "$32963.07",
             "Average.Total.Payments": "$5777.24",
             "Average.Medicare.Payments": "$4763.73"
-        })
+        }, result[0])
 
     @classmethod
     def tearDownClass(cls):
diff --git a/tests/test_matrix.py b/tests/test_matrix.py
@@ -25,7 +25,7 @@ def test_matrix(self):
         response = lambda_client.invoke(FunctionName=get_function_name("MatrixFunction"))
         raw_payload = response['Payload'].read().decode('utf-8')
         result = json.loads(raw_payload)
-        self.assertEqual(len(result), 3)
+        self.assertEqual(3, len(result))
         self.assertIn(4, result)
         self.assertIn(5, result)
         self.assertIn(6, result)
diff --git a/tests/test_runtime.py b/tests/test_runtime.py
@@ -1,5 +1,6 @@
+import base64
 import json
-import os
+import re
 import unittest
 
 import boto3
@@ -28,7 +29,7 @@ def test_script(self):
                                         )
         raw_payload = response['Payload'].read().decode('utf-8')
         result = json.loads(raw_payload)
-        self.assertEqual(result, 2)
+        self.assertEqual(2, result)
 
     def test_lowercase_extension(self):
         lambda_client = self.get_client()
@@ -37,7 +38,7 @@ def test_lowercase_extension(self):
                                         )
         raw_payload = response['Payload'].read().decode('utf-8')
         result = json.loads(raw_payload)
-        self.assertEqual(result, 2)
+        self.assertEqual(2, result)
 
     def test_multiple_arguments(self):
         lambda_client = self.get_client()
@@ -47,7 +48,39 @@ def test_multiple_arguments(self):
                                         )
         raw_payload = response['Payload'].read().decode('utf-8')
         result = json.loads(raw_payload)
-        self.assertDictEqual(result, payload)
+        self.assertDictEqual(payload, result)
+
+    @unittest.skipIf(is_local(), 'Lambda local does not support log retrieval')
+    def test_debug_logging(self):
+        lambda_client = self.get_client()
+        response = lambda_client.invoke(FunctionName=get_function_name("LoggingFunction"),
+                                        LogType='Tail',
+                                        Payload=json.dumps({'x': 1}),
+                                        )
+        raw_payload = response['Payload'].read().decode('utf-8')
+        result = json.loads(raw_payload)
+        self.assertEqual(1, result)
+        log = base64.b64decode(response['LogResult']).decode('utf-8')
+        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):
+        lambda_client = self.get_client()
+        response = lambda_client.invoke(FunctionName=get_function_name("ExampleFunction"),
+                                        LogType='Tail',
+                                        Payload=json.dumps({'x': 1}),
+                                        )
+        raw_payload = response['Payload'].read().decode('utf-8')
+        result = json.loads(raw_payload)
+        self.assertEqual(2, result)
+        log = base64.b64decode(response['LogResult']).decode('utf-8')
+        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):
@@ -58,7 +91,7 @@ def test_missing_source_file(self):
         raw_payload = response['Payload'].read().decode('utf-8')
         json_payload = json.loads(raw_payload)
         self.assertIn('Source file does not exist: missing.[R|r]', json_payload['errorMessage'])
-        self.assertEqual(json_payload['errorType'], 'simpleError')
+        self.assertEqual('simpleError', json_payload['errorType'])
 
     @unittest.skipIf(is_local(), 'Lambda local does not pass errors properly')
     def test_missing_function(self):
@@ -69,7 +102,7 @@ def test_missing_function(self):
         raw_payload = response['Payload'].read().decode('utf-8')
         json_payload = json.loads(raw_payload)
         self.assertIn('Function "handler_missing" does not exist', json_payload['errorMessage'])
-        self.assertEqual(json_payload['errorType'], 'simpleError')
+        self.assertEqual('simpleError', json_payload['errorType'])
 
     @unittest.skipIf(is_local(), 'Lambda local does not pass errors properly')
     def test_function_as_variable(self):
@@ -80,7 +113,7 @@ def test_function_as_variable(self):
         raw_payload = response['Payload'].read().decode('utf-8')
         json_payload = json.loads(raw_payload)
         self.assertIn('Function "handler_as_variable" does not exist', json_payload['errorMessage'])
-        self.assertEqual(json_payload['errorType'], 'simpleError')
+        self.assertEqual('simpleError', json_payload['errorType'])
 
     @unittest.skipIf(is_local(), 'Lambda local does not pass errors properly')
     def test_missing_argument(self):
@@ -89,7 +122,7 @@ def test_missing_argument(self):
         raw_payload = response['Payload'].read().decode('utf-8')
         json_payload = json.loads(raw_payload)
         self.assertIn('argument "x" is missing, with no default', json_payload['errorMessage'])
-        self.assertEqual(json_payload['errorType'], 'simpleError')
+        self.assertEqual('simpleError', json_payload['errorType'])
 
     @unittest.skipIf(is_local(), 'Lambda local does not pass errors properly')
     def test_unused_argument(self):
@@ -100,18 +133,18 @@ def test_unused_argument(self):
         raw_payload = response['Payload'].read().decode('utf-8')
         json_payload = json.loads(raw_payload)
         self.assertIn('unused argument (y = 1)', json_payload['errorMessage'])
-        self.assertEqual(json_payload['errorType'], 'simpleError')
+        self.assertEqual('simpleError', json_payload['errorType'])
 
-    @unittest.skip('Lambda local does not pass errors properly')
+    @unittest.skipIf(is_local(), 'Fails locally with "argument list too long"')
     def test_long_argument(self):
         lambda_client = self.get_client()
         payload = {x: x for x in range(0, 100000)}
         response = lambda_client.invoke(FunctionName=get_function_name("VariableArgumentsFunction"),
                                         Payload=json.dumps(payload),
                                         )
         raw_payload = response['Payload'].read().decode('utf-8')
-        json_payload = json.loads(raw_payload)
-        self.assertEqual(json_payload['errorType'], 'Runtime.ExitError')
+        result = json.loads(raw_payload)
+        self.assertEqual(1, result)
 
     @unittest.skipIf(is_local(), 'Lambda local does not pass errors properly')
     def test_missing_library(self):
@@ -123,7 +156,7 @@ def test_missing_library(self):
         json_payload = json.loads(raw_payload)
         self.assertIn('there is no package called ‘Matrix’', json_payload['errorMessage'])
         error_type = 'packageNotFoundError' if get_version() == '3_6_0' else 'simpleError'
-        self.assertEqual(json_payload['errorType'], error_type)
+        self.assertEqual(error_type, json_payload['errorType'])
 
     @classmethod
     def tearDownClass(cls):

Original file line number	Diff line number	Diff line change
`@@ -10,4 +10,8 @@ handler_with_variable_arguments <- function(...) {`
`10`	`10`	`return(1)`
`11`	`11`	`}`
`12`	`12`
`13`		`-handler_as_variable <- "foo"`
	`13`	`+handler_as_variable <- "foo"`
	`14`	`+`
	`15`	`+handler_with_debug_logging <- function(x) {`
	`16`	`+ return(1)`
	`17`	`+}`
Original file line number	Diff line number	Diff line change
`@@ -72,7 +72,7 @@ def __init__(self,`
`72`	`72`
`73`	`73`	`def get_client(self):`
`74`	`74`	`config = botocore.client.Config(signature_version=botocore.UNSIGNED,`
`75`		`- read_timeout=300,`
	`75`	`+ read_timeout=900,`
`76`	`76`	`retries={'max_attempts': 0},`
`77`	`77`	`)`
`78`	`78`	`return boto3.client('lambda',`