Fix logging and add some basic verbosity

- Fix CLI logging
- Add debug logging for reports
- The SQLAlchemy Echo parameter is now properly documented
- The Debug view is now controller by the loglevel

Change-Id: I7a0f43c3e2a280538fc372f31e3252edee76c882
This commit is contained in:
David Moreau Simard 2018-04-10 12:08:00 -04:00
parent 3c91da4087
commit 21b18a8707
No known key found for this signature in database
GPG Key ID: 33A07694CBB71ECC
8 changed files with 70 additions and 39 deletions

View File

@ -41,6 +41,12 @@ class BaseConfig(object):
)
self.SQLALCHEMY_DATABASE_URI = self.ARA_DATABASE
self.SQLALCHEMY_TRACK_MODIFICATIONS = False
self.SQLALCHEMY_ECHO = ara_config(
'sqlalchemy_echo',
'SQLALCHEMY_ECHO',
False,
value_type='boolean'
)
self.SQLALCHEMY_POOL_SIZE = ara_config(
'sqlalchemy_pool_size',
'SQLALCHEMY_POOL_SIZE',

View File

@ -30,18 +30,16 @@ version: 1
formatters:
normal:
format: '%(asctime)s %(levelname)s %(name)s: %(message)s'
console:
format: '%(asctime)s %(levelname)s %(name)s: %(message)s'
handlers:
console:
class: logging.StreamHandler
formatter: console
formatter: normal
level: INFO
stream: ext://sys.stdout
normal:
file:
class: logging.handlers.TimedRotatingFileHandler
formatter: normal
level: DEBUG
level: {level}
filename: '{dir}/{file}'
when: 'midnight'
interval: 1
@ -49,31 +47,29 @@ handlers:
loggers:
ara:
handlers:
- console
- normal
- file
level: {level}
propagate: 0
alembic:
handlers:
- console
- normal
- file
level: WARN
propagate: 0
sqlalchemy.engine:
handlers:
- console
- normal
- file
level: WARN
propagate: 0
werkzeug:
handlers:
- console
- normal
- file
level: INFO
propagate: 0
root:
handlers:
- normal
- file
level: {level}
"""
@ -90,10 +86,8 @@ class LogConfig(object):
self.ARA_LOG_FILE = ara_config('logfile', 'ARA_LOG_FILE', 'ara.log')
self.ARA_LOG_LEVEL = ara_config('loglevel', 'ARA_LOG_LEVEL', 'INFO')
if self.ARA_LOG_LEVEL == 'DEBUG':
self.SQLALCHEMY_ECHO = True
self.ARA_ENABLE_DEBUG_VIEW = True
else:
self.SQLALCHEMY_ECHO = False
self.ARA_ENABLE_DEBUG_VIEW = False
@property
@ -131,7 +125,7 @@ def setup_logging(config=None):
else:
logging.config.fileConfig(config['ARA_LOG_CONFIG'])
logger = logging.getLogger('ara.logging')
logger = logging.getLogger('ara.config.logging')
msg = 'Logging: Level {level} from {config}, logging to {dir}/{file}'
msg = msg.format(
level=config['ARA_LOG_LEVEL'],

View File

@ -37,7 +37,7 @@ try:
except ImportError:
cli = None
LOG = logging.getLogger('ara.callback')
log = logging.getLogger('ara.callback')
app = create_app()
@ -62,6 +62,7 @@ class CallbackModule(CallbackBase):
def __init__(self):
super(CallbackModule, self).__init__()
log.debug('Initializing callback')
if not current_app:
ctx = app.app_context()
ctx.push()
@ -80,6 +81,7 @@ class CallbackModule(CallbackBase):
self._options = cli.options
else:
self._options = None
log.debug('Callback initialized')
def get_or_create_host(self, hostname):
try:
@ -120,7 +122,7 @@ class CallbackModule(CallbackBase):
file_.content = content
except IOError:
LOG.warn('failed to open %s for reading', path)
log.warn('failed to open %s for reading', path)
return file_
@ -130,7 +132,7 @@ class CallbackModule(CallbackBase):
host completes. It is responsible for logging a single
'TaskResult' record to the database.
"""
LOG.debug('logging task result for task %s (%s), host %s',
log.debug('Logging task result for task %s (%s), host %s',
self.task.name, self.task.id, result._host.get_name())
# An include_role task might end up putting an IncludeRole object
@ -194,7 +196,7 @@ class CallbackModule(CallbackBase):
"""
Logs playbook statistics to the database.
"""
LOG.debug('logging stats')
log.debug('logging stats')
hosts = sorted(stats.processed.keys())
for hostname in hosts:
host = self.get_or_create_host(hostname)
@ -215,7 +217,7 @@ class CallbackModule(CallbackBase):
Marks the completion time of the currently active task.
"""
if self.task is not None:
LOG.debug('closing task %s (%s)',
log.debug('Closing task %s (%s)',
self.task.name,
self.task.id)
self.task.stop()
@ -230,7 +232,7 @@ class CallbackModule(CallbackBase):
Marks the completion time of the currently active play.
"""
if self.play is not None:
LOG.debug('closing play %s (%s)', self.play.name, self.play.id)
log.debug('Closing play %s (%s)', self.play.name, self.play.id)
self.play.stop()
db.session.add(self.play)
db.session.commit()
@ -242,7 +244,7 @@ class CallbackModule(CallbackBase):
Marks the completion time of the currently active playbook.
"""
if self.playbook is not None:
LOG.debug('closing playbook %s', self.playbook.path)
log.debug('Closing playbook %s', self.playbook.path)
self.playbook.stop()
self.playbook.complete = True
db.session.add(self.playbook)
@ -276,7 +278,7 @@ class CallbackModule(CallbackBase):
is_handler=False):
self.close_task()
LOG.debug('starting task %s (action %s)',
log.debug('Starting task %s (action %s)',
task.name, task.action)
pathspec = task.get_path()
if pathspec:
@ -319,7 +321,7 @@ class CallbackModule(CallbackBase):
msg = "Parameter not saved by ARA due to configuration"
options[parameter] = msg
LOG.debug('starting playbook %s', path)
log.debug('Starting playbook %s', path)
self.playbook = models.Playbook(
ansible_version=ansible_version,
path=path,
@ -340,7 +342,7 @@ class CallbackModule(CallbackBase):
self.close_task()
self.close_play()
LOG.debug('starting play %s', play.name)
log.debug('Starting play %s', play.name)
if self.play is not None:
self.play.stop()
@ -361,5 +363,5 @@ class CallbackModule(CallbackBase):
self.close_play()
self.close_playbook()
LOG.debug('closing database')
log.debug('Closing database')
db.session.close()

View File

@ -15,6 +15,7 @@
# You should have received a copy of the GNU General Public License
# along with ARA. If not, see <http://www.gnu.org/licenses/>.
import logging
import sys
from ara import __version__
@ -24,6 +25,9 @@ from cliff.commandmanager import CommandManager
from flask import current_app
log = logging.getLogger('ara.shell')
class AraCli(App):
"""
A CLI client to query ARA databases
@ -44,10 +48,10 @@ class AraCli(App):
return parser
def initialize_app(self, argv):
self.LOG.debug('initialize_app')
log.debug('initialize_app')
def prepare_to_run_command(self, cmd):
self.LOG.debug('prepare_to_run_command %s', cmd.__class__.__name__)
log.debug('prepare_to_run_command: %s', cmd.__class__.__name__)
# Note: cliff uses self.app for itself, this gets folded back into
# self.app.ara
@ -57,9 +61,9 @@ class AraCli(App):
self.ara_context.push()
def clean_up(self, cmd, result, err):
self.LOG.debug('clean_up %s', cmd.__class__.__name__)
log.debug('clean_up %s', cmd.__class__.__name__)
if err:
self.LOG.debug('got an error: %s', err)
log.debug('got an error: %s', err)
self.ara_context.pop()

View File

@ -51,6 +51,7 @@ class TestConfig(TestAra):
],
'FREEZER_RELATIVE_URLS': True,
'SQLALCHEMY_TRACK_MODIFICATIONS': False,
'SQLALCHEMY_ECHO': False,
'SQLALCHEMY_POOL_SIZE': None,
'SQLALCHEMY_POOL_TIMEOUT': None,
'SQLALCHEMY_POOL_RECYCLE': None,

View File

@ -15,6 +15,8 @@
# You should have received a copy of the GNU General Public License
# along with ARA. If not, see <http://www.gnu.org/licenses/>.
import logging
from ara import models
from ara import utils
from flask import abort
@ -28,6 +30,7 @@ from flask import url_for
YIELD_PER = 100
reports = Blueprint('reports', __name__)
log = logging.getLogger(__name__)
# This is a flask-frozen workaround in order to generate an index.html
@ -109,10 +112,12 @@ def ajax_parameters(playbook):
results['data'].append(['playbook_path', playbook.path])
results['data'].append(['ansible_version', playbook.ansible_version])
log.debug('Loading playbook parameters')
if playbook.options:
for option in playbook.options:
results['data'].append([option, playbook.options[option]])
log.debug('%s playbook parameters loaded' % len(results['data']))
return jsonify(results)
@ -130,6 +135,7 @@ def ajax_plays(playbook):
results = dict()
results['data'] = list()
log.debug('Loading plays')
for play in plays.yield_per(YIELD_PER):
name = u"<span class='pull-left'>{0}</span>".format(play.name)
start = date.render(date=play.time_start)
@ -137,6 +143,7 @@ def ajax_plays(playbook):
duration = time.render(time=play.duration)
results['data'].append([name, start, end, duration])
log.debug('%s plays loaded' % len(results['data']))
return jsonify(results)
@ -154,12 +161,14 @@ def ajax_records(playbook):
results = dict()
results['data'] = list()
log.debug('Loading records')
for record in records.yield_per(YIELD_PER):
key = record_key.render(record=record)
value = record_value.render(record=record)
results['data'].append([key, value])
log.debug('%s records loaded' % len(results['data']))
return jsonify(results)
@ -180,6 +189,8 @@ def ajax_results(playbook):
results = dict()
results['data'] = list()
log.debug('Loading results')
log.debug('* If this part eats your RAM, please help us fix this :)')
for result in task_results.yield_per(YIELD_PER):
name = name_cell.render(tags=result.task.tags, name=result.task.name)
host = result.host.name
@ -192,6 +203,8 @@ def ajax_results(playbook):
derived_status=result.derived_status)
results['data'].append([name, host, action, elapsed, duration, status])
log.debug('%s results loaded' % len(results['data']))
return jsonify(results)
@ -208,6 +221,7 @@ def ajax_stats(playbook):
results = dict()
results['data'] = list()
log.debug('Loading host statistics and facts')
for stat in stats.yield_per(YIELD_PER):
host = host_link.render(host=stat.host)
ok = stat.ok if stat.ok >= 1 else 0
@ -219,4 +233,5 @@ def ajax_stats(playbook):
data = [host, ok, changed, failed, skipped, unreachable]
results['data'].append(data)
log.debug('%s host stats and facts loaded' % len(results['data']))
return jsonify(results)

