Protocol.connection_lost() is inappropriately chatty

[ShaheedHaque]

I'd like to suggest a change in the way Protocol.connection_lost() records the loss of a connection. At the moment, it does this:

logger.info("Connection lost: %r", exc)

even when exc is None (on a normal disconnection, IIUC). I think it would be better to not output anything if exc is None, else a higher severity should be used (warning or error), for example:

if exc:
    logger.error("Connection lost: %r", exc)

[adamhooper]

If I understand correctly: you're calling connection.close() and are dismayed that there's a log message?

You can filter for loglevel > INFO if you want more quiet. INFO means, "Confirmation that things are working as expected." [ref]

That's the case here: if you know what you're doing, you are welcome to always ignore this message. (Heck, Python logging hides INFO messages by default.) If an exception occurs, you'll see it when you await connection.connect() or await connection.closed.

Does ignoring the INFO level solve your problem? Otherwise, could you please give more info on what you're trying to accomplish? Would it help if this were a logger.debug() call, instead of logger.info()?

[ShaheedHaque]

If I understand correctly: you're calling connection.close() and are dismayed that there's a log message?

Yes, generally, I prefer libraries to communicate to my app via the API (including exceptions), and to limit what they log.

You can filter for loglevel > INFO if you want more quiet. INFO means, "Confirmation that things are working as expected." [ref]

Yes, I'm aware of how to configure logging levels globally, and if needed, on a module basis. My app has it's global log level set to emit logging.INFO.

Here, I acknowledge that during resource disposal, raising exceptions isn't usually much help so when there is an error, I think a logging.WARNING or Iogging.ERROR is a reasonable choice for a library. When there isn't an error, then since it is presumably in response to me asking for the connection to be cleaned up, I'd prefer the library to be silent (and yes, logging.DEBUG would achieve that for my setup).

[adamhooper]

I'd like Carehare to be "Pythonic" and follow the standards of other DB-connectivity libraries. Can you please point to a couple of other DB-connectivity libraries' choices? Do they log connect/disconnect as "INFO", "DEBUG", etc?

Here, I acknowledge that during resource disposal, raising exceptions isn't usually much help

Actually, I'm proud to report that Carehare is decidedly un-Pythonic when it comes to exceptions. Carehare is built primarily for exception-handling. You can always await the exception that is logged here, and it will always be the "first" error (e.g., OSError or carehare.ConnectionClosedException). Subsequent errors are silenced.

The use case for this INFO message is: user has a long-running, always-connected app. In the real world, "always-connected" means, "always-connected until OSError. Users tend to ignore testing for OSError, and there are lots of potential OSErrors; so this INFO log can give many users a hint to help with debugging. (These log messages aren't errors: If the client/server reports an error, we already log that elsewhere.)

Anyway. I'd like to defer to Python's best practice here. Could you please cite what other libraries do?

[ShaheedHaque]

I'd like Carehare to be "Pythonic" and follow the standards of other DB-connectivity libraries. Can you please point to a couple of other DB-connectivity libraries' choices? Do they log connect/disconnect as "INFO", "DEBUG", etc?

I use Django and Celery, both of which use ongoing connections to database or database-like backends and neither emit logs that I see for this case.

Here, I acknowledge that during resource disposal, raising exceptions isn't usually much help

Actually, I'm proud to report that Carehare is decidedly un-Pythonic when it comes to exceptions. Carehare is built primarily for exception-handling. You can always await the exception that is logged here, and it will always be the "first" error (e.g., OSError or carehare.ConnectionClosedException). Subsequent errors are silenced.

Emphatic thumbs-up from me on this.

The use case for this INFO message is: user has a long-running, always-connected app. In the real world, "always-connected" means, "always-connected until OSError. Users tend to ignore testing for OSError, and there are lots of potential OSErrors; so this INFO log can give many users a hint to help with debugging. (These log messages aren't errors: If the client/server reports an error, we already log that elsewhere.)

Anyway. I'd like to defer to Python's best practice here. Could you please cite what other libraries do?

Again, fully agreed. In general, errors which cannot be sanely converted into expected behaviour must ALWAYS be capable of being tracked. Given a language/runtime that supports them, that means an exception should be raised. However, I consider that the purpose of this is to allow a higher level to take appropriate action (log a message, take other recovery steps etc.); the problem is that during a "close" operation, there is generally little that can be done to recover. For example, in many operating systems, a file close can return a non-success status...but since the file handle being closed is now in an indeterminate state, retrying the close would be a very bad idea! However, not recording the error might allow a serious underlying problem to go unrecognised, therefore that recording SHOULD take the form of a log message or possibly a counter.

To summarise...

• In a language like Python, errors should always be signalled using exceptions to allow the application to record and/or recover at it sees fit. The exception is that during a close/resource deallocation where (a) retry is not an option, and (b) recovery is barely meaningful, tracking using a message is the best that can be done. That message should generally be at WARNING or higher.
• From a library developer perspective, I think it is reasonable to track the lifetime of expensive/significant objects for diagnostic purposes and might use a pair of DEBUG messages for that. What would qualify for this is your call, but opening or closing some random file would not qualify, but launching or deleting a new VM on EC2 might.

[adamhooper]

Finally got around to this :). v1.0.2 nixes the log message.

Thank you for the report!

[ShaheedHaque]

Thanks for getting back to it!

On Sun, 2 Jan 2022, 02:41 Adam Hooper, @.***> wrote:

Finally got around to this :). v1.0.2 nixes the log message.

Thank you for the report!

— Reply to this email directly, view it on GitHub https://github.com/CJWorkbench/carehare/issues/5#issuecomment-1003654549, or unsubscribe https://github.com/notifications/unsubscribe-auth/ABFHWKMAPTRPCM4GMZSME5LUT63NFANCNFSM5JLRWVDA . Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub.

You are receiving this because you authored the thread.Message ID: @.***>