From 2e113ca6b2cc31aa8a9687d40ee1bd759381654f Mon Sep 17 00:00:00 2001 From: Naresh Date: Thu, 1 Mar 2018 13:24:45 +0530 Subject: [PATCH] Update logging in Python to use module-level logger All logging in Python so far was done with the root logger, resulting in logs like: `ERROR:Exception calling application:`. With module-level loggers, the logs will instead include the module in which the exception is raised: `ERROR:grpc._server:Exception calling application:` --- src/python/grpcio/grpc/_channel.py | 4 +++- src/python/grpcio/grpc/_common.py | 6 ++++-- .../grpcio/grpc/_cython/_cygrpc/grpc_string.pyx.pxi | 3 ++- src/python/grpcio/grpc/_cython/_cygrpc/server.pyx.pxi | 6 ++++-- src/python/grpcio/grpc/_plugin_wrapping.py | 4 +++- src/python/grpcio/grpc/_server.py | 10 ++++++---- .../grpcio/grpc/framework/foundation/callable_util.py | 4 +++- .../grpcio/grpc/framework/foundation/logging_pool.py | 4 +++- .../grpcio/grpc/framework/foundation/stream_util.py | 3 ++- .../grpc_testing/_channel/_invocation.py | 3 ++- src/python/grpcio_testing/grpc_testing/_server/_rpc.py | 6 ++++-- src/python/grpcio_testing/grpc_testing/_time.py | 4 +++- src/python/grpcio_tests/tests/interop/server.py | 7 ++++--- 13 files changed, 43 insertions(+), 21 deletions(-) diff --git a/src/python/grpcio/grpc/_channel.py b/src/python/grpcio/grpc/_channel.py index 2017d471308..9fe946b2d58 100644 --- a/src/python/grpcio/grpc/_channel.py +++ b/src/python/grpcio/grpc/_channel.py @@ -24,6 +24,8 @@ from grpc import _grpcio_metadata from grpc._cython import cygrpc from grpc.framework.foundation import callable_util +_LOGGER = logging.getLogger(__name__) + _USER_AGENT = 'grpc-python/{}'.format(_grpcio_metadata.__version__) _EMPTY_FLAGS = 0 @@ -181,7 +183,7 @@ def _consume_request_iterator(request_iterator, state, call, request_serializer, except Exception: # pylint: disable=broad-except code = grpc.StatusCode.UNKNOWN details = 'Exception iterating requests!' - logging.exception(details) + _LOGGER.exception(details) call.cancel(_common.STATUS_CODE_TO_CYGRPC_STATUS_CODE[code], details) _abort(state, code, details) diff --git a/src/python/grpcio/grpc/_common.py b/src/python/grpcio/grpc/_common.py index 862987a0cd1..8358cbec5b3 100644 --- a/src/python/grpcio/grpc/_common.py +++ b/src/python/grpcio/grpc/_common.py @@ -20,6 +20,8 @@ import six import grpc from grpc._cython import cygrpc +_LOGGER = logging.getLogger(__name__) + CYGRPC_CONNECTIVITY_STATE_TO_CHANNEL_CONNECTIVITY = { cygrpc.ConnectivityState.idle: grpc.ChannelConnectivity.IDLE, @@ -73,7 +75,7 @@ def decode(b): try: return b.decode('utf8') except UnicodeDecodeError: - logging.exception('Invalid encoding on %s', b) + _LOGGER.exception('Invalid encoding on %s', b) return b.decode('latin1') @@ -84,7 +86,7 @@ def _transform(message, transformer, exception_message): try: return transformer(message) except Exception: # pylint: disable=broad-except - logging.exception(exception_message) + _LOGGER.exception(exception_message) return None diff --git a/src/python/grpcio/grpc/_cython/_cygrpc/grpc_string.pyx.pxi b/src/python/grpcio/grpc/_cython/_cygrpc/grpc_string.pyx.pxi index 53e06a15967..00a1b23a67b 100644 --- a/src/python/grpcio/grpc/_cython/_cygrpc/grpc_string.pyx.pxi +++ b/src/python/grpcio/grpc/_cython/_cygrpc/grpc_string.pyx.pxi @@ -14,6 +14,7 @@ import logging +_LOGGER = logging.getLogger(__name__) # This function will ascii encode unicode string inputs if neccesary. # In Python3, unicode strings are the default str type. @@ -49,5 +50,5 @@ cdef str _decode(bytes bytestring): try: return bytestring.decode('utf8') except UnicodeDecodeError: - logging.exception('Invalid encoding on %s', bytestring) + _LOGGER.exception('Invalid encoding on %s', bytestring) return bytestring.decode('latin1') diff --git a/src/python/grpcio/grpc/_cython/_cygrpc/server.pyx.pxi b/src/python/grpcio/grpc/_cython/_cygrpc/server.pyx.pxi index 707ec742dda..da3dd212441 100644 --- a/src/python/grpcio/grpc/_cython/_cygrpc/server.pyx.pxi +++ b/src/python/grpcio/grpc/_cython/_cygrpc/server.pyx.pxi @@ -18,6 +18,8 @@ import logging import time import grpc +_LOGGER = logging.getLogger(__name__) + cdef grpc_ssl_certificate_config_reload_status _server_cert_config_fetcher_wrapper( void* user_data, grpc_ssl_server_certificate_config **config) with gil: # This is a credentials.ServerCertificateConfig @@ -34,13 +36,13 @@ cdef grpc_ssl_certificate_config_reload_status _server_cert_config_fetcher_wrapp try: cert_config_wrapper = user_cb() except Exception: - logging.exception('Error fetching certificate config') + _LOGGER.exception('Error fetching certificate config') return GRPC_SSL_CERTIFICATE_CONFIG_RELOAD_FAIL if cert_config_wrapper is None: return GRPC_SSL_CERTIFICATE_CONFIG_RELOAD_UNCHANGED elif not isinstance( cert_config_wrapper, grpc.ServerCertificateConfiguration): - logging.error( + _LOGGER.error( 'Error fetching certificate configuration: certificate ' 'configuration must be of type grpc.ServerCertificateConfiguration, ' 'not %s' % type(cert_config_wrapper).__name__) diff --git a/src/python/grpcio/grpc/_plugin_wrapping.py b/src/python/grpcio/grpc/_plugin_wrapping.py index 6785e5876a6..916ee080b60 100644 --- a/src/python/grpcio/grpc/_plugin_wrapping.py +++ b/src/python/grpcio/grpc/_plugin_wrapping.py @@ -20,6 +20,8 @@ import grpc from grpc import _common from grpc._cython import cygrpc +_LOGGER = logging.getLogger(__name__) + class _AuthMetadataContext( collections.namedtuple('AuthMetadataContext', ( @@ -76,7 +78,7 @@ class _Plugin(object): _AuthMetadataPluginCallback( callback_state, callback)) except Exception as exception: # pylint: disable=broad-except - logging.exception( + _LOGGER.exception( 'AuthMetadataPluginCallback "%s" raised exception!', self._metadata_plugin) with callback_state.lock: diff --git a/src/python/grpcio/grpc/_server.py b/src/python/grpcio/grpc/_server.py index d849cadbeea..d12a2421cd8 100644 --- a/src/python/grpcio/grpc/_server.py +++ b/src/python/grpcio/grpc/_server.py @@ -27,6 +27,8 @@ from grpc import _interceptor from grpc._cython import cygrpc from grpc.framework.foundation import callable_util +_LOGGER = logging.getLogger(__name__) + _SHUTDOWN_TAG = 'shutdown' _REQUEST_CALL_TAG = 'request_call' @@ -279,7 +281,7 @@ class _Context(grpc.ServicerContext): def abort(self, code, details): # treat OK like other invalid arguments: fail the RPC if code == grpc.StatusCode.OK: - logging.error( + _LOGGER.error( 'abort() called with StatusCode.OK; returning UNKNOWN') code = grpc.StatusCode.UNKNOWN details = '' @@ -390,7 +392,7 @@ def _call_behavior(rpc_event, state, behavior, argument, request_deserializer): b'RPC Aborted') elif exception not in state.rpc_errors: details = 'Exception calling application: {}'.format(exception) - logging.exception(details) + _LOGGER.exception(details) _abort(state, rpc_event.call, cygrpc.StatusCode.unknown, _common.encode(details)) return None, False @@ -408,7 +410,7 @@ def _take_response_from_response_iterator(rpc_event, state, response_iterator): b'RPC Aborted') elif exception not in state.rpc_errors: details = 'Exception iterating responses: {}'.format(exception) - logging.exception(details) + _LOGGER.exception(details) _abort(state, rpc_event.call, cygrpc.StatusCode.unknown, _common.encode(details)) return None, False @@ -617,7 +619,7 @@ def _handle_call(rpc_event, generic_handlers, interceptor_pipeline, thread_pool, interceptor_pipeline) except Exception as exception: # pylint: disable=broad-except details = 'Exception servicing handler: {}'.format(exception) - logging.exception(details) + _LOGGER.exception(details) return _reject_rpc(rpc_event, cygrpc.StatusCode.unknown, b'Error in service handler!'), None if method_handler is None: diff --git a/src/python/grpcio/grpc/framework/foundation/callable_util.py b/src/python/grpcio/grpc/framework/foundation/callable_util.py index b9b9c49f17d..24daf3406f8 100644 --- a/src/python/grpcio/grpc/framework/foundation/callable_util.py +++ b/src/python/grpcio/grpc/framework/foundation/callable_util.py @@ -21,6 +21,8 @@ import logging import six +_LOGGER = logging.getLogger(__name__) + class Outcome(six.with_metaclass(abc.ABCMeta)): """A sum type describing the outcome of some call. @@ -53,7 +55,7 @@ def _call_logging_exceptions(behavior, message, *args, **kwargs): return _EasyOutcome(Outcome.Kind.RETURNED, behavior(*args, **kwargs), None) except Exception as e: # pylint: disable=broad-except - logging.exception(message) + _LOGGER.exception(message) return _EasyOutcome(Outcome.Kind.RAISED, None, e) diff --git a/src/python/grpcio/grpc/framework/foundation/logging_pool.py b/src/python/grpcio/grpc/framework/foundation/logging_pool.py index f75df100424..216e3990db0 100644 --- a/src/python/grpcio/grpc/framework/foundation/logging_pool.py +++ b/src/python/grpcio/grpc/framework/foundation/logging_pool.py @@ -17,6 +17,8 @@ import logging from concurrent import futures +_LOGGER = logging.getLogger(__name__) + def _wrap(behavior): """Wraps an arbitrary callable behavior in exception-logging.""" @@ -25,7 +27,7 @@ def _wrap(behavior): try: return behavior(*args, **kwargs) except Exception: - logging.exception( + _LOGGER.exception( 'Unexpected exception from %s executed in logging pool!', behavior) raise diff --git a/src/python/grpcio/grpc/framework/foundation/stream_util.py b/src/python/grpcio/grpc/framework/foundation/stream_util.py index 04631d9899c..ed0448aa08a 100644 --- a/src/python/grpcio/grpc/framework/foundation/stream_util.py +++ b/src/python/grpcio/grpc/framework/foundation/stream_util.py @@ -19,6 +19,7 @@ import threading from grpc.framework.foundation import stream _NO_VALUE = object() +_LOGGER = logging.getLogger(__name__) class TransformingConsumer(stream.Consumer): @@ -103,7 +104,7 @@ class ThreadSwitchingConsumer(stream.Consumer): else: sink.consume(value) except Exception as e: # pylint:disable=broad-except - logging.exception(e) + _LOGGER.exception(e) with self._lock: if terminate: diff --git a/src/python/grpcio_testing/grpc_testing/_channel/_invocation.py b/src/python/grpcio_testing/grpc_testing/_channel/_invocation.py index ebce652eeb0..191b1c17264 100644 --- a/src/python/grpcio_testing/grpc_testing/_channel/_invocation.py +++ b/src/python/grpcio_testing/grpc_testing/_channel/_invocation.py @@ -18,6 +18,7 @@ import threading import grpc _NOT_YET_OBSERVED = object() +_LOGGER = logging.getLogger(__name__) def _cancel(handler): @@ -248,7 +249,7 @@ def consume_requests(request_iterator, handler): break except Exception: # pylint: disable=broad-except details = 'Exception iterating requests!' - logging.exception(details) + _LOGGER.exception(details) handler.cancel(grpc.StatusCode.UNKNOWN, details) consumption = threading.Thread(target=_consume) diff --git a/src/python/grpcio_testing/grpc_testing/_server/_rpc.py b/src/python/grpcio_testing/grpc_testing/_server/_rpc.py index 2060e8daff5..b856da100f0 100644 --- a/src/python/grpcio_testing/grpc_testing/_server/_rpc.py +++ b/src/python/grpcio_testing/grpc_testing/_server/_rpc.py @@ -18,6 +18,8 @@ import threading import grpc from grpc_testing import _common +_LOGGER = logging.getLogger(__name__) + class Rpc(object): @@ -47,7 +49,7 @@ class Rpc(object): try: callback() except Exception: # pylint: disable=broad-except - logging.exception('Exception calling server-side callback!') + _LOGGER.exception('Exception calling server-side callback!') callback_calling_thread = threading.Thread(target=call_back) callback_calling_thread.start() @@ -86,7 +88,7 @@ class Rpc(object): def application_exception_abort(self, exception): with self._condition: if exception not in self._rpc_errors: - logging.exception('Exception calling application!') + _LOGGER.exception('Exception calling application!') self._abort( grpc.StatusCode.UNKNOWN, 'Exception calling application: {}'.format(exception)) diff --git a/src/python/grpcio_testing/grpc_testing/_time.py b/src/python/grpcio_testing/grpc_testing/_time.py index afbdad3524e..75e6db34586 100644 --- a/src/python/grpcio_testing/grpc_testing/_time.py +++ b/src/python/grpcio_testing/grpc_testing/_time.py @@ -21,13 +21,15 @@ import time as _time import grpc import grpc_testing +_LOGGER = logging.getLogger(__name__) + def _call(behaviors): for behavior in behaviors: try: behavior() except Exception: # pylint: disable=broad-except - logging.exception('Exception calling behavior "%r"!', behavior) + _LOGGER.exception('Exception calling behavior "%r"!', behavior) def _call_in_thread(behaviors): diff --git a/src/python/grpcio_tests/tests/interop/server.py b/src/python/grpcio_tests/tests/interop/server.py index 0810de2394a..fd28d498a18 100644 --- a/src/python/grpcio_tests/tests/interop/server.py +++ b/src/python/grpcio_tests/tests/interop/server.py @@ -26,6 +26,7 @@ from tests.interop import resources from tests.unit import test_common _ONE_DAY_IN_SECONDS = 60 * 60 * 24 +_LOGGER = logging.getLogger(__name__) def serve(): @@ -52,14 +53,14 @@ def serve(): server.add_insecure_port('[::]:{}'.format(args.port)) server.start() - logging.info('Server serving.') + _LOGGER.info('Server serving.') try: while True: time.sleep(_ONE_DAY_IN_SECONDS) except BaseException as e: - logging.info('Caught exception "%s"; stopping server...', e) + _LOGGER.info('Caught exception "%s"; stopping server...', e) server.stop(None) - logging.info('Server stopped; exiting.') + _LOGGER.info('Server stopped; exiting.') if __name__ == '__main__':