Skip to content
This repository has been archived by the owner on Apr 7, 2022. It is now read-only.

Commit

Permalink
We now have a logger!
Browse files Browse the repository at this point in the history
- `from utils.log import logger`, logger.debug/info/etc('log message')
- logs to logs/cfme.log
  • Loading branch information
seandst committed Jan 21, 2014
1 parent 0f28ff7 commit ecfe0e7
Show file tree
Hide file tree
Showing 8 changed files with 185 additions and 27 deletions.
4 changes: 3 additions & 1 deletion .gitignore
Expand Up @@ -18,8 +18,9 @@ develop-eggs
lib
lib64

# Installer logs
# logs
pip-log.txt
log/*.log

# Unit test / coverage reports
.coverage
Expand All @@ -41,3 +42,4 @@ pytest.ini

# Ipython notebooks need to be explicitly added
notebooks/*.ipynb
notebooks/.ipynb_checkpoints
4 changes: 4 additions & 0 deletions docs/modules/utils.rst
Expand Up @@ -3,6 +3,10 @@ utils

.. automodule:: utils
:members:
.. automodule:: utils.log
:members:
.. automodule:: utils.path
:members:
.. automodule:: utils.providers
:members:
.. automodule:: utils.wait
Expand Down
4 changes: 2 additions & 2 deletions fixtures/datafile.py
@@ -1,7 +1,7 @@
import os
import pytest
from utils.datafile import data_path_for_filename, load_data_file
from utils.path import data_path
from utils.path import data_path, log_path

# Collection for storing unique combinations of data file paths
# and filenames for usage reporting after a completed test run
Expand Down Expand Up @@ -60,7 +60,7 @@ def pytest_addoption(parser):


def pytest_sessionfinish(session, exitstatus):
udf_log_file = session.fspath.join('unused_data_files.log')
udf_log_file = log_path.join('unused_data_files.log')

if udf_log_file.check():
# Clean up old udf log if it exists
Expand Down
37 changes: 18 additions & 19 deletions fixtures/events.py
@@ -1,4 +1,3 @@
import logging
import requests
import socket
import subprocess
Expand All @@ -7,9 +6,10 @@

import pytest
from jinja2 import Template
from py.path import local

from utils.conf import cfme_data
from utils.log import create_logger
from utils.path import data_path, scripts_path


def get_current_time_GMT():
Expand All @@ -23,9 +23,7 @@ def __init__(self, events):
self.events = events

def generate(self, filename):
tpl_filename = local(__file__)\
.new(basename='../data/templates/event_testing.html')\
.strpath
tpl_filename = data_path.join('templates', 'event_testing.html').strpath

with open(tpl_filename, "r") as tpl, \
open(filename, "w") as f:
Expand Down Expand Up @@ -88,13 +86,13 @@ class EventListener(object):

TIME_FORMAT = "%Y-%m-%d-%H-%M-%S"

def __init__(self, listener_port, settle_time, log_file="test_events.log"):
def __init__(self, listener_port, settle_time):
self.listener_port = int(listener_port)
listener_filename = local(__file__).new(basename='../scripts/listener.py').strpath
listener_filename = scripts_path.join('listener.py').strpath
self.listener_script = "%s %d" % (listener_filename, self.listener_port)
self.settle_time = int(settle_time)
self.expectations = []
logging.basicConfig(filename=log_file, level=logging.INFO)
self.logger = create_logger('events')
self.listener = None

def get_listener_host(self):
Expand Down Expand Up @@ -125,11 +123,11 @@ def _get(self, route):
"""
assert not self.finished, "Listener dead!"
listener_url = "%s:%d" % (self.get_listener_host(), self.listener_port)
logging.info("checking api: %s%s" % (listener_url, route))
self.logger.info("checking api: %s%s" % (listener_url, route))
r = requests.get(listener_url + route)
r.raise_for_status()
response = r.json()
logging.debug("Response: %s" % response)
self.logger.debug("Response: %s" % response)
return response

def mgmt_sys_type(self, sys_type, obj_type):
Expand Down Expand Up @@ -169,16 +167,16 @@ def check_db(self, sys_type, obj_type, obj, event, after=None, before=None):
assert len(data) > 0
except AssertionError as e:
if attempt < max_attempts:
logging.debug("Waiting for DB (%s/%s): %s" % (attempt, max_attempts, e))
self.logger.debug("Waiting for DB (%s/%s): %s" % (attempt, max_attempts, e))
time.sleep(sleep_interval)
pass
# Enough sleeping, something went wrong
else:
logging.exception("Check DB failed. Max attempts: '%s'." % (max_attempts))
self.logger.exception("Check DB failed. Max attempts: '%s'." % (max_attempts))
return False
else:
# No exceptions raised
logging.info("DB row found for '%s'" % req)
self.logger.info("DB row found for '%s'" % req)
return datetime.strptime(data[0]["event_time"], "%Y-%m-%d %H:%M:%S")
return False

Expand Down Expand Up @@ -232,7 +230,7 @@ def __call__(self, sys_type, obj_type, obj, events):
events = [events]
for event in events:
print "Registering event", event
logging.info("Event registration: \n%s" % str(locals())) # Debug
self.logger.info("Event registration: %s" % str(locals())) # Debug
self.add_expectation(sys_type, obj_type, obj, event)

@pytest.fixture(scope="session")
Expand Down Expand Up @@ -283,22 +281,23 @@ def finished(self):

def start(self):
assert not self.listener, "Listener can't be running in order to start it!"
logging.info("Starting listener...\n%s" % self.listener_script)
self.logger.info("Starting listener %s" % self.listener_script)
self.listener = subprocess.Popen(self.listener_script,
stderr=subprocess.PIPE,
shell=True)
logging.info("(%s)\n" % self.listener.pid)
self.logger.info("Listener pid %d" % self.listener.pid)
time.sleep(3)
assert not self.finished, "Listener has died. Something must be blocking selected port"
logging.info("Listener alive")
self.logger.info("Listener alive")

def stop(self):
assert self.listener, "Listener must be running in order to stop it!"
logging.info("\nKilling listener (%s)..." % (self.listener.pid))
self.logger.info("Killing listener %d" % (self.listener.pid))
self.listener.kill()
(stdout, stderr) = self.listener.communicate()
self.listener = None
logging.info("%s\n%s" % (stdout, stderr))
self.logger.info("listener stdout: %s" % stdout)
self.logger.info("listener stderr: %s" % stderr)

def pytest_unconfigure(self, config):
""" Collect and clean up the testing.
Expand Down
2 changes: 2 additions & 0 deletions fixtures/navigation.py
Expand Up @@ -7,6 +7,7 @@

from pages.login import LoginPage
from utils.browser import browser, ensure_browser_open, testsetup
from utils.log import logger

_width_errmsg = '''The minimum supported width of CFME is 1280 pixels
Expand Down Expand Up @@ -61,6 +62,7 @@ def navigator(first_level, second_level):
# Adds a _navigate method to a Page, as well as makes fixtures
# themselves callable using the same method.
# This is evil, but transitional.
logger.debug('Navigating to %s/%s' % (first_level, second_level))
navigator = partial(navigate, first_level, second_level)
page = navigator()
type(page).__call__ = navigator
Expand Down
Empty file added log/.placeholder
Empty file.
133 changes: 133 additions & 0 deletions utils/log.py
@@ -0,0 +1,133 @@
"""
utils.log
---------
This module creates the cfme logger, for use throughout the project. This logger only captures log
messages explicitly sent to it, not logs emitted by other components (such as selenium). To capture
those, consider using the pytest-capturelog plugin.
Usage:
from utils.log import logger
logger.debug('debug log message')
logger.info('info log message')
logger.warning('warning log message')
logger.error('error log message')
logger.critical('critical log message')
The above will result in the following output in ``cfme_tests/logs/cfme.log``:
1970-01-01 00:00:00,000 [D] debug log message (filename.py:3)
1970-01-01 00:00:00,000 [I] info log message (filename.py:4)
1970-01-01 00:00:00,000 [W] warning log message (filename.py:5)
1970-01-01 00:00:00,000 [E] error log message (filename.py:6)
1970-01-01 00:00:00,000 [C] fatal log message (filename.py:7)
Additionally, if ``log_error_to_console`` is True (see below), the following will be
written to stderr:
[E] error (filename.py:6)
[C] fatal (filename.py:7)
Configuration
^^^^^^^^^^^^^
.. code-block:: yaml
# in env.yaml
logging:
# Can be one of DEBUG, INFO, WARNING, ERROR, CRITICAL
level: INFO
# Maximum logfile size, in bytes, before starting a new logfile
# Set to 0 to disable log rotation
max_logfile_size: 0
# Maximimum backup copies to make of rotated log files (e.g. cfme.log.1, cfme.log.2, ...)
# Set to 0 to keep no backups
max_logfile_backups: 0
# If True, messages of level ERROR and CRITICAL are also written to stderr
log_errors_to_console: False
Message Format
^^^^^^^^^^^^^^
``year-month-day hour:minute:second,millisecond [Level] message text (file:linenumber)``
``[Level]``:
One letter in square brackets, where ``[I]`` corresponds to INFO, ``[D]`` corresponds to
DEBUG, and so on.
``(file:linenumber)``:
The relative location from which this log message was emitted. Paths outside
Members
^^^^^^^
"""
import logging
from logging.handlers import RotatingFileHandler

from py.path import local

from utils.conf import env
from utils.path import project_path, log_path


# Pull in config values/set defaults
logging_conf = env.get('logging', {})
log_level = logging_conf.get('level', 'INFO')
max_logfile_size = logging_conf.get('max_file_size', 0)
max_logfile_backups = logging_conf.get('max_file_backups', 0)
log_errors_to_console = logging_conf.get('errors_to_console', False)


class RelpathFilter(logging.Filter):
"""Adds the relpath attr to records
Not actually a filter, this was the least ridiculous way to add custom dynamic
record attributes.
"""
def filter(self, record):
record_path = local(record.pathname)
record.relpath = str(record_path.relto(project_path))
return True


def create_logger(logger_name):
"""Creates and returns the named logger
Used to create the cfme logger, this can be used to create other loggers, if desired.
"""
log_path.ensure(dir=True)
log_file = str(log_path.join('%s.log' % logger_name))

relpath_filter = RelpathFilter()

# log_file is dynamic, so we can't used logging.config.dictConfig here without creating
# a custom RotatingFileHandler class. At some point, we should do that, and move the
# entire logging config into env.yaml
file_format = '%(asctime)-15s [%(levelname).1s] %(message)s (%(relpath)s:%(lineno)d)'
file_formatter = logging.Formatter(file_format)
file_handler = RotatingFileHandler(log_file, maxBytes=max_logfile_size, encoding='utf8')
file_handler.setFormatter(file_formatter)

stream_format = '[%(levelname)s] %(message)s (%(relpath)s:%(lineno)d)'
stream_formatter = logging.Formatter(stream_format)
stream_handler = logging.StreamHandler()
stream_handler.setLevel(logging.ERROR)
stream_handler.setFormatter(stream_formatter)

logger = logging.getLogger(logger_name)
logger.addHandler(file_handler)
logger.setLevel(log_level)
if log_errors_to_console:
logger.addHandler(stream_handler)
logger.addFilter(relpath_filter)
return logger

logger = create_logger('cfme')
28 changes: 23 additions & 5 deletions utils/path.py
@@ -1,7 +1,14 @@
"""Project path helpers
"""
utils.path
----------
Project path helpers
Contains py.path.Local objects for accessing common project locations.
Contains `py.path.local`_ objects for accessing common project locations.
Paths rendered below will be different in your local environment.
.. _py.path.local: http://pylib.readthedocs.org/en/latest/path.html
"""

import os
Expand All @@ -10,6 +17,17 @@

_this_file = os.path.abspath(__file__)

project = py.path.local(_this_file).new(basename='..')
conf_path = project.join('conf')
data_path = project.join('data')
#: The project root, ``cfme_tests/``
project_path = py.path.local(_this_file).new(basename='..')

#: conf yaml storage, ``cfme_tests/conf/``
conf_path = project_path.join('conf')

#: datafile storage, ``cfme_tests/data/``
data_path = project_path.join('data')

#: log storage, ``cfme_tests/log/``
log_path = project_path.join('log')

#: interactive scripts, ``cfme_tests/scripts/``
scripts_path = project_path.join('scripts')

0 comments on commit ecfe0e7

Please sign in to comment.