From dcef7b03c17bd395defddab27fa66778e4051c18 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Daniel=20Gra=C3=B1a?= <dangra@gmail.com>
Date: Thu, 9 Aug 2012 16:55:05 -0300
Subject: [PATCH 1/2] format log lines lazily in case they are dropped by
 loglevels

---
 scrapy/commands/parse.py                      | 19 ++++++-----
 .../contrib/downloadermiddleware/redirect.py  |  9 ++---
 scrapy/contrib/downloadermiddleware/retry.py  |  9 +++--
 .../contrib/downloadermiddleware/robotstxt.py |  3 +-
 scrapy/contrib/memusage.py                    |  7 ++--
 scrapy/contrib/pipeline/images.py             | 33 +++++++++++--------
 scrapy/contrib/spidermiddleware/depth.py      |  5 +--
 scrapy/contrib/spidermiddleware/offsite.py    |  4 +--
 scrapy/contrib/spidermiddleware/urllength.py  |  5 +--
 scrapy/contrib/spiders/sitemap.py             |  3 +-
 .../downloadermiddleware/decompression.py     |  4 +--
 scrapy/core/engine.py                         |  9 ++---
 scrapy/core/scheduler.py                      |  9 ++---
 scrapy/core/scraper.py                        | 19 ++++++-----
 scrapy/crawler.py                             |  8 ++---
 scrapy/log.py                                 | 30 +++++++++++++----
 scrapy/logformatter.py                        | 27 ++++++++++++---
 scrapy/mail.py                                | 16 +++++----
 scrapy/middleware.py                          |  8 +++--
 scrapy/telnet.py                              |  3 +-
 scrapy/tests/test_commands.py                 | 27 +++++++++++----
 scrapy/tests/test_logformatter.py             | 16 ++++++---
 scrapy/utils/iterators.py                     |  3 +-
 scrapy/utils/signal.py                        |  4 +--
 scrapy/utils/spider.py                        | 10 ++++--
 scrapy/webservice.py                          |  3 +-
 scrapyd/app.py                                |  3 +-
 scrapyd/launcher.py                           | 11 ++++---
 28 files changed, 199 insertions(+), 108 deletions(-)

diff --git a/scrapy/commands/parse.py b/scrapy/commands/parse.py
index a1b7849f1..3be80db9b 100644
--- a/scrapy/commands/parse.py
+++ b/scrapy/commands/parse.py
@@ -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
diff --git a/scrapy/contrib/downloadermiddleware/redirect.py b/scrapy/contrib/downloadermiddleware/redirect.py
index ea1247532..1247c018d 100644
--- a/scrapy/contrib/downloadermiddleware/redirect.py
+++ b/scrapy/contrib/downloadermiddleware/redirect.py
@@ -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):
diff --git a/scrapy/contrib/downloadermiddleware/retry.py b/scrapy/contrib/downloadermiddleware/retry.py
index 38dc5988b..9f41197c4 100644
--- a/scrapy/contrib/downloadermiddleware/retry.py
+++ b/scrapy/contrib/downloadermiddleware/retry.py
@@ -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)
diff --git a/scrapy/contrib/downloadermiddleware/robotstxt.py b/scrapy/contrib/downloadermiddleware/robotstxt.py
index 8e9feda81..f0dfd3fef 100644
--- a/scrapy/contrib/downloadermiddleware/robotstxt.py
+++ b/scrapy/contrib/downloadermiddleware/robotstxt.py
@@ -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):
diff --git a/scrapy/contrib/memusage.py b/scrapy/contrib/memusage.py
index 6388c42af..191bacb73 100644
--- a/scrapy/contrib/memusage.py
+++ b/scrapy/contrib/memusage.py
@@ -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())
diff --git a/scrapy/contrib/pipeline/images.py b/scrapy/contrib/pipeline/images.py
index 90ab80c7e..fa4125520 100644
--- a/scrapy/contrib/pipeline/images.py
+++ b/scrapy/contrib/pipeline/images.py
@@ -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)
diff --git a/scrapy/contrib/spidermiddleware/depth.py b/scrapy/contrib/spidermiddleware/depth.py
index 2a218f990..15780685f 100644
--- a/scrapy/contrib/spidermiddleware/depth.py
+++ b/scrapy/contrib/spidermiddleware/depth.py
@@ -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:
diff --git a/scrapy/contrib/spidermiddleware/offsite.py b/scrapy/contrib/spidermiddleware/offsite.py
index 2010ca571..a32672a99 100644
--- a/scrapy/contrib/spidermiddleware/offsite.py
+++ b/scrapy/contrib/spidermiddleware/offsite.py
@@ -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
 
