From patchwork Fri May 22 19:16:43 2009 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Lucas Meneghel Rodrigues X-Patchwork-Id: 25447 Received: from vger.kernel.org (vger.kernel.org [209.132.176.167]) by demeter.kernel.org (8.14.2/8.14.2) with ESMTP id n4MJH4fR006473 for ; Fri, 22 May 2009 19:17:04 GMT Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1756726AbZEVTQz (ORCPT ); Fri, 22 May 2009 15:16:55 -0400 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1756340AbZEVTQy (ORCPT ); Fri, 22 May 2009 15:16:54 -0400 Received: from mx2.redhat.com ([66.187.237.31]:53843 "EHLO mx2.redhat.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752496AbZEVTQv (ORCPT ); Fri, 22 May 2009 15:16:51 -0400 Received: from int-mx2.corp.redhat.com (int-mx2.corp.redhat.com [172.16.27.26]) by mx2.redhat.com (8.13.8/8.13.8) with ESMTP id n4MJGqSf015112 for ; Fri, 22 May 2009 15:16:52 -0400 Received: from ns3.rdu.redhat.com (ns3.rdu.redhat.com [10.11.255.199]) by int-mx2.corp.redhat.com (8.13.1/8.13.1) with ESMTP id n4MJGp91008049; Fri, 22 May 2009 15:16:51 -0400 Received: from localhost.localdomain (vpn-13-120.rdu.redhat.com [10.11.13.120]) by ns3.rdu.redhat.com (8.13.8/8.13.8) with ESMTP id n4MJGmII031495; Fri, 22 May 2009 15:16:49 -0400 From: Lucas Meneghel Rodrigues To: kvm@vger.kernel.org Cc: "lmr@redhat.com" Subject: [PATCH 1/5] Moving from kvm_log to the upstream logging system. Date: Fri, 22 May 2009 16:16:43 -0300 Message-Id: <1243019807-21078-1-git-send-email-lmr@redhat.com> X-Scanned-By: MIMEDefang 2.58 on 172.16.27.26 Sender: kvm-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: kvm@vger.kernel.org From: lmr@redhat.com kvm_log can be replaced by the upstream logging system with advantages: * Uses the standard python module, that allows us to define multiple message destinations * It implements nearly all functionalities implemented on kvm_log This patch converts all kvm_log statements to logging statements. --- client/tests/kvm_runtest_2/kvm_guest_wizard.py | 14 ++-- client/tests/kvm_runtest_2/kvm_install.py | 56 +++++++------- client/tests/kvm_runtest_2/kvm_log.py | 60 -------------- client/tests/kvm_runtest_2/kvm_preprocessing.py | 58 +++++++------- client/tests/kvm_runtest_2/kvm_runtest_2.py | 18 ++-- client/tests/kvm_runtest_2/kvm_tests.py | 96 +++++++++++----------- client/tests/kvm_runtest_2/kvm_utils.py | 59 ++++++++------- client/tests/kvm_runtest_2/kvm_vm.py | 78 +++++++++--------- client/tests/kvm_runtest_2/stepmaker.py | 6 +- 9 files changed, 193 insertions(+), 252 deletions(-) delete mode 100644 client/tests/kvm_runtest_2/kvm_log.py diff --git a/client/tests/kvm_runtest_2/kvm_guest_wizard.py b/client/tests/kvm_runtest_2/kvm_guest_wizard.py index c89e12e..46de723 100644 --- a/client/tests/kvm_runtest_2/kvm_guest_wizard.py +++ b/client/tests/kvm_runtest_2/kvm_guest_wizard.py @@ -9,7 +9,7 @@ import shutil from autotest_lib.client.common_lib import utils, error import kvm_utils -import kvm_log +import logging import ppm_utils @@ -23,7 +23,7 @@ def handle_var(vm, params, varname): def barrier_2(vm, words, fail_if_stuck_for, stuck_detection_history, output_dir, data_scrdump_filename, current_step_num): if len(words) < 7: - kvm_log.error("Bad barrier_2 command line") + logging.error("Bad barrier_2 command line") return False cmd, dx, dy, x1, y1, md5sum, timeout = words[:7] @@ -69,7 +69,7 @@ def barrier_2(vm, words, fail_if_stuck_for, stuck_detection_history, output_dir, # Request screendump (status, output) = vm.send_monitor_cmd("screendump %s" % scrdump_filename) if status: - kvm_log.error("Could not fetch screendump") + logging.error("Could not fetch screendump") continue # Make sure image is valid @@ -108,7 +108,7 @@ def barrier_2(vm, words, fail_if_stuck_for, stuck_detection_history, output_dir, # What should we do with this failure? if words[-1] == "optional": - kvm_log.info(message) + logging.info(message) return False else: # Collect information and put it in output_dir @@ -126,7 +126,7 @@ def barrier_2(vm, words, fail_if_stuck_for, stuck_detection_history, output_dir, ppm_utils.image_write_to_ppm_file(comparison_filename, w, h, data) # Print error messages and fail the test long_message = message + "\n(see analysis at %s)" % output_dir - kvm_log.error(long_message) + logging.error(long_message) raise error.TestFail, message @@ -171,7 +171,7 @@ def run_steps(test, params, env): line = line.strip() if not line: continue - kvm_log.info(line) + logging.info(line) if line.startswith("#"): continue @@ -191,7 +191,7 @@ def run_steps(test, params, env): vm.send_key(words[1]) elif words[0] == "var": if not handle_var(vm, params, words[1]): - kvm_log.error("Variable not defined: %s" % words[1]) + logging.error("Variable not defined: %s" % words[1]) elif words[0] == "barrier_2": if current_screendump: scrdump_filename = os.path.join(ppm_utils.get_data_dir(steps_filename), current_screendump) diff --git a/client/tests/kvm_runtest_2/kvm_install.py b/client/tests/kvm_runtest_2/kvm_install.py index 8be5a93..1b3bb47 100755 --- a/client/tests/kvm_runtest_2/kvm_install.py +++ b/client/tests/kvm_runtest_2/kvm_install.py @@ -9,13 +9,13 @@ from datetime import * from autotest_lib.client.bin import utils, test from autotest_lib.client.common_lib import error -import kvm_log +import logging import kvm_utils def run_kvm_install(test, params, env): install_mode = params.get("mode") - kvm_log.info("Selected installation mode: %s" % install_mode) + logging.info("Selected installation mode: %s" % install_mode) srcdir = params.get("srcdir", test.srcdir) if not os.path.exists(srcdir): @@ -23,7 +23,7 @@ def run_kvm_install(test, params, env): # do not install if install_mode == "noinstall": - kvm_log.info("Skipping installation") + logging.info("Skipping installation") # install from git elif install_mode == "git": @@ -35,11 +35,11 @@ def run_kvm_install(test, params, env): user_tag = params.get("user_git_tag", "HEAD") if not repo: message = "KVM git repository path not specified" - kvm_log.error(message) + logging.error(message) raise error.TestError, message if not user_repo: message = "KVM user git repository path not specified" - kvm_log.error(message) + logging.error(message) raise error.TestError, message __install_kvm_from_git(test, srcdir, repo, user_repo, branch, tag, user_tag, lbranch) @@ -50,7 +50,7 @@ def run_kvm_install(test, params, env): release_tag = params.get("release_tag") if not release_dir: message = "Release dir not specified" - kvm_log.error(message) + logging.error(message) raise error.TestError, message __install_kvm_release(test, srcdir, release_dir, release_tag) @@ -60,7 +60,7 @@ def run_kvm_install(test, params, env): snapshot_date = params.get("snapshot_date") if not snapshot_dir: message = "Snapshot dir not specified" - kvm_log.error(message) + logging.error(message) raise error.TestError, message __install_kvm_from_snapshot(test, srcdir, snapshot_dir, snapshot_date) @@ -69,7 +69,7 @@ def run_kvm_install(test, params, env): tarball = params.get("tarball") if not tarball: message = "Local tarball filename not specified" - kvm_log.error(message) + logging.error(message) raise error.TestError, message __install_kvm_from_local_tarball(test, srcdir, tarball) @@ -80,21 +80,21 @@ def run_kvm_install(test, params, env): # invalid installation mode else: message = "Invalid installation mode: '%s'" % install_mode - kvm_log.error(message) + logging.error(message) raise error.TestError, message # load kvm modules (unless requested not to) if params.get('load_modules', "yes") == "yes": __load_kvm_modules() else: - kvm_log.info("user requested not to load kvm modules") + logging.info("user requested not to load kvm modules") def __cleanup_dir(dir): # only alerts if src directory is not empty for root, dirs, files in os.walk(dir): if dirs or files: message = "Directory \'%s\' is not empty" % dir - kvm_log.error(message) + logging.error(message) raise error.TestError, message def __install_kvm_release(test, srcdir, release_dir, release_tag): @@ -115,10 +115,10 @@ def __install_kvm_release(test, srcdir, release_dir, release_tag): release_tag = matches[0] # the first match contains the latest release tag except Exception, e: message = "Could not fetch latest KVM release tag (%s)" % str(e) - kvm_log.error(message) + logging.error(message) raise error.TestError(message) - kvm_log.info("Installing release %s (kvm-%s)" % (release_tag, release_tag)) + logging.info("Installing release %s (kvm-%s)" % (release_tag, release_tag)) tarball = os.path.join(release_dir, "kvm-%s.tar.gz" % release_tag) tarball = utils.unmap_url("/", tarball, "/tmp") __install_kvm_from_local_tarball(test, srcdir, tarball) @@ -140,7 +140,7 @@ def __install_kvm_from_git(test, srcdir, repo, user_repo, branch, tag, def __get_git_branch(repository, branch, srcdir, commit=None, lbranch=None): - kvm_log.info("Getting sources from git to local directory <%s>" % (repository, branch, commit, srcdir)) + logging.info("Getting sources from git to local directory <%s>" % (repository, branch, commit, srcdir)) pwd = os.getcwd() os.chdir(srcdir) if os.path.exists(".git"): @@ -159,13 +159,13 @@ def __get_git_branch(repository, branch, srcdir, commit=None, lbranch=None): h = utils.system_output('git log --pretty=format:"%H" -1') desc = utils.system_output("git describe") - kvm_log.info("Commit hash for %s is %s (%s)" % (repository, h.strip(), desc)) + logging.info("Commit hash for %s is %s (%s)" % (repository, h.strip(), desc)) os.chdir(pwd) def __install_kvm_from_snapshot(test, srcdir, snapshot_dir ,snapshot_date): - kvm_log.info("Source snapshot dir: %s" % snaphost_dir) - kvm_log.info("Source snapshot date: %s" % snapshot_date) + logging.info("Source snapshot dir: %s" % snaphost_dir) + logging.info("Source snapshot date: %s" % snapshot_date) if not snapshot_date: d = (date.today() - timedelta(1)).strftime("%Y%m%d") # takes yesterday's snapshot @@ -173,7 +173,7 @@ def __install_kvm_from_snapshot(test, srcdir, snapshot_dir ,snapshot_date): d = snapshot_date tarball = os.path.join(snaphost_dir, "kvm-snapshot-%s.tar.gz" % d) - kvm_log.info("Tarball url: %s" % tarball) + logging.info("Tarball url: %s" % tarball) tarball = utils.unmap_url("/", tarball, "/tmp") __install_kvm_from_local_tarball(test, srcdir, tarball) @@ -189,15 +189,15 @@ def __install_kvm_from_local_tarball(test, srcdir, tarball): def __load_kvm_modules(): - kvm_log.info("Detecting CPU vendor...") + logging.info("Detecting CPU vendor...") vendor = "intel" if os.system("grep vmx /proc/cpuinfo 1>/dev/null") != 0: vendor = "amd" - kvm_log.info("Detected CPU vendor as '%s'" %(vendor)) + logging.info("Detected CPU vendor as '%s'" %(vendor)) #if self.config.load_modules == "yes": # remove existing in kernel kvm modules - kvm_log.info("Unloading loaded KVM modules (if present)...") + logging.info("Unloading loaded KVM modules (if present)...") #utils.system("pkill qemu 1>/dev/null 2>&1", ignore_status=True) utils.system("pkill qemu", ignore_status=True) #if utils.system("grep kvm_%s /proc/modules 1>/dev/null" % vendor, ignore_status=True) == 0: @@ -207,23 +207,23 @@ def __load_kvm_modules(): if utils.system("grep kvm /proc/modules 1>/dev/null", ignore_status=True) == 0: message = "Failed to remove old KVM modules" - kvm_log.error(message) + logging.error(message) raise error.TestError, message - kvm_log.info("Loading new KVM modules...") + logging.info("Loading new KVM modules...") os.chdir("kernel") if os.path.exists("x86"): os.chdir("x86") utils.system("/sbin/insmod ./kvm.ko && sleep 1 && /sbin/insmod ./kvm-%s.ko" % vendor) #elif self.config.load_modules == "no": - #kvm_log.info("user requested not to load kvm modules") + #logging.info("user requested not to load kvm modules") ### no matter if new kvm modules are to be loaded or not ### make sure there are kvm modules installed. if utils.system("grep kvm_%s /proc/modules 1>/dev/null" %(vendor), ignore_status=True) != 0: message = "Failed to load KVM modules" - kvm_log.error(message) + logging.error(message) raise error.TestError, message def __install_kvm(test, srcdir): @@ -239,10 +239,10 @@ def __install_kvm(test, srcdir): os.chdir(srcdir) # start working... - kvm_log.info("Building KVM...") + logging.info("Building KVM...") def run(cmd, title, timeout): - (status, pid, output) = kvm_utils.run_bg(cmd, None, kvm_log.info, + (status, pid, output) = kvm_utils.run_bg(cmd, None, logging.info, '(%s)' % title, timeout=timeout) if status != 0: kvm_utils.safe_kill(pid, signal.SIGTERM) @@ -280,4 +280,4 @@ def __install_kvm(test, srcdir): os.symlink(kvm_qemu, qemu_path) os.symlink(kvm_qemu_img, qemu_img_path) - kvm_log.info("Done building and installing KVM") + logging.info("Done building and installing KVM") diff --git a/client/tests/kvm_runtest_2/kvm_log.py b/client/tests/kvm_runtest_2/kvm_log.py deleted file mode 100644 index ff1dfe9..0000000 --- a/client/tests/kvm_runtest_2/kvm_log.py +++ /dev/null @@ -1,60 +0,0 @@ -#!/usr/bin/env python - -# Copyright: Red Hat 2008 -version = "20081205" - -import time -import sys - -prefix_stack = [""] -log_level = 4 - - -def name_of_caller(): - return sys._getframe(2).f_code.co_name - -def format_stack(min_depth, max_depth, stop_func): - list = [] - depth = min_depth - while depth <= max_depth: - try: - func_name = sys._getframe(depth).f_code.co_name - list.append(func_name) - if func_name == stop_func: - break - depth += 1 - except: - break - list.reverse() - return "|".join(list) - -def set_prefix(prefix): - global prefix_stack - prefix_stack.append(" %s" % prefix) - -def restore_prefix(): - global prefix_stack - prefix_stack.pop() - -def set_level(level): - global log_level - log_level = level - -def log(level, message, prefix=True): - if message.endswith("\n"): - message = message[:-1] - if level <= log_level: - if prefix: - print "%s%s: %s" % (time.strftime("%Y%m%d-%H%M%S"), prefix_stack[-1], message) - else: - print message - -def info(message): - log(1, message) - -def debug(message): - #log(1, "DEBUG: %s: %s" % (format_stack(2, 20, "run_once"), message), prefix=False) - log(3, "DEBUG: %s: %s" % (name_of_caller(), message)) - -def error(message): - log(0, "ERROR: %s: %s" % (name_of_caller(), message)) diff --git a/client/tests/kvm_runtest_2/kvm_preprocessing.py b/client/tests/kvm_runtest_2/kvm_preprocessing.py index c9eb35d..a233f7c 100644 --- a/client/tests/kvm_runtest_2/kvm_preprocessing.py +++ b/client/tests/kvm_runtest_2/kvm_preprocessing.py @@ -1,17 +1,13 @@ #!/usr/bin/python -import sys -import os -import time -import commands -import re +import sys, os, time, commands, re from autotest_lib.client.bin import test from autotest_lib.client.common_lib import error import kvm_vm import kvm_utils -import kvm_log +import logging def preprocess_image(test, params): @@ -29,16 +25,16 @@ def preprocess_image(test, params): create_image = False if params.get("force_create_image") == "yes": - kvm_log.debug("'force_create_image' specified; creating image...") + logging.debug("'force_create_image' specified; creating image...") create_image = True elif params.get("create_image") == "yes" and not os.path.exists(image_filename): - kvm_log.debug("Creating image...") + logging.debug("Creating image...") create_image = True if create_image: if not kvm_vm.create_image(params, qemu_img_path, image_dir): message = "Could not create image" - kvm_log.error(message) + logging.error(message) raise error.TestError, message @@ -56,12 +52,12 @@ def preprocess_vm(test, params, env, name): image_dir = os.path.join(test.bindir, "images") iso_dir = os.path.join(test.bindir, "isos") - kvm_log.debug("Preprocessing VM '%s'..." % name) + logging.debug("Preprocessing VM '%s'..." % name) vm = kvm_utils.env_get_vm(env, name) if vm: - kvm_log.debug("VM object found in environment") + logging.debug("VM object found in environment") else: - kvm_log.debug("VM object does not exist; creating it") + logging.debug("VM object does not exist; creating it") vm = kvm_vm.VM(name, params, qemu_path, image_dir, iso_dir) kvm_utils.env_register_vm(env, name, vm) @@ -69,25 +65,25 @@ def preprocess_vm(test, params, env, name): for_migration = False if params.get("start_vm_for_migration") == "yes": - kvm_log.debug("'start_vm_for_migration' specified; (re)starting VM with -incoming option...") + logging.debug("'start_vm_for_migration' specified; (re)starting VM with -incoming option...") start_vm = True for_migration = True elif params.get("restart_vm") == "yes": - kvm_log.debug("'restart_vm' specified; (re)starting VM...") + logging.debug("'restart_vm' specified; (re)starting VM...") start_vm = True elif params.get("start_vm") == "yes": if not vm.is_alive(): - kvm_log.debug("VM is not alive; starting it...") + logging.debug("VM is not alive; starting it...") start_vm = True elif vm.make_qemu_command() != vm.make_qemu_command(name, params, qemu_path, image_dir, iso_dir): - kvm_log.debug("VM's qemu command differs from requested one; restarting it...") + logging.debug("VM's qemu command differs from requested one; restarting it...") start_vm = True if start_vm: vm.destroy() if not vm.create(name, params, qemu_path, image_dir, iso_dir, for_migration): message = "Could not start VM" - kvm_log.error(message) + logging.error(message) raise error.TestError, message scrdump_filename = os.path.join(test.debugdir, "pre_%s.ppm" % name) @@ -118,12 +114,12 @@ def postprocess_vm(test, params, env, name): Kill the VM if requested and get a screendump. """ - kvm_log.debug("Postprocessing VM '%s'..." % name) + logging.debug("Postprocessing VM '%s'..." % name) vm = kvm_utils.env_get_vm(env, name) if vm: - kvm_log.debug("VM object found in environment") + logging.debug("VM object found in environment") else: - kvm_log.debug("VM object does not exist in environment") + logging.debug("VM object does not exist in environment") return scrdump_filename = os.path.join(test.debugdir, "post_%s.ppm" % name) @@ -133,7 +129,7 @@ def postprocess_vm(test, params, env, name): if not kvm_utils.wait_for(vm.is_dead, float(params.get("kill_vm_timeout", 0)), 0.0, 1.0, "Waiting for VM to kill itself..."): - kvm_log.debug("'kill_vm' specified; killing VM...") + logging.debug("'kill_vm' specified; killing VM...") vm.destroy(gracefully = params.get("kill_vm_gracefully") == "yes") @@ -178,7 +174,7 @@ def preprocess(test, params, env): if vm.is_dead(): continue if not vm.verify_process_identity(): - kvm_log.debug("VM '%s' seems to have been replaced by another process" % vm.name) + logging.debug("VM '%s' seems to have been replaced by another process" % vm.name) vm.pid = None # Destroy and remove VMs that are no longer needed in the environment @@ -188,7 +184,7 @@ def preprocess(test, params, env): if not kvm_utils.is_vm(vm): continue if not vm.name in requested_vms: - kvm_log.debug("VM '%s' found in environment but not required for test; removing it..." % vm.name) + logging.debug("VM '%s' found in environment but not required for test; removing it..." % vm.name) vm.destroy() del env[key] @@ -196,7 +192,7 @@ def preprocess(test, params, env): process(test, params, env, preprocess_image, preprocess_vm) # Get the KVM kernel module version and write it as a keyval - kvm_log.debug("Fetching KVM module version...") + logging.debug("Fetching KVM module version...") if os.path.exists("/dev/kvm"): kvm_version = os.uname()[2] try: @@ -207,12 +203,12 @@ def preprocess(test, params, env): pass else: kvm_version = "Unknown" - kvm_log.debug("KVM module not loaded") - kvm_log.debug("KVM version: %s" % kvm_version) + logging.debug("KVM module not loaded") + logging.debug("KVM version: %s" % kvm_version) test.write_test_keyval({"kvm_version": kvm_version}) # Get the KVM userspace version and write it as a keyval - kvm_log.debug("Fetching KVM userspace version...") + logging.debug("Fetching KVM userspace version...") qemu_path = os.path.join(test.bindir, "qemu") version_line = commands.getoutput("%s -help | head -n 1" % qemu_path) exp = re.compile("[Vv]ersion .*?,") @@ -221,8 +217,8 @@ def preprocess(test, params, env): kvm_userspace_version = " ".join(match.group().split()[1:]).strip(",") else: kvm_userspace_version = "Unknown" - kvm_log.debug("Could not fetch KVM userspace version") - kvm_log.debug("KVM userspace version: %s" % kvm_userspace_version) + 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}) @@ -238,8 +234,8 @@ def postprocess(test, params, env): # See if we should get rid of all PPM files if not params.get("keep_ppm_files") == "yes": # Remove them all - kvm_log.debug("'keep_ppm_files' not specified; removing all PPM files from results dir...") - kvm_utils.run_bg("rm -vf %s" % os.path.join(test.debugdir, "*.ppm"), None, kvm_log.debug, "(rm) ", timeout=5.0) + logging.debug("'keep_ppm_files' not specified; removing all PPM files from results dir...") + kvm_utils.run_bg("rm -vf %s" % os.path.join(test.debugdir, "*.ppm"), None, logging.debug, "(rm) ", timeout=5.0) def postprocess_on_error(test, params, env): diff --git a/client/tests/kvm_runtest_2/kvm_runtest_2.py b/client/tests/kvm_runtest_2/kvm_runtest_2.py index fda7282..5371d4b 100644 --- a/client/tests/kvm_runtest_2/kvm_runtest_2.py +++ b/client/tests/kvm_runtest_2/kvm_runtest_2.py @@ -42,7 +42,7 @@ class kvm_runtest_2(test.test): sys.path.append(self.bindir) def run_once(self, params): - import kvm_log + import logging import kvm_utils import kvm_preprocessing @@ -53,20 +53,20 @@ class kvm_runtest_2(test.test): resource.setrlimit(resource.RLIMIT_CORE, (-1, -1)) # Set the logging prefix - kvm_log.set_prefix(params.get("shortname")) + #kvm_log.set_prefix(params.get("shortname")) # Report the parameters we've received and write them as keyvals - kvm_log.debug("Test parameters:") + logging.debug("Test parameters:") keys = params.keys() keys.sort() for key in keys: - kvm_log.debug(" %s = %s" % (key, params[key])) + logging.debug(" %s = %s" % (key, params[key])) self.write_test_keyval({key: params[key]}) # Open the environment file env_filename = os.path.join(self.bindir, "env") env = shelve.open(env_filename, writeback=True) - kvm_log.debug("Contents of environment: %s" % str(env)) + logging.debug("Contents of environment: %s" % str(env)) try: try: @@ -76,7 +76,7 @@ class kvm_runtest_2(test.test): # If type could not be found in self.test_routines... if not routine_obj: message = "Unsupported test type: %s" % type - kvm_log.error(message) + logging.error(message) raise error.TestError, message # If we don't have the test routine yet... if not routine_obj.routine: @@ -93,8 +93,8 @@ class kvm_runtest_2(test.test): env.sync() except Exception, e: - kvm_log.error("Test failed: %s" % e) - kvm_log.debug("Postprocessing on error...") + logging.error("Test failed: %s" % e) + logging.debug("Postprocessing on error...") kvm_preprocessing.postprocess_on_error(self, params, env) env.sync() raise @@ -102,7 +102,7 @@ class kvm_runtest_2(test.test): finally: # Postprocess kvm_preprocessing.postprocess(self, params, env) - kvm_log.debug("Contents of environment: %s" % str(env)) + logging.debug("Contents of environment: %s" % str(env)) env.sync() env.close() diff --git a/client/tests/kvm_runtest_2/kvm_tests.py b/client/tests/kvm_runtest_2/kvm_tests.py index 950115d..90a87db 100644 --- a/client/tests/kvm_runtest_2/kvm_tests.py +++ b/client/tests/kvm_runtest_2/kvm_tests.py @@ -3,7 +3,7 @@ import os from autotest_lib.client.common_lib import utils, error -import kvm_log +import logging import kvm_utils import ppm_utils import scan_results @@ -16,31 +16,31 @@ def run_boot(test, params, env): if not vm.is_alive(): raise error.TestError, "VM seems to be dead; Test requires a living VM" - kvm_log.info("Waiting for guest to be up...") + logging.info("Waiting for guest to be up...") session = kvm_utils.wait_for(vm.ssh_login, 240, 0, 2) if not session: raise error.TestFail, "Could not log into guest" - kvm_log.info("Logged in") + logging.info("Logged in") if params.get("reboot") == "yes": # Send the VM's reboot command session.sendline(vm.get_params().get("cmd_reboot")) - kvm_log.info("Reboot command sent; waiting for guest to go down...") + logging.info("Reboot command sent; waiting for guest to go down...") if not kvm_utils.wait_for(lambda: not session.is_responsive(), 120, 0, 1): raise error.TestFail, "Guest refuses to go down" session.close() - kvm_log.info("Guest is down; waiting for it to go up again...") + logging.info("Guest is down; waiting for it to go up again...") session = kvm_utils.wait_for(vm.ssh_login, 120, 0, 2) if not session: raise error.TestFail, "Could not log into guest after reboot" - kvm_log.info("Guest is up again") + logging.info("Guest is up again") session.close() @@ -69,25 +69,25 @@ def run_migration(test, params, env): raise error.TestError, "Migration is not supported" # Log into guest and get the output of migration_test_command - kvm_log.info("Waiting for guest to be up...") + logging.info("Waiting for guest to be up...") session = kvm_utils.wait_for(vm.ssh_login, 240, 0, 2) if not session: raise error.TestFail, "Could not log into guest" - kvm_log.info("Logged in") + logging.info("Logged in") reference_output = session.get_command_output(params.get("migration_test_command")) session.close() # Define the migration command cmd = "migrate -d tcp:localhost:%d" % dest_vm.migration_port - kvm_log.debug("Migration command: %s" % cmd) + logging.debug("Migration command: %s" % cmd) # Migrate s, o = vm.send_monitor_cmd(cmd) if s: - kvm_log.error("Migration command failed (command: %r, output: %r)" % (cmd, o)) + logging.error("Migration command failed (command: %r, output: %r)" % (cmd, o)) raise error.TestFail, "Migration command failed" # Define some helper functions @@ -117,7 +117,7 @@ def run_migration(test, params, env): # Report migration status if mig_succeeded(): - kvm_log.info("Migration finished successfully") + logging.info("Migration finished successfully") else: if mig_failed(): message = "Migration failed" @@ -140,7 +140,7 @@ def run_migration(test, params, env): #(post_w, post_h, post_data) = ppm_utils.image_read_from_ppm_file(post_scrdump_filename) #if pre_w != post_w or pre_h != post_h or ppm_utils.image_fuzzy_compare(pre_w, pre_h, pre_data, post_data) < 0.99: # message = "Pre- and post-migration screendumps are too different" - # kvm_log.error(message + "\n(see info at %s)" % test.debugdir) + # logging.error(message + "\n(see info at %s)" % test.debugdir) # raise error.TestFail, message # Hack: it seems that the first attempt to communicate with the SSH port following migration @@ -149,23 +149,23 @@ def run_migration(test, params, env): dest_vm.is_sshd_running(timeout=0.0) # Log into guest and get the output of migration_test_command - kvm_log.info("Logging into guest after migration...") + logging.info("Logging into guest after migration...") session = dest_vm.ssh_login() if not session: raise error.TestFail, "Could not log into guest after migration" - kvm_log.info("Logged in after migration") + logging.info("Logged in after migration") output = session.get_command_output(params.get("migration_test_command")) session.close() # Compare output to reference output if output != reference_output: - kvm_log.info("Command output before migration differs from command output after migration") - kvm_log.info("Command: %s" % params.get("migration_test_command")) - kvm_log.info("Output before:" + kvm_utils.format_str_for_message(reference_output)) - kvm_log.info("Output after:" + kvm_utils.format_str_for_message(output)) + logging.info("Command output before migration differs from command output after migration") + logging.info("Command: %s" % params.get("migration_test_command")) + logging.info("Output before:" + kvm_utils.format_str_for_message(reference_output)) + logging.info("Output after:" + kvm_utils.format_str_for_message(output)) raise error.TestFail, "Command produced different output before and after migration" @@ -176,13 +176,13 @@ def run_autotest(test, params, env): if not vm.is_alive(): raise error.TestError, "VM seems to be dead; Test requires a living VM" - kvm_log.info("Logging into guest...") + logging.info("Logging into guest...") session = kvm_utils.wait_for(vm.ssh_login, 240, 0, 2) if not session: raise error.TestFail, "Could not log into guest" - kvm_log.info("Logged in") + logging.info("Logged in") # Collect some info test_name = params.get("test_name") @@ -220,7 +220,7 @@ def run_autotest(test, params, env): copy = True # Perform the copy if copy: - kvm_log.info("Copying autotest.tar.bz2 to guest (file is missing or has a different size)...") + logging.info("Copying autotest.tar.bz2 to guest (file is missing or has a different size)...") if not vm.scp_to_remote(tarred_autotest_path, ""): raise error.TestFail, "Could not copy autotest.tar.bz2 to guest" @@ -235,12 +235,12 @@ def run_autotest(test, params, env): copy = True # Perform the copy if copy: - kvm_log.info("Copying %s.tar.bz2 to guest (file is missing or has a different size)..." % test_name) + logging.info("Copying %s.tar.bz2 to guest (file is missing or has a different size)..." % test_name) if not vm.scp_to_remote(tarred_test_path, ""): raise error.TestFail, "Could not copy %s.tar.bz2 to guest" % test_name # Extract autotest.tar.bz2 - kvm_log.info("Extracting autotest.tar.bz2...") + logging.info("Extracting autotest.tar.bz2...") status = session.get_command_status("tar xvfj autotest.tar.bz2") if status != 0: raise error.TestFail, "Could not extract autotest.tar.bz2" @@ -249,20 +249,20 @@ def run_autotest(test, params, env): session.sendline("mkdir autotest/tests") # Extract .tar.bz2 into autotest/tests - kvm_log.info("Extracting %s.tar.bz2..." % test_name) + logging.info("Extracting %s.tar.bz2..." % test_name) status = session.get_command_status("tar xvfj %s.tar.bz2 -C autotest/tests" % test_name) if status != 0: raise error.TestFail, "Could not extract %s.tar.bz2" % test_name # Run the test - kvm_log.info("Running test '%s'..." % test_name) + logging.info("Running test '%s'..." % test_name) session.sendline("cd autotest/tests/%s" % test_name) session.sendline("rm -f ./%s.state" % test_control_file) session.read_up_to_prompt() session.sendline("../../bin/autotest ./%s" % test_control_file) - kvm_log.info("---------------- Test output ----------------") - match, output = session.read_up_to_prompt(timeout=test_timeout, print_func=kvm_log.info) - kvm_log.info("---------------- End of test output ----------------") + logging.info("---------------- Test output ----------------") + match, output = session.read_up_to_prompt(timeout=test_timeout, print_func=logging.info) + logging.info("---------------- End of test output ----------------") if not match: raise error.TestFail, "Timeout elapsed while waiting for test to complete" @@ -272,14 +272,14 @@ def run_autotest(test, params, env): result_list = scan_results.parse_results(output) # Report test results and check for FAIL/ERROR status - kvm_log.info("Results (test, status, duration, info):") + logging.info("Results (test, status, duration, info):") status_error = False status_fail = False if result_list == []: status_fail = True message_fail = "Test '%s' did not produce any recognizable results" % test_name for result in result_list: - kvm_log.info(str(result)) + logging.info(str(result)) if result[1] == "FAIL": status_fail = True message_fail = "Test '%s' ended with FAIL (info: '%s')" % (result[0], result[3]) @@ -291,12 +291,12 @@ def run_autotest(test, params, env): message_error = "Test '%s' ended with ABORT (info: '%s')" % (result[0], result[3]) # Copy test results to the local bindir/guest_results - kvm_log.info("Copying results back from guest...") + logging.info("Copying results back from guest...") guest_results_dir = os.path.join(test.outputdir, "guest_results") if not os.path.exists(guest_results_dir): os.mkdir(guest_results_dir) if not vm.scp_from_remote("autotest/results/default/*", guest_results_dir): - kvm_log.error("Could not copy results back from guest") + logging.error("Could not copy results back from guest") # Fail the test if necessary if status_fail: @@ -314,13 +314,13 @@ def internal_yum_update(session, command, prompt, timeout): while time.time() < end_time: (match, text) = session.read_until_last_line_matches(["[Ii]s this [Oo][Kk]", prompt], timeout=timeout) if match == 0: - kvm_log.info("Got 'Is this ok'; sending 'y'") + logging.info("Got 'Is this ok'; sending 'y'") session.sendline("y") elif match == 1: - kvm_log.info("Got shell prompt") + logging.info("Got shell prompt") return True else: - kvm_log.info("Timeout or process exited") + logging.info("Timeout or process exited") return False @@ -328,22 +328,22 @@ def run_yum_update(test, params, env): vm = kvm_utils.env_get_vm(env, params.get("main_vm")) if not vm: message = "VM object not found in environment" - kvm_log.error(message) + logging.error(message) raise error.TestError, message if not vm.is_alive(): message = "VM seems to be dead; Test requires a living VM" - kvm_log.error(message) + logging.error(message) raise error.TestError, message - kvm_log.info("Logging into guest...") + logging.info("Logging into guest...") session = kvm_utils.wait_for(vm.ssh_login, 120, 0, 2) if not session: message = "Could not log into guest" - kvm_log.error(message) + logging.error(message) raise error.TestFail, message - kvm_log.info("Logged in") + logging.info("Logged in") internal_yum_update(session, "yum update", params.get("ssh_prompt"), 600) internal_yum_update(session, "yum update kernel", params.get("ssh_prompt"), 600) @@ -358,26 +358,26 @@ def run_linux_s3(test, params, env): if not vm.is_alive(): raise error.TestError, "VM seems to be dead; Test requires a living VM" - kvm_log.info("Waiting for guest to be up...") + logging.info("Waiting for guest to be up...") session = kvm_utils.wait_for(vm.ssh_login, 240, 0, 2) if not session: raise error.TestFail, "Could not log into guest" - kvm_log.info("Logged in") - kvm_log.info("Checking that VM supports S3") + logging.info("Logged in") + logging.info("Checking that VM supports S3") status = session.get_command_status("grep -q mem /sys/power/state") if status == None: - kvm_log.error("Failed to check if S3 exists") + logging.error("Failed to check if S3 exists") elif status != 0: raise error.TestFail, "Guest does not support S3" - kvm_log.info("Waiting for a while for X to start") + logging.info("Waiting for a while for X to start") time.sleep(10) src_tty = session.get_command_output("fgconsole").strip() - kvm_log.info("Current virtual terminal is %s" % src_tty) + logging.info("Current virtual terminal is %s" % src_tty) if src_tty not in map(str, range(1,10)): raise error.TestFail, "Got a strange current vt (%s)" % src_tty @@ -385,12 +385,12 @@ def run_linux_s3(test, params, env): if src_tty == "1": dst_tty = "2" - kvm_log.info("Putting VM into S3") + logging.info("Putting VM into S3") command = "chvt %s && echo mem > /sys/power/state && chvt %s" % (dst_tty, src_tty) status = session.get_command_status(command, timeout=120) if status != 0: raise error.TestFail, "Suspend to mem failed" - kvm_log.info("VM resumed after S3") + logging.info("VM resumed after S3") session.close() diff --git a/client/tests/kvm_runtest_2/kvm_utils.py b/client/tests/kvm_runtest_2/kvm_utils.py index be8ad95..d715ef4 100644 --- a/client/tests/kvm_runtest_2/kvm_utils.py +++ b/client/tests/kvm_runtest_2/kvm_utils.py @@ -1,5 +1,6 @@ #!/usr/bin/python +<<<<<<< HEAD:client/tests/kvm_runtest_2/kvm_utils.py import md5 import thread import subprocess @@ -14,6 +15,10 @@ import select import re import kvm_log +======= +import md5, thread, subprocess, time, string, random, socket, os, signal, pty +import select, re, logging +>>>>>>> d701d9e... Fixing a kvm_log import lying around, imported logging on kvm_utils.:client/tests/kvm_runtest_2/kvm_utils.py # Functions for working with dicts obtained from the test config file @@ -174,11 +179,11 @@ class kvm_spawn: try: data += os.read(self.fd, 1024) except OSError: - #kvm_log.debug(data) - #kvm_log.debug("except OSError") + #logging.debug(data) + #logging.debug("except OSError") return data else: - #kvm_log.debug(data) + #logging.debug(data) return data def match_patterns(self, str, patterns): @@ -234,14 +239,14 @@ class kvm_spawn: done = True # Check if child has died if self.poll() != None: - kvm_log.debug("Process terminated with status %d" % self.poll()) + logging.debug("Process terminated with status %d" % self.poll()) done = True # Are we done? if done: break # Print some debugging info if match == None and self.poll() != 0: - kvm_log.debug("Timeout elapsed or process terminated; output so far:" \ + logging.debug("Timeout elapsed or process terminated; output so far:" \ + format_str_for_message(data.strip())) return (match, data) @@ -334,7 +339,7 @@ class kvm_spawn: output of command. """ # Print some debugging info - kvm_log.debug("Sending command: %s" % command) + logging.debug("Sending command: %s" % command) # Read everything that's waiting to be read self.read_nonblocking(0.1) @@ -355,7 +360,7 @@ class kvm_spawn: # Print some debugging info if status != 0: - kvm_log.debug("Command failed; status: %d, output:" % status \ + logging.debug("Command failed; status: %d, output:" % status \ + format_str_for_message(output.strip())) return (status, output) @@ -409,39 +414,39 @@ def remote_login(command, password, prompt, linesep="\n", timeout=10): password_prompt_count = 0 - kvm_log.debug("Trying to login...") + logging.debug("Trying to login...") while True: (match, text) = sub.read_until_last_line_matches( ["[Aa]re you sure", "[Pp]assword:", "[Ll]ogin:", "[Cc]onnection.*closed", prompt], timeout=timeout, internal_timeout=0.5) if match == 0: # "Are you sure you want to continue connecting" - kvm_log.debug("Got 'Are you sure...'; sending 'yes'") + logging.debug("Got 'Are you sure...'; sending 'yes'") sub.sendline("yes") continue elif match == 1: # "password:" if password_prompt_count == 0: - kvm_log.debug("Got password prompt; sending '%s'" % password) + logging.debug("Got password prompt; sending '%s'" % password) sub.sendline(password) password_prompt_count += 1 continue else: - kvm_log.debug("Got password prompt again") + logging.debug("Got password prompt again") sub.close() return None elif match == 2: # "login:" - kvm_log.debug("Got unexpected login prompt") + logging.debug("Got unexpected login prompt") sub.close() return None elif match == 3: # "Connection closed" - kvm_log.debug("Got 'Connection closed'") + logging.debug("Got 'Connection closed'") sub.close() return None elif match == 4: # prompt - kvm_log.debug("Got shell prompt -- logged in") + logging.debug("Got shell prompt -- logged in") return sub else: # match == None - kvm_log.debug("Timeout or process terminated") + logging.debug("Timeout or process terminated") sub.close() return None @@ -466,33 +471,33 @@ def remote_scp(command, password, timeout=300, login_timeout=10): password_prompt_count = 0 _timeout = login_timeout - kvm_log.debug("Trying to login...") + logging.debug("Trying to login...") while True: (match, text) = sub.read_until_last_line_matches( ["[Aa]re you sure", "[Pp]assword:", "lost connection"], timeout=_timeout, internal_timeout=0.5) if match == 0: # "Are you sure you want to continue connecting" - kvm_log.debug("Got 'Are you sure...'; sending 'yes'") + logging.debug("Got 'Are you sure...'; sending 'yes'") sub.sendline("yes") continue elif match == 1: # "password:" if password_prompt_count == 0: - kvm_log.debug("Got password prompt; sending '%s'" % password) + logging.debug("Got password prompt; sending '%s'" % password) sub.sendline(password) password_prompt_count += 1 _timeout = timeout continue else: - kvm_log.debug("Got password prompt again") + logging.debug("Got password prompt again") sub.close() return False elif match == 2: # "lost connection" - kvm_log.debug("Got 'lost connection'") + logging.debug("Got 'lost connection'") sub.close() return False else: # match == None - kvm_log.debug("Timeout or process terminated") + logging.debug("Timeout or process terminated") sub.close() return sub.poll() == 0 @@ -632,7 +637,7 @@ def is_sshd_running(host, port, timeout=10.0): except socket.error: # Can't connect -- return False s.close() - kvm_log.debug("Could not connect") + logging.debug("Could not connect") return False s.setblocking(False) # Wait up to 'timeout' seconds @@ -645,7 +650,7 @@ def is_sshd_running(host, port, timeout=10.0): if len(str) > 0: s.shutdown(socket.SHUT_RDWR) s.close() - kvm_log.debug("Success! got string %r" % str) + logging.debug("Success! got string %r" % str) return True except socket.error: # No text was available; try again @@ -653,7 +658,7 @@ def is_sshd_running(host, port, timeout=10.0): # Timeout elapsed and no text was received s.shutdown(socket.SHUT_RDWR) s.close() - kvm_log.debug("Timeout") + logging.debug("Timeout") return False @@ -735,7 +740,7 @@ def wait_for(func, timeout, first=0.0, step=1.0, text=None): while time.time() < end_time: if text: - kvm_log.debug("%s (%f secs)" % (text, time.time() - start_time)) + logging.debug("%s (%f secs)" % (text, time.time() - start_time)) output = func() if output: @@ -743,7 +748,7 @@ def wait_for(func, timeout, first=0.0, step=1.0, text=None): time.sleep(step) - kvm_log.debug("Timeout elapsed") + logging.debug("Timeout elapsed") return None @@ -767,7 +772,7 @@ def md5sum_file(filename, size=None): chunksize = size data = f.read(chunksize) if len(data) == 0: - kvm_log.debug("Nothing left to read but size=%d" % size) + logging.debug("Nothing left to read but size=%d" % size) break o.update(data) size -= len(data) diff --git a/client/tests/kvm_runtest_2/kvm_vm.py b/client/tests/kvm_runtest_2/kvm_vm.py index fab839f..d0bd39f 100644 --- a/client/tests/kvm_runtest_2/kvm_vm.py +++ b/client/tests/kvm_runtest_2/kvm_vm.py @@ -5,7 +5,7 @@ import socket import os import kvm_utils -import kvm_log +import logging def get_image_filename(params, image_dir): @@ -50,19 +50,19 @@ def create_image(params, qemu_img_path, image_dir): size = params.get("image_size", "10G") qemu_img_cmd += " %s" % size - kvm_log.debug("Running qemu-img command:\n%s" % qemu_img_cmd) - (status, pid, output) = kvm_utils.run_bg(qemu_img_cmd, None, kvm_log.debug, "(qemu-img) ", timeout=30) + logging.debug("Running qemu-img command:\n%s" % qemu_img_cmd) + (status, pid, output) = kvm_utils.run_bg(qemu_img_cmd, None, logging.debug, "(qemu-img) ", timeout=30) if status: - kvm_log.debug("qemu-img exited with status %d" % status) - kvm_log.error("Could not create image %s" % image_filename) + logging.debug("qemu-img exited with status %d" % status) + logging.error("Could not create image %s" % image_filename) return None if not os.path.exists(image_filename): - kvm_log.debug("Image file does not exist for some reason") - kvm_log.error("Could not create image %s" % image_filename) + logging.debug("Image file does not exist for some reason") + logging.error("Could not create image %s" % image_filename) return None - kvm_log.info("Image created in %s" % image_filename) + logging.info("Image created in %s" % image_filename) return image_filename @@ -77,11 +77,11 @@ def remove_image(params, image_dir): image_format -- the format of the image (qcow2, raw etc) """ image_filename = get_image_filename(params, image_dir) - kvm_log.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: - kvm_log.debug("Image file %s not found") + logging.debug("Image file %s not found") class VM: @@ -117,7 +117,7 @@ class VM: return True filename = "/proc/%d/cmdline" % self.pid if not os.path.exists(filename): - kvm_log.debug("Filename %s does not exist" % filename) + logging.debug("Filename %s does not exist" % filename) return False file = open(filename) cmdline = file.read() @@ -259,24 +259,24 @@ class VM: if iso: iso = os.path.join(iso_dir, iso) if not os.path.exists(iso): - kvm_log.error("ISO file not found: %s" % iso) + logging.error("ISO file not found: %s" % iso) return False compare = False if params.get("md5sum_1m"): - kvm_log.debug("Comparing expected MD5 sum with MD5 sum of first MB of ISO file...") + logging.debug("Comparing expected MD5 sum with MD5 sum of first MB of ISO file...") actual_md5sum = kvm_utils.md5sum_file(iso, 1048576) expected_md5sum = params.get("md5sum_1m") compare = True elif params.get("md5sum"): - kvm_log.debug("Comparing expected MD5 sum with MD5 sum of ISO file...") + logging.debug("Comparing expected MD5 sum with MD5 sum of ISO file...") actual_md5sum = kvm_utils.md5sum_file(iso) expected_md5sum = params.get("md5sum") compare = True if compare: if actual_md5sum == expected_md5sum: - kvm_log.debug("MD5 sums match") + logging.debug("MD5 sums match") else: - kvm_log.error("Actual MD5 sum differs from expected one") + logging.error("Actual MD5 sum differs from expected one") return False # Find available monitor filename @@ -310,23 +310,23 @@ class VM: # Add -incoming option to the qemu command qemu_command += " -incoming tcp:0:%d" % self.migration_port - kvm_log.debug("Running qemu command:\n%s" % qemu_command) - (status, pid, output) = kvm_utils.run_bg(qemu_command, None, kvm_log.debug, "(qemu) ") + logging.debug("Running qemu command:\n%s" % qemu_command) + (status, pid, output) = kvm_utils.run_bg(qemu_command, None, logging.debug, "(qemu) ") if status: - kvm_log.debug("qemu exited with status %d" % status) - kvm_log.error("VM could not be created -- qemu command failed:\n%s" % qemu_command) + logging.debug("qemu exited with status %d" % status) + logging.error("VM could not be created -- qemu command failed:\n%s" % qemu_command) return False self.pid = pid if not kvm_utils.wait_for(self.is_alive, timeout, 0, 1): - kvm_log.debug("VM is not alive for some reason") - kvm_log.error("VM could not be created with command:\n%s" % qemu_command) + logging.debug("VM is not alive for some reason") + logging.error("VM could not be created with command:\n%s" % qemu_command) self.destroy() return False - kvm_log.debug("VM appears to be alive with PID %d" % self.pid) + logging.debug("VM appears to be alive with PID %d" % self.pid) return True @@ -361,18 +361,18 @@ class VM: return (False, o) # Connect to monitor - kvm_log.debug("Sending monitor command: %s" % command) + logging.debug("Sending monitor command: %s" % command) try: s = socket.socket(socket.AF_UNIX, socket.SOCK_STREAM) s.setblocking(False) s.connect(self.monitor_file_name) except: - kvm_log.debug("Could not connect to monitor socket") + logging.debug("Could not connect to monitor socket") return (1, "") status, data = read_up_to_qemu_prompt(s, timeout) if not status: s.close() - kvm_log.debug("Could not find (qemu) prompt; output so far:" \ + logging.debug("Could not find (qemu) prompt; output so far:" \ + kvm_utils.format_str_for_message(data)) return (1, "") # Send command @@ -384,7 +384,7 @@ class VM: data = "\n".join(data.splitlines()[1:]) if not status: s.close() - kvm_log.debug("Could not find (qemu) prompt after command; output so far:" \ + logging.debug("Could not find (qemu) prompt after command; output so far:" \ + kvm_utils.format_str_for_message(data)) return (1, data) s.close() @@ -399,45 +399,45 @@ class VM: """ # Is it already dead? if self.is_dead(): - kvm_log.debug("VM is already down") + logging.debug("VM is already down") return - kvm_log.debug("Destroying VM with PID %d..." % self.pid) + logging.debug("Destroying VM with PID %d..." % self.pid) if gracefully and self.params.get("cmd_shutdown"): # Try to destroy with SSH command - kvm_log.debug("Trying to shutdown VM with SSH command...") + logging.debug("Trying to shutdown VM with SSH command...") (status, output) = self.ssh(self.params.get("cmd_shutdown")) # Was the command sent successfully? if status == 0: #if self.ssh(self.params.get("cmd_shutdown")): - kvm_log.debug("Shutdown command sent; Waiting for VM to go down...") + logging.debug("Shutdown command sent; Waiting for VM to go down...") if kvm_utils.wait_for(self.is_dead, 60, 1, 1): - kvm_log.debug("VM is down") + logging.debug("VM is down") self.pid = None return # Try to destroy with a monitor command - kvm_log.debug("Trying to kill VM with monitor command...") + logging.debug("Trying to kill VM with monitor command...") (status, output) = self.send_monitor_cmd("quit", block=False) # Was the command sent successfully? if status == 0: # Wait for the VM to be really dead if kvm_utils.wait_for(self.is_dead, 5, 0.5, 0.5): - kvm_log.debug("VM is down") + logging.debug("VM is down") self.pid = None return # If the VM isn't dead yet... - kvm_log.debug("Cannot quit normally; Sending a kill to close the deal...") + logging.debug("Cannot quit normally; Sending a kill to close the deal...") kvm_utils.safe_kill(self.pid, 9) # Wait for the VM to be really dead if kvm_utils.wait_for(self.is_dead, 5, 0.5, 0.5): - kvm_log.debug("VM is down") + logging.debug("VM is down") self.pid = None return - kvm_log.error("We have a zombie! PID %d is a zombie!" % self.pid) + logging.error("We have a zombie! PID %d is a zombie!" % self.pid) def is_alive(self): """Return True iff the VM's monitor is responsive.""" @@ -480,7 +480,7 @@ class VM: if self.redirs.has_key(port): return self.redirs[port] else: - kvm_log.debug("Warning: guest port %s requested but not redirected" % port) + logging.debug("Warning: guest port %s requested but not redirected" % port) return None def is_sshd_running(self, timeout=10): @@ -545,7 +545,7 @@ class VM: if not session: return (1, "") - kvm_log.debug("Sending command: %s" % command) + logging.debug("Sending command: %s" % command) session.sendline(command) output = session.read_nonblocking(1.0) session.close() diff --git a/client/tests/kvm_runtest_2/stepmaker.py b/client/tests/kvm_runtest_2/stepmaker.py index 54a1a4a..c07c125 100644 --- a/client/tests/kvm_runtest_2/stepmaker.py +++ b/client/tests/kvm_runtest_2/stepmaker.py @@ -15,7 +15,7 @@ import commands from autotest_lib.client.common_lib import error import kvm_utils -import kvm_log +import logging import ppm_utils import stepeditor @@ -136,7 +136,7 @@ class StepMaker(stepeditor.StepMakerWindow): (status, output) = self.vm.send_monitor_cmd("screendump " + self.screendump_filename) if status: # Failure - kvm_log.info("Could not fetch screendump") + logging.info("Could not fetch screendump") else: self.set_image_from_file(self.screendump_filename) @@ -281,7 +281,7 @@ class StepMaker(stepeditor.StepMakerWindow): (status, output) = self.vm.send_monitor_cmd("screendump " + self.screendump_filename) if status: # Failure - kvm_log.info("Could not fetch screendump") + logging.info("Could not fetch screendump") else: self.set_image_from_file(self.screendump_filename)