google-cloud-datastore no longer works with freezegun

[remcohaszing]

As of google-cloud-datastore 1.0.0 it no longer works together with freezegun.

Workaround: downgrade to google-cloud-datastore 0.23.0

1. OS type and version:

Ubuntu 17.04, but it was also reproduced on 16.04.

2. Python version and virtual environment information python --version

$ python --version
Python 3.6.0+

3. google-cloud-python version pip show google-cloud, pip show google-<service> or pip freeze

$ pip list | grep google-cloud
gapic-google-cloud-datastore-v1 0.15.3 
google-cloud-core               0.24.0 
google-cloud-datastore          1.0.0  
google-cloud-storage            1.0.0  
proto-google-cloud-datastore-v1 0.90.3

4. Stacktrace if available

py.test --tb native

Traceback (most recent call last):
  File "/home/remco/.local/share/virtualenvs/tmp-35dac56d418be2c/lib/python3.6/site-packages/google/gax/retry.py", line 120, in inner
    return to_call(*args)
  File "/home/remco/.local/share/virtualenvs/tmp-35dac56d418be2c/lib/python3.6/site-packages/google/gax/retry.py", line 68, in inner
    return a_func(*updated_args, **kwargs)
  File "/home/remco/.local/share/virtualenvs/tmp-35dac56d418be2c/lib/python3.6/site-packages/grpc/_channel.py", line 507, in __call__
    return _end_unary_response_blocking(state, call, False, deadline)
  File "/home/remco/.local/share/virtualenvs/tmp-35dac56d418be2c/lib/python3.6/site-packages/grpc/_channel.py", line 455, in _end_unary_response_blocking
    raise _Rendezvous(state, None, None, deadline)
grpc._channel._Rendezvous: <_Rendezvous of RPC that terminated with (StatusCode.INTERNAL, Received RST_STREAM with error code 2)>

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/remco/.local/share/virtualenvs/tmp-35dac56d418be2c/lib/python3.6/site-packages/google/cloud/datastore/_gax.py", line 74, in _catch_remap_gax_error
    yield
  File "/home/remco/.local/share/virtualenvs/tmp-35dac56d418be2c/lib/python3.6/site-packages/google/cloud/datastore/_gax.py", line 173, in commit
    return super(GAPICDatastoreAPI, self).commit(*args, **kwargs)
  File "/home/remco/.local/share/virtualenvs/tmp-35dac56d418be2c/lib/python3.6/site-packages/google/cloud/gapic/datastore/v1/datastore_client.py", line 345, in commit
    return self._commit(request, options)
  File "/home/remco/.local/share/virtualenvs/tmp-35dac56d418be2c/lib/python3.6/site-packages/google/gax/api_callable.py", line 419, in inner
    return api_caller(api_call, this_settings, request)
  File "/home/remco/.local/share/virtualenvs/tmp-35dac56d418be2c/lib/python3.6/site-packages/google/gax/api_callable.py", line 407, in base_caller
    return api_call(*args)
  File "/home/remco/.local/share/virtualenvs/tmp-35dac56d418be2c/lib/python3.6/site-packages/google/gax/api_callable.py", line 368, in inner
    return a_func(*args, **kwargs)
  File "/home/remco/.local/share/virtualenvs/tmp-35dac56d418be2c/lib/python3.6/site-packages/google/gax/retry.py", line 126, in inner
    ' classified as transient', exception)
