In order to make it easier for people to read KVM autotest logs,
went through the virt module and the kvm test, removing some not
overly useful debug messages and modified others. Some things that
were modified:
1) Removed MAC address management messages
2) Removed ellipses from most of the debug messages, as they're
unnecessary
Signed-off-by: Lucas Meneghel Rodrigues <lmr@xxxxxxxxxx>
---
client/tests/kvm/kvm.py | 2 -
client/virt/kvm_vm.py | 15 ++++-------
client/virt/virt_env_process.py | 50 ++++++++++++++++++--------------------
client/virt/virt_test_setup.py | 18 +++++++-------
client/virt/virt_test_utils.py | 14 +++++-----
client/virt/virt_utils.py | 16 ++++--------
client/virt/virt_vm.py | 13 ++++-----
7 files changed, 57 insertions(+), 71 deletions(-)
diff --git a/client/tests/kvm/kvm.py b/client/tests/kvm/kvm.py
index 84c361e..c69ad46 100644
--- a/client/tests/kvm/kvm.py
+++ b/client/tests/kvm/kvm.py
@@ -45,8 +45,6 @@ class kvm(test.test):
virt_utils.set_log_file_dir(self.debugdir)
# Open the environment file
- logging.info("Unpickling env. You may see some harmless error "
- "messages.")
env_filename = os.path.join(self.bindir, params.get("env", "env"))
env = virt_utils.Env(env_filename, self.env_version)
diff --git a/client/virt/kvm_vm.py b/client/virt/kvm_vm.py
index b7afeeb..a2f22b4 100644
--- a/client/virt/kvm_vm.py
+++ b/client/virt/kvm_vm.py
@@ -393,9 +393,6 @@ class VM(virt_vm.BaseVM):
qemu_binary = virt_utils.get_path(root_dir, params.get("qemu_binary",
"qemu"))
- # Get the output of 'qemu -help' (log a message in case this call never
- # returns or causes some other kind of trouble)
- logging.debug("Getting output of 'qemu -help'")
help = commands.getoutput("%s -help" % qemu_binary)
# Start constructing the qemu command
@@ -877,11 +874,11 @@ class VM(virt_vm.BaseVM):
if self.is_dead():
return
- logging.debug("Destroying VM with PID %s...", self.get_pid())
+ logging.debug("Destroying VM with PID %s", self.get_pid())
if gracefully and self.params.get("shutdown_command"):
# Try to destroy with shell command
- logging.debug("Trying to shutdown VM with shell command...")
+ logging.debug("Trying to shutdown VM with shell command")
try:
session = self.login()
except (virt_utils.LoginError, virt_vm.VMError), e:
@@ -891,7 +888,7 @@ class VM(virt_vm.BaseVM):
# Send the shutdown command
session.sendline(self.params.get("shutdown_command"))
logging.debug("Shutdown command sent; waiting for VM "
- "to go down...")
+ "to go down")
if virt_utils.wait_for(self.is_dead, 60, 1, 1):
logging.debug("VM is down")
return
@@ -900,7 +897,7 @@ class VM(virt_vm.BaseVM):
if self.monitor:
# Try to destroy with a monitor command
- logging.debug("Trying to kill VM with monitor command...")
+ logging.debug("Trying to kill VM with monitor command")
try:
self.monitor.quit()
except kvm_monitor.MonitorError, e:
@@ -912,8 +909,8 @@ class VM(virt_vm.BaseVM):
return
# If the VM isn't dead yet...
- logging.debug("Cannot quit normally; sending a kill to close the "
- "deal...")
+ logging.debug("Cannot quit normally, sending a kill to close the "
+ "deal")
virt_utils.kill_process_tree(self.process.get_pid(), 9)
# Wait for the VM to be really dead
if virt_utils.wait_for(self.is_dead, 5, 0.5, 0.5):
diff --git a/client/virt/virt_env_process.py b/client/virt/virt_env_process.py
index b237ed2..b47a9a5 100644
--- a/client/virt/virt_env_process.py
+++ b/client/virt/virt_env_process.py
@@ -29,11 +29,10 @@ def preprocess_image(test, params):
create_image = False
if params.get("force_create_image") == "yes":
- logging.debug("'force_create_image' specified; creating image...")
+ logging.debug("Param 'force_create_image' specified, creating image")
create_image = True
elif (params.get("create_image") == "yes" and not
os.path.exists(image_filename)):
- logging.debug("Creating image...")
create_image = True
if create_image and not virt_vm.create_image(params, test.bindir):
@@ -50,10 +49,10 @@ def preprocess_vm(test, params, env, name):
@param env: The environment (a dict-like object).
@param name: The name of the VM object.
"""
- logging.debug("Preprocessing VM '%s'..." % name)
+ logging.debug("Preprocessing VM '%s'", name)
vm = env.get_vm(name)
if not vm:
- logging.debug("VM object does not exist; creating it")
+ logging.debug("VM object for '%s' does not exist, creating it", name)
vm_type = params.get('vm_type')
if vm_type == 'kvm':
vm = kvm_vm.VM(name, params, test.bindir, env.get("address_cache"))
@@ -62,18 +61,19 @@ def preprocess_vm(test, params, env, name):
start_vm = False
if params.get("restart_vm") == "yes":
- logging.debug("'restart_vm' specified; (re)starting VM...")
+ logging.debug("Param 'restart_vm' specified, (re)starting VM")
start_vm = True
elif params.get("migration_mode"):
- logging.debug("Starting VM in incoming migration mode...")
+ logging.debug("Param 'migration_mode specified, starting VM in "
+ "incoming migration mode")
start_vm = True
elif params.get("start_vm") == "yes":
if not vm.is_alive():
- logging.debug("VM is not alive; starting it...")
+ logging.debug("VM is not alive, starting it")
start_vm = True
if vm.needs_restart(name=name, params=params, basedir=test.bindir):
logging.debug("Current VM specs differ from requested one; "
- "restarting it...")
+ "restarting it")
start_vm = True
if start_vm:
@@ -115,7 +115,7 @@ def postprocess_vm(test, params, env, name):
@param env: The environment (a dict-like object).
@param name: The name of the VM object.
"""
- logging.debug("Postprocessing VM '%s'..." % name)
+ logging.debug("Postprocessing VM '%s'" % name)
vm = env.get_vm(name)
if not vm:
return
@@ -130,11 +130,11 @@ def postprocess_vm(test, params, env, name):
if params.get("kill_vm") == "yes":
kill_vm_timeout = float(params.get("kill_vm_timeout", 0))
if kill_vm_timeout:
- logging.debug("'kill_vm' specified; waiting for VM to shut down "
- "before killing it...")
+ logging.debug("Param 'kill_vm' specified, waiting for VM to shut "
+ "down before killing it")
virt_utils.wait_for(vm.is_dead, kill_vm_timeout, 0, 1)
else:
- logging.debug("'kill_vm' specified; killing VM...")
+ logging.debug("Param 'kill_vm' specified, killing VM")
vm.destroy(gracefully = params.get("kill_vm_gracefully") == "yes")
@@ -162,6 +162,7 @@ def process_command(test, params, env, command, command_timeout,
else:
raise
+
def process(test, params, env, image_func, vm_func):
"""
Pre- or post-process VMs and images according to the instructions in params.
@@ -209,7 +210,7 @@ def preprocess(test, params, env):
del env["tcpdump"]
if "tcpdump" not in env and params.get("run_tcpdump", "yes") == "yes":
cmd = "%s -npvi any 'dst port 68'" % virt_utils.find_command("tcpdump")
- logging.debug("Starting tcpdump (%s)...", cmd)
+ logging.debug("Starting tcpdump '%s'", cmd)
env["tcpdump"] = aexpect.Tail(
command=cmd,
output_func=_update_address_cache,
@@ -229,12 +230,11 @@ def preprocess(test, params, env):
continue
if not vm.name in requested_vms:
logging.debug("VM '%s' found in environment but not required for "
- "test; removing it..." % vm.name)
+ "test, destroying it" % vm.name)
vm.destroy()
del env[key]
# Get the KVM kernel module version and write it as a keyval
- logging.debug("Fetching KVM module version...")
if os.path.exists("/dev/kvm"):
try:
kvm_version = open("/sys/module/kvm/version").read().strip()
@@ -247,7 +247,6 @@ def preprocess(test, params, env):
test.write_test_keyval({"kvm_version": kvm_version})
# Get the KVM userspace version and write it as a keyval
- logging.debug("Fetching KVM userspace version...")
qemu_path = virt_utils.get_path(test.bindir, params.get("qemu_binary",
"qemu"))
version_line = commands.getoutput("%s -help | head -n 1" % qemu_path)
@@ -256,7 +255,6 @@ def preprocess(test, params, env):
kvm_userspace_version = " ".join(matches[0].split()[1:]).strip(",")
else:
kvm_userspace_version = "Unknown"
- logging.debug("Could not fetch KVM userspace version")
logging.debug("KVM userspace version: %s" % kvm_userspace_version)
test.write_test_keyval({"kvm_userspace_version": kvm_userspace_version})
@@ -300,7 +298,7 @@ def postprocess(test, params, env):
# Terminate the screendump thread
global _screendump_thread, _screendump_thread_termination_event
if _screendump_thread:
- logging.debug("Terminating screendump thread...")
+ logging.debug("Terminating screendump thread")
_screendump_thread_termination_event.set()
_screendump_thread.join(10)
_screendump_thread = None
@@ -312,8 +310,8 @@ def postprocess(test, params, env):
# Should we convert PPM files to PNG format?
if params.get("convert_ppm_files_to_png") == "yes":
- logging.debug("'convert_ppm_files_to_png' specified; converting PPM "
- "files to PNG format...")
+ logging.debug("Param 'convert_ppm_files_to_png' specified, converting "
+ "PPM files to PNG format")
try:
for f in glob.glob(os.path.join(test.debugdir, "*.ppm")):
if ppm_utils.image_verify_ppm_file(f):
@@ -325,23 +323,23 @@ def postprocess(test, params, env):
# Should we keep the PPM files?
if params.get("keep_ppm_files") != "yes":
- logging.debug("'keep_ppm_files' not specified; removing all PPM files "
- "from debug dir...")
+ logging.debug("Param 'keep_ppm_files' not specified, removing all PPM "
+ "files from debug dir")
for f in glob.glob(os.path.join(test.debugdir, '*.ppm')):
os.unlink(f)
# Should we keep the screendump dirs?
if params.get("keep_screendumps") != "yes":
- logging.debug("'keep_screendumps' not specified; removing screendump "
- "dirs...")
+ logging.debug("Param 'keep_screendumps' not specified, removing "
+ "screendump dirs")
for d in glob.glob(os.path.join(test.debugdir, "screendumps_*")):
if os.path.isdir(d) and not os.path.islink(d):
shutil.rmtree(d, ignore_errors=True)
# Kill all unresponsive VMs
if params.get("kill_unresponsive_vms") == "yes":
- logging.debug("'kill_unresponsive_vms' specified; killing all VMs "
- "that fail to respond to a remote login request...")
+ logging.debug("Param 'kill_unresponsive_vms' specified, killing all "
+ "VMs that fail to respond to a remote login request")
for vm in env.get_all_vms():
if vm.is_alive():
try:
diff --git a/client/virt/virt_test_setup.py b/client/virt/virt_test_setup.py
index 2717014..6e2d477 100644
--- a/client/virt/virt_test_setup.py
+++ b/client/virt/virt_test_setup.py
@@ -352,14 +352,14 @@ class PrivateBridgeConfig(object):
def _start_dhcp_server(self):
- utils.system("service dnsmasq stop")
- utils.system("dnsmasq --strict-order --bind-interfaces "
- "--listen-address %s.1 --dhcp-range %s.2,%s.254 "
- "--dhcp-lease-max=253 "
- "--dhcp-no-override "
- "--pid-file=/tmp/dnsmasq.pid "
- "--log-facility=/tmp/dnsmasq.log" %
- (self.subnet, self.subnet, self.subnet))
+ utils.run("service dnsmasq stop")
+ utils.run("dnsmasq --strict-order --bind-interfaces "
+ "--listen-address %s.1 --dhcp-range %s.2,%s.254 "
+ "--dhcp-lease-max=253 "
+ "--dhcp-no-override "
+ "--pid-file=/tmp/dnsmasq.pid "
+ "--log-facility=/tmp/dnsmasq.log" %
+ (self.subnet, self.subnet, self.subnet))
self.dhcp_server_pid = None
try:
self.dhcp_server_pid = int(open('/tmp/dnsmasq.pid', 'r').read())
@@ -378,7 +378,7 @@ class PrivateBridgeConfig(object):
def setup(self):
brctl_output = utils.system_output("brctl show")
if self.brname not in brctl_output:
- logging.info("Configuring KVM test private bridge %s", self.brname)
+ logging.debug("Configuring KVM test private bridge %s", self.brname)
try:
self._add_bridge()
except:
diff --git a/client/virt/virt_test_utils.py b/client/virt/virt_test_utils.py
index 2636352..30d7da8 100644
--- a/client/virt/virt_test_utils.py
+++ b/client/virt/virt_test_utils.py
@@ -107,7 +107,7 @@ def reboot(vm, session, method="shell", sleep_before_reset=10, nic_index=0,
if method == "shell":
# Send a reboot command to the guest's shell
session.sendline(vm.get_params().get("reboot_command"))
- logging.info("Reboot command sent. Waiting for guest to go down...")
+ logging.info("Reboot command sent. Waiting for guest to go down")
elif method == "system_reset":
# Sleep for a while before sending the command
time.sleep(sleep_before_reset)
@@ -118,7 +118,7 @@ def reboot(vm, session, method="shell", sleep_before_reset=10, nic_index=0,
# Send a system_reset monitor command
vm.monitor.cmd("system_reset")
logging.info("Monitor command system_reset sent. Waiting for guest to "
- "go down...")
+ "go down")
# Look for RESET QMP events
time.sleep(1)
for m in monitors:
@@ -193,7 +193,7 @@ def migrate(vm, env=None, mig_timeout=3600, mig_protocol="tcp",
def wait_for_migration():
if not virt_utils.wait_for(mig_finished, mig_timeout, 2, 2,
- "Waiting for migration to finish..."):
+ "Waiting for migration to finish"):
raise error.TestFail("Timeout expired while waiting for migration "
"to finish")
@@ -278,7 +278,7 @@ def migrate(vm, env=None, mig_timeout=3600, mig_protocol="tcp",
if dest_host == 'localhost':
if "paused" in dest_vm.monitor.info("status"):
- logging.debug("Destination VM is paused, resuming it...")
+ logging.debug("Destination VM is paused, resuming it")
dest_vm.monitor.cmd("cont")
# Kill the source VM
@@ -479,7 +479,7 @@ def run_autotest(vm, session, control_path, timeout, outputdir, params):
@param dest_dir: Destination dir for the contents
"""
basename = os.path.basename(remote_path)
- logging.info("Extracting %s...", basename)
+ logging.debug("Extracting %s on VM %s", basename, vm.name)
e_cmd = "tar xjvf %s -C %s" % (remote_path, dest_dir)
session.cmd(e_cmd, timeout=120)
@@ -488,7 +488,7 @@ def run_autotest(vm, session, control_path, timeout, outputdir, params):
"""
Copy autotest results present on the guest back to the host.
"""
- logging.info("Trying to copy autotest results from guest")
+ logging.debug("Trying to copy autotest results from guest")
guest_results_dir = os.path.join(outputdir, "guest_autotest_results")
if not os.path.exists(guest_results_dir):
os.mkdir(guest_results_dir)
@@ -576,7 +576,7 @@ def run_autotest(vm, session, control_path, timeout, outputdir, params):
while bg.is_alive():
logging.info("Tests is not ended, start a round of"
- "migration ...")
+ "migration")
vm.migrate(timeout=mig_timeout, protocol=mig_protocol)
else:
session.cmd_output("bin/autotest control", timeout=timeout,
diff --git a/client/virt/virt_utils.py b/client/virt/virt_utils.py
index 89a1193..d443a84 100644
--- a/client/virt/virt_utils.py
+++ b/client/virt/virt_utils.py
@@ -296,15 +296,12 @@ def _generate_mac_address_prefix(mac_pool):
"""
if "prefix" in mac_pool:
prefix = mac_pool["prefix"]
- logging.debug("Used previously generated MAC address prefix for this "
- "host: %s", prefix)
else:
r = random.SystemRandom()
prefix = "9a:%02x:%02x:%02x:" % (r.randint(0x00, 0xff),
r.randint(0x00, 0xff),
r.randint(0x00, 0xff))
mac_pool["prefix"] = prefix
- logging.debug("Generated MAC address prefix for this host: %s", prefix)
return prefix
@@ -334,7 +331,6 @@ def generate_mac_address(vm_instance, nic_index):
if mac in mac_pool.values():
continue
mac_pool[key] = mac
- logging.debug("Generated MAC address for NIC %s: %s", key, mac)
_close_mac_pool(mac_pool, lock_file)
return mac
@@ -349,7 +345,6 @@ def free_mac_address(vm_instance, nic_index):
mac_pool, lock_file = _open_mac_pool(fcntl.LOCK_EX)
key = "%s:%s" % (vm_instance, nic_index)
if key in mac_pool:
- logging.debug("Freeing MAC address for NIC %s: %s", key, mac_pool[key])
del mac_pool[key]
_close_mac_pool(mac_pool, lock_file)
@@ -631,12 +626,12 @@ def _remote_login(session, username, password, prompt, timeout=10):
r"[Pp]lease wait", r"[Ww]arning", prompt],
timeout=timeout, internal_timeout=0.5)
if match == 0: # "Are you sure you want to continue connecting"
- logging.debug("Got 'Are you sure...'; sending 'yes'")
+ logging.debug("Got 'Are you sure...', sending 'yes'")
session.sendline("yes")
continue
elif match == 1: # "password:"
if password_prompt_count == 0:
- logging.debug("Got password prompt; sending '%s'", password)
+ logging.debug("Got password prompt, sending '%s'", password)
session.sendline(password)
password_prompt_count += 1
continue
@@ -783,12 +778,12 @@ def _remote_scp(session, password_list, transfer_timeout=600, login_timeout=10):
[r"[Aa]re you sure", r"[Pp]assword:\s*$", r"lost connection"],
timeout=timeout, internal_timeout=0.5)
if match == 0: # "Are you sure you want to continue connecting"
- logging.debug("Got 'Are you sure...'; sending 'yes'")
+ logging.debug("Got 'Are you sure...', sending 'yes'")
session.sendline("yes")
continue
elif match == 1: # "password:"
if password_prompt_count == 0:
- logging.debug("Got password prompt; sending '%s'" %
+ logging.debug("Got password prompt, sending '%s'" %
password_list[password_prompt_count])
session.sendline(password_list[password_prompt_count])
password_prompt_count += 1
@@ -797,7 +792,7 @@ def _remote_scp(session, password_list, transfer_timeout=600, login_timeout=10):
authentication_done = True
continue
elif password_prompt_count == 1 and scp_type == 2:
- logging.debug("Got password prompt; sending '%s'" %
+ logging.debug("Got password prompt, sending '%s'" %
password_list[password_prompt_count])
session.sendline(password_list[password_prompt_count])
password_prompt_count += 1
@@ -1181,7 +1176,6 @@ def wait_for(func, timeout, first=0.0, step=1.0, text=None):
time.sleep(step)
- logging.debug("Timeout elapsed")
return None
diff --git a/client/virt/virt_vm.py b/client/virt/virt_vm.py
index 7236218..8815bf4 100644
--- a/client/virt/virt_vm.py
+++ b/client/virt/virt_vm.py
@@ -240,7 +240,6 @@ def create_image(params, root_dir):
qemu_img_cmd += " %s" % size
utils.system(qemu_img_cmd)
- logging.info("Image created in %r", image_filename)
return image_filename
@@ -256,7 +255,7 @@ def remove_image(params, root_dir):
image_format -- the format of the image (qcow2, raw etc)
"""
image_filename = get_image_filename(params, root_dir)
- logging.debug("Removing image file %s...", image_filename)
+ logging.debug("Removing image file %s", image_filename)
if os.path.exists(image_filename):
os.unlink(image_filename)
else:
@@ -279,7 +278,7 @@ def check_image(params, root_dir):
vm_type = params.get("vm_type")
if vm_type == 'kvm':
image_filename = get_image_filename(params, root_dir)
- logging.debug("Checking image file %s...", image_filename)
+ logging.debug("Checking image file %s", image_filename)
qemu_img_cmd = virt_utils.get_path(root_dir,
params.get("qemu_img_binary", "qemu-img"))
image_is_qcow2 = params.get("image_format") == 'qcow2'
@@ -290,11 +289,11 @@ def check_image(params, root_dir):
check_img = True
if not "check" in q_output:
logging.error("qemu-img does not support 'check', "
- "skipping check...")
+ "skipping check")
check_img = False
if not "info" in q_output:
logging.error("qemu-img does not support 'info', "
- "skipping check...")
+ "skipping check")
check_img = False
if check_img:
try:
@@ -331,10 +330,10 @@ def check_image(params, root_dir):
else:
if not os.path.exists(image_filename):
- logging.debug("Image file %s not found, skipping check...",
+ logging.debug("Image file %s not found, skipping check",
image_filename)
elif not image_is_qcow2:
- logging.debug("Image file %s not qcow2, skipping check...",
+ logging.debug("Image file %s not qcow2, skipping check",
image_filename)
--
1.7.5.4
--
To unsubscribe from this list: send the line "unsubscribe kvm" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
