Cannot send scheduler.run_instance events

Bug #1279881 reported by Julien Danjou on 2014-02-13
38
This bug affects 6 people
Affects Status Importance Assigned to Milestone
Cinder
Critical
Flavio Percoco
OpenStack Compute (nova)
Critical
Mehdi Abaakouk

Bug Description

When launching an instance I'm able to trigger the following error with notifications active:

2014-02-13 16:26:39.974 ERROR oslo.messaging.notify._impl_messaging [-] Could not send notification to notifications. Payload={'_context_roles': [u'admin'], '_context_request_id': u'req-7d0ca56f-f609-40ef-91e1-acf7d5a4a607', '_context_quota_class': None, 'event_type': 'scheduler.run_instance', '_context_service_catalog': [{u'endpoints': [{u'adminURL': u'http://162.209.87.220:8776/v1/8c5cfa81726043afb5641ec3d6665f27', u'region': u'RegionOne', u'id': u'125bb6de586c435eb4e14e5e62090b43', u'internalURL': u'http://162.209.87.220:8776/v1/8c5cfa81726043afb5641ec3d6665f27', u'publicURL': u'http://162.209.87.220:8776/v1/8c5cfa81726043afb5641ec3d6665f27'}], u'endpoints_links': [], u'type': u'volume', u'name': u'cinder'}], 'timestamp': '2014-02-13 16:26:39.970161', '_context_user': u'b6bbfab520dc4f6b91a95cd819f0316c', '_unique_id': '447230aa40904dd1aa2b6a9319b57f56', '_context_instance_lock_checked': False, '_context_user_id': u'b6bbfab520dc4f6b91a95cd819f0316c', 'payload': {'instance_id': u'84a4f45c-3f85-4527-ae85-6f323e136d01', 'state': 'error', 'request_spec': {u'num_instances': 1, u'block_device_mapping': [{u'instance_uuid': u'84a4f45c-3f85-4527-ae85-6f323e136d01', u'guest_format': None, u'boot_index': 0, u'delete_on_termination': True, u'no_device': None, u'connection_info': None, u'snapshot_id': None, u'device_name': None, u'disk_bus': None, u'image_id': u'0fbb3b3b-7d69-42d2-8bc7-3b87073e69b2', u'source_type': u'image', u'device_type': u'disk', u'volume_id': None, u'destination_type': u'local', u'volume_size': None}], u'image': {u'status': u'active', u'name': u'ubuntu1310', u'deleted': False, u'container_format': u'bare', u'created_at': u'2014-02-13T15:50:11.000000', u'disk_format': u'raw', u'updated_at': u'2014-02-13T15:50:17.000000', u'id': u'0fbb3b3b-7d69-42d2-8bc7-3b87073e69b2', u'owner': u'8c5cfa81726043afb5641ec3d6665f27', u'min_ram': 0, u'checksum': u'5c7a196274f24cd40100eac98f661057', u'min_disk': 0, u'is_public': True, u'deleted_at': None, u'properties': {}, u'size': 244711424}, u'instance_type': {u'root_gb': 40, u'name': u'm1.medium', u'ephemeral_gb': 0, u'memory_mb': 4096, u'vcpus': 2, u'extra_specs': {}, u'swap': 0, u'rxtx_factor': 1.0, u'flavorid': u'3', u'vcpu_weight': None, u'id': 1}, u'instance_properties': {u'vm_state': u'building', u'availability_zone': u'nova', u'terminated_at': None, u'ephemeral_gb': 0, u'instance_type_id': 1, u'user_data': None, u'cleaned': False, u'vm_mode': None, u'deleted_at': None, u'reservation_id': u'r-6sv4oy43', u'id': 2, u'security_groups': [{u'project_id': u'8c5cfa81726043afb5641ec3d6665f27', u'user_id': u'b6bbfab520dc4f6b91a95cd819f0316c', u'description': u'default', u'deleted': False, u'created_at': u'2014-02-13T15:50:52.000000', u'updated_at': None, u'deleted_at': None, u'id': 1, u'name': u'default'}], u'disable_terminate': False, u'display_name': u'lol', u'uuid': u'84a4f45c-3f85-4527-ae85-6f323e136d01', u'default_swap_device': None, u'info_cache': {u'instance_uuid': u'84a4f45c-3f85-4527-ae85-6f323e136d01', u'deleted': False, u'created_at': u'2014-02-13T16:26:39.000000', u'updated_at': None, u'network_info': [], u'deleted_at': None}, u'hostname': u'lol', u'launched_on': None, u'display_description': u'lol', u'key_data': None, u'kernel_id': u'', u'power_state': 0, u'default_ephemeral_device': None, u'progress': 0, u'project_id': u'8c5cfa81726043afb5641ec3d6665f27', u'launched_at': None, u'scheduled_at': None, u'node': None, u'ramdisk_id': u'', u'access_ip_v6': None, u'access_ip_v4': None, u'deleted': False, u'key_name': None, u'updated_at': None, u'host': None, u'ephemeral_key_uuid': None, u'architecture': None, u'user_id': u'b6bbfab520dc4f6b91a95cd819f0316c', u'system_metadata': {u'image_min_disk': u'40', u'instance_type_memory_mb': u'4096', u'instance_type_swap': u'0', u'instance_type_vcpu_weight': None, u'instance_type_root_gb': u'40', u'instance_type_id': u'1', u'instance_type_name': u'm1.medium', u'instance_type_ephemeral_gb': u'0', u'instance_type_rxtx_factor': u'1.0', u'instance_type_flavorid': u'3', u'image_container_format': u'bare', u'instance_type_vcpus': u'2', u'image_min_ram': u'0', u'image_disk_format': u'raw', u'image_base_image_ref': u'0fbb3b3b-7d69-42d2-8bc7-3b87073e69b2'}, u'task_state': u'scheduling', u'shutdown_terminate': False, u'cell_name': None, u'root_gb': 40, u'locked': False, u'name': u'instance-00000002', u'created_at': u'2014-02-13T16:26:39.000000', u'locked_by': None, u'launch_index': 0, u'metadata': {}, u'memory_mb': 4096, u'vcpus': 2, u'image_ref': u'0fbb3b3b-7d69-42d2-8bc7-3b87073e69b2', u'root_device_name': None, u'auto_disk_config': False, u'os_type': None, u'config_drive': u''}, u'security_group': [u'default']}, 'instance_properties': {u'vm_state': u'building', u'availability_zone': u'nova', u'terminated_at': None, u'ephemeral_gb': 0, u'instance_type_id': 1, u'user_data': None, u'cleaned': False, u'vm_mode': None, u'deleted_at': None, u'reservation_id': u'r-6sv4oy43', u'id': 2, u'security_groups': [{u'project_id': u'8c5cfa81726043afb5641ec3d6665f27', u'user_id': u'b6bbfab520dc4f6b91a95cd819f0316c', u'description': u'default', u'deleted': False, u'created_at': u'2014-02-13T15:50:52.000000', u'updated_at': None, u'deleted_at': None, u'id': 1, u'name': u'default'}], u'disable_terminate': False, u'display_name': u'lol', u'uuid': u'84a4f45c-3f85-4527-ae85-6f323e136d01', u'default_swap_device': None, u'info_cache': {u'instance_uuid': u'84a4f45c-3f85-4527-ae85-6f323e136d01', u'deleted': False, u'created_at': u'2014-02-13T16:26:39.000000', u'updated_at': None, u'network_info': [], u'deleted_at': None}, u'hostname': u'lol', u'launched_on': None, u'display_description': u'lol', u'key_data': None, u'kernel_id': u'', u'power_state': 0, u'default_ephemeral_device': None, u'progress': 0, u'project_id': u'8c5cfa81726043afb5641ec3d6665f27', u'launched_at': None, u'scheduled_at': None, u'node': None, u'ramdisk_id': u'', u'access_ip_v6': None, u'access_ip_v4': None, u'deleted': False, u'key_name': None, u'updated_at': None, u'host': None, u'ephemeral_key_uuid': None, u'architecture': None, u'user_id': u'b6bbfab520dc4f6b91a95cd819f0316c', u'system_metadata': {u'image_min_disk': u'40', u'instance_type_memory_mb': u'4096', u'instance_type_swap': u'0', u'instance_type_vcpu_weight': None, u'instance_type_root_gb': u'40', u'instance_type_id': u'1', u'instance_type_name': u'm1.medium', u'instance_type_ephemeral_gb': u'0', u'instance_type_rxtx_factor': u'1.0', u'instance_type_flavorid': u'3', u'image_container_format': u'bare', u'instance_type_vcpus': u'2', u'image_min_ram': u'0', u'image_disk_format': u'raw', u'image_base_image_ref': u'0fbb3b3b-7d69-42d2-8bc7-3b87073e69b2'}, u'task_state': u'scheduling', u'shutdown_terminate': False, u'cell_name': None, u'root_gb': 40, u'locked': False, u'name': u'instance-00000002', u'created_at': u'2014-02-13T16:26:39.000000', u'locked_by': None, u'launch_index': 0, u'metadata': {}, u'memory_mb': 4096, u'vcpus': 2, u'image_ref': u'0fbb3b3b-7d69-42d2-8bc7-3b87073e69b2', u'root_device_name': None, u'auto_disk_config': False, u'os_type': None, u'config_drive': u''}, 'reason': NoValidHost(u'No valid host was found. ',), 'method': 'run_instance'}, '_context_project_name': u'demo', '_context_read_deleted': u'no', '_context_auth_token': u'06fb3c10469c7811eeae6936ff3b12ec', '_context_tenant': u'8c5cfa81726043afb5641ec3d6665f27', 'priority': 'ERROR', '_context_is_admin': True, '_context_project_id': u'8c5cfa81726043afb5641ec3d6665f27', '_context_timestamp': '2014-02-13T16:26:39.446679', '_context_user_name': u'admin', 'publisher_id': 'scheduler.devstack', 'message_id': 'f1f2ab74-1bd7-4992-89e7-93de9adeae5a', '_context_remote_address': u'162.209.87.220'}

