From a75ad2bbc63e2fd351c43069a034461c1ab673cf Mon Sep 17 00:00:00 2001 From: Akhil Lb Date: Wed, 4 Nov 2015 01:59:57 +0530 Subject: [PATCH 1/7] LOG_SHORT_NAMES option --- docs/topics/logging.rst | 5 +++++ docs/topics/settings.rst | 10 ++++++++++ scrapy/settings/default_settings.py | 1 + scrapy/utils/log.py | 3 ++- 4 files changed, 18 insertions(+), 1 deletion(-) diff --git a/docs/topics/logging.rst b/docs/topics/logging.rst index b7aa6d985..231f5186b 100644 --- a/docs/topics/logging.rst +++ b/docs/topics/logging.rst @@ -150,6 +150,7 @@ These settings can be used to configure the logging: * :setting:`LOG_FORMAT` * :setting:`LOG_DATEFORMAT` * :setting:`LOG_STDOUT` +* :setting:`LOG_SHORT_NAMES` The first couple of settings define a destination for log messages. If :setting:`LOG_FILE` is set, messages sent through the root logger will be @@ -170,6 +171,10 @@ listed in `logging's logrecord attributes docs `_ respectively. +If :setting:`LOG_SHORT_NAMES` is set, then the logs will not display the scrapy +component that prints the log. It is unset by default, hence logs contain the +scrapy component responsible for that log output. + Command-line options -------------------- diff --git a/docs/topics/settings.rst b/docs/topics/settings.rst index a17472564..c528987ec 100644 --- a/docs/topics/settings.rst +++ b/docs/topics/settings.rst @@ -788,6 +788,16 @@ If ``True``, all standard output (and error) of your process will be redirected to the log. For example if you ``print 'hello'`` it will appear in the Scrapy log. +.. setting:: LOG_SHORT_NAMES + +LOG_SHORT_NAMES +____________ + +Default: ``False`` + +If ``True``, the logs will just contain the root path. If it is set to ``False`` +then it displays the component responsible for the log output + .. setting:: MEMDEBUG_ENABLED MEMDEBUG_ENABLED diff --git a/scrapy/settings/default_settings.py b/scrapy/settings/default_settings.py index 61f4bd567..24714a7a8 100644 --- a/scrapy/settings/default_settings.py +++ b/scrapy/settings/default_settings.py @@ -191,6 +191,7 @@ LOG_DATEFORMAT = '%Y-%m-%d %H:%M:%S' LOG_STDOUT = False LOG_LEVEL = 'DEBUG' LOG_FILE = None +LOG_SHORT_NAMES = False SCHEDULER_DEBUG = False diff --git a/scrapy/utils/log.py b/scrapy/utils/log.py index 51f303216..f33ce7017 100644 --- a/scrapy/utils/log.py +++ b/scrapy/utils/log.py @@ -118,7 +118,8 @@ def _get_handler(settings): ) handler.setFormatter(formatter) handler.setLevel(settings.get('LOG_LEVEL')) - handler.addFilter(TopLevelFormatter(['scrapy'])) + if settings.getbool('LOG_SHORT_NAMES'): + handler.addFilter(TopLevelFormatter(['scrapy'])) return handler From 05cec0f2f348345e3d32242968450fb523d25dff Mon Sep 17 00:00:00 2001 From: Mikhail Korobov Date: Wed, 27 Jan 2016 15:21:05 +0500 Subject: [PATCH 2/7] fixed ReST syntax --- docs/topics/settings.rst | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/topics/settings.rst b/docs/topics/settings.rst index c528987ec..503f4afb1 100644 --- a/docs/topics/settings.rst +++ b/docs/topics/settings.rst @@ -791,7 +791,7 @@ log. .. setting:: LOG_SHORT_NAMES LOG_SHORT_NAMES -____________ +--------------- Default: ``False`` From 6eab59cbac6a35e7d92a7391541ad2f16493338b Mon Sep 17 00:00:00 2001 From: Mikhail Korobov Date: Fri, 9 Dec 2016 02:14:12 +0500 Subject: [PATCH 3/7] TST cleanup runspider tests --- tests/test_commands.py | 47 +++++++++++++++++++++--------------------- 1 file changed, 24 insertions(+), 23 deletions(-) diff --git a/tests/test_commands.py b/tests/test_commands.py index b507c46bc..bcd7215a0 100644 --- a/tests/test_commands.py +++ b/tests/test_commands.py @@ -38,11 +38,11 @@ class ProjectTest(unittest.TestCase): return subprocess.call(args, stdout=out, stderr=out, cwd=self.cwd, env=self.env, **kwargs) - def proc(self, *new_args, **kwargs): + def proc(self, *new_args, **popen_kwargs): args = (sys.executable, '-m', 'scrapy.cmdline') + new_args p = subprocess.Popen(args, cwd=self.cwd, env=self.env, stdout=subprocess.PIPE, stderr=subprocess.PIPE, - **kwargs) + **popen_kwargs) waited = 0 interval = 0.2 @@ -182,6 +182,17 @@ class MiscCommandsTest(CommandTest): class RunSpiderCommandTest(CommandTest): + debug_log_spider = """ +import scrapy + +class MySpider(scrapy.Spider): + name = 'myspider' + + def start_requests(self): + self.logger.debug("It Works!") + return [] +""" + @contextmanager def _create_file(self, content, name): tmpdir = self.mktemp() @@ -194,32 +205,23 @@ class RunSpiderCommandTest(CommandTest): finally: rmtree(tmpdir) - def runspider(self, code, name='myspider.py'): + def runspider(self, code, name='myspider.py', args=()): with self._create_file(code, name) as fname: - return self.proc('runspider', fname) + return self.proc('runspider', fname, *args) + + def get_log(self, code, name='myspider.py', args=()): + p = self.runspider(code, name=name, args=args) + return to_native_str(p.stderr.read()) def test_runspider(self): - spider = """ -import scrapy - -class MySpider(scrapy.Spider): - name = 'myspider' - - def start_requests(self): - self.logger.debug("It Works!") - return [] -""" - p = self.runspider(spider) - log = to_native_str(p.stderr.read()) - + log = self.get_log(self.debug_log_spider) 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): - p = self.runspider("from scrapy.spiders import Spider\n") - log = to_native_str(p.stderr.read()) + log = self.get_log("from scrapy.spiders import Spider\n") self.assertIn("No spider found in file", log) def test_runspider_file_not_found(self): @@ -228,12 +230,11 @@ class MySpider(scrapy.Spider): self.assertIn("File not found: some_non_existent_file", log) def test_runspider_unable_to_load(self): - p = self.runspider('', 'myspider.txt') - log = to_native_str(p.stderr.read()) + log = self.get_log('', name='myspider.txt') self.assertIn('Unable to load', log) def test_start_requests_errors(self): - p = self.runspider(""" + log = self.get_log(""" import scrapy class BadSpider(scrapy.Spider): @@ -241,11 +242,11 @@ class BadSpider(scrapy.Spider): def start_requests(self): raise Exception("oops!") """, name="badspider.py") - log = to_native_str(p.stderr.read()) print(log) self.assertIn("start_requests", log) self.assertIn("badspider.py", log) + class BenchCommandTest(CommandTest): def test_run(self): From e46572d6f2de1533b1df2ab206971351c22bbbbe Mon Sep 17 00:00:00 2001 From: Mikhail Korobov Date: Fri, 9 Dec 2016 02:19:33 +0500 Subject: [PATCH 4/7] TST end-to-end test for LOG_LEVEL option there were no end-to-end tests for this option --- tests/test_commands.py | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/tests/test_commands.py b/tests/test_commands.py index bcd7215a0..1dd88f342 100644 --- a/tests/test_commands.py +++ b/tests/test_commands.py @@ -220,6 +220,12 @@ class MySpider(scrapy.Spider): self.assertIn("INFO: Closing spider (finished)", log) self.assertIn("INFO: Spider closed (finished)", log) + def test_runspider_log_level(self): + log = self.get_log(self.debug_log_spider, + args=('-s', 'LOG_LEVEL=INFO')) + self.assertNotIn("DEBUG: It Works!", log) + self.assertIn("INFO: Spider opened", log) + def test_runspider_no_spider_found(self): log = self.get_log("from scrapy.spiders import Spider\n") self.assertIn("No spider found in file", log) From 05b4555f3932afb04ab3b15893a5858fca9dec04 Mon Sep 17 00:00:00 2001 From: Mikhail Korobov Date: Fri, 9 Dec 2016 02:19:51 +0500 Subject: [PATCH 5/7] TST tests for LOG_SHORT_NAMES --- tests/test_commands.py | 15 +++++++++++++++ 1 file changed, 15 insertions(+) diff --git a/tests/test_commands.py b/tests/test_commands.py index 1dd88f342..922098668 100644 --- a/tests/test_commands.py +++ b/tests/test_commands.py @@ -226,6 +226,21 @@ class MySpider(scrapy.Spider): self.assertNotIn("DEBUG: It Works!", log) self.assertIn("INFO: Spider opened", log) + def test_runspider_log_short_names(self): + log1 = self.get_log(self.debug_log_spider, + args=('-s', 'LOG_SHORT_NAMES=1')) + print(log1) + self.assertIn("[myspider] DEBUG: It Works!", log1) + self.assertIn("[scrapy]", log1) + self.assertNotIn("[scrapy.core.engine]", log1) + + log2 = self.get_log(self.debug_log_spider, + args=('-s', 'LOG_SHORT_NAMES=0')) + print(log2) + self.assertIn("[myspider] DEBUG: It Works!", log2) + self.assertNotIn("[scrapy]", log2) + self.assertIn("[scrapy.core.engine]", log2) + def test_runspider_no_spider_found(self): log = self.get_log("from scrapy.spiders import Spider\n") self.assertIn("No spider found in file", log) From 0fc73a9d558158f1686f9cc9c289fe364b5df536 Mon Sep 17 00:00:00 2001 From: Mikhail Korobov Date: Fri, 16 Dec 2016 21:47:58 +0500 Subject: [PATCH 6/7] DOC update examples with long longger names --- docs/intro/tutorial.rst | 24 +++---- docs/topics/benchmarking.rst | 92 +++++++++++++++++---------- docs/topics/downloader-middleware.rst | 8 +-- docs/topics/settings.rst | 2 +- docs/topics/shell.rst | 10 +-- 5 files changed, 81 insertions(+), 55 deletions(-) diff --git a/docs/intro/tutorial.rst b/docs/intro/tutorial.rst index 0941eb1e5..8e14d1b7c 100644 --- a/docs/intro/tutorial.rst +++ b/docs/intro/tutorial.rst @@ -130,15 +130,15 @@ will send some requests for the ``quotes.toscrape.com`` domain. You will get an similar to this:: ... (omitted for brevity) - 2016-09-20 14:48:00 [scrapy] INFO: Spider opened - 2016-09-20 14:48:00 [scrapy] INFO: Crawled 0 pages (at 0 pages/min), scraped 0 items (at 0 items/min) - 2016-09-20 14:48:00 [scrapy] DEBUG: Telnet console listening on 127.0.0.1:6023 - 2016-09-20 14:48:00 [scrapy] DEBUG: Crawled (404) (referer: None) - 2016-09-20 14:48:00 [scrapy] DEBUG: Crawled (200) (referer: None) - 2016-09-20 14:48:01 [quotes] DEBUG: Saved file quotes-1.html - 2016-09-20 14:48:01 [scrapy] DEBUG: Crawled (200) (referer: None) - 2016-09-20 14:48:01 [quotes] DEBUG: Saved file quotes-2.html - 2016-09-20 14:48:01 [scrapy] INFO: Closing spider (finished) + 2016-12-16 21:24:05 [scrapy.core.engine] INFO: Spider opened + 2016-12-16 21:24:05 [scrapy.extensions.logstats] INFO: Crawled 0 pages (at 0 pages/min), scraped 0 items (at 0 items/min) + 2016-12-16 21:24:05 [scrapy.extensions.telnet] DEBUG: Telnet console listening on 127.0.0.1:6023 + 2016-12-16 21:24:05 [scrapy.core.engine] DEBUG: Crawled (404) (referer: None) + 2016-12-16 21:24:05 [scrapy.core.engine] DEBUG: Crawled (200) (referer: None) + 2016-12-16 21:24:05 [scrapy.core.engine] DEBUG: Crawled (200) (referer: None) + 2016-12-16 21:24:05 [quotes] DEBUG: Saved file quotes-1.html + 2016-12-16 21:24:05 [quotes] DEBUG: Saved file quotes-2.html + 2016-12-16 21:24:05 [scrapy.core.engine] INFO: Closing spider (finished) ... Now, check the files in the current directory. You should notice that two new @@ -212,7 +212,7 @@ using the shell :ref:`Scrapy shell `. Run:: You will see something like:: [ ... Scrapy log here ... ] - 2016-09-19 12:09:27 [scrapy] DEBUG: Crawled (200) (referer: None) + 2016-09-19 12:09:27 [scrapy.core.engine] DEBUG: Crawled (200) (referer: None) [s] Available Scrapy objects: [s] scrapy scrapy module (contains scrapy.Request, scrapy.Selector, etc) [s] crawler @@ -429,9 +429,9 @@ in the callback, as you can see below:: If you run this spider, it will output the extracted data with the log:: - 2016-09-19 18:57:19 [scrapy] DEBUG: Scraped from <200 http://quotes.toscrape.com/page/1/> + 2016-09-19 18:57:19 [scrapy.core.scraper] DEBUG: Scraped from <200 http://quotes.toscrape.com/page/1/> {'tags': ['life', 'love'], 'author': 'André Gide', 'text': '“It is better to be hated for what you are than to be loved for what you are not.”'} - 2016-09-19 18:57:19 [scrapy] DEBUG: Scraped from <200 http://quotes.toscrape.com/page/1/> + 2016-09-19 18:57:19 [scrapy.core.scraper] DEBUG: Scraped from <200 http://quotes.toscrape.com/page/1/> {'tags': ['edison', 'failure', 'inspirational', 'paraphrased'], 'author': 'Thomas A. Edison', 'text': "“I have not failed. I've just found 10,000 ways that won't work.”"} diff --git a/docs/topics/benchmarking.rst b/docs/topics/benchmarking.rst index 632190067..99469ebf1 100644 --- a/docs/topics/benchmarking.rst +++ b/docs/topics/benchmarking.rst @@ -18,40 +18,66 @@ To run it use:: You should see an output like this:: - 2013-05-16 13:08:46-0300 [scrapy] INFO: Scrapy 0.17.0 started (bot: scrapybot) - 2013-05-16 13:08:47-0300 [scrapy] INFO: Spider opened - 2013-05-16 13:08:47-0300 [scrapy] INFO: Crawled 0 pages (at 0 pages/min), scraped 0 items (at 0 items/min) - 2013-05-16 13:08:48-0300 [scrapy] INFO: Crawled 74 pages (at 4440 pages/min), scraped 0 items (at 0 items/min) - 2013-05-16 13:08:49-0300 [scrapy] INFO: Crawled 143 pages (at 4140 pages/min), scraped 0 items (at 0 items/min) - 2013-05-16 13:08:50-0300 [scrapy] INFO: Crawled 210 pages (at 4020 pages/min), scraped 0 items (at 0 items/min) - 2013-05-16 13:08:51-0300 [scrapy] INFO: Crawled 274 pages (at 3840 pages/min), scraped 0 items (at 0 items/min) - 2013-05-16 13:08:52-0300 [scrapy] INFO: Crawled 343 pages (at 4140 pages/min), scraped 0 items (at 0 items/min) - 2013-05-16 13:08:53-0300 [scrapy] INFO: Crawled 410 pages (at 4020 pages/min), scraped 0 items (at 0 items/min) - 2013-05-16 13:08:54-0300 [scrapy] INFO: Crawled 474 pages (at 3840 pages/min), scraped 0 items (at 0 items/min) - 2013-05-16 13:08:55-0300 [scrapy] INFO: Crawled 538 pages (at 3840 pages/min), scraped 0 items (at 0 items/min) - 2013-05-16 13:08:56-0300 [scrapy] INFO: Crawled 602 pages (at 3840 pages/min), scraped 0 items (at 0 items/min) - 2013-05-16 13:08:57-0300 [scrapy] INFO: Closing spider (closespider_timeout) - 2013-05-16 13:08:57-0300 [scrapy] INFO: Crawled 666 pages (at 3840 pages/min), scraped 0 items (at 0 items/min) - 2013-05-16 13:08:57-0300 [scrapy] INFO: Dumping Scrapy stats: - {'downloader/request_bytes': 231508, - 'downloader/request_count': 682, - 'downloader/request_method_count/GET': 682, - 'downloader/response_bytes': 1172802, - 'downloader/response_count': 682, - 'downloader/response_status_count/200': 682, - 'finish_reason': 'closespider_timeout', - 'finish_time': datetime.datetime(2013, 5, 16, 16, 8, 57, 985539), - 'log_count/INFO': 14, - 'request_depth_max': 34, - 'response_received_count': 682, - 'scheduler/dequeued': 682, - 'scheduler/dequeued/memory': 682, - 'scheduler/enqueued': 12767, - 'scheduler/enqueued/memory': 12767, - 'start_time': datetime.datetime(2013, 5, 16, 16, 8, 47, 676539)} - 2013-05-16 13:08:57-0300 [scrapy] INFO: Spider closed (closespider_timeout) + 2016-12-16 21:18:48 [scrapy.utils.log] INFO: Scrapy 1.2.2 started (bot: quotesbot) + 2016-12-16 21:18:48 [scrapy.utils.log] INFO: Overridden settings: {'CLOSESPIDER_TIMEOUT': 10, 'ROBOTSTXT_OBEY': True, 'SPIDER_MODULES': ['quotesbot.spiders'], 'LOGSTATS_INTERVAL': 1, 'BOT_NAME': 'quotesbot', 'LOG_LEVEL': 'INFO', 'NEWSPIDER_MODULE': 'quotesbot.spiders'} + 2016-12-16 21:18:49 [scrapy.middleware] INFO: Enabled extensions: + ['scrapy.extensions.closespider.CloseSpider', + 'scrapy.extensions.logstats.LogStats', + 'scrapy.extensions.telnet.TelnetConsole', + 'scrapy.extensions.corestats.CoreStats'] + 2016-12-16 21:18:49 [scrapy.middleware] INFO: Enabled downloader middlewares: + ['scrapy.downloadermiddlewares.robotstxt.RobotsTxtMiddleware', + 'scrapy.downloadermiddlewares.httpauth.HttpAuthMiddleware', + 'scrapy.downloadermiddlewares.downloadtimeout.DownloadTimeoutMiddleware', + 'scrapy.downloadermiddlewares.defaultheaders.DefaultHeadersMiddleware', + 'scrapy.downloadermiddlewares.useragent.UserAgentMiddleware', + 'scrapy.downloadermiddlewares.retry.RetryMiddleware', + 'scrapy.downloadermiddlewares.redirect.MetaRefreshMiddleware', + 'scrapy.downloadermiddlewares.httpcompression.HttpCompressionMiddleware', + 'scrapy.downloadermiddlewares.redirect.RedirectMiddleware', + 'scrapy.downloadermiddlewares.cookies.CookiesMiddleware', + 'scrapy.downloadermiddlewares.stats.DownloaderStats'] + 2016-12-16 21:18:49 [scrapy.middleware] INFO: Enabled spider middlewares: + ['scrapy.spidermiddlewares.httperror.HttpErrorMiddleware', + 'scrapy.spidermiddlewares.offsite.OffsiteMiddleware', + 'scrapy.spidermiddlewares.referer.RefererMiddleware', + 'scrapy.spidermiddlewares.urllength.UrlLengthMiddleware', + 'scrapy.spidermiddlewares.depth.DepthMiddleware'] + 2016-12-16 21:18:49 [scrapy.middleware] INFO: Enabled item pipelines: + [] + 2016-12-16 21:18:49 [scrapy.core.engine] INFO: Spider opened + 2016-12-16 21:18:49 [scrapy.extensions.logstats] INFO: Crawled 0 pages (at 0 pages/min), scraped 0 items (at 0 items/min) + 2016-12-16 21:18:50 [scrapy.extensions.logstats] INFO: Crawled 70 pages (at 4200 pages/min), scraped 0 items (at 0 items/min) + 2016-12-16 21:18:51 [scrapy.extensions.logstats] INFO: Crawled 134 pages (at 3840 pages/min), scraped 0 items (at 0 items/min) + 2016-12-16 21:18:52 [scrapy.extensions.logstats] INFO: Crawled 198 pages (at 3840 pages/min), scraped 0 items (at 0 items/min) + 2016-12-16 21:18:53 [scrapy.extensions.logstats] INFO: Crawled 254 pages (at 3360 pages/min), scraped 0 items (at 0 items/min) + 2016-12-16 21:18:54 [scrapy.extensions.logstats] INFO: Crawled 302 pages (at 2880 pages/min), scraped 0 items (at 0 items/min) + 2016-12-16 21:18:55 [scrapy.extensions.logstats] INFO: Crawled 358 pages (at 3360 pages/min), scraped 0 items (at 0 items/min) + 2016-12-16 21:18:56 [scrapy.extensions.logstats] INFO: Crawled 406 pages (at 2880 pages/min), scraped 0 items (at 0 items/min) + 2016-12-16 21:18:57 [scrapy.extensions.logstats] INFO: Crawled 438 pages (at 1920 pages/min), scraped 0 items (at 0 items/min) + 2016-12-16 21:18:58 [scrapy.extensions.logstats] INFO: Crawled 470 pages (at 1920 pages/min), scraped 0 items (at 0 items/min) + 2016-12-16 21:18:59 [scrapy.core.engine] INFO: Closing spider (closespider_timeout) + 2016-12-16 21:18:59 [scrapy.extensions.logstats] INFO: Crawled 518 pages (at 2880 pages/min), scraped 0 items (at 0 items/min) + 2016-12-16 21:19:00 [scrapy.statscollectors] INFO: Dumping Scrapy stats: + {'downloader/request_bytes': 229995, + 'downloader/request_count': 534, + 'downloader/request_method_count/GET': 534, + 'downloader/response_bytes': 1565504, + 'downloader/response_count': 534, + 'downloader/response_status_count/200': 534, + 'finish_reason': 'closespider_timeout', + 'finish_time': datetime.datetime(2016, 12, 16, 16, 19, 0, 647725), + 'log_count/INFO': 17, + 'request_depth_max': 19, + 'response_received_count': 534, + 'scheduler/dequeued': 533, + 'scheduler/dequeued/memory': 533, + 'scheduler/enqueued': 10661, + 'scheduler/enqueued/memory': 10661, + 'start_time': datetime.datetime(2016, 12, 16, 16, 18, 49, 799869)} + 2016-12-16 21:19:00 [scrapy.core.engine] INFO: Spider closed (closespider_timeout) -That tells you that Scrapy is able to crawl about 3900 pages per minute in the +That tells you that Scrapy is able to crawl about 3000 pages per minute in the hardware where you run it. Note that this is a very simple spider intended to follow links, any custom spider you write will probably do more stuff which results in slower crawl rates. How slower depends on how much your spider does diff --git a/docs/topics/downloader-middleware.rst b/docs/topics/downloader-middleware.rst index 29d9b0298..3b9a5335a 100644 --- a/docs/topics/downloader-middleware.rst +++ b/docs/topics/downloader-middleware.rst @@ -238,14 +238,14 @@ header) and all cookies received in responses (ie. ``Set-Cookie`` header). Here's an example of a log with :setting:`COOKIES_DEBUG` enabled:: - 2011-04-06 14:35:10-0300 [scrapy] INFO: Spider opened - 2011-04-06 14:35:10-0300 [scrapy] DEBUG: Sending cookies to: + 2011-04-06 14:35:10-0300 [scrapy.core.engine] INFO: Spider opened + 2011-04-06 14:35:10-0300 [scrapy.downloadermiddlewares.cookies] DEBUG: Sending cookies to: Cookie: clientlanguage_nl=en_EN - 2011-04-06 14:35:14-0300 [scrapy] DEBUG: Received cookies from: <200 http://www.diningcity.com/netherlands/index.html> + 2011-04-06 14:35:14-0300 [scrapy.downloadermiddlewares.cookies] DEBUG: Received cookies from: <200 http://www.diningcity.com/netherlands/index.html> Set-Cookie: JSESSIONID=B~FA4DC0C496C8762AE4F1A620EAB34F38; Path=/ Set-Cookie: ip_isocode=US Set-Cookie: clientlanguage_nl=en_EN; Expires=Thu, 07-Apr-2011 21:21:34 GMT; Path=/ - 2011-04-06 14:49:50-0300 [scrapy] DEBUG: Crawled (200) (referer: None) + 2011-04-06 14:49:50-0300 [scrapy.core.engine] DEBUG: Crawled (200) (referer: None) [...] diff --git a/docs/topics/settings.rst b/docs/topics/settings.rst index 503f4afb1..0515a9e0d 100644 --- a/docs/topics/settings.rst +++ b/docs/topics/settings.rst @@ -1037,7 +1037,7 @@ Stats counter (``scheduler/unserializable``) tracks the number of times this hap Example entry in logs:: - 1956-01-31 00:00:00+0800 [scrapy] ERROR: Unable to serialize request: + 1956-01-31 00:00:00+0800 [scrapy.core.scheduler] ERROR: Unable to serialize request: - reason: cannot serialize (type Request)> - no more unserializable requests will be logged (see 'scheduler/unserializable' stats counter) diff --git a/docs/topics/shell.rst b/docs/topics/shell.rst index 322c3ddfa..da91108b2 100644 --- a/docs/topics/shell.rst +++ b/docs/topics/shell.rst @@ -173,7 +173,7 @@ all start with the ``[s]`` prefix):: After that, we can start playing with the objects:: >>> response.xpath('//title/text()').extract_first() - u'Scrapy | A Fast and Powerful Scraping and Web Crawling Framework' + 'Scrapy | A Fast and Powerful Scraping and Web Crawling Framework' >>> fetch("http://reddit.com") [s] Available Scrapy objects: @@ -189,7 +189,7 @@ After that, we can start playing with the objects:: [s] view(response) View response in a browser >>> response.xpath('//title/text()').extract() - [u'reddit: the front page of the internet'] + ['reddit: the front page of the internet'] >>> request = request.replace(method="POST") @@ -234,8 +234,8 @@ Here's an example of how you would call it from your spider:: When you run the spider, you will get something similar to this:: - 2014-01-23 17:48:31-0400 [scrapy] DEBUG: Crawled (200) (referer: None) - 2014-01-23 17:48:31-0400 [scrapy] DEBUG: Crawled (200) (referer: None) + 2014-01-23 17:48:31-0400 [scrapy.core.engine] DEBUG: Crawled (200) (referer: None) + 2014-01-23 17:48:31-0400 [scrapy.core.engine] DEBUG: Crawled (200) (referer: None) [s] Available Scrapy objects: [s] crawler ... @@ -258,7 +258,7 @@ Finally you hit Ctrl-D (or Ctrl-Z in Windows) to exit the shell and resume the crawling:: >>> ^D - 2014-01-23 17:50:03-0400 [scrapy] DEBUG: Crawled (200) (referer: None) + 2014-01-23 17:50:03-0400 [scrapy.core.engine] DEBUG: Crawled (200) (referer: None) ... Note that you can't use the ``fetch`` shortcut here since the Scrapy engine is From da19f0b7b73ca4fd78d828e710e111c60bc658e3 Mon Sep 17 00:00:00 2001 From: Mikhail Korobov Date: Fri, 16 Dec 2016 22:14:54 +0500 Subject: [PATCH 7/7] DOC how to override log level for a specific Scrapy component --- docs/topics/logging.rst | 39 ++++++++++++++++++++++++++++++++++++++- 1 file changed, 38 insertions(+), 1 deletion(-) diff --git a/docs/topics/logging.rst b/docs/topics/logging.rst index 231f5186b..ac3b614fc 100644 --- a/docs/topics/logging.rst +++ b/docs/topics/logging.rst @@ -10,7 +10,7 @@ Logging about the new logging system. Scrapy uses `Python's builtin logging system -`_ for event logging. We'll +`_ for event logging. We'll provide some simple examples to get you started, but for more advanced use-cases it's strongly suggested to read thoroughly its documentation. @@ -193,6 +193,43 @@ to override some of the Scrapy settings regarding logging. Module `logging.handlers `_ Further documentation on available handlers +Advanced customization +---------------------- + +Because Scrapy uses stdlib logging module, you can customize logging using +all features of stdlib logging. + +For example, let's say you're scraping a website which returns many +HTTP 404 and 500 responses, and you want to hide all messages like this:: + + 2016-12-16 22:00:06 [scrapy.spidermiddlewares.httperror] INFO: Ignoring + response <500 http://quotes.toscrape.com/page/1-34/>: HTTP status code + is not handled or not allowed + +The first thing to note is a logger name - it is in brackets: +``[scrapy.spidermiddlewares.httperror]``. If you get just ``[scrapy]`` then +:setting:`LOG_SHORT_NAMES` is likely set to True; set it to False and re-run +the crawl. + +Next, we can see that the message has INFO level. To hide it +we should set logging level for ``scrapy.spidermiddlewares.httperror`` +higher than INFO; next level after INFO is WARNING. It could be done +e.g. in the spider's ``__init__`` method:: + + import logging + import scrapy + + + class MySpider(scrapy.Spider): + # ... + def __init__(self, *args, **kwargs): + logger = logging.getLogger('scrapy.spidermiddlewares.httperror') + logger.setLevel(logging.WARNING) + super().__init__(*args, **kwargs) + +If you run this spider again then INFO messages from +``scrapy.spidermiddlewares.httperror`` logger will be gone. + scrapy.utils.log module =======================