Skip to content

fix(logger): force Logger to use local timezone when UTC flag is not set #3168

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 18 commits into from
Oct 13, 2023
Merged
Show file tree
Hide file tree
Changes from 10 commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 2 additions & 0 deletions aws_lambda_powertools/logging/formatter.py
Original file line number Diff line number Diff line change
Expand Up @@ -146,6 +146,8 @@ def __init__(

if self.utc:
self.converter = time.gmtime
else:
self.converter = time.localtime

self.keys_combined = {**self._build_default_keys(), **kwargs}
self.log_format.update(**self.keys_combined)
Expand Down
28 changes: 19 additions & 9 deletions docs/core/logger.md
Original file line number Diff line number Diff line change
Expand Up @@ -39,7 +39,7 @@ Your Logger will include the following keys to your structured logging:
| **level**: `str` | `INFO` | Logging level |
| **location**: `str` | `collect.handler:1` | Source code location where statement was executed |
| **message**: `Any` | `Collecting payment` | Unserializable JSON values are casted as `str` |
| **timestamp**: `str` | `2021-05-03 10:20:19,650+0200` | Timestamp with milliseconds, by default uses local timezone |
| **timestamp**: `str` | `2021-05-03 10:20:19,650+0000` | Timestamp with milliseconds, by default uses default AWS Lambda timezone (UTC) |
| **service**: `str` | `payment` | Service name defined, by default `service_undefined` |
| **xray_trace_id**: `str` | `1-5759e988-bd862e3fe1be46a994272793` | When [tracing is enabled](https://docs.aws.amazon.com/lambda/latest/dg/services-xray.html){target="_blank"}, it shows X-Ray Trace ID |
| **sampling_rate**: `float` | `0.1` | When enabled, it shows sampling rate in percentage e.g. 10% |
Expand Down Expand Up @@ -337,12 +337,12 @@ By default, the Logger will automatically include the full stack trace in JSON f

### Date formatting

Logger uses Python's standard logging date format with the addition of timezone: `2021-05-03 11:47:12,494+0200`.
Logger uses Python's standard logging date format with the addition of timezone: `2021-05-03 11:47:12,494+0000`.

You can easily change the date format using one of the following parameters:

* **`datefmt`**. You can pass any [strftime format codes](https://strftime.org/){target="_blank" rel="nofollow"}. Use `%F` if you need milliseconds.
* **`use_rfc3339`**. This flag will use a format compliant with both RFC3339 and ISO8601: `2022-10-27T16:27:43.738+02:00`
* **`use_rfc3339`**. This flag will use a format compliant with both RFC3339 and ISO8601: `2022-10-27T16:27:43.738+00:00`

???+ tip "Prefer using [datetime string formats](https://docs.python.org/3/library/datetime.html#strftime-and-strptime-format-codes){target="_blank" rel="nofollow"}?"
Use `use_datetime_directive` flag along with `datefmt` to instruct Logger to use `datetime` instead of `time.strftime`.
Expand All @@ -368,6 +368,7 @@ The following environment variables are available to configure Logger at a globa
| **Event Logging** | Whether to log the incoming event. | `POWERTOOLS_LOGGER_LOG_EVENT` | `false` |
| **Debug Sample Rate** | Sets the debug log sampling. | `POWERTOOLS_LOGGER_SAMPLE_RATE` | `0` |
| **Disable Deduplication** | Disables log deduplication filter protection to use Pytest Live Log feature. | `POWERTOOLS_LOG_DEDUPLICATION_DISABLED` | `false` |
| **TZ** | Sets timezone when using Logger, e.g., `US/Eastern`. Timezone is defaulted to UTC when `TZ` is not set | `TZ` | `None` (UTC) |

[`POWERTOOLS_LOGGER_LOG_EVENT`](#logging-incoming-event) can also be set on a per-method basis, and [`POWERTOOLS_LOGGER_SAMPLE_RATE`](#sampling-debug-logs) on a per-instance basis. These parameter values will override the environment variable value.

Expand Down Expand Up @@ -464,7 +465,7 @@ If you prefer configuring it separately, or you'd want to bring this JSON Format
| **`json_default`** | function to coerce unserializable values, when no custom serializer/deserializer is set | `str` |
| **`datefmt`** | string directives (strftime) to format log timestamp | `%Y-%m-%d %H:%M:%S,%F%z`, where `%F` is a custom ms directive |
| **`use_datetime_directive`** | format the `datefmt` timestamps using `datetime`, not `time` (also supports the custom `%F` directive for milliseconds) | `False` |
| **`utc`** | set logging timestamp to UTC | `False` |
| **`utc`** | enforce logging timestamp to UTC (ignore `TZ` environment variable) | `False` |
| **`log_record_order`** | set order of log keys when logging | `["level", "location", "message", "timestamp"]` |
| **`kwargs`** | key-value to be included in log messages | `None` |

Expand Down Expand Up @@ -583,17 +584,26 @@ You can change the order of [standard Logger keys](#standard-structured-keys) or
--8<-- "examples/logger/src/reordering_log_keys_output.json"
```

#### Setting timestamp to UTC
#### Setting timestamp to custom Timezone

By default, this Logger and standard logging library emits records using local time timestamp. You can override this behavior via `utc` parameter:
By default, this Logger and the standard logging library emit records with the default AWS Lambda timestamp in **UTC**.

=== "setting_utc_timestamp.py"
<!-- markdownlint-disable MD013 -->
If you prefer to log in a specific timezone, you can configure it by setting the `TZ` environment variable. You can do this either as an AWS Lambda environment variable or directly within your Lambda function settings. [Click here](https://docs.aws.amazon.com/lambda/latest/dg/configuration-envvars.html#configuration-envvars-runtime){target="_blank"} for a comprehensive list of available Lambda environment variables.
<!-- markdownlint-enable MD013 -->

???+ tip
`TZ` environment variable will be ignored if `utc` is set to `True`

```python hl_lines="6"
=== "setting_custom_timezone.py"

```python hl_lines="9 12"
--8<-- "examples/logger/src/setting_utc_timestamp.py"
```

=== "setting_utc_timestamp_output.json"
1. if you set TZ in your Lambda function, `time.tzset()` need to be called. You don't need it when setting TZ in AWS Lambda environment variable

=== "setting_custom_timezone_output.json"

```json hl_lines="6 13"
--8<-- "examples/logger/src/setting_utc_timestamp_output.json"
Expand Down
2 changes: 1 addition & 1 deletion examples/logger/src/append_keys_extra_output.json
Original file line number Diff line number Diff line change
Expand Up @@ -2,7 +2,7 @@
"level": "INFO",
"location": "collect.handler:9",
"message": "Collecting payment",
"timestamp": "2021-05-03 11:47:12,494+0200",
"timestamp": "2021-05-03 11:47:12,494+0000",
"service": "payment",
"request_id": "1123"
}
2 changes: 1 addition & 1 deletion examples/logger/src/append_keys_kwargs_output.json
Original file line number Diff line number Diff line change
Expand Up @@ -2,7 +2,7 @@
"level": "INFO",
"location": "collect.handler:8",
"message": "Collecting payment",
"timestamp": "2022-11-26 11:47:12,494+0200",
"timestamp": "2022-11-26 11:47:12,494+0000",
"service": "payment",
"request_id": "1123"
}
2 changes: 1 addition & 1 deletion examples/logger/src/append_keys_output.json
Original file line number Diff line number Diff line change
Expand Up @@ -2,7 +2,7 @@
"level": "INFO",
"location": "collect.handler:11",
"message": "Collecting payment",
"timestamp": "2021-05-03 11:47:12,494+0200",
"timestamp": "2021-05-03 11:47:12,494+0000",
"service": "payment",
"order_id": "order_id_value"
}
2 changes: 1 addition & 1 deletion examples/logger/src/bring_your_own_formatter_output.json
Original file line number Diff line number Diff line change
@@ -1,7 +1,7 @@
{
"level": "INFO",
"location": "<module>:16",
"timestamp": "2021-12-30 13:41:53,413+0100",
"timestamp": "2021-12-30 13:41:53,413+0000",
"service": "payment",
"event": "hello"
}
2 changes: 1 addition & 1 deletion examples/logger/src/clear_state_event_one.json
Original file line number Diff line number Diff line change
Expand Up @@ -2,7 +2,7 @@
"level": "INFO",
"location": "collect.handler:10",
"message": "Collecting payment",
"timestamp": "2021-05-03 11:47:12,494+0200",
"timestamp": "2021-05-03 11:47:12,494+0000",
"service": "payment",
"special_key": "debug_key",
"cold_start": true,
Expand Down
2 changes: 1 addition & 1 deletion examples/logger/src/clear_state_event_two.json
Original file line number Diff line number Diff line change
Expand Up @@ -2,7 +2,7 @@
"level": "INFO",
"location": "collect.handler:10",
"message": "Collecting payment",
"timestamp": "2021-05-03 11:47:12,494+0200",
"timestamp": "2021-05-03 11:47:12,494+0000",
"service": "payment",
"cold_start": false,
"function_name": "test",
Expand Down
2 changes: 1 addition & 1 deletion examples/logger/src/date_formatting_output.json
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,7 @@
"level": "INFO",
"location": "<module>:6",
"message": "Collecting payment",
"timestamp": "2022-10-28T14:35:03.210+02:00",
"timestamp": "2022-10-28T14:35:03.210+00:00",
"service": "payment"
},
{
Expand Down
4 changes: 2 additions & 2 deletions examples/logger/src/inject_lambda_context_output.json
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,7 @@
"level": "INFO",
"location": "collect.handler:9",
"message": "Collecting payment",
"timestamp": "2021-05-03 11:47:12,494+0200",
"timestamp": "2021-05-03 11:47:12,494+0000",
"service": "payment",
"cold_start": true,
"function_name": "test",
Expand All @@ -18,7 +18,7 @@
"operation": "collect_payment",
"charge_id": "ch_AZFlk2345C0"
},
"timestamp": "2021-05-03 11:47:12,494+0200",
"timestamp": "2021-05-03 11:47:12,494+0000",
"service": "payment",
"cold_start": true,
"function_name": "test",
Expand Down
2 changes: 1 addition & 1 deletion examples/logger/src/logger_reuse_output.json
Original file line number Diff line number Diff line change
Expand Up @@ -2,7 +2,7 @@
"level": "INFO",
"location": "collect.handler:12",
"message": "Collecting payment",
"timestamp": "2021-05-03 11:47:12,494+0200",
"timestamp": "2021-05-03 11:47:12,494+0000",
"service": "payment",
"cold_start": true,
"function_name": "test",
Expand Down
2 changes: 1 addition & 1 deletion examples/logger/src/logging_exceptions_output.json
Original file line number Diff line number Diff line change
Expand Up @@ -2,7 +2,7 @@
"level": "ERROR",
"location": "collect.handler:15",
"message": "Received a HTTP 5xx error",
"timestamp": "2021-05-03 11:47:12,494+0200",
"timestamp": "2021-05-03 11:47:12,494+0000",
"service": "payment",
"exception_name": "RuntimeError",
"exception": "Traceback (most recent call last):\n File \"<input>\", line 2, in <module> RuntimeError: Unable to fullfil request"
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -2,7 +2,7 @@
"level": "ERROR",
"location": "log_uncaught_exception_hook:756",
"message": "500 Server Error: INTERNAL SERVER ERROR for url: http://httpbin.org/status/500",
"timestamp": "2022-11-16 13:51:29,198+0100",
"timestamp": "2022-11-16 13:51:29,198+0000",
"service": "payment",
"exception": "Traceback (most recent call last):\n File \"<input>\", line 52, in <module>\n handler({}, {})\n File \"<input>\", line 17, in handler\n ret.raise_for_status()\n File \"<input>/lib/python3.9/site-packages/requests/models.py\", line 1021, in raise_for_status\n raise HTTPError(http_error_msg, response=self)\nrequests.exceptions.HTTPError: 500 Server Error: INTERNAL SERVER ERROR for url: http://httpbin.org/status/500",
"exception_name": "HTTPError"
Expand Down
4 changes: 2 additions & 2 deletions examples/logger/src/overriding_log_records_output.json
Original file line number Diff line number Diff line change
Expand Up @@ -3,13 +3,13 @@
"level": "INFO",
"location": "[<module>] overriding_log_records",
"message": "Collecting payment",
"timestamp": "2022-10-28 14:40:43,801+0200",
"timestamp": "2022-10-28 14:40:43,801+0000",
"service": "payment"
},
{
"level": "INFO",
"message": "Calculating points",
"timestamp": "2022-10-28 14:40:43,801+0200",
"timestamp": "2022-10-28 14:40:43,801+0000",
"service": "loyalty"
}
]
4 changes: 2 additions & 2 deletions examples/logger/src/remove_keys_output.json
Original file line number Diff line number Diff line change
Expand Up @@ -3,15 +3,15 @@
"level": "INFO",
"location": "collect.handler:9",
"message": "Collecting payment",
"timestamp": "2021-05-03 11:47:12,494+0200",
"timestamp": "2021-05-03 11:47:12,494+0000",
"service": "payment",
"sample_key": "value"
},
{
"level": "INFO",
"location": "collect.handler:12",
"message": "Collecting payment without sample key",
"timestamp": "2021-05-03 11:47:12,494+0200",
"timestamp": "2021-05-03 11:47:12,494+0000",
"service": "payment"
}
]
4 changes: 2 additions & 2 deletions examples/logger/src/reordering_log_keys_output.json
Original file line number Diff line number Diff line change
Expand Up @@ -3,14 +3,14 @@
"message": "hello world",
"level": "INFO",
"location": "<module>:11",
"timestamp": "2022-06-24 11:25:40,143+0200",
"timestamp": "2022-06-24 11:25:40,143+0000",
"service": "payment"
},
{
"request_id": "123",
"level": "INFO",
"location": "<module>:12",
"timestamp": "2022-06-24 11:25:40,144+0200",
"timestamp": "2022-06-24 11:25:40,144+0000",
"service": "order",
"message": "hello universe"
}
Expand Down
4 changes: 2 additions & 2 deletions examples/logger/src/sampling_debug_logs_output.json
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,7 @@
"level": "DEBUG",
"location": "collect.handler:7",
"message": "Verifying whether order_id is present",
"timestamp": "2021-05-03 11:47:12,494+0200",
"timestamp": "2021-05-03 11:47:12,494+0000",
"service": "payment",
"cold_start": true,
"function_name": "test",
Expand All @@ -16,7 +16,7 @@
"level": "INFO",
"location": "collect.handler:7",
"message": "Collecting payment",
"timestamp": "2021-05-03 11:47:12,494+0200",
"timestamp": "2021-05-03 11:47:12,494+0000",
"service": "payment",
"cold_start": true,
"function_name": "test",
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -2,7 +2,7 @@
"level": "INFO",
"location": "collect.handler:11",
"message": "Collecting payment",
"timestamp": "2021-05-03 11:47:12,494+0200",
"timestamp": "2021-05-03 11:47:12,494+0000",
"service": "payment",
"cold_start": true,
"function_name": "test",
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -2,7 +2,7 @@
"level": "INFO",
"location": "collect.handler:13",
"message": "Collecting payment",
"timestamp": "2021-05-03 11:47:12,494+0200",
"timestamp": "2021-05-03 11:47:12,494+0000",
"service": "payment",
"correlation_id": "correlation_id_value"
}
2 changes: 1 addition & 1 deletion examples/logger/src/set_correlation_id_output.json
Original file line number Diff line number Diff line change
Expand Up @@ -2,7 +2,7 @@
"level": "INFO",
"location": "collect.handler:10",
"message": "Collecting payment",
"timestamp": "2021-05-03 11:47:12,494+0200",
"timestamp": "2021-05-03 11:47:12,494+0000",
"service": "payment",
"cold_start": true,
"function_name": "test",
Expand Down
14 changes: 10 additions & 4 deletions examples/logger/src/setting_utc_timestamp.py
Original file line number Diff line number Diff line change
@@ -1,7 +1,13 @@
import os
import time

from aws_lambda_powertools import Logger

logger = Logger(service="payment")
logger.info("Local time")
logger_in_utc = Logger(service="payment")
logger_in_utc.info("Logging with default AWS Lambda timezone: UTC time")

os.environ["TZ"] = "US/Eastern"
time.tzset() # (1)!

logger_in_utc = Logger(service="order", utc=True)
logger_in_utc.info("GMT time zone")
logger = Logger(service="order")
logger.info("Logging with US Eastern timezone")
20 changes: 10 additions & 10 deletions examples/logger/src/setting_utc_timestamp_output.json
Original file line number Diff line number Diff line change
@@ -1,16 +1,16 @@
[
{
"level": "INFO",
"location": "<module>:4",
"message": "Local time",
"timestamp": "2022-06-24 11:39:49,421+0200",
"service": "payment"
"level":"INFO",
"location":"<module>:7",
"message":"Logging with default AWS Lambda timezone: UTC time",
"timestamp":"2023-10-09 21:33:55,733+0000",
"service":"payment"
},
{
"level": "INFO",
"location": "<module>:7",
"message": "GMT time zone",
"timestamp": "2022-06-24 09:39:49,421+0100",
"service": "order"
"level":"INFO",
"location":"<module>:13",
"message":"Logging with US Eastern timezone",
"timestamp":"2023-10-09 17:33:55,734-0400",
"service":"order"
}
]
2 changes: 1 addition & 1 deletion examples/logger/src/unserializable_values_output.json
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,6 @@
"ingestion_time": "2022-06-24T10:12:09.526365",
"serialize_me": "<non-serializable: Unserializable>"
},
"timestamp": "2022-06-24 12:12:09,526+0200",
"timestamp": "2022-06-24 12:12:09,526+0000",
"service": "payment"
}
Loading