Logging timestamps when --debug flag is presented (aws#1773)

log entry will look like '2020-09-30 20:51:12,353 | ...'
aahung · Oct 7, 2020 · c75356f · c75356f
1 parent 2f6061f
commit c75356f
Show file tree

Hide file tree

Showing 5 changed files with 38 additions and 8 deletions.
diff --git a/samcli/cli/context.py b/samcli/cli/context.py
@@ -12,6 +12,7 @@
 import click
 
 from samcli.commands.exceptions import CredentialsError
+from samcli.lib.utils.sam_logging import SAM_CLI_FORMATTER_WITH_TIMESTAMP
 
 
 class Context:
@@ -50,9 +51,12 @@ def debug(self, value):
         self._debug = value
 
         if self._debug:
-            # Turn on debug logging
-            logging.getLogger("samcli").setLevel(logging.DEBUG)
-            logging.getLogger("aws_lambda_builders").setLevel(logging.DEBUG)
+            # Turn on debug logging and display timestamps
+            for logger_name in ["samcli", "aws_lambda_builders"]:
+                logger = logging.getLogger(logger_name)
+                logger.setLevel(logging.DEBUG)
+                for handler in logger.handlers:
+                    handler.setFormatter(SAM_CLI_FORMATTER_WITH_TIMESTAMP)
 
     @property
     def region(self):

diff --git a/samcli/cli/main.py b/samcli/cli/main.py
@@ -8,7 +8,7 @@
 
 from samcli import __version__
 from samcli.lib.telemetry.metrics import send_installed_metric
-from samcli.lib.utils.sam_logging import SamCliLogger
+from samcli.lib.utils.sam_logging import SamCliLogger, SAM_CLI_FORMATTER
 from .options import debug_option, region_option, profile_option
 from .context import Context
 from .command import BaseCommand
@@ -95,10 +95,9 @@ def cli(ctx):
             LOG.debug("Unable to write telemetry flag", exc_info=ex)
 
     sam_cli_logger = logging.getLogger("samcli")
-    sam_cli_formatter = logging.Formatter("%(message)s")
     lambda_builders_logger = logging.getLogger("aws_lambda_builders")
     botocore_logger = logging.getLogger("botocore")
 
-    SamCliLogger.configure_logger(sam_cli_logger, sam_cli_formatter, logging.INFO)
-    SamCliLogger.configure_logger(lambda_builders_logger, sam_cli_formatter, logging.INFO)
+    SamCliLogger.configure_logger(sam_cli_logger, SAM_CLI_FORMATTER, logging.INFO)
+    SamCliLogger.configure_logger(lambda_builders_logger, SAM_CLI_FORMATTER, logging.INFO)
     SamCliLogger.configure_null_logger(botocore_logger)
diff --git a/samcli/cli/options.py b/samcli/cli/options.py
@@ -25,7 +25,7 @@ def callback(ctx, param, value):
         expose_value=False,
         is_flag=True,
         envvar="SAM_DEBUG",
-        help="Turn on debug logging to print debug message generated by SAM CLI.",
+        help="Turn on debug logging to print debug message generated by SAM CLI and display timestamps.",
         callback=callback,
     )(f)
 

diff --git a/samcli/lib/utils/sam_logging.py b/samcli/lib/utils/sam_logging.py
@@ -4,6 +4,10 @@
 import logging
 
 
+SAM_CLI_FORMATTER = logging.Formatter("%(message)s")
+SAM_CLI_FORMATTER_WITH_TIMESTAMP = logging.Formatter("%(asctime)s | %(message)s")
+
+
 class SamCliLogger:
     @staticmethod
     def configure_logger(logger, formatter, level):

diff --git a/tests/unit/cli/test_context.py b/tests/unit/cli/test_context.py
@@ -1,10 +1,13 @@
+import re
+
 import boto3
 import logging
 
 from unittest import TestCase
 from unittest.mock import patch, ANY
 
 from samcli.cli.context import Context
+from samcli.lib.utils.sam_logging import SamCliLogger, SAM_CLI_FORMATTER
 
 
 class TestContext(TestCase):
@@ -24,8 +27,28 @@ def test_must_set_get_debug_flag(self):
     def test_must_unset_get_debug_flag(self):
         ctx = Context()
 
+        message_record = logging.makeLogRecord({"msg": "hello world"})
+        timestamp_log_regex = re.compile(r"^[0-9:\- ,]+ \| .*$")
+
+        sam_cli_logger = logging.getLogger("samcli")
+        lambda_builders_logger = logging.getLogger("aws_lambda_builders")
+        SamCliLogger.configure_logger(sam_cli_logger, SAM_CLI_FORMATTER, logging.INFO)
+        SamCliLogger.configure_logger(lambda_builders_logger, SAM_CLI_FORMATTER, logging.INFO)
+
+        handlers = logging.getLogger("samcli").handlers + logging.getLogger("aws_lambda_builders").handlers
+        # timestamp should not be output
+        for handler in handlers:
+            self.assertNotRegex(handler.formatter.format(message_record), timestamp_log_regex)
+
         ctx.debug = True
         self.assertEqual(ctx.debug, True, "debug must be set to True")
+        # timestamp should be output
+        for handler in handlers:
+            self.assertRegex(
+                handler.formatter.format(message_record),
+                timestamp_log_regex,
+                "debug log record should contain timestamps",
+            )
 
         # Flipping from True to False
         ctx.debug = False