Ensure proper log line/filename in warning/errors

[copperchin]

Fix #3037

Pull Request Checklist

Resolves: Warning and Error logs messages show wrong source #3037

• [x] Ensured tests pass and (if applicable) updated functional test output
• [x] Conformed to code style guidelines by running appropriate linting tools
• [x] Added tests for changed code
• [x] Updated documentation for changed code

[copperchin]

Looking at this more, I'm seeing that the tests fail due to xdist: there's now race conditions on the global root logger...

I can get around this by testing log.init() on other (ie. non-root) loggers; but for that to work, the module-level code changing the root logger class would need to be implemented in log.init(), affecting only the named logger (rather than assuming root).

This is all fine and good, but at that point I feel like I might as well tackle an issue that these code smells point to:

Frankly, I was never happy to see this feature implemented via custom logger classes -- I'd prefer to instead:

• use a custom logging.Filter to manage the quit-on-fatal behavior
• drop the LimitLogger class, converting the LimitLogger methods to module-level add_limit/remove_limit definitions.

This of course changes the interface...which I'm hesitant to just throw out there. Although, as far as I can tell, nothing in this codebase uses them outside of log.py and a few tests modules; I can't speak for any of the plugins though.

Any thoughts?

[avaris]

This of course changes the interface...which I'm hesitant to just throw out there. Although, as far as I can tell, nothing in this codebase uses them outside of log.py and a few tests modules; I can't speak for any of the plugins though.

That's the point :). log.py sets things up (with global state or root logger) so that no other module needs to do any setup. They can just do:

import logging
logger = logging.getLogger(__name__)

and things will work.

I would agree that some things could be cleaned away. pelican essentially relies on root logger to do the heavy lifting. handler are defined there. Although LimitLogger/FatalLogger set up so that individual loggers have certain filters, but they don't have to. That can be pushed to the root logger as well. So I would be on board with cutting LimitLogger and FatalLogger, turning them into logging.Filters and installing them to the root logger in init.

init would not be really testable, since that would alter global state, but hey... python logging is practically a giant global state anyway, so hard to get around that. But it would be possible to test filters independently, since they could be installed to sub-loggers.

[justinmayer]

@copperchin: Any chance you could take another look at your PR here and decide how you'd like to carry it forward?

[copperchin]

Yes, I'll take another look at this.

I don't actually remember why this stalled but, reviewing the notes here, it looks like this might have been blocked by a deeper issue. If that's the case I'll open a separate issue for that and link it here.

[copperchin]

So I think this stalled because I became mired in a lot of unrelated test failures.

At first, I was getting a very large number of test failures due to timezones. Turns out this is an issue in the main branch even without any additional changes. Installing tzdata resolves that. I was going to suggest that package be added to the requirements/test.pip file, but I didn't see anyone else reporting that issue so I'm a bit bewildered as to why.

The other things I'm working through is a number of remaining test failures in what feels like unrelated code. These failures arise because rather than testing the direct result of an operation, they count the number of warnings logged.

Now, in theory, the changes I'm putting forward shouldn't change the actual logging behavior, so I'm looking into why these other tests no longer pass, but I am a bit concerned about leaving tests to rely on specific logging behavior to pass/fail.

Anyway. I'll keep kicking at this for now, but wanted to leave an update.

[avaris]

@copperchin If you need any assistance or guidance, I'd be happy to lend a hand.

[copperchin]

@avaris Thanks!

I think I had a breakthrough that resolved most of the issues when I last looked at it. I haven't had much time at my machine for the last week and a bit but I'm hoping to be able to spend a bit of time tonight on it; I don't think an updated PR is far off.

[copperchin]

Just working on adding some tests, doing some cleanup, and adding docstrings to my changes.

I have a couple of questions regarding style preferences for pelican code:

1. I don't see much use of type hints yet in the repo, but as the latest supported python version is now 3.7, are type hints something we are ok to start using?

2. Also, I couldn't find whether there's a preferred style for docstrings (specifically re: describing parameters, return, etc.). I'm personally a fan of NumPy style, but I see a few modules using what appears to be a reStructuredText version of EpyDoc/EpiText.

[avaris]

@copperchin sorry, I totally missed your questions

I have a couple of questions regarding style preferences for pelican code:

1. I don't see much use of type hints yet in the repo, but as the latest supported python version is now 3.7, are type hints something we are ok to start using?

I have a love/hate relationship with type hints. If you start your project with type hints in mind, they are usually great and helpful. But adding type hints to existing and dated projects was most of the time frustrating (unless you are willing to refactor it to the point of almost rewriting). Unions all around, turning single line defs to many many lines and obfuscating code more than it helps with readability... So, in short it depends. If they are helpful in documenting the code I don't mind them. That being said, I wouldn't hold my breath for all of pelican typed and checked :).

2. Also, I couldn't find whether there's a preferred style for docstrings (specifically re: describing parameters, return, etc.). I'm personally a fan of NumPy style, but I see a few modules using what appears to be a reStructuredText version of EpyDoc/EpiText.

I don't think we have a docstring style. As long as it is accurate I am fine with mostly anything :).

[copperchin]

@avaris Yeah I see what you mean; I initially started adding type hints for new content but it felt so out of place that it seemed more distracting than helpful. I also balked at how long it made lines >_< haha.

I see the latest surge of merges (a great thing!) has left this PR with some conflicts -- I'll try to get those resolved this weekend.

[avaris]

@copperchin is it possible to incorporate #3108 into this? Once this is merged, that PR effectively needs to be rewritten :). But if it will delay this one further, don't worry about it. I can deal with all the conflicts, refactoring after this is handled.

[copperchin]

Funny you should bring that up; I came across https://github.com/getpelican/pelican/issues/2893 yesterday and commented there -- missed the PR #3108 though. My suggestion was to keep the 2-tuple form and just use regex objects where regex is desired -- this would preserve backwards compatibility.

I'm happy to implement that change but I don't want to include it in the scope of this change; I'll work on it after this gets merged.

[copperchin]

Thanks for the in-depth review @avaris ! This is a pretty big diff, so I really appreciate the effort.

I'm hoping to be able to get revisions up here in the next fews days at most, to keep the momentum :)

[avaris]

I also have a sneaking suspicion that filters will not be active for anything outside pelican.* namespace: e.g. legacy plugins. But I have not tested it. It would probably be resolved if they are also installed to the root logger.

[MinchinWeb]

The topline issue can be solved with #3257, which changes only 2 lines. (I didn't realize this was underway, and in your defense, my fix relies on a Python 3.8 feature, which may not have been an acceptable solution a year ago when you started.) I realize this has grown in scope since...

At first, I was getting a very large number of test failures due to timezones. Turns out this is an issue in the main branch even without any additional changes. Installing tzdata resolves that. I was going to suggest that package be added to the requirements/test.pip file, but I didn't see anyone else reporting that issue so I'm a bit bewildered as to why.

Hopefully this was fixed by #3246. I suspect it might be a Windows-only issue, which would lower the number of people reporting it.