RomanNum3ral
/
scrapy
mirror of https://github.com/scrapy/scrapy.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Replace scrapy.log calls for their equivalents in the logging std module 

Changes:
 - Each module takes 'scrapy' logger and logs through it
 - Lazy string evaluation in all log messages
 - Added missing log messages in scrapy/core/engine.py
 - Contextual data such as crawler or spider instances, and failures
This commit is contained in:
Julia Medina 2015-02-27 23:36:30 -03:00
parent 571bf68d7d
commit 7a958f90be
34 changed files with 401 additions and 222 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

29
scrapy/commands/parse.py
View File

@ -1,5 +1,8 @@
from __future__ import print_function
import logging
from w3lib.url import is_url
from scrapy.command import ScrapyCommand
from scrapy.http import Request
from scrapy.item import BaseItem
@ -7,7 +10,9 @@ from scrapy.utils import display
from scrapy.utils.conf import arglist_to_dict
from scrapy.utils.spider import iterate_spider_output, spidercls_for_request
from scrapy.exceptions import UsageError
from scrapy import log
logger = logging.getLogger('scrapy')
class Command(ScrapyCommand):
@ -119,9 +124,9 @@ class Command(ScrapyCommand):
if rule.link_extractor.matches(response.url) and rule.callback:
return rule.callback
else:
log.msg(format='No CrawlSpider rules found in spider %(spider)r, '
'please specify a callback to use for parsing',
level=log.ERROR, spider=spider.name)
logger.error('No CrawlSpider rules found in spider %(spider)r, '
'please specify a callback to use for parsing',
{'spider': spider.name})
def set_spidercls(self, url, opts):
spider_loader = self.crawler_process.spider_loader
@ -129,13 +134,13 @@ class Command(ScrapyCommand):
try:
self.spidercls = spider_loader.load(opts.spider)
except KeyError:
log.msg(format='Unable to find spider: %(spider)s',
level=log.ERROR, spider=opts.spider)
logger.error('Unable to find spider: %(spider)s',
{'spider': opts.spider})
else:
self.spidercls = spidercls_for_request(spider_loader, Request(url))
if not self.spidercls:
log.msg(format='Unable to find spider for: %(url)s',
level=log.ERROR, url=url)
logger.error('Unable to find spider for: %(url)s',
{'url': url})
request = Request(url, opts.callback)
_start_requests = lambda s: [self.prepare_request(s, request, opts)]
@ -148,8 +153,8 @@ class Command(ScrapyCommand):
self.crawler_process.start()
if not self.first_response:
log.msg(format='No response downloaded for: %(url)s',
level=log.ERROR, url=url)
logger.error('No response downloaded for: %(url)s',
{'url': url})
def prepare_request(self, spider, request, opts):
def callback(response):
@ -170,8 +175,8 @@ class Command(ScrapyCommand):
if callable(cb_method):
cb = cb_method
else:
log.msg(format='Cannot find callback %(callback)r in spider: %(spider)s',
callback=callback, spider=spider.name, level=log.ERROR)
logger.error('Cannot find callback %(callback)r in spider: %(spider)s',
{'callback': callback, 'spider': spider.name})
return
# parse items and requests

1
scrapy/commands/shell.py
View File

@ -9,7 +9,6 @@ from threading import Thread
from scrapy.command import ScrapyCommand
from scrapy.shell import Shell
from scrapy.http import Request
from scrapy import log
from scrapy.utils.spider import spidercls_for_request, DefaultSpider

18
scrapy/contrib/debug.py
View File

@ -6,13 +6,15 @@ See documentation in docs/topics/extensions.rst
import sys
import signal
import logging
import traceback
import threading
from pdb import Pdb
from scrapy.utils.engine import format_engine_status
from scrapy.utils.trackref import format_live_refs
from scrapy import log
logger = logging.getLogger('scrapy')
class StackTraceDump(object):
@ -31,12 +33,14 @@ class StackTraceDump(object):
return cls(crawler)
def dump_stacktrace(self, signum, frame):
stackdumps = self._thread_stacks()
enginestatus = format_engine_status(self.crawler.engine)
liverefs = format_live_refs()
msg = "Dumping stack trace and engine status" \
"\n{0}\n{1}\n{2}".format(enginestatus, liverefs, stackdumps)
log.msg(msg)
log_args = {
'stackdumps': self._thread_stacks(),
'enginestatus': format_engine_status(self.crawler.engine),
'liverefs': format_live_refs(),
}
logger.info("Dumping stack trace and engine status\n"
"%(enginestatus)s\n%(liverefs)s\n%(stackdumps)s",
log_args, extra={'crawler': self.crawler})
def _thread_stacks(self):
id2name = dict((th.ident, th.name) for th in threading.enumerate())

13
scrapy/contrib/downloadermiddleware/ajaxcrawl.py
View File

@ -1,14 +1,19 @@
# -*- coding: utf-8 -*-
from __future__ import absolute_import
import re
import logging
import six
from w3lib import html
from scrapy import log
from scrapy.exceptions import NotConfigured
from scrapy.http import HtmlResponse
from scrapy.utils.response import _noscript_re, _script_re
logger = logging.getLogger('scrapy')
class AjaxCrawlMiddleware(object):
"""
Handle 'AJAX crawlable' pages marked as crawlable via meta tag.
@ -46,9 +51,9 @@ class AjaxCrawlMiddleware(object):
# scrapy already handles #! links properly
ajax_crawl_request = request.replace(url=request.url+'#!')
log.msg(format="Downloading AJAX crawlable %(ajax_crawl_request)s instead of %(request)s",
level=log.DEBUG, spider=spider,
ajax_crawl_request=ajax_crawl_request, request=request)
logger.debug("Downloading AJAX crawlable %(ajax_crawl_request)s instead of %(request)s",
{'ajax_crawl_request': ajax_crawl_request, 'request': request},
extra={'spider': spider})
ajax_crawl_request.meta['ajax_crawlable'] = True
return ajax_crawl_request

8
scrapy/contrib/downloadermiddleware/cookies.py
View File

@ -1,11 +1,13 @@
import os
import six
import logging
from collections import defaultdict
from scrapy.exceptions import NotConfigured
from scrapy.http import Response
from scrapy.http.cookies import CookieJar
from scrapy import log
logger = logging.getLogger('scrapy')
class CookiesMiddleware(object):
@ -54,7 +56,7 @@ class CookiesMiddleware(object):
if cl:
msg = "Sending cookies to: %s" % request + os.linesep
msg += os.linesep.join("Cookie: %s" % c for c in cl)
log.msg(msg, spider=spider, level=log.DEBUG)
logger.debug(msg, extra={'spider': spider})
def _debug_set_cookie(self, response, spider):
if self.debug:
@ -62,7 +64,7 @@ class CookiesMiddleware(object):
if cl:
msg = "Received cookies from: %s" % response + os.linesep
msg += os.linesep.join("Set-Cookie: %s" % c for c in cl)
log.msg(msg, spider=spider, level=log.DEBUG)
logger.debug(msg, extra={'spider': spider})
def _format_cookie(self, cookie):
# build cookie string

10
scrapy/contrib/downloadermiddleware/decompression.py
View File

@ -1,11 +1,12 @@
""" This module implements the DecompressionMiddleware which tries to recognise
and extract the potentially compressed responses that may arrive.
and extract the potentially compressed responses that may arrive.
"""
import bz2
import gzip
import zipfile
import tarfile
import logging
from tempfile import mktemp
import six
@ -15,9 +16,10 @@ try:
except ImportError:
from io import BytesIO
from scrapy import log
from scrapy.responsetypes import responsetypes
logger = logging.getLogger('scrapy')
class DecompressionMiddleware(object):
""" This middleware tries to recognise and extract the possibly compressed
@ -80,7 +82,7 @@ class DecompressionMiddleware(object):
for fmt, func in six.iteritems(self._formats):
new_response = func(response)
if new_response:
log.msg(format='Decompressed response with format: %(responsefmt)s',
level=log.DEBUG, spider=spider, responsefmt=fmt)
logger.debug('Decompressed response with format: %(responsefmt)s',
{'responsefmt': fmt}, extra={'spider': spider})
return new_response
return response

