feat(all): logging to files for drivers and fixtures

Otherwise it's very hard to debug anything at all.

Signed-off-by: Jakub Sokołowski <jakub@status.im>
This commit is contained in:
Jakub Sokołowski 2023-11-30 14:07:26 +01:00
parent 9d754e90ab
commit 21f4f786fd
No known key found for this signature in database
GPG Key ID: FE65CD384D5BF7B4
10 changed files with 86 additions and 41 deletions

View File

@ -23,5 +23,8 @@ AUT_PATH = SystemPath(AUT_PATH)
# Save application logs
AUT_DIR = path.dirname(AUT_PATH)
AUT_LOGS_STDOUT = path.join(APP_DIR, 'aut_stdout.log')
AUT_LOGS_STDERR = path.join(APP_DIR, 'aut_stderr.log')
PYTEST_LOG = path.join(AUT_DIR, 'pytest.log')
AUT_LOGS_STDOUT = path.join(AUT_DIR, 'aut_stdout.log')
AUT_LOGS_STDERR = path.join(AUT_DIR, 'aut_stderr.log')
SERVER_LOGS_STDOUT = path.join(AUT_DIR, 'server_stdout.log')
SERVER_LOGS_STDERR = path.join(AUT_DIR, 'server_stderr.log')

View File

@ -10,7 +10,14 @@ from configs.system import IS_LIN
from fixtures.path import generate_test_info
from scripts.utils.system_path import SystemPath
_logger = logging.getLogger(__name__)
# Send logs to pytest.log as well
handler = logging.FileHandler(filename=configs.PYTEST_LOG)
logging.basicConfig(
level=logging.DEBUG,
format='[%(asctime)s] {%(filename)s:%(lineno)d} %(levelname)s - %(message)s',
handlers=[handler],
)
LOG = logging.getLogger(__name__)
pytest_plugins = [
'fixtures.aut',
@ -26,6 +33,7 @@ def setup_session_scope(
prepare_test_directory,
start_squish_server,
):
LOG.info('Session startup...')
yield
@ -36,7 +44,8 @@ def setup_function_scope(
check_result,
application_logs
):
caplog.set_level(configs.LOG_LEVEL)
# FIXME: broken due to KeyError: <_pytest.stash.StashKey object at 0x7fd1ba6d78c0>
#caplog.set_level(configs.LOG_LEVEL)
yield
@ -48,18 +57,16 @@ def pytest_runtest_makereport(item, call):
def pytest_exception_interact(node):
try:
test_path, test_name, test_params = generate_test_info(node)
node_dir: SystemPath = configs.testpath.RUN / test_path / test_name / test_params
node_dir.mkdir(parents=True, exist_ok=True)
test_path, test_name, test_params = generate_test_info(node)
node_dir: SystemPath = configs.testpath.RUN / test_path / test_name / test_params
node_dir.mkdir(parents=True, exist_ok=True)
screenshot = node_dir / 'screenshot.png'
if screenshot.exists():
screenshot = node_dir / f'screenshot_{datetime.now():%H%M%S}.png'
ImageGrab.grab(xdisplay=configs.system.DISPLAY if IS_LIN else None).save(screenshot)
allure.attach(
name='Screenshot on fail',
body=screenshot.read_bytes(),
attachment_type=allure.attachment_type.PNG)
except Exception as ex:
_logger.debug(ex)
screenshot = node_dir / 'screenshot.png'
if screenshot.exists():
screenshot = node_dir / f'screenshot_{datetime.now():%H%M%S}.png'
ImageGrab.grab(xdisplay=configs.system.DISPLAY if IS_LIN else None).save(screenshot)
allure.attach(
name='Screenshot on fail',
body=screenshot.read_bytes(),
attachment_type=allure.attachment_type.PNG
)

View File

@ -16,7 +16,7 @@ from gui.objects_map import statusDesktop_mainWindow
from scripts.utils import system_path, local_system
from scripts.utils.system_path import SystemPath
_logger = logging.getLogger(__name__)
LOG = logging.getLogger(__name__)
class AUT:
@ -63,7 +63,7 @@ class AUT:
body=screenshot.read_bytes(),
attachment_type=allure.attachment_type.PNG)
except Exception as err:
_logger.info(err)
LOG.info(err)
self.stop()
@ -88,6 +88,7 @@ class AUT:
@allure.step('Close application')
def stop(self):
LOG.info('Stoping AUT: %s', self.path)
self._detach_context()
self._kill_process()
@ -105,6 +106,7 @@ class AUT:
]
try:
self.pid = local_system.execute_with_log_files(command)
LOG.debug('Launched AUT under PID: %d', self.pid)
self.attach()
assert squish.waitFor(lambda: self.ctx.isRunning, configs.timeouts.PROCESS_TIMEOUT_SEC)
return self

View File

@ -7,17 +7,17 @@ import squish
import configs
from driver.server import SquishServer
_logger = logging.getLogger(__name__)
LOG = logging.getLogger(__name__)
@allure.step('Attaching to "{0}"')
def attach(aut_id: str, timeout_sec: int = configs.timeouts.PROCESS_TIMEOUT_SEC):
started_at = time.monotonic()
_logger.debug(f'Attaching to {aut_id}')
LOG.debug('Attaching to: %s', aut_id)
while True:
try:
context = squish.attachToApplication(aut_id, SquishServer().host, SquishServer().port)
_logger.info(f'AUT: {aut_id} attached')
LOG.info('AUT %s attached', aut_id)
return context
except RuntimeError as err:
time.sleep(1)
@ -29,4 +29,4 @@ def detach():
for ctx in squish.applicationContextList():
ctx.detach()
assert squish.waitFor(lambda: not ctx.isRunning, configs.timeouts.APP_LOAD_TIMEOUT_MSEC)
_logger.info(f'All AUTs detached')
LOG.info('All AUTs detached')

