[MRG+1] Respect custom log level: fixes GH-1612

[lopuhin]

See #1612: this uses self.settings instead of settings, as elsewhere in the crawler init.
Main change is that now a new root logger is installed when a crawler is created if one was already installed before. This allows to respect custom settings related to logging, such as LOG_LEVEL, LOG_FILE, etc.

As the result, in case of several spiders, logging settings from the last spider take precedence. Without this change, all logging settings in custom_settings are ignored. Both behaviours are not great, but it seems that in most cases there is just one spider running in the process, so the new behaviour seems less bad, but it's a tough call.

[codecov-io]

Codecov Report

Merging #2581 into master will increase coverage by 0.07%.
The diff coverage is 100%.

@@            Coverage Diff             @@
##           master    #2581      +/-   ##
==========================================
+ Coverage   84.14%   84.21%   +0.07%     
==========================================
  Files         161      161              
  Lines        9063     9072       +9     
  Branches     1344     1346       +2     
==========================================
+ Hits         7626     7640      +14     
+ Misses       1177     1174       -3     
+ Partials      260      258       -2

Impacted Files	Coverage Δ
scrapy/utils/log.py	88.5% <100%> (+7.25%)	✅
scrapy/crawler.py	90% <100%> (+0.12%)	✅

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 7e8453c...6f55ca4. Read the comment docs.

[kmike]

The fix makes sense, but I wonder what happens if there are two spiders in the same process (executed via CrawlerRunner), and one of them changes LOG_LEVEL - does it affect the other spider?

[lopuhin]

Yes, I don't think you can have two spiders with different log levels in one process, and I don't immediately see a backwards-compatible fix for that.

[djunzu]

I guess the last spider to start will override any previous log level.
In this case I think a warning note should be somewhere in the docs saying it.

[kmike]

@djunzu I'd expect it to still follow log level for this spider, at least if spider is in context. This is not always possible though because some messages are global (without spider in context). But if we document current behavior then maybe we'll documet a bug; I'm not sure. Anyways, it looks like a different issue.

[djunzu]

@kmike I decided to test it just to know what happens. I tried

# settings.py:
LOG_LEVEL = 'WARNING'

#testspider.py:
class TestSpider(scrapy.Spider):
    name = "Test"
    custom_settings = {
        'LOG_LEVEL': 'DEBUG',
    }

# output just with warning messages

and

# settings.py:
LOG_LEVEL = 'DEBUG'

#testspider.py:
class TestSpider(scrapy.Spider):
    name = "Test"
    custom_settings = {
        'LOG_LEVEL': 'WARNING',
    }

# output with a lot of debug messages

and

# settings.py:
#LOG_LEVEL = 'DEBUG'

#testspider.py:
class TestSpider(scrapy.Spider):
    name = "Test"
    custom_settings = {
        'LOG_LEVEL': 'WARNING',
    }

# output with a lot of debug messages (default LOG_LEVEL)

None of them works. It does not solve the problem and it is still not possible to set log level using custom_settings attribute. (This or I did something very wrong!)

tested with scrapy 1.3.2

@lopuhin Did you do any other test than the one you wrote?

[lopuhin]

@djunzu yes, I did check that this pull request solves the issue for me (specifically, I was using scrapy runspider command), and I checked that the test I wrote fails without this PR. Let me also check the scrapy crawl command.

[lopuhin]

@djunzu you are right, this is my mistake. Honestly, I'm not sure how did I test it and get what I expected. Thanks for checking! I'll see if I can fix it.
The test also needs updating: it just check log stats (which do respect log level in custom_settings), but not the actual log output.

[lopuhin]

The tests are green finally, yay! @kmike @djunzu @redapple do you mind having another look at this? I updated the PR description with summary of changes and also checked that scrapy crawl and scrapy runspider commands both respect custom log settings.

[kmike]

Hm, previously this function was only called by Scrapy commands, not by Crawler. I think we should check carefully that calling it in Crawler doesn't affect usage examples in https://doc.scrapy.org/en/latest/topics/logging.html#scrapy.utils.log.configure_logging.

[lopuhin]

Right, thanks for the catch! Probably it's wrong to call it unconditionally when starting any crawler - when you are using scrapy as a library you'd like to be in control of the logging. Initially I added this call to support other log settings as well, but now I see that this is problematic. Maybe it's better to change scrapy root handler only if it's already installed.

[lopuhin]

Now a new root logger is installed when a crawler is created only if one was already installed before.

[kmike]

what is the reason for this change?

[lopuhin]

I made that changes because a new root log handler was installed when crawler was created, and so LogCapture did not work (and many other tests also have crawler creation outside of LogCapture). But it looks like it is no longer required, at least when the tests are run in isolation. I revered this changes in 6f55ca4, let's see if the full test suite passes.

[lopuhin]

Yep, the tests passed, probably it's better to leave it as it was in master. Thanks for the catch!

[kmike]

Looks good to me, thanks @lopuhin for the fix and @djunzu for the review.

[djunzu]

👍

Back to my initial comment:
I think that docs should have this note: "in case of several spiders, logging settings from the last spider take precedence".

@kmike, regarding

But if we document current behavior then maybe we'll documet a bug

I think documented bugs are good: everyone knows what to expect. Undocumented bugs are bad: when you are not expecting it, something blows up in front of you!

Nonetheless, +1 for merge.