Public bug reported:

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

** Affects: nova
     Importance: Undecided
         Status: New

-- 
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):
  New

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

-- 
Mailing list: https://launchpad.net/~yahoo-eng-team
Post to     : yahoo-eng-team@lists.launchpad.net
Unsubscribe : https://launchpad.net/~yahoo-eng-team
More help   : https://help.launchpad.net/ListHelp

Reply via email to