14
scrapy/contrib/downloadermiddleware/redirect.py
View File

@ -1,10 +1,12 @@
import logging
from six.moves.urllib.parse import urljoin
from scrapy import log
from scrapy.http import HtmlResponse
from scrapy.utils.response import get_meta_refresh
from scrapy.exceptions import IgnoreRequest, NotConfigured
logger = logging.getLogger('scrapy')
class BaseRedirectMiddleware(object):
@ -32,13 +34,13 @@ class BaseRedirectMiddleware(object):
[request.url]
redirected.dont_filter = request.dont_filter
redirected.priority = request.priority + self.priority_adjust
log.msg(format="Redirecting (%(reason)s) to %(redirected)s from %(request)s",
level=log.DEBUG, spider=spider, request=request,
redirected=redirected, reason=reason)
logger.debug("Redirecting (%(reason)s) to %(redirected)s from %(request)s",
{'reason': reason, 'redirected': redirected, 'request': request},
extra={'spider': spider})
return redirected
else:
log.msg(format="Discarding %(request)s: max redirections reached",
level=log.DEBUG, spider=spider, request=request)
logger.debug("Discarding %(request)s: max redirections reached",
{'request': request}, extra={'spider': spider})
raise IgnoreRequest("max redirections reached")
def _redirect_request_using_get(self, request, redirect_url):

14
scrapy/contrib/downloadermiddleware/retry.py
View File

@ -17,17 +17,19 @@ About HTTP errors to consider:
protocol. It's included by default because it's a common code used to
indicate server overload, which would be something we want to retry
"""
import logging
from twisted.internet import defer
from twisted.internet.error import TimeoutError, DNSLookupError, \
ConnectionRefusedError, ConnectionDone, ConnectError, \
ConnectionLost, TCPTimedOutError
from scrapy import log
from scrapy.exceptions import NotConfigured
from scrapy.utils.response import response_status_message
from scrapy.xlib.tx import ResponseFailed
logger = logging.getLogger('scrapy')
class RetryMiddleware(object):
@ -66,13 +68,15 @@ class RetryMiddleware(object):
retries = request.meta.get('retry_times', 0) + 1
if retries <= self.max_retry_times:
log.msg(format="Retrying %(request)s (failed %(retries)d times): %(reason)s",
level=log.DEBUG, spider=spider, request=request, retries=retries, reason=reason)
logger.debug("Retrying %(request)s (failed %(retries)d times): %(reason)s",
{'request': request, 'retries': retries, 'reason': reason},
extra={'spider': spider})
retryreq = request.copy()
retryreq.meta['retry_times'] = retries
retryreq.dont_filter = True
retryreq.priority = request.priority + self.priority_adjust
return retryreq
else:
log.msg(format="Gave up retrying %(request)s (failed %(retries)d times): %(reason)s",
level=log.DEBUG, spider=spider, request=request, retries=retries, reason=reason)
logger.debug("Gave up retrying %(request)s (failed %(retries)d times): %(reason)s",
{'request': request, 'retries': retries, 'reason': reason},
extra={'spider': spider})

14
scrapy/contrib/downloadermiddleware/robotstxt.py
View File

@ -4,13 +4,16 @@ enable this middleware and enable the ROBOTSTXT_OBEY setting.
"""
import logging
from six.moves.urllib import robotparser
from scrapy import signals, log
from scrapy.exceptions import NotConfigured, IgnoreRequest
from scrapy.http import Request
from scrapy.utils.httpobj import urlparse_cached
logger = logging.getLogger('scrapy')
class RobotsTxtMiddleware(object):
DOWNLOAD_PRIORITY = 1000
@ -32,8 +35,8 @@ class RobotsTxtMiddleware(object):
return
rp = self.robot_parser(request, spider)
if rp and not rp.can_fetch(self._useragent, request.url):
log.msg(format="Forbidden by robots.txt: %(request)s",
level=log.DEBUG, request=request)
logger.debug("Forbidden by robots.txt: %(request)s",
{'request': request}, extra={'spider': spider})
raise IgnoreRequest
def robot_parser(self, request, spider):
@ -54,8 +57,9 @@ class RobotsTxtMiddleware(object):
def _logerror(self, failure, request, spider):
if failure.type is not IgnoreRequest:
log.msg(format="Error downloading %%(request)s: %s" % failure.value,
level=log.ERROR, request=request, spider=spider)
logger.error("Error downloading %(request)s: %(f_exception)s",
{'request': request, 'f_exception': failure.value},
extra={'spider': spider, 'failure': failure})
def _parse_robots(self, response):
rp = robotparser.RobotFileParser(response.url)

29
scrapy/contrib/feedexport.py
View File

