def testReturncode(self, cmd1, cmd2, returncode):
p1 = v2v._simple_exec_cmd([cmd1], stdout=subprocess.PIPE)
with terminating(p1):
p2 = v2v._simple_exec_cmd([cmd2],
stdin=p1.stdout,
stdout=subprocess.PIPE)
with terminating(p2):
p = v2v.PipelineProc(p1, p2)
p.wait(self.PROC_WAIT_TIMEOUT)
assert p.returncode == returncode
def testWait(self, cmd1, cmd2):
p1 = v2v._simple_exec_cmd(cmd1, stdout=subprocess.PIPE)
with terminating(p1):
p2 = v2v._simple_exec_cmd(cmd2,
stdin=p1.stdout,
stdout=subprocess.PIPE)
with terminating(p2):
p = v2v.PipelineProc(p1, p2)
ret = p.wait(2 * SHORT_SLEEP)
p.kill()
assert ret is False
def testReturncode(self, cmd1, cmd2, returncode):
p1 = v2v._simple_exec_cmd([cmd1],
stdout=subprocess.PIPE)
with terminating(p1):
p2 = v2v._simple_exec_cmd([cmd2],
stdin=p1.stdout,
stdout=subprocess.PIPE)
with terminating(p2):
p = v2v.PipelineProc(p1, p2)
p.wait(self.PROC_WAIT_TIMEOUT)
self.assertEqual(p.returncode, returncode)
def testWait(self, cmd1, cmd2):
p1 = v2v._simple_exec_cmd(cmd1,
stdout=subprocess.PIPE)
with terminating(p1):
p2 = v2v._simple_exec_cmd(cmd2,
stdin=p1.stdout,
stdout=subprocess.PIPE)
with terminating(p2):
p = v2v.PipelineProc(p1, p2)
ret = p.wait(2 * SHORT_SLEEP)
p.kill()
self.assertEqual(ret, False)
def test_wait_on_two_processes_that_finished(self):
cmd = ['sleep', str(SHORT_SLEEP)]
p1 = v2v._simple_exec_cmd(cmd, stdout=subprocess.PIPE)
with terminating(p1):
p2 = v2v._simple_exec_cmd(
cmd, stdin=p1.stdout, stdout=subprocess.PIPE)
with terminating(p2):
# Wait for the processes to finish.
time.sleep(2 * SHORT_SLEEP)
p = v2v.PipelineProc(p1, p2)
ret = p.wait(2 * SHORT_SLEEP)
p.kill()
self.assertEqual(ret, True)
def test_wait_on_two_processes_that_finish_before_timeout(self):
cmd1 = ['sleep', str(SHORT_SLEEP)]
cmd2 = ['sleep', str(1.5 * SHORT_SLEEP)]
p1 = v2v._simple_exec_cmd(cmd1, stdout=subprocess.PIPE)
with terminating(p1):
p2 = v2v._simple_exec_cmd(
cmd2, stdin=p1.stdout, stdout=subprocess.PIPE)
with terminating(p2):
p = v2v.PipelineProc(p1, p2)
# Processes finish at different times but before the timeout.
ret = p.wait(3 * SHORT_SLEEP)
p.kill()
self.assertEqual(ret, True)
def test_wait_on_two_processes_that_finished(self):
cmd = ['sleep', str(SHORT_SLEEP)]
p1 = v2v._simple_exec_cmd(cmd, stdout=subprocess.PIPE)
with terminating(p1):
p2 = v2v._simple_exec_cmd(
cmd, stdin=p1.stdout, stdout=subprocess.PIPE)
with terminating(p2):
# Wait for the processes to finish.
time.sleep(2 * SHORT_SLEEP)
p = v2v.PipelineProc(p1, p2)
ret = p.wait(2 * SHORT_SLEEP)
p.kill()
self.assertEqual(ret, True)
def test_wait_on_two_processes_that_finish_before_timeout(self):
cmd1 = ['sleep', str(SHORT_SLEEP)]
cmd2 = ['sleep', str(1.5 * SHORT_SLEEP)]
p1 = v2v._simple_exec_cmd(cmd1, stdout=subprocess.PIPE)
with terminating(p1):
p2 = v2v._simple_exec_cmd(
cmd2, stdin=p1.stdout, stdout=subprocess.PIPE)
with terminating(p2):
p = v2v.PipelineProc(p1, p2)
# Processes finish at different times but before the timeout.
ret = p.wait(3 * SHORT_SLEEP)
p.kill()
self.assertEqual(ret, True)
def copyToImage(dstImgPath, methodArgs):
totalSize = getLengthFromArgs(methodArgs)
fileObj = methodArgs['fileObj']
# Unlike copyFromImage, we don't use direct I/O when writing because:
# - Images are small so using host page cache is ok.
# - Images typically aligned to 512 bytes (tar), may fail on 4k storage.
cmd = [
constants.EXT_DD,
"of=%s" % dstImgPath,
"bs=%s" % MiB,
# Ensure that data reach physical storage before returning.
"conv=fsync",
]
log.info("Copy to image %s", dstImgPath)
with utils.stopwatch("Copy %s bytes" % totalSize,
level=logging.INFO,
log=log):
p = commands.start(cmd, stdin=subprocess.PIPE, stderr=subprocess.PIPE)
with commands.terminating(p):
_copyData(fileObj, p.stdin, totalSize)
try:
_, err = p.communicate(timeout=WAIT_TIMEOUT)
except subprocess.TimeoutExpired:
log.error("timeout waiting for dd process")
raise se.StorageException()
if p.returncode != 0:
log.error("dd failed rc=%s err=%r", p.returncode, err)
raise se.MiscFileWriteException()
def check_failure(self):
with self.assertRaises(commands.TerminatingFailure) as e:
with commands.terminating(self.proc):
self.assertIsNone(self.proc_poll())
self.assertEqual(e.exception.pid, self.proc.pid)
self.assertEqual(type(e.exception.error), ExpectedFailure)
def testRun(self):
msg = 'foo\nbar'
p1 = v2v._simple_exec_cmd(['echo', '-n', msg], stdout=subprocess.PIPE)
with terminating(p1):
p2 = v2v._simple_exec_cmd(['cat'],
stdin=p1.stdout,
stdout=subprocess.PIPE)
with terminating(p2):
p = v2v.PipelineProc(p1, p2)
assert p.pids == [p1.pid, p2.pid]
ret = p.wait(self.PROC_WAIT_TIMEOUT)
assert ret is True
out = p.stdout.read()
assert out == msg.encode()
def testRun(self):
msg = 'foo\nbar'
p1 = v2v._simple_exec_cmd(['echo', '-n', msg], stdout=subprocess.PIPE)
with terminating(p1):
p2 = v2v._simple_exec_cmd(['cat'],
stdin=p1.stdout,
stdout=subprocess.PIPE)
with terminating(p2):
p = v2v.PipelineProc(p1, p2)
self.assertEqual(p.pids, [p1.pid, p2.pid])
ret = p.wait(self.PROC_WAIT_TIMEOUT)
self.assertEqual(ret, True)
out = p.stdout.read()
self.assertEqual(out, msg.encode())
def testRun(self):
msg = 'foo\nbar'
p1 = v2v._simple_exec_cmd(['echo', '-n', msg],
stdout=subprocess.PIPE)
with terminating(p1):
p2 = v2v._simple_exec_cmd(['cat'],
stdin=p1.stdout,
stdout=subprocess.PIPE)
with terminating(p2):
p = v2v.PipelineProc(p1, p2)
self.assertEqual(p.pids, [p1.pid, p2.pid])
ret = p.wait(self.PROC_WAIT_TIMEOUT)
self.assertEqual(ret, True)
out = p.stdout.read()
self.assertEqual(out, msg.encode())
def copyFromImage(dstImgPath, methodArgs):
fileObj = methodArgs['fileObj']
bytes_left = total_size = methodArgs['length']
cmd = [constants.EXT_DD, "if=%s" % dstImgPath, "bs=%s" % constants.MEGAB,
"count=%s" % (total_size / constants.MEGAB + 1)]
p = commands.execCmd(cmd, sync=False)
p.blocking = True
with commands.terminating(p):
_copyData(p.stdout, fileObj, bytes_left)
def copyFromImage(dstImgPath, methodArgs):
fileObj = methodArgs['fileObj']
bytes_left = total_size = methodArgs['length']
cmd = [constants.EXT_DD, "if=%s" % dstImgPath, "bs=%s" % constants.MEGAB,
"count=%s" % (total_size // constants.MEGAB + 1)]
p = commands.execCmd(cmd, sync=False)
p.blocking = True
with commands.terminating(p):
_copyData(p.stdout, fileObj, bytes_left)
def test_process_zombie(self):
self.proc.terminate()
wait_for_zombie(self.proc, 1)
def fail():
raise RuntimeError("Attempt to kill a zombie process")
self.proc.kill = fail
with commands.terminating(self.proc):
pass
self.assertEqual(self.proc.returncode, -signal.SIGTERM)
def copyToImage(dstImgPath, methodArgs):
totalSize = getLengthFromArgs(methodArgs)
fileObj = methodArgs['fileObj']
cmd = [constants.EXT_DD, "of=%s" % dstImgPath, "bs=%s" % constants.MEGAB]
p = commands.execCmd(cmd, sync=False)
with commands.terminating(p):
_copyData(fileObj, p.stdin, totalSize)
p.stdin.close()
if not p.wait(WAIT_TIMEOUT):
log.error("timeout waiting for dd process")
raise se.StorageException()
if p.returncode != 0:
log.error("dd error - code %s, stderr %s",
p.returncode, p.stderr.read(1000))
raise se.MiscFileWriteException()
def copyToImage(dstImgPath, methodArgs):
totalSize = getLengthFromArgs(methodArgs)
fileObj = methodArgs['fileObj']
cmd = [constants.EXT_DD, "of=%s" % dstImgPath, "bs=%s" % constants.MEGAB]
p = commands.execCmd(cmd, sync=False)
with commands.terminating(p):
_copyData(fileObj, p.stdin, totalSize)
p.stdin.close()
if not p.wait(WAIT_TIMEOUT):
log.error("timeout waiting for dd process")
raise se.StorageException()
if p.returncode != 0:
log.error("dd error - code %s, stderr %s",
p.returncode, p.stderr.read(1000))
raise se.MiscFileWriteException()
def _query_v2v_caps(self):
self._v2v_caps = frozenset()
p = _simple_exec_cmd([_VIRT_V2V.cmd, '--machine-readable'],
env=os.environ.copy(),
stdout=subprocess.PIPE,
stderr=subprocess.PIPE)
with terminating(p):
try:
out, err = p.communicate()
except Exception:
logging.exception('Terminating virt-v2v process after error')
raise
if p.returncode != 0:
raise V2VProcessError('virt-v2v exited with code: %d, stderr: %r' %
(p.returncode, err))
self._v2v_caps = frozenset(out.decode('utf8').splitlines())
logging.debug("Detected virt-v2v capabilities: %r", self._v2v_caps)
def _query_v2v_caps(self):
self._v2v_caps = frozenset()
p = _simple_exec_cmd([_VIRT_V2V.cmd, '--machine-readable'],
env=os.environ.copy(),
stdout=subprocess.PIPE,
stderr=subprocess.PIPE)
with terminating(p):
try:
out, err = p.communicate()
except Exception:
logging.exception('Terminating virt-v2v process after error')
raise
if p.returncode != 0:
raise V2VProcessError(
'virt-v2v exited with code: %d, stderr: %r' %
(p.returncode, err))
self._v2v_caps = frozenset(out.decode('utf8').splitlines())
logging.debug("Detected virt-v2v capabilities: %r", self._v2v_caps)
def copyFromImage(dstImgPath, methodArgs):
fileObj = methodArgs['fileObj']
bytes_left = total_size = methodArgs['length']
# Unlike copyToImage, we must use direct I/O to avoid reading stale data
# from host page cache, in case OVF disk was modified on another host.
cmd = [
constants.EXT_DD,
"if=%s" % dstImgPath,
"bs=%s" % MiB,
"count=%s" % (total_size // MiB + 1),
"iflag=direct",
]
log.info("Copy from image %s", dstImgPath)
with utils.stopwatch(
"Copy %s bytes" % total_size, level=logging.INFO, log=log):
p = commands.start(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE)
with commands.terminating(p):
_copyData(p.stdout, fileObj, bytes_left)
def _runHooksDir(data,
dir,
vmconf={},
raiseError=True,
errors=None,
params={},
hookType=_DOMXML_HOOK):
if errors is None:
errors = []
scripts = _scriptsPerDir(dir)
scripts.sort()
if not scripts:
return data
data_fd, data_filename = tempfile.mkstemp()
try:
if hookType == _DOMXML_HOOK:
os.write(data_fd, data.encode('utf-8') if data else b'')
elif hookType == _JSON_HOOK:
os.write(data_fd, json.dumps(data).encode('utf-8'))
os.close(data_fd)
scriptenv = os.environ.copy()
# Update the environment using params and custom configuration
env_update = [
six.iteritems(params),
six.iteritems(vmconf.get('custom', {}))
]
# Encode custom properties to UTF-8 and save them to scriptenv
# Pass str objects (byte-strings) without any conversion
for k, v in itertools.chain(*env_update):
try:
if isinstance(v, six.text_type):
scriptenv[k] = v.encode('utf-8')
else:
scriptenv[k] = v
except UnicodeEncodeError:
pass
if vmconf.get('vmId'):
scriptenv['vmId'] = vmconf.get('vmId')
ppath = scriptenv.get('PYTHONPATH', '')
hook = os.path.dirname(pkgutil.get_loader('vdsm.hook').get_filename())
scriptenv['PYTHONPATH'] = ':'.join(ppath.split(':') + [hook])
if hookType == _DOMXML_HOOK:
scriptenv['_hook_domxml'] = data_filename
elif hookType == _JSON_HOOK:
scriptenv['_hook_json'] = data_filename
for s in scripts:
p = commands.start([s],
stdout=subprocess.PIPE,
stderr=subprocess.PIPE,
env=scriptenv)
with commands.terminating(p):
(out, err) = p.communicate()
rc = p.returncode
logging.info('%s: rc=%s err=%s', s, rc, err)
if rc != 0:
errors.append(err)
if rc == 2:
break
elif rc > 2:
logging.warning('hook returned unexpected return code %s', rc)
if errors and raiseError:
raise exception.HookError(err)
with open(data_filename) as f:
final_data = f.read()
finally:
os.unlink(data_filename)
if hookType == _DOMXML_HOOK:
return final_data
elif hookType == _JSON_HOOK:
return json.loads(final_data)
def run_logging(args, log_tag=None):
"""
Start a command storing its stdout/stderr into a file, communicate with it,
and wait until the command terminates. Ensures that the command is killed
if an unexpected error is raised. Note that since the stdout/stderr is
redirected to the file it is not piped to VDSM.
args are logged when command starts, and are included in the exception if a
command has failed. If args contain sensitive information that should not
be logged, such as passwords, they must be wrapped with ProtectedPassword.
While access to the directory with log files is restricted caution should
be taken when logging commands. Avoid storing output of commands that may
leak passwords or other sensitive information.
The child process stdout and stderr are always buffered. If you have
special needs, such as running the command without buffering stdout, or
create a pipeline of several commands, use the lower level start()
function.
If log_tag is not used the log file name is
'virtcmd-<command>-<datetime>-<random_string>.log'. If
log_tag is used the format is
'virtcmd-<command>-<log_tag>-<datetime>-<random_string>.log'.
The granularity of <datetime> part of the file name is one second. To
minimize file collision there is a random string of characters appended to
the name.
Arguments:
args (list): Command arguments
log_tag (str): Optional string to be included in log file name to
better distinguish the log files and avoid potential name
collisions. This could be for example VM ID.
Returns:
Path to the log file.
Raises:
LoggingError if the command terminated with a non-zero exit code.
TerminatingFailure if command could not be terminated.
"""
stdout = subprocess.DEVNULL
stderr = subprocess.DEVNULL
cmd_log_file = None
timestamp = time.strftime('%Y%m%dT%H%M%S')
command = os.path.basename(str(args[0]))
log_tag = '' if log_tag is None else '-%s' % log_tag
suffix = ''.join(random.choice(string.ascii_lowercase) for _ in range(4))
cmd_log_path = os.path.join(
_COMMANDS_LOG_DIR,
'virtcmd-%s%s-%s-%s.log' % (command, log_tag, timestamp, suffix))
try:
os.makedirs(_COMMANDS_LOG_DIR, mode=0o750, exist_ok=True)
cmd_log_file = os.open(cmd_log_path,
os.O_WRONLY | os.O_CREAT | os.O_APPEND,
mode=0o640)
except OSError:
log.exception('Failed to open log file')
cmd_log_path = None
else:
stdout = cmd_log_file
stderr = cmd_log_file
log.debug('Running command %r with logs in %s', args, cmd_log_path)
p = start(args, stdin=subprocess.PIPE, stdout=stdout, stderr=stderr)
with terminating(p):
p.communicate()
log.debug(cmdutils.retcode_log_line(p.returncode))
if cmd_log_file is not None:
os.close(cmd_log_file)
if p.returncode != 0:
raise LoggingError(args, p.returncode, cmd_log_path)
return cmd_log_path
def test_process_running(self):
with commands.terminating(self.proc):
self.assertIsNone(self.proc_poll())
self.assertEqual(self.proc.returncode, -signal.SIGKILL)
