test-runner: python3 support

Updated to be compatible with Python 2.6, 2.7, 3.5 or newer.

Reviewed-by: John Ramsden <johnramsden@riseup.net>
Reviewed-by: Neal Gompa <ngompa@datto.com>
Reviewed-by: loli10K <ezomori.nozomu@gmail.com>
Reviewed-by: Brian Behlendorf <behlendorf1@llnl.gov>
Signed-off-by: John Wren Kennedy <john.kennedy@delphix.com>
Closes #8096
This commit is contained in:
John Wren Kennedy 2018-12-03 11:38:06 -07:00 committed by Tony Hutter
parent c32c2f17d0
commit 2af898ee24
1 changed files with 100 additions and 95 deletions

View File

@ -12,7 +12,7 @@
# #
# #
# Copyright (c) 2012, 2015 by Delphix. All rights reserved. # Copyright (c) 2012, 2018 by Delphix. All rights reserved.
# Copyright (c) 2017 Datto Inc. # Copyright (c) 2017 Datto Inc.
# #
@ -23,7 +23,8 @@ except ImportError:
import ConfigParser as configparser import ConfigParser as configparser
import os import os
import logging import sys
from datetime import datetime from datetime import datetime
from optparse import OptionParser from optparse import OptionParser
from pwd import getpwnam from pwd import getpwnam
@ -31,8 +32,6 @@ from pwd import getpwuid
from select import select from select import select
from subprocess import PIPE from subprocess import PIPE
from subprocess import Popen from subprocess import Popen
from sys import argv
from sys import maxsize
from threading import Timer from threading import Timer
from time import time from time import time
@ -41,6 +40,10 @@ TESTDIR = '/usr/share/zfs/'
KILL = 'kill' KILL = 'kill'
TRUE = 'true' TRUE = 'true'
SUDO = 'sudo' SUDO = 'sudo'
LOG_FILE = 'LOG_FILE'
LOG_OUT = 'LOG_OUT'
LOG_ERR = 'LOG_ERR'
LOG_FILE_OBJ = None
class Result(object): class Result(object):
@ -84,7 +87,7 @@ class Output(object):
""" """
def __init__(self, stream): def __init__(self, stream):
self.stream = stream self.stream = stream
self._buf = '' self._buf = b''
self.lines = [] self.lines = []
def fileno(self): def fileno(self):
@ -109,15 +112,15 @@ class Output(object):
buf = os.read(fd, 4096) buf = os.read(fd, 4096)
if not buf: if not buf:
return None return None
if '\n' not in buf: if b'\n' not in buf:
self._buf += buf self._buf += buf
return [] return []
buf = self._buf + buf buf = self._buf + buf
tmp, rest = buf.rsplit('\n', 1) tmp, rest = buf.rsplit(b'\n', 1)
self._buf = rest self._buf = rest
now = datetime.now() now = datetime.now()
rows = tmp.split('\n') rows = tmp.split(b'\n')
self.lines += [(now, r) for r in rows] self.lines += [(now, r) for r in rows]
@ -225,7 +228,7 @@ class Cmd(object):
proc = Popen(privcmd, stdout=PIPE, stderr=PIPE) proc = Popen(privcmd, stdout=PIPE, stderr=PIPE)
# Allow a special timeout value of 0 to mean infinity # Allow a special timeout value of 0 to mean infinity
if int(self.timeout) == 0: if int(self.timeout) == 0:
self.timeout = maxsize self.timeout = sys.maxsize
t = Timer(int(self.timeout), self.kill_cmd, [proc]) t = Timer(int(self.timeout), self.kill_cmd, [proc])
try: try:
@ -252,50 +255,52 @@ class Cmd(object):
self.result.runtime = '%02d:%02d' % (m, s) self.result.runtime = '%02d:%02d' % (m, s)
self.result.result = 'SKIP' self.result.result = 'SKIP'
def log(self, logger, options): def log(self, options):
""" """
This function is responsible for writing all output. This includes This function is responsible for writing all output. This includes
the console output, the logfile of all results (with timestamped the console output, the logfile of all results (with timestamped
merged stdout and stderr), and for each test, the unmodified merged stdout and stderr), and for each test, the unmodified
stdout/stderr/merged in it's own file. stdout/stderr/merged in it's own file.
""" """
if logger is None:
return
logname = getpwuid(os.getuid()).pw_name logname = getpwuid(os.getuid()).pw_name
user = ' (run as %s)' % (self.user if len(self.user) else logname) user = ' (run as %s)' % (self.user if len(self.user) else logname)
msga = 'Test: %s%s ' % (self.pathname, user) msga = 'Test: %s%s ' % (self.pathname, user)
msgb = '[%s] [%s]' % (self.result.runtime, self.result.result) msgb = '[%s] [%s]\n' % (self.result.runtime, self.result.result)
pad = ' ' * (80 - (len(msga) + len(msgb))) pad = ' ' * (80 - (len(msga) + len(msgb)))
result_line = msga + pad + msgb
# If -q is specified, only print a line for tests that didn't pass. # The result line is always written to the log file. If -q was
# This means passing tests need to be logged as DEBUG, or the one # specified only failures are written to the console, otherwise
# line summary will only be printed in the logfile for failures. # the result line is written to the console.
write_log(bytearray(result_line, encoding='utf-8'), LOG_FILE)
if not options.quiet: if not options.quiet:
logger.info('%s%s%s' % (msga, pad, msgb)) write_log(result_line, LOG_OUT)
elif self.result.result is not 'PASS': elif options.quiet and self.result.result is not 'PASS':
logger.info('%s%s%s' % (msga, pad, msgb)) write_log(result_line, LOG_OUT)
else:
logger.debug('%s%s%s' % (msga, pad, msgb))
lines = sorted(self.result.stdout + self.result.stderr, lines = sorted(self.result.stdout + self.result.stderr,
key=lambda x: x[0]) key=lambda x: x[0])
# Write timestamped output (stdout and stderr) to the logfile
for dt, line in lines: for dt, line in lines:
logger.debug('%s %s' % (dt.strftime("%H:%M:%S.%f ")[:11], line)) timestamp = bytearray(dt.strftime("%H:%M:%S.%f ")[:11],
encoding='utf-8')
write_log(b'%s %s\n' % (timestamp, line), LOG_FILE)
# Write the separate stdout/stderr/merged files, if the data exists
if len(self.result.stdout): if len(self.result.stdout):
with open(os.path.join(self.outputdir, 'stdout'), 'w') as out: with open(os.path.join(self.outputdir, 'stdout'), 'wb') as out:
for _, line in self.result.stdout: for _, line in self.result.stdout:
os.write(out.fileno(), '%s\n' % line) os.write(out.fileno(), b'%s\n' % line)
if len(self.result.stderr): if len(self.result.stderr):
with open(os.path.join(self.outputdir, 'stderr'), 'w') as err: with open(os.path.join(self.outputdir, 'stderr'), 'wb') as err:
for _, line in self.result.stderr: for _, line in self.result.stderr:
os.write(err.fileno(), '%s\n' % line) os.write(err.fileno(), b'%s\n' % line)
if len(self.result.stdout) and len(self.result.stderr): if len(self.result.stdout) and len(self.result.stderr):
with open(os.path.join(self.outputdir, 'merged'), 'w') as merged: with open(os.path.join(self.outputdir, 'merged'), 'wb') as merged:
for _, line in lines: for _, line in lines:
os.write(merged.fileno(), '%s\n' % line) os.write(merged.fileno(), b'%s\n' % line)
class Test(Cmd): class Test(Cmd):
@ -323,7 +328,7 @@ class Test(Cmd):
(self.pathname, self.outputdir, self.timeout, self.pre, (self.pathname, self.outputdir, self.timeout, self.pre,
pre_user, self.post, post_user, self.user, self.tags) pre_user, self.post, post_user, self.user, self.tags)
def verify(self, logger): def verify(self):
""" """
Check the pre/post scripts, user and Test. Omit the Test from this Check the pre/post scripts, user and Test. Omit the Test from this
run if there are any problems. run if there are any problems.
@ -333,19 +338,19 @@ class Test(Cmd):
for f in [f for f in files if len(f)]: for f in [f for f in files if len(f)]:
if not verify_file(f): if not verify_file(f):
logger.info("Warning: Test '%s' not added to this run because" write_log("Warning: Test '%s' not added to this run because"
" it failed verification." % f) " it failed verification.\n" % f, LOG_ERR)
return False return False
for user in [user for user in users if len(user)]: for user in [user for user in users if len(user)]:
if not verify_user(user, logger): if not verify_user(user):
logger.info("Not adding Test '%s' to this run." % write_log("Not adding Test '%s' to this run.\n" %
self.pathname) self.pathname, LOG_ERR)
return False return False
return True return True
def run(self, logger, options): def run(self, options):
""" """
Create Cmd instances for the pre/post scripts. If the pre script Create Cmd instances for the pre/post scripts. If the pre script
doesn't pass, skip this Test. Run the post script regardless. doesn't pass, skip this Test. Run the post script regardless.
@ -363,18 +368,18 @@ class Test(Cmd):
if len(pretest.pathname): if len(pretest.pathname):
pretest.run(options) pretest.run(options)
cont = pretest.result.result is 'PASS' cont = pretest.result.result is 'PASS'
pretest.log(logger, options) pretest.log(options)
if cont: if cont:
test.run(options) test.run(options)
else: else:
test.skip() test.skip()
test.log(logger, options) test.log(options)
if len(posttest.pathname): if len(posttest.pathname):
posttest.run(options) posttest.run(options)
posttest.log(logger, options) posttest.log(options)
class TestGroup(Test): class TestGroup(Test):
@ -398,7 +403,7 @@ class TestGroup(Test):
(self.pathname, self.outputdir, self.tests, self.timeout, (self.pathname, self.outputdir, self.tests, self.timeout,
self.pre, pre_user, self.post, post_user, self.user, self.tags) self.pre, pre_user, self.post, post_user, self.user, self.tags)
def verify(self, logger): def verify(self):
""" """
Check the pre/post scripts, user and tests in this TestGroup. Omit Check the pre/post scripts, user and tests in this TestGroup. Omit
the TestGroup entirely, or simply delete the relevant tests in the the TestGroup entirely, or simply delete the relevant tests in the
@ -416,34 +421,34 @@ class TestGroup(Test):
for f in [f for f in auxfiles if len(f)]: for f in [f for f in auxfiles if len(f)]:
if self.pathname != os.path.dirname(f): if self.pathname != os.path.dirname(f):
logger.info("Warning: TestGroup '%s' not added to this run. " write_log("Warning: TestGroup '%s' not added to this run. "
"Auxiliary script '%s' exists in a different " "Auxiliary script '%s' exists in a different "
"directory." % (self.pathname, f)) "directory.\n" % (self.pathname, f), LOG_ERR)
return False return False
if not verify_file(f): if not verify_file(f):
logger.info("Warning: TestGroup '%s' not added to this run. " write_log("Warning: TestGroup '%s' not added to this run. "
"Auxiliary script '%s' failed verification." % "Auxiliary script '%s' failed verification.\n" %
(self.pathname, f)) (self.pathname, f), LOG_ERR)
return False return False
for user in [user for user in users if len(user)]: for user in [user for user in users if len(user)]:
if not verify_user(user, logger): if not verify_user(user):
logger.info("Not adding TestGroup '%s' to this run." % write_log("Not adding TestGroup '%s' to this run.\n" %
self.pathname) self.pathname, LOG_ERR)
return False return False
# If one of the tests is invalid, delete it, log it, and drive on. # If one of the tests is invalid, delete it, log it, and drive on.
for test in self.tests: for test in self.tests:
if not verify_file(os.path.join(self.pathname, test)): if not verify_file(os.path.join(self.pathname, test)):
del self.tests[self.tests.index(test)] del self.tests[self.tests.index(test)]
logger.info("Warning: Test '%s' removed from TestGroup '%s' " write_log("Warning: Test '%s' removed from TestGroup '%s' "
"because it failed verification." % "because it failed verification.\n" %
(test, self.pathname)) (test, self.pathname), LOG_ERR)
return len(self.tests) is not 0 return len(self.tests) is not 0
def run(self, logger, options): def run(self, options):
""" """
Create Cmd instances for the pre/post scripts. If the pre script Create Cmd instances for the pre/post scripts. If the pre script
doesn't pass, skip all the tests in this TestGroup. Run the post doesn't pass, skip all the tests in this TestGroup. Run the post
@ -464,7 +469,7 @@ class TestGroup(Test):
if len(pretest.pathname): if len(pretest.pathname):
pretest.run(options) pretest.run(options)
cont = pretest.result.result is 'PASS' cont = pretest.result.result is 'PASS'
pretest.log(logger, options) pretest.log(options)
for fname in self.tests: for fname in self.tests:
test = Cmd(os.path.join(self.pathname, fname), test = Cmd(os.path.join(self.pathname, fname),
@ -475,11 +480,11 @@ class TestGroup(Test):
else: else:
test.skip() test.skip()
test.log(logger, options) test.log(options)
if len(posttest.pathname): if len(posttest.pathname):
posttest.run(options) posttest.run(options)
posttest.log(logger, options) posttest.log(options)
class TestRun(object): class TestRun(object):
@ -491,7 +496,7 @@ class TestRun(object):
self.starttime = time() self.starttime = time()
self.timestamp = datetime.now().strftime('%Y%m%dT%H%M%S') self.timestamp = datetime.now().strftime('%Y%m%dT%H%M%S')
self.outputdir = os.path.join(options.outputdir, self.timestamp) self.outputdir = os.path.join(options.outputdir, self.timestamp)
self.logger = self.setup_logging(options) self.setup_logging(options)
self.defaults = [ self.defaults = [
('outputdir', BASEDIR), ('outputdir', BASEDIR),
('quiet', False), ('quiet', False),
@ -524,7 +529,7 @@ class TestRun(object):
for prop in Test.props: for prop in Test.props:
setattr(test, prop, getattr(options, prop)) setattr(test, prop, getattr(options, prop))
if test.verify(self.logger): if test.verify():
self.tests[pathname] = test self.tests[pathname] = test
def addtestgroup(self, dirname, filenames, options): def addtestgroup(self, dirname, filenames, options):
@ -546,9 +551,9 @@ class TestRun(object):
self.testgroups[dirname] = testgroup self.testgroups[dirname] = testgroup
self.testgroups[dirname].tests = sorted(filenames) self.testgroups[dirname].tests = sorted(filenames)
testgroup.verify(self.logger) testgroup.verify()
def read(self, logger, options): def read(self, options):
""" """
Read in the specified runfile, and apply the TestRun properties Read in the specified runfile, and apply the TestRun properties
listed in the 'DEFAULT' section to our TestRun. Then read each listed in the 'DEFAULT' section to our TestRun. Then read each
@ -589,7 +594,7 @@ class TestRun(object):
# Repopulate tests using eval to convert the string to a list # Repopulate tests using eval to convert the string to a list
testgroup.tests = eval(config.get(section, 'tests')) testgroup.tests = eval(config.get(section, 'tests'))
if testgroup.verify(logger): if testgroup.verify():
self.testgroups[section] = testgroup self.testgroups[section] = testgroup
else: else:
test = Test(section) test = Test(section)
@ -598,7 +603,7 @@ class TestRun(object):
if config.has_option(sect, prop): if config.has_option(sect, prop):
setattr(test, prop, config.get(sect, prop)) setattr(test, prop, config.get(sect, prop))
if test.verify(logger): if test.verify():
self.tests[section] = test self.tests[section] = test
def write(self, options): def write(self, options):
@ -661,42 +666,23 @@ class TestRun(object):
def setup_logging(self, options): def setup_logging(self, options):
""" """
Two loggers are set up here. The first is for the logfile which This funtion creates the output directory and gets a file object
will contain one line summarizing the test, including the test for the logfile. This function must be called before write_log()
name, result, and running time. This logger will also capture the can be used.
timestamped combined stdout and stderr of each run. The second
logger is optional console output, which will contain only the one
line summary. The loggers are initialized at two different levels
to facilitate segregating the output.
""" """
if options.dryrun is True: if options.dryrun is True:
return return
testlogger = logging.getLogger(__name__) global LOG_FILE_OBJ
testlogger.setLevel(logging.DEBUG)
if options.cmd is not 'wrconfig': if options.cmd is not 'wrconfig':
try: try:
old = os.umask(0) old = os.umask(0)
os.makedirs(self.outputdir, mode=0o777) os.makedirs(self.outputdir, mode=0o777)
os.umask(old) os.umask(old)
filename = os.path.join(self.outputdir, 'log')
LOG_FILE_OBJ = open(filename, buffering=0, mode='wb')
except OSError as e: except OSError as e:
fail('%s' % e) fail('%s' % e)
filename = os.path.join(self.outputdir, 'log')
logfile = logging.FileHandler(filename)
logfile.setLevel(logging.DEBUG)
logfilefmt = logging.Formatter('%(message)s')
logfile.setFormatter(logfilefmt)
testlogger.addHandler(logfile)
cons = logging.StreamHandler()
cons.setLevel(logging.INFO)
consfmt = logging.Formatter('%(message)s')
cons.setFormatter(consfmt)
testlogger.addHandler(cons)
return testlogger
def run(self, options): def run(self, options):
""" """
@ -713,14 +699,14 @@ class TestRun(object):
if not os.path.exists(logsymlink): if not os.path.exists(logsymlink):
os.symlink(self.outputdir, logsymlink) os.symlink(self.outputdir, logsymlink)
else: else:
print('Could not make a symlink to directory %s' % ( write_log('Could not make a symlink to directory %s\n' %
self.outputdir)) self.outputdir, LOG_ERR)
iteration = 0 iteration = 0
while iteration < options.iterations: while iteration < options.iterations:
for test in sorted(self.tests.keys()): for test in sorted(self.tests.keys()):
self.tests[test].run(self.logger, options) self.tests[test].run(options)
for testgroup in sorted(self.testgroups.keys()): for testgroup in sorted(self.testgroups.keys()):
self.testgroups[testgroup].run(self.logger, options) self.testgroups[testgroup].run(options)
iteration += 1 iteration += 1
def summary(self): def summary(self):
@ -748,6 +734,23 @@ class TestRun(object):
return 0 return 0
def write_log(msg, target):
"""
Write the provided message to standard out, standard error or
the logfile. If specifying LOG_FILE, then `msg` must be a bytes
like object. This way we can still handle output from tests that
may be in unexpected encodings.
"""
if target == LOG_OUT:
os.write(sys.stdout.fileno(), bytearray(msg, encoding='utf-8'))
elif target == LOG_ERR:
os.write(sys.stderr.fileno(), bytearray(msg, encoding='utf-8'))
elif target == LOG_FILE:
os.write(LOG_FILE_OBJ.fileno(), msg)
else:
fail('log_msg called with unknown target "%s"' % target)
def verify_file(pathname): def verify_file(pathname):
""" """
Verify that the supplied pathname is an executable regular file. Verify that the supplied pathname is an executable regular file.
@ -763,7 +766,7 @@ def verify_file(pathname):
return False return False
def verify_user(user, logger): def verify_user(user):
""" """
Verify that the specified user exists on this system, and can execute Verify that the specified user exists on this system, and can execute
sudo without being prompted for a password. sudo without being prompted for a password.
@ -776,13 +779,15 @@ def verify_user(user, logger):
try: try:
getpwnam(user) getpwnam(user)
except KeyError: except KeyError:
logger.info("Warning: user '%s' does not exist.", user) write_log("Warning: user '%s' does not exist.\n" % user,
LOG_ERR)
return False return False
p = Popen(testcmd) p = Popen(testcmd)
p.wait() p.wait()
if p.returncode is not 0: if p.returncode is not 0:
logger.info("Warning: user '%s' cannot use passwordless sudo.", user) write_log("Warning: user '%s' cannot use passwordless sudo.\n" % user,
LOG_ERR)
return False return False
else: else:
Cmd.verified_users.append(user) Cmd.verified_users.append(user)
@ -810,7 +815,7 @@ def find_tests(testrun, options):
def fail(retstr, ret=1): def fail(retstr, ret=1):
print('%s: %s' % (argv[0], retstr)) print('%s: %s' % (sys.argv[0], retstr))
exit(ret) exit(ret)
@ -900,7 +905,7 @@ def main():
if options.cmd is 'runtests': if options.cmd is 'runtests':
find_tests(testrun, options) find_tests(testrun, options)
elif options.cmd is 'rdconfig': elif options.cmd is 'rdconfig':
testrun.read(testrun.logger, options) testrun.read(options)
elif options.cmd is 'wrconfig': elif options.cmd is 'wrconfig':
find_tests(testrun, options) find_tests(testrun, options)
testrun.write(options) testrun.write(options)