google.gax.errors.RetryError: GaxError(Exception occurred in retry method that was not classified as transient, caused by <_Rendezvous of RPC that terminated with (StatusCode.INTERNAL, Received RST_STREAM with error code 2)>)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/remco/example/test.py", line 16, in test_put_frozen
    client.put(entity)
  File "/home/remco/.local/share/virtualenvs/tmp-35dac56d418be2c/lib/python3.6/site-packages/google/cloud/datastore/client.py", line 384, in put
    self.put_multi(entities=[entity])
  File "/home/remco/.local/share/virtualenvs/tmp-35dac56d418be2c/lib/python3.6/site-packages/google/cloud/datastore/client.py", line 411, in put_multi
    current.commit()
  File "/home/remco/.local/share/virtualenvs/tmp-35dac56d418be2c/lib/python3.6/site-packages/google/cloud/datastore/batch.py", line 273, in commit
    self._commit()
  File "/home/remco/.local/share/virtualenvs/tmp-35dac56d418be2c/lib/python3.6/site-packages/google/cloud/datastore/batch.py", line 249, in _commit
    self.project, mode, self._mutations, transaction=self._id)
  File "/home/remco/.local/share/virtualenvs/tmp-35dac56d418be2c/lib/python3.6/site-packages/google/cloud/datastore/_gax.py", line 173, in commit
    return super(GAPICDatastoreAPI, self).commit(*args, **kwargs)
  File "/usr/lib/python3.6/contextlib.py", line 100, in __exit__
    self.gen.throw(type, value, traceback)
  File "/home/remco/.local/share/virtualenvs/tmp-35dac56d418be2c/lib/python3.6/site-packages/google/cloud/datastore/_gax.py", line 82, in _catch_remap_gax_error
    six.reraise(error_class, new_exc, sys.exc_info()[2])
  File "/home/remco/.local/share/virtualenvs/tmp-35dac56d418be2c/lib/python3.6/site-packages/six.py", line 685, in reraise
    raise value.with_traceback(tb)
  File "/home/remco/.local/share/virtualenvs/tmp-35dac56d418be2c/lib/python3.6/site-packages/google/cloud/datastore/_gax.py", line 74, in _catch_remap_gax_error
    yield
  File "/home/remco/.local/share/virtualenvs/tmp-35dac56d418be2c/lib/python3.6/site-packages/google/cloud/datastore/_gax.py", line 173, in commit
    return super(GAPICDatastoreAPI, self).commit(*args, **kwargs)
  File "/home/remco/.local/share/virtualenvs/tmp-35dac56d418be2c/lib/python3.6/site-packages/google/cloud/gapic/datastore/v1/datastore_client.py", line 345, in commit
    return self._commit(request, options)
  File "/home/remco/.local/share/virtualenvs/tmp-35dac56d418be2c/lib/python3.6/site-packages/google/gax/api_callable.py", line 419, in inner
    return api_caller(api_call, this_settings, request)
  File "/home/remco/.local/share/virtualenvs/tmp-35dac56d418be2c/lib/python3.6/site-packages/google/gax/api_callable.py", line 407, in base_caller
    return api_call(*args)
  File "/home/remco/.local/share/virtualenvs/tmp-35dac56d418be2c/lib/python3.6/site-packages/google/gax/api_callable.py", line 368, in inner
    return a_func(*args, **kwargs)
  File "/home/remco/.local/share/virtualenvs/tmp-35dac56d418be2c/lib/python3.6/site-packages/google/gax/retry.py", line 126, in inner
    ' classified as transient', exception)
google.cloud.exceptions.InternalServerError: 500 Received RST_STREAM with error code 2

5. Steps to reproduce

Decorate a function using freezegun.freeze_time from freezegun and put a gcloud datastore entity.

6. Code example

import google.cloud.datastore
import pytest
from freezegun import freeze_time


# Works
def test_put():
    client = google.cloud.datastore.Client()
    entity = google.cloud.datastore.Entity(key=client.key('spam'))
    client.put(entity)


# Fails
@freeze_time('3216-08-04')
def test_put_frozen():
    client = google.cloud.datastore.Client()
    entity = google.cloud.datastore.Entity(key=client.key('spam'))
    client.put(entity)

The datastore was launched in the background using the following code:

