Google-cloud-python: Every error that is not catchable by the user should be logged via the logging module

[gcbirzan]

Currently, at the very least helper threads for pubsub seem to not and they let the exception bubble up and get printed to stderr.

I think this is bad form, there's nothing _I_ can do to catch this error, but it'd be nice if I could get it logged in the format I want.

[Cory-Simon]

We handle this by explicitly adding a handler to the root logger.

https://googlecloudplatform.github.io/google-cloud-python/latest/logging/usage.html#integration-with-python-logging-module

[gcbirzan]

I think you misunderstood the problem. Firstly, we do have logging set up. Everything above INFO on the root logger goes through our handler. And, yet, we end up errors in the logs that don't have a jsonPayload and none of our metadata, only a textPayload. The errrors I'm talking about look like this:

Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/google/api_core/grpc_helpers.py", line 54, in error_remapped_callable
    return callable_(*args, **kwargs)
  File "/usr/local/lib/python3.6/site-packages/newrelic/api/external_trace.py", line 40, in dynamic_wrapper
    return wrapped(*args, **kwargs)
  File "/usr/local/lib/python3.6/site-packages/grpc/_channel.py", line 492, in __call__
    return _end_unary_response_blocking(state, call, False, deadline)
  File "/usr/local/lib/python3.6/site-packages/grpc/_channel.py", line 440, in _end_unary_response_blocking
    raise _Rendezvous(state, None, None, deadline)
grpc._channel._Rendezvous: <_Rendezvous of RPC that terminated with (StatusCode.UNAUTHENTICATED, Deadline Exceeded)>

and

Traceback (most recent call last):
  File "/usr/local/lib/python3.6/threading.py", line 916, in _bootstrap_inner
    self.run()
  File "/usr/local/lib/python3.6/threading.py", line 864, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/local/lib/python3.6/site-packages/google/cloud/pubsub_v1/publisher/batch/thread.py", line 239, in monitor
    return self._commit()
  File "/usr/local/lib/python3.6/site-packages/google/cloud/pubsub_v1/publisher/batch/thread.py", line 204, in _commit
    self._messages,
  File "/usr/local/lib/python3.6/site-packages/google/cloud/pubsub_v1/gapic/publisher_client.py", line 325, in publish
    return self._publish(request, retry=retry, timeout=timeout)
  File "/usr/local/lib/python3.6/site-packages/google/api_core/gapic_v1/method.py", line 139, in __call__
    return wrapped_func(*args, **kwargs)
  File "/usr/local/lib/python3.6/site-packages/google/api_core/retry.py", line 260, in retry_wrapped_func
    on_error=on_error,
  File "/usr/local/lib/python3.6/site-packages/google/api_core/retry.py", line 177, in retry_target
    return target()
  File "/usr/local/lib/python3.6/site-packages/google/api_core/timeout.py", line 206, in func_with_timeout
    return func(*args, **kwargs)
  File "/usr/local/lib/python3.6/site-packages/google/api_core/grpc_helpers.py", line 56, in error_remapped_callable
    six.raise_from(exceptions.from_grpc_error(exc), exc)
  File "<string>", line 3, in raise_from
google.api_core.exceptions.Unauthenticated: 401 Deadline Exceeded

As you see, the last one bubbles up all the way to the thread and gets handled there. There's no way for us to catch these and log them correctly. An artefact of the lack of logging support the fact that they're not linked together, since the parser seems to be unable to figure they're linked since we have more than one worker logging there and I guess another process is logging around the same time. In the containers where we only have one process, they get grouped together correctly:

Exception in thread Thread-MonitorBatchPublisher:
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/google/api_core/grpc_helpers.py", line 54, in error_remapped_callable
    return callable_(*args, **kwargs)
  File "/usr/local/lib/python3.6/site-packages/newrelic/api/external_trace.py", line 40, in dynamic_wrapper
    return wrapped(*args, **kwargs)
  File "/usr/local/lib/python3.6/site-packages/grpc/_channel.py", line 492, in __call__
    return _end_unary_response_blocking(state, call, False, deadline)
  File "/usr/local/lib/python3.6/site-packages/grpc/_channel.py", line 440, in _end_unary_response_blocking
    raise _Rendezvous(state, None, None, deadline)
grpc._channel._Rendezvous: <_Rendezvous of RPC that terminated with (StatusCode.UNAUTHENTICATED, Deadline Exceeded)>

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.6/threading.py", line 916, in _bootstrap_inner
    self.run()
  File "/usr/local/lib/python3.6/threading.py", line 864, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/local/lib/python3.6/site-packages/google/cloud/pubsub_v1/publisher/batch/thread.py", line 239, in monitor
    return self._commit()
  File "/usr/local/lib/python3.6/site-packages/google/cloud/pubsub_v1/publisher/batch/thread.py", line 204, in _commit
    self._messages,
  File "/usr/local/lib/python3.6/site-packages/google/cloud/pubsub_v1/gapic/publisher_client.py", line 325, in publish
    return self._publish(request, retry=retry, timeout=timeout)
  File "/usr/local/lib/python3.6/site-packages/google/api_core/gapic_v1/method.py", line 139, in __call__
    return wrapped_func(*args, **kwargs)
  File "/usr/local/lib/python3.6/site-packages/google/api_core/retry.py", line 260, in retry_wrapped_func
    on_error=on_error,
  File "/usr/local/lib/python3.6/site-packages/google/api_core/retry.py", line 177, in retry_target
    return target()
  File "/usr/local/lib/python3.6/site-packages/google/api_core/timeout.py", line 206, in func_with_timeout
    return func(*args, **kwargs)
  File "/usr/local/lib/python3.6/site-packages/google/api_core/grpc_helpers.py", line 56, in error_remapped_callable
    six.raise_from(exceptions.from_grpc_error(exc), exc)
  File "<string>", line 3, in raise_from
google.api_core.exceptions.Unauthenticated: 401 Deadline Exceeded