Activity log for bug #1843493

Date Who What changed Old value New value Message
2019-09-10 20:26:56 Pedro Guimarães bug added bug
2019-09-11 06:53:47 Pedro Guimarães description MAAS: 2.6.0 (7802-g59416a869-0ubuntu1~18.04.1) Whenever I boot multiple VM pods at the same time using "allocate" operation, I get some VMs failing with overall message on Juju as: 3 down pending bionic suitable availability zone for machine 3 not found Looking into MAAS source code, I can see decision on which pod will receive corresponding VM is done on method: https://github.com/maas/maas/blob/5fe288985249afedadf4656b595238856b13ce4d/src/maasserver/forms/pods.py#L726 Added more logs to the "except" statement and found out two types of errors: OperationalError and TransactionManagementError. I believe both errors correspond to a resource dispute on database, since error message is generally: "could not serialize access due to concurrent update", which is also documented on Postgres: https://www.postgresql.org/docs/9.1/transaction-iso.html Full traceback of OperationalError: Traceback (most recent call last): File "/usr/lib/python3/dist-packages/django/db/backends/utils.py", line 64, in execute return self.cursor.execute(sql, params) psycopg2.extensions.TransactionRollbackError: could not serialize access due to concurrent update The above exception was the direct cause of the following exception: Traceback (most recent call last): File "/usr/lib/python3/dist-packages/maasserver/forms/pods.py", line 745, in compose creation_type=NODE_CREATION_TYPE.DYNAMIC) File "/usr/lib/python3/dist-packages/maasserver/forms/pods.py", line 664, in compose return create_and_sync((requested_machine, result)) File "/usr/lib/python3/dist-packages/maasserver/forms/pods.py", line 606, in create_and_sync self.pod.sync_hints(pod_hints) File "/usr/lib/python3/dist-packages/maasserver/models/bmc.py", line 622, in sync_hints hints.save() File "/usr/lib/python3/dist-packages/maasserver/models/cleansave.py", line 252, in save return super(CleanSave, self).save(*args, **kwargs) File "/usr/lib/python3/dist-packages/django/db/models/base.py", line 808, in save force_update=force_update, update_fields=update_fields) File "/usr/lib/python3/dist-packages/django/db/models/base.py", line 838, in save_base updated = self._save_table(raw, cls, force_insert, force_update, using, update_fields) File "/usr/lib/python3/dist-packages/maasserver/models/cleansave.py", line 278, in _save_table update_fields=update_fields) File "/usr/lib/python3/dist-packages/django/db/models/base.py", line 905, in _save_table forced_update) File "/usr/lib/python3/dist-packages/django/db/models/base.py", line 955, in _do_update return filtered._update(values) > 0 File "/usr/lib/python3/dist-packages/django/db/models/query.py", line 664, in _update return query.get_compiler(self.db).execute_sql(CURSOR) File "/usr/lib/python3/dist-packages/django/db/models/sql/compiler.py", line 1204, in execute_sql cursor = super(SQLUpdateCompiler, self).execute_sql(result_type) File "/usr/lib/python3/dist-packages/django/db/models/sql/compiler.py", line 899, in execute_sql raise original_exception File "/usr/lib/python3/dist-packages/django/db/models/sql/compiler.py", line 889, in execute_sql cursor.execute(sql, params) File "/usr/lib/python3/dist-packages/maasserver/prometheus/middleware.py", line 21, in execute return super().execute(sql, params=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 94, 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 Full tracestack for TransactionManagementError (unformatted): 2019-09-10 20:13:12 maasserver.forms.pods: [info] Unable to format event {'log_logger': <LegacyLogger 'maasserver.forms.pods'>, 'log_level': <LogLevel=info>, 'log_namespace': 'maasserver.forms.pods', 'log_source': None, 'log_format': 'Traceback (most recent call last):\n File "/usr/lib/python3/dist-packages/maasserver/forms/pods.py", line 742, in compose\n log.info("ComposeMachineForPodsForm compose commit_forms: {}".format(form))\n File "/usr/lib/python3/dist-packages/django/utils/html.py", line 394, in <lambda>\n klass.__str__ = lambda self: mark_safe(klass_str(self))\n File "/usr/lib/python3/dist-packages/django/forms/forms.py", line 137, in __str__\n return self.as_table()\n File "/usr/lib/python3/dist-packages/django/forms/forms.py", line 285, in as_table\n errors_on_separate_row=False)\n File "/usr/lib/python3/dist-packages/django/forms/forms.py", line 240, in _html_output\n \'field\': six.text_type(bf),\n File "/usr/lib/python3/dist-packages/django/utils/html.py", line 394, in <lambda>\n klass.__str__ = lambda self: mark_safe(klass_str(self))\n File "/usr/lib/python3/dist-packages/django/forms/boundfield.py", line 41, in __str__\n return self.as_widget()\n File "/usr/lib/python3/dist-packages/django/forms/boundfield.py", line 127, in as_widget\n **kwargs\n File "/usr/lib/python3/dist-packages/django/forms/widgets.py", line 220, in render\n context = self.get_context(name, value, attrs)\n File "/usr/lib/python3/dist-packages/django/forms/widgets.py", line 665, in get_context\n context = super(Select, self).get_context(name, value, attrs)\n File "/usr/lib/python3/dist-packages/django/forms/widgets.py", line 627, in get_context\n context[\'widget\'][\'optgroups\'] = self.optgroups(name, context[\'widget\'][\'value\'], attrs)\n File "/usr/lib/python3/dist-packages/django/forms/widgets.py", line 575, in optgroups\n for index, (option_value, option_label) in enumerate(chain(self.choices)):\n File "/usr/lib/python3/dist-packages/django/forms/models.py", line 1139, in __iter__\n for obj in queryset:\n File "/usr/lib/python3/dist-packages/django/db/models/query.py", line 53, in __iter__\n results = compiler.execute_sql(chunked_fetch=self.chunked_fetch)\n File "/usr/lib/python3/dist-packages/django/db/models/sql/compiler.py", line 899, in execute_sql\n raise original_exception\n File "/usr/lib/python3/dist-packages/django/db/models/sql/compiler.py", line 889, in execute_sql\n cursor.execute(sql, params)\n File "/usr/lib/python3/dist-packages/maasserver/prometheus/middleware.py", line 21, in execute\n return super().execute(sql, params=params)\n File "/usr/lib/python3/dist-packages/django/db/backends/utils.py", line 59, in execute\n self.db.validate_no_broken_transaction()\n File "/usr/lib/python3/dist-packages/django/db/backends/base/base.py", line 448, in validate_no_broken_transaction\n "An error occurred in the current transaction. You can\'t "\ndjango.db.transaction.TransactionManagementError: An error occurred in the current transaction. You can\'t execute queries until the end of the \'atomic\' block.\n', 'log_time': 1568146392.1984248}: tuple index out of range 2019-09-10 20:13:12 maasserver.forms.pods: [info] ComposeMachineForPodsForm commit_forms Exception: An error occurred in the current transaction. You can't execute queries until the end of the 'atomic' block. MAAS: 2.6.0 (7802-g59416a869-0ubuntu1~18.04.1) Whenever I boot multiple VM pods at the same time using "allocate" operation, I get some VMs failing with overall message on Juju as: 3 down pending bionic suitable availability zone for machine 3 not found Looking into MAAS source code, I can see decision on which pod will receive corresponding VM is done on method: https://github.com/maas/maas/blob/5fe288985249afedadf4656b595238856b13ce4d/src/maasserver/forms/pods.py#L726 Added more logs to the "except" statement and found out we're throwing OperationalError. I believe it corresponds to a resource dispute on database, since error message is: "could not serialize access due to concurrent update", which is also documented on Postgres: https://www.postgresql.org/docs/9.1/transaction-iso.html Full traceback of OperationalError: Traceback (most recent call last):    File "/usr/lib/python3/dist-packages/django/db/backends/utils.py", line 64, in execute      return self.cursor.execute(sql, params)  psycopg2.extensions.TransactionRollbackError: could not serialize access due to concurrent update  The above exception was the direct cause of the following exception:  Traceback (most recent call last):    File "/usr/lib/python3/dist-packages/maasserver/forms/pods.py", line 745, in compose      creation_type=NODE_CREATION_TYPE.DYNAMIC)    File "/usr/lib/python3/dist-packages/maasserver/forms/pods.py", line 664, in compose      return create_and_sync((requested_machine, result))    File "/usr/lib/python3/dist-packages/maasserver/forms/pods.py", line 606, in create_and_sync      self.pod.sync_hints(pod_hints)    File "/usr/lib/python3/dist-packages/maasserver/models/bmc.py", line 622, in sync_hints      hints.save()    File "/usr/lib/python3/dist-packages/maasserver/models/cleansave.py", line 252, in save      return super(CleanSave, self).save(*args, **kwargs)    File "/usr/lib/python3/dist-packages/django/db/models/base.py", line 808, in save      force_update=force_update, update_fields=update_fields)    File "/usr/lib/python3/dist-packages/django/db/models/base.py", line 838, in save_base      updated = self._save_table(raw, cls, force_insert, force_update, using, update_fields)    File "/usr/lib/python3/dist-packages/maasserver/models/cleansave.py", line 278, in _save_table      update_fields=update_fields)    File "/usr/lib/python3/dist-packages/django/db/models/base.py", line 905, in _save_table      forced_update)    File "/usr/lib/python3/dist-packages/django/db/models/base.py", line 955, in _do_update      return filtered._update(values) > 0    File "/usr/lib/python3/dist-packages/django/db/models/query.py", line 664, in _update      return query.get_compiler(self.db).execute_sql(CURSOR)    File "/usr/lib/python3/dist-packages/django/db/models/sql/compiler.py", line 1204, in execute_sql      cursor = super(SQLUpdateCompiler, self).execute_sql(result_type)    File "/usr/lib/python3/dist-packages/django/db/models/sql/compiler.py", line 899, in execute_sql      raise original_exception    File "/usr/lib/python3/dist-packages/django/db/models/sql/compiler.py", line 889, in execute_sql      cursor.execute(sql, params)    File "/usr/lib/python3/dist-packages/maasserver/prometheus/middleware.py", line 21, in execute      return super().execute(sql, params=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 94, 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
2019-09-11 16:10:35 Launchpad Janitor merge proposal linked https://code.launchpad.net/~blake-rouse/maas/+git/maas/+merge/372623
2019-09-11 16:12:09 Blake Rouse maas: status New In Progress
2019-09-11 16:12:12 Blake Rouse maas: importance Undecided High
2019-09-11 16:12:14 Blake Rouse maas: milestone 2.7.0alpha1
2019-09-11 16:12:17 Blake Rouse maas: assignee Blake Rouse (blake-rouse)
2019-12-04 17:54:48 Adam Collard maas: milestone 2.7.0b1 2.7.0b2
2019-12-18 12:28:44 Adam Collard maas: milestone 2.7.0b2
2020-03-09 10:17:50 Adam Collard maas: assignee Blake Rouse (blake-rouse)
2020-03-09 10:17:53 Adam Collard maas: status In Progress Triaged
2023-06-21 09:18:34 Jerzy Husakowski maas: status Triaged Incomplete
2023-08-21 04:17:15 Launchpad Janitor maas: status Incomplete Expired