beetbox / beets

music library manager and MusicBrainz tagger
http://beets.io/
MIT License
12.77k stars 1.82k forks source link

test suite errors #2400

Closed antlarr closed 4 years ago

antlarr commented 7 years ago

Problem

I'm trying to generate a beets package for openSUSE using python3 and got problems when running the test suite. Many tests fail with: "ValueError: underlying buffer has been detached" although that's not the ony problem happening.

The test output log is large, so I'll copy here the relevant parts:

abuild@geeko.site:/home/abuild/beets> python3 setup.py test
running test
running egg_info
writing dependency_links to beets.egg-info/dependency_links.txt
writing entry points to beets.egg-info/entry_points.txt
writing top-level names to beets.egg-info/top_level.txt
writing beets.egg-info/PKG-INFO
writing requirements to beets.egg-info/requires.txt
reading manifest file 'beets.egg-info/SOURCES.txt'
reading manifest template 'MANIFEST.in'
'test/rsrc/unicode\udce2\udc80\udc99d.mp3' not utf-8 encodable -- skipping
warning: no previously-included files matching '*.pyc' found under directory 'test/rsrc'
warning: no previously-included files matching '*.pyo' found under directory 'test/rsrc'
warning: no files found matching 'man/beet.1'
warning: no files found matching 'man/beetsconfig.5'
no previously-included directories found matching 'docs/_build'
warning: no previously-included files matching '.DS_Store' found anywhere in distribution
writing manifest file 'beets.egg-info/SOURCES.txt'
running build_ext
test_album_item (test_vfs.VFSTest) ... Sending event: database_change
Sending event: database_change
Sending event: database_change
Sending event: database_change
Sending event: database_change
Sending event: database_change
ok
test_singleton_item (test_vfs.VFSTest) ... Sending event: database_change
Sending event: database_change
Sending event: database_change
Sending event: database_change
Sending event: database_change
Sending event: database_change
ok

... I'll jump to where errors start happening ...

test_solo_pattern (test_autotag.StringDistanceTest) ... ok
test_different_artist (test_autotag.TrackDistanceTest) ... ok
test_different_title (test_autotag.TrackDistanceTest) ... ok
test_identical_tracks (test_autotag.TrackDistanceTest) ... ok
test_various_artists_tolerated (test_autotag.TrackDistanceTest) ... ok

