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

Merge pull request #164 from dangra/lazy-log-formatting 

format log lines lazily in case they are dropped by loglevels
This commit is contained in:
Pablo Hoffman 2012-08-31 14:33:41 -07:00
parent be206ca5ab a2d22307ad
commit 3891c20840
29 changed files with 200 additions and 108 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

1
docs/news.rst
View File

@ -6,6 +6,7 @@ Release notes
Scrapy changes:
- changed LogFormatter API to support lazy formatting of scraped/dropped items. #164 (:commit:`dcef7b0`)
- added :meth:`~scrapy.contrib.spidermiddleware.SpiderMiddleware.process_start_requests` method to spider middlewares
- dropped Signals singleton. Signals should now be accesed through the Crawler.signals attribute. See the signals documentation for more info.
- dropped Signals singleton. Signals should now be accesed through the Crawler.signals attribute. See the signals documentation for more info.

19
scrapy/commands/parse.py
View File

@ -113,19 +113,22 @@ class Command(ScrapyCommand):
if rule.link_extractor.matches(response.url) and rule.callback:
return rule.callback
else:
log.msg("No CrawlSpider rules found in spider %r, please specify "
"a callback to use for parsing" % self.spider.name, log.ERROR)
log.msg(format='No CrawlSpider rules found in spider %(spider)r, '
'please specify a callback to use for parsing',
level=log.ERROR, spider=self.spider.name)
def set_spider(self, url, opts):
if opts.spider:
try:
self.spider = self.crawler.spiders.create(opts.spider)
except KeyError:
log.msg('Unable to find spider: %s' % opts.spider, log.ERROR)
log.msg(format='Unable to find spider: %(spider)s',
level=log.ERROR, spider=opts.spider)
else:
self.spider = create_spider_for_request(self.crawler.spiders, url)
if not self.spider:
log.msg('Unable to find spider for: %s' % request, log.ERROR)
log.msg(format='Unable to find spider for: %(url)s',
level=log.ERROR, url=url)
def start_parsing(self, url, opts):
request = Request(url, opts.callback)
@ -135,8 +138,8 @@ class Command(ScrapyCommand):
self.crawler.start()
if not self.first_response:
log.msg('No response downloaded for: %s' % request, log.ERROR, \
spider=self.spider)
log.msg(format='No response downloaded for: %(request)s',
level=log.ERROR, request=request)
def prepare_request(self, request, opts):
def callback(response):
@ -157,8 +160,8 @@ class Command(ScrapyCommand):
if callable(cb_method):
cb = cb_method
else:
log.msg('Cannot find callback %r in spider: %s' % \
(cb, self.spider.name), level=log.ERROR)
log.msg(format='Cannot find callback %(callback)r in spider: %(spider)s',
callback=callback, spider=self.spider.name, level=log.ERROR)
return
# parse items and requests

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

@ -60,12 +60,13 @@ class RedirectMiddleware(object):
[request.url]
redirected.dont_filter = request.dont_filter
redirected.priority = request.priority + self.priority_adjust
log.msg("Redirecting (%s) to %s from %s" % (reason, redirected, request),
spider=spider, level=log.DEBUG)
log.msg(format="Redirecting (%(reason)s) to %(redirected)s from %(request)s",
level=log.DEBUG, spider=spider, request=request,
redirected=redirected, reason=reason)
return redirected
else:
log.msg("Discarding %s: max redirections reached" % request,
spider=spider, level=log.DEBUG)
log.msg(format="Discarding %(request)s: max redirections reached",
level=log.DEBUG, spider=spider, request=request)
raise IgnoreRequest
def _redirect_request_using_get(self, request, redirect_url):

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

@ -64,14 +64,13 @@ class RetryMiddleware(object):
retries = request.meta.get('retry_times', 0) + 1
if retries <= self.max_retry_times:
log.msg("Retrying %s (failed %d times): %s" % (request, retries, reason),
spider=spider, level=log.DEBUG)
log.msg(format="Retrying %(request)s (failed %(retries)d times): %(reason)s",
level=log.DEBUG, spider=spider, request=request, retries=retries, reason=reason)
retryreq = request.copy()
retryreq.meta['retry_times'] = retries
retryreq.dont_filter = True
retryreq.priority = request.priority + self.priority_adjust
return retryreq
else:
log.msg("Gave up retrying %s (failed %d times): %s" % (request, retries, reason),
spider=spider, level=log.DEBUG)
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)

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

