log timestamp when --debug is presented (#1773) #2266

aahung · 2020-10-01T06:33:46Z

log entry will look like '2020-09-30 20:51:12,353 | ...'

Issue #1773, if available:

Why is this change necessary?

Allow users to have better visibility on how long each process takes

How does it address the issue?

Timestamp is printed as well

What side effects does this change have?

No side effect I am aware of

Did you change a dependency in requirements/base.txt?
If so, did you run make update-reproducible-reqs

Checklist:

Write Design Document (Do I need to write a design document?)
Write unit tests
Write/update functional tests
Write/update integration tests
make pr passes
Write documentation

By submitting this pull request, I confirm that my contribution is made under the terms of the Apache 2.0 license.

aahung · 2020-10-01T06:35:21Z

A sample log:

(samcli37) ~/P/hello-world-nodejs ❯❯❯ samdev local invoke "HelloWorldFunction" -e events/event.json --debug --timestamp-output
2020-09-30 20:51:12,353 | Telemetry endpoint configured to be https://aws-serverless-tools-telemetry.us-west-2.amazonaws.com/metrics
2020-09-30 20:51:12,509 | local invoke command is called
2020-09-30 20:51:12,515 | No Parameters detected in the template
2020-09-30 20:51:12,539 | 2 resources found in the template
2020-09-30 20:51:12,539 | Found Serverless function with name='HelloWorldFunction' and CodeUri='HelloWorldFunction'
2020-09-30 20:51:12,548 | Found one Lambda function with name 'HelloWorldFunction'
2020-09-30 20:51:12,549 | Invoking app.lambdaHandler (nodejs12.x)
2020-09-30 20:51:12,549 | No environment variables found for function 'HelloWorldFunction'
2020-09-30 20:51:12,549 | Environment variables overrides data is standard format
2020-09-30 20:51:12,549 | Loading AWS credentials from session with profile 'None'
2020-09-30 20:51:12,574 | Resolving code path. Cwd=/Users/XXXXX/Projects/hello-world-nodejs/.aws-sam/build, CodeUri=HelloWorldFunction
2020-09-30 20:51:12,574 | Resolved absolute path to code is /Users/XXXXX/Projects/hello-world-nodejs/.aws-sam/build/HelloWorldFunction
2020-09-30 20:51:12,574 | Code /Users/XXXXX/Projects/hello-world-nodejs/.aws-sam/build/HelloWorldFunction is not a zip/jar file
2020-09-30 20:51:12,586 | Skip pulling image and use local one: amazon/aws-sam-cli-emulation-image-nodejs12.x:rapid-1.3.2.

2020-09-30 20:51:12,586 | Mounting /Users/XXXXX/Projects/hello-world-nodejs/.aws-sam/build/HelloWorldFunction as /var/task:ro,delegated inside runtime container
2020-09-30 20:51:12,884 | Starting a timer for 3 seconds for function 'HelloWorldFunction'
START RequestId: XXXXX-XXXXXXX Version: $LATEST
END RequestId: XXXXX-XXXXXXXREPORT RequestId: XXXXX-XXXXXXX	Init Duration: 101.10 ms	Duration: 2.50 ms	Billed Duration: 100 ms	Memory Size: 128 MB	Max Memory Used: 39 MB
2020-09-30 20:51:13,132 | Sending Telemetry: {XXXXXXXXXXXXXXXXXXXXXXX}
2020-09-30 23:36:41,996 | Telemetry response: 200

{"statusCode":200,"body":"{\"message\":\"hello world\"}"}

tests/unit/cli/test_context.py

samcli/cli/context.py

jfuss · 2020-10-01T19:22:04Z

samcli/cli/context.py

@@ -40,6 +42,10 @@ def __init__(self):
    def debug(self):
        return self._debug

+    @property
+    def output_timestamp(self):


Can't we just configure the logger to have the timestamp when debugging is enabled? Do we really need a new options for this?

Related comment from @awsjeffg

#1773 (comment)

I think the idea is, maybe, for non-debug mode, users will want still to see the timestamp. So having a dedicate flag gives such flexibility.

@jfuss You're not wrong, I am just being careful as we've run into other problems where changing stdout behaviour causes customers problems.

@awsjeffg Yes, we have run into problems with other tools expecting certain output but that has been against our 'info' logs not 'debug'. Additionally, we should be able to freely add data without worrying. I see a stronger case for removing output. I am not saying we shouldn't be cautious around changing output but as a product we need to have the flexibility to update and change output, otherwise we are always stuck with whatever we ship with. I am a strong believer in relying on stdout or stderr output is an anti-pattern and should be treated as behavior not an interface. I am only aware of the AWS Toolkit depending on our output, can't we just ask them if this would break them? My understanding is it shouldn't.

Long ago, we had the default logger for all of SAM CLI's logs. This was overly noisy and we ended up removing it. I personally do not see a difference between adding --time-stamp-output and using --debug. They are ways to configure the logging and output. We should be aware of the additional overhead on our customer when adding new options for things. Why should we have an option versus an environment variable? If you want this still to be intentionally, wouldn't something like allowing --debug --debug to allow customers to control/add additional output (similar to -vv which is common for command line tools)?

I can understand wanting to introduce this in a new way somehow (though I don't fully agree), but the main thing I want to poke at is: Why a new command line option?

Both are valid in my opinion. Another thought against ONLY including timestamp in DEBUG mode: including timestamp into --debug which is used for configuring logging level is implicit in my opinion.

Ideally I would prefer to always include timestamps regardless what logging level users chooses to configure. But as @awsjeffg pointed out, it will change stdout behaviour. I understand changing stdout is not something we like to do very often, but --output-timetamp does feel like a temporary solution.

Considering users only use --debug mode for investigating (are they?), I think it is fairly safe to change stdout behavior there assuming debug stdout won't be used for postprcessing. What do you think?

jfuss

Just a couple questions but overall this looks good.

jfuss · 2020-10-09T21:15:50Z

samcli/cli/context.py

+            for logger_name in [SAM_CLI_LOGGER_NAME, LAMBDA_BULDERS_LOGGER_NAME]:
+                logger = logging.getLogger(logger_name)
+                logger.setLevel(logging.DEBUG)
+                for handler in logger.handlers:


Why are we setting on all handlers?

There is only one handlers I think. In order to get handler object from logger, only logger.handlers is available.

(no longer applicable in the latest iteration)

jfuss · 2020-10-09T21:18:30Z

samcli/cli/context.py

-            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 [SAM_CLI_LOGGER_NAME, LAMBDA_BULDERS_LOGGER_NAME]:


Just noticing this. Why are we setting the logger directly instead of through SamCliLogger.configure_logger like we do in other places?

SamCliLogger.configure_logger will add a new handler. We should change the existing handlers here.

But I do think we should pack this into SamCliLogger though!

jfuss · 2020-10-13T20:22:17Z

samcli/lib/utils/sam_logging.py

+            log_stream_handler = handlers[0]
+        else:
+            log_stream_handler = logging.StreamHandler()
+            logger.addHandler(log_stream_handler)


Do we not need to addHandler() in the if part?

If there is already a handler, it indicates this method is called before. We only need to change the existing handler instead of creating a new one.

So then we don't need line 32 and 33 above? Can we update this to only do the StreamHanlder if handler is None?

log entry will look like '2020-09-30 20:51:12,353 | ...'

aahung force-pushed the add-option-timestamp-output branch from 3e5377c to e0ae22e Compare October 1, 2020 17:06

aahung requested review from CoshUS and jfuss October 1, 2020 17:10

CoshUS reviewed Oct 1, 2020

View reviewed changes

tests/unit/cli/test_context.py Outdated Show resolved Hide resolved

CoshUS suggested changes Oct 1, 2020

View reviewed changes

samcli/cli/context.py Outdated Show resolved Hide resolved

jfuss requested changes Oct 1, 2020

View reviewed changes

CoshUS approved these changes Oct 1, 2020

View reviewed changes

aahung force-pushed the add-option-timestamp-output branch 3 times, most recently from 8ffbffb to d6f7645 Compare October 7, 2020 04:28

aahung requested a review from jfuss October 7, 2020 04:29

aahung changed the title ~~Add option --timestamp-output to log timestamp (#1773)~~ log timestamp when --debug is presented (#1773) Oct 7, 2020

aahung force-pushed the add-option-timestamp-output branch from d6f7645 to bece598 Compare October 7, 2020 04:34

jfuss requested changes Oct 9, 2020

View reviewed changes

aahung force-pushed the add-option-timestamp-output branch from bece598 to c8aaaca Compare October 10, 2020 00:37

aahung requested a review from jfuss October 13, 2020 20:13

jfuss reviewed Oct 13, 2020

View reviewed changes

jfuss approved these changes Oct 13, 2020

View reviewed changes

aahung added 2 commits October 13, 2020 14:43

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

3881bc8

log entry will look like '2020-09-30 20:51:12,353 | ...'

chore: Make logger name into shared constants (aws#1773)

7a48acb

aahung force-pushed the add-option-timestamp-output branch from 82caa58 to 7a48acb Compare October 13, 2020 21:45

aahung merged commit cd4c061 into aws:develop Oct 13, 2020

aahung deleted the add-option-timestamp-output branch October 13, 2020 23:12

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

log timestamp when --debug is presented (#1773) #2266

log timestamp when --debug is presented (#1773) #2266

aahung commented Oct 1, 2020

aahung commented Oct 1, 2020 •

edited

Loading

jfuss Oct 1, 2020

aahung Oct 1, 2020

awsjeffg Oct 1, 2020

jfuss Oct 2, 2020

aahung Oct 5, 2020

jfuss left a comment

jfuss Oct 9, 2020

aahung Oct 9, 2020

aahung Oct 10, 2020

jfuss Oct 9, 2020

aahung Oct 9, 2020

aahung Oct 9, 2020

aahung Oct 10, 2020

jfuss Oct 13, 2020

aahung Oct 13, 2020

jfuss Oct 13, 2020

log timestamp when --debug is presented (#1773) #2266

log timestamp when --debug is presented (#1773) #2266

Conversation

aahung commented Oct 1, 2020

aahung commented Oct 1, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jfuss left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

aahung commented Oct 1, 2020 •

edited

Loading