Lots of mapreduce errors reported when backing up to Google Cloud Storage

[Marcel Manz]

We were migrating one of our applications from US to EU using Google Cloud Storage as backup destination and noticed that LOTS of errors are reported during the backup process (the backup went fine though).

Most of the errors reported seem to be transaction collisions, which sounds strange to us as basically the application had no DataStore activity (with disabled writes) during the time we took the backup.

Below are some dashboard values of the ah-builtin-python-bundle, including one sample error:

Is this behaviour normal?

- Marcel

Current Load

URI	Req/Min current	Requests last 23 hrs	Runtime MCycles last hr	Avg Latency last hr
/_ah/mapreduce/worker_callback	26.0	15.30K	19489	20630 ms
/_ah/mapreduce/controller_callback	8.0	1.46K	169	1703 ms
/_ah/mapreduce/kickoffjob_callback	0.0	144
/_ah/mapreduce/finalizejob_callback	0.0	43	99	967 ms
/_ah/datastore_admin/	0.2	41	234	1269 ms
/_ah/datastore_admin/mapreduce_done	0.0	39	134	252 ms
/_ah/datastore_admin/static/css/compiled.css	0.0	15	46	394 ms
/_ah/mapreduce/detail	0.0	14
/_ah/datastore_admin/static/js/compiled.js	0.0	14	32	1659 ms
/_ah/datastore_admin/static/img/help.gif	0.0	14	31	576 ms
/_ah/mapreduce/command/get_job_detail	0.0	13	136	298 ms
/_ah/mapreduce/status.js	0.0	5
/_ah/mapreduce/jquery.js	0.0	5	16	446 ms
/_ah/mapreduce/jquery-json.js	0.0	5	152	2089 ms
/_ah/mapreduce/base.css	0.0	5	24	187 ms
/_ah/datastore_admin/backup.do	0.0	4
/_ah/mapreduce/status	0.0	2	44	3582 ms
/_ah/mapreduce/command/list_configs	0.0	2	0	69 ms
/_ah/datastore_admin/queue/deferred	0.0	2
/_ah/datastore_admin	0.0	2

Errors

URI	Count	% Errors last 23 hrs
/_ah/mapreduce/worker_callback	10292	67%
/_ah/mapreduce/controller_callback	450	31%
/_ah/mapreduce/kickoffjob_callback	106	74%
/_ah/mapreduce/finalizejob_callback	14	33%
/_ah/datastore_admin/mapreduce_done	10	26%
/img/icn/warning.png	2
/_ah/mapreduce/base.css	1	20%
/_ah/mapreduce/detail	1	7.1%
/_ah/datastore_admin/static/img/help.gif	1	7.1%
/_ah/datastore_admin/static/css/compiled.css	1	6.7%

© 2008 Google | Terms of Service | Privacy Policy | Blog | Discussion Forums | Project | Docs

1. 1. 2012-11-23 10:02:11.495 /_ah/mapreduce/worker_callback 500 38690ms 1kb AppEngine-Google; (+http://code.google.com/appengine)

      0.1.0.2 - - [23/Nov/2012:02:02:11 -0800] "POST /_ah/mapreduce/worker_callback HTTP/1.1" 500 1399 "http://ah-builtin-python-bundle-dot-latest-dot-NAMEHERE.appspot.com/_ah/mapreduce/worker_callback" "AppEngine-Google; (+http://code.google.com/appengine)" "ah-builtin-python-bundle-dot-latest-dot-NAMEHERE.appspot.com" ms=38690 cpu_ms=24181 cpm_usd=0.000156 queue_name=default task_name=appengine-mrshard-158262053854451F422C9-0-1 instance=00c61b117c40497530af9f0d75b7a691d84a4813

   2. D 2012-11-23 10:01:34.969

      Could not import map from google.appengine.ext.datastore_admin.backup_handler.BackupEntity. Will try recursively.
      Traceback (most recent call last):
        File "/base/python_runtime/python_lib/versions/1/google/appengine/ext/mapreduce/util.py", line 98, in for_name
          result = __import__(module_name, None, None, [short_name])
      ImportError: No module named BackupEntity

   3. W 2012-11-23 10:01:55.500

      Transaction collision. Retrying... 

   4. W 2012-11-23 10:02:01.893

      Transaction collision. Retrying... 

   5. W 2012-11-23 10:02:05.847

      Transaction collision. Retrying... 

   6. W 2012-11-23 10:02:11.091

      Transaction collision. Retrying... 

   7. E 2012-11-23 10:02:11.391

      The transaction could not be committed. Please try again.
      Traceback (most recent call last):
        File "/base/python_runtime/python_lib/versions/1/google/appengine/ext/webapp/_webapp25.py", line 712, in __call__
          handler.post(*groups)
        File "/base/python_runtime/python_lib/versions/1/google/appengine/ext/mapreduce/base_handler.py", line 81, in post
          self.handle()
        File "/base/python_runtime/python_lib/versions/1/google/appengine/ext/mapreduce/handlers.py", line 223, in handle
          ctx.flush()
        File "/base/python_runtime/python_lib/versions/1/google/appengine/ext/mapreduce/context.py", line 348, in flush
          pool.flush()
        File "/base/python_runtime/python_lib/versions/1/google/appengine/ext/datastore_admin/backup_handler.py", line 1461, in flush
          db.run_in_transaction(tx)
        File "/base/python_runtime/python_lib/versions/1/google/appengine/api/datastore.py", line 2433, in RunInTransaction
          return RunInTransactionOptions(None, function, *args, **kwargs)
        File "/base/python_runtime/python_lib/versions/1/google/appengine/api/datastore.py", line 2579, in RunInTransactionOptions
          'The transaction could not be committed. Please try again.')
      TransactionFailedError: The transaction could not be committed. Please try again.