@ -33,7 +33,8 @@ class RobotsTxtMiddleware(object):
useragent = self._useragents[spider]
rp = self.robot_parser(request, spider)
if rp and not rp.can_fetch(useragent, request.url):
log.msg("Forbidden by robots.txt: %s" % request, log.DEBUG)
log.msg(format="Forbidden by robots.txt: %(request)s",
level=log.DEBUG, request=request)
raise IgnoreRequest
def robot_parser(self, request, spider):

7
scrapy/contrib/memusage.py
View File

@ -67,12 +67,14 @@ 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("Memory usage exceeded %dM. Shutting down Scrapy..." % mem, level=log.ERROR)
log.msg(format="Memory usage exceeded %(memusage)dM. Shutting down Scrapy...",
level=log.ERROR, memusage=mem)
if self.notify_mails:
subj = "%s terminated: memory usage exceeded %dM at %s" % \
(self.crawler.settings['BOT_NAME'], mem, socket.gethostname())
self._send_report(self.notify_mails, subj)
self.crawler.stats.set_value('memusage/limit_notified', 1)
open_spiders = self.crawler.engine.open_spiders
if open_spiders:
for spider in open_spiders:
@ -86,7 +88,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("Memory usage reached %dM" % mem, level=log.WARNING)
log.msg(format="Memory usage reached %(memusage)dM",
level=log.WARNING, memusage=mem)
if self.notify_mails:
subj = "%s warning: memory usage reached %dM at %s" % \
(self.crawler.settings['BOT_NAME'], mem, socket.gethostname())

33
scrapy/contrib/pipeline/images.py
View File

