feat: replace standard logging with structured logging #122

therealvio · 2025-01-15T07:47:12Z

Purpose 🎯

These changes replace the standard library logging with structured logging using structlog. Structured logging provides easier-to-parse capabilities for toolings and humans when going through logs.

Context 🧠

Part 1 to satisfy Suggestion: Add Structured logging #76
- I intend to contribute a follow-up PR that adds logging all connection test events for the purpose of fostering greater support for SLIs, as mentioned in this comment. For those unfamiliar, calculating the SLI is a matter of bad events/all valid events, and right now aws-alternat exercises a kind of "no news is good news" reporting.

Notes 📓

I have performed an in-place replacement of the default logger - no changes to the message contents have occurred (though if I missed something, let me know!)
The standard logger is still present because as far as I know, there doesn't seem to be an easy way to wrap third party dependency logs with structlog
Example screenshot of debug log messages through structlog

therealvio · 2025-01-15T07:49:08Z

functions/replace-route/app.py

 logger = logging.getLogger()
-logger.setLevel(logging.INFO)
 logging.getLogger('boto3').setLevel(logging.CRITICAL)
 logging.getLogger('botocore').setLevel(logging.CRITICAL)


I found this guide with regards to working with the standard library, but I wasn't sure how I could make this applicable here. Otherwise, third party deps will continue using the standard logger unless someone can figure out if wrapping the logger is possible.

My colleague suggests that we could use https://nhairs.github.io/python-json-logger/latest/ as the formatter for these handlers. e.g. something like:

handler = logging.StreamHandler() handler.setFormatter(JsonFormatter()) logging.getLogger('boto3').addHandler(handler) logging.getLogger('botocore').addHandler(handler)

Do you think this would work?

therealvio · 2025-01-15T07:52:02Z

functions/replace-route/app.py

+# use structlog's production-ready, performant example config
+# ref: https://www.structlog.org/en/stable/performance.html#example


Talking to this particular config, when I ran into the example in this document, it matched what I had in my head as a starting point. The company I work at have some opinions on things, though I wasn't going to impose them here.

therealvio · 2025-01-15T07:55:58Z

functions/replace-route/app.py

+        structlog.processors.add_log_level,
+        structlog.processors.format_exc_info,
+        structlog.processors.TimeStamper(fmt="iso", utc=True),
+        structlog.processors.EventRenamer("message"),


By default, this value is "event" though that term seems to be loaded since the Lambda accepts "events" and I thought that maybe message would be a good compromise. Though I am wary of long-term implications of this choice.

Either way, I don't have a strong opinion on whether it stays as this, we leave it as the default event, or we use a different name.

message works fine for me. 👍

therealvio · 2025-01-15T07:59:01Z

functions/replace-route/app.py

+        slogger.error("Unknown event", eventPayload=event)
        return

    if event.get("source") != "aws.events":
-        logger.error(f"Unable to handle unknown event type: {json.dumps(event)}")
+        slogger.error("Unable to handle unknown event type", eventPayload=json.dumps(event))


As the diff indicates, this changed from a string interpolation to a key. As this comment alludes to, the term event is loaded.

I am inclined to drop this key and keep the string interpolation like I did everywhere else, or do a combination of both, or even leave that decision to another PR.

I decided to preserve the string interpolation in a later commit and will leave changes to the log message contents themselves to a later PR.

This changes removes the addition of the eventPayload key that was imposed in the previous commit. I would rather leave the decision to the maintainers. Whether it be reverting *this* commit, or accepting this one, or leaving it to the future PR.

bwhaley · 2025-01-21T16:47:09Z

Thank you for the PR! I am a bit busy atm, but I hope to review & discuss in the coming days. Appreciate the patience!

bwhaley

Left a couple comments/ideas to consider.

Mind taking a peek at test_replace_route.py and adding a unit test?

bwhaley · 2025-01-24T23:49:51Z

functions/replace-route/app.py

@@ -120,10 +137,10 @@ def replace_route(route_table_id, nat_gateway_id):
        "RouteTableId": route_table_id
    }
    try:
-        logger.info("Replacing existing route %s for route table %s", route_table_id, new_route_table)
+        slogger.info("Replacing existing route %s for route table %s", route_table_id, new_route_table)


This line prints a dictionary (new_route_table), which would end up nested in json. The message here is sorta broken - "existing route {route_table_id}" is wrong, and then it prints the whole route table.