2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging Traceback (most recent call last):
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging File "/opt/stack/oslo.messaging/oslo/messaging/notify/_impl_messaging.py", line 47, in notify
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging version=self.version)
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging File "/opt/stack/oslo.messaging/oslo/messaging/transport.py", line 93, in _send_notification
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging self._driver.send_notification(target, ctxt, message, version)
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging File "/opt/stack/oslo.messaging/oslo/messaging/_drivers/amqpdriver.py", line 393, in send_notification
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging return self._send(target, ctxt, message, envelope=(version == 2.0))
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging File "/opt/stack/oslo.messaging/oslo/messaging/_drivers/amqpdriver.py", line 378, in _send
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging conn.topic_send(topic, msg, timeout=timeout)
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging File "/opt/stack/oslo.messaging/oslo/messaging/_drivers/impl_rabbit.py", line 701, in topic_send
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging self.publisher_send(TopicPublisher, topic, msg, timeout)
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging File "/opt/stack/oslo.messaging/oslo/messaging/_drivers/impl_rabbit.py", line 673, in publisher_send
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging self.ensure(_error_callback, _publish)
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging File "/opt/stack/oslo.messaging/oslo/messaging/_drivers/impl_rabbit.py", line 577, in ensure
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging return method(*args, **kwargs)
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging File "/opt/stack/oslo.messaging/oslo/messaging/_drivers/impl_rabbit.py", line 671, in _publish
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging publisher.send(msg, timeout)
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging File "/opt/stack/oslo.messaging/oslo/messaging/_drivers/impl_rabbit.py", line 328, in send
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging self.producer.publish(msg)
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging File "/usr/local/lib/python2.7/dist-packages/kombu/messaging.py", line 157, in publish
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging compression, headers)
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging File "/usr/local/lib/python2.7/dist-packages/kombu/messaging.py", line 233, in _prepare
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging body) = encode(body, serializer=serializer)
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging File "/usr/local/lib/python2.7/dist-packages/kombu/serialization.py", line 170, in encode
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging payload = encoder(data)
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging File "/usr/lib/python2.7/dist-packages/anyjson/__init__.py", line 141, in dumps
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging return implementation.dumps(value)
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging File "/usr/lib/python2.7/dist-packages/anyjson/__init__.py", line 87, in dumps
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging return self._encode(data)
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging File "/usr/local/lib/python2.7/dist-packages/neutronclient/openstack/common/jsonutils.py", line 155, in dumps
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging return json.dumps(value, default=default, **kwargs)
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging File "/usr/lib/python2.7/json/__init__.py", line 250, in dumps
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging sort_keys=sort_keys, **kw).encode(obj)
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging File "/usr/lib/python2.7/json/encoder.py", line 207, in encode
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging chunks = self.iterencode(o, _one_shot=True)
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging File "/usr/lib/python2.7/json/encoder.py", line 270, in iterencode
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging return _iterencode(o, 0)
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging ValueError: Circular reference detected
2014-02-13 16:26:39.974 TRACE oslo.messaging.notify._impl_messaging