@ -177,26 +177,29 @@ class ImagesPipeline(MediaPipeline):
referer = request.headers.get('Referer')
if response.status != 200:
log.msg('Image (code: %s): Error downloading image from %s referred in <%s>' \
% (response.status, request, referer), level=log.WARNING, spider=info.spider)
log.msg(format='Image (code: %(status)s): Error downloading image from %(request)s referred in <%(referer)s>',
level=log.WARNING, spider=info.spider,
status=response.status, request=request, referer=referer)
raise ImageException
if not response.body:
log.msg('Image (empty-content): Empty image from %s referred in <%s>: no-content' \
% (request, referer), level=log.WARNING, spider=info.spider)
log.msg(format='Image (empty-content): Empty image from %(request)s referred in <%(referer)s>: no-content',
level=log.WARNING, spider=info.spider,
request=request, referer=referer)
raise ImageException
status = 'cached' if 'cached' in response.flags else 'downloaded'
msg = 'Image (%s): Downloaded image from %s referred in <%s>' % \
(status, request, referer)
log.msg(msg, level=log.DEBUG, spider=info.spider)
log.msg(format='Image (%(status)s): Downloaded image from %(request)s referred in <%(referer)s>',
level=log.DEBUG, spider=info.spider,
status=status, request=request, referer=referer)
self.inc_stats(info.spider, status)
try:
key = self.image_key(request.url)
checksum = self.image_downloaded(response, request, info)
except ImageException, ex:
log.msg(str(ex), level=log.WARNING, spider=info.spider)
log.err('image_downloaded hook failed',
level=log.WARNING, spider=info.spider)
raise
except Exception:
log.err(spider=info.spider)
@ -207,9 +210,12 @@ class ImagesPipeline(MediaPipeline):
def media_failed(self, failure, request, info):
if not isinstance(failure.value, IgnoreRequest):
referer = request.headers.get('Referer')
msg = 'Image (unknown-error): Error downloading %s from %s referred in <%s>: %s' \
% (self.MEDIA_NAME, request, referer, str(failure))
log.msg(msg, level=log.WARNING, spider=info.spider)
log.msg(format='Image (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)
raise ImageException
def media_to_download(self, request, info):
@ -227,8 +233,9 @@ class ImagesPipeline(MediaPipeline):
return # returning None force download
referer = request.headers.get('Referer')
log.msg('Image (uptodate): Downloaded %s from <%s> referred in <%s>' % \
(self.MEDIA_NAME, request.url, referer), level=log.DEBUG, spider=info.spider)
log.msg(format='Image (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)
self.inc_stats(info.spider, 'uptodate')
checksum = result.get('checksum', None)

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

@ -31,8 +31,9 @@ class DepthMiddleware(object):
if self.prio:
request.priority -= depth * self.prio
if self.maxdepth and depth > self.maxdepth:
log.msg("Ignoring link (depth > %d): %s " % (self.maxdepth, request.url), \
level=log.DEBUG, spider=spider)
log.msg(format="Ignoring link (depth > %(maxdepth)d): %(requrl)s ",
level=log.DEBUG, spider=spider,
maxdepth=self.maxdepth, requrl=request.url)
return False
elif self.stats:
if self.verbose_stats:

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

@ -32,9 +32,9 @@ class OffsiteMiddleware(object):
else:
domain = urlparse_cached(x).hostname
if domain and domain not in self.domains_seen[spider]:
log.msg("Filtered offsite request to %r: %s" % (domain, x),
level=log.DEBUG, spider=spider)
self.domains_seen[spider].add(domain)
log.msg(format="Filtered offsite request to %(domain)r: %(request)s",
level=log.DEBUG, spider=spider, domain=domain, request=x)
else:
yield x

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

@ -23,8 +23,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("Ignoring link (url length > %d): %s " % (self.maxlength, request.url), \
level=log.DEBUG, spider=spider)
log.msg(format="Ignoring link (url length > %(maxlength)d): %(url)s ",
level=log.DEBUG, spider=spider,
maxlength=self.maxlength, url=request.url)
return False
else:
return True

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

@ -31,7 +31,8 @@ class SitemapSpider(BaseSpider):
else:
body = self._get_sitemap_body(response)
if body is None:
log.msg("Ignoring invalid sitemap: %s" % response, log.WARNING)
log.msg(format="Ignoring invalid sitemap: %(response)s",
level=log.WARNING, spider=self, response=response)
return
s = Sitemap(body)

4
scrapy/contrib_exp/downloadermiddleware/decompression.py
View File

@ -75,7 +75,7 @@ class DecompressionMiddleware(object):
for fmt, func in self._formats.iteritems():
new_response = func(response)
if new_response:
log.msg('Decompressed response with format: %s' % \
fmt, log.DEBUG, spider=spider)
log.msg(format='Decompressed response with format: %(responsefmt)s',
level=log.DEBUG, spider=spider, responsefmt=fmt)
return new_response
return response

9
scrapy/core/engine.py
View File

@ -193,8 +193,8 @@ class ExecutionEngine(object):
assert isinstance(response, (Response, Request))
if isinstance(response, Response):
response.request = request # tie request to response received
log.msg(log.formatter.crawled(request, response, spider), \
level=log.DEBUG, spider=spider)
logkws = log.formatter.crawled(request, response, spider)
log.msg(level=log.DEBUG, spider=spider, **logkws)
self.signals.send_catch_log(signal=signals.response_received, \
response=response, request=request, spider=spider)
return response
@ -252,7 +252,8 @@ class ExecutionEngine(object):
slot = self.slots[spider]
if slot.closing:
return slot.closing
log.msg("Closing spider (%s)" % reason, spider=spider)
log.msg(format="Closing spider (%(reason)s)", reason=reason, spider=spider)
log.msg(format='hohohoohoo %(aaa)s', spider=spider, aaa='12')
dfd = slot.close()
@ -269,7 +270,7 @@ class ExecutionEngine(object):
dfd.addBoth(lambda _: self.crawler.stats.close_spider(spider, reason=reason))
dfd.addErrback(log.err, spider=spider)
dfd.addBoth(lambda _: log.msg("Spider closed (%s)" % reason, spider=spider))
dfd.addBoth(lambda _: log.msg(format="Spider closed (%(reason)s)", reason=reason, spider=spider))
dfd.addBoth(lambda _: self.slots.pop(spider))
dfd.addErrback(log.err, spider=spider)

9
scrapy/core/scheduler.py
View File

@ -64,8 +64,9 @@ class Scheduler(object):
self.dqs.push(reqd, -request.priority)
except ValueError, e: # non serializable request
if self.logunser:
log.msg("Unable to serialize request: %s - reason: %s" % \
(request, str(e)), level=log.ERROR, spider=self.spider)
log.msg(format="Unable to serialize request: %(request)s - reason: %(reason)s",
level=log.ERROR, spider=self.spider,
request=request, reason=e)
return
else:
if self.stats:
@ -98,8 +99,8 @@ class Scheduler(object):
prios = ()
q = PriorityQueue(self._newdq, startprios=prios)
if q:
log.msg("Resuming crawl (%d requests scheduled)" % len(q), \
spider=self.spider)
log.msg(format="Resuming crawl (%(queuesize)d requests scheduled)",
spider=self.spider, queuesize=len(q))
return q
def _dqdir(self, jobdir):

19
scrapy/core/scraper.py
View File

@ -174,8 +174,10 @@ class Scraper(object):
elif output is None:
pass
else:
log.msg("Spider must return Request, BaseItem or None, got %r in %s" % \
(type(output).__name__, request), log.ERROR, spider=spider)
typename = type(output).__name__
log.msg(format='Spider must return Request, BaseItem or None, '
'got %(typename)r in %(request)s',
level=log.ERROR, spider=spider, request=request, typename=typename)
def _log_download_errors(self, spider_failure, download_failure, request, spider):
"""Log and silence errors that come from the engine (typically download
@ -185,7 +187,8 @@ class Scraper(object):
errmsg = spider_failure.getErrorMessage()
spider_failure.printTraceback()
if errmsg:
log.msg("Error downloading %s: %s" % (request, errmsg), log.ERROR, spider=spider)
log.msg(format='Error downloading %(request)s: %(errmsg)s',
level=log.ERROR, spider=spider, request=request, errmsg=errmsg)
return
return spider_failure
@ -196,15 +199,15 @@ class Scraper(object):
if isinstance(output, Failure):
ex = output.value
if isinstance(ex, DropItem):
log.msg(log.formatter.dropped(item, ex, response, spider), \
level=log.WARNING, spider=spider)
logkws = log.formatter.dropped(item, ex, response, spider)
log.msg(level=log.WARNING, spider=spider, **logkws)
return self.signals.send_catch_log_deferred(signal=signals.item_dropped, \
item=item, spider=spider, exception=output.value)
else:
log.err(output, 'Error processing %s' % item, spider=spider)
log.err(output, 'Error processing %(item)s', item=item, spider=spider)
else:
log.msg(log.formatter.scraped(output, response, spider), \
log.DEBUG, spider=spider)
logkws = log.formatter.scraped(output, response, spider)
log.msg(level=log.DEBUG, spider=spider, **logkws)
return self.signals.send_catch_log_deferred(signal=signals.item_scraped, \
item=output, response=response, spider=spider)

8
scrapy/crawler.py
View File

@ -91,13 +91,13 @@ class CrawlerProcess(Crawler):
def _signal_shutdown(self, signum, _):
install_shutdown_handlers(self._signal_kill)
signame = signal_names[signum]
log.msg("Received %s, shutting down gracefully. Send again to force " \
"unclean shutdown" % signame, level=log.INFO)
log.msg(format="Received %(signame)s, shutting down gracefully. Send again to force ",
level=log.INFO, signame=signame)
reactor.callFromThread(self.stop)
def _signal_kill(self, signum, _):
install_shutdown_handlers(signal.SIG_IGN)
signame = signal_names[signum]
log.msg('Received %s twice, forcing unclean shutdown' % signame, \
level=log.INFO)
log.msg(format='Received %(signame)s twice, forcing unclean shutdown',
level=log.INFO, signame=signame)
reactor.callFromThread(self._stop_reactor)

30
scrapy/log.py
View File

@ -56,28 +56,41 @@ def _adapt_eventdict(eventDict, log_level=INFO, encoding='utf-8', prepend_level=
ev = eventDict.copy()
if ev['isError']:
ev.setdefault('logLevel', ERROR)
# ignore non-error messages from outside scrapy
if ev.get('system') != 'scrapy' and not ev['isError']:
return
level = ev.get('logLevel')
if level < log_level:
return
spider = ev.get('spider')
if spider:
ev['system'] = spider.name
message = ev.get('message')
lvlname = level_names.get(level, 'NOLEVEL')
message = ev.get('message')
if message:
message = [unicode_to_str(x, encoding) for x in message]
if prepend_level:
message[0] = "%s: %s" % (lvlname, message[0])
ev['message'] = message
ev['message'] = message
why = ev.get('why')
if why:
why = unicode_to_str(why, encoding)
if prepend_level:
why = "%s: %s" % (lvlname, why)
ev['why'] = why
ev['why'] = why
fmt = ev.get('format')
if fmt:
fmt = unicode_to_str(fmt, encoding)
if prepend_level:
fmt = "%s: %s" % (lvlname, fmt)
ev['format'] = fmt
return ev
def _get_log_level(level_name_or_id=None):
@ -111,14 +124,17 @@ def start(logfile=None, loglevel=None, logstdout=None):
msg("Scrapy %s started (bot: %s)" % (scrapy.__version__, \
settings['BOT_NAME']))
def msg(message, level=INFO, **kw):
def msg(message=None, _level=INFO, **kw):
kw['logLevel'] = kw.pop('level', _level)
kw.setdefault('system', 'scrapy')
kw['logLevel'] = level
log.msg(message, **kw)
if message is None:
log.msg(**kw)
else:
log.msg(message, **kw)
def err(_stuff=None, _why=None, **kw):
kw.setdefault('system', 'scrapy')
kw['logLevel'] = kw.pop('level', ERROR)
kw.setdefault('system', 'scrapy')
log.err(_stuff, _why, **kw)
formatter = load_object(settings['LOG_FORMATTER'])()

27
scrapy/logformatter.py
View File

@ -2,6 +2,11 @@ import os
from twisted.python.failure import Failure
SCRAPEDFMT = u"Scraped from %(src)s" + os.linesep + "%(item)s"
DROPPEDFMT = u"Dropped: %(exception)s" + os.linesep + "%(item)s"
CRAWLEDFMT = u"Crawled (%(status)s) %(request)s (referer: %(referer)s)%(flags)s"
class LogFormatter(object):
"""Class for generating log messages for different actions. All methods
must return a plain string which doesn't include the log level or the
@ -9,14 +14,26 @@ class LogFormatter(object):
"""
def crawled(self, request, response, spider):
referer = request.headers.get('Referer')
flags = ' %s' % str(response.flags) if response.flags else ''
return u"Crawled (%d) %s (referer: %s)%s" % (response.status, \
request, referer, flags)
return {
'format': CRAWLEDFMT,
'status': response.status,
'request': request,
'referer': request.headers.get('Referer'),
'flags': flags,
}
def scraped(self, item, response, spider):
src = response.getErrorMessage() if isinstance(response, Failure) else response
return u"Scraped from %s%s%s" % (src, os.linesep, item)
return {
'format': SCRAPEDFMT,
'src': src,
'item': item,
}
def dropped(self, item, exception, response, spider):
return u"Dropped: %s%s%s" % (exception, os.linesep, item)
return {
'format': DROPPEDFMT,
'exception': exception,
'item': item,
}

16
scrapy/mail.py
View File

@ -70,8 +70,8 @@ class MailSender(object):
cc=cc, attach=attachs, msg=msg)
if self.debug:
log.msg('Debug mail sent OK: To=%s Cc=%s Subject="%s" Attachs=%d' % \
(to, cc, subject, len(attachs)), level=log.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))
return
dfd = self._sendmail(rcpts, msg.as_string())
@ -82,13 +82,17 @@ class MailSender(object):
return dfd
def _sent_ok(self, result, to, cc, subject, nattachs):
log.msg('Mail sent OK: To=%s Cc=%s Subject="%s" Attachs=%d' % \
(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)
def _sent_failed(self, failure, to, cc, subject, nattachs):
errstr = str(failure.value)
log.msg('Unable to send mail: To=%s Cc=%s Subject="%s" Attachs=%d - %s' % \
(to, cc, subject, nattachs, errstr), level=log.ERROR)
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)
def _sendmail(self, to_addrs, msg):
msg = StringIO(msg)

8
scrapy/middleware.py
View File

@ -37,10 +37,12 @@ class MiddlewareManager(object):
except NotConfigured, e:
if e.args:
clsname = clspath.split('.')[-1]
log.msg("Disabled %s: %s" % (clsname, e.args[0]), log.WARNING)
log.msg(format="Disabled %(clsname)s: %(eargs)s",
level=log.WARNING, clsname=clsname, eargs=e.args[0])
enabled = [x.__class__.__name__ for x in middlewares]
log.msg("Enabled %ss: %s" % (cls.component_name, ", ".join(enabled)), \
level=log.DEBUG)
log.msg(format="Enabled %(componentname)ss: %(enabledlist)s", level=log.DEBUG,
componentname=cls.component_name, enabledlist=', '.join(enabled))
return cls(*middlewares)
@classmethod

3
scrapy/telnet.py
View File

@ -46,7 +46,8 @@ class TelnetConsole(protocol.ServerFactory):
def start_listening(self):
self.port = listen_tcp(self.portrange, self.host, self)
h = self.port.getHost()
log.msg("Telnet console listening on %s:%d" % (h.host, h.port), log.DEBUG)
log.msg(format="Telnet console listening on %(host)s:%(port)d",
level=log.DEBUG, host=h.host, port=h.port)
def stop_listening(self):
self.port.stopListening()

27
scrapy/tests/test_commands.py
View File

@ -1,6 +1,7 @@
import sys
import os
import sys
import subprocess
from time import sleep
from os.path import exists, join, abspath
from shutil import rmtree
from tempfile import mkdtemp
@ -32,8 +33,20 @@ class ProjectTest(unittest.TestCase):
def proc(self, *new_args, **kwargs):
args = (sys.executable, '-m', 'scrapy.cmdline') + new_args
return subprocess.Popen(args, stdout=subprocess.PIPE, stderr=subprocess.PIPE, \
cwd=self.cwd, env=self.env, **kwargs)
p = subprocess.Popen(args, cwd=self.cwd, env=self.env,
stdout=subprocess.PIPE, stderr=subprocess.PIPE,
**kwargs)
waited = 0
interval = 0.2
while p.poll() is None:
sleep(interval)
waited += interval
if waited > 5:
p.kill()
assert False, 'Command took too much time to complete'
return p
class StartprojectTest(ProjectTest):
@ -125,10 +138,10 @@ class MySpider(BaseSpider):
""")
p = self.proc('runspider', fname)
log = p.stderr.read()
self.assert_("[myspider] DEBUG: It Works!" in log)
self.assert_("[myspider] INFO: Spider opened" in log)
self.assert_("[myspider] INFO: Closing spider (finished)" in log)
self.assert_("[myspider] INFO: Spider closed (finished)" in log)
self.assert_("[myspider] DEBUG: It Works!" in log, log)
self.assert_("[myspider] INFO: Spider opened" in log, log)
self.assert_("[myspider] INFO: Closing spider (finished)" in log, log)
self.assert_("[myspider] INFO: Spider closed (finished)" in log, log)
def test_runspider_no_spider_found(self):
tmpdir = self.mktemp()

16
scrapy/tests/test_logformatter.py
View File

@ -23,19 +23,25 @@ class LoggingContribTest(unittest.TestCase):
def test_crawled(self):
req = Request("http://www.example.com")
res = Response("http://www.example.com")
self.assertEqual(self.formatter.crawled(req, res, self.spider),
logkws = self.formatter.crawled(req, res, self.spider)
logline = logkws['format'] % logkws
self.assertEqual(logline,
"Crawled (200) <GET http://www.example.com> (referer: None)")
req = Request("http://www.example.com", headers={'referer': 'http://example.com'})
res = Response("http://www.example.com", flags=['cached'])
self.assertEqual(self.formatter.crawled(req, res, self.spider),
logkws = self.formatter.crawled(req, res, self.spider)
logline = logkws['format'] % logkws
self.assertEqual(logline,
"Crawled (200) <GET http://www.example.com> (referer: http://example.com) ['cached']")
def test_dropped(self):
item = {}
exception = Exception(u"\u2018")
response = Response("http://www.example.com")
lines = self.formatter.dropped(item, exception, response, self.spider).splitlines()
logkws = self.formatter.dropped(item, exception, response, self.spider)
logline = logkws['format'] % logkws
lines = logline.splitlines()
assert all(isinstance(x, unicode) for x in lines)
self.assertEqual(lines, [u"Dropped: \u2018", '{}'])
@ -43,7 +49,9 @@ class LoggingContribTest(unittest.TestCase):
item = CustomItem()
item['name'] = u'\xa3'
response = Response("http://www.example.com")
lines = self.formatter.scraped(item, response, self.spider).splitlines()
logkws = self.formatter.scraped(item, response, self.spider)
logline = logkws['format'] % logkws
lines = logline.splitlines()
assert all(isinstance(x, unicode) for x in lines)
self.assertEqual(lines, [u"Scraped from <200 http://www.example.com>", u'name: \xa3'])

3
scrapy/utils/iterators.py
View File

@ -61,7 +61,8 @@ def csviter(obj, delimiter=None, headers=None, encoding=None):
while True:
row = _getrow(csv_r)
if len(row) != len(headers):
log.msg("ignoring row %d (length: %d, should be: %d)" % (csv_r.line_num, len(row), len(headers)), log.WARNING)
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))
continue
else:
yield dict(zip(headers, row))

4
scrapy/utils/signal.py
View File

@ -21,8 +21,8 @@ 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("Cannot return deferreds from signal handler: %s" % \
receiver, log.ERROR, spider=spider)
log.msg(format="Cannot return deferreds from signal handler: %(receiver)s",
level=log.ERROR, spider=spider, receiver=receiver)
except dont_log:
result = Failure()
except Exception:

10
scrapy/utils/spider.py
View File

@ -38,10 +38,14 @@ def create_spider_for_request(spidermanager, request, default_spider=None, \
snames = spidermanager.find_by_request(request)
if len(snames) == 1:
return spidermanager.create(snames[0], **spider_kwargs)
if len(snames) > 1 and log_multiple:
log.msg('More than one spider can handle: %s - %s' % \
(request, ", ".join(snames)), log.ERROR)
log.msg(format='More than one spider can handle: %(request)s - %(snames)s',
level=log.ERROR, request=request, snames=', '.join(snames))
if len(snames) == 0 and log_none:
log.msg('Unable to find spider that handles: %s' % request, log.ERROR)
log.msg(format='Unable to find spider that handles: %(request)s',
level=log.ERROR, request=request)
return default_spider

3
scrapy/webservice.py
View File

@ -89,7 +89,8 @@ class WebService(server.Site):
def start_listening(self):
self.port = listen_tcp(self.portrange, self.host, self)
h = self.port.getHost()
log.msg("Web service listening on %s:%d" % (h.host, h.port), log.DEBUG)
log.msg(format='Web service listening on %(host)s:%(port)d',
level=log.DEBUG, host=h.host, port=h.port)
def stop_listening(self):
self.port.stopListening()

3
scrapyd/app.py
View File

@ -35,7 +35,8 @@ def application(config):
timer = TimerService(5, poller.poll)
webservice = TCPServer(http_port, server.Site(Root(config, app)), interface=bind_address)
log.msg("Scrapyd web console available at http://%s:%s/" % (bind_address, http_port))
log.msg(format="Scrapyd web console available at http://%(bind_address)s:%(http_port)s/",
bind_address=bind_address, http_port=http_port)
launcher.setServiceParent(app)
timer.setServiceParent(app)

11
scrapyd/launcher.py
View File

@ -25,8 +25,9 @@ class Launcher(Service):
def startService(self):
for slot in range(self.max_proc):
self._wait_for_project(slot)
log.msg("%s started: max_proc=%r, runner=%r" % (self.parent.name, \
self.max_proc, self.runner), system="Launcher")
log.msg(format='%(parent)s started: max_proc=%(max_proc)r, runner=%(runner)r',
parent=self.parent.name, max_proc=self.max_proc,
runner=self.runner, system='Launcher')
def _wait_for_project(self, slot):
poller = self.app.getComponent(IPoller)
@ -96,6 +97,6 @@ class ScrapyProcessProtocol(protocol.ProcessProtocol):
self.deferred.callback(self)
def log(self, msg):
msg += "project=%r spider=%r job=%r pid=%r log=%r items=%r" % (self.project, \
self.spider, self.job, self.pid, self.logfile, self.itemsfile)
log.msg(msg, system="Launcher")
fmt = 'project=%(project)r spider=%(spider)r job=%(job)r pid=%(pid)r log=%(log)r items=%(items)r'
log.msg(format=fmt, project=self.project, spider=self.spider,
job=self.job, pid=self.pid, log=self.logfile, items=self.itemsfile)