Do not log raised exceptions

[edigaryev]

This blog post sums the essence of this issue pretty well:

Roughly: if your library catches and swallows an exception in a graceful, designed-for manner, then it almost certainly shouldn't be logging the event as an exception. Since exceptions are logged at the highest priority, there is no way to turn off these useless, highly verbose, gracefully handled exception messages without disabling logging for your entire package, which might result in some important messages getting hidden that really should have been logged.

A notorious example:

grpclib/grpclib/server.py

Lines 402 to 413 in a21e598

	log.exception('Timeout occurred')
	raise
	except StreamTerminatedError:
	log.exception('Request was cancelled')
	raise
	except Exception:
	log.exception('Application error')
	raise
	except ProtocolError:
	log.exception('Application error')
	except Exception:
	log.exception('Server error')

Currently I set the root logger to CRITICAL level to avoid getting all these redundant messages in the program's log:

logging.getLogger().setLevel(logging.CRITICAL)`

...but that's clearly a workaround.

[edigaryev]

I just realized that after setting the root logger level to CRITICAL my stream unwinding coroutine (i.e. coroutine that does async for item in stream) stopped throwing StreamTerminatedError exception and started emitting generic asyncio.CancelledError exceptions that silently get ignored unless you wrap them in try/except.

Is this intended behavior?

[vmagamedov]

Python's logging library is very flexible, you actually can mute any kind of log entry individually. And there is no need to touch root logger when all our logs are logged with grpclib.server logger. See https://docs.python.org/3/library/logging.html#filter-objects for more details.

But I agree that logging levels should be reconsidered. Can you elaborate on which log entries you think are redundant?

CancelledError is an error with which asyncio task gets cancelled, it is not ignored, it is re-raised as StreamTerminatedError and logged afterwards by grpclib.server.request_handler(). You were seeing these errors before changing loggers setup. And such errors re-raising gives you a cues about why request was cancelled (a common problem in asyncio world). So CancelledError is always raised in your handler and loggers setup has nothing to do with this.

[vmagamedov]

Lowered level down to INFO for successfully handled request cancellation in case of deadline or stream reset.

[vmagamedov]

Documented how cancellation works on the server-side: https://grpclib.readthedocs.io/en/latest/errors.html#server-side

[vmagamedov]

Closing this issue, please reopen if you have specific suggestions to improve logging in grpclib