Changed in nova:
milestone: none → icehouse-3
tags: added: notifications oslo
Mehdi Abaakouk (sileht) wrote :

In old oslo-incubator notifier code, the notifier never trust the application payload and do a

payload = jsonutils.to_primitive(payload, convert_instances=True)

to ensure that the object is serializable.

Now oslo.messaging assume the application have setuped all needed serializer to convert all objects in the payload to serialisable format.

Or it seems, that data in the payload continue to have unserialisable object in nova.

The question is, does oslo.messaging should restore the previous behavior (and we continue to send payload without mastering the content)

Or we fix nova by adding missing serializer.

I think the second option needs more work but are better.

Eoghan Glynn (eglynn) wrote :

Seems to have been fixed somewhere between `git shortlog bced0a74..60f30c26` in nova.

Mark McLoughlin (markmc) wrote :

Ok, so RequestContextSerializer doesn't do any payload serialization. We need to add a serializer which does:

    # Ensure everything is JSON serializable.
    payload = jsonutils.to_primitive(payload, convert_instances=True)

Mark McLoughlin (markmc) wrote :

Something like this maybe? http://paste.openstack.org/show/67279/

Mehdi Abaakouk (sileht) on 2014-02-19
Changed in nova:
assignee: nobody → Mehdi Abaakouk (sileht)
Mehdi Abaakouk (sileht) wrote :

