Add logging for input and output event streams

[jonathan343]

Summary

This PR adds logging for input and output event streams. Specifically, we will log events before and after serialization/deserialization.

Input Example

DEBUG:aws_event_stream._private.serializers:Preparing to publish event: EventsSimpleEvent(value=SimpleEvent(message='test'))
DEBUG:aws_event_stream._private.serializers:Publishing serialized event: EventMessage(headers={':message-type': 'event', ':event-type': 'simpleEvent', ':content-type': 'application/json'}, payload=b'{"message":"test"}')
DEBUG:aws_event_stream._private.serializers:Preparing to publish event: EventsSimpleEvent(value=SimpleEvent(message='test2'))
DEBUG:aws_event_stream._private.serializers:Publishing serialized event: EventMessage(headers={':message-type': 'event', ':event-type': 'simpleEvent', ':content-type': 'application/json'}, payload=b'{"message":"test2"}')
DEBUG:aws_event_stream._private.serializers:Preparing to publish event: EventsSimpleEvent(value=SimpleEvent(message='test3'))
DEBUG:aws_event_stream._private.serializers:Publishing serialized event: EventMessage(headers={':message-type': 'event', ':event-type': 'simpleEvent', ':content-type': 'application/json'}, payload=b'{"message":"test3"}')

Output Example

DEBUG:aws_event_stream._private.deserializers:Received raw event: Event(prelude=EventPrelude(total_length=115, headers_length=81, crc=3342607380), message=EventMessage(headers={':message-type': 'event', ':event-type': 'simpleEvent', ':content-type': 'application/json'}, payload=b'{"message":"test"}'), crc=2514834424)
DEBUG:aws_event_stream._private.deserializers:Successfully deserialized event: EventsSimpleEvent(value=SimpleEvent(message='test'))
DEBUG:aws_event_stream._private.deserializers:Received raw event: Event(prelude=EventPrelude(total_length=116, headers_length=81, crc=1964832772), message=EventMessage(headers={':message-type': 'event', ':event-type': 'simpleEvent', ':content-type': 'application/json'}, payload=b'{"message":"test2"}'), crc=3383786838)
DEBUG:aws_event_stream._private.deserializers:Successfully deserialized event: EventsSimpleEvent(value=SimpleEvent(message='test2'))
DEBUG:aws_event_stream._private.deserializers:Received raw event: Event(prelude=EventPrelude(total_length=116, headers_length=81, crc=1964832772), message=EventMessage(headers={':message-type': 'event', ':event-type': 'simpleEvent', ':content-type': 'application/json'}, payload=b'{"message":"test3"}'), crc=3362920289)
DEBUG:aws_event_stream._private.deserializers:Successfully deserialized event: EventsSimpleEvent(value=SimpleEvent(message='test3'))
DEBUG:aws_event_stream._private.deserializers:No event received from the source.

---

By submitting this pull request, I confirm that you can use, modify, copy, and redistribute this contribution, under the terms of your choice.

[JordonPhillips]

I really wish python had a TRACE level or something like that below debug.

[JordonPhillips]

Suggested change

	logger = logging.getLogger(__name__)
	LOGGER = logging.getLogger(__name__)

[jonathan343]

It seems wrong to make this variable all-caps since it doesn't represent a constant and instead represents a <class 'logging.Logger'> object. Also, for what it's worth, logger seems to be the standard in docs and other projects I've seen.

I don't feel too strongly, so happy to change if you disagree.

[JordonPhillips]

But it is a constant. You're never mutating it in any scope.

[JordonPhillips]

You could more accurately describe it as Final, which is more or less the same concept. Final symbols in Python are generally upper-cased. In fact, upper casing a symbol name implicitly finalizes it. So LOGGER is equivalent to LOGGER: Final.

PEP8 doesn't really have anything to say about Final, but that was written 20 years before Final was an actual construct in the language. But most programming language naming conventions upper-case finalized properties and constants

[jonathan343]

Yea I totally agree with you now. I've updated this in 74881a1

In fact, upper casing a symbol name implicitly finalizes it. So LOGGER is equivalent to LOGGER: Final.

Also, I had no idea this was a thing. Pretty cool

 error: "LOGGER" is constant (because it is uppercase) and cannot be redefined (reportConstantRedefinition)

[nateprewitt]

We can add the typing, I don't know if we need to all caps it as a constant. logger is pretty much the universal standard for implementing your file-scope logger. It's in the docs and we already use it that way in other files. It's also convention in other languages like Java (ref) where constant is considered some immutable value.

If we really feel strongly about it, lets split that work into a separate PR to update everything at once rather than having the logger name be inconsistent across libraries.

[jonathan343]

Sure, I reverted the change for now and will follow up with a separate PR to address all instances if we decide to switch to LOGGER

[jonathan343]

I really wish python had a TRACE level or something like that below debug.

The standard logging levels for logging.NOTSET and logging.DEBUG are 0 and 10 respectively. It seems possible for us to define our own TRACE level with a value of 5.

However, doing this make this level non-obvious to users since it isn't a standard level. If we do this, we'd probably want to expose some helper methods for enabling logging such as enable_trace_logging().

[alextwoods]

RE: Logging levels - is it common for python developers to configure fine-grained (ie, module level) log levels? (ie, using logger.getLogger('module').setLevel(logging.DEBUG))? If so, then the general spam from DEBUG is less concerning.

Another general thought - have you traditionally supported wire logs in the SDK? This logging is a level above wire logs since it doesn't show the actual bytes on wire - are we considering ways to get that information?

[nateprewitt]

is it common for python developers to configure fine-grained (ie, module level) log levels?

It's going to vary between user and what they're trying to get, you'll find every use case across the spectrum in production. I think you'll generally see people just turn on debugging for everything outside of a prod context. More refined applications/systems are going to target modules/libraries.

Another general thought - have you traditionally supported wire logs in the SDK?

Right now Boto3 does wire-level logs at DEBUG. This is how most libraries work in Python but does catch people by surprise from time-to-time. Adding another log level creates some issues for both us and customers since it's just an alias to a level constant. Other libraries may have implemented their own semantics for that level and a global scope logger makes this setup messy.

[alextwoods]

RE: Wire logging - at least in Ruby we consider wire logging to be separate from standard debug/trace logging and require that it be configured on the client (or more specifically, its a configuration of the http client itself) since its fairly dangerous to accidentally enable.

[nateprewitt]

I think centralizing the configuration for wire-level make sense. It probably needs to be on the client rather than the http client since we may end up with wirelogging elsewhere like the IMDS client which may have a separate HTTP client? It would make sense that the HTTP clients are aware of the setting but I'm not sure if it makes more sense to do individually or universally.

[alextwoods]

I think centralizing the configuration for wire-level make sense. It probably needs to be on the client rather than the http client since we may end up with wirelogging elsewhere like the IMDS client which may have a separate HTTP client

Yeah - I get why having it centralized makes sense, esp for imds client. At least in Ruby, our thought was that individual HTTP clients have different levels of support for wire logging and so require different configurations for that.

Anyway - all out of scope for this PR - just wanted to add general thoughts on wirelogging :-)

Will discuss logger constant casing with the team and address in a follow-up PR if needed