diff --git a/docs/topics/logging.rst b/docs/topics/logging.rst index 5e1a0e4bb..1d9b04727 100644 --- a/docs/topics/logging.rst +++ b/docs/topics/logging.rst @@ -53,10 +53,6 @@ scrapy.log module .. module:: scrapy.log :synopsis: Logging facility -.. attribute:: log_level - - The current log level being used - .. attribute:: started A boolean which is ``True`` is logging has been started or ``False`` otherwise. @@ -81,7 +77,7 @@ scrapy.log module setting will be used. :type logstdout: boolean -.. function:: msg(message, level=INFO, component=BOT_NAME, spider=None) +.. function:: msg(message, level=INFO, spider=None) Log a message @@ -91,24 +87,11 @@ scrapy.log module :param level: the log level for this message. See :ref:`topics-logging-levels`. - :param component: the component to use for logging, it defaults to - :setting:`BOT_NAME` - :type component: str - :param spider: the spider to use for logging this message. This parameter should always be used when logging things related to a particular spider. :type spider: :class:`~scrapy.spider.BaseSpider` object -.. function:: exc(message, level=ERROR, component=BOT_NAME, spider=None) - - Log an exception. Similar to ``msg()`` but it also appends a stack trace - report using `traceback.format_exc`. - - .. _traceback.format_exc: http://docs.python.org/library/traceback.html#traceback.format_exc - - It accepts the same parameters as the :func:`msg` function. - .. data:: CRITICAL Log level for critical errors diff --git a/scrapy/log.py b/scrapy/log.py index c8e969928..0caa82ed7 100644 --- a/scrapy/log.py +++ b/scrapy/log.py @@ -4,42 +4,64 @@ Scrapy logging facility See documentation in docs/topics/logging.rst """ import sys -from traceback import format_exc +import logging from twisted.python import log -from scrapy.xlib.pydispatch import dispatcher from scrapy.conf import settings from scrapy.utils.python import unicode_to_str # Logging levels -SILENT, CRITICAL, ERROR, WARNING, INFO, DEBUG = range(6) +DEBUG = logging.DEBUG +INFO = logging.INFO +WARNING = logging.WARNING +ERROR = logging.ERROR +CRITICAL = logging.CRITICAL +SILENT = CRITICAL + 1 + level_names = { - 0: "SILENT", - 1: "CRITICAL", - 2: "ERROR", - 3: "WARNING", - 4: "INFO", - 5: "DEBUG", + logging.DEBUG: "DEBUG", + logging.INFO: "INFO", + logging.WARNING: "WARNING", + logging.ERROR: "ERROR", + logging.CRITICAL: "CRITICAL", + SILENT: "SILENT", } -BOT_NAME = settings['BOT_NAME'] - -# signal sent when log message is received -# args: message, level, spider -logmessage_received = object() - -# default values -log_level = DEBUG -log_encoding = 'utf-8' - started = False +class ScrapyFileLogObserver(log.FileLogObserver): + + def __init__(self, f, level=INFO, encoding='utf-8'): + self.level = level + self.encoding = encoding + log.FileLogObserver.__init__(self, f) + + def emit(self, eventDict): + if eventDict.get('system') != 'scrapy': + return + level = eventDict.get('logLevel') + if level < self.level: + return + spider = eventDict.get('spider') + message = eventDict.get('message') + lvlname = level_names.get(level, 'NOLEVEL') + if message: + message = [unicode_to_str(x, self.encoding) for x in message] + message[0] = "%s: %s" % (lvlname, message[0]) + why = eventDict.get('why') + if why: + why = "%s: %s" % (lvlname, unicode_to_str(why, self.encoding)) + eventDict['message'] = message + eventDict['why'] = why + eventDict['system'] = spider.name if spider else '-' + log.FileLogObserver.emit(self, eventDict) + def _get_log_level(level_name_or_id=None): if level_name_or_id is None: - lvlname = settings['LOG_LEVEL'] or settings['LOGLEVEL'] + lvlname = settings['LOG_LEVEL'] return globals()[lvlname] - elif isinstance(level_name_or_id, int) and 0 <= level_name_or_id <= 5: + elif isinstance(level_name_or_id, int): return level_name_or_id elif isinstance(level_name_or_id, basestring): return globals()[level_name_or_id] @@ -47,53 +69,31 @@ def _get_log_level(level_name_or_id=None): raise ValueError("Unknown log level: %r" % level_name_or_id) def start(logfile=None, loglevel=None, logstdout=None): - """Initialize and start logging facility""" - global log_level, log_encoding, started - + global started if started or not settings.getbool('LOG_ENABLED'): return - log_level = _get_log_level(loglevel) - log_encoding = settings['LOG_ENCODING'] started = True - # set log observer if log.defaultObserver: # check twisted log not already started - logfile = logfile or settings['LOG_FILE'] or settings['LOGFILE'] + loglevel = _get_log_level(loglevel) + logfile = logfile or settings['LOG_FILE'] + file = open(logfile, 'a') if logfile else sys.stderr if logstdout is None: logstdout = settings.getbool('LOG_STDOUT') + sflo = ScrapyFileLogObserver(file, loglevel, settings['LOG_ENCODING']) + log.startLoggingWithObserver(sflo.emit, setStdout=logstdout) + msg("Started project: %s" % settings['BOT_NAME']) - file = open(logfile, 'a') if logfile else sys.stderr - log.startLogging(file, setStdout=logstdout) - -def msg(message, level=INFO, component=BOT_NAME, domain=None, spider=None): - """Log message according to the level""" - if level > log_level: - return - if domain is not None: +def msg(message, level=INFO, **kw): + if 'component' in kw: import warnings - warnings.warn("'domain' argument of scrapy.log.msg() is deprecated, " \ - "use 'spider' argument instead", DeprecationWarning, stacklevel=2) - dispatcher.send(signal=logmessage_received, message=message, level=level, \ - spider=spider) - system = domain or (spider.name if spider else component) - msg_txt = unicode_to_str("%s: %s" % (level_names[level], message), log_encoding) - log.msg(msg_txt, system=system) + warnings.warn("Argument `component` of scrapy.log.msg() is deprecated", \ + DeprecationWarning, stacklevel=2) + kw.setdefault('system', 'scrapy') + kw['logLevel'] = level + log.msg(message, **kw) -def exc(message, level=ERROR, component=BOT_NAME, domain=None, spider=None): - message = message + '\n' + format_exc() - msg(message, level, component, domain, spider) - -def err(_stuff=None, _why=None, **kwargs): - if ERROR > log_level: - return - domain = kwargs.pop('domain', None) - spider = kwargs.pop('spider', None) - component = kwargs.pop('component', BOT_NAME) - if domain is not None: - import warnings - warnings.warn("'domain' argument of scrapy.log.err() is deprecated, " \ - "use 'spider' argument instead", DeprecationWarning, stacklevel=2) - kwargs['system'] = domain or (spider.name if spider else component) - if _why: - _why = unicode_to_str("ERROR: %s" % _why, log_encoding) - log.err(_stuff, _why, **kwargs) +def err(_stuff=None, _why=None, **kw): + kw.setdefault('system', 'scrapy') + kw['logLevel'] = kw.pop('level', ERROR) + log.err(_stuff, _why, **kw) diff --git a/scrapy/tests/test_log.py b/scrapy/tests/test_log.py index ec9c1a2db..da3baa1a8 100644 --- a/scrapy/tests/test_log.py +++ b/scrapy/tests/test_log.py @@ -1,17 +1,129 @@ -import unittest +from cStringIO import StringIO + +from twisted.python import log as txlog, failure +from twisted.trial import unittest from scrapy import log +from scrapy.spider import BaseSpider from scrapy.conf import settings -class ItemTest(unittest.TestCase): +class LogTest(unittest.TestCase): def test_get_log_level(self): default_log_level = getattr(log, settings['LOG_LEVEL']) self.assertEqual(log._get_log_level(), default_log_level) self.assertEqual(log._get_log_level('WARNING'), log.WARNING) self.assertEqual(log._get_log_level(log.WARNING), log.WARNING) - self.assertRaises(ValueError, log._get_log_level, 99999) self.assertRaises(ValueError, log._get_log_level, object()) +class ScrapyFileLogObserverTest(unittest.TestCase): + + level = log.INFO + encoding = 'utf-8' + + def setUp(self): + self.f = StringIO() + self.sflo = log.ScrapyFileLogObserver(self.f, self.level, self.encoding) + self.sflo.start() + + def tearDown(self): + self.flushLoggedErrors() + self.sflo.stop() + + def logged(self): + return self.f.getvalue().strip()[25:] + + def first_log_line(self): + logged = self.logged() + return logged.splitlines()[0] if logged else '' + + def test_msg_basic(self): + log.msg("Hello") + self.assertEqual(self.logged(), "[-] INFO: Hello") + + def test_msg_spider(self): + spider = BaseSpider("myspider") + log.msg("Hello", spider=spider) + self.assertEqual(self.logged(), "[myspider] INFO: Hello") + + def test_msg_level1(self): + log.msg("Hello", level=log.WARNING) + self.assertEqual(self.logged(), "[-] WARNING: Hello") + + def test_msg_level2(self): + log.msg("Hello", log.WARNING) + self.assertEqual(self.logged(), "[-] WARNING: Hello") + + def test_msg_wrong_level(self): + log.msg("Hello", level=9999) + self.assertEqual(self.logged(), "[-] NOLEVEL: Hello") + + def test_msg_level_spider(self): + spider = BaseSpider("myspider") + log.msg("Hello", spider=spider, level=log.WARNING) + self.assertEqual(self.logged(), "[myspider] WARNING: Hello") + + def test_msg_encoding(self): + log.msg(u"Price: \xa3100") + self.assertEqual(self.logged(), "[-] INFO: Price: \xc2\xa3100") + + def test_msg_ignore_level(self): + log.msg("Hello", level=log.DEBUG) + log.msg("World", level=log.INFO) + self.assertEqual(self.logged(), "[-] INFO: World") + + def test_msg_ignore_system(self): + txlog.msg("Hello") + self.failIf(self.logged()) + + def test_msg_ignore_system_err(self): + txlog.msg("Hello") + self.failIf(self.logged()) + + def test_err_noargs(self): + try: + a = 1/0 + except: + log.err() + self.failUnless('Traceback' in self.logged()) + self.failUnless('ZeroDivisionError' in self.logged()) + + def test_err_why(self): + log.err(TypeError("bad type"), "Wrong type") + self.assertEqual(self.first_log_line(), "[-] ERROR: Wrong type") + self.failUnless('TypeError' in self.logged()) + self.failUnless('bad type' in self.logged()) + + def test_err_why_encoding(self): + log.err(TypeError("bad type"), u"\xa3") + self.assertEqual(self.first_log_line(), "[-] ERROR: \xc2\xa3") + + def test_err_exc(self): + log.err(TypeError("bad type")) + self.failUnless('Unhandled Error' in self.logged()) + self.failUnless('TypeError' in self.logged()) + self.failUnless('bad type' in self.logged()) + + def test_err_failure(self): + log.err(failure.Failure(TypeError("bad type"))) + self.failUnless('Unhandled Error' in self.logged()) + self.failUnless('TypeError' in self.logged()) + self.failUnless('bad type' in self.logged()) + + +class Latin1ScrapyFileLogObserverTest(ScrapyFileLogObserverTest): + + encoding = 'latin-1' + + def test_msg_encoding(self): + log.msg(u"Price: \xa3100") + logged = self.f.getvalue().strip()[25:] + self.assertEqual(self.logged(), "[-] INFO: Price: \xa3100") + + def test_err_why_encoding(self): + log.err(TypeError("bad type"), u"\xa3") + self.assertEqual(self.first_log_line(), "[-] ERROR: \xa3") + + if __name__ == "__main__": unittest.main() diff --git a/scrapy/tests/test_utils_signal.py b/scrapy/tests/test_utils_signal.py index 139d8a632..1a1534932 100644 --- a/scrapy/tests/test_utils_signal.py +++ b/scrapy/tests/test_utils_signal.py @@ -1,5 +1,7 @@ import unittest +from twisted.python import log as txlog + from scrapy.xlib.pydispatch import dispatcher from scrapy.utils.signal import send_catch_log from scrapy import log @@ -20,12 +22,12 @@ class SignalUtilsTest(unittest.TestCase): assert arg == 'test' return "OK" - def log_received(message, level): + def log_received(event): handlers_called.add(log_received) - assert "test_handler_error" in message - assert level == log.ERROR + assert "test_handler_error" in event['message'][0] + assert event['logLevel'] == log.ERROR - dispatcher.connect(log_received, signal=log.logmessage_received) + txlog.addObserver(log_received) dispatcher.connect(test_handler_error, signal=test_signal) dispatcher.connect(test_handler_check, signal=test_signal) result = send_catch_log(test_signal, arg='test') @@ -37,7 +39,7 @@ class SignalUtilsTest(unittest.TestCase): self.assert_(isinstance(result[0][1], Exception)) self.assertEqual(result[1], (test_handler_check, "OK")) - dispatcher.disconnect(log_received, signal=log.logmessage_received) + txlog.removeObserver(log_received) dispatcher.disconnect(test_handler_error, signal=test_signal) dispatcher.disconnect(test_handler_check, signal=test_signal)