View File

@ -7,7 +7,7 @@ from scripts.utils.wait_for_port import wait_for_port
_PROCESS_NAME = '_squishserver'
_logger = logging.getLogger(__name__)
LOG = logging.getLogger(__name__)
class SquishServer:
@ -26,6 +26,7 @@ class SquishServer:
@classmethod
def start(cls):
cls.port = local_system.find_free_port(configs.squish.SERVER_PORT, 100)
LOG.info('Starting Squish Server on port: %d', cls.port)
cmd = [
str(cls.path),
'--verbose',
@ -33,13 +34,18 @@ class SquishServer:
f'--host={cls.host}',
f'--port={cls.port}',
]
cls.pid = local_system.execute(cmd)
cls.pid = local_system.execute_with_log_files(
cmd,
stderr_log=configs.SERVER_LOGS_STDOUT,
stdout_log=configs.SERVER_LOGS_STDOUT,
)
@classmethod
def stop(cls):
if cls.pid is None:
return
local_system.kill_process(cls.pid)
LOG.info('Stopping Squish Server with PID: %d', cls.pid)
local_system.kill_process_with_retries(cls.pid)
cls.pid = None
cls.port = None
@ -52,11 +58,20 @@ class SquishServer:
# https://doc-snapshots.qt.io/squish/cli-squishserver.html
@classmethod
def configuring(cls, action: str, options: typing.Union[int, str, list]):
local_system.run([
str(cls.path),
f'--configfile={cls.config}',
f'--config={action}',
] + options)
with (
open(configs.SERVER_LOGS_STDOUT, "ab") as out_file,
open(configs.SERVER_LOGS_STDERR, "ab") as err_file,
):
rval = local_system.run(
[
str(cls.path),
f'--configfile={cls.config}',
f'--config={action}',
] + options,
stdout=out_file,
stderr=err_file,
)
LOG.info('rval: %s', rval)
@classmethod
def add_attachable_aut(cls, aut_id: str, port: int):

View File

@ -1,6 +1,6 @@
import allure
import pytest
import logging
import configs
import constants
from constants import UserAccount
@ -9,6 +9,7 @@ from gui.main_window import MainWindow
from scripts.utils import system_path
from scripts.utils.system_path import SystemPath
LOG = logging.getLogger(__name__)
@pytest.fixture
@ -55,8 +56,9 @@ def multiple_instance():
@pytest.fixture
def main_window(aut: AUT, user_data, options):
aut.launch(options)
def main_window(aut: AUT, user_data):
aut.launch()
LOG.debug('Waiting for main window...')
yield MainWindow().wait_until_appears().prepare()
aut.stop()

View File

@ -16,10 +16,10 @@ def generate_test_data(request):
node_dir = configs.testpath.TEST / test_params
configs.testpath.TEST_ARTIFACTS = node_dir / 'artifacts'
configs.testpath.TEST_VP = configs.testpath.VP / test_path / test_name
_logger.info(
f'\nArtifacts directory:\t{configs.testpath.TEST_ARTIFACTS.relative_to(configs.testpath.ROOT)}'
f'\nVerification points directory:\t{configs.testpath.TEST_VP.relative_to(configs.testpath.ROOT)}'
)
_logger.debug('Artifacts directory: %s',
configs.testpath.TEST_ARTIFACTS.relative_to(configs.testpath.ROOT))
_logger.debug('Verification points directory: %s',
configs.testpath.TEST_VP.relative_to(configs.testpath.ROOT))
_logger.info(f'Start test: {test_name}')

View File

@ -9,6 +9,7 @@ LOG = logging.getLogger(__name__)
@pytest.fixture(scope='session')
def start_squish_server():
LOG.info('Starting Squish Server...')
server = SquishServer()
server.stop()
try:
@ -16,7 +17,7 @@ def start_squish_server():
server.wait()
yield server
except Exception as err:
LOG.error('Failed to start Squish Server: %s', error)
LOG.error('Failed to start Squish Server: %s', err)
pytest.exit(err)
finally:
LOG.info('Stopping Squish Server...')

View File

@ -1,8 +1,11 @@
[pytest]
log_level = DEBUG
log_format = %(asctime)s.%(msecs)03d %(levelname)7s %(name)s %(message).5000s
log_cli = true
log_cli_level = DEBUG
log_cli_format = %(asctime)s.%(msecs)03d %(levelname)7s CLI %(name)s %(message).5000s
addopts = --disable-warnings
addopts = --disable-warnings -p no:logging
markers =
smoke: Smoke tests

View File

@ -74,6 +74,18 @@ def execute(
process = subprocess.Popen(command, shell=shell, stderr=stderr, stdout=stdout)
return process.pid
def execute_with_log_files(
command: list,
stderr_log=configs.AUT_LOGS_STDERR,
stdout_log=configs.AUT_LOGS_STDOUT,
shell=False,
):
with (
open(stderr_log, "ab") as out_file,
open(stdout_log, "ab") as err_file,
):
return execute(command, shell=shell, stderr=err_file, stdout=out_file)
@allure.step('System run command')
def run(
command: list,