Datastore local testing issues and fixes

[txomon]

Following #1822, I have been focusing on datastore testing, and found the following errors.

Test environment

I am using the following script:

from gcloud import datastore

client = datastore.Client()
entity = datastore.Entity(client.key('Test1'))
client.put(entity)

I have checked in python3.4 and python2.7, and it can be reproduced.

I suspect the error is in datastore emulator rather than in gcloud python, although I think it triggers an exception that shouldn't happen in datastore.

Setting up environment

To trigger it, you need to have 2 configurations (gcloud config configurations) pointing to two different projects:

• Activate configuration 1 (test-suite) gcloud config configurations activate test-suite
• Run gcloud beta emulators datastore start
• Stop it
• Activate configuration 2 (mos-history) gcloud config configurations activate mos-history
• Run gcloud beta emulators datastore start
• Run the script

Show case

When starting in a changed config environment (activated another configuration), we can find the following error:

(ve2) javier@theoden:~/projects/spinoffs/gae$ python test-script.py                                      
Traceback (most recent call last):
  File "test-script.py", line 5, in <module>
    client.put(entity)
  File "/home/javier/projects/spinoffs/gae/ve2/lib/python2.7/site-packages/gcloud/datastore/client.py", line 319, in put
    self.put_multi(entities=[entity])
  File "/home/javier/projects/spinoffs/gae/ve2/lib/python2.7/site-packages/gcloud/datastore/client.py", line 345, in put_multi
    current.commit()
  File "/home/javier/projects/spinoffs/gae/ve2/lib/python2.7/site-packages/gcloud/datastore/batch.py", line 260, in commit
    self._commit()
  File "/home/javier/projects/spinoffs/gae/ve2/lib/python2.7/site-packages/gcloud/datastore/batch.py", line 243, in _commit
    self.project, self._commit_request, self._id)
  File "/home/javier/projects/spinoffs/gae/ve2/lib/python2.7/site-packages/gcloud/datastore/connection.py", line 331, in commit
    _datastore_pb2.CommitResponse)
  File "/home/javier/projects/spinoffs/gae/ve2/lib/python2.7/site-packages/gcloud/datastore/connection.py", line 121, in _rpc
    data=request_pb.SerializeToString())
  File "/home/javier/projects/spinoffs/gae/ve2/lib/python2.7/site-packages/gcloud/datastore/connection.py", line 97, in _request
    error_status = status_pb2.Status.FromString(content)
  File "/home/javier/projects/spinoffs/gae/ve2/lib/python2.7/site-packages/google/protobuf/internal/python_message.py", line 780, in FromString
    message.MergeFromString(s)
  File "/home/javier/projects/spinoffs/gae/ve2/lib/python2.7/site-packages/google/protobuf/internal/python_message.py", line 1080, in MergeFromString
    if self._InternalParse(serialized, 0, length) != length:
  File "/home/javier/projects/spinoffs/gae/ve2/lib/python2.7/site-packages/google/protobuf/internal/python_message.py", line 1106, in InternalParse
    new_pos = local_SkipField(buffer, new_pos, end, tag_bytes)
  File "/home/javier/projects/spinoffs/gae/ve2/lib/python2.7/site-packages/google/protobuf/internal/decoder.py", line 850, in SkipField
    return WIRETYPE_TO_SKIPPER[wire_type](buffer, pos, end)
  File "/home/javier/projects/spinoffs/gae/ve2/lib/python2.7/site-packages/google/protobuf/internal/decoder.py", line 820, in _RaiseInvalidWireType
    raise _DecodeError('Tag had invalid wire type.')
google.protobuf.message.DecodeError: Tag had invalid wire type.

With the following datastore emulator output:

javier@theoden ~/p/s/gae> gcloud beta emulators datastore start
WARNING: Reusing existing data in [/home/javier/.config/gcloud/emulators/datastore].
Executing: /opt/google-cloud-sdk/platform/gcd/gcd.sh start --host=localhost --port=8572 --store_on_disk=True --consistency=0.9 --allow_remote_shutdown /home/javier/.config/gcloud/emulators/datastore
[datastore] API endpoint: http://localhost:8572/datastore
[datastore] If you are using a library that supports the DATASTORE_LOCAL_HOST environment variable, run:
[datastore] 
[datastore]   export DATASTORE_LOCAL_HOST=localhost:8572
[datastore] 
[datastore] Invoking dev_appserver with args: [--disable_update_check --jvm_flag=-Doauth.is_admin=true --property=datastore.index_configuration_format=yaml --port=8572 --address=localhost --property=datastore.force_is_high_replication=true --property=datastore.default_high_rep_job_policy_unapplied_job_pct=10.0 --allow_remote_shutdown /home/javier/.config/gcloud/emulators/datastore].
[datastore] Executing [/usr/lib/jvm/java-8-jdk/jre/bin/java, -Doauth.is_admin=true, -javaagent:/opt/google-cloud-sdk/platform/gcd/.appengine/lib/agent/appengine-agent.jar, -Xbootclasspath/p:/opt/google-cloud-sdk/platform/gcd/.appengine/lib/override/appengine-dev-jdk-overrides.jar, -classpath, /opt/google-cloud-sdk/platform/gcd/CloudDatastore.jar:/opt/google-cloud-sdk/platform/gcd/.appengine/lib/impl/appengine-api.jar:/opt/google-cloud-sdk/platform/gcd/.appengine/lib/appengine-tools-api.jar:/opt/google-cloud-sdk/platform/gcd/.appengine/lib/impl/appengine-api-stubs.jar, com.google.appengine.tools.development.DevAppServerMain, --property=kickstart.user.dir=/home/javier/projects/spinoffs/gae, --disable_update_check, --property=datastore.index_configuration_format=yaml, --port=8572, --address=localhost, --property=datastore.force_is_high_replication=true, --property=datastore.default_high_rep_job_policy_unapplied_job_pct=10.0, --allow_remote_shutdown, /home/javier/.config/gcloud/emulators/datastore]
[datastore] May 31, 2016 9:32:02 PM com.google.apphosting.utils.jetty.JettyLogger info
[datastore] INFO: Logging to JettyLogger(null) via com.google.apphosting.utils.jetty.JettyLogger
[datastore] May 31, 2016 9:32:02 PM com.google.appengine.tools.development.DevAppServerImpl setServerTimeZone
[datastore] WARNING: Unable to set the TimeZone to UTC (this is expected if running on JDK 8)
[datastore] May 31, 2016 9:32:02 PM com.google.apphosting.utils.jetty.JettyLogger info
[datastore] INFO: jetty-6.1.x
[datastore] May 31, 2016 9:32:02 PM com.google.apphosting.utils.jetty.JettyLogger info
[datastore] INFO: Started SelectChannelConnector@localhost:8572
[datastore] May 31, 2016 9:32:02 PM com.google.appengine.tools.development.AbstractModule startup
[datastore] INFO: Module instance default is running at http://localhost:8572/
[datastore] May 31, 2016 9:32:02 PM com.google.appengine.tools.development.AbstractModule startup
[datastore] INFO: The admin console is running at http://localhost:8572/_ah/admin
[datastore] May 31, 2016 9:32:02 PM com.google.appengine.tools.development.DevAppServerImpl doStart
[datastore] INFO: Dev App Server is now running
[datastore] May 31, 2016 9:32:22 PM com.google.appengine.tools.development.DevAppEngineWebAppContext disableTransportGuarantee
[datastore] INFO: Ignoring <transport-guarantee> for /datastore/* as the SDK does not support HTTPS.  It will still be used when you upload your application.
[datastore] May 31, 2016 9:32:22 PM com.google.apphosting.client.serviceapp.BaseApiServlet doPost
[datastore] INFO: Hosted project, test-suite, does not match requested project, mos-history.

Workaround

I have discovered that this if fixed by doing

rm -rf ~/.config/gcloud/emulators/datastore/

Running perfect after the datastore purge

javier@theoden ~/p/s/gae> gcloud beta emulators datastore start
Executing: /opt/google-cloud-sdk/platform/gcd/gcd.sh create --project_id=mos-history /home/javier/.config/gcloud/emulators/datastore
[datastore] Created new Cloud Datastore project in '/home/javier/.config/gcloud/emulators/datastore' with project ID 'mos-history'.
Executing: /opt/google-cloud-sdk/platform/gcd/gcd.sh start --host=localhost --port=8725 --store_on_disk=True --consistency=0.9 --allow_remote_shutdown /home/javier/.config/gcloud/emulators/datastore
[datastore] API endpoint: http://localhost:8725/datastore
[datastore] If you are using a library that supports the DATASTORE_LOCAL_HOST environment variable, run:
[datastore] 
[datastore]   export DATASTORE_LOCAL_HOST=localhost:8725
[datastore] 
[datastore] Invoking dev_appserver with args: [--disable_update_check --jvm_flag=-Doauth.is_admin=true --property=datastore.index_configuration_format=yaml --port=8725 --address=localhost --property=datastore.force_is_high_replication=true --property=datastore.default_high_rep_job_policy_unapplied_job_pct=10.0 --allow_remote_shutdown /home/javier/.config/gcloud/emulators/datastore].
[datastore] Executing [/usr/lib/jvm/java-8-jdk/jre/bin/java, -Doauth.is_admin=true, -javaagent:/opt/google-cloud-sdk/platform/gcd/.appengine/lib/agent/appengine-agent.jar, -Xbootclasspath/p:/opt/google-cloud-sdk/platform/gcd/.appengine/lib/override/appengine-dev-jdk-overrides.jar, -classpath, /opt/google-cloud-sdk/platform/gcd/CloudDatastore.jar:/opt/google-cloud-sdk/platform/gcd/.appengine/lib/impl/appengine-api.jar:/opt/google-cloud-sdk/platform/gcd/.appengine/lib/appengine-tools-api.jar:/opt/google-cloud-sdk/platform/gcd/.appengine/lib/impl/appengine-api-stubs.jar, com.google.appengine.tools.development.DevAppServerMain, --property=kickstart.user.dir=/home/javier/projects/spinoffs/gae, --disable_update_check, --property=datastore.index_configuration_format=yaml, --port=8725, --address=localhost, --property=datastore.force_is_high_replication=true, --property=datastore.default_high_rep_job_policy_unapplied_job_pct=10.0, --allow_remote_shutdown, /home/javier/.config/gcloud/emulators/datastore]
[datastore] May 31, 2016 9:36:32 PM com.google.apphosting.utils.jetty.JettyLogger info
[datastore] INFO: Logging to JettyLogger(null) via com.google.apphosting.utils.jetty.JettyLogger
[datastore] May 31, 2016 9:36:32 PM com.google.appengine.tools.development.DevAppServerImpl setServerTimeZone
[datastore] WARNING: Unable to set the TimeZone to UTC (this is expected if running on JDK 8)
[datastore] May 31, 2016 9:36:32 PM com.google.apphosting.utils.jetty.JettyLogger info
[datastore] INFO: jetty-6.1.x
[datastore] May 31, 2016 9:36:33 PM com.google.apphosting.utils.jetty.JettyLogger info
[datastore] INFO: Started SelectChannelConnector@localhost:8725
[datastore] May 31, 2016 9:36:33 PM com.google.appengine.tools.development.AbstractModule startup
[datastore] INFO: Module instance default is running at http://localhost:8725/
[datastore] May 31, 2016 9:36:33 PM com.google.appengine.tools.development.AbstractModule startup
[datastore] INFO: The admin console is running at http://localhost:8725/_ah/admin
[datastore] May 31, 2016 9:36:33 PM com.google.appengine.tools.development.DevAppServerImpl doStart
[datastore] INFO: Dev App Server is now running
[datastore] May 31, 2016 9:36:50 PM com.google.appengine.tools.development.DevAppEngineWebAppContext disableTransportGuarantee
[datastore] INFO: Ignoring <transport-guarantee> for /datastore/* as the SDK does not support HTTPS.  It will still be used when you upload your application.
[datastore] May 31, 2016 9:36:50 PM com.google.appengine.api.datastore.dev.LocalDatastoreService init
[datastore] INFO: Local Datastore initialized:
[datastore]     Type: High Replication
[datastore]     Storage: /home/javier/.config/gcloud/emulators/datastore/WEB-INF/appengine-generated/local_db.bin
[datastore] May 31, 2016 9:36:50 PM com.google.appengine.api.datastore.dev.LocalDatastoreService load
[datastore] INFO: The backing store, /home/javier/.config/gcloud/emulators/datastore/WEB-INF/appengine-generated/local_db.bin, does not exist. It will be created.
[datastore] May 31, 2016 9:37:20 PM com.google.appengine.api.datastore.dev.LocalDatastoreService$PersistDatastore persist
[datastore] INFO: Time to persist datastore: 17 ms
[datastore] May 31, 2016 9:38:50 PM com.google.appengine.api.datastore.dev.LocalDatastoreService$PersistDatastore persist
[datastore] INFO: Time to persist datastore: 1 ms

The error probably comes from ~/.config/gcloud/emulators/datastore/WEB-INF/appengine-web.xml not getting updated properly.

Why does gcloud-python fail so cryptic is unknown to me.

Error 2

documented in #1839

[dhermes]

@txomon I don't see any mention of using $(gcloud beta emulators datastore start env-init) or export-ing the required environment variables. This seems to be a likely reason that you don't see the right app.

As for the credentials issue, can you file a separate issue so we don't get our streams crossed.

[txomon]

@dhermes that is done, I didn't put it here though. You can actually check that it's connecting in the logs

As for the credentials issue, ok!

[dhermes]

/cc @pcostell

[pcostell]

So I think there are really two issues here, though fixing either one should solve your issue.

1. Cloud Datastore emulator enforces one project per data-dir directory
2. Changing the gcloud config doesn't change the Cloud Datastore emulator directory

For (1) this should be fixed by the new emulator, which you can run with gcloud beta emulators datastore start --no-legacy

For (2) this looks like a bug, I'll dig into it. A workaround is to specify --data-dir, which changes where the data is written. You could then have two different data directories, one for each project.

[dhermes]

@pcostell Can we close this?