def start_datastore():
    """
    Start an in memory gcloud datastore emulator.

    The datastore and all of its subprocesses are killed when the Python
    interpreter is shut down.

    Raises:
        RuntimeError: If the datastore failed to start.

    """
    tmpdir = tempfile.TemporaryDirectory()
    atexit.register(partial(tmpdir.cleanup))
    command = (
        'gcloud',
        'beta',
        'emulators',
        'datastore',
        'start',
        '--project', os.environ['GOOGLE_CLOUD_PROJECT'],
        '--no-store-on-disk',
        '--data-dir', tmpdir.name,
        '--consistency', '1.0'
    )
    proc = subprocess.Popen(
        command,
        stderr=subprocess.PIPE,
        preexec_fn=os.setsid)
    atexit.register(partial(os.killpg, os.getpgid(proc.pid), signal.SIGTERM))
    logs = []
    for lineno, line in enumerate(proc.stderr):
        line = line.decode()
        logs.append(line)
        if 'Dev App Server is now running' in line:
            return tmpdir
        # At the time of writing, 22 lines were printed before the
        # server was up and running. A small buffer is allowed in case
        # changes are introduced in the logging output.
        if lineno > 40:
            break
    raise RuntimeError('Unable to start datastore\n' + ''.join(logs))

[lukesneeringer]

Hi @remcohaszing,
Thanks for reporting, and for the level of detail.

That traceback looks like an internal server error to me. Is this a repeatable error, or did you get it once and downgrade? I think it is probably (almost certainly) unrelated to the version difference (particularly because the version difference had no actual code change, I do not think).

[remcohaszing]

I managed to repeat this consistently. All of my tests succeed when using version 0.23.0, but all tests decorated with freeze_time fail when using version 1.0.0. I've upgraded the packages, downgraded them, did some full virtualenv wipes for fresh installs, etc.

I've tested this with the google-cloud-sdk-datastore-emulator installed using apt on my machine and in a Docker image in which I have recently upgraded the google-cloud-sdk tar download from 143.0.0 to 150.0.0.

Behaviour is very consistent. All that affects the tests' success is the version of google-cloud-datastore.

[lukesneeringer]

Interesting. Thank you. I will look into it.

[dhermes]

So a primary difference between 0.23.0 and 1.0.0 is the usage of the GAPIC generated surface for the client (see the release notes)

@remcohaszing Can you manually pass _use_grpc=False when creating a Client and see if the issue persists? (This way we can zoom in on it.)

[remcohaszing]

Adding _use_grpc=False still makes the test fail, but with another error.

The test without freezegun still works.

import google.cloud.datastore
import pytest
from freezegun import freeze_time


# Works
def test_put():
    client = google.cloud.datastore.Client(_use_grpc=False)
    entity = google.cloud.datastore.Entity(key=client.key('spam'))
    client.put(entity)


# Fails
@freeze_time('3216-08-04')
def test_put_frozen():
    client = google.cloud.datastore.Client(_use_grpc=False)
    entity = google.cloud.datastore.Entity(key=client.key('spam'))
    client.put(entity)

Stack trace from test_put_frozen:

Traceback (most recent call last):
  File "/home/remco/test/test.py", line 18, in test_put_frozen
    client.put(entity)
  File "/home/remco/.local/share/virtualenvs/tmp-685d52736dc8093/lib/python3.6/site-packages/google/cloud/datastore/client.py", line 384, in put
    self.put_multi(entities=[entity])
  File "/home/remco/.local/share/virtualenvs/tmp-685d52736dc8093/lib/python3.6/site-packages/google/cloud/datastore/client.py", line 411, in put_multi
    current.commit()
  File "/home/remco/.local/share/virtualenvs/tmp-685d52736dc8093/lib/python3.6/site-packages/google/cloud/datastore/batch.py", line 273, in commit
    self._commit()
  File "/home/remco/.local/share/virtualenvs/tmp-685d52736dc8093/lib/python3.6/site-packages/google/cloud/datastore/batch.py", line 249, in _commit
    self.project, mode, self._mutations, transaction=self._id)
  File "/home/remco/.local/share/virtualenvs/tmp-685d52736dc8093/lib/python3.6/site-packages/google/cloud/datastore/_http.py", line 265, in commit
    request_pb, _datastore_pb2.CommitResponse)
  File "/home/remco/.local/share/virtualenvs/tmp-685d52736dc8093/lib/python3.6/site-packages/google/cloud/datastore/_http.py", line 112, in _rpc
    http, project, method, req_data, base_url)
  File "/home/remco/.local/share/virtualenvs/tmp-685d52736dc8093/lib/python3.6/site-packages/google/cloud/datastore/_http.py", line 72, in _request
    uri=api_url, method='POST', headers=headers, body=data)
  File "/home/remco/.local/share/virtualenvs/tmp-685d52736dc8093/lib/python3.6/site-packages/google_auth_httplib2.py", line 187, in request
    self._request, method, uri, request_headers)
  File "/home/remco/.local/share/virtualenvs/tmp-685d52736dc8093/lib/python3.6/site-packages/google/auth/credentials.py", line 118, in before_request
    self.refresh(request)
  File "/home/remco/.local/share/virtualenvs/tmp-685d52736dc8093/lib/python3.6/site-packages/google/oauth2/service_account.py", line 310, in refresh
    request, self._token_uri, assertion)
  File "/home/remco/.local/share/virtualenvs/tmp-685d52736dc8093/lib/python3.6/site-packages/google/oauth2/_client.py", line 143, in jwt_grant
    response_data = _token_endpoint_request(request, token_uri, body)
  File "/home/remco/.local/share/virtualenvs/tmp-685d52736dc8093/lib/python3.6/site-packages/google/oauth2/_client.py", line 109, in _token_endpoint_request
    _handle_error_response(response_body)
  File "/home/remco/.local/share/virtualenvs/tmp-685d52736dc8093/lib/python3.6/site-packages/google/oauth2/_client.py", line 59, in _handle_error_response
    error_details, response_body)
google.auth.exceptions.RefreshError: ('invalid_grant: Invalid JWT: Token must be a short-lived token and in a reasonable timeframe', '{\n  "error" : "invalid_grant",\n  "error_description" : "Invalid JWT: Token must be a short-lived token and in a reasonable timeframe"\n}')

[dhermes]

Well that's at least comforting. Your test is trying to make a live request to the auth server with a bad time. That's the buyer beware of using freezegun. You'll probably want to use a mocked out credentials instance (e.g.).

I'm not sure what other timing issues you're having in GAPIC / gRPC but there's not much we can do about it (aside from better stacktraces, which were pretty non-helpful for the gRPC case).

[remcohaszing]

I'm using google-cloud-datastore and google-cloud-storage. My tests for GCloud storage are fully based on mocks, because there is no emulator for this. The ones on google-cloud-datastore use an actual datastore emulator, as I've experienced this catches far more bugs than when mocking everything. Because of this, I'm only having this issue with the datastore.

Since the issue occurs regardless of the datastore emulator version, I think this should be fixable.

I don't know much about internals of google-cloud-* packages, GAPIC, or gRPC. What's the difference between google-cloud-datastore versions 0.23.0 and 1.0.0? Were these packages bumped? Are they new dependencies? If so, is this an upstream issue for those packages?

[dhermes]

@remcohaszing The issue is that you aren't mocking auth, but you are mocking the system time, so when your tests try to communicate with the auth server, bad things happen.

[remcohaszing]

I couldn't figure out a proper way to mock auth. Instead, I've created the following pytest fixture to work around this issue:

import datetime

import pytest
from freezegun import freeze_time
from pytz import utc


@pytest.fixture
def now():
    """
    Freeze the current time.

    This allows to freeze time and make assertions while working around
    https://github.com/GoogleCloudPlatform/google-cloud-python/issues/3284

    """
    now = datetime.datetime.utcnow().replace(tzinfo=utc)
    with freeze_time(now):
        yield now

[dhermes]

@remcohaszing I'd recommend just starting with a mock credentials object and passing it to a client:

credentials = mock.Mock(spec=[])
client = storage.Client(credentials=credentials, project=project)

then build up the mock slowly as you find the AttributeError-s in your tests. The snippet I linked to before should work just fine, and I'm happy to chat in Google Hangouts if you are having issues getting it off the ground.

I'm closing this issue out, it seems to be "resolved" in some sense.

[theacodes]

here's a simple mock credentials class you can work from.