"Cannot call obj_load_attr on orphaned Instance object" in baremetal_basic_ops

[Vladyslav Drok]

Recent ironic job runs (like https://review.openstack.org/#/c/314917/) fail with the following traceback:

2016-05-12 10:19:51.730 | ironic_tempest_plugin.tests.scenario.test_baremetal_basic_ops.BaremetalBasicOps.test_baremetal_server_ops[baremetal,compute,id-549173a5-38ec-42bb-b0e2-c8b9f4a08943,image,network]
2016-05-12 10:19:51.731 | ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
2016-05-12 10:19:51.731 |
2016-05-12 10:19:51.731 | Captured traceback:
2016-05-12 10:19:51.731 | ~~~~~~~~~~~~~~~~~~~
2016-05-12 10:19:51.731 | Traceback (most recent call last):
2016-05-12 10:19:51.731 | File "tempest/test.py", line 113, in wrapper
2016-05-12 10:19:51.731 | return f(self, *func_args, **func_kwargs)
2016-05-12 10:19:51.731 | File "/opt/stack/new/ironic/ironic_tempest_plugin/tests/scenario/test_baremetal_basic_ops.py", line 113, in test_baremetal_server_ops
2016-05-12 10:19:51.732 | self.boot_instance()
2016-05-12 10:19:51.732 | File "/opt/stack/new/ironic/ironic_tempest_plugin/tests/scenario/baremetal_manager.py", line 164, in boot_instance
2016-05-12 10:19:51.732 | interval=30)
2016-05-12 10:19:51.732 | File "/opt/stack/new/ironic/ironic_tempest_plugin/tests/scenario/baremetal_manager.py", line 94, in wait_provisioning_state
2016-05-12 10:19:51.732 | target_states=state, timeout=timeout, interval=interval)
2016-05-12 10:19:51.732 | File "/opt/stack/new/ironic/ironic_tempest_plugin/tests/scenario/baremetal_manager.py", line 89, in _node_state_timeout
2016-05-12 10:19:51.733 | raise lib_exc.TimeoutException(msg)
2016-05-12 10:19:51.733 | tempest.lib.exceptions.TimeoutException: Request timed out
2016-05-12 10:19:51.733 | Details: Timed out waiting for node 92f193e8-9955-4335-b4cf-f24804bf5d07 to reach provision_state state(s) ['active']

in n-cpu there is the following:

