Instance action recording fails with "primary key must be unique" error

[Trey Morris]

1. pulled trunk
2. started nova screen session
3. euca-run-instances -k test -t m1.tiny ami-tiny
4. get the following in the compute worker output/logs:

DEBUG:root:instance 1: starting...
DEBUG:root:Asking xapi to fetch http://10.127.4.133:3333/_images/ami-tiny/image as admin:admin
INFO:root:Task [Async.host.call_plugin] OpaqueRef:cfd9ecce-8119-d184-b4f8-48b48fc9af5e status: success <value>5a076be8-0221-4a4b-9d68-3f3e306c7c02</value>
DEBUG:root:Asking xapi to fetch http://10.127.4.133:3333/_images/aki-lucid/image as admin:admin
INFO:root:Task [Async.host.call_plugin] OpaqueRef:13d1feb3-984a-3f9d-2786-dc191ed38fc0 status: success <value>/boot/guest/_images/aki-lucid/image</value>
ERROR:root:in looping call
Traceback (most recent call last):
  File "/home/trey/openstack/novascript/nova/nova/utils.py", line 323, in _inner
    self.f(*self.args, **self.kw)
  File "/home/trey/openstack/novascript/nova/nova/virt/xenapi_conn.py", line 257, in _poll_task
    db.instance_action_create(context.get_admin_context(), action)
  File "/home/trey/openstack/novascript/nova/nova/db/api.py", line 383, in instance_action_create
    return IMPL.instance_action_create(context, values)
  File "/home/trey/openstack/novascript/nova/nova/db/sqlalchemy/api.py", line 108, in wrapper
    return f(*args, **kwargs)
  File "/home/trey/openstack/novascript/nova/nova/db/sqlalchemy/api.py", line 855, in instance_action_create
    action_ref.save(session=session)
  File "/home/trey/openstack/novascript/nova/nova/db/sqlalchemy/models.py", line 57, in save
    session.flush()
  File "/usr/lib/python2.6/dist-packages/sqlalchemy/orm/session.py", line 1346, in flush
    self._flush(objects)
  File "/usr/lib/python2.6/dist-packages/sqlalchemy/orm/session.py", line 1427, in _flush
    flush_context.execute()
  File "/usr/lib/python2.6/dist-packages/sqlalchemy/orm/unitofwork.py", line 299, in execute
    rec.execute(self)
  File "/usr/lib/python2.6/dist-packages/sqlalchemy/orm/unitofwork.py", line 443, in execute
    uow
  File "/usr/lib/python2.6/dist-packages/sqlalchemy/orm/mapper.py", line 1833, in _save_obj
    execute(statement, params)
  File "/usr/lib/python2.6/dist-packages/sqlalchemy/engine/base.py", line 1157, in execute
    params)
  File "/usr/lib/python2.6/dist-packages/sqlalchemy/engine/base.py", line 1237, in _execute_clauseelement
    return self.__execute_context(context)
  File "/usr/lib/python2.6/dist-packages/sqlalchemy/engine/base.py", line 1268, in __execute_context
    context.parameters[0], context=context)
  File "/usr/lib/python2.6/dist-packages/sqlalchemy/engine/base.py", line 1367, in _cursor_execute
    context)
  File "/usr/lib/python2.6/dist-packages/sqlalchemy/engine/base.py", line 1360, in _cursor_execute
    context)
  File "/usr/lib/python2.6/dist-packages/sqlalchemy/engine/default.py", line 288, in do_execute
    cursor.execute(statement, parameters)
IntegrityError: (IntegrityError) PRIMARY KEY must be unique u'INSERT INTO instance_actions (created_at, updated_at, deleted_at, deleted, id, instance_id, action, error) VALUES (?, ?, ?, ?, ?, ?, ?, ?)' ('2010-12-30 05:18:01.935480', None, None, False, 0, None, 'Async.host.call_plugin', None)

