Firestore: invalid metadata error with grpcio 1.8.0 works with 1.7.3

[szferi]

The last update of grpcio 1.8.0 makes the firestore service fail with the following trace:

E1213 10:00:33.957789953    5598 ev_epollex_linux.cc:1482]   Skipping epollex becuase GRPC_LINUX_EPOLL is not defined.
E1213 10:00:33.957804187    5598 ev_epoll1_linux.cc:1261]    Skipping epoll1 becuase GRPC_LINUX_EPOLL is not defined.
E1213 10:00:33.957817171    5598 ev_epollsig_linux.cc:1761]  Skipping epollsig becuase GRPC_LINUX_EPOLL is not defined.
TypeError: Expected str, got unicode
Exception TypeError: 'Expected str, got unicode' in 'grpc._cython.cygrpc._store_c_metadata' ignored
E1213 10:00:33.959709563    5598 call.cc:1001]               validate_metadata: {"created":"@1513155633.959693129","description":"Metadata keys cannot be zero length","file":"src/core/lib/surface/validate_metadata.cc","file_line":66}
Traceback (most recent call last):
  File "t.py", line 11, in <module>
    db.collection('foo').document('foo').set({'foo': 'bar'})
  File "/home/szferi/envs/navega2/local/lib/python2.7/site-packages/google/cloud/firestore_v1beta1/document.py", line 224, in set
    write_results = batch.commit()
  File "/home/szferi/envs/navega2/local/lib/python2.7/site-packages/google/cloud/firestore_v1beta1/batch.py", line 135, in commit
    transaction=None, options=self._client._call_options)
  File "/home/szferi/envs/navega2/local/lib/python2.7/site-packages/google/cloud/firestore_v1beta1/gapic/firestore_client.py", line 851, in commit
    return self._commit(request, options)
  File "/home/szferi/envs/navega2/local/lib/python2.7/site-packages/google/gax/api_callable.py", line 452, in inner
    return api_caller(api_call, this_settings, request)
  File "/home/szferi/envs/navega2/local/lib/python2.7/site-packages/google/gax/api_callable.py", line 438, in base_caller
    return api_call(*args)
  File "/home/szferi/envs/navega2/local/lib/python2.7/site-packages/google/gax/api_callable.py", line 376, in inner
    return a_func(*args, **kwargs)
  File "/home/szferi/envs/navega2/local/lib/python2.7/site-packages/google/gax/retry.py", line 68, in inner
    return a_func(*updated_args, **kwargs)
  File "/home/szferi/envs/navega2/local/lib/python2.7/site-packages/grpc/_channel.py", line 484, in __call__
    credentials)
  File "/home/szferi/envs/navega2/local/lib/python2.7/site-packages/grpc/_channel.py", line 477, in _blocking
    _check_call_error(call_error, metadata)
  File "/home/szferi/envs/navega2/local/lib/python2.7/site-packages/grpc/_channel.py", line 86, in _check_call_error
    raise ValueError('metadata was invalid: %s' % metadata)
ValueError: metadata was invalid: [('google-cloud-resource-prefix', u'projects/platform-dev-187006/databases/(default)'), (u'x-goog-api-client', 'gl-python/2.7.13 gccl/0.28.0 gapic/0.28.0 gax/0.15.16 grpc/1.8.0')]

If I downgrade it to 1.7.3 it works just fine.

OS type and version

Linux, Ubuntu 17.04

Python version and virtual environment information python --version

Python 2.7.13

Relevant package versions

google-api-core==0.1.2
google-auth==1.2.1
google-cloud-core==0.28.0
google-cloud-firestore==0.28.0
google-cloud-storage==1.6.0
google-gax==0.15.16
google-resumable-media==0.3.1
googleapis-common-protos==1.5.3
grpcio==1.8.0
firebase-admin==2.6.0

Code example

import firebase_admin
from firebase_admin import credentials
from firebase_admin import firestore

fb_cred = credentials.Certificate('./platform-dev-service-account.json')    
firebase_admin.initialize_app(fb_cred)
db = firestore.client()
db.collection('foo').document('foo').set({'foo': 'bar'})

[cpavon]