@ -4,7 +4,10 @@ Feed Exports extension
See documentation in docs/topics/feed-exports.rst
"""
import sys, os, posixpath
import os
import sys
import logging
import posixpath
from tempfile import TemporaryFile
from datetime import datetime
from six.moves.urllib.parse import urlparse
@ -14,12 +17,14 @@ from zope.interface import Interface, implementer
from twisted.internet import defer, threads
from w3lib.url import file_uri_to_path
from scrapy import log, signals
from scrapy import signals
from scrapy.utils.ftp import ftp_makedirs_cwd
from scrapy.exceptions import NotConfigured
from scrapy.utils.misc import load_object
from scrapy.utils.python import get_func_args
logger = logging.getLogger('scrapy')
class IFeedStorage(Interface):
"""Interface that all Feed Storages must implement"""
@ -171,11 +176,15 @@ class FeedExporter(object):
if not slot.itemcount and not self.store_empty:
return
slot.exporter.finish_exporting()
logfmt = "%%s %s feed (%d items) in: %s" % (self.format, \
slot.itemcount, slot.uri)
logfmt = "%%s %(format)s feed (%(itemcount)d items) in: %(uri)s"
log_args = {'format': self.format,
'itemcount': slot.itemcount,
'uri': slot.uri}
d = defer.maybeDeferred(slot.storage.store, slot.file)
d.addCallback(lambda _: log.msg(logfmt % "Stored", spider=spider))
d.addErrback(log.err, logfmt % "Error storing", spider=spider)
d.addCallback(lambda _: logger.info(logfmt % "Stored", log_args,
extra={'spider': spider}))
d.addErrback(lambda f: logger.error(logfmt % "Error storing", log_args,
extra={'spider': spider, 'failure': f}))
return d
def item_scraped(self, item, spider):
@ -198,7 +207,7 @@ class FeedExporter(object):
def _exporter_supported(self, format):
if format in self.exporters:
return True
log.msg("Unknown feed format: %s" % format, log.ERROR)
logger.error("Unknown feed format: %(format)s", {'format': format})
def _storage_supported(self, uri):
scheme = urlparse(uri).scheme
@ -207,9 +216,11 @@ class FeedExporter(object):
self._get_storage(uri)
return True
except NotConfigured:
log.msg("Disabled feed storage scheme: %s" % scheme, log.ERROR)
logger.error("Disabled feed storage scheme: %(scheme)s",
{'scheme': scheme})
else:
log.msg("Unknown feed storage scheme: %s" % scheme, log.ERROR)
logger.error("Unknown feed storage scheme: %(scheme)s",
{'scheme': scheme})
def _get_exporter(self, *args, **kwargs):
return self.exporters[self.format](*args, **kwargs)

15
scrapy/contrib/logstats.py
View File

@ -1,7 +1,11 @@
import logging
from twisted.internet import task
from scrapy.exceptions import NotConfigured
from scrapy import log, signals
from scrapy import signals
logger = logging.getLogger('scrapy')
class LogStats(object):
@ -35,9 +39,12 @@ class LogStats(object):
irate = (items - self.itemsprev) * self.multiplier
prate = (pages - self.pagesprev) * self.multiplier
self.pagesprev, self.itemsprev = pages, items
msg = "Crawled %d pages (at %d pages/min), scraped %d items (at %d items/min)" \
% (pages, prate, items, irate)
log.msg(msg, spider=spider)
msg = ("Crawled %(pages)d pages (at %(pagerate)d pages/min), "
"scraped %(items)d items (at %(itemrate)d items/min)")
log_args = {'pages': pages, 'pagerate': prate,
'items': items, 'itemrate': irate}
logger.info(msg, log_args, extra={'spider': spider})
def spider_closed(self, spider, reason):
if self.task.running:

14
scrapy/contrib/memusage.py
View File

@ -5,16 +5,20 @@ See documentation in docs/topics/extensions.rst
"""
import sys
import socket
import logging
from pprint import pformat
from importlib import import_module
from twisted.internet import task
from scrapy import signals, log
from scrapy import signals
from scrapy.exceptions import NotConfigured
from scrapy.mail import MailSender
from scrapy.utils.engine import get_engine_status
logger = logging.getLogger('scrapy')
class MemoryUsage(object):
def __init__(self, crawler):
@ -74,8 +78,8 @@ class MemoryUsage(object):
if self.get_virtual_size() > self.limit:
self.crawler.stats.set_value('memusage/limit_reached', 1)
mem = self.limit/1024/1024
log.msg(format="Memory usage exceeded %(memusage)dM. Shutting down Scrapy...",
level=log.ERROR, memusage=mem)
logger.error("Memory usage exceeded %(memusage)dM. Shutting down Scrapy...",
{'memusage': mem}, extra={'crawler': self.crawler})
if self.notify_mails:
subj = "%s terminated: memory usage exceeded %dM at %s" % \
(self.crawler.settings['BOT_NAME'], mem, socket.gethostname())
@ -95,8 +99,8 @@ class MemoryUsage(object):
if self.get_virtual_size() > self.warning:
self.crawler.stats.set_value('memusage/warning_reached', 1)
mem = self.warning/1024/1024
log.msg(format="Memory usage reached %(memusage)dM",
level=log.WARNING, memusage=mem)
logger.warning("Memory usage reached %(memusage)dM",
{'memusage': mem}, extra={'crawler': self.crawler})
if self.notify_mails:
subj = "%s warning: memory usage reached %dM at %s" % \
(self.crawler.settings['BOT_NAME'], mem, socket.gethostname())

77
scrapy/contrib/pipeline/files.py
View File

@ -9,6 +9,7 @@ import os
import os.path
import rfc822
import time
import logging
from six.moves.urllib.parse import urlparse
from collections import defaultdict
import six
@ -20,12 +21,13 @@ except ImportError:
from twisted.internet import defer, threads
from scrapy import log
from scrapy.contrib.pipeline.media import MediaPipeline
from scrapy.exceptions import NotConfigured, IgnoreRequest
from scrapy.http import Request
from scrapy.utils.misc import md5sum
logger = logging.getLogger('scrapy')
class FileException(Exception):
"""General media error exception"""
@ -192,9 +194,13 @@ class FilesPipeline(MediaPipeline):
return # returning None force download
referer = request.headers.get('Referer')
log.msg(format='File (uptodate): Downloaded %(medianame)s from %(request)s referred in <%(referer)s>',
level=log.DEBUG, spider=info.spider,
medianame=self.MEDIA_NAME, request=request, referer=referer)
logger.debug(
'File (uptodate): Downloaded %(medianame)s from %(request)s '
'referred in <%(referer)s>',
{'medianame': self.MEDIA_NAME, 'request': request,
'referer': referer},
extra={'spider': info.spider}
)
self.inc_stats(info.spider, 'uptodate')
checksum = result.get('checksum', None)
@ -203,17 +209,23 @@ class FilesPipeline(MediaPipeline):
path = self.file_path(request, info=info)
dfd = defer.maybeDeferred(self.store.stat_file, path, info)
dfd.addCallbacks(_onsuccess, lambda _: None)
dfd.addErrback(log.err, self.__class__.__name__ + '.store.stat_file')
dfd.addErrback(
lambda f:
logger.error(self.__class__.__name__ + '.store.stat_file',
extra={'spider': info.spider, 'failure': f})
)
return dfd
def media_failed(self, failure, request, info):
if not isinstance(failure.value, IgnoreRequest):
referer = request.headers.get('Referer')
log.msg(format='File (unknown-error): Error downloading '
'%(medianame)s from %(request)s referred in '
'<%(referer)s>: %(exception)s',
level=log.WARNING, spider=info.spider, exception=failure.value,
medianame=self.MEDIA_NAME, request=request, referer=referer)
logger.warning(
'File (unknown-error): Error downloading %(medianame)s from '
'%(request)s referred in <%(referer)s>: %(exception)s',
{'medianame': self.MEDIA_NAME, 'request': request,
'referer': referer, 'exception': failure.value},
extra={'spider': info.spider}
)
raise FileException
@ -221,34 +233,51 @@ class FilesPipeline(MediaPipeline):
referer = request.headers.get('Referer')
if response.status != 200:
log.msg(format='File (code: %(status)s): Error downloading file from %(request)s referred in <%(referer)s>',
level=log.WARNING, spider=info.spider,
status=response.status, request=request, referer=referer)
logger.warning(
'File (code: %(status)s): Error downloading file from '
'%(request)s referred in <%(referer)s>',
{'status': response.status,
'request': request, 'referer': referer},
extra={'spider': info.spider}
)
raise FileException('download-error')
if not response.body:
log.msg(format='File (empty-content): Empty file from %(request)s referred in <%(referer)s>: no-content',
level=log.WARNING, spider=info.spider,
request=request, referer=referer)
logger.warning(
'File (empty-content): Empty file from %(request)s referred '
'in <%(referer)s>: no-content',
{'request': request, 'referer': referer},
extra={'spider': info.spider}
)
raise FileException('empty-content')
status = 'cached' if 'cached' in response.flags else 'downloaded'
log.msg(format='File (%(status)s): Downloaded file from %(request)s referred in <%(referer)s>',
level=log.DEBUG, spider=info.spider,
status=status, request=request, referer=referer)
logger.debug(
'File (%(status)s): Downloaded file from %(request)s referred in '
'<%(referer)s>',
{'status': status, 'request': request, 'referer': referer},
extra={'spider': info.spider}
)
self.inc_stats(info.spider, status)
try:
path = self.file_path(request, response=response, info=info)
checksum = self.file_downloaded(response, request, info)
except FileException as exc:
whyfmt = 'File (error): Error processing file from %(request)s referred in <%(referer)s>: %(errormsg)s'
log.msg(format=whyfmt, level=log.WARNING, spider=info.spider,
request=request, referer=referer, errormsg=str(exc))
logger.warning(
'File (error): Error processing file from %(request)s '
'referred in <%(referer)s>: %(errormsg)s',
{'request': request, 'referer': referer, 'errormsg': str(exc)},
extra={'spider': info.spider}, exc_info=True
)
raise
except Exception as exc:
whyfmt = 'File (unknown-error): Error processing file from %(request)s referred in <%(referer)s>'
log.err(None, whyfmt % {'request': request, 'referer': referer}, spider=info.spider)
logger.exception(
'File (unknown-error): Error processing file from %(request)s '
'referred in <%(referer)s>',
{'request': request, 'referer': referer},
extra={'spider': info.spider}
)
raise FileException(str(exc))
return {'url': request.url, 'path': path, 'checksum': checksum}

