yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1536610] Re: nova instance actions periodically have no start and finish time (empty events[])

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Sean Dague <sean@xxxxxxxxx>
Date: Wed, 17 Feb 2016 15:39:31 -0000
Reply-to: Bug 1536610 <1536610@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
** Changed in: nova
       Status: New => Opinion

** Changed in: nova
   Importance: Undecided => Wishlist

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1536610

Title:
  nova instance actions periodically have no start and finish time
  (empty events[])

Status in OpenStack Compute (nova):
  Opinion

Bug description:
  Nova instance actions periodically have no start and finish time, I
  get empty events[]:

  root@controller1:/var/log# nova instance-action-list 5f844d05-405f-4997-b542-0c85d1b6c8ed
  +--------+------------------------------------------+---------+----------------------------+
  | Action | Request_ID                               | Message | Start_Time                 |
  +--------+------------------------------------------+---------+----------------------------+
  | create | req-58d31051-ca3b-4a1c-ab75-0335ff3b28ae | -       | 2016-01-21T11:24:07.000000 |
  | reboot | req-eba0435f-610a-47cd-841f-f3500c7b66b7 | -       | 2016-01-21T11:25:47.000000 |
  | reboot | req-71688344-840e-4cb4-ba3e-21e4c0a85db7 | -       | 2016-01-21T11:26:17.000000 |
  +--------+------------------------------------------+---------+----------------------------+

  root@controller1:/var/log# nova instance-action 5f844d05-405f-4997-b542-0c85d1b6c8ed req-eba0435f-610a-47cd-841f-f3500c7b66b7
  +---------------+--------------------------------------------------+
  | Property      | Value                                            |
  +---------------+--------------------------------------------------+
  | action        | reboot                                           |
  | events        | [{u'event': u'compute_reboot_instance',          |
  |               |   u'finish_time': u'2016-01-21T11:25:50.000000', |
  |               |   u'result': u'Success',                         |
  |               |   u'start_time': u'2016-01-21T11:25:48.000000',  |
  |               |   u'traceback': None}]                           |
  | instance_uuid | 5f844d05-405f-4997-b542-0c85d1b6c8ed             |
  | message       | -                                                |
  | project_id    | 73eb606e175249049987ec6a5774f282                 |
  | request_id    | req-eba0435f-610a-47cd-841f-f3500c7b66b7         |
  | start_time    | 2016-01-21T11:25:47.000000                       |
  | user_id       | 8855a4b15321469c8b44bbc1e0ea5320                 |
  +---------------+--------------------------------------------------+

  root@controller1:/var/log# nova instance-action 5f844d05-405f-4997-b542-0c85d1b6c8ed req-71688344-840e-4cb4-ba3e-21e4c0a85db7
  +---------------+------------------------------------------+
  | Property      | Value                                    |
  +---------------+------------------------------------------+
  | action        | reboot                                   |
  | events        | []                                       |
  | instance_uuid | 5f844d05-405f-4997-b542-0c85d1b6c8ed     |
  | message       | -                                        |
  | project_id    | 73eb606e175249049987ec6a5774f282         |
  | request_id    | req-71688344-840e-4cb4-ba3e-21e4c0a85db7 |
  | start_time    | 2016-01-21T11:26:17.000000               |
  | user_id       | 8855a4b15321469c8b44bbc1e0ea5320         |
  +---------------+------------------------------------------+

  root@controller1:/var/log# nova show 5f844d05-405f-4997-b542-0c85d1b6c8ed
  +--------------------------------------+------------------------------------------------------------------------------------------+
  | Property                             | Value                                                                                    |
  +--------------------------------------+------------------------------------------------------------------------------------------+
  | OS-DCF:diskConfig                    | MANUAL                                                                                   |
  | OS-EXT-AZ:availability_zone          | nova                                                                                     |
  | OS-EXT-SRV-ATTR:host                 | compute3                                                                                 |
  | OS-EXT-SRV-ATTR:hypervisor_hostname  | compute3.serverel.net                                                                    |
  | OS-EXT-SRV-ATTR:instance_name        | instance-0000010e                                                                        |
  | OS-EXT-STS:power_state               | 1                                                                                        |
  | OS-EXT-STS:task_state                | -                                                                                        |
  | OS-EXT-STS:vm_state                  | active                                                                                   |
  | OS-SRV-USG:launched_at               | 2016-01-21T11:24:14.000000                                                               |
  | OS-SRV-USG:terminated_at             | -                                                                                        |
  | accessIPv4                           |                                                                                          |
  | accessIPv6                           |                                                                                          |
  | config_drive                         |                                                                                          |
  | created                              | 2016-01-21T11:24:08Z                                                                     |
  | flavor                               | CL-1_PR-69_vCPUs-1_RAM-512_Disk-5_RxTx_Factor-1.0 (f807d233-1aec-44d5-828f-785137b0b687) |
  | hostId                               | 4b5575c8d545b442b101a6c6f9fd1f5224974e465b7bfcc43d90730a                                 |
  | id                                   | 5f844d05-405f-4997-b542-0c85d1b6c8ed                                                     |
  | image                                | cirros (ea3dfccd-3099-4584-8cb8-6017bc3faa2a)                                            |
  | key_name                             | -                                                                                        |
  | metadata                             | {}                                                                                       |
  | name                                 | test12                                                                                   |
  | os-extended-volumes:volumes_attached | []                                                                                       |
  | progress                             | 0                                                                                        |
  | pubnet1-591 network                  | 199.182.165.231                                                                          |
  | security_groups                      | default                                                                                  |
  | status                               | ACTIVE                                                                                   |
  | tenant_id                            | 73eb606e175249049987ec6a5774f282                                                         |
  | updated                              | 2016-01-21T11:26:17Z                                                                     |
  | user_id                              | 8855a4b15321469c8b44bbc1e0ea5320                                                         |
  +--------------------------------------+------------------------------------------------------------------------------------------+

  In nova-compute.log at compute node for request req-71688344-840e-4cb4
  -ba3e-21e4c0a85db7 I get:

  2016-01-21 11:26:17.046 36019 DEBUG oslo_concurrency.lockutils [req-71688344-840e-4cb4-ba3e-21e4c0a85db7 8855a4b15321469c8b44bbc1e0ea5320 73eb606e175249049987ec6a5774f282 - - -] Lock "compute_resources" acquired by "nova.compute.resource_tracker.update_usage" :: waited 0.000s inner /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:253
  2016-01-21 11:26:17.093 36019 DEBUG oslo_concurrency.lockutils [req-71688344-840e-4cb4-ba3e-21e4c0a85db7 8855a4b15321469c8b44bbc1e0ea5320 73eb606e175249049987ec6a5774f282 - - -] Lock "compute_resources" released by "nova.compute.resource_tracker.update_usage" :: held 0.047s inner /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:265
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher [req-71688344-840e-4cb4-ba3e-21e4c0a85db7 8855a4b15321469c8b44bbc1e0ea5320 73eb606e175249049987ec6a5774f282 - - -] Exception during message handling: Action for request_id req-71688344-840e-4cb4-ba3e-21e4c0a85db7 on instance 5f844d05-405f-4997-b542-0c85d1b6c8ed not found
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher Traceback (most recent call last):
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 142, in _dispatch_and_reply
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher     executor_callback))
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 186, in _dispatch
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher     executor_callback)
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 129, in _do_dispatch
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher     result = func(ctxt, **new_args)
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/nova/exception.py", line 89, in wrapped
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher     payload)
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 195, in __exit__
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/nova/exception.py", line 72, in wrapped
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher     return f(self, context, *args, **kw)
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 350, in decorated_function
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher     LOG.warning(msg, e, instance=instance)
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 195, in __exit__
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 323, in decorated_function
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 399, in decorated_function
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher     with compute_utils.EventReporter(context, event_name, instance_uuid):
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/nova/compute/utils.py", line 537, in __enter__
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher     self.context, uuid, self.event_name, want_result=False)
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/oslo_versionedobjects/base.py", line 169, in wrapper
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher     args, kwargs)
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/nova/conductor/rpcapi.py", line 229, in object_class_action
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher     args, kwargs)
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/nova/conductor/rpcapi.py", line 237, in object_class_action_versions
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher     args=args, kwargs=kwargs)
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/oslo_messaging/rpc/client.py", line 158, in call
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher     retry=self.retry)
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/oslo_messaging/transport.py", line 90, in _send
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher     timeout=timeout, retry=retry)
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 431, in send
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher     retry=retry)
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 422, in _send
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher     raise result
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher InstanceActionNotFound_Remote: Action for request_id req-71688344-840e-4cb4-ba3e-21e4c0a85db7 on instance 5f844d05-405f-4997-b542-0c85d1b6c8ed not found
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher Traceback (most recent call last):
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher 
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/nova/conductor/manager.py", line 447, in _object_dispatch
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher     return getattr(target, method)(*args, **kwargs)
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher 
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/oslo_versionedobjects/base.py", line 171, in wrapper
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher     result = fn(cls, context, *args, **kwargs)
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher 
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/nova/objects/instance_action.py", line 173, in event_start
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher     db_event = db.action_event_start(context, values)
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher 
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/nova/db/api.py", line 1806, in action_event_start
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher     return IMPL.action_event_start(context, values)
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher 
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/nova/db/sqlalchemy/api.py", line 5768, in action_event_start
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher     instance_uuid=values['instance_uuid'])
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher 
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher InstanceActionNotFound: Action for request_id req-71688344-840e-4cb4-ba3e-21e4c0a85db7 on instance 5f844d05-405f-4997-b542-0c85d1b6c8ed not found
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher 
  2016-01-21 11:26:17.102 36019 ERROR oslo_messaging.rpc.dispatcher

  For request req-eba0435f-610a-47cd-841f-f3500c7b66b7 instance rebooted
  successfully.

  The same problems with "InstanceActionNotFound" in nova-compute.log
  periodically happens with other actions (stop/start instances), but
  actions always finish successfully

  root@controller1:/var/log# dpkg -l | grep nova
  ii  nova-api                                 2:12.0.0-0ubuntu2~cloud0              all          OpenStack Compute - API frontend
  ii  nova-cert                                2:12.0.0-0ubuntu2~cloud0              all          OpenStack Compute - certificate management
  ii  nova-common                              2:12.0.0-0ubuntu2~cloud0              all          OpenStack Compute - common files
  ii  nova-conductor                           2:12.0.0-0ubuntu2~cloud0              all          OpenStack Compute - conductor service
  ii  nova-consoleauth                         2:12.0.0-0ubuntu2~cloud0              all          OpenStack Compute - Console Authenticator
  ii  nova-novncproxy                          2:12.0.0-0ubuntu2~cloud0              all          OpenStack Compute - NoVNC proxy
  ii  nova-scheduler                           2:12.0.0-0ubuntu2~cloud0              all          OpenStack Compute - virtual machine scheduler
  ii  python-nova                              2:12.0.0-0ubuntu2~cloud0              all          OpenStack Compute Python libraries
  ii  python-novaclient                        2:2.30.1-1~cloud0                     all          client library for OpenStack Compute API

  root@compute3:/etc# dpkg -l | grep nova
  ii  nova-common                          2:12.0.0-0ubuntu2~cloud0              all          OpenStack Compute - common files
  ii  nova-compute                         2:12.0.0-0ubuntu2~cloud0              all          OpenStack Compute - compute node base
  ii  nova-compute-kvm                     2:12.0.0-0ubuntu2~cloud0              all          OpenStack Compute - compute node (KVM)
  ii  nova-compute-libvirt                 2:12.0.0-0ubuntu2~cloud0              all          OpenStack Compute - compute node libvirt support
  ii  python-nova                          2:12.0.0-0ubuntu2~cloud0              all          OpenStack Compute Python libraries
  ii  python-novaclient                    2:2.30.1-1~cloud0                     all          client library for OpenStack Compute API

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1536610/+subscriptions
References

[Bug 1536610] [NEW] nova instance actions periodically have no start and finish time (empty events[])
From: Pavel Djakonov, 2016-01-21