DEBUG:root:Asking xapi to fetch http://10.127.4.133:3333/_images/ari-lucid/image as admin:admin
INFO:root:Task [Async.host.call_plugin] OpaqueRef:2fc0cacd-fb81-8751-725f-b9f02b056c09 status: success <value>/boot/guest/_images/ari-lucid/image</value>
ERROR:root:in looping call
Traceback (most recent call last):
  File "/home/trey/openstack/novascript/nova/nova/utils.py", line 323, in _inner
    self.f(*self.args, **self.kw)
  File "/home/trey/openstack/novascript/nova/nova/virt/xenapi_conn.py", line 257, in _poll_task
    db.instance_action_create(context.get_admin_context(), action)
  File "/home/trey/openstack/novascript/nova/nova/db/api.py", line 383, in instance_action_create
    return IMPL.instance_action_create(context, values)
  File "/home/trey/openstack/novascript/nova/nova/db/sqlalchemy/api.py", line 108, in wrapper
    return f(*args, **kwargs)
  File "/home/trey/openstack/novascript/nova/nova/db/sqlalchemy/api.py", line 855, in instance_action_create
    action_ref.save(session=session)
  File "/home/trey/openstack/novascript/nova/nova/db/sqlalchemy/models.py", line 57, in save
    session.flush()
  File "/usr/lib/python2.6/dist-packages/sqlalchemy/orm/session.py", line 1346, in flush
    self._flush(objects)
  File "/usr/lib/python2.6/dist-packages/sqlalchemy/orm/session.py", line 1427, in _flush
    flush_context.execute()
  File "/usr/lib/python2.6/dist-packages/sqlalchemy/orm/unitofwork.py", line 299, in execute
    rec.execute(self)
  File "/usr/lib/python2.6/dist-packages/sqlalchemy/orm/unitofwork.py", line 443, in execute
    uow
  File "/usr/lib/python2.6/dist-packages/sqlalchemy/orm/mapper.py", line 1833, in _save_obj
    execute(statement, params)
  File "/usr/lib/python2.6/dist-packages/sqlalchemy/engine/base.py", line 1157, in execute
    params)
  File "/usr/lib/python2.6/dist-packages/sqlalchemy/engine/base.py", line 1237, in _execute_clauseelement
    return self.__execute_context(context)
  File "/usr/lib/python2.6/dist-packages/sqlalchemy/engine/base.py", line 1268, in __execute_context
    context.parameters[0], context=context)
  File "/usr/lib/python2.6/dist-packages/sqlalchemy/engine/base.py", line 1367, in _cursor_execute
    context)
  File "/usr/lib/python2.6/dist-packages/sqlalchemy/engine/base.py", line 1360, in _cursor_execute
    context)
  File "/usr/lib/python2.6/dist-packages/sqlalchemy/engine/default.py", line 288, in do_execute
    cursor.execute(statement, parameters)
IntegrityError: (IntegrityError) PRIMARY KEY must be unique u'INSERT INTO instance_actions (created_at, updated_at, deleted_at, deleted, id, instance_id, action, error) VALUES (?, ?, ?, ?, ?, ?, ?, ?)' ('2010-12-30 05:18:02.755981', None, None, False, 0, None, 'Async.host.call_plugin', None)

