mirror of https://github.com/scrapy/scrapy.git
Scrapy logging refactoring (closes #188):
* added Twisted log observer for Scrapy, with unittests * use numeric values from Python logging module for log levels * removed scrapy.log.exc() function - use scrapy.log.err() instead * removed logmessage_received signal - write a (twisted) log observer instead * dropped support for obsolete `domain` argument * dropped support for old setting names: LOGLEVEL, LOGFILE (replaced by LOG_LEVEL, LOG_FILE) * deprecated `component` argument
This commit is contained in:
Pablo Hoffman
parent
c5fd113c09
commit
453e7bf38c
|
|
@ -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
|
||||
|
|
|
|||
122
scrapy/log.py
122
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)
|
||||
|
|
|
|||
|
|
@ -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()
|
||||
|
|
|
|||
|
|
@ -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)
|
||||
|
||||
|
|
|
|||
Loading…
Reference in New Issue