I have found many hits in logstash.openstack.org this last hour, I will propose the fix tomorow

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

Changed in nova:
status: New → In Progress
Mark McLoughlin (markmc) on 2014-02-24
Changed in nova:
importance: Undecided → Critical

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

commit a83d5f11e410223825ac32ccdd3d70651af3f2e1
Author: Mehdi Abaakouk <email address hidden>
Date: Thu Feb 20 10:25:23 2014 +0100

    Serialize the notification payload in json

    When a notification payload is passed to the oslo.messaging the
    payload must be correctly serialized.

    This change encode the payload into json as the old rpc did.

    Closes bug: #1279881

    Change-Id: I99fc2a4b0e0146c9faa6abeddbd15cb24169e024

Changed in nova:
status: In Progress → Fix Committed
Thierry Carrez (ttx) on 2014-03-05
Changed in nova:
status: Fix Committed → Fix Released
Mike Perez (thingee) wrote :
Changed in cinder:
importance: Undecided → Critical
assignee: nobody → John Griffith (john-griffith)
milestone: none → icehouse-rc1
status: New → In Progress
Mike Perez (thingee) wrote :
Changed in cinder:
status: In Progress → Fix Committed
assignee: John Griffith (john-griffith) → Flavio Percoco (flaper87)
Thierry Carrez (ttx) on 2014-03-27
Changed in cinder:
status: Fix Committed → Fix Released
Thierry Carrez (ttx) on 2014-04-17
Changed in nova:
milestone: icehouse-3 → 2014.1
Thierry Carrez (ttx) on 2014-04-17
Changed in cinder:
milestone: icehouse-rc1 → 2014.1
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Duplicates of this bug

Other bug subscribers