======================================================================
ERROR: test_pretend_sync_from_itunes (test_metasync.MetaSyncTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/abuild/beets/test/test_metasync.py", line 95, in test_pretend_sync_from_itunes
    out = self.run_with_output('metasync', '-p')
  File "/home/abuild/beets/test/helper.py", line 449, in run_with_output
    self.run_command(*args)
  File "/usr/lib64/python3.5/contextlib.py", line 66, in __exit__
    next(self.gen)
  File "/home/abuild/beets/test/helper.py", line 118, in capture_stdout
    print(capture.getvalue())
ValueError: underlying buffer has been detached

======================================================================
ERROR: test_sync_from_itunes (test_metasync.MetaSyncTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/abuild/beets/test/test_metasync.py", line 106, in test_sync_from_itunes
    self.run_command('metasync')
  File "/home/abuild/beets/test/helper.py", line 445, in run_command
    beets.ui._raw_main(_convert_args(list(args)), lib)
  File "../beets/ui/__init__.py", line 1196, in _raw_main
    subcommand.func(lib, suboptions, subargs)
  File "/home/abuild/beets/beetsplug/metasync/__init__.py", line 138, in func
    changed = ui.show_model_changes(item)
  File "../beets/ui/__init__.py", line 714, in show_model_changes
    print_(format(old))
  File "../beets/ui/__init__.py", line 143, in print_
    sys.stdout.write(txt)
ValueError: underlying buffer has been detached

======================================================================
ERROR: test_track_request (test_spotify.SpotifyPluginTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "<string>", line 3, in wrapper
  File "/home/abuild/beets/test/test_spotify.py", line 101, in test_track_request
    self.spotify.output_results(results)
  File "/home/abuild/beets/beetsplug/spotify.py", line 173, in output_results
    print(self.open_url + item)
ValueError: underlying buffer has been detached

======================================================================
ERROR: test_flex_field_type (test_plugins.ItemTypesTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/abuild/beets/test/test_plugins.py", line 81, in test_flex_field_type
    out = self.run_with_output(u'ls', u'rating:1..3')
  File "/home/abuild/beets/test/helper.py", line 449, in run_with_output
    self.run_command(*args)
  File "/usr/lib64/python3.5/contextlib.py", line 66, in __exit__
    next(self.gen)
  File "/home/abuild/beets/test/helper.py", line 118, in capture_stdout
    print(capture.getvalue())
ValueError: underlying buffer has been detached

======================================================================
ERROR: test_broken_symlink (test_mediafile_edge.SafetyTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/abuild/beets/test/test_mediafile_edge.py", line 193, in test_broken_symlink
    os.symlink('does_not_exist', fn)
PermissionError: [Errno 13] Permission denied: 'does_not_exist' -> b'/home/abuild/beets/test/rsrc/brokenlink'

... and more errors keep coming, but I'll jump to the end of the test output ...

======================================================================
ERROR: test_integer_modify_and_query (test_types_plugin.TypesPluginTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/abuild/beets/test/test_types_plugin.py", line 42, in test_integer_modify_and_query
    out = self.list(u'myint:1..3')
  File "/home/abuild/beets/test/test_types_plugin.py", line 153, in list
    return self.run_with_output(u'ls', u'-f', fmt, query).strip()
  File "/home/abuild/beets/test/helper.py", line 449, in run_with_output
    self.run_command(*args)
  File "/usr/lib64/python3.5/contextlib.py", line 66, in __exit__
    next(self.gen)
  File "/home/abuild/beets/test/helper.py", line 118, in capture_stdout
    print(capture.getvalue())
ValueError: underlying buffer has been detached

======================================================================
ERROR: test_update_library (test_mbsync.MbsyncCliTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/usr/lib/python3.5/site-packages/mock/mock.py", line 1305, in patched
    return func(*args, **keywargs)
  File "/home/abuild/beets/test/test_mbsync.py", line 64, in test_update_library
    self.run_command('mbsync')
  File "/home/abuild/beets/test/helper.py", line 445, in run_command
    beets.ui._raw_main(_convert_args(list(args)), lib)
  File "../beets/ui/__init__.py", line 1196, in _raw_main
    subcommand.func(lib, suboptions, subargs)
  File "/home/abuild/beets/beetsplug/mbsync.py", line 72, in func
    self.albums(lib, query, move, pretend, write)
  File "/home/abuild/beets/beetsplug/mbsync.py", line 149, in albums
    item_changed = ui.show_model_changes(item)
  File "../beets/ui/__init__.py", line 714, in show_model_changes
    print_(format(old))
  File "../beets/ui/__init__.py", line 143, in print_
    sys.stdout.write(txt)
ValueError: underlying buffer has been detached

======================================================================
FAIL: test_read_audio_properties (test_mediafile.FlacTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/abuild/beets/test/test_mediafile.py", line 435, in test_read_audio_properties
    self.assertEqual(getattr(mediafile, key), value)
AssertionError: 175120 != 108688

======================================================================
FAIL: test_import_converted (test_convert.ImportConvertTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/abuild/beets/test/test_convert.py", line 102, in test_import_converted
    self.assertFileTag(item.path, 'convert')
  File "/home/abuild/beets/test/test_convert.py", line 58, in assertFileTag
    display_tag))
AssertionError: b'\x00\x00\x00\x00\x00\x00\x00' != b'convert' : /tmp/tmpoti52slt/libdir/artist/album 0/02 track 0.mp3 is not tagged with convert

----------------------------------------------------------------------
Ran 1740 tests in 100.026s

FAILED (failures=2, errors=88, skipped=60)
Test failed: <unittest.runner.TextTestResult run=1740 errors=88 failures=2>
error: Test failed: <unittest.runner.TextTestResult run=1740 errors=88 failures=2>
Exception ignored in: <_io.TextIOWrapper mode='w' encoding='ANSI_X3.4-1968'>
ValueError: underlying buffer has been detached
sys:1: ResourceWarning: unclosed file <_io.BufferedReader name=6>
sys:1: ResourceWarning: unclosed file <_io.BufferedWriter name=5>

Setup

Just in case it helps, I'm using: python3-audioread-2.1.4 python3-cookies-2.2.1 python3-discogs-client-2.2.1 python3-jellyfish-0.5.6 python3-munkres-1.0.9 python3-pyacoustid-1.1.4 python3-python-mpd2-0.5.5 python3-responses-0.5.1 python3-musicbrainzngs-0.6 with some patches from the git repository:

Open XML files in binary mode, as they contain non-ASCII https://github.com/alastair/python-musicbrainzngs/commit/3ff4ace30954b6254ada397089bf594229bcb336

Remove duplicate import https://github.com/alastair/python-musicbrainzngs/commit/01efb005620f78cceb2d627ec42fd56bb8a2b367

Convert the CAA response data to unicode before loading it via json https://github.com/alastair/python-musicbrainzngs/commit/d90967eac38ffe66e455137077e09ee16aa04c79

add "work-level-rels" support for recording lookup https://github.com/alastair/python-musicbrainzngs/commit/2cc2266f8b2102556cffa4fd75b036ed2d8e9d61

Also, the output from the builds at the openSUSE build service can be seen at: https://build.opensuse.org/build/home:alarrosa:branches:devel:languages:python3/openSUSE_Factory/x86_64/beets/_log and the package sources, at https://build.opensuse.org/package/show/home:alarrosa:branches:devel:languages:python3/beets Note that the build service is building beets 1.4.3, not the git version.

If you need any other information or want me to test anything, please tell me.

ghost commented 7 years ago

what happens if you use nose to run the test suite instead of python setup.py test?

sampsyo commented 7 years ago

Wow; I'm pretty stumped—I don't see a reason why this would happen, but it looks like the StringIO object we're using to collect output is having .detach() called on it, but we never do that in our tests.

Can you try running one or two of the failing tests alone to see if this still happens? (Or, I suppose I should ask: does this happen on your local machine, or just on the build servers?)

ghost commented 7 years ago

@sampsyo : interesting tidbit in the logs (but unrelated to the core problem)

reading manifest template 'MANIFEST.in'
'test/rsrc/unicode\udce2\udc80\udc99d.mp3' not utf-8 encodable -- skipping
sampsyo commented 7 years ago

Interesting! This setuptools issue looks related, perhaps? https://github.com/pypa/setuptools/issues/193

antlarr commented 7 years ago

Can you try running one or two of the failing tests alone to see if this still happens? (Or, I suppose I should ask: does this happen on your local machine, or just on the build servers?)

I finally installed all the dependencies on my machine and run the tests with "nosetests". I definitely got far fewer errors (and none of the "underlying buffer has been detached" issues) . After a while testing I found and fixed a problem (I'll create the pull request in a moment) related to python2/3 and reduced the failing issues to two:

======================================================================
ERROR: test_command_line_option_relative_to_working_dir (test.test_ui.ConfigTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/DD4/antonio/git/beets/test/test_ui.py", line 893, in test_command_line_option_relative_to_working_dir
    self.run_command('--library', 'foo.db', 'test', lib=None)
  File "/mnt/DD4/antonio/git/beets/test/helper.py", line 445, in run_command
    beets.ui._raw_main(_convert_args(list(args)), lib)
  File "../beets/ui/__init__.py", line 1192, in _raw_main
    subcommands, plugins, lib = _setup(options, lib)
  File "../beets/ui/__init__.py", line 1085, in _setup
    mb.configure()
  File "../beets/autotag/mb.py", line 81, in configure
    hostname = config['musicbrainz']['host'].as_str()
  File "../beets/util/confit.py", line 420, in as_str
    return self.get(String())
  File "../beets/util/confit.py", line 389, in get
    return as_template(template).value(self, template)
  File "../beets/util/confit.py", line 1005, in value
    raise NotFoundError(u"{0} not found".format(view.name))
beets.util.confit.NotFoundError: musicbrainz.host not found

======================================================================
FAIL: test_read_audio_properties (test.test_mediafile.FlacTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/DD4/antonio/git/beets/test/test_mediafile.py", line 435, in test_read_audio_properties
    self.assertEqual(getattr(mediafile, key), value)
AssertionError: 175120 != 108688

----------------------------------------------------------------------
Ran 1746 tests in 38.351s

FAILED (SKIP=43, errors=1, failures=1)

I'm not sure if SKIP=43 is ok (python3 setup.py test gives the same number), but in theory shouldn't be a problem :).

About the remaining two issues, I had a look at what test_read_audio_properties (test.test_mediafile.FlacTest) does and noticed the assert is checking the properties of the rsrc/full.flac file. I tested with ffprobe and got: Duration: 00:00:01.00, start: 0.000000, bitrate: 175 kb/s Are you sure the assertion is right and the file has a bitrate of 108688 ?

With the other I'm not sure what to do. I didn't install beets (is that necessary before running the tests?) so I guess beets/config_default.yaml is the configuration used by the tests, and there I have:

musicbrainz:
    host: musicbrainz.org

So I'm not sure why it says musicbrainz.host is not found. Any idea?

Finally, I guess the detached buffer issues are related to being run in a chroot. I'll see if I can do more tests about that and give you more information, since I guess it's difficult to reproduce for you.

antlarr commented 7 years ago

I found the reason for the detached buffer issues. When the test suite is run in a chroot, it's run by a local (to the chroot system) user that doesn't have a locale set in the environment. Changing the test command line to:

LC_CTYPE=C.UTF8 python3 setup.py test

fixes those errors.

After doing that and adding the patch in the pull request above (Run python2 or python3 ...) I'm getting the above two errors from the previous comment both locally and in the build server too (the musicbrainz.host issue and the flac bitrate assert issue)

sampsyo commented 7 years ago

I'm surprised that the "detached buffer" errors can be solved by setting a locale—that's somewhat worrisome. I've tried unsetting LC_TYPE to no avail, so let us know if you have any bright ideas for how to reproduce the problem.

antlarr commented 7 years ago

I've tried unsetting LC_TYPE to no avail, so let us know if you have any bright ideas for how to reproduce the problem.

note that the variable name is LC_CTYPE, I just tested on my local system and running:

unset LC_CTYPE
python3 setup.py test

reproduces the problem and I get the "detached buffer" errors. I guess the problem is not the locale as in "the language used" but the locale as in "the coding of the terminal". If it's not configured maybe some python subsystem just detaches it, so that incorrect coding is not written to the terminal or something like that.

sampsyo commented 7 years ago

OK, thanks! (And sorry for the typo in that variable name above; I did mean LC_CTYPE.)

It looks like I can reproduce the problem (also using PYTHONIOENCODING=ascii) only with setup.py test; using Nose (as we usually do) does not cause the problem. I also can't seem to trigger the problem when running individual test files like so:

PYTHONIOENCODING=ascii PYTHONPATH=. python3 test/test_zero.py

So it seems like this is somehow connected to the setuptools test runner? That thing seems to do nothing but cause problems.

Have you found a way to run one test at a time and still exhibit this failure?

antlarr commented 7 years ago

Have you found a way to run one test at a time and still exhibit this failure?

I'm afraid not, but I can run the tests with

LC_CTYPE=C.UTF8 python3 setup.py test

and that works for me. Btw, it's interesting that Nose works fine too, indeed. The only remaining issues that worry me are the ones mentioned a few comments above (the test.flac bitrate issue and the mediabrainz.host not found error). Any idea about those?

sampsyo commented 7 years ago

Weird. The "buffer detached" thing will remain a mystery for now, I guess…

The FLAC bitrate error is probably due to the Mutagen version. A recent version made its bitrate calculation more accurate, and the test now conforms to that new number.

I don't see an obvious cause for the musicbrainz.host thing—is that something we can reproduce in isolation?

Also, did you get a chance to look at #2408, which might solve the problems with the convert plugin?

antlarr commented 7 years ago

Thanks! I updated the python3-mutagen package from 1.34.1 to 1.36.1 and the FLAC bitrate error is gone now. Now only the musicbrainz.host issue is left. I can't reproduce it locally with setuptools. In fact, when running python3 setup.py test locally, either from git or 1.4.3 (patched for the test_convert issue) I get another failure:

======================================================================
FAIL: test_add_tags (test_thumbnails.ThumbnailsTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/usr/lib/python3.5/site-packages/mock/mock.py", line 1305, in patched
    return func(*args, **keywargs)
  File "/mnt/DD4/antonio/beets-1.4.3/test/test_thumbnails.py", line 66, in test_add_tags
    mock_stat.assert_called_once_with(album.artpath)
  File "/usr/lib/python3.5/site-packages/mock/mock.py", line 947, in assert_called_once_with
    raise AssertionError(msg)
AssertionError: Expected 'stat' to be called once. Called 2 times.

But when I use nosetests (or nosetests test_ui.py) I get the musicbrainz.host error and not the stat called 2 times error.

About #2408... It works at removing the dependencies, but I'm afraid it doesn't fix the issue completely. It tries to run "python" but command_output has shell=False by default, so it's not searched in the PATH and so, it complains about the python executable not being found. I tried replacing return u"python '{}' $source $dest {}".format(stub, tag) in test_convert.py with return u"/usr/bin/python '{}' $source $dest {}".format(stub, tag) and that works fine, but I guess that won't work on windows. I also tried using sys.executable there, and that works too.

sampsyo commented 7 years ago

Dang; that is truly mysterious! I've tried several ways, and I can't seem to reproduce either of these—it's hard to see exactly what's going wrong in both cases. It must be an OS-related thing—maybe I should try spinning up an openSUSE VM?

OK, thanks for the feedback about #2408. It sounds like we just have to shell-escape sys.executable or look for a completely different strategy. I'll probably merge that PR anyway to simplify things, but this will require more work…

arcresu commented 5 years ago

I noticed that Debian has disabled the same test in a patch, presumably for the same musicbrainz.host failure. This actually looks like the same symptom we were seeing when you try to run beets as a zipped egg, and it isn't able to load the default config file. In that scenario, there are no default config values so that would explain the message. Is there any chance that was what was going on here @antlarr?

stale[bot] commented 4 years ago

Is this still relevant? If so, what is blocking it? Is there anything you can do to help move it forward?

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.