Merge branch 'better-logs'

* better-logs:
  Add logger feature to changelog
  Fix doclint issues
  Add docs for logging feature
  Don't include lambda messages by default
  Add app specific logging handler

CHANGELOG.rst

@@ -2,6 +2,13 @@
 CHANGELOG
 =========
 
+Next Release (TBD)
+==================
+
+* Add default application logger
+  (`#149 <https://github.com/awslabs/chalice/issues/149>`__)
+
+
 0.4.0
 =====
 

chalice/app.py

@@ -1,6 +1,8 @@
 """Chalice app and routing code."""
 import re
+import sys
 import base64
+import logging
 from collections import Mapping
 
 # Implementation note:  This file is intended to be a standalone file
@@ -149,11 +151,43 @@ def __eq__(self, other):
 
 class Chalice(object):
 
-    def __init__(self, app_name):
+    FORMAT_STRING = '%(name)s - %(levelname)s - %(message)s'
+
+    def __init__(self, app_name, configure_logs=True):
         self.app_name = app_name
         self.routes = {}
         self.current_request = None
         self.debug = False
+        self.configure_logs = configure_logs
+        self.log = logging.getLogger(self.app_name)
+        if self.configure_logs:
+            self._configure_logging()
+
+    def _configure_logging(self):
+        log = logging.getLogger(self.app_name)
+        if self._already_configured(log):
+            return
+        handler = logging.StreamHandler(sys.stdout)
+        # Timestamp is handled by lambda itself so the
+        # default FORMAT_STRING doesn't need to include it.
+        formatter = logging.Formatter(self.FORMAT_STRING)
+        handler.setFormatter(formatter)
+        log.propagate = False
+        if self.debug:
+            level = logging.DEBUG
+        else:
+            level = logging.ERROR
+        log.setLevel(level)
+        log.addHandler(handler)
+
+    def _already_configured(self, log):
+        if not log.handlers:
+            return False
+        for handler in log.handlers:
+            if isinstance(handler, logging.StreamHandler):
+                if handler.stream == sys.stdout:
+                    return True
+        return False
 
     def route(self, path, **kwargs):
         def _register_view(view_func):

chalice/cli/__init__.py

@@ -198,7 +198,7 @@ def deploy(ctx, project_dir, autogen_policy, profile, debug, stage):
 @click.option('--num-entries', default=None, type=int,
               help='Max number of log entries to show.')
 @click.option('--include-lambda-messages/--no-include-lambda-messages',
-              default=True,
+              default=False,
               help='Controls whether or not lambda log messages are included.')
 @click.pass_context
 def logs(ctx, project_dir, num_entries, include_lambda_messages):

docs/source/index.rst

@@ -57,6 +57,7 @@ Topics
    topics/routing
    topics/configfile
    topics/multifile
+   topics/logging
 
 
 API Reference

docs/source/topics/logging.rst

@@ -0,0 +1,85 @@
+Logging
+=======
+
+You have several options for logging in your
+application.  You can use any of the options
+available to lambda functions as outlined
+in the
+`AWS Lambda Docs <http://docs.aws.amazon.com/lambda/latest/dg/python-logging.html>`_.
+The simplest option is to just use print statements.
+Anything you print will be accessible in cloudwatch logs
+as well as in the output of the ``chalice logs`` command.
+
+In addition to using the stdlib ``logging`` module directly,
+the framework offers a preconfigured logger designed to work
+nicely with Lambda.  This is offered purely as a convenience,
+you can use ``print`` or the ``logging`` module directly if you prefer.
+
+You can access this logger via the ``app.log``
+attribute, which is a a logger specifically for your application.
+This attribute is an instance of ``logging.getLogger(your_app_name_)``
+that's been preconfigured with reasonable defaults:
+
+* StreamHandler associated with ``sys.stdout``.
+* Log level set to ``logging.ERROR`` by default.
+  You can also manually set the logging level by setting
+  ``app.log.setLevel(logging.DEBUG)``.
+* A logging formatter that displays the app name, level name,
+  and message.
+
+
+Examples
+--------
+
+In the following application, we're using the application logger
+to emit two log messages, one at ``DEBUG`` and one at the ``ERROR``
+level:
+
+.. code-block:: python
+
+    from chalice import Chalice
+
+    app = Chalice(app_name='demolog')
+
+
+    @app.route('/')
+    def index():
+        app.log.debug("This is a debug statement")
+        app.log.error("This is an error statement")
+        return {'hello': 'world'}
+
+
+If we make a request to this endpoint, and then look at
+``chalice logs`` we'll see the following log message::
+
+    2016-11-06 20:24:25.490000 9d2a92 demolog - ERROR - This is an error statement
+
+As you can see, only the ``ERROR`` level log is emitted because
+the default log level is ``ERROR``.  Also note the log message formatting.
+This is the default format that's been automatically configured.
+We can make a change to set our log level to debug:
+
+
+.. code-block:: python
+
+    from chalice import Chalice
+
+    app = Chalice(app_name='demolog')
+    # Enable DEBUG logs.
+    app.log.setLevel(logging.DEBUG)
+
+
+    @app.route('/')
+    def index():
+        app.log.debug("This is a debug statement")
+        app.log.error("This is an error statement")
+        return {'hello': 'world'}
+
+Now if we make a request to the ``/`` URL and look at the
+output of ``chalice logs``, we'll see the following log message::
+
+    2016-11-07 12:29:15.714 431786 demolog - DEBUG - This is a debug statement
+    2016-11-07 12:29:15.714 431786 demolog - ERROR - This is an error statement
+
+
+As you can see here, both the debug and error log message are shown.

tests/unit/test_app.py

@@ -1,4 +1,5 @@
 import base64
+import logging
 import json
 
 import pytest
@@ -369,3 +370,36 @@ def test_unknown_kwargs_raise_error(sample_app):
         @sample_app.route('/foo', unknown_kwargs='foo')
         def badkwargs():
             pass
+
+
+def test_default_logging_handlers_created():
+    handlers_before = logging.getLogger('log_app').handlers[:]
+    # configure_logs = True is the default, but we're
+    # being explicit here.
+    app.Chalice('log_app', configure_logs=True)
+    handlers_after = logging.getLogger('log_app').handlers[:]
+    new_handlers = set(handlers_after) - set(handlers_before)
+    # Should have added a new handler
+    assert len(new_handlers) == 1
+
+
+def test_default_logging_only_added_once():
+    # And creating the same app object means we shouldn't
+    # configure logging again.
+    handlers_before = logging.getLogger('added_once').handlers[:]
+    app.Chalice('added_once', configure_logs=True)
+    # The same app name, we should still only configure logs
+    # once.
+    app.Chalice('added_once', configure_logs=True)
+    handlers_after = logging.getLogger('added_once').handlers[:]
+    new_handlers = set(handlers_after) - set(handlers_before)
+    # Should have added a new handler
+    assert len(new_handlers) == 1
+
+
+def test_logs_can_be_disabled():
+    handlers_before = logging.getLogger('log_app').handlers[:]
+    app.Chalice('log_app', configure_logs=False)
+    handlers_after = logging.getLogger('log_app').handlers[:]
+    new_handlers = set(handlers_after) - set(handlers_before)
+    assert len(new_handlers) == 0