def pre_test(self):
"""
TODO:
step 1: setup private bridge network environment;
step 2: sync host time from ntp server;
step 3: verify system time drift between host and guest;
step 4: verify guest clock source if linux guest;
"""
self.setup_private_network()
self.sync_host_time()
vm = self.get_vm(create=True)
if self.params["os_type"] == 'windows':
utils_time.sync_timezone_win(vm)
else:
utils_time.sync_timezone_linux(vm)
session = self.get_session(vm)
self.check_dirft_before_adjust_time(session)
if self.params.get("read_clock_source_cmd"):
self.verify_clock_source(session)
def run(test, params, env):
"""
This test virsh domtime command and its options.
1) Start a guest with/without guest agent configured;
2) Record guest times;
3) Do some operation to stop VM;
4) Run virsh domtime command with different options;
5) Check the command result;
6) Check the guest times against expectation;
7) Cleanup test environment.
"""
epoch = datetime.datetime(1970, 1, 1, 0, 0, 0)
# Max time can be set with domtime successfully in newer qemu-ga
time_max_1 = 3155731199
# Max time can be set with domtime successfully in older qemu-ga
time_max_2 = 3155759999
# Max time can be set with domtime bug failed to set RTC in older qemu-ga
time_max_3 = 9223372035
def init_time(session):
"""
Initialize guest RTC time to epoch + 1234567890 and system time
one day latter.
:param session: Session from which to access guest
"""
res = virsh.domtime(vm_name, time=1234567890)
if res.exit_status:
logging.debug("Failed to init time to 1234567890:\n%s", res)
status, output = session.cmd_status_output('date -s "1 day"')
if status:
test.error("Failed to set guest time:\n%s" % output)
def get_host_utc_time():
"""
Get host UTC time from date command.
"""
res = process.run("date -u", shell=True)
# Strip timezone info from output
# e.g. 'Sun Feb 15 07:31:40 CST 2009' -> 'Sun Feb 15 07:31:40 2009'
time_str = re.sub(r'\S+ (?=\S+$)', '', res.stdout_text.strip())
return datetime.datetime.strptime(time_str, r"%a %b %d %H:%M:%S %Y")
def run_cmd(session, cmd):
"""
Run a command in a session and record duration of call.
"""
start = time.time()
output = session.cmd_output(cmd)
duration = time.time() - start
logging.info('Result of command "%s". Duration: %s. Output:%s', cmd,
duration, output.strip())
return output, duration
def get_guest_times(session):
"""
Retrieve different guest time as a dict for checking.
Keys:
local_hw: Guest RTC time in local timezone
local_sys: Guest system time in local timezone
utc_sys: Guest system time in UTC
domtime: Guest system time in UTC got from virsh domtime command
:param session: Session from which to access guest
"""
times = {}
get_begin = time.time()
# Guest RTC local timezone time
output, _ = run_cmd(session, 'hwclock')
time_str, _ = re.search(r"(.+) (\S+ seconds)", output).groups()
try:
# output format 1: Tue 01 Mar 2016 01:53:46 PM CST
# Remove timezone info from output
new_str = re.sub(r'\s+\S+$', '', time_str)
times['local_hw'] = datetime.datetime.strptime(
new_str, r"%a %d %b %Y %I:%M:%S %p")
except ValueError:
# There are two possible output format for `hwclock`
# output format 2: Sat Feb 14 07:31:33 2009
times['local_hw'] = datetime.datetime.strptime(
time_str, r"%a %b %d %H:%M:%S %Y")
delta = time.time() - get_begin
times['local_hw'] -= datetime.timedelta(seconds=delta)
# Guest system local timezone time
output, _ = run_cmd(session, 'date')
# Strip timezone info from output
# e.g. 'Sun Feb 15 07:31:40 CST 2009' -> 'Sun Feb 15 07:31:40 2009'
time_str = re.sub(r'\S+ (?=\S+$)', '', output.strip())
times['local_sys'] = datetime.datetime.strptime(
time_str, r"%a %b %d %H:%M:%S %Y")
delta = time.time() - get_begin
times['local_sys'] -= datetime.timedelta(seconds=delta)
# Guest system UTC timezone time
output, _ = run_cmd(session, 'date -u')
# Strip timezone info from output
# e.g. 'Sun Feb 15 07:31:40 CST 2009' -> 'Sun Feb 15 07:31:40 2009'
time_str = re.sub(r'\S+ (?=\S+$)', '', output.strip())
times['utc_sys'] = datetime.datetime.strptime(time_str,
r"%a %b %d %H:%M:%S %Y")
delta = time.time() - get_begin
times['utc_sys'] -= datetime.timedelta(seconds=delta)
# Guest UTC time from virsh domtime
res = virsh.domtime(vm_name, pretty=True, ignore_status=True)
if not res.exit_status:
logging.info('Result of "domtime". Duration: %s. Output:%s',
res.duration, res.stdout.strip())
_, time_str = res.stdout.split(" ", 1)
times['domtime'] = datetime.datetime.strptime(
time_str.strip(), r"%Y-%m-%d %H:%M:%S")
delta = time.time() - get_begin
times['domtime'] -= datetime.timedelta(seconds=delta)
else:
logging.debug("Unable to get domain time:\n%s", res)
times['domtime'] = None
return times, time.time() - get_begin
def check_get_success(expected_times):
"""
Check virsh command get result against expected times
:param expected_times: Expected time for checking
"""
_, time_str = res.stdout.split(" ", 1)
if pretty:
# Time: 2015-01-13 06:29:18
domtime = datetime.datetime.strptime(time_str.strip(),
r"%Y-%m-%d %H:%M:%S")
else:
# Time: 1421130740
domtime = epoch + datetime.timedelta(seconds=int(time_str))
time_shift = time.time() - start
logging.debug("Time shift is %s", time_shift)
result_diff = (domtime - expected_times['domtime']).total_seconds()
if abs(result_diff) > 2.0:
test.fail("Expect get time %s, but got %s, time "
"diff: %s" %
(org_times['domtime'], domtime, result_diff))
def check_guest_times(expected_times, cur_times):
"""
Check guest times after test against expected times
:param expected_times: Expected time for checking
"""
time_shift = time.time() - start
logging.debug("Time shift is %s", time_shift)
error_msgs = []
for key in cur_times:
if cur_times[key] is not None:
cur = cur_times[key]
expect = expected_times[key]
diff = (cur - expect).total_seconds()
msg = "For %s, expect get time %s, got %s, time diff: %s" % (
key, expect, cur, diff)
logging.debug(msg)
if abs(diff) > 2.0:
error_msgs.append(msg)
if error_msgs:
test.fail('\n'.join(error_msgs))
def check_time(result, org_times, cur_times):
"""
Check whether domain time has been change accordingly.
:param result: virsh domtime CmdResult instance
:param org_times: Original guest times
"""
action = "get"
if now or sync or (set_time is not None):
action = "set"
host_tz_diff = org_host_loc_time - org_host_time
logging.debug("Timezone diff on host is %d hours.",
(host_tz_diff.total_seconds() // 3600))
# Hardware time will never stop
logging.info('Add %ss to expected guest time', interval)
if action == 'get':
expected_times = org_times
elif action == 'set':
if result.exit_status:
# Time not change if domtime fails
expected_times = org_times
else:
# Time change accordingly if succeed.
if now:
utc_time = org_host_time
local_time = utc_time + guest_tz_diff
elif sync:
local_time = org_times["local_hw"]
utc_time = local_time - guest_tz_diff
elif set_time is not None:
utc_time = epoch + datetime.timedelta(
seconds=(int(set_time) - guest_duration))
local_time = utc_time + guest_tz_diff
expected_times = {}
expected_times['local_hw'] = local_time
expected_times['local_sys'] = local_time
expected_times["utc_sys"] = utc_time
expected_times["domtime"] = utc_time
# Add interval between two checks of guest time
for key in expected_times:
if expected_times[key] is not None:
expected_times[key] += interval
# Hardware time will never stop
# Software time will stop if suspended or managed-saved
if suspend or managedsave:
logging.info('Remove %ss from expected guest software time',
stop_time)
expected_times["domtime"] -= stop_time
expected_times["local_sys"] -= stop_time
expected_times["utc_sys"] -= stop_time
# Check guest time if domtime succeeded
check_guest_times(expected_times, cur_times)
# Check if output of domtime is correct
if action == 'get' and not result.exit_status:
check_get_success(expected_times)
def prepare_fail_patts():
"""
Predict fail pattern from test parameters.
"""
fail_patts = []
if not channel:
fail_patts.append(r"QEMU guest agent is not configured")
if not agent:
# For older version
fail_patts.append(r"Guest agent not available for now")
# For newer version
fail_patts.append(r"Guest agent is not responding")
if int(now) + int(sync) + int(bool(set_time)) > 1:
fail_patts.append(r"Options \S+ and \S+ are mutually exclusive")
if shutdown:
fail_patts.append(r"domain is not running")
if set_time is not None:
if int(set_time) < 0:
fail_patts.append(r"Invalid argument")
elif time_max_1 < int(set_time) <= time_max_2:
fail_patts.append(r"Invalid time")
elif time_max_2 < int(set_time) <= time_max_3:
fail_patts.append(r"Invalid time")
elif time_max_3 < int(set_time):
fail_patts.append(r"too big for guest agent")
if readonly:
fail_patts.append(r"operation forbidden")
return fail_patts
def stop_vm():
"""
Suspend, managedsave, pmsuspend or shutdown a VM for a period of time
"""
stop_start = time.time()
vmlogin_dur = 0.0
if suspend:
vm.pause()
time.sleep(vm_stop_duration)
vm.resume()
elif managedsave:
vm.managedsave()
time.sleep(vm_stop_duration)
vm.start()
start_dur = time.time()
vm.wait_for_login()
vmlogin_dur = time.time() - start_dur
elif pmsuspend:
vm.pmsuspend()
time.sleep(vm_stop_duration)
vm.pmwakeup()
start_dur = time.time()
vm.wait_for_login()
vmlogin_dur = time.time() - start_dur
elif shutdown:
vm.destroy()
# Check real guest stop time
stop_seconds = time.time() - stop_start - vmlogin_dur
stop_time = datetime.timedelta(seconds=stop_seconds)
logging.debug("Guest stopped: %s", stop_time)
return stop_time
# Check availability of virsh command domtime
if not virsh.has_help_command('domtime'):
test.cancel("This version of libvirt does not support "
"the domtime test")
channel = (params.get("prepare_channel", "yes") == 'yes')
agent = (params.get("start_agent", "yes") == 'yes')
pretty = (params.get("domtime_pretty", "no") == 'yes')
now = (params.get("domtime_now", "no") == 'yes')
sync = (params.get("domtime_sync", "no") == 'yes')
set_time = params.get("domtime_time", None)
shutdown = (params.get("shutdown_vm", "no") == 'yes')
suspend = (params.get("suspend_vm", "no") == 'yes')
managedsave = (params.get("managedsave_vm", "no") == 'yes')
pmsuspend = (params.get("pmsuspend_vm", "no") == 'yes')
vm_stop_duration = int(params.get("vm_stop_duration", "10"))
vm_name = params.get("main_vm")
vm = env.get_vm(vm_name)
readonly = (params.get("readonly_test", "no") == "yes")
# Backup domain XML
xml_backup = vm_xml.VMXML.new_from_inactive_dumpxml(vm_name)
try:
if pmsuspend:
vm_xml.VMXML.set_pm_suspend(vm_name)
# Add or remove qemu-agent from guest before test
vm.prepare_guest_agent(channel=channel, start=agent)
session = vm.wait_for_login()
# Let's set guest timezone to region where we do not
# have day light savings, to affect the time
session.cmd("timedatectl set-timezone Asia/Kolkata")
try:
init_guest_times, _ = get_guest_times(session)
guest_tz_diff = init_guest_times['local_sys'] - init_guest_times[
'utc_sys']
logging.debug("Timezone diff on guest is %d hours.",
(guest_tz_diff.total_seconds() // 3600))
if channel and agent:
init_time(session)
# Expected fail message patterns
fail_patts = prepare_fail_patts()
# Message patterns test should skip when met
skip_patts = [
r'The command \S+ has not been found',
]
# Record start time
start = time.time()
# Record host utc time before testing
org_host_time = get_host_utc_time()
# Record host local time before testing
outp = process.run('date', shell=True)
time_st = re.sub(r'\S+ (?=\S+$)', '', outp.stdout_text.strip())
org_host_loc_time = datetime.datetime.strptime(
time_st, r"%a %b %d %H:%M:%S %Y")
# Get original guest times
org_times, guest_duration = get_guest_times(session)
# Run some operations to stop guest system
stop_time = stop_vm()
# Run command with specified options.
res = virsh.domtime(vm_name,
now=now,
pretty=pretty,
sync=sync,
time=set_time,
readonly=readonly,
debug=True)
libvirt.check_result(res, fail_patts, skip_patts)
# Check interval between two check of guest time
interval = datetime.timedelta(seconds=(time.time() - start))
logging.debug("Interval between guest checking: %s", interval)
if not shutdown:
# Get current guest times
cur_times, _ = get_guest_times(session)
check_time(res, org_times, cur_times)
finally:
if shutdown:
vm.start()
# sync guest timezone
utils_time.sync_timezone_linux(vm)
# Sync guest time with host
if channel and agent and not shutdown:
res = virsh.domtime(vm_name, now=True)
if res.exit_status:
session.close()
test.error("Failed to recover guest time:\n%s" % res)
session.close()
finally:
# Restore VM XML
xml_backup.sync()
def run(test, params, env):
"""
Timer device boot guest:
1) Check host clock's sync status with chronyd
2) Add some load on host (Optional)
3) Boot the guest with specific clock source
4) Check the clock source currently used on guest
5) Do some file operation on guest (Optional)
6) Check the system time on guest and host (Optional)
7) Check the hardware time on guest (linux only)
8) Sleep period of time before reboot (Optional)
9) Reboot guest (Optional)
10) Check the system time on guest and host (Optional)
11) Check the hardware time on guest (Optional)
12) Restore guest's clock source
:param test: QEMU test object.
:param params: Dictionary with test parameters.
:param env: Dictionary with the test environment.
"""
def get_hwtime(session):
"""
Get guest's hardware clock.
:param session: VM session.
"""
hwclock_time_command = params.get("hwclock_time_command", "hwclock -u")
hwclock_time_filter_re = params.get("hwclock_time_filter_re",
r"(\d+-\d+-\d+ \d+:\d+:\d+)")
hwclock_time_format = params.get("hwclock_time_format",
"%Y-%m-%d %H:%M:%S")
output = session.cmd_output_safe(hwclock_time_command)
try:
str_time = re.findall(hwclock_time_filter_re, output)[0]
guest_time = time.mktime(
time.strptime(str_time, hwclock_time_format))
except Exception as err:
test.log.debug("(time_format, time_string): (%s, %s)",
hwclock_time_format, str_time)
raise err
return guest_time
def verify_timedrift(session, is_hardware=False):
"""
Verify timedrift between host and guest.
:param session: VM session.
:param is_hardware: if need to verify guest's hardware time.
"""
# Command to run to get the current time
time_command = params["time_command"]
# Filter which should match a string to be passed to time.strptime()
time_filter_re = params["time_filter_re"]
# Time format for time.strptime()
time_format = params["time_format"]
timerdevice_drift_threshold = float(
params.get("timerdevice_drift_threshold", 3))
time_type = "system" if not is_hardware else "harware"
error_context.context("Check the %s time on guest" % time_type,
test.log.info)
host_time, guest_time = utils_test.get_time(session, time_command,
time_filter_re,
time_format)
if is_hardware:
guest_time = get_hwtime(session)
drift = abs(float(host_time) - float(guest_time))
if drift > timerdevice_drift_threshold:
test.fail("The guest's %s time is different with"
" host's system time. Host time: '%s', guest time:"
" '%s'" % (time_type, host_time, guest_time))
def get_current_clksrc(session):
cmd = "cat /sys/devices/system/clocksource/"
cmd += "clocksource0/current_clocksource"
current_clksrc = session.cmd_output_safe(cmd)
if "kvm-clock" in current_clksrc:
return "kvm-clock"
elif "tsc" in current_clksrc:
return "tsc"
elif "timebase" in current_clksrc:
return "timebase"
elif "acpi_pm" in current_clksrc:
return "acpi_pm"
return current_clksrc
def update_clksrc(session, clksrc):
"""
Update guest's clocksource, this func can work when not login
into guest with ssh.
:param session: VM session.
:param clksrc: expected guest's clocksource.
"""
avail_cmd = "cat /sys/devices/system/clocksource/clocksource0/"
avail_cmd += "available_clocksource"
avail_clksrc = session.cmd_output_safe(avail_cmd)
if clksrc in avail_clksrc:
clksrc_cmd = "echo %s > /sys/devices/system/clocksource/" % clksrc
clksrc_cmd += "clocksource0/current_clocksource"
status, output = session.cmd_status_output(clksrc_cmd)
if status:
test.fail(
"fail to update guest's clocksource to %s,"
"details: %s" % clksrc, output)
else:
test.error("please check the clocksource you want to set, "
"it's not supported by current guest, current "
"available clocksources: %s" % avail_clksrc)
error_context.context("sync host time with NTP server", test.log.info)
clock_sync_command = params["clock_sync_command"]
process.system(clock_sync_command, shell=True)
timerdevice_host_load_cmd = params.get("timerdevice_host_load_cmd")
if timerdevice_host_load_cmd:
error_context.context("Add some load on host", test.log.info)
host_cpu_cnt_cmd = params["host_cpu_cnt_cmd"]
host_cpu_cnt = int(
process.system_output(host_cpu_cnt_cmd, shell=True).strip())
if params["os_type"] == "linux":
timerdevice_host_load_cmd = timerdevice_host_load_cmd % host_cpu_cnt
process.system(timerdevice_host_load_cmd,
shell=True,
ignore_bg_processes=True)
else:
timerdevice_host_load_cmd = timerdevice_host_load_cmd % int(
host_cpu_cnt / 2)
stress_bg = utils_test.HostStress(
"stress", params, stress_args=timerdevice_host_load_cmd)
stress_bg.load_stress_tool()
host_load_stop_cmd = params.get("timerdevice_host_load_stop_cmd",
"pkill -f 'do X=1'")
funcatexit.register(env, params["type"], _system, host_load_stop_cmd)
params["start_vm"] = "yes"
env_process.preprocess_vm(test, params, env, params.get("main_vm"))
vm = env.get_vm(params["main_vm"])
vm.verify_alive()
error_context.context("Sync guest timezone before test", test.log.info)
timeout = int(params.get("login_timeout", 360))
if params["os_type"] == 'linux':
utils_time.sync_timezone_linux(vm, timeout)
else:
utils_time.sync_timezone_win(vm, timeout)
session = vm.wait_for_serial_login(timeout=timeout)
timerdevice_clksource = params.get("timerdevice_clksource")
need_restore_clksrc = False
if timerdevice_clksource:
origin_clksrc = get_current_clksrc(session)
test.log.info("guest is booted with %s", origin_clksrc)
if timerdevice_clksource != origin_clksrc:
update_clksrc(session, timerdevice_clksource)
need_restore_clksrc = True
error_context.context("check timedrift between guest and host.",
test.log.info)
verify_timedrift(session)
if params["os_type"] == "linux":
verify_timedrift(session, is_hardware=True)
repeat_nums = params.get_numeric("repeat_nums")
if repeat_nums:
sleep_time = params["sleep_time"]
for index in range(repeat_nums):
time.sleep(int(sleep_time))
verify_timedrift(session)
if params["os_type"] == "linux":
verify_timedrift(session, is_hardware=True)
if params.get("timerdevice_reboot_test") == "yes":
sleep_time = params.get("timerdevice_sleep_time")
if sleep_time:
error_context.context("Sleep '%s' secs before reboot" % sleep_time,
test.log.info)
sleep_time = int(sleep_time)
time.sleep(sleep_time)
error_context.context(
"Check timedrift between guest and host "
"after reboot.", test.log.info)
vm.reboot(timeout=timeout, serial=True)
verify_timedrift(session)
if params["os_type"] == "linux":
verify_timedrift(session, is_hardware=True)
if need_restore_clksrc:
update_clksrc(session, origin_clksrc)
session.close()
def run(test, params, env):
"""
Time drift test with reboot:
1) Log into a guest.
2) Take a time reading from the guest and host.
3) Reboot the guest.
4) Take a second time reading.
5) If the drift (in seconds) is higher than a user specified value, fail.
:param test: QEMU test object.
:param params: Dictionary with test parameters.
:param env: Dictionary with the test environment.
"""
vm = env.get_vm(params["main_vm"])
vm.verify_alive()
boot_option_added = params.get("boot_option_added")
boot_option_removed = params.get("boot_option_removed")
if boot_option_added or boot_option_removed:
utils_test.update_boot_option(vm,
args_removed=boot_option_removed,
args_added=boot_option_added)
if params.get("os_type") == 'linux':
utils_time.sync_timezone_linux(vm)
else:
utils_time.sync_timezone_win(vm)
timeout = int(params.get("login_timeout", 360))
session = vm.wait_for_login(timeout=timeout)
# Collect test parameters:
# Command to run to get the current time
time_command = params["time_command"]
# Filter which should match a string to be passed to time.strptime()
time_filter_re = params["time_filter_re"]
# Time format for time.strptime()
time_format = params["time_format"]
drift_threshold = float(params.get("drift_threshold", "10"))
drift_threshold_single = float(params.get("drift_threshold_single", "3"))
reboot_iterations = int(params.get("reboot_iterations", 1))
try:
# Get initial time
# (ht stands for host time, gt stands for guest time)
(ht0, gt0) = utils_test.get_time(session, time_command,
time_filter_re, time_format)
# Reboot
for i in range(reboot_iterations):
# Get time before current iteration
(ht0_, gt0_) = utils_test.get_time(session, time_command,
time_filter_re, time_format)
# Run current iteration
test.log.info("Rebooting: iteration %d of %d...",
(i + 1), reboot_iterations)
session = vm.reboot(session, timeout=timeout)
# Get time after current iteration
(ht1_, gt1_) = utils_test.get_time(session, time_command,
time_filter_re, time_format)
# Report iteration results
host_delta = ht1_ - ht0_
guest_delta = gt1_ - gt0_
drift = abs(host_delta - guest_delta)
test.log.info("Host duration (iteration %d): %.2f",
(i + 1), host_delta)
test.log.info("Guest duration (iteration %d): %.2f",
(i + 1), guest_delta)
test.log.info("Drift at iteration %d: %.2f seconds",
(i + 1), drift)
# Fail if necessary
if drift > drift_threshold_single:
test.fail("Time drift too large at iteration %d: "
"%.2f seconds" % (i + 1, drift))
# Get final time
(ht1, gt1) = utils_test.get_time(session, time_command,
time_filter_re, time_format)
finally:
if session:
session.close()
# remove flags add for this test.
if boot_option_added or boot_option_removed:
utils_test.update_boot_option(vm,
args_removed=boot_option_added,
args_added=boot_option_removed)
# Report results
host_delta = ht1 - ht0
guest_delta = gt1 - gt0
drift = abs(host_delta - guest_delta)
test.log.info("Host duration (%d reboots): %.2f",
reboot_iterations, host_delta)
test.log.info("Guest duration (%d reboots): %.2f",
reboot_iterations, guest_delta)
test.log.info("Drift after %d reboots: %.2f seconds",
reboot_iterations, drift)
# Fail if necessary
if drift > drift_threshold:
test.fail("Time drift too large after %d reboots: "
"%.2f seconds" % (reboot_iterations, drift))
def run(test, params, env):
"""
This test virsh domtime command and its options.
1) Start a guest with/without guest agent configured;
2) Record guest times;
3) Do some operation to stop VM;
4) Run virsh domtime command with different options;
5) Check the command result;
6) Check the guest times against expectation;
7) Cleanup test environment.
"""
epoch = datetime.datetime(1970, 1, 1, 0, 0, 0)
# Max time can be set with domtime successfully in newer qemu-ga
time_max_1 = 3155731199
# Max time can be set with domtime successfully in older qemu-ga
time_max_2 = 3155759999
# Max time can be set with domtime bug failed to set RTC in older qemu-ga
time_max_3 = 9223372035
def init_time(session):
"""
Initialize guest RTC time to epoch + 1234567890 and system time
one day latter.
:param session: Session from which to access guest
"""
res = virsh.domtime(vm_name, time=1234567890)
if res.exit_status:
logging.debug("Failed to init time to 1234567890:\n%s", res)
status, output = session.cmd_status_output('date -s "1 day"')
if status:
test.error("Failed to set guest time:\n%s" % output)
def get_host_utc_time():
"""
Get host UTC time from date command.
"""
res = process.run("date -u", shell=True)
# Strip timezone info from output
# e.g. 'Sun Feb 15 07:31:40 CST 2009' -> 'Sun Feb 15 07:31:40 2009'
time_str = re.sub(r'\S+ (?=\S+$)', '', res.stdout_text.strip())
return datetime.datetime.strptime(time_str,
r"%a %b %d %H:%M:%S %Y")
def run_cmd(session, cmd):
"""
Run a command in a session and record duration of call.
"""
start = time.time()
output = session.cmd_output(cmd)
duration = time.time() - start
logging.info('Result of command "%s". Duration: %s. Output:%s',
cmd, duration, output.strip())
return output, duration
def get_guest_times(session):
"""
Retrieve different guest time as a dict for checking.
Keys:
local_hw: Guest RTC time in local timezone
local_sys: Guest system time in local timezone
utc_sys: Guest system time in UTC
domtime: Guest system time in UTC got from virsh domtime command
:param session: Session from which to access guest
"""
times = {}
get_begin = time.time()
# Guest RTC local timezone time
output, _ = run_cmd(session, 'hwclock')
try:
time_str, _ = re.search(r"(.+) (\S+ seconds)", output).groups()
try:
# output format 1: Tue 01 Mar 2016 01:53:46 PM CST
# Remove timezone info from output
new_str = re.sub(r'\s+\S+$', '', time_str)
times['local_hw'] = datetime.datetime.strptime(
new_str, r"%a %d %b %Y %I:%M:%S %p")
except ValueError:
# There are known three possible output format for `hwclock`
# output format 2: Sat Feb 14 07:31:33 2009
times['local_hw'] = datetime.datetime.strptime(
time_str, r"%a %b %d %H:%M:%S %Y")
except AttributeError:
try: # output format 3: 2019-03-22 05:16:18.224511-04:00
time_str = output.split(".")[0]
times['local_hw'] = datetime.datetime.strptime(
time_str, r"%Y-%m-%d %H:%M:%S")
except ValueError:
test.fail("Unknown hwclock output format in guest: %s", output)
delta = time.time() - get_begin
times['local_hw'] -= datetime.timedelta(seconds=delta)
# Guest system local timezone time
output, _ = run_cmd(session, 'date')
# Strip timezone info from output
# e.g. 'Sun Feb 15 07:31:40 CST 2009' -> 'Sun Feb 15 07:31:40 2009'
time_str = re.sub(r'\S+ (?=\S+$)', '', output.strip())
times['local_sys'] = datetime.datetime.strptime(
time_str, r"%a %b %d %H:%M:%S %Y")
delta = time.time() - get_begin
times['local_sys'] -= datetime.timedelta(seconds=delta)
# Guest system UTC timezone time
output, _ = run_cmd(session, 'date -u')
# Strip timezone info from output
# e.g. 'Sun Feb 15 07:31:40 CST 2009' -> 'Sun Feb 15 07:31:40 2009'
time_str = re.sub(r'\S+ (?=\S+$)', '', output.strip())
times['utc_sys'] = datetime.datetime.strptime(
time_str, r"%a %b %d %H:%M:%S %Y")
delta = time.time() - get_begin
times['utc_sys'] -= datetime.timedelta(seconds=delta)
# Guest UTC time from virsh domtime
res = virsh.domtime(vm_name, pretty=True, ignore_status=True)
if not res.exit_status:
logging.info('Result of "domtime". Duration: %s. Output:%s',
res.duration, res.stdout.strip())
_, time_str = res.stdout.split(" ", 1)
times['domtime'] = datetime.datetime.strptime(
time_str.strip(), r"%Y-%m-%d %H:%M:%S")
delta = time.time() - get_begin
times['domtime'] -= datetime.timedelta(seconds=delta)
else:
logging.debug("Unable to get domain time:\n%s", res)
times['domtime'] = None
return times, time.time() - get_begin
def check_get_success(expected_times):
"""
Check virsh command get result against expected times
:param expected_times: Expected time for checking
"""
_, time_str = res.stdout.split(" ", 1)
if pretty:
# Time: 2015-01-13 06:29:18
domtime = datetime.datetime.strptime(time_str.strip(),
r"%Y-%m-%d %H:%M:%S")
else:
# Time: 1421130740
domtime = epoch + datetime.timedelta(seconds=int(time_str))
time_shift = time.time() - start
logging.debug("Time shift is %s", time_shift)
result_diff = (domtime - expected_times['domtime']).total_seconds()
if abs(result_diff) > 2.0:
test.fail("Expect get time %s, but got %s, time "
"diff: %s" % (org_times['domtime'],
domtime, result_diff))
def check_guest_times(expected_times, cur_times):
"""
Check guest times after test against expected times
:param expected_times: Expected time for checking
"""
time_shift = time.time() - start
logging.debug("Time shift is %s", time_shift)
error_msgs = []
for key in cur_times:
if cur_times[key] is not None:
cur = cur_times[key]
expect = expected_times[key]
diff = (cur - expect).total_seconds()
msg = "For %s, expect get time %s, got %s, time diff: %s" % (
key, expect, cur, diff)
logging.debug(msg)
if abs(diff) > 2.0:
error_msgs.append(msg)
if error_msgs:
test.fail('\n'.join(error_msgs))
def check_time(result, org_times, cur_times):
"""
Check whether domain time has been change accordingly.
:param result: virsh domtime CmdResult instance
:param org_times: Original guest times
"""
action = "get"
if now or sync or (set_time is not None):
action = "set"
host_tz_diff = org_host_loc_time - org_host_time
logging.debug("Timezone diff on host is %d hours.",
(host_tz_diff.total_seconds() // 3600))
# Hardware time will never stop
logging.info('Add %ss to expected guest time', interval)
if action == 'get':
expected_times = org_times
elif action == 'set':
if result.exit_status:
# Time not change if domtime fails
expected_times = org_times
else:
# Time change accordingly if succeed.
if now:
utc_time = org_host_time
local_time = utc_time + guest_tz_diff
elif sync:
local_time = org_times["local_hw"]
utc_time = local_time - guest_tz_diff
elif set_time is not None:
utc_time = epoch + datetime.timedelta(
seconds=(int(set_time) - guest_duration))
local_time = utc_time + guest_tz_diff
expected_times = {}
expected_times['local_hw'] = local_time
expected_times['local_sys'] = local_time
expected_times["utc_sys"] = utc_time
expected_times["domtime"] = utc_time
# Add interval between two checks of guest time
for key in expected_times:
if expected_times[key] is not None:
expected_times[key] += interval
# Hardware time will never stop
# Software time will stop if suspended or managed-saved
if suspend or managedsave:
logging.info('Remove %ss from expected guest software time',
stop_time)
expected_times["domtime"] -= stop_time
expected_times["local_sys"] -= stop_time
expected_times["utc_sys"] -= stop_time
# Check guest time if domtime succeeded
check_guest_times(expected_times, cur_times)
# Check if output of domtime is correct
if action == 'get' and not result.exit_status:
check_get_success(expected_times)
def prepare_fail_patts():
"""
Predict fail pattern from test parameters.
"""
fail_patts = []
if not channel:
fail_patts.append(r"QEMU guest agent is not configured")
if not agent:
# For older version
fail_patts.append(r"Guest agent not available for now")
# For newer version
fail_patts.append(r"Guest agent is not responding")
if int(now) + int(sync) + int(bool(set_time)) > 1:
fail_patts.append(r"Options \S+ and \S+ are mutually exclusive")
if shutdown:
fail_patts.append(r"domain is not running")
if set_time is not None:
if int(set_time) < 0:
fail_patts.append(r"Invalid argument")
elif time_max_1 < int(set_time) <= time_max_2:
fail_patts.append(r"Invalid time")
elif time_max_2 < int(set_time) <= time_max_3:
fail_patts.append(r"Invalid time")
elif time_max_3 < int(set_time):
fail_patts.append(r"too big for guest agent")
if readonly:
fail_patts.append(r"operation forbidden")
return fail_patts
def stop_vm():
"""
Suspend, managedsave, pmsuspend or shutdown a VM for a period of time
"""
stop_start = time.time()
vmlogin_dur = 0.0
if suspend:
vm.pause()
time.sleep(vm_stop_duration)
vm.resume()
elif managedsave:
vm.managedsave()
time.sleep(vm_stop_duration)
vm.start()
start_dur = time.time()
vm.wait_for_login()
vmlogin_dur = time.time() - start_dur
elif pmsuspend:
vm.pmsuspend()
time.sleep(vm_stop_duration)
vm.pmwakeup()
start_dur = time.time()
vm.wait_for_login()
vmlogin_dur = time.time() - start_dur
elif shutdown:
vm.destroy()
# Check real guest stop time
stop_seconds = time.time() - stop_start - vmlogin_dur
stop_time = datetime.timedelta(seconds=stop_seconds)
logging.debug("Guest stopped: %s", stop_time)
return stop_time
# Check availability of virsh command domtime
if not virsh.has_help_command('domtime'):
test.cancel("This version of libvirt does not support "
"the domtime test")
channel = (params.get("prepare_channel", "yes") == 'yes')
agent = (params.get("start_agent", "yes") == 'yes')
pretty = (params.get("domtime_pretty", "no") == 'yes')
now = (params.get("domtime_now", "no") == 'yes')
sync = (params.get("domtime_sync", "no") == 'yes')
set_time = params.get("domtime_time", None)
shutdown = (params.get("shutdown_vm", "no") == 'yes')
suspend = (params.get("suspend_vm", "no") == 'yes')
managedsave = (params.get("managedsave_vm", "no") == 'yes')
pmsuspend = (params.get("pmsuspend_vm", "no") == 'yes')
vm_stop_duration = int(params.get("vm_stop_duration", "10"))
vm_name = params.get("main_vm")
vm = env.get_vm(vm_name)
readonly = (params.get("readonly_test", "no") == "yes")
# Backup domain XML
xml_backup = vm_xml.VMXML.new_from_inactive_dumpxml(vm_name)
try:
if pmsuspend:
vm_xml.VMXML.set_pm_suspend(vm_name)
# Add or remove qemu-agent from guest before test
vm.prepare_guest_agent(channel=channel, start=agent)
session = vm.wait_for_login()
# Let's set guest timezone to region where we do not
# have day light savings, to affect the time
session.cmd("timedatectl set-timezone Asia/Kolkata")
try:
init_guest_times, _ = get_guest_times(session)
guest_tz_diff = init_guest_times['local_sys'] - init_guest_times['utc_sys']
logging.debug("Timezone diff on guest is %d hours.",
(guest_tz_diff.total_seconds() // 3600))
if channel and agent:
init_time(session)
# Expected fail message patterns
fail_patts = prepare_fail_patts()
# Message patterns test should skip when met
skip_patts = [
r'The command \S+ has not been found',
]
# Record start time
start = time.time()
# Record host utc time before testing
org_host_time = get_host_utc_time()
# Record host local time before testing
outp = process.run('date', shell=True)
time_st = re.sub(r'\S+ (?=\S+$)', '', outp.stdout_text.strip())
org_host_loc_time = datetime.datetime.strptime(time_st, r"%a %b %d %H:%M:%S %Y")
# Get original guest times
org_times, guest_duration = get_guest_times(session)
# Run some operations to stop guest system
stop_time = stop_vm()
# Run command with specified options.
res = virsh.domtime(vm_name, now=now, pretty=pretty, sync=sync,
time=set_time, readonly=readonly, debug=True)
libvirt.check_result(res, fail_patts, skip_patts)
# Check interval between two check of guest time
interval = datetime.timedelta(
seconds=(time.time() - start))
logging.debug("Interval between guest checking: %s", interval)
if not shutdown:
# Get current guest times
cur_times, _ = get_guest_times(session)
check_time(res, org_times, cur_times)
finally:
if shutdown:
vm.start()
# sync guest timezone
utils_time.sync_timezone_linux(vm)
# Sync guest time with host
if channel and agent and not shutdown:
res = virsh.domtime(vm_name, now=True)
if res.exit_status:
session.close()
test.error("Failed to recover guest time:\n%s"
% res)
session.close()
finally:
# Restore VM XML
xml_backup.sync()
def run(test, params, env):
"""
Timer device boot guest:
1) Check host clock's sync status with chronyd
2) Add some load on host (Optional)
3) Boot the guest with specific clock source
4) Check the clock source currently used on guest
5) Do some file operation on guest (Optional)
6) Check the system time on guest and host (Optional)
7) Check the hardware time on guest (linux only)
8) Sleep period of time before reboot (Optional)
9) Reboot guest (Optional)
10) Check the system time on guest and host (Optional)
11) Check the hardware time on guest (Optional)
12) Restore guest's clock source
:param test: QEMU test object.
:param params: Dictionary with test parameters.
:param env: Dictionary with the test environment.
"""
def get_hwtime(session):
"""
Get guest's hardware clock.
:param session: VM session.
"""
hwclock_time_command = params.get("hwclock_time_command",
"hwclock -u")
hwclock_time_filter_re = params.get("hwclock_time_filter_re",
r"(\d+-\d+-\d+ \d+:\d+:\d+)")
hwclock_time_format = params.get("hwclock_time_format",
"%Y-%m-%d %H:%M:%S")
output = session.cmd_output_safe(hwclock_time_command)
try:
str_time = re.findall(hwclock_time_filter_re, output)[0]
guest_time = time.mktime(time.strptime(str_time, hwclock_time_format))
except Exception as err:
logging.debug(
"(time_format, time_string): (%s, %s)", hwclock_time_format, str_time)
raise err
return guest_time
def verify_timedrift(session, is_hardware=False):
"""
Verify timedrift between host and guest.
:param session: VM session.
:param is_hardware: if need to verify guest's hardware time.
"""
# Command to run to get the current time
time_command = params["time_command"]
# Filter which should match a string to be passed to time.strptime()
time_filter_re = params["time_filter_re"]
# Time format for time.strptime()
time_format = params["time_format"]
timerdevice_drift_threshold = float(params.get(
"timerdevice_drift_threshold", 3))
time_type = "system" if not is_hardware else "harware"
error_context.context("Check the %s time on guest" % time_type,
logging.info)
host_time, guest_time = utils_test.get_time(session, time_command,
time_filter_re,
time_format)
if is_hardware:
guest_time = get_hwtime(session)
drift = abs(float(host_time) - float(guest_time))
if drift > timerdevice_drift_threshold:
test.fail("The guest's %s time is different with"
" host's system time. Host time: '%s', guest time:"
" '%s'" % (time_type, host_time, guest_time))
def get_current_clksrc(session):
cmd = "cat /sys/devices/system/clocksource/"
cmd += "clocksource0/current_clocksource"
current_clksrc = session.cmd_output_safe(cmd)
if "kvm-clock" in current_clksrc:
return "kvm-clock"
elif "tsc" in current_clksrc:
return "tsc"
elif "timebase" in current_clksrc:
return "timebase"
elif "acpi_pm" in current_clksrc:
return "acpi_pm"
return current_clksrc
def update_clksrc(session, clksrc):
"""
Update guest's clocksource, this func can work when not login
into guest with ssh.
:param session: VM session.
:param clksrc: expected guest's clocksource.
"""
avail_cmd = "cat /sys/devices/system/clocksource/clocksource0/"
avail_cmd += "available_clocksource"
avail_clksrc = session.cmd_output_safe(avail_cmd)
if clksrc in avail_clksrc:
clksrc_cmd = "echo %s > /sys/devices/system/clocksource/" % clksrc
clksrc_cmd += "clocksource0/current_clocksource"
status, output = session.cmd_status_output(clksrc_cmd)
if status:
test.fail("fail to update guest's clocksource to %s,"
"details: %s" % clksrc, output)
else:
test.error("please check the clocksource you want to set, "
"it's not supported by current guest, current "
"available clocksources: %s" % avail_clksrc)
error_context.context("sync host time with NTP server",
logging.info)
clock_sync_command = params["clock_sync_command"]
process.system(clock_sync_command, shell=True)
timerdevice_host_load_cmd = params.get("timerdevice_host_load_cmd")
if timerdevice_host_load_cmd:
error_context.context("Add some load on host", logging.info)
process.system(timerdevice_host_load_cmd, shell=True,
ignore_bg_processes=True)
host_load_stop_cmd = params.get("timerdevice_host_load_stop_cmd",
"pkill -f 'do X=1'")
funcatexit.register(env, params["type"], _system,
host_load_stop_cmd)
vm = env.get_vm(params["main_vm"])
vm.verify_alive()
error_context.context("Sync guest timezone before test", logging.info)
if params["os_type"] == 'linux':
utils_time.sync_timezone_linux(vm)
else:
utils_time.sync_timezone_win(vm)
timeout = int(params.get("login_timeout", 360))
session = vm.wait_for_serial_login(timeout=timeout)
timerdevice_clksource = params.get("timerdevice_clksource")
need_restore_clksrc = False
if timerdevice_clksource:
origin_clksrc = get_current_clksrc(session)
logging.info("guest is booted with %s" % origin_clksrc)
if timerdevice_clksource != origin_clksrc:
update_clksrc(session, timerdevice_clksource)
need_restore_clksrc = True
error_context.context("check timedrift between guest and host.",
logging.info)
verify_timedrift(session)
if params["os_type"] == "linux":
verify_timedrift(session, is_hardware=True)
if params.get("timerdevice_reboot_test") == "yes":
sleep_time = params.get("timerdevice_sleep_time")
if sleep_time:
error_context.context("Sleep '%s' secs before reboot" % sleep_time,
logging.info)
sleep_time = int(sleep_time)
time.sleep(sleep_time)
error_context.context("Check timedrift between guest and host "
"after reboot.", logging.info)
vm.reboot(timeout=timeout, serial=True)
verify_timedrift(session)
if params["os_type"] == "linux":
verify_timedrift(session, is_hardware=True)
if need_restore_clksrc:
update_clksrc(session, origin_clksrc)
session.close()
def run(test, params, env):
"""
Time drift test with reboot:
1) Log into a guest.
2) Take a time reading from the guest and host.
3) Reboot the guest.
4) Take a second time reading.
5) If the drift (in seconds) is higher than a user specified value, fail.
:param test: QEMU test object.
:param params: Dictionary with test parameters.
:param env: Dictionary with the test environment.
"""
vm = env.get_vm(params["main_vm"])
vm.verify_alive()
boot_option_added = params.get("boot_option_added")
boot_option_removed = params.get("boot_option_removed")
if boot_option_added or boot_option_removed:
utils_test.update_boot_option(vm,
args_removed=boot_option_removed,
args_added=boot_option_added)
if params.get("os_type") == 'linux':
utils_time.sync_timezone_linux(vm)
else:
utils_time.sync_timezone_win(vm)
timeout = int(params.get("login_timeout", 360))
session = vm.wait_for_login(timeout=timeout)
# Collect test parameters:
# Command to run to get the current time
time_command = params["time_command"]
# Filter which should match a string to be passed to time.strptime()
time_filter_re = params["time_filter_re"]
# Time format for time.strptime()
time_format = params["time_format"]
drift_threshold = float(params.get("drift_threshold", "10"))
drift_threshold_single = float(params.get("drift_threshold_single", "3"))
reboot_iterations = int(params.get("reboot_iterations", 1))
try:
# Get initial time
# (ht stands for host time, gt stands for guest time)
(ht0, gt0) = utils_test.get_time(session, time_command,
time_filter_re, time_format)
# Reboot
for i in range(reboot_iterations):
# Get time before current iteration
(ht0_, gt0_) = utils_test.get_time(session, time_command,
time_filter_re, time_format)
# Run current iteration
logging.info("Rebooting: iteration %d of %d...",
(i + 1), reboot_iterations)
session = vm.reboot(session, timeout=timeout)
# Get time after current iteration
(ht1_, gt1_) = utils_test.get_time(session, time_command,
time_filter_re, time_format)
# Report iteration results
host_delta = ht1_ - ht0_
guest_delta = gt1_ - gt0_
drift = abs(host_delta - guest_delta)
logging.info("Host duration (iteration %d): %.2f",
(i + 1), host_delta)
logging.info("Guest duration (iteration %d): %.2f",
(i + 1), guest_delta)
logging.info("Drift at iteration %d: %.2f seconds",
(i + 1), drift)
# Fail if necessary
if drift > drift_threshold_single:
test.fail("Time drift too large at iteration %d: "
"%.2f seconds" % (i + 1, drift))
# Get final time
(ht1, gt1) = utils_test.get_time(session, time_command,
time_filter_re, time_format)
finally:
if session:
session.close()
# remove flags add for this test.
if boot_option_added or boot_option_removed:
utils_test.update_boot_option(vm,
args_removed=boot_option_added,
args_added=boot_option_removed)
# Report results
host_delta = ht1 - ht0
guest_delta = gt1 - gt0
drift = abs(host_delta - guest_delta)
logging.info("Host duration (%d reboots): %.2f",
reboot_iterations, host_delta)
logging.info("Guest duration (%d reboots): %.2f",
reboot_iterations, guest_delta)
logging.info("Drift after %d reboots: %.2f seconds",
reboot_iterations, drift)
# Fail if necessary
if drift > drift_threshold:
test.fail("Time drift too large after %d reboots: "
"%.2f seconds" % (reboot_iterations, drift))
