search

aio-libs / aiosmtpd

A reimplementation of the Python stdlib smtpd.py based on asyncio.
https://aiosmtpd.aio-libs.org
Apache License 2.0
319 stars 96 forks source link

Introduce different loggers for different purposes #239

Open TheAssassin opened 3 years ago

TheAssassin commented 3 years ago

I've recently come across this library, and am in the process of implementing some tools using it. However, I find the logging a bit too verbose for production use:

2021-01-29 19:32:04,061 importer.cli [INFO] server listening on ::1:8025
2021-01-29 19:32:06,811 mail.log [INFO] Available AUTH mechanisms: LOGIN(builtin) PLAIN(builtin)
2021-01-29 19:32:06,813 mail.log [INFO] Peer: ('::1', 57254, 0, 0)
2021-01-29 19:32:06,817 mail.log [INFO] ('::1', 57254, 0, 0) handling connection
2021-01-29 19:32:06,818 mail.log [INFO] ('::1', 57254, 0, 0) Data: b'lhlo [127.0.1.1]'
2021-01-29 19:32:06,820 mail.log [INFO] ('::1', 57254, 0, 0) Data: b'mail FROM:<a@b.cde>'
2021-01-29 19:32:06,821 mail.log [INFO] ('::1', 57254, 0, 0) sender: a@b.cde
2021-01-29 19:32:06,822 mail.log [INFO] ('::1', 57254, 0, 0) Data: b'rcpt TO:<z@y.xwv>'
2021-01-29 19:32:06,823 mail.log [INFO] ('::1', 57254, 0, 0) recip: z@y.xwv
2021-01-29 19:32:06,824 mail.log [INFO] ('::1', 57254, 0, 0) Data: b'data'
2021-01-29 19:32:06,833 importer.cli [INFO] Handling mail
[... my own two messages ...]
2021-01-29 19:32:06,927 mail.log [INFO] ('::1', 57254, 0, 0) EOF received
2021-01-29 19:32:06,928 mail.log [INFO] Connection lost during _handle_client()
2021-01-29 19:32:06,928 mail.log [INFO] ('::1', 57254, 0, 0) connection lost

All I'm interested in is basically "client connected" and "client disconnected". The rest is logged in my handler anyway. However, I have no chance of filtering these messages.

In Python, we have two dimensions that can be used to filter log messages: logger name and loglevel. Now, one can argue very much about what kind of log level to choose for different types of messages. I personally think these "info" messages that print every single message sent and received would better suit a "verbose" (which doesn't exist in Python by default) or "debug" level, as the average user doesn't usually need to see them unless they're debugging.

However, I'd rather not start a discussion on log levels but suggest to use different loggers for different purposes. Instead of a mail.log that shall fit all purposes, one could have mail.smtp logger for the SMTP class that prints the connection made and connection lost messages, etc. See https://docs.python.org/3/library/logging.html#logger-objects and https://docs.python.org/3/library/logging.html#logging.Logger.getChild for more information on logger hierarchy.

Right now, it's not really viable to implement such a change by just adding class-specific loggers, as the majority of the logic is contained in SMTP. Therefore, it might make more sense to just add purpose-specific loggers like mail.connection or mail.auth.

I think this might also be a chance to refactor the (very large and complex) SMTP class, e.g., by extracting _handle_client into something like a ClientHandler to implement separation of concerns and split responsibilities better. This eliminates the need for SMTP to know about any of these implementations, and maybe even swap the implementations via DOI to also make testing easier. In fact, there are already some classes like Session into which the algorithms might be moved, but right now they're merely used to track state, whereas the business logic remains in SMTP. I guess this discussion should be moved into another issue, though.

pepoluan commented 3 years ago

However, I'd rather not start a discussion on log levels but suggest to use different loggers for different purposes. Instead of a mail.log that shall fit all purposes, one could have mail.smtp logger for the SMTP class that prints the connection made and connection lost messages, etc.

Makes sense. In all actuality, the whole library actually is already using 2 loggers: mail.log and mail.debug. Splitting the "verbose" logging might be a good idea, say into a mail.verbose logger. (We'll need to think of the name and hierarchy).

That said, such changes will definitely not go into the 1.x series, as it will be breaking. I'll mark the idea in #229 for inclusion in 2.x

As for the other suggestion you have, namely separating _handle_client, might be a good idea to start a different issue.

luckydonald commented 3 years ago

Sorry to actually start the log level discussion, but I feel like having a logger literally called .debug with the existence of the .debug log level seems kinda redundant. Usually it makes more sense to split logger names by part of the library, most of the times import name aiosmtpd.handlers, aiosmtpd.server etc.

That's just my two €0.02 though, as I just stumbled over this library.

pepoluan commented 3 years ago

Sorry to actually start the log level discussion, but I feel like having a logger literally called .debug with the existence of the .debug log level seems kinda redundant. Usually it makes more sense to split logger names by part of the library, most of the times import name aiosmtpd.handlers, aiosmtpd.server etc.

That's just my two €0.02 though, as I just stumbled over this library.

For SMTP related stuff, traditionally we go with at least the "mail" part as it will map to syslog facility of "mail" (though practically whatever the log is named, Python can map it to any syslog facility.)

The current name of "mail.log" and "mail.debug" is currently considered legacy and not changeable due to the possibility of breaking with users of this library.

We'll rethink how best to tidy up the logging problems in 2.0.