16
scrapy/contrib/pipeline/media.py
View File

@ -1,13 +1,16 @@
from __future__ import print_function
import logging
from collections import defaultdict
from twisted.internet.defer import Deferred, DeferredList
from twisted.python.failure import Failure
from scrapy.utils.defer import mustbe_deferred, defer_result
from scrapy import log
from scrapy.utils.request import request_fingerprint
from scrapy.utils.misc import arg_to_iter
logger = logging.getLogger('scrapy')
class MediaPipeline(object):
@ -66,7 +69,9 @@ class MediaPipeline(object):
dfd = mustbe_deferred(self.media_to_download, request, info)
dfd.addCallback(self._check_media_to_download, request, info)
dfd.addBoth(self._cache_result_and_execute_waiters, fp, info)
dfd.addErrback(log.err, spider=info.spider)
dfd.addErrback(lambda f: logger.error(
f.value, extra={'spider': info.spider, 'failure': f})
)
return dfd.addBoth(lambda _: wad) # it must return wad at last
def _check_media_to_download(self, result, request, info):
@ -117,8 +122,11 @@ class MediaPipeline(object):
def item_completed(self, results, item, info):
"""Called per item when all media requests has been processed"""
if self.LOG_FAILED_RESULTS:
msg = '%s found errors processing %s' % (self.__class__.__name__, item)
for ok, value in results:
if not ok:
log.err(value, msg, spider=info.spider)
logger.error(
'%(class)s found errors processing %(item)s',
{'class': self.__class__.__name__, 'item': item},
extra={'spider': info.spider, 'failure': value}
)
return item

12
scrapy/contrib/spidermiddleware/depth.py
View File

