search

scrapy / scrapy

Scrapy, a fast high-level web crawling & scraping framework for Python.
https://scrapy.org
BSD 3-Clause "New" or "Revised" License
53.11k stars 10.56k forks source link

LOG_LEVEL settings not work #6421

Closed czqqqaq closed 4 months ago

czqqqaq commented 4 months ago

Description of the Issue

I've added LOG_LEVEL = "INFO to my settings.py file. However, when I run scrapy crawl spider, the log still contains Debug level messages, and the log levels of other modules are also being altered.

Analysis

I discovered that when Scrapy initializes the CrawlerProcess, it calls the configure_logging function in scrapy.utils.log, which sets the root logger's level to NOTSET. This causes all log levels (including Debug) to be processed.

Expected Behavior

I would like to set Scrapy's log level to INFO without affecting the log levels of other modules.

Current Behavior

Despite setting LOG_LEVEL = "INFO" or LOG_ENABLED = False in settings.py, the log still contains Debug level messages, and the log levels of other modules are being changed because the logging.root.level has been change to NOTSET.

wRAR commented 4 months ago

If you think there is some bug in Scrapy causing this problem for your code you need to provide a minimal reproducible example of it.

LOG_LEVEL in settings.py is obviously not broken for everyone.

czqqqaq commented 4 months ago

this is my spider, I found out is the logging.basicConfig makes the log level broken.

import json
import scrapy
import datetime
import logging 

logging.basicConfig(level="ERROR")
class RawItem(scrapy.Item):
    time = scrapy.Field()
    data = scrapy.Field()
    file_name = scrapy.Field()

class THSHotETFSpider(scrapy.Spider):
    name = "ths_hot_etf"
    url = "https://dq.10jqka.com.cn/fuyao/hot_list_data/out/hot_list/v1/etf"
    custom_settings = {"ITEM_PIPELINES": {"spider.pipelines.DynamicFilePipeline": 400}, "LOG_LEVEL": "ERROR"}

    def start_requests(self):
        yield scrapy.Request(self.url, callback=self.parse, meta={"file_name": self.name})

    def parse(self, response):
        data = json.loads(response.text)
        file_name = response.meta["file_name"]

        item = RawItem(
            time=datetime.datetime.now().strftime("%Y-%m-%d %H:%M:%S"),
            data=data["data"],
            file_name=file_name,
        )
        yield item
wRAR commented 4 months ago

This isn't minimal and isn't reproducible.

czqqqaq commented 4 months ago

sorry about that. this is the new code

import scrapy
from scrapy.crawler import CrawlerProcess
import logging 

logging.basicConfig(level="ERROR")
class RawItem(scrapy.Item):
    data = scrapy.Field()

class TestSpider(scrapy.Spider):
    name = "test_spider"
    url = "https://example.com"
    custom_settings = {"LOG_LEVEL": "ERROR"}

    def start_requests(self):
        yield scrapy.Request(self.url, callback=self.parse)

    def parse(self, response): 
        item = RawItem(data="test_message")
        yield item

if __name__ == "__main__":
    process = CrawlerProcess()
    process.crawl(TestSpider)
    process.start()

Then this is the terminal output after running the code, which you can see the debug message:

INFO:scrapy.utils.log:Scrapy 2.11.2 started (bot: scrapybot)
2024-07-02 10:23:28 [scrapy.utils.log] INFO: Scrapy 2.11.2 started (bot: scrapybot)
INFO:scrapy.utils.log:Versions: lxml 5.2.2.0, libxml2 2.12.6, cssselect 1.2.0, parsel 1.9.1, w3lib 2.0.0, Twisted 24.3.0, Python 3.10.14 (main, May  6 2024, 19:42:50) [GCC 11.2.0], pyOpenSSL 24.1.0 (OpenSSL 3.2.2 4 Jun 2024), cryptography 42.0.8, Platform Linux-5.10.0-27-amd64-x86_64-with-glibc2.31
2024-07-02 10:23:28 [scrapy.utils.log] INFO: Versions: lxml 5.2.2.0, libxml2 2.12.6, cssselect 1.2.0, parsel 1.9.1, w3lib 2.0.0, Twisted 24.3.0, Python 3.10.14 (main, May  6 2024, 19:42:50) [GCC 11.2.0], pyOpenSSL 24.1.0 (OpenSSL 3.2.2 4 Jun 2024), cryptography 42.0.8, Platform Linux-5.10.0-27-amd64-x86_64-with-glibc2.31
INFO:scrapy.addons:Enabled addons:
[]
WARNING:py.warnings:/root/miniconda3/envs/test_spider/lib/python3.10/site-packages/scrapy/utils/request.py:254: ScrapyDeprecationWarning: '2.6' is a deprecated value for the 'REQUEST_FINGERPRINTER_IMPLEMENTATION' setting.

