[2.2rc1] Failed to process message for node

Bug #1680278 reported by Andres Rodriguez
10
This bug affects 2 people
Affects Status Importance Assigned to Milestone
MAAS
Fix Released
Critical
Blake Rouse

Bug Description

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

Related branches

Changed in maas:
importance: Undecided → Critical
milestone: none → 2.2.0rc2
description: updated
Revision history for this message
Blake Rouse (blake-rouse) wrote :

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.

Revision history for this message
Blake Rouse (blake-rouse) wrote :

@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.

Revision history for this message
Gavin Panella (allenap) wrote :

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.

Changed in maas:
status: New → Triaged
assignee: nobody → Blake Rouse (blake-rouse)
Revision history for this message
Andres Rodriguez (andreserl) wrote :
Changed in maas:
status: Triaged → In Progress
Changed in maas:
status: In Progress → Fix Committed
Changed in maas:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.