Merge pull request #1745 from anandpdoshi/cleanup/logging

[cleanup] simpler logging system that does not affect other loggers

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)

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

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

frappe/setup_logging.py

@@ -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)

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='&'):
 	"""

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,

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):
 	"""

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 = {}
+

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))