[Marcel Manz]

Few more concerning issues we've seen in this regard.

Why should the GAE backup process exceed any limits here?

1. 2012-11-23 12:09:59.114 /_ah/mapreduce/worker_callback 500 18339ms 2kb AppEngine-Google; (+http://code.google.com/appengine)0.1.0.2 - - [23/Nov/2012:04:09:59 -0800] "POST /_ah/mapreduce/worker_callback HTTP/1.1" 500 2592 "http://ah-builtin-python-bundle-dot-latest-dot.appspot.com/_ah/mapreduce/worker_callback" "AppEngine-Google; (+http://code.google.com/appengine)" "ah-builtin-python-bundle-dot-latest-dot.appspot.com" ms=18339 cpu_ms=16769 cpm_usd=0.000290 queue_name=default task_name=appengine-mrshard-158262053021454DD84AC-1-13 instance=00c61b117c34c5634e86dc85a5e55323018ab2
   1. D 2012-11-23 12:09:40.919

1. 1. Could not import map from google.appengine.ext.datastore_admin.backup_handler.BackupEntity. Will try recursively.
      Traceback (most recent call last):
        File "/base/python_runtime/python_lib/versions/1/google/appengine/ext/mapreduce/util.py", line 98, in for_name
          result = __import__(module_name, None, None, [short_name])
      ImportError: No module named BackupEntity

1. 1. 
      E 2012-11-23 12:09:59.028

      string property entity_type_info is too long.  It cannot exceed 1000000 characters.

1. 1. Traceback (most recent call last):
        File "/base/python_runtime/python_lib/versions/1/google/appengine/ext/webapp/_webapp25.py", line 712, in __call__
          handler.post

1. 1. (*groups)
        File "/base/python_runtime/python_lib/versions/1/google/appengine/ext/mapreduce/base_handler.py", line 81, in post
          self.handle()
        File "/base/python_runtime/python_lib/versions/1/google/appengine/ext/mapreduce/handlers.py", line 223, in handle
          ctx.flush()
        File "/base/python_runtime/python_lib/versions/1/google/appengine/ext/mapreduce/context.py", line 348, in flush
          pool.flush()
        File "/base/python_runtime/python_lib/versions/1/google/appengine/ext/datastore_admin/backup_handler.py", line 1461, in flush
          db.run_in_transaction(tx)
        File "/base/python_runtime/python_lib/versions/1/google/appengine/api/datastore.py", line 2433, in RunInTransaction
          return RunInTransactionOptions(None, function, *args, **kwargs)
        File "/base/python_runtime/python_lib/versions/1/google/appengine/api/datastore.py", line 2571, in RunInTransactionOptions
          ok, result = _DoOneTry(new_connection, function, args, kwargs)
        File "/base/python_runtime/python_lib/versions/1/google/appengine/api/datastore.py", line 2593, in _DoOneTry
          result = function(*args, **kwargs)
        File "/base/python_runtime/python_lib/versions/1/google/appengine/ext/datastore_admin/backup_handler.py", line 1457, in tx
          aggregation.put(force_writes=True)
        File "/base/python_runtime/python_lib/versions/1/google/appengine/ext/db/__init__.py", line 1074, in put
          return datastore.Put(self._entity, **kwargs)
        File "/base/python_runtime/python_lib/versions/1/google/appengine/api/datastore.py", line 579, in Put
          return PutAsync(entities, **kwargs).get_result()
        File "/base/python_runtime/python_lib/versions/1/google/appengine/api/apiproxy_stub_map.py", line 604, in get_result
          return self.__get_result_hook(self)
        File "/base/python_runtime/python_lib/versions/1/google/appengine/datastore/datastore_rpc.py", line 1569, in __put_hook
          self.check_rpc_success(rpc)
        File "/base/python_runtime/python_lib/versions/1/google/appengine/datastore/datastore_rpc.py", line 1224, in check_rpc_success
          raise _ToDatastoreError(err)
      BadRequestError: string property entity_type_info is too long.  It cannot exceed 1000000 characters.
      
      

   2. 2012-11-23 12:09:54.845 /_ah/mapreduce/worker_callback 500 22865ms 2kb AppEngine-Google; (+http://code.google.com/appengine)0.1.0.2 - - [23/Nov/2012:04:09:54 -0800] "POST /_ah/mapreduce/worker_callback HTTP/1.1" 500 2875 "http://ah-builtin-python-bundle-dot-latest-dot.appspot.com/_ah/mapreduce/worker_callback" "AppEngine-Google; (+http://code.google.com/appengine)" "ah-builtin-python-bundle-dot-latest-dot.appspot.com" ms=22865 cpu_ms=15340 cpm_usd=0.000321 queue_name=default task_name=appengine-mrshard-158262053021454DD84AC-20-9 instance=00c61b117cbbc7d880c5bc39716fdc80406d5e8c
      D 2012-11-23 12:09:32.674

1. 1. 1. Could not import map from google.appengine.ext.datastore_admin.backup_handler.BackupEntity. Will try recursively.
         Traceback (most recent call last):
           File "/base/python_runtime/python_lib/versions/1/google/appengine/ext/mapreduce/util.py", line 98, in for_name
             result = __import__(module_name, None, None, [short_name])
         ImportError: No module named BackupEntity

1. 1. 1. E 2012-11-23 12:09:52.330

         The request to API call datastore_v3.Put() was too large.

1. 1. 1. Traceback (most recent call last):
           File "/base/python_runtime/python_lib/versions/1/google/appengine/ext/webapp/_webapp25.py", line 712, in __call__
             handler.post

1. 1. 1. (*groups)
           File "/base/python_runtime/python_lib/versions/1/google/appengine/ext/mapreduce/base_handler.py", line 81, in post
             self.handle()
           File "/base/python_runtime/python_lib/versions/1/google/appengine/ext/mapreduce/handlers.py", line 223, in handle
             ctx.flush()
           File "/base/python_runtime/python_lib/versions/1/google/appengine/ext/mapreduce/context.py", line 348, in flush
             pool.flush()
           File "/base/python_runtime/python_lib/versions/1/google/appengine/ext/datastore_admin/backup_handler.py", line 1461, in flush
             db.run_in_transaction(tx)
           File "/base/python_runtime/python_lib/versions/1/google/appengine/api/datastore.py", line 2433, in RunInTransaction
             return RunInTransactionOptions(None, function, *args, **kwargs)
           File "/base/python_runtime/python_lib/versions/1/google/appengine/api/datastore.py", line 2571, in RunInTransactionOptions
             ok, result = _DoOneTry(new_connection, function, args, kwargs)
           File "/base/python_runtime/python_lib/versions/1/google/appengine/api/datastore.py", line 2593, in _DoOneTry
             result = function(*args, **kwargs)
           File "/base/python_runtime/python_lib/versions/1/google/appengine/ext/datastore_admin/backup_handler.py", line 1457, in tx
             aggregation.put(force_writes=True)
           File "/base/python_runtime/python_lib/versions/1/google/appengine/ext/db/__init__.py", line 1074, in put
             return datastore.Put(self._entity, **kwargs)
           File "/base/python_runtime/python_lib/versions/1/google/appengine/api/datastore.py", line 579, in Put
             return PutAsync(entities, **kwargs).get_result()
           File "/base/python_runtime/python_lib/versions/1/google/appengine/api/apiproxy_stub_map.py", line 604, in get_result
             return self.__get_result_hook(self)
           File "/base/python_runtime/python_lib/versions/1/google/appengine/datastore/datastore_rpc.py", line 1569, in __put_hook
             self.check_rpc_success(rpc)
           File "/base/python_runtime/python_lib/versions/1/google/appengine/datastore/datastore_rpc.py", line 1222, in check_rpc_success
             rpc.check_success()
           File "/base/python_runtime/python_lib/versions/1/google/appengine/api/apiproxy_stub_map.py", line 570, in check_success
             self.__rpc.CheckSuccess()
           File "/base/python_runtime/python_lib/versions/1/google/appengine/api/apiproxy_rpc.py", line 133, in CheckSuccess
             raise self.exception
         RequestTooLargeError: The request to API call datastore_v3.Put() was too large.

[Marcel Manz]

Looks like the GAE backup process to Google Storage is in fact broken. We had issues backing up certain kinds that contain entities with a large amount of properties (the backup at some point simply stalls and stays pending without any further activity).

In the end we could only successfully transfer the data by installing the python Datastore-Admin remote-api in order to copy the data between our Java apps.

See issues:

http://code.google.com/p/googleappengine/issues/detail?id=8379

http://code.google.com/p/googleappengine/issues/detail?id=8363

- Marcel

[Arie Ozarov]

As indicated in issue 8363 this may happen when backing-up kinds with very large number of properties (and only when using Google Cloud Storage).

The issue will be fixed in an upcoming release.