[2.2rc1] Failed to process message for node

[Andres Rodriguez]

2017-04-05 22:44:04 regiond: [info] 10.244.192.10 GET /MAAS/rpc/ HTTP/1.0 --> 200 OK (referrer: -; agent: provisioningserver.rpc.clusterservice.ClusterClientService)
2017-04-05 22:44:04 metadataserver.api_twisted: [critical] Failed to process status message instantly.

Traceback (most recent call last):
  File "/usr/lib/python3.5/threading.py", line 862, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/lib/python3/dist-packages/provisioningserver/utils/twisted.py", line 830, in worker
    return target()
  File "/usr/lib/python3/dist-packages/twisted/_threads/_threadworker.py", line 46, in work
    task()
  File "/usr/lib/python3/dist-packages/twisted/_threads/_team.py", line 190, in doWork
    task()
--- <exception caught here> ---
  File "/usr/lib/python3/dist-packages/twisted/python/threadpool.py", line 246, in inContext
    result = inContext.theWork()
  File "/usr/lib/python3/dist-packages/twisted/python/threadpool.py", line 262, in <lambda>
    inContext.theWork = lambda: context.call(ctx, func, *args, **kw)
  File "/usr/lib/python3/dist-packages/twisted/python/context.py", line 118, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/usr/lib/python3/dist-packages/twisted/python/context.py", line 81, in callWithContext
    return func(*args,**kw)
  File "/usr/lib/python3/dist-packages/provisioningserver/utils/twisted.py", line 863, in callInContext
    return func(*args, **kwargs)
  File "/usr/lib/python3/dist-packages/provisioningserver/utils/twisted.py", line 231, in wrapper
    result = func(*args, **kwargs)
  File "/usr/lib/python3/dist-packages/maasserver/utils/orm.py", line 686, in call_within_transaction
    return func_outside_txn(*args, **kwargs)
  File "/usr/lib/python3/dist-packages/maasserver/utils/orm.py", line 517, in retrier
    return func(*args, **kwargs)
  File "/usr/lib/python3.5/contextlib.py", line 30, in inner
    return func(*args, **kwds)
  File "/usr/lib/python3/dist-packages/metadataserver/api_twisted.py", line 354, in _processMessageNow
    return self._processMessage(node, message)
  File "/usr/lib/python3/dist-packages/maasserver/utils/orm.py", line 670, in call_within_transaction
    return func_within_txn(*args, **kwargs)
  File "/usr/lib/python3.5/contextlib.py", line 30, in inner
    return func(*args, **kwds)
  File "/usr/lib/python3/dist-packages/metadataserver/api_twisted.py", line 291, in _processMessage
    script_set.save()
  File "/usr/lib/python3/dist-packages/maasserver/models/cleansave.py", line 29, in save
    return super(CleanSave, self).save(*args, **kwargs)
  File "/usr/lib/python3/dist-packages/django/db/models/base.py", line 734, in save
    force_update=force_update, update_fields=update_fields)
  File "/usr/lib/python3/dist-packages/django/db/models/base.py", line 762, in save_base
    updated = self._save_table(raw, cls, force_insert, force_update, using, update_fields)
  File "/usr/lib/python3/dist-packages/django/db/models/base.py", line 827, in _save_table
    forced_update)
  File "/usr/lib/python3/dist-packages/django/db/models/base.py", line 877, in _do_update
    return filtered._update(values) > 0
  File "/usr/lib/python3/dist-packages/django/db/models/query.py", line 580, in _update
    return query.get_compiler(self.db).execute_sql(CURSOR)
  File "/usr/lib/python3/dist-packages/django/db/models/sql/compiler.py", line 1062, in execute_sql
    cursor = super(SQLUpdateCompiler, self).execute_sql(result_type)
  File "/usr/lib/python3/dist-packages/django/db/models/sql/compiler.py", line 840, in execute_sql
    cursor.execute(sql, params)
  File "/usr/lib/python3/dist-packages/django/db/backends/utils.py", line 64, in execute
    return self.cursor.execute(sql, params)
  File "/usr/lib/python3/dist-packages/django/db/utils.py", line 98, in __exit__
    six.reraise(dj_exc_type, dj_exc_value, traceback)
  File "/usr/lib/python3/dist-packages/django/utils/six.py", line 685, in reraise
    raise value.with_traceback(tb)
  File "/usr/lib/python3/dist-packages/django/db/backends/utils.py", line 64, in execute
    return self.cursor.execute(sql, params)