Let's update the message so it's more accurate and doesn't include a nested dictionary. It will print more cleanly in the output. It does break backward compatibility for folks monitoring for this specific phrasing, which is too bad, but worthwhile to fix. May as well do it now.

Suggested change

slogger.info("Replacing existing route %s for route table %s", route_table_id, new_route_table)

slogger.info("Updating route table %s to use NAT Gateway ID %s", route_table_id, nat_gateway_id)

Also, most folks should be monitoring for ERROR status or the "Failed connectivity tests! Replacing route" message. This one is INFO.

bwhaley · 2025-01-24T23:50:35Z

functions/replace-route/app.py

-        logger.error(f"Unknown event: {event}")
+        slogger.error("Unknown event: %s", {event})


Thanks for standardizing this throughout the file.

bwhaley · 2025-01-24T23:51:06Z

functions/replace-route/app.py

+        structlog.processors.add_log_level,
+        structlog.processors.format_exc_info,
+        structlog.processors.TimeStamper(fmt="iso", utc=True),
+        structlog.processors.EventRenamer("message"),


message works fine for me. 👍

bwhaley · 2025-01-25T00:08:57Z

functions/replace-route/app.py

+    logger_factory=structlog.BytesLoggerFactory()
+)
+
+# logger is still needed to set the level for dependencies
 logger = logging.getLogger()


Is this line still needed?

bwhaley · 2025-01-25T00:11:55Z

functions/replace-route/app.py

 logger = logging.getLogger()
-logger.setLevel(logging.INFO)
 logging.getLogger('boto3').setLevel(logging.CRITICAL)
 logging.getLogger('botocore').setLevel(logging.CRITICAL)


My colleague suggests that we could use https://nhairs.github.io/python-json-logger/latest/ as the formatter for these handlers. e.g. something like:

handler = logging.StreamHandler() handler.setFormatter(JsonFormatter()) logging.getLogger('boto3').addHandler(handler) logging.getLogger('botocore').addHandler(handler)

Do you think this would work?

feat: use structured logging with structlog

00b6031

therealvio commented Jan 15, 2025

View reviewed changes

therealvio marked this pull request as ready for review January 15, 2025 07:59

therealvio requested a review from a team as a code owner January 15, 2025 07:59

therealvio mentioned this pull request Jan 15, 2025

Suggestion: Add Structured logging #76

Closed

therealvio changed the title ~~feat: use structured logging with structlog~~ feat: replace standard logging with structured logging Jan 15, 2025

fix: use slogger as drop-in replacement

faa1779

This changes removes the addition of the eventPayload key that was imposed in the previous commit. I would rather leave the decision to the maintainers. Whether it be reverting *this* commit, or accepting this one, or leaving it to the future PR.

therealvio mentioned this pull request Jan 16, 2025

feat: opt-in to expose successful connection logs #123

Open

Trigger tests

53c2e62

bwhaley mentioned this pull request Jan 24, 2025

Triggers workflows on pull_request #124

Closed

bwhaley reviewed Jan 25, 2025

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat: replace standard logging with structured logging #122

feat: replace standard logging with structured logging #122

therealvio commented Jan 15, 2025

therealvio Jan 15, 2025

bwhaley Jan 25, 2025

therealvio Jan 15, 2025

therealvio Jan 15, 2025

bwhaley Jan 24, 2025

therealvio Jan 15, 2025

therealvio Jan 15, 2025

bwhaley commented Jan 21, 2025

bwhaley left a comment

bwhaley Jan 24, 2025

bwhaley Jan 25, 2025 •

edited

Loading

bwhaley Jan 24, 2025

bwhaley Jan 24, 2025

bwhaley Jan 25, 2025

bwhaley Jan 25, 2025

		# use structlog's production-ready, performant example config
		# ref: https://www.structlog.org/en/stable/performance.html#example

	slogger.info("Replacing existing route %s for route table %s", route_table_id, new_route_table)
	slogger.info("Updating route table %s to use NAT Gateway ID %s", route_table_id, nat_gateway_id)

		logger.error(f"Unknown event: {event}")
		slogger.error("Unknown event: %s", {event})

feat: replace standard logging with structured logging #122

Are you sure you want to change the base?

feat: replace standard logging with structured logging #122

Conversation

therealvio commented Jan 15, 2025

Purpose 🎯

Context 🧠

Notes 📓

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

bwhaley commented Jan 21, 2025

bwhaley left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bwhaley Jan 25, 2025 • 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

bwhaley Jan 25, 2025 •

edited

Loading