View File

@ -187,6 +187,9 @@ def configure_template_filters(app):
def configure_context_processors(app):
log = logging.getLogger('ara.webapp.context_processors')
log.debug('Loading context_processors...')
@app.context_processor
def ctx_add_nav_data():
"""
@ -210,6 +213,9 @@ def configure_context_processors(app):
def configure_blueprints(app):
log = logging.getLogger('ara.webapp.configure_blueprints')
log.debug('Loading blueprints...')
import ara.views # flake8: noqa
views = (
(ara.views.about, '/about'),
@ -222,7 +228,7 @@ def configure_blueprints(app):
for view, prefix in views:
app.register_blueprint(view, url_prefix=prefix)
if app.config.get('ARA_ENABLE_DEBUG_VIEW'):
if app.config.get('ARA_LOG_LEVEL') == 'DEBUG':
app.register_blueprint(ara.views.debug, url_prefix='/debug')
@ -235,7 +241,8 @@ def configure_db(app):
revision which contains the latest state of the database prior to this.
"""
models.db.init_app(app)
log = logging.getLogger(app.logger_name)
log = logging.getLogger('ara.webapp.configure_db')
log.debug('Setting up database...')
if app.config.get('ARA_AUTOCREATE_DATABASE'):
with app.app_context():
@ -282,6 +289,9 @@ def configure_static_route(app):
# dots and we can decorate "serve_static_packaged" instead of, say,
# "static.serve_packaged".
log = logging.getLogger('ara.webapp.configure_static_route')
log.debug('Loading static routes...')
@app.route('/static/packaged/<module>/<path:filename>')
def serve_static_packaged(module, filename):
xstatic = app.config['XSTATIC']
@ -294,5 +304,8 @@ def configure_static_route(app):
def configure_cache(app):
""" Sets up an attribute to cache data in the app context """
log = logging.getLogger('ara.webapp.configure_cache')
log.debug('Configuring cache')
if not getattr(app, '_cache', None):
app._cache = {}