django.db.utils.OperationalError: could not serialize access due to concurrent update

============================

2017-04-05 22:46:45 regiond: [info] 10.244.240.86 POST /MAAS/metadata/2012-03-01/ HTTP/1.1 --> 409 CONFLICT (referrer: -; agent: Python-urllib/3.5)
2017-04-05 22:46:57 regiond: [info] 10.244.240.86 POST /MAAS/metadata/2012-03-01/ HTTP/1.1 --> 200 OK (referrer: -; agent: Python-urllib/3.5)
2017-04-05 22:46:57 metadataserver.api_twisted: [critical] Failed to process message for node: zygarde

Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/twisted/python/context.py", line 118, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/usr/lib/python3/dist-packages/twisted/python/context.py", line 81, in callWithContext
    return func(*args,**kw)
  File "/usr/lib/python3/dist-packages/provisioningserver/utils/twisted.py", line 863, in callInContext
    return func(*args, **kwargs)
  File "/usr/lib/python3/dist-packages/provisioningserver/utils/twisted.py", line 231, in wrapper
    result = func(*args, **kwargs)
--- <exception caught here> ---
  File "/usr/lib/python3/dist-packages/metadataserver/api_twisted.py", line 230, in _processMessages
    self._processMessage(node, message)
  File "/usr/lib/python3/dist-packages/maasserver/utils/orm.py", line 686, in call_within_transaction
    return func_outside_txn(*args, **kwargs)
  File "/usr/lib/python3/dist-packages/maasserver/utils/orm.py", line 517, in retrier
    return func(*args, **kwargs)
  File "/usr/lib/python3.5/contextlib.py", line 30, in inner
    return func(*args, **kwds)
  File "/usr/lib/python3/dist-packages/metadataserver/api_twisted.py", line 291, in _processMessage
    script_set.save()
  File "/usr/lib/python3/dist-packages/maasserver/models/cleansave.py", line 29, in save
    return super(CleanSave, self).save(*args, **kwargs)
  File "/usr/lib/python3/dist-packages/django/db/models/base.py", line 734, in save
    force_update=force_update, update_fields=update_fields)
  File "/usr/lib/python3/dist-packages/django/db/models/base.py", line 762, in save_base
    updated = self._save_table(raw, cls, force_insert, force_update, using, update_fields)
  File "/usr/lib/python3/dist-packages/django/db/models/base.py", line 827, in _save_table
    forced_update)
  File "/usr/lib/python3/dist-packages/django/db/models/base.py", line 877, in _do_update
    return filtered._update(values) > 0
  File "/usr/lib/python3/dist-packages/django/db/models/query.py", line 580, in _update
    return query.get_compiler(self.db).execute_sql(CURSOR)
  File "/usr/lib/python3/dist-packages/django/db/models/sql/compiler.py", line 1062, in execute_sql
    cursor = super(SQLUpdateCompiler, self).execute_sql(result_type)
  File "/usr/lib/python3/dist-packages/django/db/models/sql/compiler.py", line 840, in execute_sql
    cursor.execute(sql, params)
  File "/usr/lib/python3/dist-packages/django/db/backends/utils.py", line 64, in execute
    return self.cursor.execute(sql, params)
  File "/usr/lib/python3/dist-packages/django/db/utils.py", line 98, in __exit__
    six.reraise(dj_exc_type, dj_exc_value, traceback)
  File "/usr/lib/python3/dist-packages/django/utils/six.py", line 685, in reraise
    raise value.with_traceback(tb)
  File "/usr/lib/python3/dist-packages/django/db/backends/utils.py", line 64, in execute
    return self.cursor.execute(sql, params)
django.db.utils.OperationalError: could not serialize access due to concurrent update

[Blake Rouse (blake-rouse)]

I believe this is wrapped in transactional. So that means this is failing after 10 times! That is crazy.

Need to verify that its wrapped in transactional first. But if it is then we have a real problem.

[Blake Rouse (blake-rouse)]

@transactional
def _processMessageNow(self, authorization, message):

It is wrapped in transactional... Maybe because it calls _processMessage that is also wrapped in transactional, but that path should work correctly.

[Gavin Panella (allenap)]

A separate failure I'm working on has a similar traceback involving list_cluster_nodes_power_parameters where the transaction fails after 10 retries.

My hunch is that something added to MAAS recently (weeks) is doing something like:

- Making frequent updates to many/all rows in a heavily-used table (e.g. Node).

- Holding transactions open for a long time.