search

beetbox / beets

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

Assertion error when importing in threaded mode #1467

Closed steveh closed 8 years ago

steveh commented 9 years ago

When using threaded=yes I get this error quite quickly:

Traceback (most recent call last):
  File "/usr/local/bin/beet", line 9, in <module>
    load_entry_point('beets==1.3.13', 'console_scripts', 'beet')()
  File "/usr/local/lib/python2.7/dist-packages/beets/ui/__init__.py", line 1104, in main
    _raw_main(args)
  File "/usr/local/lib/python2.7/dist-packages/beets/ui/__init__.py", line 1094, in _raw_main
    subcommand.func(lib, suboptions, subargs)
  File "/usr/local/lib/python2.7/dist-packages/beets/ui/commands.py", line 893, in import_func
    import_files(lib, paths, query)
  File "/usr/local/lib/python2.7/dist-packages/beets/ui/commands.py", line 870, in import_files
    session.run()
  File "/usr/local/lib/python2.7/dist-packages/beets/importer.py", line 316, in run
    pl.run_parallel(QUEUE_SIZE)
  File "/usr/local/lib/python2.7/dist-packages/beets/util/pipeline.py", line 301, in run
    out = self.coro.send(msg)
  File "/usr/local/lib/python2.7/dist-packages/beets/util/pipeline.py", line 160, in coro
    task = func(*(args + (task,)))
  File "/usr/local/lib/python2.7/dist-packages/beets/importer.py", line 1258, in user_query
    plugins.send('import_task_choice', session=session, task=task)
  File "/usr/local/lib/python2.7/dist-packages/beets/plugins.py", line 455, in send
    result = handler(**arguments)
  File "/usr/local/lib/python2.7/dist-packages/beets/plugins.py", line 117, in wrapper
    assert self._log.level == logging.NOTSET
AssertionError

With threaded=no the importer runs just fine.

sampsyo commented 9 years ago

Can you please provide some more information to help reproduce the problem? For example, can you narrow down a plugin that's causing it? Does it happen every time, or just sometimes? Does it happen with particular music files? Which version are you running? Have you tried the latest source? Et cetera.

hrehfeld commented 9 years ago

$ pacman -Qi beets-git Name : beets-git Version : 1.3.13.r93.gce91a0c-1 Description : Flexible music library manager and tagger - git version Architecture : any URL : http://beets.radbox.org/ Licenses : MIT Groups : None Provides : beets Depends On : python2-munkres mutagen python2-setuptools python2-unidecode python2-musicbrainzngs python2-yaml python2-enum34 python2-jellyfish Optional Deps : python2-pyacoustid: acoustic fingerprinting [installed] python2-flask: web interface [installed] gstreamer0.10-python: BPD audio player plugin python2-pylast: lastgenre plugin [installed] Required By : beets-check-git beets-copyartifacts-git Optional For : None Conflicts With : beets Replaces : None Installed Size : 3.12 MiB Packager : Unknown Packager Build Date : Tue 23 Jun 2015 12:49:19 PM CEST Install Date : Tue 23 Jun 2015 12:49:24 PM CEST Install Reason : Explicitly installed Install Script : No Validated By : None

$ beet version beets version 1.3.14 plugins: check

sampsyo commented 9 years ago

Is there anything specific I can do on my end to reproduce this problem?

Does it still occur if you disable the beets-check plugin?

nathdwek commented 9 years ago

I had the same issue pop up after enabling the beets-check plugin. The error occured on the second album of a group import and didn't occur with beets-check disabled.

beet import --flat -g 2012\ -\ The\ Best\ Of\ Santana\ \(Sony\ Music\)/

<normal output for the first grouping, then starts a second grouping>