@ -4,9 +4,13 @@ Depth Spider Middleware
See documentation in docs/topics/spider-middleware.rst
"""
from scrapy import log
import logging
from scrapy.http import Request
logger = logging.getLogger('scrapy')
class DepthMiddleware(object):
def __init__(self, maxdepth, stats=None, verbose_stats=False, prio=1):
@ -31,9 +35,9 @@ class DepthMiddleware(object):
if self.prio:
request.priority -= depth * self.prio
if self.maxdepth and depth > self.maxdepth:
log.msg(format="Ignoring link (depth > %(maxdepth)d): %(requrl)s ",
level=log.DEBUG, spider=spider,
maxdepth=self.maxdepth, requrl=request.url)
logger.debug("Ignoring link (depth > %(maxdepth)d): %(requrl)s ",
{'maxdepth': self.maxdepth, 'requrl': request.url},
extra={'spider': spider})
return False
elif self.stats:
if self.verbose_stats:

14
scrapy/contrib/spidermiddleware/httperror.py
View File

@ -3,8 +3,12 @@ HttpError Spider Middleware
See documentation in docs/topics/spider-middleware.rst
"""
import logging
from scrapy.exceptions import IgnoreRequest
from scrapy import log
logger = logging.getLogger('scrapy')
class HttpError(IgnoreRequest):
"""A non-200 response was filtered"""
@ -42,10 +46,8 @@ class HttpErrorMiddleware(object):
def process_spider_exception(self, response, exception, spider):
if isinstance(exception, HttpError):
log.msg(
format="Ignoring response %(response)r: HTTP status code is not handled or not allowed",
level=log.DEBUG,
spider=spider,
response=response
logger.debug(
"Ignoring response %(response)r: HTTP status code is not handled or not allowed",
{'response': response}, extra={'spider': spider},
)
return []

8
scrapy/contrib/spidermiddleware/offsite.py
View File

@ -5,11 +5,13 @@ See documentation in docs/topics/spider-middleware.rst
"""
import re
import logging
from scrapy import signals
from scrapy.http import Request
from scrapy.utils.httpobj import urlparse_cached
from scrapy import log
logger = logging.getLogger('scrapy')
class OffsiteMiddleware(object):
@ -31,8 +33,8 @@ class OffsiteMiddleware(object):
domain = urlparse_cached(x).hostname
if domain and domain not in self.domains_seen:
self.domains_seen.add(domain)
log.msg(format="Filtered offsite request to %(domain)r: %(request)s",
level=log.DEBUG, spider=spider, domain=domain, request=x)
logger.debug("Filtered offsite request to %(domain)r: %(request)s",
{'domain': domain, 'request': x}, extra={'spider': spider})
self.stats.inc_value('offsite/domains', spider=spider)
self.stats.inc_value('offsite/filtered', spider=spider)
else:

12
scrapy/contrib/spidermiddleware/urllength.py
View File

@ -4,10 +4,14 @@ Url Length Spider Middleware
See documentation in docs/topics/spider-middleware.rst
"""
from scrapy import log
import logging
from scrapy.http import Request
from scrapy.exceptions import NotConfigured
logger = logging.getLogger('scrapy')
class UrlLengthMiddleware(object):
def __init__(self, maxlength):
@ -23,9 +27,9 @@ class UrlLengthMiddleware(object):
def process_spider_output(self, response, result, spider):
def _filter(request):
if isinstance(request, Request) and len(request.url) > self.maxlength:
log.msg(format="Ignoring link (url length > %(maxlength)d): %(url)s ",
level=log.DEBUG, spider=spider,
maxlength=self.maxlength, url=request.url)
logger.debug("Ignoring link (url length > %(maxlength)d): %(url)s ",
{'maxlength': self.maxlength, 'url': request.url},
extra={'spider': spider})
return False
else:
return True

9
scrapy/contrib/spiders/sitemap.py
View File

@ -1,10 +1,13 @@
import re
import logging
from scrapy.spider import Spider
from scrapy.http import Request, XmlResponse
from scrapy.utils.sitemap import Sitemap, sitemap_urls_from_robots
from scrapy.utils.gz import gunzip, is_gzipped
from scrapy import log
logger = logging.getLogger('scrapy')
class SitemapSpider(Spider):
@ -32,8 +35,8 @@ class SitemapSpider(Spider):
else:
body = self._get_sitemap_body(response)
if body is None:
log.msg(format="Ignoring invalid sitemap: %(response)s",
level=log.WARNING, spider=self, response=response)
logger.warning("Ignoring invalid sitemap: %(response)s",
{'response': response}, extra={'spider': self})
return
s = Sitemap(body)

17
scrapy/contrib/throttle.py
View File

@ -1,7 +1,10 @@
import logging
from scrapy.exceptions import NotConfigured
from scrapy import signals
logger = logging.getLogger('scrapy')
class AutoThrottle(object):
@ -47,9 +50,17 @@ class AutoThrottle(object):
diff = slot.delay - olddelay
size = len(response.body)
conc = len(slot.transferring)
msg = "slot: %s | conc:%2d | delay:%5d ms (%+d) | latency:%5d ms | size:%6d bytes" % \
(key, conc, slot.delay * 1000, diff * 1000, latency * 1000, size)
spider.log(msg, level=logging.INFO)
logger.info(
"slot: %(slot)s | conc:%(concurrency)2d | "
"delay:%(delay)5d ms (%(delaydiff)+d) | "
"latency:%(latency)5d ms | size:%(size)6d bytes",
{
'slot': key, 'concurrency': conc,
'delay': slot.delay * 1000, 'delaydiff': diff * 1000,
'latency': latency * 1000, 'size': size
},
extra={'spider': spider}
)
def _get_slot(self, request, spider):
key = request.meta.get('download_slot')

28
scrapy/core/downloader/handlers/http11.py
View File

@ -1,7 +1,7 @@
"""Download handlers for http and https schemes"""
import re
import logging
from io import BytesIO
from time import time
from six.moves.urllib.parse import urldefrag
@ -19,7 +19,9 @@ from scrapy.http import Headers
from scrapy.responsetypes import responsetypes
from scrapy.core.downloader.webclient import _parse
from scrapy.utils.misc import load_object
from scrapy import log, twisted_version
from scrapy import twisted_version
logger = logging.getLogger('scrapy')
class HTTP11DownloadHandler(object):
@ -237,14 +239,16 @@ class ScrapyAgent(object):
expected_size = txresponse.length if txresponse.length != UNKNOWN_LENGTH else -1
if maxsize and expected_size > maxsize:
log.msg("Expected response size (%s) larger than download max size (%s)." % (expected_size, maxsize),
logLevel=log.ERROR)
logger.error("Expected response size (%(size)s) larger than "
"download max size (%(maxsize)s).",
{'size': expected_size, 'maxsize': maxsize})
txresponse._transport._producer.loseConnection()
raise defer.CancelledError()
if warnsize and expected_size > warnsize:
log.msg("Expected response size (%s) larger than downlod warn size (%s)." % (expected_size, warnsize),
logLevel=log.WARNING)
logger.warning("Expected response size (%(size)s) larger than "
"download warn size (%(warnsize)s).",
{'size': expected_size, 'warnsize': warnsize})
def _cancel(_):
txresponse._transport._producer.loseConnection()
@ -295,13 +299,17 @@ class _ResponseReader(protocol.Protocol):
self._bytes_received += len(bodyBytes)
if self._maxsize and self._bytes_received > self._maxsize:
log.msg("Received (%s) bytes larger than download max size (%s)." % (self._bytes_received, self._maxsize),
logLevel=log.ERROR)
logger.error("Received (%(bytes)s) bytes larger than download "
"max size (%(maxsize)s).",
{'bytes': self._bytes_received,
'maxsize': self._maxsize})
self._finished.cancel()
if self._warnsize and self._bytes_received > self._warnsize:
log.msg("Received (%s) bytes larger than download warn size (%s)." % (self._bytes_received, self._warnsize),
logLevel=log.WARNING)
logger.warning("Received (%(bytes)s) bytes larger than download "
"warn size (%(warnsize)s).",
{'bytes': self._bytes_received,
'warnsize': self._warnsize})
def connectionLost(self, reason):
if self._finished.called:

50
scrapy/core/engine.py
View File

@ -4,6 +4,7 @@ This is the Scrapy engine which controls the Scheduler, Downloader and Spiders.
For more information see docs/topics/architecture.rst
"""
import logging
from time import time
from twisted.internet import defer
@ -16,6 +17,8 @@ from scrapy.http import Response, Request
from scrapy.utils.misc import load_object
from scrapy.utils.reactor import CallLaterOnce
logger = logging.getLogger('scrapy')
class Slot(object):
@ -106,10 +109,10 @@ class ExecutionEngine(object):
request = next(slot.start_requests)
except StopIteration:
slot.start_requests = None
except Exception as exc:
except Exception:
slot.start_requests = None
log.err(None, 'Obtaining request from start requests', \
spider=spider)
logger.exception('Error while obtaining start requests',
extra={'spider': spider})
else:
self.crawl(request, spider)
@ -130,11 +133,14 @@ class ExecutionEngine(object):
return
d = self._download(request, spider)
d.addBoth(self._handle_downloader_output, request, spider)
d.addErrback(log.msg, spider=spider)
d.addErrback(lambda f: logger.info('Error while handling downloader output',
extra={'spider': spider, 'failure': f}))
d.addBoth(lambda _: slot.remove_request(request))
d.addErrback(log.msg, spider=spider)
d.addErrback(lambda f: logger.info('Error while removing request from slot',
extra={'spider': spider, 'failure': f}))
d.addBoth(lambda _: slot.nextcall.schedule())
d.addErrback(log.msg, spider=spider)
d.addErrback(lambda f: logger.info('Error while scheduling new request',
extra={'spider': spider, 'failure': f}))
return d
def _handle_downloader_output(self, response, request, spider):
@ -145,7 +151,8 @@ class ExecutionEngine(object):
return
# response is a Response or Failure
d = self.scraper.enqueue_scrape(response, request, spider)
d.addErrback(log.err, spider=spider)
d.addErrback(lambda f: logger.error('Error while enqueuing downloader output',
extra={'spider': spider, 'failure': f}))
return d
def spider_is_idle(self, spider):
@ -215,7 +222,7 @@ class ExecutionEngine(object):
def open_spider(self, spider, start_requests=(), close_if_idle=True):
assert self.has_capacity(), "No free spider slot when opening %r" % \
spider.name
log.msg("Spider opened", spider=spider)
logger.info("Spider opened", extra={'spider': spider})
nextcall = CallLaterOnce(self._next_request, spider)
scheduler = self.scheduler_cls.from_crawler(self.crawler)
start_requests = yield self.scraper.spidermw.process_start_requests(start_requests, spider)
@ -252,33 +259,42 @@ class ExecutionEngine(object):
slot = self.slot
if slot.closing:
return slot.closing
log.msg(format="Closing spider (%(reason)s)", reason=reason, spider=spider)
logger.info("Closing spider (%(reason)s)",
{'reason': reason},
extra={'spider': spider})
dfd = slot.close()
def log_failure(msg):
def errback(failure):
logger.error(msg, extra={'spider': spider, 'failure': failure})
return errback
dfd.addBoth(lambda _: self.downloader.close())
dfd.addErrback(log.err, spider=spider)
dfd.addErrback(log_failure('Downloader close failure'))
dfd.addBoth(lambda _: self.scraper.close_spider(spider))
dfd.addErrback(log.err, spider=spider)
dfd.addErrback(log_failure('Scraper close failure'))
dfd.addBoth(lambda _: slot.scheduler.close(reason))
dfd.addErrback(log.err, spider=spider)
dfd.addErrback(log_failure('Scheduler close failure'))
dfd.addBoth(lambda _: self.signals.send_catch_log_deferred(
signal=signals.spider_closed, spider=spider, reason=reason))
dfd.addErrback(log.err, spider=spider)
dfd.addErrback(log_failure('Error while sending spider_close signal'))
dfd.addBoth(lambda _: self.crawler.stats.close_spider(spider, reason=reason))
dfd.addErrback(log.err, spider=spider)
dfd.addErrback(log_failure('Stats close failure'))
dfd.addBoth(lambda _: log.msg(format="Spider closed (%(reason)s)", reason=reason, spider=spider))
dfd.addBoth(lambda _: logger.info("Spider closed (%(reason)s)",
{'reason': reason},
extra={'spider': spider}))
dfd.addBoth(lambda _: setattr(self, 'slot', None))
dfd.addErrback(log.err, spider=spider)
dfd.addErrback(log_failure('Error while unassigning slot'))
dfd.addBoth(lambda _: setattr(self, 'spider', None))
dfd.addErrback(log.err, spider=spider)
dfd.addErrback(log_failure('Error while unassigning spider'))
dfd.addBoth(lambda _: self._spider_closed_callback(spider))

15
scrapy/core/scheduler.py
View File

@ -1,12 +1,15 @@
import os
import json
import logging
from os.path import join, exists
from queuelib import PriorityQueue
from scrapy.utils.reqser import request_to_dict, request_from_dict
from scrapy.utils.misc import load_object
from scrapy.utils.job import job_dir
from scrapy import log
logger = logging.getLogger('scrapy')
class Scheduler(object):
@ -80,9 +83,9 @@ class Scheduler(object):
self.dqs.push(reqd, -request.priority)
except ValueError as e: # non serializable request
if self.logunser:
log.msg(format="Unable to serialize request: %(request)s - reason: %(reason)s",
level=log.ERROR, spider=self.spider,
request=request, reason=e)
logger.exception("Unable to serialize request: %(request)s - reason: %(reason)s",
{'request': request, 'reason': e},
extra={'spider': self.spider})
return
else:
return True
@ -111,8 +114,8 @@ class Scheduler(object):
prios = ()
q = PriorityQueue(self._newdq, startprios=prios)
if q:
log.msg(format="Resuming crawl (%(queuesize)d requests scheduled)",
spider=self.spider, queuesize=len(q))
logger.info("Resuming crawl (%(queuesize)d requests scheduled)",
{'queuesize': len(q)}, extra={'spider': self.spider})
return q
def _dqdir(self, jobdir):

36
scrapy/core/scraper.py
View File

@ -1,6 +1,7 @@
"""This module implements the Scraper component which parses responses and
extracts information from them"""
import logging
from collections import deque
from twisted.python.failure import Failure
@ -16,6 +17,8 @@ from scrapy.item import BaseItem
from scrapy.core.spidermw import SpiderMiddlewareManager
from scrapy import log
logger = logging.getLogger('scrapy')
class Slot(object):
"""Scraper slot (one per running spider)"""
@ -102,7 +105,9 @@ class Scraper(object):
return _
dfd.addBoth(finish_scraping)
dfd.addErrback(
log.err, 'Scraper bug processing %s' % request, spider=spider)
lambda f: logger.error('Scraper bug processing %(request)s',
{'request': request},
extra={'spider': spider, 'failure': f}))
self._scrape_next(spider, slot)
return dfd
@ -145,10 +150,10 @@ class Scraper(object):
self.crawler.engine.close_spider(spider, exc.reason or 'cancelled')
return
referer = request.headers.get('Referer')
log.err(
_failure,
"Spider error processing %s (referer: %s)" % (request, referer),
spider=spider
logger.error(
"Spider error processing %(request)s (referer: %(referer)s)",
{'request': request, 'referer': referer},
extra={'spider': spider, 'failure': _failure}
)
self.signals.send_catch_log(
signal=signals.spider_error,
@ -183,9 +188,10 @@ class Scraper(object):
pass
else:
typename = type(output).__name__
log.msg(format='Spider must return Request, BaseItem, dict or None, '
'got %(typename)r in %(request)s',
level=log.ERROR, spider=spider, request=request, typename=typename)
logger.error('Spider must return Request, BaseItem, dict or None, '
'got %(typename)r in %(request)s',
{'request': request, 'typename': typename},
extra={'spider': spider})
def _log_download_errors(self, spider_failure, download_failure, request, spider):
"""Log and silence errors that come from the engine (typically download
@ -194,14 +200,15 @@ class Scraper(object):
if (isinstance(download_failure, Failure) and
not download_failure.check(IgnoreRequest)):
if download_failure.frames:
log.err(download_failure, 'Error downloading %s' % request,
spider=spider)
logger.error('Error downloading %(request)s',
{'request': request},
extra={'spider': spider, 'failure': download_failure})
else:
errmsg = download_failure.getErrorMessage()
if errmsg:
log.msg(format='Error downloading %(request)s: %(errmsg)s',
level=log.ERROR, spider=spider, request=request,
errmsg=errmsg)
logger.error('Error downloading %(request)s: %(errmsg)s',
{'request': request, 'errmsg': errmsg},
extra={'spider': spider})
if spider_failure is not download_failure:
return spider_failure
@ -219,7 +226,8 @@ class Scraper(object):
signal=signals.item_dropped, item=item, response=response,
spider=spider, exception=output.value)
else:
log.err(output, 'Error processing %s' % item, spider=spider)
logger.error('Error processing %(item)s', {'item': item},
extra={'spider': spider, 'failure': output})
else:
logkws = self.logformatter.scraped(output, response, spider)
log.msg(spider=spider, **logkws)

13
scrapy/crawler.py
View File

@ -1,5 +1,6 @@
import six
import signal
import logging
import warnings
from twisted.internet import reactor, defer
@ -14,7 +15,9 @@ from scrapy.signalmanager import SignalManager
from scrapy.exceptions import ScrapyDeprecationWarning
from scrapy.utils.ossignal import install_shutdown_handlers, signal_names
from scrapy.utils.misc import load_object
from scrapy import log, signals
from scrapy import signals
logger = logging.getLogger('scrapy')
class Crawler(object):
@ -145,15 +148,15 @@ class CrawlerProcess(CrawlerRunner):
def _signal_shutdown(self, signum, _):
install_shutdown_handlers(self._signal_kill)
signame = signal_names[signum]
log.msg(format="Received %(signame)s, shutting down gracefully. Send again to force ",
level=log.INFO, signame=signame)
logger.info("Received %(signame)s, shutting down gracefully. Send again to force ",
{'signame': signame})
reactor.callFromThread(self.stop)
def _signal_kill(self, signum, _):
install_shutdown_handlers(signal.SIG_IGN)
signame = signal_names[signum]
log.msg(format='Received %(signame)s twice, forcing unclean shutdown',
level=log.INFO, signame=signame)
logger.info('Received %(signame)s twice, forcing unclean shutdown',
{'signame': signame})
self._stop_logging()
reactor.callFromThread(self._stop_reactor)

11
scrapy/dupefilter.py
View File

@ -1,7 +1,7 @@
from __future__ import print_function
import os
import logging
from scrapy import log
from scrapy.utils.job import job_dir
from scrapy.utils.request import request_fingerprint
@ -33,6 +33,7 @@ class RFPDupeFilter(BaseDupeFilter):
self.fingerprints = set()
self.logdupes = True
self.debug = debug
self.logger = logging.getLogger('scrapy')
if path:
self.file = open(os.path.join(path, 'requests.seen'), 'a+')
self.fingerprints.update(x.rstrip() for x in self.file)
@ -59,13 +60,13 @@ class RFPDupeFilter(BaseDupeFilter):
def log(self, request, spider):
if self.debug:
fmt = "Filtered duplicate request: %(request)s"
log.msg(format=fmt, request=request, level=log.DEBUG, spider=spider)
msg = "Filtered duplicate request: %(request)s"
self.logger.debug(msg, {'request': request}, extra={'spider': spider})
elif self.logdupes:
fmt = ("Filtered duplicate request: %(request)s"
msg = ("Filtered duplicate request: %(request)s"
" - no more duplicates will be shown"
" (see DUPEFILTER_DEBUG to show all duplicates)")
log.msg(format=fmt, request=request, level=log.DEBUG, spider=spider)
self.logger.debug(msg, {'request': request}, extra={'spider': spider})
self.logdupes = False
spider.crawler.stats.inc_value('dupefilter/filtered', spider=spider)

28
scrapy/mail.py
View File

@ -3,6 +3,8 @@ Mail sending helpers
See documentation in docs/topics/email.rst
"""
import logging
from six.moves import cStringIO as StringIO
import six
@ -20,7 +22,8 @@ else:
from twisted.internet import defer, reactor, ssl
from twisted.mail.smtp import ESMTPSenderFactory
from scrapy import log
logger = logging.getLogger('scrapy')
class MailSender(object):
@ -71,8 +74,10 @@ class MailSender(object):
_callback(to=to, subject=subject, body=body, cc=cc, attach=attachs, msg=msg)
if self.debug:
log.msg(format='Debug mail sent OK: To=%(mailto)s Cc=%(mailcc)s Subject="%(mailsubject)s" Attachs=%(mailattachs)d',
level=log.DEBUG, mailto=to, mailcc=cc, mailsubject=subject, mailattachs=len(attachs))
logger.debug('Debug mail sent OK: To=%(mailto)s Cc=%(mailcc)s '
'Subject="%(mailsubject)s" Attachs=%(mailattachs)d',
{'mailto': to, 'mailcc': cc, 'mailsubject': subject,
'mailattachs': len(attachs)})
return
dfd = self._sendmail(rcpts, msg.as_string())
@ -83,17 +88,18 @@ class MailSender(object):
return dfd
def _sent_ok(self, result, to, cc, subject, nattachs):
log.msg(format='Mail sent OK: To=%(mailto)s Cc=%(mailcc)s '
'Subject="%(mailsubject)s" Attachs=%(mailattachs)d',
mailto=to, mailcc=cc, mailsubject=subject, mailattachs=nattachs)
logger.info('Mail sent OK: To=%(mailto)s Cc=%(mailcc)s '
'Subject="%(mailsubject)s" Attachs=%(mailattachs)d',
{'mailto': to, 'mailcc': cc, 'mailsubject': subject,
'mailattachs': nattachs})
def _sent_failed(self, failure, to, cc, subject, nattachs):
errstr = str(failure.value)
log.msg(format='Unable to send mail: To=%(mailto)s Cc=%(mailcc)s '
'Subject="%(mailsubject)s" Attachs=%(mailattachs)d'
'- %(mailerr)s',
level=log.ERROR, mailto=to, mailcc=cc, mailsubject=subject,
mailattachs=nattachs, mailerr=errstr)
logger.error('Unable to send mail: To=%(mailto)s Cc=%(mailcc)s '
'Subject="%(mailsubject)s" Attachs=%(mailattachs)d'
'- %(mailerr)s',
{'mailto': to, 'mailcc': cc, 'mailsubject': subject,
'mailattachs': nattachs, 'mailerr': errstr})
def _sendmail(self, to_addrs, msg):
msg = StringIO(msg)

16
scrapy/middleware.py
View File

@ -1,10 +1,13 @@
import logging
from collections import defaultdict
from scrapy import log
from scrapy.exceptions import NotConfigured
from scrapy.utils.misc import load_object
from scrapy.utils.defer import process_parallel, process_chain, process_chain_both
logger = logging.getLogger('scrapy')
class MiddlewareManager(object):
"""Base class for implementing middleware managers"""
@ -37,12 +40,15 @@ class MiddlewareManager(object):
except NotConfigured as e:
if e.args:
clsname = clspath.split('.')[-1]
log.msg(format="Disabled %(clsname)s: %(eargs)s",
level=log.WARNING, clsname=clsname, eargs=e.args[0])
logger.warning("Disabled %(clsname)s: %(eargs)s",
{'clsname': clsname, 'eargs': e.args[0]},
extra={'crawler': crawler})
enabled = [x.__class__.__name__ for x in middlewares]
log.msg(format="Enabled %(componentname)ss: %(enabledlist)s", level=log.INFO,
componentname=cls.component_name, enabledlist=', '.join(enabled))
logger.info("Enabled %(componentname)ss: %(enabledlist)s",
{'componentname': cls.component_name,
'enabledlist': ', '.join(enabled)},
extra={'crawler': crawler})
return cls(*middlewares)
@classmethod

8
scrapy/statscol.py
View File

@ -2,8 +2,10 @@
Scrapy extension for collecting scraping stats
"""
import pprint
import logging
logger = logging.getLogger('scrapy')
from scrapy import log
class StatsCollector(object):
@ -41,8 +43,8 @@ class StatsCollector(object):
def close_spider(self, spider, reason):
if self._dump:
log.msg("Dumping Scrapy stats:\n" + pprint.pformat(self._stats), \
spider=spider)
logger.info("Dumping Scrapy stats:\n" + pprint.pformat(self._stats),
extra={'spider': spider})
self._persist_stats(self._stats, spider)
def _persist_stats(self, stats, spider):

10
scrapy/telnet.py
View File

@ -5,6 +5,7 @@ See documentation in docs/topics/telnetconsole.rst
"""
import pprint
import logging
from twisted.internet import protocol
try:
@ -15,7 +16,7 @@ except ImportError:
TWISTED_CONCH_AVAILABLE = False
from scrapy.exceptions import NotConfigured
from scrapy import log, signals
from scrapy import signals
from scrapy.utils.trackref import print_live_refs
from scrapy.utils.engine import print_engine_status
from scrapy.utils.reactor import listen_tcp
@ -26,6 +27,8 @@ try:
except ImportError:
hpy = None
logger = logging.getLogger('scrapy')
# signal to update telnet variables
# args: telnet_vars
update_telnet_vars = object()
@ -52,8 +55,9 @@ class TelnetConsole(protocol.ServerFactory):
def start_listening(self):
self.port = listen_tcp(self.portrange, self.host, self)
h = self.port.getHost()
log.msg(format="Telnet console listening on %(host)s:%(port)d",
level=log.DEBUG, host=h.host, port=h.port)
logger.debug("Telnet console listening on %(host)s:%(port)d",
{'host': h.host, 'port': h.port},
extra={'crawler': self.crawler})
def stop_listening(self):
self.port.stopListening()

15
scrapy/utils/iterators.py
View File

@ -1,15 +1,20 @@
import re, csv, six
import re
import csv
import logging
try:
from cStringIO import StringIO as BytesIO
except ImportError:
from io import BytesIO
import six
from scrapy.http import TextResponse, Response
from scrapy.selector import Selector
from scrapy import log
from scrapy.utils.python import re_rsearch, str_to_unicode
logger = logging.getLogger('scrapy')
def xmliter(obj, nodename):
"""Return a iterator of Selector's over all nodes of a XML document,
@ -108,8 +113,10 @@ def csviter(obj, delimiter=None, headers=None, encoding=None, quotechar=None):
while True:
row = _getrow(csv_r)
if len(row) != len(headers):
log.msg(format="ignoring row %(csvlnum)d (length: %(csvrow)d, should be: %(csvheader)d)",
level=log.WARNING, csvlnum=csv_r.line_num, csvrow=len(row), csvheader=len(headers))
logger.warning("ignoring row %(csvlnum)d (length: %(csvrow)d, "
"should be: %(csvheader)d)",
{'csvlnum': csv_r.line_num, 'csvrow': len(row),
'csvheader': len(headers)})
continue
else:
yield dict(zip(headers, row))

18
scrapy/utils/signal.py
View File

@ -1,5 +1,7 @@
"""Helper functions for working with signals"""
import logging
from twisted.internet.defer import maybeDeferred, DeferredList, Deferred
from twisted.python.failure import Failure
@ -7,7 +9,8 @@ from scrapy.xlib.pydispatch.dispatcher import Any, Anonymous, liveReceivers, \
getAllReceivers, disconnect
from scrapy.xlib.pydispatch.robustapply import robustApply
from scrapy import log
logger = logging.getLogger('scrapy')
def send_catch_log(signal=Any, sender=Anonymous, *arguments, **named):
"""Like pydispatcher.robust.sendRobust but it also logs errors and returns
@ -21,14 +24,14 @@ def send_catch_log(signal=Any, sender=Anonymous, *arguments, **named):
response = robustApply(receiver, signal=signal, sender=sender,
*arguments, **named)
if isinstance(response, Deferred):
log.msg(format="Cannot return deferreds from signal handler: %(receiver)s",
level=log.ERROR, spider=spider, receiver=receiver)
logger.error("Cannot return deferreds from signal handler: %(receiver)s",
{'receiver': receiver}, extra={'spider': spider})
except dont_log:
result = Failure()
except Exception:
result = Failure()
log.err(result, "Error caught on signal handler: %s" % receiver, \
spider=spider)
logger.exception("Error caught on signal handler: %(receiver)s",
{'receiver': receiver}, extra={'spider': spider})
else:
result = response
responses.append((receiver, result))
@ -41,8 +44,9 @@ def send_catch_log_deferred(signal=Any, sender=Anonymous, *arguments, **named):
"""
def logerror(failure, recv):
if dont_log is None or not isinstance(failure.value, dont_log):
log.err(failure, "Error caught on signal handler: %s" % recv, \
spider=spider)
logger.error("Error caught on signal handler: %(receiver)s",
{'receiver': recv},
extra={'spider': spider, 'failure': failure})
return failure
dont_log = named.pop('dont_log', None)

12
scrapy/utils/spider.py
View File

@ -1,11 +1,13 @@
import logging
import inspect
import six
from scrapy import log
from scrapy.spider import Spider
from scrapy.utils.misc import arg_to_iter
logger = logging.getLogger('scrapy')
def iterate_spider_output(result):
return arg_to_iter(result)
@ -43,12 +45,12 @@ def spidercls_for_request(spider_loader, request, default_spidercls=None,
return spider_loader.load(snames[0])
if len(snames) > 1 and log_multiple:
log.msg(format='More than one spider can handle: %(request)s - %(snames)s',
level=log.ERROR, request=request, snames=', '.join(snames))
logger.error('More than one spider can handle: %(request)s - %(snames)s',
{'request': request, 'snames': ', '.join(snames)})
if len(snames) == 0 and log_none:
log.msg(format='Unable to find spider that handles: %(request)s',
level=log.ERROR, request=request)
logger.error('Unable to find spider that handles: %(request)s',
{'request': request})
return default_spidercls

19
tests/test_commands.py
View File

@ -137,7 +137,6 @@ class RunSpiderCommandTest(CommandTest):
with open(fname, 'w') as f:
f.write("""
import scrapy
from scrapy import log
class MySpider(scrapy.Spider):
name = 'myspider'
@ -148,10 +147,10 @@ class MySpider(scrapy.Spider):
""")
p = self.proc('runspider', fname)
log = p.stderr.read()
self.assertIn("[myspider] DEBUG: It Works!", log)
self.assertIn("[myspider] INFO: Spider opened", log)
self.assertIn("[myspider] INFO: Closing spider (finished)", log)
self.assertIn("[myspider] INFO: Spider closed (finished)", log)
self.assertIn("DEBUG: It Works!", log)
self.assertIn("INFO: Spider opened", log)
self.assertIn("INFO: Closing spider (finished)", log)
self.assertIn("INFO: Spider closed (finished)", log)
def test_runspider_no_spider_found(self):
tmpdir = self.mktemp()
@ -159,7 +158,6 @@ class MySpider(scrapy.Spider):
fname = abspath(join(tmpdir, 'myspider.py'))
with open(fname, 'w') as f:
f.write("""
from scrapy import log
from scrapy.spider import Spider
""")
p = self.proc('runspider', fname)
@ -192,7 +190,6 @@ class ParseCommandTest(ProcessTest, SiteTest, CommandTest):
fname = abspath(join(self.proj_mod_path, 'spiders', 'myspider.py'))
with open(fname, 'w') as f:
f.write("""
from scrapy import log
import scrapy
class MySpider(scrapy.Spider):
@ -207,13 +204,13 @@ class MySpider(scrapy.Spider):
fname = abspath(join(self.proj_mod_path, 'pipelines.py'))
with open(fname, 'w') as f:
f.write("""
from scrapy import log
import logging
class MyPipeline(object):
component_name = 'my_pipeline'
def process_item(self, item, spider):
log.msg('It Works!')
logging.info('It Works!')
return item
""")
@ -229,7 +226,7 @@ ITEM_PIPELINES = {'%s.pipelines.MyPipeline': 1}
'-a', 'test_arg=1',
'-c', 'parse',
self.url('/html')])
self.assertIn("[parse_spider] DEBUG: It Works!", stderr)
self.assertIn("DEBUG: It Works!", stderr)
@defer.inlineCallbacks
def test_pipelines(self):
@ -237,7 +234,7 @@ ITEM_PIPELINES = {'%s.pipelines.MyPipeline': 1}
'--pipelines',
'-c', 'parse',
self.url('/html')])
self.assertIn("[scrapy] INFO: It Works!", stderr)
self.assertIn("INFO: It Works!", stderr)
@defer.inlineCallbacks
def test_parse_items(self):