DEBUG:root:Created VM instance-137521447...
DEBUG:root:Created VM instance-137521447 as OpaqueRef:2e4954fb-1443-4540-e6fc-59f85c6700fa.
DEBUG:root:Creating VBD for VM OpaqueRef:2e4954fb-1443-4540-e6fc-59f85c6700fa, VDI OpaqueRef:603743d5-6cc6-a69a-95a0-680b249ad153 ...
DEBUG:root:Created VBD OpaqueRef:b708f65a-df73-5f4b-8427-872755fcf6d0 for VM OpaqueRef:2e4954fb-1443-4540-e6fc-59f85c6700fa, VDI OpaqueRef:603743d5-6cc6-a69a-95a0-680b249ad153.
DEBUG:root:Creating VIF for VM OpaqueRef:2e4954fb-1443-4540-e6fc-59f85c6700fa, network OpaqueRef:eff1853c-a45d-fa66-bced-50c1c3e286a2.
DEBUG:root:Created VIF OpaqueRef:6d07708c-71bc-47c2-941e-b4c77a8bf57a for VM OpaqueRef:2e4954fb-1443-4540-e6fc-59f85c6700fa, network OpaqueRef:eff1853c-a45d-fa66-bced-50c1c3e286a2.
DEBUG:root:Starting VM OpaqueRef:2e4954fb-1443-4540-e6fc-59f85c6700fa...
INFO:root:Spawning VM instance-137521447 created OpaqueRef:2e4954fb-1443-4540-e6fc-59f85c6700fa.
INFO:root:(VM_UTILS) xenserver vm state -> |Running|
INFO:root:(VM_UTILS) xenapi power_state -> |1|
DEBUG:root:Instance instance-137521447: booted
INFO:root:(VM_UTILS) xenserver vm state -> |Running|
INFO:root:(VM_UTILS) xenapi power_state -> |1|

The instance is running and works. I was able to test locking, pause, unpause etc successfully.

[Trey Morris (tr3buchet)]

Also wanted to note that similar error cropped up all over the place while i was testing, but everything still worked.

[Thierry Carrez (ttx)]

The instance_actions table has "id" as primary key, but "id" is not set in the dict at ./virt/xenapi_conn.py:243, so it defaults to 0... subsequent tries to record an instance action with id=0 will fail with "primary key must be unique" INSERT error.

Not sure how Josh intended to make that id field unique, apparently instance_actions are only used in xenapi_conn.py:243 so far.

[Josh Kearney (jk0)]

It should be set automatically. I don't know why that isn't happening, so I'll investigate and put out a fix.

[Josh Kearney (jk0)]

I am unable to reproduce this. To test, I wiped the database, pulled down trunk, created a new user/project/etc and fired up a brand new instance. The actions are being recorded as as expected:

mysql> select * from instance_actions;
+---------------------+------------+------------+---------+----+-------------+------------------------+-----------------------------------------------------------------------------------------------+
| created_at | updated_at | deleted_at | deleted | id | instance_id | action | error |
+---------------------+------------+------------+---------+----+-------------+------------------------+-----------------------------------------------------------------------------------------------+
| 2011-01-05 17:16:10 | NULL | NULL | 0 | 1 | 1 | Async.host.call_plugin | NULL |
| 2011-01-05 17:16:11 | NULL | NULL | 0 | 2 | 1 | Async.host.call_plugin | NULL |
| 2011-01-05 17:16:12 | NULL | NULL | 0 | 3 | 1 | Async.host.call_plugin | NULL |
| 2011-01-05 17:17:18 | NULL | NULL | 0 | 4 | 1 | Async.VM.clean_reboot | ['VM_BAD_POWER_STATE', 'OpaqueRef:1b3c13c6-b74a-f276-99f7-60c29160cb30', 'running', 'halted'] |
| 2011-01-05 17:18:12 | NULL | NULL | 0 | 5 | 1 | Async.VM.clean_reboot | ['VM_BAD_POWER_STATE', 'OpaqueRef:1b3c13c6-b74a-f276-99f7-60c29160cb30', 'running', 'halted'] |
+---------------------+------------+------------+---------+----+-------------+------------------------+-----------------------------------------------------------------------------------------------+
5 rows in set (0.00 sec)

The id column is populated automatically my SQLAlchemy.

[Trey Morris (tr3buchet)]

i was using sqlite. Maybe that's the issue?

[Thierry Carrez (ttx)]

Josh: could this be linked to Trey's usage of sqlite ?

[Thierry Carrez (ttx)]

@jk0: any chance you could answer the above question, so that we unblock this bug ?

[Josh Kearney (jk0)]

Thierry,

Sorry for the late response (this somehow escaped my attention). The fix for this was actually included in my XS-Rescue work that landed a week or two ago, making the instance_id optional (set to None by default).

I will mark this as Fix Committed.