/common/torrents/Santana-Discography.1969-2013.Lossless/2012 - The Best Of Santana (Sony Music)/Vol.2/01. Persuasion.flac
/common/torrents/Santana-Discography.1969-2013.Lossless/2012 - The Best Of Santana (Sony Music)/Vol.2/02. You Just Don't Care.flac
/common/torrents/Santana-Discography.1969-2013.Lossless/2012 - The Best Of Santana (Sony Music)/Vol.2/03. Black Magic Woman,Gypsy Queen (Live).flac
/common/torrents/Santana-Discography.1969-2013.Lossless/2012 - The Best Of Santana (Sony Music)/Vol.2/04. Incident At Neshabur.flac
/common/torrents/Santana-Discography.1969-2013.Lossless/2012 - The Best Of Santana (Sony Music)/Vol.2/05. Se A Cabo.flac
/common/torrents/Santana-Discography.1969-2013.Lossless/2012 - The Best Of Santana (Sony Music)/Vol.2/06. Hope You're Feeling Better.flac
/common/torrents/Santana-Discography.1969-2013.Lossless/2012 - The Best Of Santana (Sony Music)/Vol.2/07. Toussaint L'Overture.flac
/common/torrents/Santana-Discography.1969-2013.Lossless/2012 - The Best Of Santana (Sony Music)/Vol.2/08. Guajira.flac
/common/torrents/Santana-Discography.1969-2013.Lossless/2012 - The Best Of Santana (Sony Music)/Vol.2/09. Everything's Coming Our Way.flac
/common/torrents/Santana-Discography.1969-2013.Lossless/2012 - The Best Of Santana (Sony Music)/Vol.2/10. Europa (Earth's Cry Heaven's Smile) (Live).flac
/common/torrents/Santana-Discography.1969-2013.Lossless/2012 - The Best Of Santana (Sony Music)/Vol.2/11. Stormy.flac
/common/torrents/Santana-Discography.1969-2013.Lossless/2012 - The Best Of Santana (Sony Music)/Vol.2/12. Well All Right.flac
/common/torrents/Santana-Discography.1969-2013.Lossless/2012 - The Best Of Santana (Sony Music)/Vol.2/13. One Chain (Don't Make No Prison).flac
/common/torrents/Santana-Discography.1969-2013.Lossless/2012 - The Best Of Santana (Sony Music)/Vol.2/14. Peace On Earth- Mother Earth- Third Stone From The Sun (Medley).flac (14 items)

Correcting tags from:
    Santana - The Best Of Santana Volume 2
To:
    Santana - The Best of Santana, Volume 2
URL:
    http://musicbrainz.org/release/92c67fbd-9131-4703-b8ca-30351f320d54
(Similarity: 99.9%) (tracks) (2000, US)
 * Black Magic Woman/Gypsy Queen (Live)                            -> Black Magic Woman / Gypsy Queen (live)
 * Incident At Neshabur                                            -> Incident at Neshabur
 * Se A Cabo                                                       -> Se Acabo
 * Europa (Earth's Cry Heaven's Smile) (Live)                      -> Europa (Earth's Cry Heaven's Smile) (live)
 * Peace On Earth- Mother Earth- Third Stone From The Sun (Medley) -> Peace on Earth... Mother Earth... Third Stone From the Sun (title)
Traceback (most recent call last):
  File "/bin/beet", line 9, in <module>
    load_entry_point('beets==1.3.14', 'console_scripts', 'beet')()
  File "/usr/lib/python2.7/site-packages/beets-1.3.14-py2.7.egg/beets/ui/__init__.py", line 1140, in main
    _raw_main(args)
  File "/usr/lib/python2.7/site-packages/beets-1.3.14-py2.7.egg/beets/ui/__init__.py", line 1130, in _raw_main
    subcommand.func(lib, suboptions, subargs)
  File "/usr/lib/python2.7/site-packages/beets-1.3.14-py2.7.egg/beets/ui/commands.py", line 881, in import_func
    import_files(lib, paths, query)
  File "/usr/lib/python2.7/site-packages/beets-1.3.14-py2.7.egg/beets/ui/commands.py", line 858, in import_files
    session.run()
  File "/usr/lib/python2.7/site-packages/beets-1.3.14-py2.7.egg/beets/importer.py", line 316, in run
    pl.run_parallel(QUEUE_SIZE)
  File "/usr/lib/python2.7/site-packages/beets-1.3.14-py2.7.egg/beets/util/pipeline.py", line 347, in run
    self.coro.send(msg)
  File "/usr/lib/python2.7/site-packages/beets-1.3.14-py2.7.egg/beets/util/pipeline.py", line 160, in coro
    task = func(*(args + (task,)))
  File "/usr/lib/python2.7/site-packages/beets-1.3.14-py2.7.egg/beets/importer.py", line 1376, in manipulate_files
    session=session,
  File "/usr/lib/python2.7/site-packages/beets-1.3.14-py2.7.egg/beets/importer.py", line 671, in manipulate_files
    item.try_write()
  File "/usr/lib/python2.7/site-packages/beets-1.3.14-py2.7.egg/beets/library.py", line 609, in try_write
    self.write(path, tags)
  File "/usr/lib/python2.7/site-packages/beets-1.3.14-py2.7.egg/beets/library.py", line 581, in write
    plugins.send('write', item=self, path=path, tags=item_tags)
  File "/usr/lib/python2.7/site-packages/beets-1.3.14-py2.7.egg/beets/plugins.py", line 458, in send
    result = handler(**arguments)
  File "/usr/lib/python2.7/site-packages/beets-1.3.14-py2.7.egg/beets/plugins.py", line 117, in wrapper
    assert self._log.level == logging.NOTSET
AssertionError
beets version 1.3.14
plugins: chroma, check, convert, duplicates, embedart, fetchart, info, missing, play, smartplaylist, zero
sampsyo commented 9 years ago

Hmm, this sounds like it could be an issue with the plugin. Could one of you please try asking the author if that seems plausible (perhaps by filing a bug with that project)?

sampsyo commented 8 years ago

Closing this issue since it seems to be a problem with beets-check.

wisp3rwind commented 8 years ago

In spite of this being closed, I'll note my observations, too, as I noticed this as well. First of all, the plugin seems to be horribly outdated as concerns the plugin API, so it may overall be a bad idea to use it. This doesn't affect the issue though.

After a little debugging, the error seems to occur because the plugin listens to several events ('item_imported', 'album_imported', 'write', 'after_write', 'after_convert', 'import_task_choice'). In threaded mode, after some time, these are likely to coincide, more so because calculating checksums can take a while.

Thus, I don't believe this to be a problem of beets-check only, but also a limitation of the plugin system. What is the precise reasoning behind asserting the loglevel to be NOTSET? The history shows changing this, but the comments don't mean a lot to me. Moreover, the previous loglevel restoring would not have the expected behaviour, either; the following would happen:

(I don't know how threading is implemented, however, and this reasoning could be mistaken)

sampsyo commented 8 years ago

Well, here's the thing: the beets logging logic specifically tried to prevent that problem. In logging.py, see ThreadLocalLevelLogger, which ensures that each thread can have an isolated logging level per-logger. So when task 1 and task 2 overlap in separate threads while adjusting their levels, they should never interact with each other—it should be impossible for one's level to pollute the other's.

Is there any chance something nasty is going on in that plugin that is preventing the thread-local level logic from kicking in?

wisp3rwind commented 8 years ago

It probably does, it doesn't log on self._log, but gets the logger with log = logging.getLogger('beets.check'). I believe there was some way to pass a thing named LoggerFactory or similiar to the Python logging infrastructure, that way plugins could be prevented from messing it up. Need to search that one.

sampsyo commented 8 years ago

That would do it!

It's probably best to avoid monkeypatching global modules, which can be a problem for testing and when embedding as a library, but we should indeed fix the function to use from beets import logging instead of import logging.

wisp3rwind commented 8 years ago

https://docs.python.org/2/library/logging.html#logging.setLoggerClass is what i was talking about, but it is indeed global.