Same problem using google-cloud-datastore.
Downgrade to 1.7.3 also works.

[bcoghe]

same problem, same solution

[kmaillet]

Same here with google-cloud-datastore. Same fix

[igorpeshansky]

This is an issue with api_core/core, and seems to have been triggered by #4280 allowing a broken dependency in.

[dhermes]

@igorpeshansky Not quite. It's caused by the 1.8.0 release of grpcio breaking the way it accepts request metadata (which amounts to the equivalent of an HTTP header). The reason it just cropped up is because grpcio==1.8.0 was released last night.

[bmoyles0117]

Will that change be rolled back as a result? Or is this intended behavior?

[igorpeshansky]

@dhermes Right, 1.8.0 was the broken dependency... Can we restrict the version at 1.7.3 as a temporary fix, while grpcio gets their fix out?

[dhermes]

@igorpeshansky That won't help the already released versions, but depending on how difficult the fix is, that may be the best choice. I'm at lunch right now but hope to be able to address this soon.

[r00tat]

I've also opened a issue on the grpc github project before I found this issue. According to the issue #13752 this are the relevant code changes

[r00tat]

grpcio 1.8.0 is temporarily disabled on PyPI

[dhermes]

I am going to close this since 1.8.1 reverted the problematic change.

[sawgataroy]

facing above same issue after upgraded to 1.8.1 yesterday
ev_epollex_linux.cc:1482] Skipping epollex becuase GRPC_LINUX_EPOLL is not defined

[dhermes]

@sawgataroy That's just a stray logging message from grpcio. Do you have any actual crash / stacktrace?

[jackiosport]

Hey, I also have this issue for data store when I deploy my project to Google App Engine (even after changing to 1.8.1). However when I run locally, there seems to be no problems. Was a long term solution reached for this problem? Many thanks.

[dhermes]

@jackiosport Are you talking about the issue reported in this bug or the issue in @sawgataroy's comment about a stray logging statement?

[jackiosport]

@dhermes I don't believe it is just a stray logging statement. I cannot re-create the error locally (I run in a virtual env with the same requirements.txt,), but when I deploy my project to Google App Engine. I get this in the logs:
2017-12-20 16:26:27.000 GMT E1220 16:26:27.496184865 9 ev_epollex_linux.cc:1482] Skipping epollex becuase GRPC_LINUX_EPOLL is not defined.

Which seems to correspond to a HTTP 502 error. Perhaps the google docker is using the broken grpcio. Any suggestions would be useful, I am a bit stumped.

[dhermes]

No, it doesn't correspond to an error, it's just what grpcio logs when a channel is defined. I don't think it should be logging this without a user turning on logging, but it's not a sign of any breakage.

This issue refers to a different breakage regarding user metadata.

[foresmac]

@dhermes FWIW, I'm getting the same stuff dumped to stdout when I create a client locally or within a delian-based container.

E1220 10:22:50.073753000 140736194212800 ev_epollex_linux.cc:1482]     Skipping epollex becuase GRPC_LINUX_EPOLL is not defined.
E1220 10:22:50.073786000 140736194212800 ev_epoll1_linux.cc:1261]      Skipping epoll1 becuase GRPC_LINUX_EPOLL is not defined.
E1220 10:22:50.073791000 140736194212800 ev_epollsig_linux.cc:1761]    Skipping epollsig becuase GRPC_LINUX_EPOLL is not defined.

As noted, it doesn't appear to be an actual error, but it was frustrating trying to figure out if it actually was a problem or not. Should I (or someone) make a report on the grpcio repo?

[jackiosport]

@dhermes thanks for your reply. I must have associated this message with another unrelated error which occurred at the same time. A case of correlation does not imply causation! This helps me rule out where the bug is. Thanks, Jack.

[dhermes]

Should I (or someone) make a report on the grpcio repo?

Sure thing, here is a link

[dhermes]

Note that the newly discussed issue (brought up by @sawgataroy and reiterated by @jackiosport) about the logging about GRPC_LINUX_EPOLL was raised as a separate issue in #4650.

To address it, I have filed: grpc/grpc#13855

[foresmac]

Thanks for opening the issue @dhermes.