Change in vdsm[ovirt-4.0]: rpc: Log RPC call summary on info level
by mzamazal＠redhat.com
Hello Piotr Kliczewski, Nir Soffer,
I'd like you to do a code review. Please visit
https://gerrit.ovirt.org/59998
to review the following change.
Change subject: rpc: Log RPC call summary on info level
......................................................................
rpc: Log RPC call summary on info level
We currently log relatively detailed information about all RPC calls.
This information is logged on the debug level. We are going to switch
to the info logging level sometimes in future and then information about
RPC calls won't be logged anymore. But we still want to see some very
basic information about the RPC calls, such as that they were performed
and how much time they took.
This patch adds the corresponding logging. We additionally add the
response to the context at a single place as a preparation for the
following patch that logs the response.
Change-Id: Idde2f1ba7394f16770543f5ca13411e8c2339cc6
Bug-Url: https://bugzilla.redhat.com/1351247
Backport-To: 4.0
Signed-off-by: Milan Zamazal <mzamazal(a)redhat.com>
Reviewed-on: https://gerrit.ovirt.org/59080
Reviewed-by: Nir Soffer <nsoffer(a)redhat.com>
Reviewed-by: Piotr Kliczewski <piotr.kliczewski(a)gmail.com>
Continuous-Integration: Jenkins CI
---
M lib/vdsm/rpc/bindingxmlrpc.py
M lib/yajsonrpc/__init__.py
2 files changed, 26 insertions(+), 11 deletions(-)
git pull ssh://gerrit.ovirt.org:29418/vdsm refs/changes/98/59998/1
diff --git a/lib/vdsm/rpc/bindingxmlrpc.py b/lib/vdsm/rpc/bindingxmlrpc.py
index 2c4765a..732918f 100644
--- a/lib/vdsm/rpc/bindingxmlrpc.py
+++ b/lib/vdsm/rpc/bindingxmlrpc.py
@@ -302,6 +302,8 @@
def _registerFunctions(self):
def wrapIrsMethod(f):
def wrapper(*args, **kwargs):
+ start_time = utils.monotonic_time()
+
fmt = ""
logargs = []
@@ -321,6 +323,10 @@
except:
self.log.error("Unexpected exception", exc_info=True)
return errCode['unexpected']
+ finally:
+ self.log.info("RPC call %s finished in %.2f seconds",
+ f.__name__,
+ utils.monotonic_time() - start_time)
wrapper.__name__ = f.__name__
wrapper.__doc__ = f.__doc__
@@ -1191,6 +1197,7 @@
def wrapApiMethod(f):
def wrapper(*args, **kwargs):
+ start_time = utils.monotonic_time()
try:
logLevel = logging.DEBUG
suppress_args = f.__name__ in ('fenceNode',)
@@ -1260,6 +1267,10 @@
except:
f.__self__.cif.log.error("unexpected error", exc_info=True)
return errCode['unexpected']
+ finally:
+ f.__self__.cif.log.info("RPC call %s finished in %.2f seconds",
+ f.__name__,
+ utils.monotonic_time() - start_time)
wrapper.__name__ = f.__name__
wrapper.__doc__ = f.__doc__
return wrapper
diff --git a/lib/yajsonrpc/__init__.py b/lib/yajsonrpc/__init__.py
index 71db724..ff8e4ae 100644
--- a/lib/yajsonrpc/__init__.py
+++ b/lib/yajsonrpc/__init__.py
@@ -501,6 +501,14 @@
self._counter = 0
def _serveRequest(self, ctx, req):
+ start_time = monotonic_time()
+ response = self._handle_request(req, ctx.server_address)
+ self.log.info("RPC call %s finished in %.2f seconds",
+ req.method, monotonic_time() - start_time)
+ if response is not None:
+ ctx.requestDone(response)
+
+ def _handle_request(self, req, server_address):
self._attempt_log_stats()
logLevel = logging.DEBUG
@@ -510,8 +518,7 @@
self.log.info("In recovery, ignoring '%s' in bridge with %s",
req.method, req.params)
# TODO: take the response from the exception instead of via errCode
- ctx.requestDone(JsonRpcResponse(errCode['recovery'], None, req.id))
- return
+ return JsonRpcResponse(errCode['recovery'], None, req.id)
self.log.log(logLevel, "Calling '%s' in bridge with %s",
req.method, req.params)
@@ -519,32 +526,29 @@
method = self._bridge.dispatch(req.method)
except JsonRpcMethodNotFoundError as e:
if req.isNotification():
- return
+ return None
- ctx.requestDone(JsonRpcResponse(None, e, req.id))
- return
+ return JsonRpcResponse(None, e, req.id)
try:
params = req.params
- self._bridge.register_server_address(ctx.server_address)
+ self._bridge.register_server_address(server_address)
if isinstance(req.params, list):
res = method(*params)
else:
res = method(**params)
self._bridge.unregister_server_address()
except JsonRpcError as e:
- ctx.requestDone(JsonRpcResponse(None, e, req.id))
+ return JsonRpcResponse(None, e, req.id)
except Exception as e:
self.log.exception("Internal server error")
- ctx.requestDone(JsonRpcResponse(None,
- JsonRpcInternalError(str(e)),
- req.id))
+ return JsonRpcResponse(None, JsonRpcInternalError(str(e)), req.id)
else:
self.log.log(logLevel, "Return '%s' in bridge with %s",
req.method, res)
if isinstance(res, Suppressed):
res = res.value
- ctx.requestDone(JsonRpcResponse(res, None, req.id))
+ return JsonRpcResponse(res, None, req.id)
@traceback(on=log.name)
def serve_requests(self):
--
To view, visit https://gerrit.ovirt.org/59998
To unsubscribe, visit https://gerrit.ovirt.org/settings
Gerrit-MessageType: newchange
Gerrit-Change-Id: Idde2f1ba7394f16770543f5ca13411e8c2339cc6
Gerrit-PatchSet: 1
Gerrit-Project: vdsm
Gerrit-Branch: ovirt-4.0
Gerrit-Owner: Milan Zamazal <mzamazal(a)redhat.com>
Gerrit-Reviewer: Nir Soffer <nsoffer(a)redhat.com>
Gerrit-Reviewer: Piotr Kliczewski <piotr.kliczewski(a)gmail.com>
7 years, 9 months
- 3
- 8
Change in vdsm[ovirt-3.6]: hooks: openstack hook should wait a while for nic activation
by mmirecki＠redhat.com
Hello Dan Kenigsberg, Francesco Romani,
I'd like you to do a code review. Please visit
https://gerrit.ovirt.org/60035
to review the following change.
Change subject: hooks: openstack hook should wait a while for nic activation
......................................................................
hooks: openstack hook should wait a while for nic activation
The vm will be stated in a paused state if a nic managed by
an external openstack network provider is present. The openstack
hook after_vm_start must then wait a given time to allow the
nic to be activated before unpausing the vm.
Change-Id: Ib4f455789909f090a039863fdcfeb61b9db1042f
Bug-Url: https://bugzilla.redhat.com/1314371
Signed-off-by: mirecki <mmirecki(a)redhat.com>
Reviewed-on: https://gerrit.ovirt.org/58917
Continuous-Integration: Jenkins CI
Reviewed-by: Dan Kenigsberg <danken(a)redhat.com>
Reviewed-by: Francesco Romani <fromani(a)redhat.com>
---
A vdsm_hooks/openstacknet/after_vm_start.py
M vdsm_hooks/openstacknet/before_device_create.py
M vdsm_hooks/openstacknet/openstacknet_utils.py
3 files changed, 84 insertions(+), 0 deletions(-)
git pull ssh://gerrit.ovirt.org:29418/vdsm refs/changes/35/60035/1
diff --git a/vdsm_hooks/openstacknet/after_vm_start.py b/vdsm_hooks/openstacknet/after_vm_start.py
new file mode 100644
index 0000000..6f5c1e5
--- /dev/null
+++ b/vdsm_hooks/openstacknet/after_vm_start.py
@@ -0,0 +1,53 @@
+#!/usr/bin/python
+
+'''
+OpenStack Network Hook (Post vm start)
+=============================================
+The hook unpauses a vm if it was started in the paused state.
+
+Syntax:
+ { 'vmId': 'VM_ID', 'vnic_id': 'port_id' }
+Where:
+ VM_ID should be replaced with the vm id.'''
+
+import libvirt
+import os
+import time
+import traceback
+import hooking
+from openstacknet_utils import MARK_FOR_UNPAUSE_PATH
+from openstacknet_utils import VM_ID_KEY
+from vdsm import vdscli
+
+
+OPENSTACK_NIC_WAIT_TIME = 15
+
+
+def resume_paused_vm(vm_id):
+ unpause_file = MARK_FOR_UNPAUSE_PATH % vm_id
+ if os.path.isfile(unpause_file):
+ vdscli.connect().cont(vm_id)
+ os.remove(unpause_file)
+
+
+def main():
+
+ # TODO (HACK):
+ # This code waits for the nic to be attached to neutron for a
+ # certain amount of time. This is one way of going around the
+ # race between the code and the vm nic becoming active. It is
+ # a very fragile hack, as there is no guarantee the nic will
+ # actually be ready after this.
+ vm_id = os.environ[VM_ID_KEY]
+ launch_flags = hooking.load_vm_launch_flags_from_file(vm_id)
+ if launch_flags == libvirt.VIR_DOMAIN_START_PAUSED:
+ time.sleep(OPENSTACK_NIC_WAIT_TIME)
+ resume_paused_vm(vm_id)
+
+
+if __name__ == '__main__':
+ try:
+ main()
+ except:
+ hooking.exit_hook('openstacknet hook: [unexpected error]: %s\n' %
+ traceback.format_exc())
diff --git a/vdsm_hooks/openstacknet/before_device_create.py b/vdsm_hooks/openstacknet/before_device_create.py
index c37f81a..3cc8376 100755
--- a/vdsm_hooks/openstacknet/before_device_create.py
+++ b/vdsm_hooks/openstacknet/before_device_create.py
@@ -31,6 +31,7 @@
'''
from __future__ import print_function
+import libvirt
import os
import sys
import traceback
@@ -39,12 +40,14 @@
import hooking
from openstacknet_utils import DUMMY_BRIDGE
from openstacknet_utils import INTEGRATION_BRIDGE
+from openstacknet_utils import MARK_FOR_UNPAUSE_PATH
from openstacknet_utils import OPENSTACK_NET_PROVIDER_TYPE
from openstacknet_utils import PLUGIN_TYPE_KEY
from openstacknet_utils import PROVIDER_TYPE_KEY
from openstacknet_utils import PT_BRIDGE
from openstacknet_utils import PT_OVS
from openstacknet_utils import SECURITY_GROUPS_KEY
+from openstacknet_utils import VM_ID_KEY
from openstacknet_utils import VNIC_ID_KEY
from openstacknet_utils import devName
from openstacknet_utils import setUpSecurityGroupVnic
@@ -120,6 +123,16 @@
hooking.exit_hook("Unknown plugin type: %s" % pluginType)
+def mark_for_unpause(vm_id):
+ unpause_file = MARK_FOR_UNPAUSE_PATH % vm_id
+ try:
+ os.makedirs(os.path.dirname(unpause_file))
+ except OSError:
+ pass
+ with open(unpause_file, mode='w') as f:
+ f.write("true")
+
+
def main():
if PROVIDER_TYPE_KEY not in os.environ:
return
@@ -135,6 +148,15 @@
addOpenstackVnic(domxml, pluginType, vNicId, hasSecurityGroups)
hooking.write_domxml(domxml)
+ vm_id = os.environ[VM_ID_KEY]
+ PAUSE_FLAG = libvirt.VIR_DOMAIN_START_PAUSED
+ flags = hooking.load_vm_launch_flags_from_file(vm_id)
+
+ if (flags & PAUSE_FLAG) != PAUSE_FLAG:
+ flags |= PAUSE_FLAG
+ hooking.dump_vm_launch_flags_to_file(vm_id, flags)
+ mark_for_unpause(vm_id)
+
def test(ovs, withSecurityGroups):
domxml = minidom.parseString("""<?xml version="1.0" encoding="utf-8"?>
diff --git a/vdsm_hooks/openstacknet/openstacknet_utils.py b/vdsm_hooks/openstacknet/openstacknet_utils.py
index 11623e7..d5245ad 100644
--- a/vdsm_hooks/openstacknet/openstacknet_utils.py
+++ b/vdsm_hooks/openstacknet/openstacknet_utils.py
@@ -2,11 +2,14 @@
from __future__ import print_function
import hooking
+import os
import subprocess
+from vdsm import constants
from vdsm.netinfo import DUMMY_BRIDGE
from vdsm.utils import CommandPath
# Constants for hook's API
+VM_ID_KEY = 'vmId'
PROVIDER_TYPE_KEY = 'provider_type'
OPENSTACK_NET_PROVIDER_TYPE = 'OPENSTACK_NETWORK'
VNIC_ID_KEY = 'vnic_id'
@@ -26,6 +29,12 @@
ovs_vsctl = CommandPath('ovs-vsctl',
'/usr/sbin/ovs-vsctl',
'/usr/bin/ovs-vsctl')
+MARK_FOR_UNPAUSE_FILE = 'marked_for_unpause'
+MARK_FOR_UNPAUSE_PATH = os.path.join(
+ constants.P_VDSM_RUN,
+ '%s',
+ MARK_FOR_UNPAUSE_FILE,
+)
# Make pyflakes happy
DUMMY_BRIDGE
--
To view, visit https://gerrit.ovirt.org/60035
To unsubscribe, visit https://gerrit.ovirt.org/settings
Gerrit-MessageType: newchange
Gerrit-Change-Id: Ib4f455789909f090a039863fdcfeb61b9db1042f
Gerrit-PatchSet: 1
Gerrit-Project: vdsm
Gerrit-Branch: ovirt-3.6
Gerrit-Owner: Marcin Mirecki <mmirecki(a)redhat.com>
Gerrit-Reviewer: Dan Kenigsberg <danken(a)redhat.com>
Gerrit-Reviewer: Francesco Romani <fromani(a)redhat.com>
7 years, 9 months
- 3
- 5
Change in vdsm[ovirt-4.0]: rpc: Log important info from VM stats
by mzamazal＠redhat.com
Hello Nir Soffer,
I'd like you to do a code review. Please visit
https://gerrit.ovirt.org/59997
to review the following change.
Change subject: rpc: Log important info from VM stats
......................................................................
rpc: Log important info from VM stats
Currently, we don't log results of getAllVmStats API calls. This is not
to fill logs with a lot of uninteresting information. But information
contained in the VM stats is useful and we'd like to have it somewhere.
A possible solution to these contradictory requirements is to log just
important information and to log it only occasionally. In this patch,
we introduce logging VM ids and states in getAllVmStats calls from time
to time.
We implement this as a rather general functionality. We are going to
use the same mechanism for other large API outputs in followup patches.
There may be performance concerns but please consider that we perform
data extraction only for calls that are global (not per VM) and that are
not very frequent (like every second or so). So the processing overhead
shouldn't hurt much and shouldn't be much big in comparison to creating
the returned data inside Vdsm.
Change-Id: Ifcbac615323b62fb9a27e5c0f5a4e98990076146
Signed-off-by: Milan Zamazal <mzamazal(a)redhat.com>
Bug-Url: https://bugzilla.redhat.com/1351247
Backport-To: 4.0
Backport-To: 3.6
Reviewed-on: https://gerrit.ovirt.org/58465
Continuous-Integration: Jenkins CI
Reviewed-by: Nir Soffer <nsoffer(a)redhat.com>
---
M lib/vdsm/logUtils.py
M tests/Makefile.am
A tests/logutils_test.py
M vdsm/API.py
4 files changed, 54 insertions(+), 1 deletion(-)
git pull ssh://gerrit.ovirt.org:29418/vdsm refs/changes/97/59997/1
diff --git a/lib/vdsm/logUtils.py b/lib/vdsm/logUtils.py
index 853889d..3794edd 100644
--- a/lib/vdsm/logUtils.py
+++ b/lib/vdsm/logUtils.py
@@ -219,3 +219,9 @@
def __repr__(self):
return '(suppressed)'
+
+
+class AllVmStatsValue(Suppressed):
+
+ def __repr__(self):
+ return repr({vm.get('vmId'): vm.get('status') for vm in self._value})
diff --git a/tests/Makefile.am b/tests/Makefile.am
index db35bdd..d9ffbf7 100644
--- a/tests/Makefile.am
+++ b/tests/Makefile.am
@@ -76,6 +76,7 @@
iscsiTests.py \
jobsTests.py \
libvirtconnectionTests.py \
+ logutils_test.py \
lvmTests.py \
main.py \
miscTests.py \
diff --git a/tests/logutils_test.py b/tests/logutils_test.py
new file mode 100644
index 0000000..ba9ef41
--- /dev/null
+++ b/tests/logutils_test.py
@@ -0,0 +1,40 @@
+#
+# Copyright 2016 Red Hat, Inc.
+#
+# This program is free software; you can redistribute it and/or modify
+# it under the terms of the GNU General Public License as published by
+# the Free Software Foundation; either version 2 of the License, or
+# (at your option) any later version.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+# GNU General Public License for more details.
+#
+# You should have received a copy of the GNU General Public License
+# along with this program; if not, write to the Free Software
+# Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA
+#
+# Refer to the README and COPYING files for full details of the license
+#
+
+from vdsm.logUtils import AllVmStatsValue
+
+from testlib import VdsmTestCase as TestCaseBase
+
+
+class TestAllVmStats(TestCaseBase):
+
+ _STATS = [{'foo': 'bar',
+ 'status': 'Up',
+ 'vmId': u'43f02a2d-e563-4f11-a7bc-9ee191cfeba1'},
+ {'foo': 'bar',
+ 'status': 'Powering up',
+ 'vmId': u'bd0d066b-971e-42f8-8bc6-d647ab7e0e70'}]
+ _SIMPLIFIED = ({u'43f02a2d-e563-4f11-a7bc-9ee191cfeba1': 'Up',
+ u'bd0d066b-971e-42f8-8bc6-d647ab7e0e70': 'Powering up'})
+
+ def test_allvmstats(self):
+ data = AllVmStatsValue(self._STATS)
+ result = str(data)
+ self.assertEqual(eval(result), self._SIMPLIFIED)
diff --git a/vdsm/API.py b/vdsm/API.py
index 753f6be..9d8f8ab 100644
--- a/vdsm/API.py
+++ b/vdsm/API.py
@@ -34,10 +34,11 @@
from vdsm import hostdev
from vdsm import response
from vdsm import supervdsm
+from vdsm import throttledlog
from vdsm import jobs
from vdsm import v2v
from vdsm.host import api as hostapi
-from vdsm.logUtils import Suppressed
+from vdsm.logUtils import AllVmStatsValue, Suppressed
from vdsm.storage import clusterlock
from vdsm.storage import misc
from vdsm.storage import constants as sc
@@ -64,6 +65,9 @@
# default message for system shutdown, will be displayed in guest
USER_SHUTDOWN_MESSAGE = 'System going down'
+
+
+throttledlog.throttle('getAllVmStats', 100)
def updateTimestamp():
@@ -1343,6 +1347,8 @@
hooks.before_get_all_vm_stats()
statsList = self._cif.getAllVmStats()
statsList = hooks.after_get_all_vm_stats(statsList)
+ throttledlog.info('getAllVmStats', "Current getAllVmStats: %s",
+ AllVmStatsValue(statsList))
return {'status': doneCode, 'statsList': Suppressed(statsList)}
def hostdevListByCaps(self, caps=None):
--
To view, visit https://gerrit.ovirt.org/59997
To unsubscribe, visit https://gerrit.ovirt.org/settings
Gerrit-MessageType: newchange
Gerrit-Change-Id: Ifcbac615323b62fb9a27e5c0f5a4e98990076146
Gerrit-PatchSet: 1
Gerrit-Project: vdsm
Gerrit-Branch: ovirt-4.0
Gerrit-Owner: Milan Zamazal <mzamazal(a)redhat.com>
Gerrit-Reviewer: Nir Soffer <nsoffer(a)redhat.com>
7 years, 9 months
- 3
- 4