Repository: bentoml/BentoML
Pull request: Add prediction logging to AWS Lambda deployment
<!--- Thanks for sending a pull request! Please make sure to read the contribution guidelines, then fill out the blanks below. -->

## Description
* fix some basic typos in Lambda utils
* made bad python version during Lambda deploy error more descriptive
* add prediction logging to AWS Lambda endpoint

## Motivation and Context
* Improves usability of BentoML
* fixes #524 

## How Has This Been Tested?
<img width="808" alt="Screen Shot 2020-06-12 at 10 34 50 AM" src="https://user-images.githubusercontent.com/23178940/84530891-84214200-ac98-11ea-91e1-42976f15a017.png">

## Types of changes
- [ ] Breaking change (fix or feature that would cause existing functionality to change)
- [x] New feature (non-breaking change which adds functionality)
- [x] Bug fix (non-breaking change which fixes an issue)
- [ ] Documentation
- [ ] Test, CI, or build
- [ ] None

## Components (if applicable)
- [ ] BentoService (model packaging, dependency management, handler definition)
- [ ] Model Artifact (model serialization, multi-framework support)
- [ ] Model Server (mico-batching, logging, metrics, tracing, benchmark, OpenAPI)
- [x] YataiService (model management, deployment automation)
- [ ] Documentation