2016-05-04 21:44:02.548 25779 ERROR nova.virt.ironic.driver [req-d8ace69f-f1f2-4901-bb4d-8975bc660cf2 tempest-BaremetalBasicOps-1503755723 tempest-BaremetalBasicOps-529747769] Error deploying instance 96a56107-9e09-42a2-a287-66e0305aeed4 on baremetal node 0c8fd6b5-0a02-44f3-a637-0b3e1e174732.
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [req-d8ace69f-f1f2-4901-bb4d-8975bc660cf2 tempest-BaremetalBasicOps-1503755723 tempest-BaremetalBasicOps-529747769] [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] Instance failed to spawn
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] Traceback (most recent call last):
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] File "/opt/stack/new/nova/nova/compute/manager.py", line 2041, in _build_resources
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] yield resources
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] File "/opt/stack/new/nova/nova/compute/manager.py", line 1887, in _build_and_run_instance
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] block_device_info=block_device_info)
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] File "/opt/stack/new/nova/nova/virt/ironic/driver.py", line 781, in spawn
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] 'node': node_uuid})
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] self.force_reraise()
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] six.reraise(self.type_, self.value, self.tb)
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] File "/opt/stack/new/nova/nova/virt/ironic/driver.py", line 773, in spawn
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] timer.start(interval=CONF.ironic.api_retry_interval).wait()
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] File "/usr/local/lib/python2.7/dist-packages/eventlet/event.py", line 121, in wait
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] return hubs.get_hub().switch()
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] File "/usr/local/lib/python2.7/dist-packages/eventlet/hubs/hub.py", line 294, in switch
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] return self.greenlet.switch()
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] File "/usr/local/lib/python2.7/dist-packages/oslo_service/loopingcall.py", line 136, in _run_loop
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] result = func(*self.args, **self.kw)
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] File "/opt/stack/new/nova/nova/virt/ironic/driver.py", line 382, in _wait_for_active
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] instance.refresh()
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] File "/usr/local/lib/python2.7/dist-packages/oslo_versionedobjects/base.py", line 207, in wrapper
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] ctxt, self, fn.__name__, args, kwargs)
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] File "/opt/stack/new/nova/nova/conductor/rpcapi.py", line 241, in object_action
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] objmethod=objmethod, args=args, kwargs=kwargs)
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/client.py", line 158, in call
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] retry=self.retry)
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/transport.py", line 90, in _send
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] timeout=timeout, retry=retry)
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 470, in send
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] retry=retry)
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 461, in _send
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] raise result
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] OrphanedObjectError_Remote: Cannot call obj_load_attr on orphaned Instance object
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] Traceback (most recent call last):
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4]
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] File "/opt/stack/new/nova/nova/conductor/manager.py", line 85, in _object_dispatch
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] return getattr(target, method)(*args, **kwargs)
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4]
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] File "/usr/local/lib/python2.7/dist-packages/oslo_versionedobjects/base.py", line 223, in wrapper
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] return fn(self, *args, **kwargs)
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4]
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] File "/opt/stack/new/nova/nova/objects/instance.py", line 760, in refresh
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] elif self[field] != current[field]:
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4]
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] File "/usr/local/lib/python2.7/dist-packages/oslo_versionedobjects/base.py", line 724, in __getitem__
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] return getattr(self, name)
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4]
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] File "/usr/local/lib/python2.7/dist-packages/oslo_versionedobjects/base.py", line 67, in getter
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] self.obj_load_attr(name)
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4]
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] File "/opt/stack/new/nova/nova/objects/instance.py", line 932, in obj_load_attr
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] objtype=self.obj_name())
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4]
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4] OrphanedObjectError: Cannot call obj_load_attr on orphaned Instance object
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4]
2016-05-04 21:44:02.549 25779 ERROR nova.compute.manager [instance: 96a56107-9e09-42a2-a287-66e0305aeed4]

Seems to be happening after https://review.openstack.org/#/c/312750/ was merged.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/315495

[Matt Riedemann (mriedem)]

The non-voting ironic job even failed in the original change but we didn't notice because it's non-voting:

http://logs.openstack.org/50/312750/5/check/gate-tempest-dsvm-ironic-pxe_ipa-nv/a3d58f4/logs/screen-n-cpu.txt.gz?level=TRACE

It scares me that this broke ironic - do we know why? Seems like a bug in ironic because in Nova we should just be lazy-loading instance.keypairs, and if that's not in the instance_extra table we'd just return a KeyPairList with a single KeyPair object that has the key_name set from the instance field.

[OpenStack Infra (hudson-openstack)]

Change abandoned by Jim Rollenhagen (<email address hidden>) on branch: master
Review: https://review.openstack.org/315491
Reason: This isn't necessary

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/315495
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=fa3453fcc1bc7061f9e39d872bdda6a6944ccaad
Submitter: Jenkins
Branch: master

commit fa3453fcc1bc7061f9e39d872bdda6a6944ccaad
Author: Jim Rollenhagen <email address hidden>
Date: Thu May 12 07:32:27 2016 -0400

    Eager load keypairs in instance metadata

    In the review for e83842b80b73c451f78a4bb9e7bd5dfcebdefcab it was
    pointed out that keypairs should be added to the eager load list for
    get_metadata_for_instance_id. Due to a lack of a proper context in a
    thread in the ironic driver, this actually totally broke ironic.
    The context problem is being fixed elsewhere, but this should be
    eager-loaded to minimize DB queries anyway.

    Change-Id: I67b4665bdebd45c66983c6a556d20f367fa7fbdf
    Closes-Bug: #1580987

[Davanum Srinivas (DIMS) (dims-v)]

This issue was fixed in the openstack/nova 14.0.0.0b1 development milestone.