Repository: scrapy/scrapy
Pull request #3588 (2019-01-18 13:42:51)

[MRG+1] Adding requests referer to RFPDupeFilter log messages
I just changed the log message when DUPEFILTER_DEBUG is active because it helps knowing which request is generating the duplicates (I'd this problem recently).

Also, I added some tests for the log method to check the proper messages and stats.


Patch:
diff --git a/scrapy/dupefilters.py b/scrapy/dupefilters.py
index 9d8966b9c..0bcdd3495 100644
--- a/scrapy/dupefilters.py
+++ b/scrapy/dupefilters.py
@@ -3,8 +3,7 @@ import os
 import logging
 
 from scrapy.utils.job import job_dir
-from scrapy.utils.request import request_fingerprint
-
+from scrapy.utils.request import referer_str, request_fingerprint
 
 class BaseDupeFilter(object):
 
@@ -61,8 +60,9 @@ class RFPDupeFilter(BaseDupeFilter):
 
     def log(self, request, spider):
         if self.debug:
-            msg = "Filtered duplicate request: %(request)s"
-            self.logger.debug(msg, {'request': request}, extra={'spider': spider})
+            msg = "Filtered duplicate request: %(request)s (referer: %(referer)s)"
+            args = {'request': request, 'referer': referer_str(request) }
+            self.logger.debug(msg, args, extra={'spider': spider})
         elif self.logdupes:
             msg = ("Filtered duplicate request: %(request)s"
                    " - no more duplicates will be shown"


Test patch:
diff --git a/tests/test_dupefilters.py b/tests/test_dupefilters.py
index db69597a2..d7eb98c97 100644
--- a/tests/test_dupefilters.py
+++ b/tests/test_dupefilters.py
@@ -2,6 +2,7 @@ import hashlib
 import tempfile
 import unittest
 import shutil
+from testfixtures import LogCapture
 
 from scrapy.dupefilters import RFPDupeFilter
 from scrapy.http import Request
@@ -9,7 +10,7 @@ from scrapy.core.scheduler import Scheduler
 from scrapy.utils.python import to_bytes
 from scrapy.utils.job import job_dir
 from scrapy.utils.test import get_crawler
-
+from tests.spiders import SimpleSpider
 
 class FromCrawlerRFPDupeFilter(RFPDupeFilter):
 
@@ -126,3 +127,57 @@ class RFPDupeFilterTest(unittest.TestCase):
         assert case_insensitive_dupefilter.request_seen(r2)
 
         case_insensitive_dupefilter.close('finished')
+
+    def test_log(self):
+        with LogCapture() as l:
+            settings = {'DUPEFILTER_DEBUG': False,
+                        'DUPEFILTER_CLASS': __name__  + '.FromCrawlerRFPDupeFilter'}
+            crawler = get_crawler(SimpleSpider, settings_dict=settings)
+            scheduler = Scheduler.from_crawler(crawler)
+            spider = SimpleSpider.from_crawler(crawler)
+
+            dupefilter = scheduler.df
+            dupefilter.open()
+
+            r1 = Request('http://scrapytest.org/index.html')
+            r2 = Request('http://scrapytest.org/index.html')
+            
+            dupefilter.log(r1, spider)
+            dupefilter.log(r2, spider)
+
+            assert crawler.stats.get_value('dupefilter/filtered') == 2
+            l.check_present(('scrapy.dupefilters', 'DEBUG', 
+                ('Filtered duplicate request: <GET http://scrapytest.org/index.html>'
+                ' - no more duplicates will be shown'
+                ' (see DUPEFILTER_DEBUG to show all duplicates)')))
+
+            dupefilter.close('finished')
+
+    def test_log_debug(self):
+        with LogCapture() as l:
+            settings = {'DUPEFILTER_DEBUG': True,
+                        'DUPEFILTER_CLASS': __name__  + '.FromCrawlerRFPDupeFilter'}
+            crawler = get_crawler(SimpleSpider, settings_dict=settings)
+            scheduler = Scheduler.from_crawler(crawler)
+            spider = SimpleSpider.from_crawler(crawler)
+
+            dupefilter = scheduler.df
+            dupefilter.open()
+
+            r1 = Request('http://scrapytest.org/index.html')
+            r2 = Request('http://scrapytest.org/index.html',
+                headers={'Referer': 'http://scrapytest.org/INDEX.html'}
+            )
+            
+            dupefilter.log(r1, spider)
+            dupefilter.log(r2, spider)
+
+            assert crawler.stats.get_value('dupefilter/filtered') == 2
+            l.check_present(('scrapy.dupefilters', 'DEBUG',
+                ('Filtered duplicate request: <GET http://scrapytest.org/index.html>'
+                ' (referer: None)')))
+            l.check_present(('scrapy.dupefilters', 'DEBUG',
+                ('Filtered duplicate request: <GET http://scrapytest.org/index.html>'
+                ' (referer: http://scrapytest.org/INDEX.html)')))
+
+            dupefilter.close('finished')