instance not found trace log can be ignored while get-console-output

[wangpan]

during we cold-migrating or resizing an instance to another host(or during deleting it), the get_console_output
method may raise an InstanceNotFound excetpion if the instance is not on the hypervisor, this is an expected error,
so we should add the InstanceNotFound excetpion to expected exceptions list in the compute manager.

2014-03-14 11:59:58.884 AUDIT nova.compute.manager [req-6414594a-7fcd-427e-9ed6-1d78f12d40e0 demo demo] [instance: c68b2e95-8299-415a-a837-ff9f7303e6db] Get console output
2014-03-14 11:59:58.901 ERROR oslo.messaging._executors.base [-] Exception during message handling
2014-03-14 11:59:58.901 TRACE oslo.messaging._executors.base Traceback (most recent call last):
2014-03-14 11:59:58.901 TRACE oslo.messaging._executors.base File "/opt/stack/oslo.messaging/oslo/messaging/_executors/base.py", line 36, in _dispatch
2014-03-14 11:59:58.901 TRACE oslo.messaging._executors.base incoming.reply(self.callback(incoming.ctxt, incoming.message))
2014-03-14 11:59:58.901 TRACE oslo.messaging._executors.base File "/opt/stack/oslo.messaging/oslo/messaging/rpc/dispatcher.py", line 134, in __call__
2014-03-14 11:59:58.901 TRACE oslo.messaging._executors.base return self._dispatch(endpoint, method, ctxt, args)
2014-03-14 11:59:58.901 TRACE oslo.messaging._executors.base File "/opt/stack/oslo.messaging/oslo/messaging/rpc/dispatcher.py", line 104, in _dispatch
2014-03-14 11:59:58.901 TRACE oslo.messaging._executors.base result = getattr(endpoint, method)(ctxt, **new_args)
2014-03-14 11:59:58.901 TRACE oslo.messaging._executors.base File "/opt/stack/oslo.messaging/oslo/messaging/rpc/server.py", line 153, in inner
2014-03-14 11:59:58.901 TRACE oslo.messaging._executors.base return func(*args, **kwargs)
2014-03-14 11:59:58.901 TRACE oslo.messaging._executors.base File "/opt/stack/nova/nova/exception.py", line 88, in wrapped
2014-03-14 11:59:58.901 TRACE oslo.messaging._executors.base payload)
2014-03-14 11:59:58.901 TRACE oslo.messaging._executors.base File "/opt/stack/nova/nova/openstack/common/excutils.py", line 68, in __exit__
2014-03-14 11:59:58.901 TRACE oslo.messaging._executors.base six.reraise(self.type_, self.value, self.tb)
2014-03-14 11:59:58.901 TRACE oslo.messaging._executors.base File "/opt/stack/nova/nova/exception.py", line 71, in wrapped
2014-03-14 11:59:58.901 TRACE oslo.messaging._executors.base return f(self, context, *args, **kw)
2014-03-14 11:59:58.901 TRACE oslo.messaging._executors.base File "/opt/stack/nova/nova/compute/manager.py", line 293, in decorated_function
2014-03-14 11:59:58.901 TRACE oslo.messaging._executors.base return function(self, context, *args, **kwargs)
2014-03-14 11:59:58.901 TRACE oslo.messaging._executors.base File "/opt/stack/nova/nova/compute/manager.py", line 3932, in get_console_output
2014-03-14 11:59:58.901 TRACE oslo.messaging._executors.base output = self.driver.get_console_output(context, instance)
2014-03-14 11:59:58.901 TRACE oslo.messaging._executors.base File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 2268, in get_console_output
2014-03-14 11:59:58.901 TRACE oslo.messaging._executors.base virt_dom = self._lookup_by_name(instance.name)
2014-03-14 11:59:58.901 TRACE oslo.messaging._executors.base File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 3437, in _lookup_by_name
2014-03-14 11:59:58.901 TRACE oslo.messaging._executors.base raise exception.InstanceNotFound(instance_id=instance_name)
2014-03-14 11:59:58.901 TRACE oslo.messaging._executors.base InstanceNotFound: Instance instance-0000000c could not be found.
2014-03-14 11:59:58.901 TRACE oslo.messaging._executors.base

[wangpan (hzwangpan)]

