Firestore overrides logging level

[rgant]

1. Firestore
2. MacOS 10.14.1 Mojave
3. Python 3.7.1 & Python 2.7.15
4. google-cloud-firestore==0.30.0

When I include firestore in my application it resets/undoes/breaks my logging. I
expect that importing firestore will not affect the root logger's level.

I've tried this in several different versions of python 2 & 3, pip and pipenv all
with the same results.

Steps to Reproduce

Create virtualenv:

python3 -m venv ./venv

Activate it:

source ./venv/bin/activate

Upgrade pip & setuptools so everything is the latest version.

pip3 install --upgrade pip setuptools

Collecting pip
  Using cached https://files.pythonhosted.org/packages/c2/d7/90f34cb0d83a6c5631cf71dfe64cc1054598c843a92b400e55675cc2ac37/pip-18.1-py2.py3-none-any.whl
Collecting setuptools
  Using cached https://files.pythonhosted.org/packages/82/a1/ba6fb41367b375f5cb653d1317d8ca263c636cff6566e2da1b0da716069d/setuptools-40.5.0-py2.py3-none-any.whl
Installing collected packages: pip, setuptools
  Found existing installation: pip 10.0.1
    Uninstalling pip-10.0.1:
      Successfully uninstalled pip-10.0.1
  Found existing installation: setuptools 39.0.1
    Uninstalling setuptools-39.0.1:
      Successfully uninstalled setuptools-39.0.1
Successfully installed pip-18.1 setuptools-40.5.0

Install google-cloud-firestore:

pip3 install google-cloud-firestore

Collecting google-cloud-firestore
  Using cached https://files.pythonhosted.org/packages/47/e1/43a9577ae1db52b7edc72f75f8b275cceffe5b08fd27e13eb4d72f6f9a11/google_cloud_firestore-0.30.0-py2.py3-none-any.whl
Collecting google-cloud-core<0.29dev,>=0.28.0 (from google-cloud-firestore)
  Using cached https://files.pythonhosted.org/packages/0f/41/ae2418b4003a14cf21c1c46d61d1b044bf02cf0f8f91598af572b9216515/google_cloud_core-0.28.1-py2.py3-none-any.whl
Collecting google-api-core[grpc]<2.0.0dev,>=0.1.1 (from google-cloud-firestore)
  Using cached https://files.pythonhosted.org/packages/48/53/2ec314fe5c167d150b6980f23765a8a8aa56861eb59e7e0fc45f499c62e3/google_api_core-1.5.1-py2.py3-none-any.whl
Collecting six>=1.10.0 (from google-api-core[grpc]<2.0.0dev,>=0.1.1->google-cloud-firestore)
  Using cached https://files.pythonhosted.org/packages/67/4b/141a581104b1f6397bfa78ac9d43d8ad29a7ca43ea90a2d863fe3056e86a/six-1.11.0-py2.py3-none-any.whl
Collecting google-auth<2.0.0dev,>=0.4.0 (from google-api-core[grpc]<2.0.0dev,>=0.1.1->google-cloud-firestore)
  Using cached https://files.pythonhosted.org/packages/58/cb/96dbb4e50e7a9d856e89cc9c8e36ab1055f9774f7d85f37e2156c1d79d9f/google_auth-1.5.1-py2.py3-none-any.whl
Requirement already satisfied: setuptools>=34.0.0 in ./venv/lib/python3.7/site-packages (from google-api-core[grpc]<2.0.0dev,>=0.1.1->google-cloud-firestore) (40.5.0)
Collecting requests<3.0.0dev,>=2.18.0 (from google-api-core[grpc]<2.0.0dev,>=0.1.1->google-cloud-firestore)
  Using cached https://files.pythonhosted.org/packages/f1/ca/10332a30cb25b627192b4ea272c351bce3ca1091e541245cccbace6051d8/requests-2.20.0-py2.py3-none-any.whl
Collecting pytz (from google-api-core[grpc]<2.0.0dev,>=0.1.1->google-cloud-firestore)
  Using cached https://files.pythonhosted.org/packages/f8/0e/2365ddc010afb3d79147f1dd544e5ee24bf4ece58ab99b16fbb465ce6dc0/pytz-2018.7-py2.py3-none-any.whl
Collecting protobuf>=3.4.0 (from google-api-core[grpc]<2.0.0dev,>=0.1.1->google-cloud-firestore)
  Using cached https://files.pythonhosted.org/packages/18/e7/785830a65d1f1faba7dccfa8314f7afded1db8cc2860218226ba4b3f6150/protobuf-3.6.1-cp37-cp37m-macosx_10_6_intel.macosx_10_9_intel.macosx_10_9_x86_64.macosx_10_10_intel.macosx_10_10_x86_64.whl
Collecting googleapis-common-protos<2.0dev,>=1.5.3 (from google-api-core[grpc]<2.0.0dev,>=0.1.1->google-cloud-firestore)
  Using cached https://files.pythonhosted.org/packages/ae/94/a256572abf5d10347301c638d5df552fab1515497270726e6b56698d2e99/googleapis-common-protos-1.5.5.tar.gz
Collecting grpcio>=1.8.2; extra == "grpc" (from google-api-core[grpc]<2.0.0dev,>=0.1.1->google-cloud-firestore)
  Using cached https://files.pythonhosted.org/packages/87/be/fb5091be98c173a6f98eeeca2fe9bc85f41f3a49ae61647351462a60e745/grpcio-1.16.0-cp37-cp37m-macosx_10_9_x86_64.whl