diff --git a/scrapy/contrib/spidermiddleware/urllength.py b/scrapy/contrib/spidermiddleware/urllength.py
index dcc0d90be..fa6f2c909 100644
--- a/scrapy/contrib/spidermiddleware/urllength.py
+++ b/scrapy/contrib/spidermiddleware/urllength.py
@@ -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
diff --git a/scrapy/contrib/spiders/sitemap.py b/scrapy/contrib/spiders/sitemap.py
index f96367905..4fc19e108 100644
--- a/scrapy/contrib/spiders/sitemap.py
+++ b/scrapy/contrib/spiders/sitemap.py
@@ -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)
diff --git a/scrapy/contrib_exp/downloadermiddleware/decompression.py b/scrapy/contrib_exp/downloadermiddleware/decompression.py
index 397c9e093..d18d51eb5 100644
--- a/scrapy/contrib_exp/downloadermiddleware/decompression.py
+++ b/scrapy/contrib_exp/downloadermiddleware/decompression.py
@@ -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
diff --git a/scrapy/core/engine.py b/scrapy/core/engine.py
index 3bb6fe19a..7258a7ee0 100644
--- a/scrapy/core/engine.py
+++ b/scrapy/core/engine.py
@@ -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)
diff --git a/scrapy/core/scheduler.py b/scrapy/core/scheduler.py
index f65fe03cb..bd4cc931f 100644
--- a/scrapy/core/scheduler.py
+++ b/scrapy/core/scheduler.py
@@ -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):
diff --git a/scrapy/core/scraper.py b/scrapy/core/scraper.py
index 97bdef81e..63dfebbc2 100644
--- a/scrapy/core/scraper.py
+++ b/scrapy/core/scraper.py
@@ -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)
 
diff --git a/scrapy/crawler.py b/scrapy/crawler.py
index 77122c743..ce6243e72 100644
--- a/scrapy/crawler.py
+++ b/scrapy/crawler.py
@@ -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)
diff --git a/scrapy/log.py b/scrapy/log.py
index ebd1ac7ec..3b3f01fa3 100644
--- a/scrapy/log.py
+++ b/scrapy/log.py
@@ -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'])()
diff --git a/scrapy/logformatter.py b/scrapy/logformatter.py
index fdbd8def9..1e584e413 100644
--- a/scrapy/logformatter.py
+++ b/scrapy/logformatter.py
@@ -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,
+        }
diff --git a/scrapy/mail.py b/scrapy/mail.py
index db5193721..d65def22d 100644
--- a/scrapy/mail.py
+++ b/scrapy/mail.py
@@ -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)
diff --git a/scrapy/middleware.py b/scrapy/middleware.py
index 031d27846..dd511638b 100644
--- a/scrapy/middleware.py
+++ b/scrapy/middleware.py
@@ -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
diff --git a/scrapy/telnet.py b/scrapy/telnet.py
index 474c504af..0ee4e6c43 100644
--- a/scrapy/telnet.py
+++ b/scrapy/telnet.py
@@ -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()
diff --git a/scrapy/tests/test_commands.py b/scrapy/tests/test_commands.py
index e3448e934..24fa072cc 100644
--- a/scrapy/tests/test_commands.py
+++ b/scrapy/tests/test_commands.py
@@ -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()
diff --git a/scrapy/tests/test_logformatter.py b/scrapy/tests/test_logformatter.py
index 77a8f732a..d4097aff5 100644
--- a/scrapy/tests/test_logformatter.py
+++ b/scrapy/tests/test_logformatter.py
@@ -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'])
 
diff --git a/scrapy/utils/iterators.py b/scrapy/utils/iterators.py
index 3b078c25a..327b9e024 100644
--- a/scrapy/utils/iterators.py
+++ b/scrapy/utils/iterators.py
@@ -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))
diff --git a/scrapy/utils/signal.py b/scrapy/utils/signal.py
index 5496b7041..724f3a892 100644
--- a/scrapy/utils/signal.py
+++ b/scrapy/utils/signal.py
@@ -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:
diff --git a/scrapy/utils/spider.py b/scrapy/utils/spider.py
index db321dd85..5a9a419a7 100644
--- a/scrapy/utils/spider.py
+++ b/scrapy/utils/spider.py
@@ -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
 
diff --git a/scrapy/webservice.py b/scrapy/webservice.py
index 889dce5ad..43784c345 100644
--- a/scrapy/webservice.py
+++ b/scrapy/webservice.py
@@ -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()
diff --git a/scrapyd/app.py b/scrapyd/app.py
index a6c7b558f..cb2e8da3b 100644
--- a/scrapyd/app.py
+++ b/scrapyd/app.py
@@ -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)
diff --git a/scrapyd/launcher.py b/scrapyd/launcher.py
index a283ba5c7..7d4b3883a 100644
--- a/scrapyd/launcher.py
+++ b/scrapyd/launcher.py
@@ -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)

From a2d22307adb3c04dd1ba972a83525cc97131ce32 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Daniel=20Gra=C3=B1a?= <dangra@gmail.com>
Date: Fri, 31 Aug 2012 17:33:44 -0300
Subject: [PATCH 2/2] update news.rst

---
 docs/news.rst | 1 +
 1 file changed, 1 insertion(+)

diff --git a/docs/news.rst b/docs/news.rst
index 5ca1b71c1..c3546fe1d 100644
--- a/docs/news.rst
+++ b/docs/news.rst
@@ -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.