we'd better get debug log like below:
2014-03-14 11:58:40.348 AUDIT nova.compute.manager [req-3d9c7f54-8247-4719-9bbd-37d9faffa0b2 demo demo] [instance: c68b2e95-8299-415a-a837-ff9f7303e6db] Get console output
2014-03-14 11:58:40.356 DEBUG oslo.messaging._executors.base [-] Expected exception during message handling (Instance instance-0000000c could not be found.) from (pid=4318) _dispatch /opt/stack/oslo.messaging/oslo/messaging/_executors/base.py:39

[wangpan (hzwangpan)]

https://review.openstack.org/#/c/80471/

[Openstack Gerrit (openstack-gerrit)]

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

commit 1c0c1eb01d45eb016ba6b2ad63b9e3e652365b34
Author: Wangpan <email address hidden>
Date: Fri Mar 14 12:08:29 2014 +0800

    Ignore InstanceNotFound while getting console output

    During we cold-migrating or resizing an instance to another host,
    or during deleting it, the get_console_output method may raise an
    InstanceNotFound excetpion if the instance is not on the hypervisor,
    this is an expected error, so we should add it to expected
    exceptions list in compute manager.

    Closes-bug: #1292339
    Change-Id: I23a99438d73826f01ff5662130dcbfa72dc39a6e

[Ondergetekende (kvdveer)]

I suspect the fix is not complete.

During migration, there is a window (which can be pretty large) where the instance is present on the new node, but the data is still being rsynced. When the rsync order is libvirt.xml, disk, console.log, the instance is already present, but opening (and chowning) the consolelog will throw ProcessExecutionError.

We're theorizing that's the mechanism behind this stacktrace (we're seing this on 30% of resizemigrations, as our user interface polls the console log by default)

Traceback (most recent call last):
  File "oslo/messaging/rpc/dispatcher.py", line 134, in _dispatch_and_reply
    incoming.message))
  File "oslo/messaging/rpc/dispatcher.py", line 177, in _dispatch
    return self._do_dispatch(endpoint, method, ctxt, args)
  File "oslo/messaging/rpc/dispatcher.py", line 123, in _do_dispatch
    result = getattr(endpoint, method)(ctxt, **new_args)
  File "oslo/messaging/rpc/server.py", line 137, in inner
    return func(*args, **kwargs)
  File "nova/exception.py", line 88, in wrapped
    payload)
  File "nova/openstack/common/excutils.py", line 68, in __exit__
    six.reraise(self.type_, self.value, self.tb)
  File "nova/exception.py", line 71, in wrapped
    return f(self, context, *args, **kw)
  File "nova/compute/manager.py", line 309, in decorated_function
    e, sys.exc_info())
  File "nova/openstack/common/excutils.py", line 68, in __exit__
    six.reraise(self.type_, self.value, self.tb)
  File "nova/compute/manager.py", line 296, in decorated_function
    return function(self, context, *args, **kwargs)
  File "nova/compute/manager.py", line 3939, in get_console_output
    output = self.driver.get_console_output(context, instance)
  File "nova/virt/libvirt/driver.py", line 2309, in get_console_output
    libvirt_utils.chown(path, os.getuid())
  File "nova/virt/libvirt/utils.py", line 539, in chown
    execute('chown', owner, path, run_as_root=True)
  File "nova/virt/libvirt/utils.py", line 53, in execute
    return utils.execute(*args, **kwargs)
  File "nova/utils.py", line 164, in execute
    return processutils.execute(*cmd, **kwargs)
  File "nova/openstack/common/processutils.py", line 193, in execute
    cmd=' '.join(cmd))
ProcessExecutionError: Unexpected error while running command.

[OpenStack Infra (hudson-openstack)]

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

commit cb88a77da869926fbf051ee4aa52ee6513c4d192
Author: Koert van der Veer <email address hidden>
Date: Wed Nov 26 19:48:51 2014 +0100

    Libvirt: Don't let get_console_output crash on missing console file.

    During a migration, the console file may be configured, even though
    the file itself is not yet present. This patch prevents a
    ProcessExecutionError which gets thrown by the chown if the file
    doesn't exist.

    Change-Id: Ifd75ae911fc264f8284ec3f2adbf1d73bc8c4aca
    Related-Bug: #1292339