No timestamp in --debug

[literakl]

Describe your idea/feature/enhancement

I need to find out why it takes 4-6 seconds to process my lambda, which takes 400 ms to initialize and 200 ms to run. I found --debug option. It really prints more information but without a time indication. So I cannot compare where sam spent the time.

2020-02-05 18:36:22 127.0.0.1 - - [05/Feb/2020 18:36:22] "GET /v1/verify/Yk6QwCF1 HTTP/1.1" 403 -
Constructed String representation of Event to invoke Lambda. Event: {"httpMethod": "GET", "body": null, "resource": "/v1/verify/{token}", "requestContext": {"resourceId": "123456", "apiId": "1234567890", "resourcePath": "/v1/verify/{token}", "httpMethod": "GET", "requ
estId": "c6af9ac6-7b61-11e6-9a41-93e8deadbeef", "accountId": "123456789012", "stage": "production", "identity": {"apiKey": null, "userArn": null, "cognitoAuthenticationType": null, "caller": null, "userAgent": "Custom User Agent String", "user": null, "cognitoIdentity
PoolId": null, "cognitoAuthenticationProvider": null, "sourceIp": "127.0.0.1", "accountId": null}, "extendedRequestId": null, "path": "/v1/verify/{token}"}, "queryStringParameters": null, "multiValueQueryStringParameters": null, "headers": {"Host": "127.0.0.1:3000", "
Connection": "keep-alive", "Accept": "application/json, text/plain, /", "User-Agent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/79.0.3945.130 Safari/537.36", "Origin": "http://localhost:8080", "Sec-Fetch-Site": "cross-s
ite", "Sec-Fetch-Mode": "cors", "Referer": "http://localhost:8080/verify/Yk6QwCF1", "Accept-Encoding": "gzip, deflate, br", "Accept-Language": "cs", "X-Forwarded-Proto": "http", "X-Forwarded-Port": "3000"}, "multiValueHeaders": {"Host": ["127.0.0.1:3000"], "Connection
": ["keep-alive"], "Accept": ["application/json, text/plain, /"], "User-Agent": ["Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/79.0.3945.130 Safari/537.36"], "Origin": ["http://localhost:8080"], "Sec-Fetch-Site": ["cross-si
te"], "Sec-Fetch-Mode": ["cors"], "Referer": ["http://localhost:8080/verify/Yk6QwCF1"], "Accept-Encoding": ["gzip, deflate, br"], "Accept-Language": ["cs"], "X-Forwarded-Proto": ["http"], "X-Forwarded-Port": ["3000"]}, "pathParameters": {"token": "Yk6QwCF1"}, "stageVariables": null, "path": "/v1/verify/Yk6QwCF1", "isBase64Encoded": false}
Found one Lambda function with name 'BUDVerifyUserHandler'
Invoking src/handlers/users/verifyUser.handler (nodejs10.x)
Environment variables overrides data is standard format
Resolving code path. Cwd=C:\dev\mezinamiridici\infrastructure, CodeUri=.
Resolved absolute path to code is C:\dev\mezinamiridici\infrastructure
Code C:\dev\mezinamiridici\infrastructure is not a zip/jar file
Skipping building an image since no layers were defined

Fetching lambci/lambda:nodejs10.x Docker container image......
Mounting C:\dev\mezinamiridici\infrastructure as /var/task:ro,delegated inside runtime container
Starting a timer for 3 seconds for function 'BUDVerifyUserHandler'
?[32mSTART RequestId: 9b6a5604-fc33-116a-8ba9-98ba7d36910f Version: $LATEST?[0m
2020-01-27T06:42:39.391Z 9b6a5604-fc33-116a-8ba9-98ba7d36910f INFO handler starts
2020-01-27T06:42:39.392Z 9b6a5604-fc33-116a-8ba9-98ba7d36910f INFO Connect to mongo database mongodb://host.docker.internal:27017/bud?retryWrites=true&w=majority
2020-01-27T06:42:39.406Z 9b6a5604-fc33-116a-8ba9-98ba7d36910f ERROR (node:13) DeprecationWarning: current Server Discovery and Monitoring engine is deprecated, and will be removed in a future version. To use the new Server Discover and Monitoring engine, p
ass option { useUnifiedTopology: true } to the MongoClient constructor.
2020-01-27T06:42:39.423Z 9b6a5604-fc33-116a-8ba9-98ba7d36910f INFO Successful connect
2020-01-27T06:42:39.423Z 9b6a5604-fc33-116a-8ba9-98ba7d36910f INFO Mongo connected
2020-01-27T06:42:39.423Z 9b6a5604-fc33-116a-8ba9-98ba7d36910f INFO findUser
2020-01-27T06:42:39.434Z 9b6a5604-fc33-116a-8ba9-98ba7d36910f INFO findUser mongo responded: null
?[32mEND RequestId: 9b6a5604-fc33-116a-8ba9-98ba7d36910f?[0m
?[32mREPORT RequestId: 9b6a5604-fc33-116a-8ba9-98ba7d36910f Init Duration: 690.03 ms Duration: 48.90 ms Billed Duration: 100 ms Memory Size: 128 MB Max Memory Used: 59 MB ?[0m
2020-02-05 18:37:54 127.0.0.1 - - [05/Feb/2020 18:37:54] "GET /v1/verify/Yk6QwCF1 HTTP/1.1" 403 -

Proposal

Add timestamp including ms to each output:

2020-02-05 18:36:22:001 Found one Lambda function with name 'BUDVerifyUserHandler'
2020-02-05 18:36:22:003 Invoking src/handlers/users/verifyUser.handler (nodejs10.x)
2020-02-05 18:36:22:007 Environment variables overrides data is standard format
2020-02-05 18:36:22:102 Resolving code path. Cwd=C:\dev\mezinamiridici\infrastructure, CodeUri=.
2020-02-05 18:36:22:107 Resolved absolute path to code is C:\dev\mezinamiridici\infrastructure
2020-02-05 18:36:22:107 Code C:\dev\mezinamiridici\infrastructure is not a zip/jar file
2020-02-05 18:36:22:156 Skipping building an image since no layers were defined

2020-02-05 18:36:23:651 Fetching lambci/lambda:nodejs10.x Docker container image......
2020-02-05 18:36:23:980 Mounting C:\dev\mezinamiridici\infrastructure as /var/task:ro,delegated inside runtime container
2020-02-05 18:36:24:168 Starting a timer for 3 seconds for function 'BUDVerifyUserHandler'

Additional Details

[awsjeffg]

I think this could be a great optional feature, perhaps enabled with an additional flag perhaps --timestamp-output or something better?