notifications no longer available in Nova

[Phil Day]

The recent change to oslo messaging seems to have removed the ability to specify a list of topics for notifications. This is a critical feature for systems which provide multiple message streams for billing and monitoring.

To reproduce:

1) Create a devstack system

2) Add the following lines to the [DEFAULT] section of nova.conf:
notification_driver = nova.openstack.common.notifier.rpc_notifier
notification_topics = notifications,monitor
notify_on_state_change = vm_and_task_state
notify_on_any_change = True
instance_usage_audit = True
instance_usage_audit_period = hour

3) Restart all the n-* services

4) Look at the info queues in rabbit
sudo rabbitmqctl list_queues | grep info
notifications.info 15

5) Create an instance
ubuntu@devstack-net-cache:/mnt/devstack$ nova boot --image cirros-0.3.1-x86_64-uec --flavor 1 phil2

6) Look at the info queues in rabbit
sudo rabbitmqctl list_queues | grep info
notifications.info 17

Messages are being added to the "notifications" queue, but not to the monitor queue

[Phil Day (philip-day)]

I added a simple consumer to check what messages were being generated on notifications.info (since the volume of messages looked too small for nova) - and they are comming from Neutron, so this isn't just as topic issue - it looks as if Nova isn't publishing notifications at all now

[Andrea Rosa (andrea-rosa-m)]

I confirm that nova doesn't publish notifications at all, it seems that nova is not loading the plugin correctly.

I did a small test I added an non-existing notification_driver in nova.conf:

notification_driver = oslo.messaging.notify._impl_messaging:MessagingDriverFALSE

Then I restarted nova-api and I can see that the new param is there but not used at all as nova-api is not complaining:
2014-02-07 12:06:51.719 DEBUG nova.openstack.common.service [-] notification_driver = ['oslo.messaging.notify._impl_messaging:MessagingDriverFALSE'] from (pid=7229) log_opt_values /opt/stack/oslo.config/oslo
/config/cfg.py:1911

[Phil Day (philip-day)]

At least part of the problem is that the backwards compatibility values in setup.cfg have been mis-spelt:

"nova.openstack.common.notififier.rpc_notifier

instead of

"nova.openstack.common.notifier.rpc_notifier"

However configuring for the misspelt value now produces an exception in the API layer:

