From 7a958f90bef3e6a1ab51bfb04260ed6186f38924 Mon Sep 17 00:00:00 2001 From: Julia Medina Date: Fri, 27 Feb 2015 23:36:30 -0300 Subject: [PATCH] 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 --- scrapy/commands/parse.py | 29 ++++--- scrapy/commands/shell.py | 1 - scrapy/contrib/debug.py | 18 +++-- .../contrib/downloadermiddleware/ajaxcrawl.py | 13 +++- .../contrib/downloadermiddleware/cookies.py | 8 +- .../downloadermiddleware/decompression.py | 10 ++- .../contrib/downloadermiddleware/redirect.py | 14 ++-- scrapy/contrib/downloadermiddleware/retry.py | 14 ++-- .../contrib/downloadermiddleware/robotstxt.py | 14 ++-- scrapy/contrib/feedexport.py | 29 ++++--- scrapy/contrib/logstats.py | 15 +++- scrapy/contrib/memusage.py | 14 ++-- scrapy/contrib/pipeline/files.py | 77 +++++++++++++------ scrapy/contrib/pipeline/media.py | 16 +++- scrapy/contrib/spidermiddleware/depth.py | 12 ++- scrapy/contrib/spidermiddleware/httperror.py | 14 ++-- scrapy/contrib/spidermiddleware/offsite.py | 8 +- scrapy/contrib/spidermiddleware/urllength.py | 12 ++- scrapy/contrib/spiders/sitemap.py | 9 ++- scrapy/contrib/throttle.py | 17 +++- scrapy/core/downloader/handlers/http11.py | 28 ++++--- scrapy/core/engine.py | 50 ++++++++---- scrapy/core/scheduler.py | 15 ++-- scrapy/core/scraper.py | 36 +++++---- scrapy/crawler.py | 13 ++-- scrapy/dupefilter.py | 11 +-- scrapy/mail.py | 28 ++++--- scrapy/middleware.py | 16 ++-- scrapy/statscol.py | 8 +- scrapy/telnet.py | 10 ++- scrapy/utils/iterators.py | 15 +++- scrapy/utils/signal.py | 18 +++-- scrapy/utils/spider.py | 12 +-- tests/test_commands.py | 19 ++--- 34 files changed, 401 insertions(+), 222 deletions(-) diff --git a/scrapy/commands/parse.py b/scrapy/commands/parse.py index 3e006ede3..b28beecc0 100644 --- a/scrapy/commands/parse.py +++ b/scrapy/commands/parse.py @@ -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 diff --git a/scrapy/commands/shell.py b/scrapy/commands/shell.py index f8ad8a491..0b130529b 100644 --- a/scrapy/commands/shell.py +++ b/scrapy/commands/shell.py @@ -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 diff --git a/scrapy/contrib/debug.py b/scrapy/contrib/debug.py index 18a746d31..f1ec67530 100644 --- a/scrapy/contrib/debug.py +++ b/scrapy/contrib/debug.py @@ -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()) diff --git a/scrapy/contrib/downloadermiddleware/ajaxcrawl.py b/scrapy/contrib/downloadermiddleware/ajaxcrawl.py index 6c0371691..ef7f34ef9 100644 --- a/scrapy/contrib/downloadermiddleware/ajaxcrawl.py +++ b/scrapy/contrib/downloadermiddleware/ajaxcrawl.py @@ -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 diff --git a/scrapy/contrib/downloadermiddleware/cookies.py b/scrapy/contrib/downloadermiddleware/cookies.py index 4b63b8112..70ecc2dec 100644 --- a/scrapy/contrib/downloadermiddleware/cookies.py +++ b/scrapy/contrib/downloadermiddleware/cookies.py @@ -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 diff --git a/scrapy/contrib/downloadermiddleware/decompression.py b/scrapy/contrib/downloadermiddleware/decompression.py index c08f50b5f..7cd506dd9 100644 --- a/scrapy/contrib/downloadermiddleware/decompression.py +++ b/scrapy/contrib/downloadermiddleware/decompression.py @@ -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 diff --git a/scrapy/contrib/downloadermiddleware/redirect.py b/scrapy/contrib/downloadermiddleware/redirect.py index cfb10d4db..68d139bc7 100644 --- a/scrapy/contrib/downloadermiddleware/redirect.py +++ b/scrapy/contrib/downloadermiddleware/redirect.py @@ -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): diff --git a/scrapy/contrib/downloadermiddleware/retry.py b/scrapy/contrib/downloadermiddleware/retry.py index f72f39431..749b334f1 100644 --- a/scrapy/contrib/downloadermiddleware/retry.py +++ b/scrapy/contrib/downloadermiddleware/retry.py @@ -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}) diff --git a/scrapy/contrib/downloadermiddleware/robotstxt.py b/scrapy/contrib/downloadermiddleware/robotstxt.py index a58ecca8e..12ab2dd07 100644 --- a/scrapy/contrib/downloadermiddleware/robotstxt.py +++ b/scrapy/contrib/downloadermiddleware/robotstxt.py @@ -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) diff --git a/scrapy/contrib/feedexport.py b/scrapy/contrib/feedexport.py index a8404146b..7162fbc10 100644 --- a/scrapy/contrib/feedexport.py +++ b/scrapy/contrib/feedexport.py @@ -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) diff --git a/scrapy/contrib/logstats.py b/scrapy/contrib/logstats.py index 4f2567c3f..3ea347e8d 100644 --- a/scrapy/contrib/logstats.py +++ b/scrapy/contrib/logstats.py @@ -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: diff --git a/scrapy/contrib/memusage.py b/scrapy/contrib/memusage.py index 6bcba8e11..d1e13bfe5 100644 --- a/scrapy/contrib/memusage.py +++ b/scrapy/contrib/memusage.py @@ -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()) diff --git a/scrapy/contrib/pipeline/files.py b/scrapy/contrib/pipeline/files.py index 608614865..daedac3f7 100644 --- a/scrapy/contrib/pipeline/files.py +++ b/scrapy/contrib/pipeline/files.py @@ -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} diff --git a/scrapy/contrib/pipeline/media.py b/scrapy/contrib/pipeline/media.py index 012b7979a..2995dded6 100644 --- a/scrapy/contrib/pipeline/media.py +++ b/scrapy/contrib/pipeline/media.py @@ -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 diff --git a/scrapy/contrib/spidermiddleware/depth.py b/scrapy/contrib/spidermiddleware/depth.py index 5ccfc86ed..6aeb5e053 100644 --- a/scrapy/contrib/spidermiddleware/depth.py +++ b/scrapy/contrib/spidermiddleware/depth.py @@ -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: diff --git a/scrapy/contrib/spidermiddleware/httperror.py b/scrapy/contrib/spidermiddleware/httperror.py index 7fb7aa97c..1962eaf6c 100644 --- a/scrapy/contrib/spidermiddleware/httperror.py +++ b/scrapy/contrib/spidermiddleware/httperror.py @@ -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 [] diff --git a/scrapy/contrib/spidermiddleware/offsite.py b/scrapy/contrib/spidermiddleware/offsite.py index 136714508..fb69a4631 100644 --- a/scrapy/contrib/spidermiddleware/offsite.py +++ b/scrapy/contrib/spidermiddleware/offsite.py @@ -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: diff --git a/scrapy/contrib/spidermiddleware/urllength.py b/scrapy/contrib/spidermiddleware/urllength.py index fa6f2c909..d3c716063 100644 --- a/scrapy/contrib/spidermiddleware/urllength.py +++ b/scrapy/contrib/spidermiddleware/urllength.py @@ -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 diff --git a/scrapy/contrib/spiders/sitemap.py b/scrapy/contrib/spiders/sitemap.py index 84ae04d08..845e2bc18 100644 --- a/scrapy/contrib/spiders/sitemap.py +++ b/scrapy/contrib/spiders/sitemap.py @@ -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) diff --git a/scrapy/contrib/throttle.py b/scrapy/contrib/throttle.py index a5601bcd0..5f72c81fc 100644 --- a/scrapy/contrib/throttle.py +++ b/scrapy/contrib/throttle.py @@ -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') diff --git a/scrapy/core/downloader/handlers/http11.py b/scrapy/core/downloader/handlers/http11.py index 634c6398b..11fbd35b9 100644 --- a/scrapy/core/downloader/handlers/http11.py +++ b/scrapy/core/downloader/handlers/http11.py @@ -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: diff --git a/scrapy/core/engine.py b/scrapy/core/engine.py index b009898a3..7e330af1c 100644 --- a/scrapy/core/engine.py +++ b/scrapy/core/engine.py @@ -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)) diff --git a/scrapy/core/scheduler.py b/scrapy/core/scheduler.py index 232bc6a40..0e1acacea 100644 --- a/scrapy/core/scheduler.py +++ b/scrapy/core/scheduler.py @@ -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): diff --git a/scrapy/core/scraper.py b/scrapy/core/scraper.py index b301aa962..4a961f8e8 100644 --- a/scrapy/core/scraper.py +++ b/scrapy/core/scraper.py @@ -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) diff --git a/scrapy/crawler.py b/scrapy/crawler.py index b4706919a..f1ef1b524 100644 --- a/scrapy/crawler.py +++ b/scrapy/crawler.py @@ -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) diff --git a/scrapy/dupefilter.py b/scrapy/dupefilter.py index 9bd6a6e05..37376ad8a 100644 --- a/scrapy/dupefilter.py +++ b/scrapy/dupefilter.py @@ -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) diff --git a/scrapy/mail.py b/scrapy/mail.py index e1d7c44f6..7e38663cf 100644 --- a/scrapy/mail.py +++ b/scrapy/mail.py @@ -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) diff --git a/scrapy/middleware.py b/scrapy/middleware.py index b1494b137..917717de5 100644 --- a/scrapy/middleware.py +++ b/scrapy/middleware.py @@ -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 diff --git a/scrapy/statscol.py b/scrapy/statscol.py index 8a7eed149..3fe32ee81 100644 --- a/scrapy/statscol.py +++ b/scrapy/statscol.py @@ -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): diff --git a/scrapy/telnet.py b/scrapy/telnet.py index d7cd601a2..049ab32ed 100644 --- a/scrapy/telnet.py +++ b/scrapy/telnet.py @@ -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() diff --git a/scrapy/utils/iterators.py b/scrapy/utils/iterators.py index a889114d5..4f81b2d9c 100644 --- a/scrapy/utils/iterators.py +++ b/scrapy/utils/iterators.py @@ -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)) diff --git a/scrapy/utils/signal.py b/scrapy/utils/signal.py index 724f3a892..091955b73 100644 --- a/scrapy/utils/signal.py +++ b/scrapy/utils/signal.py @@ -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) diff --git a/scrapy/utils/spider.py b/scrapy/utils/spider.py index 44f098f05..1df5e3769 100644 --- a/scrapy/utils/spider.py +++ b/scrapy/utils/spider.py @@ -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 diff --git a/tests/test_commands.py b/tests/test_commands.py index 68f76d002..f888c54bd 100644 --- a/tests/test_commands.py +++ b/tests/test_commands.py @@ -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):