View File

@ -125,8 +125,6 @@ Parameters and their defaults
+-------------------------------+----------------------------+-------------------------------------------+
| ARA_LOG_FORMAT_ | logformat | %(asctime)s - %(levelname)s - %(message)s |
+-------------------------------+----------------------------+-------------------------------------------+
| ARA_SQL_DEBUG_ | sqldebug | False  |
+-------------------------------+----------------------------+-------------------------------------------+
| ARA_IGNORE_PARAMETERS_ | ignore_parameters | extra_vars  |
+-------------------------------+----------------------------+-------------------------------------------+
| ARA_IGNORE_EMPTY_GENERATION_ | ignore_empty_generation | True  |
@ -139,6 +137,8 @@ Parameters and their defaults
+-------------------------------+----------------------------+-------------------------------------------+
| ARA_RESULT_PER_PAGE_ | result_per_page | 25  |
+-------------------------------+----------------------------+-------------------------------------------+
| SQLALCHEMY_ECHO_ | sqlalchemy_echo | False |
+-------------------------------+----------------------------+-------------------------------------------+
| SQLALCHEMY_POOL_SIZE_ | sqlalchemy_pool_size | None (default managed by flask-sqlalchemy)|
+-------------------------------+----------------------------+-------------------------------------------+
| SQLALCHEMY_POOL_TIMEOUT_ | sqlalchemy_pool_timeout | None (default managed by flask-sqlalchemy)|
@ -146,6 +146,7 @@ Parameters and their defaults
| SQLALCHEMY_POOL_RECYCLE_ | sqlalchemy_pool_recycle | None (default managed by flask-sqlalchemy)|
+-------------------------------+----------------------------+-------------------------------------------+
.. _SQLALCHEMY_ECHO: http://flask-sqlalchemy.pocoo.org/2.3/config/#configuration-keys
.. _SQLALCHEMY_POOL_SIZE: http://flask-sqlalchemy.pocoo.org/2.3/config/#configuration-keys
.. _SQLALCHEMY_POOL_TIMEOUT: http://flask-sqlalchemy.pocoo.org/2.3/config/#configuration-keys
.. _SQLALCHEMY_POOL_RECYCLE: http://flask-sqlalchemy.pocoo.org/2.3/config/#configuration-keys
@ -269,11 +270,6 @@ ARA_LOG_FORMAT
The log format of the logs.
ARA_SQL_DEBUG
~~~~~~~~~~~~~
Enables the SQLAlchemy echo verbose mode.
ARA_IGNORE_PARAMETERS
~~~~~~~~~~~~~~~~~~~~~