diff --git a/frappe/__init__.py b/frappe/__init__.py index 3d21aa7f6a..fd634ff1a0 100644 --- a/frappe/__init__.py +++ b/frappe/__init__.py @@ -8,7 +8,7 @@ from __future__ import unicode_literals from werkzeug.local import Local, release_local from functools import wraps -import os, importlib, inspect, logging, json +import os, importlib, inspect, json # public from frappe.__version__ import __version__ @@ -381,7 +381,6 @@ def sendmail(recipients=(), sender="", subject="No Subject", message="No Message subject=subject, msg=content or message, attachments=attachments, reply_to=reply_to, cc=cc, message_id=message_id, in_reply_to=in_reply_to) -logger = None whitelisted = [] guest_methods = [] xss_safe_methods = [] @@ -1140,20 +1139,6 @@ def attach_print(doctype, name, file_name=None, print_format=None, style=None, h return out -logging_setup_complete = False -def get_logger(module=None, loglevel="DEBUG"): - from frappe.setup_logging import setup_logging - global logging_setup_complete - - if not logging_setup_complete: - setup_logging() - logging_setup_complete = True - - logger = logging.getLogger(module or "frappe") - logger.setLevel(logging.DEBUG) - - return logger - def publish_realtime(*args, **kwargs): """Publish real-time updates @@ -1195,3 +1180,10 @@ def get_doctype_app(doctype): return local.module_app[scrub(doctype_module)] return local_cache("doctype_app", doctype, generator=_get_doctype_app) + +loggers = {} +log_level = None +def logger(module=None, with_more_info=True): + '''Returns a python logger that uses StreamHandler''' + from frappe.utils.logger import get_logger + return get_logger(module or __name__, with_more_info=with_more_info) diff --git a/frappe/app.py b/frappe/app.py index 9e9d6cca03..ae1f14a9be 100644 --- a/frappe/app.py +++ b/frappe/app.py @@ -30,8 +30,6 @@ local_manager = LocalManager([frappe.local]) _site = None _sites_path = os.environ.get("SITES_PATH", ".") -logger = frappe.get_logger() - class RequestContext(object): def __init__(self, environ): @@ -72,7 +70,7 @@ def application(request): raise NotFound except HTTPException, e: - logger.error('Request Error') + frappe.logger().error('Request Error', exc_info=True) return e except frappe.SessionStopped, e: @@ -150,7 +148,7 @@ def handle_exception(e): frappe.local.login_manager.clear_cookies() if http_status_code >= 500: - logger.error('Request Error') + frappe.logger().error('Request Error', exc_info=True) make_error_snapshot(e) return response diff --git a/frappe/core/doctype/communication/email.py b/frappe/core/doctype/communication/email.py index 46040799ff..8b69e609dd 100755 --- a/frappe/core/doctype/communication/email.py +++ b/frappe/core/doctype/communication/email.py @@ -397,5 +397,5 @@ def sendmail(communication_name, print_html=None, print_format=None, attachments "cc": cc, "lang": lang })) - frappe.get_logger(__name__).error(traceback) + frappe.logger(__name__).error(traceback) raise diff --git a/frappe/setup_logging.py b/frappe/setup_logging.py deleted file mode 100755 index bcb374095e..0000000000 --- a/frappe/setup_logging.py +++ /dev/null @@ -1,70 +0,0 @@ - -from __future__ import unicode_literals -import frappe -import logging -import logging.config -import os -import json -from pprint import pformat - -class ContextFilter(logging.Filter): - """ - This is a filter which injects request information (if available) into the log. - """ - - def filter(self, record): - record.form_dict = pformat(getattr(frappe.local, 'form_dict', None)) - record.site = getattr(frappe.local, 'site', None) - record.tb = frappe.utils.get_traceback() - return True - -def setup_logging(): - conf = frappe.get_site_config(sites_path=os.environ.get('SITES_PATH', '.')) - if conf.logging_conf: - logging_conf = conf.logging_conf - else: - logging_conf = { - "version": 1, - "disable_existing_loggers": True, - "level": logging.DEBUG, - "filters": { - "context_filter": { - "()": "frappe.setup_logging.ContextFilter" - } - }, - "formatters": { - "site_wise": { - "format": "\n%(asctime)s %(message)s \n site: %(site)s\n form: %(form_dict)s\n\n%(tb)s\n--------------" - } - }, - "loggers": { - "frappe": { - "level": "INFO", - "propagate": False, - "filters": ["context_filter"], - "handlers": ["request_exception"] - }, - "rq.worker": { - "level": "DEBUG", - } - }, - "handlers": { - "request_exception": { - "level": "ERROR", - "formatter": "site_wise", - "class": "logging.StreamHandler", - } - } - } - if conf.request_exception_log_file: - logging_conf.update({ - "handlers": { - "request_exception": { - "level": "ERROR", - "formatter": "site_wise", - "class": "logging.handlers.WatchedFileHandler", - "filename": conf.request_exception_log_file - } - } - }) - logging.config.dictConfig(logging_conf) diff --git a/frappe/utils/__init__.py b/frappe/utils/__init__.py index 860a45a3d3..6aeaecde41 100644 --- a/frappe/utils/__init__.py +++ b/frappe/utils/__init__.py @@ -152,15 +152,10 @@ def get_traceback(): exc_type, exc_value, exc_tb = sys.exc_info() trace_list = traceback.format_exception(exc_type, exc_value, exc_tb) body = "".join(cstr(t) for t in trace_list) - - if frappe.logger: - frappe.logger.error('Db:'+(frappe.db and frappe.db.cur_db_name or '') \ - + ' - ' + body) - return body def log(event, details): - frappe.logger.info(details) + frappe.logger().info(details) def dict_to_str(args, sep='&'): """ diff --git a/frappe/utils/background_jobs.py b/frappe/utils/background_jobs.py index 80c78fc49d..c26974138d 100755 --- a/frappe/utils/background_jobs.py +++ b/frappe/utils/background_jobs.py @@ -6,8 +6,6 @@ from collections import defaultdict import frappe import os, socket -logger = frappe.get_logger(__name__) - default_timeout = 300 queue_timeout = { 'long': 1500, diff --git a/frappe/utils/error.py b/frappe/utils/error.py index 4994e13317..19a113dede 100644 --- a/frappe/utils/error.py +++ b/frappe/utils/error.py @@ -21,7 +21,7 @@ def make_error_snapshot(exception): if frappe.conf.disable_error_snapshot: return - logger = frappe.get_logger() + logger = frappe.logger(__name__, with_more_info=False) try: error_id = '{timestamp:s}-{ip:s}-{hash:s}'.format( @@ -41,7 +41,7 @@ def make_error_snapshot(exception): logger.error('New Exception collected with id: {}'.format(error_id)) except Exception, e: - logger.error('Could not take error snapshot: {0}'.format(e)) + logger.error('Could not take error snapshot: {0}'.format(e), exc_info=True) def get_snapshot(exception, context=10): """ diff --git a/frappe/utils/logger.py b/frappe/utils/logger.py new file mode 100755 index 0000000000..5b49adc760 --- /dev/null +++ b/frappe/utils/logger.py @@ -0,0 +1,53 @@ +from __future__ import unicode_literals +import frappe +import logging + +default_log_level = logging.DEBUG + +def get_logger(module, with_more_info=True): + if module in frappe.loggers: + return frappe.loggers[module] + + formatter = logging.Formatter('%(asctime)s - %(pathname)s [%(levelname)s]:\n%(message)s') + handler = logging.StreamHandler() + handler.setFormatter(formatter) + if with_more_info: + handler.addFilter(SiteContextFilter()) + + logger = logging.getLogger(module) + logger.setLevel(frappe.log_level or default_log_level) + logger.addHandler(handler) + logger.propagate = False + + frappe.loggers[module] = logger + + return logger + +class SiteContextFilter(logging.Filter): + """This is a filter which injects request information (if available) into the log.""" + def filter(self, record): + record.msg = get_more_info_for_log() + record.msg + return True + +def get_more_info_for_log(): + '''Adds Site, Form Dict into log entry''' + more_info = [] + site = getattr(frappe.local, 'site', None) + if site: + more_info.append('Site: {0}'.format(site)) + + form_dict = getattr(frappe.local, 'form_dict', None) + if form_dict: + more_info.append('Form Dict: {0}'.format(frappe.as_json(form_dict))) + + if more_info: + # to append a \n + more_info = more_info + [''] + + return '\n'.join(more_info) + +def set_log_level(level): + '''Use this method to set log level to something other than the default DEBUG''' + frappe.log_level = getattr(logging, (level or '').upper(), None) or default_log_level + frappe.loggers = {} + diff --git a/frappe/utils/scheduler.py b/frappe/utils/scheduler.py index f9e7170fef..9a40aec4e4 100755 --- a/frappe/utils/scheduler.py +++ b/frappe/utils/scheduler.py @@ -59,10 +59,10 @@ def enqueue_events_for_site(site, queued_jobs): # TODO this print call is a tempfix till logging is fixed! print 'Queued events for site {0}'.format(site) - frappe.get_logger(__name__).debug('Queued events for site {0}'.format(site)) + frappe.logger(__name__).debug('Queued events for site {0}'.format(site)) except: - frappe.get_logger(__name__).error('Exception in Enqueue Events for Site {0}'.format(site)) + frappe.logger(__name__).error('Exception in Enqueue Events for Site {0}'.format(site)) raise finally: @@ -218,7 +218,7 @@ def get_error_report(from_date=None, to_date=None, limit=10): def scheduler_task(site, event, handler, now=False): '''This is a wrapper function that runs a hooks.scheduler_events method''' - frappe.get_logger(__name__).info('running {handler} for {site} for event: {event}'.format(handler=handler, site=site, event=event)) + frappe.logger(__name__).info('running {handler} for {site} for event: {event}'.format(handler=handler, site=site, event=event)) try: if not now: frappe.connect(site=site) @@ -229,10 +229,10 @@ def scheduler_task(site, event, handler, now=False): except Exception: frappe.db.rollback() traceback = log(handler, "Method: {event}, Handler: {handler}".format(event=event, handler=handler)) - frappe.get_logger(__name__).error(traceback) + frappe.logger(__name__).error(traceback) raise else: frappe.db.commit() - frappe.get_logger(__name__).info('ran {handler} for {site} for event: {event}'.format(handler=handler, site=site, event=event)) + frappe.logger(__name__).info('ran {handler} for {site} for event: {event}'.format(handler=handler, site=site, event=event))