Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Change name of "release" method in delayed logs handler #1960

Merged
merged 1 commit into from Jan 8, 2021

Conversation

djmattyg007
Copy link
Contributor

The previous name of this method overrode a method with the same name in
the parent class that was related to lock acquisition. This was being
called internally by python logging code. Instead of releasing the lock,
this will have been accidentally dumping logs gathered before they were
ready to be handled. From what I can tell, this was happening just
before we manually called release(). This would give the appearance that
these logs were not being captured when in fact they were.

This fixes #1958

The previous name of this method overrode a method with the same name in
the parent class that was related to lock acquisition. This was being
called internally by python logging code. Instead of releasing the lock,
this will have been accidentally dumping logs gathered before they were
ready to be handled. From what I can tell, this was happening just
before we manually called release(). This would give the appearance that
these logs were not being captured when in fact they were.
@codecov
Copy link

codecov bot commented Jan 7, 2021

Codecov Report

Merging #1960 (3d8aa4d) into develop (284253c) will increase coverage by 0.10%.
The diff coverage is 50.00%.

Impacted file tree graph

@@             Coverage Diff             @@
##           develop    #1960      +/-   ##
===========================================
+ Coverage    76.87%   76.97%   +0.10%     
===========================================
  Files           55       55              
  Lines         4713     4713              
===========================================
+ Hits          3623     3628       +5     
+ Misses        1090     1085       -5     
Impacted Files Coverage Δ
mopidy/internal/log.py 31.81% <50.00%> (ø)
mopidy/audio/actor.py 60.68% <0.00%> (+1.13%) ⬆️

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 284253c...3d8aa4d. Read the comment docs.

@kingosticks
Copy link
Member

kingosticks commented Jan 7, 2021

So, why don't I see this issue?

EDIT: Is this just a race condition issue? I'm very surprised I didn't notice it missing from anyone's logs on the user forum.

EDIT EDIT: maybe something related to using venv instead of our usual virtualenv?

@djmattyg007
Copy link
Contributor Author

Yeah I think there's a multitude of possible factors. Different version of python, different virtualenv setup, ability to access the keyring to find configuration, different Linux distribution C runtimes even? I'm not familiar with how python's built-in locking primitives work.

To be honest I'm not really sure how it could be happening at all, as from what I can tell handler.acquire() and handler.release() are only called by handler.handle(), which is also overridden. It's definitely happening though, and simply renaming the method 100% resolves the issue for me.

In general though it's probably a good idea to avoid overriding these kinds of methods in stdlib classes. It's difficult to see a downside from making this change.

@kingosticks
Copy link
Member

kingosticks commented Jan 8, 2021

I have no problem with the change, it's definitely a bug and not our intention to override release. I was trying to understand it fully with the aim of patching the test hole.

@kingosticks
Copy link
Member

The test hole around logging is, for want of a better word, gaping. We can't worry about that here.

@kingosticks kingosticks merged commit 51f89d6 into mopidy:develop Jan 8, 2021
@kingosticks kingosticks added the C-bug Category: This is a bug label Jan 8, 2021
@kingosticks kingosticks added this to the Next bug fix release milestone Jan 8, 2021
@kingosticks
Copy link
Member

Thanks for drilling down and finding this.

@djmattyg007
Copy link
Contributor Author

The test hole around logging is, for want of a better word, gaping. We can't worry about that here.

I did look for some testing code, and realised I wasn't sure how to test code that interacts with python's stdlib logging mechanism.

Thanks for drilling down and finding this.

Thank you and @jodal for writing such an amazing piece of software! It's genuinely changed the way I listen to music and formed the backbone of my multi-room music setup.

@kingosticks
Copy link
Member

I can't take credit for much, I'm a relative new-comer. But I am glad you find Mopidy useful!

@kingosticks
Copy link
Member

kingosticks commented Aug 18, 2021

Oops, this never made it into the changelog

EDIT: cancel that, it did. I am blind.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
C-bug Category: This is a bug
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Logs generated during loading of extensions are not output
3 participants