It is also the default value. In other words, it is normal to get this warning if you have not defined a value for the 'REQUEST_FINGERPRINTER_IMPLEMENTATION' setting. This is so for backward compatibility reasons, but it will change in a future version of Scrapy.

See the documentation of the 'REQUEST_FINGERPRINTER_IMPLEMENTATION' setting for information on how to handle this deprecation.
  return cls(crawler)

DEBUG:scrapy.utils.log:Using reactor: twisted.internet.epollreactor.EPollReactor
INFO:scrapy.extensions.telnet:Telnet Password: 6106feb8a25b8fbc
INFO:scrapy.middleware:Enabled extensions:
['scrapy.extensions.corestats.CoreStats',
 'scrapy.extensions.telnet.TelnetConsole',
 'scrapy.extensions.memusage.MemoryUsage',
 'scrapy.extensions.logstats.LogStats']
INFO:scrapy.crawler:Overridden settings:
{'LOG_LEVEL': 'ERROR'}
INFO:scrapy.middleware:Enabled downloader middlewares:
['scrapy.downloadermiddlewares.offsite.OffsiteMiddleware',
 '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.httpproxy.HttpProxyMiddleware',
 'scrapy.downloadermiddlewares.stats.DownloaderStats']
INFO:scrapy.middleware:Enabled spider middlewares:
['scrapy.spidermiddlewares.httperror.HttpErrorMiddleware',
 'scrapy.spidermiddlewares.referer.RefererMiddleware',
 'scrapy.spidermiddlewares.urllength.UrlLengthMiddleware',
 'scrapy.spidermiddlewares.depth.DepthMiddleware']
INFO:scrapy.middleware:Enabled item pipelines:
[]
INFO:scrapy.core.engine:Spider opened
INFO:scrapy.extensions.logstats:Crawled 0 pages (at 0 pages/min), scraped 0 items (at 0 items/min)
INFO:scrapy.extensions.telnet:Telnet console listening on 127.0.0.1:6023
DEBUG:scrapy.core.engine:Crawled (200) <GET https://example.com> (referer: None)
DEBUG:scrapy.core.scraper:Scraped from <200 https://example.com>
{'data': 'test_message'}
INFO:scrapy.core.engine:Closing spider (finished)
INFO:scrapy.statscollectors:Dumping Scrapy stats:
{'downloader/request_bytes': 212,
 'downloader/request_count': 1,
 'downloader/request_method_count/GET': 1,
 'downloader/response_bytes': 1007,
 'downloader/response_count': 1,
 'downloader/response_status_count/200': 1,
 'elapsed_time_seconds': 0.706774,
 'finish_reason': 'finished',
 'finish_time': datetime.datetime(2024, 7, 2, 2, 23, 29, 877040, tzinfo=datetime.timezone.utc),
 'httpcompression/response_bytes': 1256,
 'httpcompression/response_count': 1,
 'item_scraped_count': 1,
 'memusage/max': 67862528,
 'memusage/startup': 67862528,
 'response_received_count': 1,
 'scheduler/dequeued': 1,
 'scheduler/dequeued/memory': 1,
 'scheduler/enqueued': 1,
 'scheduler/enqueued/memory': 1,
 'start_time': datetime.datetime(2024, 7, 2, 2, 23, 29, 170266, tzinfo=datetime.timezone.utc)}
INFO:scrapy.core.engine:Spider closed (finished)
wRAR commented 4 months ago

Note that CrawlerProcess automatically calls configure_logging, so it is recommended to only use logging.basicConfig() together with CrawlerRunner.

https://docs.scrapy.org/en/latest/topics/logging.html