2014-02-07 11:03:51.557 DEBUG oslo.messaging._drivers.amqp [-] UNIQUE_ID is fe1eb0016f3b4c3a856dd782ce990e09. from (pid=30234) _add_unique_id /mnt/stack/oslo.messaging/oslo/messaging/_drivers/amqp.py:333
2014-02-07 11:03:51.558 ERROR oslo.messaging.notify._impl_messaging [-] Could not send notification to monitor. Payload={'priority': 'INFO', '_unique_id': 'fe1eb0016f3b4c3a856dd782ce990e09', 'event_type': 'compute.instance.update', 'timestamp': '2014-02-07 11:03:51.557402', 'publisher_id': 'None.devstack-net-cache', 'payload': {'node': u'devstack-net-cache', 'state_description': 'deleting', 'ramdisk_id': u'50f5d917-91c7-4ffe-8126-9bbb7de2fceb', 'created_at': '2014-02-07 09:44:42', 'access_ip_v6': None, 'disk_gb': 1L, 'availability_zone': None, 'terminated_at': '', 'ephemeral_gb': 0L, 'instance_type_id': 2L, 'instance_flavor_id': '1', 'audit_period_ending': datetime.datetime(2014, 2, 7, 11, 3, 51, 552808), 'host': u'devstack-net-cache', 'user_id': u'd053d4cd7cec4279b740488e53ef7f00', 'deleted_at': '', 'reservation_id': u'r-oggomnqk', 'image_ref_url': u'http://10.2.197.166:9292/images/4f51bf3b-2ca5-4401-8c16-ea6225a24600', 'memory_mb': 512L, 'root_gb': 1L, 'display_name': u'foo', 'bandwidth': {}, 'instance_type': 'm1.tiny', 'tenant_id': u'2db8d9b4711240328b8a6c2735c3a520', 'access_ip_v4': None, 'hostname': u'foo', 'vcpus': 1L, 'old_task_state': None, 'instance_id': u'fa59ad82-91a3-4773-8f33-c18b30a788e3', 'kernel_id': u'ebbaae92-2583-4bb1-a899-46f396b1680b', 'state': u'active', 'image_meta': {u'kernel_id': u'ebbaae92-2583-4bb1-a899-46f396b1680b', u'container_format': u'ami', u'min_ram': u'0', u'ramdisk_id': u'50f5d917-91c7-4ffe-8126-9bbb7de2fceb', u'disk_format': u'ami', u'min_disk': u'1', u'base_image_ref': u'4f51bf3b-2ca5-4401-8c16-ea6225a24600'}, 'architecture': None, 'new_task_state': u'deleting', 'audit_period_beginning': datetime.datetime(2014, 2, 1, 0, 0), 'old_state': u'active', 'os_type': None, 'launched_at': '2014-02-07T09:44:47.000000', 'metadata': {}}, 'message_id': '03392b37-325e-4960-8a13-0367f9223e51'}
2014-02-07 11:03:51.558 TRACE oslo.messaging.notify._impl_messaging Traceback (most recent call last):
2014-02-07 11:03:51.558 TRACE oslo.messaging.notify._impl_messaging File "/mnt/stack/oslo.messaging/oslo/messaging/notify/_impl_messaging.py", line 47, in notify
2014-02-07 11:03:51.558 TRACE oslo.messaging.notify._impl_messaging version=self.version)
2014-02-07 11:03:51.558 TRACE oslo.messaging.notify._impl_messaging File "/mnt/stack/oslo.messaging/oslo/messaging/transport.py", line 93, in _send_notification
2014-02-07 11:03:51.558 TRACE oslo.messaging.notify._impl_messaging self._driver.send_notification(target, ctxt, message, version)
2014-02-07 11:03:51.558 TRACE oslo.messaging.notify._impl_messaging File "/mnt/stack/oslo.messaging/oslo/messaging/_drivers/amqpdriver.py", line 393, in send_notification
2014-02-07 11:0...

[Phil Day (philip-day)]

Setting this to critical as at the moment it looks like notifications in Nova are just broken since this change to oslo

[Phil Day (philip-day)]

Thanks Andera,

I've added what I found so far to the bug report. I think there are at least two issues here:

Setup.cfg has mis-spelt the backwards compatibility names

But even using the mis-spelt name produces a stack trace when Nova tries to send a message

> -----Original Message-----
> From: <email address hidden> [mailto:<email address hidden>] On Behalf
> Of Andrea Rosa
> Sent: 07 February 2014 12:09
> To: Day, Phil
> Subject: [Bug 1277204] Re: notification topics no longer configurable
>
> I confirm that nova doesn't publish notifications at all, it seems that nova is
> not loading the plugin correctly.
>
> I did a small test I added an non-existing notification_driver in
> nova.conf:
>
> notification_driver =
> oslo.messaging.notify._impl_messaging:MessagingDriverFALSE
>
> Then I restarted nova-api and I can see that the new param is there but not
> used at all as nova-api is not complaining:
> 2014-02-07 12:06:51.719 DEBUG nova.openstack.common.service [-]
> notification_driver =
> ['oslo.messaging.notify._impl_messaging:MessagingDriverFALSE'] from
> (pid=7229) log_opt_values /opt/stack/oslo.config/oslo
> /config/cfg.py:1911
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1277204
>
> Title:
> notification topics no longer configurable
>
> Status in OpenStack Compute (Nova):
> New
> Status in Messaging API for OpenStack:
> New
>
> Bug description:
> The recent change to oslo messaging seems to have removed the ability
> to specify a list of topics for notifications. This is a critical
> feature for systems which provide multiple message streams for billing
> and monitoring.
>
>
> To reproduce:
>
> 1) Create a devstack system
>
> 2) Add the following lines to the [DEFAULT] section of nova.conf:
> notification_driver = nova.openstack.common.notifier.rpc_notifier
> notification_topics = notifications,monitor
> notify_on_state_change = vm_and_task_state
> notify_on_any_change = True
> instance_usage_audit = True
> instance_usage_audit_period = hour
>
> 3) Restart all the n-* services
>
> 4) Look at the info queues in rabbit
> sudo rabbitmqctl list_queues | grep info
> notifications.info 15
>
> 5) Create an instance
> ubuntu@devstack-net-cache:/mnt/devstack$ nova boot --image cirros-
> 0.3.1-x86_64-uec --flavor 1 phil2
>
> 6) Look at the info queues in rabbit
> sudo rabbitmqctl list_queues | grep info
> notifications.info 17
>
>
> Messages are being added to the "notifications" queue, but not to the
> monitor queue
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/nova/+bug/1277204/+subscriptions

