Test test_album_art fails

[ss2]

Problem

While trying to update beets to 1.5.0 on Guix, the test test_album_art fails.

The output is:

======================================================================
FAIL: test_album_art (test.test_zero.ZeroPluginTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/guix-build-beets-1.5.0.drv-0/beets-1.5.0/test/test_zero.py", line 109, in test_album_art
    self.assertEqual(0, len(mf.images))
AssertionError: 0 != 1
-------------------- >> begin captured logging << --------------------
beets: DEBUG: Sending event: write
beets: DEBUG: Sending event: after_write
--------------------- >> end captured logging << ---------------------

----------------------------------------------------------------------
Ran 1607 tests in 69.053s

FAILED (SKIP=51, failures=1)
command "nosetests" "-v" failed with status 1

Setup

• OS: Guix
• Python version: 3.8.2
• beets version: 1.5.0
• Turning off plugins made problem go away (yes/no): -

Apparently this test has failed since maybe 04ea754d00e2873ae9aa2d9e07c5cefd790eaee2. Looking around, this test has also been disabled in Arch Linux package too, and it fails there too. Additionally another test in Arch appears to fail too.

Kind regards

[sampsyo]

Huh, thanks for pointing this out! The mystery is why it's not failing in our CI. We'll need to look into this.

https://github.com/beetbox/beets/commit/04ea754d00e2873ae9aa2d9e07c5cefd790eaee2 itself is unlikely to be the culprit (since that did not change the zero plugin that this case tests), but perhaps the timing of the problem is around there.

[jackwilsdon]

Doing some investigation, this only seems to happen when test_ui runs before test_zero - looks like this is possibly caused by one of the tests in test_ui not cleaning up after itself:

$ python -m nose --exclude-test=test.test_ui.CompletionTest test.test_zero
...bunch of output here...
----------------------------------------------------------------------
Ran 17 tests in 1.005s

OK

$ python -m nose --exclude-test=test.test_ui.CompletionTest test.test_ui test.test_zero
...bunch of output here...
======================================================================
FAIL: test_album_art (test.test_zero.ZeroPluginTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/beets/src/beets/test/test_zero.py", line 109, in test_album_art
    self.assertEqual(0, len(mf.images))
AssertionError: 0 != 1
-------------------- >> begin captured logging << --------------------
beets: DEBUG: Sending event: write
beets: DEBUG: Sending event: after_write
--------------------- >> end captured logging << ---------------------

----------------------------------------------------------------------
Ran 137 tests in 6.493s

FAILED (SKIP=1, failures=1)

I'll see if I can narrow it down to a specific UI test.

[jackwilsdon]

So I've narrowed it down to test.test_ui:ConfigTest.test_cli_config_file_loads_plugin_commands:

$ python -m nose test.test_ui:ConfigTest.test_cli_config_file_loads_plugin_commands test.test_zero:ZeroPluginTest.test_album_art
.F
======================================================================
FAIL: test_album_art (test.test_zero.ZeroPluginTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/beets/src/beets/test/test_zero.py", line 43, in test_album_art
    self.assertEqual(0, len(mf.images))
AssertionError: 0 != 1

----------------------------------------------------------------------
Ran 2 tests in 0.160s

FAILED (failures=1)

Oddly enough, I can't reproduce this issue within tox on macOS:

$ tox -e py-test test/test_ui.py::ConfigTest::test_cli_config_file_loads_plugin_commands test/test_zero.py::ZeroPluginTest::test_album_art
GLOB sdist-make: /beets/setup.py
py-test create: /beets/.tox/py-test
py-test installdeps: .[test]
py-test inst: /beets/.tox/.tmp/package/1/beets-1.5.0.zip
py-test installed: attrs==21.2.0,beautifulsoup4==4.9.3,beets @ file:///beets/.tox/.tmp/package/1/beets-1.5.0.zip,certifi==2021.5.30,charset-normalizer==2.0.4,click==8.0.1,confuse==1.5.0,coverage==5.5,discogs-client==2.3.0,Flask==2.0.1,idna==3.2,iniconfig==1.1.1,itsdangerous==2.0.1,jellyfish==0.8.8,Jinja2==3.0.1,MarkupSafe==2.0.1,mediafile==0.7.0,mock==4.0.3,munkres==1.1.4,musicbrainzngs==0.7.1,mutagen==1.45.1,oauthlib==3.1.1,packaging==21.0,pluggy==1.0.0,py==1.10.0,pylast==4.2.1,pyparsing==2.4.7,pytest==6.2.5,python-mpd2==3.0.4,pyxdg==0.27,PyYAML==5.4.1,rarfile==4.0,requests==2.26.0,requests-oauthlib==1.3.0,responses==0.13.4,six==1.16.0,soupsieve==2.2.1,toml==0.10.2,Unidecode==1.2.0,urllib3==1.26.6,Werkzeug==2.0.1
py-test run-test-pre: PYTHONHASHSEED='536063382'
py-test run-test: commands[0] | python -bb -m pytest test/test_ui.py::ConfigTest::test_cli_config_file_loads_plugin_commands test/test_zero.py::ZeroPluginTest::test_album_art
========================================= test session starts =========================================
platform darwin -- Python 3.9.6, pytest-6.2.5, py-1.10.0, pluggy-1.0.0
cachedir: .tox/py-test/.pytest_cache
rootdir: /beets
collected 2 items                                                                                     

test/test_ui.py .                                                                               [ 50%]
test/test_zero.py .                                                                             [100%]

========================================== 2 passed in 1.11s ==========================================
_______________________________________________ summary _______________________________________________
  py-test: commands succeeded
  congratulations :)

It seems to happen with both pytest and nose on my Arch Linux Docker container.

[jackwilsdon]

So this ended up being caused by test_cli_config_file_loads_plugin_commands loading a plugin into beets and then never resetting the instance lookup, meaning we ended up not loading any other plugins until unload_plugins was called.

I'm not sure why I can't reproduce this in tox on my local machine (or in tox on my Arch Linux container when running all tests), but I'll open a PR to sort this anyway.

[jackwilsdon]

Also, turns out the reason I couldn't reproduce this on my local machine was that I was miles behind master 🤦 after pulling down master, I can reproduce it on macOS.

[sampsyo]

Wow! Really great detective work, @jackwilsdon—that's a really nasty problem! Thanks for tracking down the naughty test.

[ss2]

Oh, thanks a lot! I wouldn't have expected this to be solved in such a short time, and the way it turned out to be. Great work!