Collecting cachetools>=2.0.0 (from google-auth<2.0.0dev,>=0.4.0->google-api-core[grpc]<2.0.0dev,>=0.1.1->google-cloud-firestore)
  Using cached https://files.pythonhosted.org/packages/76/7e/08cd3846bebeabb6b1cfc4af8aae649d90249b4aeed080bddb5297f1d73b/cachetools-3.0.0-py2.py3-none-any.whl
Collecting rsa>=3.1.4 (from google-auth<2.0.0dev,>=0.4.0->google-api-core[grpc]<2.0.0dev,>=0.1.1->google-cloud-firestore)
  Using cached https://files.pythonhosted.org/packages/02/e5/38518af393f7c214357079ce67a317307936896e961e35450b70fad2a9cf/rsa-4.0-py2.py3-none-any.whl
Collecting pyasn1-modules>=0.2.1 (from google-auth<2.0.0dev,>=0.4.0->google-api-core[grpc]<2.0.0dev,>=0.1.1->google-cloud-firestore)
  Using cached https://files.pythonhosted.org/packages/19/02/fa63f7ba30a0d7b925ca29d034510fc1ffde53264b71b4155022ddf3ab5d/pyasn1_modules-0.2.2-py2.py3-none-any.whl
Collecting urllib3<1.25,>=1.21.1 (from requests<3.0.0dev,>=2.18.0->google-api-core[grpc]<2.0.0dev,>=0.1.1->google-cloud-firestore)
  Using cached https://files.pythonhosted.org/packages/62/00/ee1d7de624db8ba7090d1226aebefab96a2c71cd5cfa7629d6ad3f61b79e/urllib3-1.24.1-py2.py3-none-any.whl
Collecting chardet<3.1.0,>=3.0.2 (from requests<3.0.0dev,>=2.18.0->google-api-core[grpc]<2.0.0dev,>=0.1.1->google-cloud-firestore)
  Using cached https://files.pythonhosted.org/packages/bc/a9/01ffebfb562e4274b6487b4bb1ddec7ca55ec7510b22e4c51f14098443b8/chardet-3.0.4-py2.py3-none-any.whl
Collecting certifi>=2017.4.17 (from requests<3.0.0dev,>=2.18.0->google-api-core[grpc]<2.0.0dev,>=0.1.1->google-cloud-firestore)
  Using cached https://files.pythonhosted.org/packages/56/9d/1d02dd80bc4cd955f98980f28c5ee2200e1209292d5f9e9cc8d030d18655/certifi-2018.10.15-py2.py3-none-any.whl
Collecting idna<2.8,>=2.5 (from requests<3.0.0dev,>=2.18.0->google-api-core[grpc]<2.0.0dev,>=0.1.1->google-cloud-firestore)
  Using cached https://files.pythonhosted.org/packages/4b/2a/0276479a4b3caeb8a8c1af2f8e4355746a97fab05a372e4a2c6a6b876165/idna-2.7-py2.py3-none-any.whl
Collecting pyasn1>=0.1.3 (from rsa>=3.1.4->google-auth<2.0.0dev,>=0.4.0->google-api-core[grpc]<2.0.0dev,>=0.1.1->google-cloud-firestore)
  Using cached https://files.pythonhosted.org/packages/d1/a1/7790cc85db38daa874f6a2e6308131b9953feb1367f2ae2d1123bb93a9f5/pyasn1-0.4.4-py2.py3-none-any.whl
Installing collected packages: six, cachetools, pyasn1, rsa, pyasn1-modules, google-auth, urllib3, chardet, certifi, idna, requests, pytz, protobuf, googleapis-common-protos, grpcio, google-api-core, google-cloud-core, google-cloud-firestore
  Running setup.py install for googleapis-common-protos ... done
Successfully installed cachetools-3.0.0 certifi-2018.10.15 chardet-3.0.4 google-api-core-1.5.1 google-auth-1.5.1 google-cloud-core-0.28.1 google-cloud-firestore-0.30.0 googleapis-common-protos-1.5.5 grpcio-1.16.0 idna-2.7 protobuf-3.6.1 pyasn1-0.4.4 pyasn1-modules-0.2.2 pytz-2018.7 requests-2.20.0 rsa-4.0 six-1.11.0 urllib3-1.24.1

Debug Script name test.py

import logging

from google.cloud import firestore


def main():
    logger = logging.getLogger(__name__)
    # logger.setLevel(logging.DEBUG)
    logger.info('Logging INFO level')

if __name__ == '__main__':
    logging.basicConfig(level=logging.DEBUG)
    main()

Execute script, and get no logging output:

$ python3 test.py
$

Comment out from google.cloud import firestore, and get logging output:

$ python3 test.py
INFO:__main__:Logging INFO level

Uncomment from google.cloud import firestore and uncomment logger.setLevel(logging.DEBUG),
and get logging output

$ python3 test.py
INFO:__main__:Logging INFO level

[rgant]

I've never really grokked python logging. So perhaps I'm doing something strange with my setup, but this is the way I've configured python scripts for years.

[tseaver]

@rgant Thanks for the report. google-cloud-firestore itself does not touch logging:

$ git grep logging firestore/ | wc -l
0

Based on a similar discussion in #6342, I believe that grpcio is the culprit: see grpc/grpc#16572, for instance, where one user reported:

1.16.0 release broke logging in our Python app (no output at all now when INFO level logging was visible before). It seems that logging configuration (e.g. using logging.basicConfig() should be done on the top app level and avoided on a library level.

I agree completely that logging.basicConfig() should never be done in library code. It looks like the `grpcio' developers have fixed that issue in grpc/grpc#17064, which is not yet in a release as of this writing.

[rgant]

Thanks, tracing through the dependencies trying to find the issue wasn't fun. Guess I stopped too soon. Thanks again!