def test_process_failed_to_start(tempfiles):
shell = Process(script_name=sys.executable)
script = tempfiles.makepyfile("""
# coding=utf-8
1/0
""")
result = shell.run(script)
assert result.exitcode == 1
assert "ZeroDivisionError: division by zero" in result.stderr
def test_exitcode(exitcode, tempfiles):
shell = Process(script_name=sys.executable)
script = tempfiles.makepyfile("""
# coding=utf-8
import time
time.sleep(0.125)
exit({})
""".format(exitcode))
result = shell.run(script)
assert result.exitcode == exitcode
def test_stderr_output(tempfiles):
input_str = "Thou shalt not exit cleanly"
shell = Process(script_name=sys.executable)
script = tempfiles.makepyfile("""
# coding=utf-8
exit("{}")
""".format(input_str))
result = shell.run(script)
assert result.exitcode == 1
assert result.stderr == input_str + "\n"
def test_timeout_defined_on_class_instantiation(tempfiles):
shell = Process(script_name=sys.executable, timeout=0.5)
script = tempfiles.makepyfile("""
# coding=utf-8
import time
time.sleep(1)
exit(0)
""")
with pytest.raises(FactoryTimeout):
shell.run(script)
def test_handler_does_not_block_when_not_connected(tempfiles):
log_forwarding_socket_hwm = 5
shell = Process(script_name=sys.executable, timeout=10)
script = tempfiles.makepyfile("""
# coding=utf-8
import sys
import time
import logging
import multiprocessing
from saltfactories.utils.saltext.log_handlers.pytest_log_handler import ZMQHandler
# Salt was imported by now and set up it's own logging handlers. Remove them.
logging.root.handlers = []
# Setup a stream handler so that we can confirm that logging is working
logging.basicConfig(
stream=sys.stderr,
level=logging.DEBUG,
format="[%(levelname)-8s][%(processName)s(%(process)s)] %(message)s"
)
# Add our ZMQ handler, it should not block even though it does not connect anywhere
handler = ZMQHandler(port=123456, socket_hwm={})
logging.root.addHandler(handler)
def main():
log = logging.getLogger("foo")
print("Logging started", flush=True)
for idx in range(50):
log.debug("Foo %s", idx)
print("Logging finished", flush=True)
logging.shutdown()
exit(0)
if __name__ == '__main__':
multiprocessing.freeze_support()
main()
""".format(log_forwarding_socket_hwm))
try:
result = shell.run(script)
except FactoryTimeout as exc: # pragma: no cover
pytest.fail("The ZMQHandler blocked. Process result:\n{}".format(exc))
# If the exitcode is not 0, that means the script was forcefully terminated, which,
# in turn means the ZMQHandler blocked the process when not connected to the log
# listener.
assert "Logging started" in result.stdout
assert "Logging finished" in result.stdout
# Since we set a HWM of log_forwarding_socket_hwm, we should at least see
# Foo {log_forwarding_socket_hwm + 1} logged to the console.
# If we don't, the handler blocked the process
assert "Foo {}".format(log_forwarding_socket_hwm + 1) in result.stderr
assert result.exitcode == 0
def test_json_output(input_str, expected_object, tempfiles):
shell = Process(script_name=sys.executable)
script = tempfiles.makepyfile("""
# coding=utf-8
import sys
sys.stdout.write('''{}''')
exit(0)
""".format(input_str))
result = shell.run(script)
assert result.exitcode == 0
if result.json:
assert result.json == expected_object
assert result.stdout == input_str
def test_unicode_output(tempfiles):
shell = Process(script_name=sys.executable)
script = tempfiles.makepyfile(r"""
# coding=utf-8
from __future__ import print_function
import sys
sys.stdout.write(u'STDOUT F\xe1tima')
sys.stdout.flush()
sys.stderr.write(u'STDERR F\xe1tima')
sys.stderr.flush()
exit(0)
""")
result = shell.run(script)
assert result.exitcode == 0, str(result)
assert result.stdout == "STDOUT Fátima"
assert result.stderr == "STDERR Fátima"
def test_timeout_defined_run(tempfiles):
shell = Process(script_name=sys.executable)
script = tempfiles.makepyfile("""
# coding=utf-8
import time
time.sleep(0.5)
exit(0)
""")
result = shell.run(script)
assert result.exitcode == 0
script = tempfiles.makepyfile("""
# coding=utf-8
import time
time.sleep(0.5)
exit(0)
""")
with pytest.raises(FactoryTimeout):
shell.run(script, _timeout=0.1)
def test_all_messages_received(tempfiles, salt_factories, caplog):
log_forwarding_socket_hwm = 500
log_forwarding_calls = log_forwarding_socket_hwm * 2
shell = Process(script_name=sys.executable, timeout=10)
script = tempfiles.makepyfile("""
# coding=utf-8
import sys
import time
import logging
import multiprocessing
from saltfactories.utils.saltext.log_handlers.pytest_log_handler import ZMQHandler
# Salt was imported by now and set up it's own logging handlers. Remove them.
logging.root.handlers = []
# Setup a stream handler so that we can confirm that logging is working
logging.basicConfig(
stream=sys.stderr,
level=logging.DEBUG,
format="[%(levelname)-8s][%(processName)s(%(process)s)] %(message)s"
)
# Add our ZMQ handler
handler = ZMQHandler(port={}, socket_hwm={})
logging.root.addHandler(handler)
def main():
log = logging.getLogger("foo")
print("Logging started", flush=True)
for idx in range(1, {} + 1):
log.debug("Foo:%s", idx)
print("Logging finished", flush=True)
exit(0)
if __name__ == '__main__':
multiprocessing.freeze_support()
main()
""".format(salt_factories.log_server_port, log_forwarding_socket_hwm,
log_forwarding_calls))
with caplog.at_level(logging.DEBUG, logger="foo"):
try:
result = shell.run(script)
except FactoryTimeout as exc: # pragma: no cover
pytest.fail(
"The ZMQHandler blocked. Process result:\n{}".format(exc))
# If the exitcode is not 0, that means the script was forcefully terminated, which,
# in turn means the ZMQHandler blocked the process when not connected to the log
# listener.
assert "Logging started" in result.stdout
assert "Logging finished" in result.stdout
expected_log_message = "Foo:{}".format(log_forwarding_calls)
assert expected_log_message in result.stderr
assert result.exitcode == 0
timeout = datetime.utcnow() + timedelta(seconds=120)
while True:
missed = []
found_log_messages = []
# We try multiple times because the script might have properly
# flushed it's messages to the log server, but the log server
# might still be processing them
for record in caplog.records:
if record.message.startswith("Foo"):
msgnum = int(record.message.split(":")[-1])
found_log_messages.append(msgnum)
for idx in range(1, log_forwarding_calls + 1):
if idx not in found_log_messages: # pragma: no cover
missed.append(idx)
try:
assert (
len(found_log_messages) == log_forwarding_calls
), "len(found_log_messages={}) != {} // Missed: {}".format(
len(found_log_messages), log_forwarding_calls, missed)
break
except AssertionError: # pragma: no cover
if datetime.utcnow() > timeout:
raise
def test_all_messages_received_multiprocessing(tempfiles, salt_factories,
caplog, fork_method):
# The purpose of this test is just to make sure if forked/spawned processes inherit the
# ZMQHandler and continue logging
if fork_method == "fork":
if pytestskipmarkers.utils.platform.is_windows():
pytest.skip("Start method '{}' is not supported on Windows".format(
fork_method))
if sys.version_info >= (
3, 8) and pytestskipmarkers.utils.platform.is_darwin():
pytest.skip(
"Start method '{}' is not supported on Darwin on Py3.8+".
format(fork_method))
num_processes = 2
log_forwarding_calls = 10
shell = Process(script_name=sys.executable, timeout=30)
script = tempfiles.makepyfile("""
# coding=utf-8
import os
import sys
import time
import logging
import multiprocessing
from saltfactories.utils.saltext.log_handlers.pytest_log_handler import ZMQHandler
# Salt was imported by now and set up it's own logging handlers. Remove them.
logging.root.handlers = []
# Add our ZMQ handler
handler = ZMQHandler(port={port})
handler.setLevel(logging.DEBUG)
logging.root.addHandler(handler)
logging.root.setLevel(logging.DEBUG)
def log_from_child_process(idx, parent_pid, evt):
evt.set() # process started, ready to start another one
import os
import logging
log = logging.getLogger("foo")
for idx in range(1, {calls} + 1):
log.debug("Foo(Child of pid %s):%s:%s", parent_pid, idx, os.getpid())
exit(0)
def log_from_process(pidx, evt):
import os
import logging
num_processes = {num_processes}
procs = []
cevt = multiprocessing.Event()
for idx in range(num_processes):
proc = multiprocessing.Process(
target=log_from_child_process,
args=(idx, os.getpid(), cevt),
name="P{{}}C{{}}".format(pidx, idx)
)
proc.start()
procs.append(proc)
cevt.wait()
cevt.clear()
time.sleep(0.25)
evt.set() # process started, ready to start another one
log = logging.getLogger("foo")
for idx in range(1, {calls} + 1):
log.debug("Foo:%s:%s", idx, os.getpid())
for proc in procs:
proc.join()
exit(0)
def main():
procs = []
num_processes = {num_processes}
print("Logging started", flush=True)
evt = multiprocessing.Event()
for idx in range(num_processes):
proc = multiprocessing.Process(
target=log_from_process,
args=(idx, evt),
name="P{{}}".format(idx)
)
proc.start()
procs.append(proc)
evt.wait()
evt.clear()
time.sleep(0.25)
for proc in procs:
proc.join()
print("Logging finished", flush=True)
exit(0)
if __name__ == '__main__':
multiprocessing.freeze_support()
multiprocessing.set_start_method("{fork_method}")
main()
""".format(
port=salt_factories.log_server_port,
calls=log_forwarding_calls,
num_processes=num_processes,
fork_method=fork_method,
))
with caplog.at_level(logging.DEBUG, logger="foo"):
try:
result = shell.run(script)
except FactoryTimeout as exc: # pragma: no cover
pytest.fail(
"The ZMQHandler blocked. Process result:\n{}".format(exc))
# If the exitcode is not 0, that means the script was forcefully terminated, which,
# in turn means the ZMQHandler blocked the process when not connected to the log
# listener.
assert "Logging started" in result.stdout
assert "Logging finished" in result.stdout
assert result.exitcode == 0
# It can take quite a while to receive all these messages,
# Specially for Windows and macOS under CI
timeout = datetime.utcnow() + timedelta(seconds=30)
# We start N processes and each process starts N processes
expected_process_count = (num_processes *
num_processes) + num_processes
while True:
procs = {}
# We try multiple times because the script might have properly
# flushed it's messages to the log server, but the log server
# might still be processing them
for record in caplog.records:
if record.msg.startswith("Foo"):
_, msgnum, pid = record.message.split(":")
assert record.process == int(pid)
procs.setdefault(record.processName,
[]).append(int(msgnum))
try:
assert procs
assert len(procs) == expected_process_count
break
except AssertionError: # pragma: no cover
if datetime.utcnow() > timeout:
if len(procs) >= num_processes + 1:
# Sometimes under CI, some processes either fail to start or don't log.
# If we have at least the expected top level processes plus 1 child process,
# we've asserted that logs are forwarded from forked processes.
# Good enough for the test
break
raise