[Phil Day (philip-day)]

https://review.openstack.org/#/c/71532/1 fixes the stack trace above, and https://review.openstack.org/#/c/71888/1 fixes the typo - but still can't get Nova in devstack to send a notification message into MQ.

[Phil Day (philip-day)]

Did some more debugging in Devstack after the two above were merged, but flumxed as to why notifications still don't work.

I can see the notification message reaching published_send() method in oslo/messaging/_drivers/_impl_rabbit.py with a topic of "notifications.info", and can see from the same set of tracing normal Nova messages being sent to a topic of "conductor"

But while the conductor messages clearly get there, the notification ones just never seem to make it to the queue, even though Neutron (which hasn't yet moved to oslo messaging) are going into the notification.info queue (so the queue itself exists)

[Phil Day (philip-day)]

Not sure if this is a helpful clue or not, but from the logs it looks lije each notification message alwways results in making a new connection

2014-02-07 20:06:28.557 INFO oslo.messaging._drivers.impl_rabbit [-] Connected to AMQP server on localhost:5672

whereas the rpc messages don't seem do this.

[Phil Day (philip-day)]

Setting to critical since as far as I can see notifications are broken following the switch to oslo, not juts no longer configurable

[Mark McLoughlin (markmc)]

Phil - I haven't tried with devstack yet, but tried this test:

https://gist.github.com/markmc/8953856

Basically this shows some old and new nova code sending the same notifications and a server to receive them - I'm not seeing any change in behaviour

[Mark McLoughlin (markmc)]

Ok, I've tried with devstack now and I'm happily receiving notifications

This is the listener I'm using : https://gist.github.com/markmc/8955322

To test this, I just put:

  notification_driver = nova.openstack.common.notifier.rpc_notifier
  notification_topics = notifications

in nova.conf and restarted nova-api, then did:

  $> nova keypair-add foo

and I see:

 {..., u'event_type': u'keypair.create.start', ... payload': {u'tenant_id': u'e441da12bb4a4b6999db3bf10e1940e3', u'user_id': u'400c71997c7a4622a6135d5cd9d6d357', u'key_name': u'foo'}, }

[Mark McLoughlin (markmc)]

Oh, for reference, I'm testing with nova commit 93b0fc1

Marking as Incomplete until we figure out what's different about your setup that's causing the problem

[Phil Day (philip-day)]

Thanks Mark - good to know that it might just be my set-up. I'll rebuild a new devstack and re-test.

[Phil Day (philip-day)]

Build a new devstack and confirmed that notifications are now working - so closing this issue.

The one outstanding difference seems to be that if you configure additional notification topics then the queues don't exist until something has listened on them at least once - I *think* the code used to always create the notification queues, but I'll dig into that separately and raise a new bug if i can prove that.