## Checklist:
- [x] My code follows the bentoml code style, both `./dev/format.sh` and
  `./dev/lint.sh` script have passed
  ([instructions](https://github.com/bentoml/BentoML/blob/master/DEVELOPMENT.md#style-check-and-auto-formatting-your-code)).
- [ ] My change requires a change to the documentation.
- [ ] I have updated the documentation accordingly.
- [ ] My change requires a change in [bentoml/gallery](https://github.com/bentoml/gallery) example notebooks
- [ ] I have sent a pull request to [bentoml/gallery](https://github.com/bentoml/gallery) to make that change


Problem statement:
Prediction log in AWS Lambda deployment
**Is your feature request related to a problem? Please describe.**
Currently, a BentoService AWS Lambda deployment only logs the prediction request but not the response (a.k.a the output of the model.) of API calls.


**Describe the solution you'd like**
Print the output of the model at the end of the lambda callback function

Hints from issue discussion:

Commit message: whitespace fixes

Patch to review:
diff --git a/bentoml/yatai/deployment/aws_lambda/lambda_app.py b/bentoml/yatai/deployment/aws_lambda/lambda_app.py
index 8f8cab5de36..943e6e5c483 100644
--- a/bentoml/yatai/deployment/aws_lambda/lambda_app.py
+++ b/bentoml/yatai/deployment/aws_lambda/lambda_app.py
@@ -14,13 +14,17 @@
 
 import os
 import sys
+import logging
+
+logger = logging.getLogger(__name__)
+logger.setLevel(logging.DEBUG)
 
 try:
     import download_extra_resources
 
-    print("Downloading extra requirements and files from s3..")
+    logger.info("Downloading extra requirements and files from s3..")
     download_extra_resources.download_extra_resources()
-    print("Finished downloading extra requirements and files")
+    logger.info("Finished downloading extra requirements and files")
 except ImportError:
     # When function doesn't have extra resources or dependencies, we will not include
     # unzip_extra_resources and that will result with ImportError.  We will let it fail
@@ -45,11 +49,11 @@
 if not os.path.exists(bento_bundle_path):
     bento_bundle_path = os.path.join('/tmp/requirements', bento_name)
 
-print(f'Loading BentoService bundle from path: "{bento_bundle_path}"')
+logger.info('Loading BentoService bundle from path: "%s"', bento_bundle_path)
 bento_service = load(bento_bundle_path)
-print(f'BentoService "{bento_service.name}" loaded successfully')
+logger.info('BentoService "%s" loaded successfully', bento_service.name)
 bento_service_api = bento_service.get_service_api(api_name)
-print(f'BentoService API "{api_name}" loaded successfully')
+logger.info('BentoService API "%s" loaded successfully', {api_name})
 
 this_module = sys.modules[__name__]
 
@@ -62,18 +66,36 @@ def api_func(event, context):  # pylint: disable=unused-argument
     Application Load Balancer, in which case the parameter `event` must be type `dict`
     containing the HTTP request headers and body.
 
-    see: https://docs.aws.amazon.com/lambda/latest/dg/services-alb.html
+    You can find an example of which
+    variables you can expect from the `event` object on the AWS Docs, here
+    https://docs.aws.amazon.com/lambda/latest/dg/services-alb.html
     """
 
     if type(event) is dict and "headers" in event and "body" in event:
-        return bento_service_api.handle_aws_lambda_event(event)
+        logger.info('Got prediction request with body "%s"', {event["body"]})
+        prediction = bento_service_api.handle_aws_lambda_event(event)
+
+        # raw json logs
+        logger.debug(event)
+        logger.debug(prediction)
+
+        if prediction["statusCode"] >= 400:
+            logger.warning(
+                'Error when predicting. Check logs for more information.'
+            )
+        else:
+            logger.info(
+                'Predicted "%s"', prediction["body"]
+            )
+
+        return prediction
     else:
         error_msg = (
             'Error: Unexpected Lambda event data received. Currently BentoML lambda '
             'deployment can only handle event triggered by HTTP request from '
             'Application Load Balancer.'
         )
-        print(error_msg)
+        logger.error(error_msg)
         raise RuntimeError(error_msg)
 
 
diff --git a/bentoml/yatai/deployment/aws_lambda/operator.py b/bentoml/yatai/deployment/aws_lambda/operator.py
index 24dd54362d9..a0af7cfe2c9 100644
--- a/bentoml/yatai/deployment/aws_lambda/operator.py
+++ b/bentoml/yatai/deployment/aws_lambda/operator.py
@@ -189,8 +189,10 @@ def _deploy_lambda_function(
         for i in artifact_types
     ) and (py_major, py_minor) != ('3', '6'):
         raise BentoMLException(
-            'For Tensorflow and Keras model, only python3.6 is '
-            'supported for AWS Lambda deployment'
+            'AWS Lambda Deployment only supports BentoML services'
+            'built with Python 3.6.x. To fix this, repack your'
+            'service with the right Python version'
+            '(hint: pyenv/anaconda) and try again'
         )
 
     api_names = (
diff --git a/bentoml/yatai/deployment/aws_lambda/utils.py b/bentoml/yatai/deployment/aws_lambda/utils.py
index b79e1ffa5c0..80444c0331a 100644
--- a/bentoml/yatai/deployment/aws_lambda/utils.py
+++ b/bentoml/yatai/deployment/aws_lambda/utils.py
@@ -201,7 +201,7 @@ def init_sam_project(
     function_path = os.path.join(sam_project_path, deployment_name)
     os.mkdir(function_path)
     # Copy requirements.txt
-    logger.debug('Coping requirements.txt')
+    logger.debug('Copying requirements.txt')
     requirement_txt_path = os.path.join(bento_service_bundle_path, 'requirements.txt')
     shutil.copy(requirement_txt_path, function_path)
 
@@ -210,7 +210,7 @@ def init_sam_project(
     )
     if os.path.isdir(bundled_dep_path):
         # Copy bundled pip dependencies
-        logger.debug('Coping bundled_dependencies')
+        logger.debug('Copying bundled_dependencies')
         shutil.copytree(
             bundled_dep_path, os.path.join(function_path, 'bundled_pip_dependencies')
         )
@@ -232,7 +232,7 @@ def init_sam_project(
             requirement_file.writelines(required_modules)
 
     # Copy bento_service_model
-    logger.debug('Coping model directory')
+    logger.debug('Copying model directory')
     model_path = os.path.join(bento_service_bundle_path, bento_name)
     shutil.copytree(model_path, os.path.join(function_path, bento_name))
 
diff --git a/docs/source/deployment/aws_lambda.rst b/docs/source/deployment/aws_lambda.rst
index 964dbff0f65..d9909c8bd96 100644
--- a/docs/source/deployment/aws_lambda.rst
+++ b/docs/source/deployment/aws_lambda.rst
@@ -201,7 +201,44 @@ Use `bentoml lambda list` to have a quick glance of all of the AWS Lambda deploy
     NAME                        NAMESPACE    LABELS    PLATFORM    STATUS    AGE
     my-first-lambda-deployment  dev                    aws-lambda  running   8 minutes and 49.6 seconds
 
+If you need to look at the logs of your deployed model, we can view these within AWS CloudWatch. You can get here by searching up `CloudWatch` in your AWS Console. Then, on the left panel, click `Logs > Log Groups` and select your Lambda deployment. The name should be of the form `/aws/lambda/dev-{name}` where `{name}` is the name you used when you deployed it using the CLI. Here, you can look at specific instances of your Lambda function and the logs within it. A typical prediction may look something like the following
 
+.. code-block:: none
+
+    ...
+    START RequestId: 11ee8a7a-9884-454a-b008-fd814d9b1781 Version: $LATEST
+    [INFO] 2020-06-14T02:13:24.464Z Loading BentoService bundle from path: "./IrisClassifier"
+    [INFO] 2020-06-14T02:13:26.422Z BentoService "IrisClassifier" loaded successfully
+    [INFO] 2020-06-14T02:13:26.422Z BentoService API "{'predict'}" loaded successfully
+    [INFO] 2020-06-14T02:13:26.425Z 11ee8a7a-9884-454a-b008-fd814d9b1781 Got prediction request with body "{'[[5.1, 3.5, 1.4, 0.2]]'}"
+    [DEBUG] 2020-06-14T02:13:26.439Z 11ee8a7a-9884-454a-b008-fd814d9b1781 {'resource': '/predict', 'path': '/predict',...
+    [DEBUG] 2020-06-14T02:13:26.439Z 11ee8a7a-9884-454a-b008-fd814d9b1781 {'statusCode': 200, 'body': '[0]'}
+    [INFO] 2020-06-14T02:13:26.439Z 11ee8a7a-9884-454a-b008-fd814d9b1781 Predicted "[0]"
+    END RequestId: 11ee8a7a-9884-454a-b008-fd814d9b1781
+    REPORT RequestId: 11ee8a7a-9884-454a-b008-fd814d9b1781 Duration: 14.97 ms Billed Duration: 100 ms Memory Size: 1024 MB...
+    ...
+
+If you'd like to have some more detailed analytics into your logs, you may notice that we log some more detailed JSON data as debug info. The first JSON it logs is some event info that AWS Lambda passes in to the event handler. You can find more information about what the JSON contains here: https://docs.aws.amazon.com/lambda/latest/dg/services-alb.html. The second JSON contains information regarding the output of the classifier, including its status code and actual prediction. An example of the prediction JSON is as follows,
+
+.. code-block:: bash
+
+    {
+      'statusCode': 200, 
+      'body': '[0]', 
+      'headers': {
+        'Access-Control-Allow-Origin': '*'
+      }
+    }
+
+You can parse both of these using CloudWatch Logs Insights or ElasticSearch. Within Logs Insights, you can construct a query to visualize the logs that match certain criteria. If, for example, you wanted to view all predictions the returned with a status code of 200, the query would look something like
+
+.. code-block:: none
+
+    fields @timestamp, @message, statusCode
+    | sort @timestamp desc
+    | filter statusCode = 200
+
+In this example, `@timestamp` and `@message` represent the time when the log was emitted and the full log message. The third field can be any first level JSON field that were logged (either event info or prediction info).
 
 Remove Lambda deployment is also very easy.  Calling `bentoml lambda delete` command will delete the Lambda function and related AWS resources
 
diff --git a/tests/deployment/aws_lambda/test_aws_lambda_deployment_operator.py b/tests/deployment/aws_lambda/test_aws_lambda_deployment_operator.py
index 7b18367261c..1b4c8c8c371 100644
--- a/tests/deployment/aws_lambda/test_aws_lambda_deployment_operator.py
+++ b/tests/deployment/aws_lambda/test_aws_lambda_deployment_operator.py
@@ -56,7 +56,7 @@ def generate_lambda_deployment_pb():
 
 def test_aws_lambda_app_py(monkeypatch):
     def test_predict(value):
-        return value['body']
+        return {'body': value['body'], 'statusCode': 200}
 
     class Mock_bento_service_class(object):
         name = "mock_bento_service"
@@ -106,7 +106,10 @@ def return_predict_func(mock_load_service):
     with pytest.raises(RuntimeError):
         predict("Invalid Input Type", None)
 
-    assert predict({"headers": [], "body": 'test'}, None) == 'test'
+    assert predict({"headers": [], "body": 'test'}, None) == {
+        'body': 'test',
+        'statusCode': 200,
+    }
 
 
 @patch('shutil.rmtree', MagicMock())


Code review comments:
diff_hunk: @@ -14,13 +14,17 @@
 
 import os
 import sys
+import logging
+
+logger = logging.getLogger(__name__)
+logger.setLevel(logging.DEBUG)
path: bentoml/yatai/deployment/aws_lambda/lambda_app.py
text: @user1:
after `import bentoml` below, the logging format and level might get reset, so probably don't need this `setLevel` here.

Could you move `logger = logging.getLogger(__name__)` to after the `from bentoml import load` line?  and keep the logging message in `download_extra_resources` just using `print`?

It is a bit tricky here because `bentoml` package may not be available to import before the `download_extra_resources` call, as the package file might be stored in s3 and needs to be downloaded first.

diff_hunk: @@ -45,11 +49,11 @@
 if not os.path.exists(bento_bundle_path):
     bento_bundle_path = os.path.join('/tmp/requirements', bento_name)
 
-print(f'Loading BentoService bundle from path: "{bento_bundle_path}"')
+logger.info('Loading BentoService bundle from path: "%s"', bento_bundle_path)
path: bentoml/yatai/deployment/aws_lambda/lambda_app.py
text: @user1:
how about changing all these to `logger.debug` and only keep the prediction log in `logger.info`?

diff_hunk: @@ -62,18 +66,36 @@ def api_func(event, context):  # pylint: disable=unused-argument
     Application Load Balancer, in which case the parameter `event` must be type `dict`
     containing the HTTP request headers and body.
 
-    see: https://docs.aws.amazon.com/lambda/latest/dg/services-alb.html
+    You can find an example of which
+    variables you can expect from the `event` object on the AWS Docs, here
+    https://docs.aws.amazon.com/lambda/latest/dg/services-alb.html
     """
 
     if type(event) is dict and "headers" in event and "body" in event:
-        return bento_service_api.handle_aws_lambda_event(event)
+        logger.info('Got prediction request with body "%s"', {event["body"]})
+        prediction = bento_service_api.handle_aws_lambda_event(event)
+
+        # raw json logs
+        logger.debug(event)
path: bentoml/yatai/deployment/aws_lambda/lambda_app.py
text: @user1:
I think it is more common to combine these into one JSON message to make logging ETL a lot easier, e.g.:

```python
import json
logger.info(json.dumps({ 'event': event, 'prediction': prediction["body"], 'status_code': prediction["statudCode"]}))
```

@author:
great idea, I'll add that