whipper
whipper copied to clipboard
whipper-team
`whipper cd rip` results in error reading TOC
Steps to Reproduce
- Insert specific CDs (https://musicbrainz.org/release-group/e1ba148a-2a49-3a64-8c27-0d894aff56fe)
- $ whipper cd -d /dev/sr1 rip
Expected Results
CD whips
Actual
Throws a stack trace in my one drive, not in my other. Very strange
Stack trace
Traceback (most recent call last):
File "/usr/lib/python3.9/site-packages/whipper/extern/task/task.py", line 523, in c
callable_task(*args, **kwargs)
File "/usr/lib/python3.9/site-packages/whipper/program/cdrdao.py", line 115, in _read
self._done()
File "/usr/lib/python3.9/site-packages/whipper/program/cdrdao.py", line 153, in _done
self.toc.parse()
File "/usr/lib/python3.9/site-packages/whipper/image/toc.py", line 202, in parse
with open(self._path) as f:
FileNotFoundError: [Errno 2] No such file or directory: '/tmp/tmp7foc7nnu.cdrdao.read-toc.whipper.task'
Reproducibility
This happened twice on the same CD and not before it. The next CD in my library read the TOC fine.
Environment & Drive info
OS: Arch Linux Kernel: Linux 5.11.7-arch1-1 #1 SMP PREEMPT Wed, 17 Mar 2021 16:59:58 +0000 x86_64 GNU/Linux Build: whipper-git 0.9.1.dev109+g87f3d00-1
Bad Drive
[drive:TSSTcorp%3ACDDVDW%20SH-S203N%20%3ASB02]
vendor = TSSTcorp
model = CDDVDW SH-S203N
release = SB02
defeats_cache = True
read_offset = 6
Good drive
[drive:HL-DT-ST%3ADVDRAM%20GH24NS90%20%3AIN01]
vendor = HL-DT-ST
model = DVDRAM GH24NS90
release = IN01
defeats_cache = False
read_offset = 6
I got this again on https://musicbrainz.org/release/d5584f09-5c97-46e6-82ab-49782fac1d90, but ran it again with debug and then it worked.
That makes it seem less input based.
A third time on https://musicbrainz.org/release/f5526c13-4a30-47ce-9f3c-b5d1c085b71c Ran it again, same error. Ran it with debug, started passing.
Hm!
Finally got one to fail while debug was on
DEBUG:whipper.common.config:loaded 5 sections from config file
DEBUG:whipper.common.config:loaded 5 sections from config file
DEBUG:whipper.common.config:loaded 5 sections from config file
DEBUG:whipper.common.config:loaded 5 sections from config file
DEBUG:whipper.common.config:loaded 5 sections from config file
DEBUG:whipper.common.config:loaded 5 sections from config file
DEBUG:whipper.common.config:looking at section 'drive:ASUS%20%20%20%20%3ABW-16D1HT%20%20%20%20%20%20%20%3A1.01'
DEBUG:whipper.common.config:vendor: 'HL-DT-ST' versus 'ASUS'
DEBUG:whipper.common.config:model: 'DVDRAM GH24NS90 ' versus 'BW-16D1HT'
DEBUG:whipper.common.config:release: 'IN01' versus '1.01'
DEBUG:whipper.common.config:looking at section 'drive:HL-DT-ST%3ADVDRAM%20GH20NS10%20%3AEL01'
DEBUG:whipper.common.config:vendor: 'HL-DT-ST' versus 'HL-DT-ST'
DEBUG:whipper.common.config:model: 'DVDRAM GH24NS90 ' versus 'DVDRAM GH20NS10'
DEBUG:whipper.common.config:release: 'IN01' versus 'EL01'
DEBUG:whipper.common.config:looking at section 'drive:TSSTcorp%3ACDDVDW%20SH-S203N%20%3ASB02'
DEBUG:whipper.common.config:vendor: 'HL-DT-ST' versus 'TSSTcorp'
DEBUG:whipper.common.config:model: 'DVDRAM GH24NS90 ' versus 'CDDVDW SH-S203N'
DEBUG:whipper.common.config:release: 'IN01' versus 'SB02'
DEBUG:whipper.common.config:looking at section 'drive:HL-DT-ST%3ADVDRAM%20GH24NS90%20%3AIN01'
DEBUG:whipper.common.config:vendor: 'HL-DT-ST' versus 'HL-DT-ST'
DEBUG:whipper.common.config:model: 'DVDRAM GH24NS90 ' versus 'DVDRAM GH24NS90'
DEBUG:whipper.common.config:release: 'IN01' versus 'IN01'
INFO:whipper.command.cd:using configured read offset 6
DEBUG:whipper.common.config:loaded 5 sections from config file
DEBUG:whipper.common.config:loaded 5 sections from config file
DEBUG:whipper.common.config:loaded 5 sections from config file
DEBUG:whipper.common.config:loaded 5 sections from config file
DEBUG:whipper.common.config:loaded 5 sections from config file
DEBUG:whipper.common.config:loaded 5 sections from config file
DEBUG:whipper.common.config:loaded 5 sections from config file
DEBUG:whipper.common.config:loaded 5 sections from config file
DEBUG:whipper.common.config:loaded 5 sections from config file
DEBUG:whipper.common.config:loaded 5 sections from config file
DEBUG:whipper.common.config:loaded 5 sections from config file
DEBUG:whipper.common.config:loaded 5 sections from config file
DEBUG:whipper.common.config:loaded 5 sections from config file
INFO:whipper.command.cd:checking device /dev/sr0
DEBUG:whipper.program.utils:loading (eject -t) device /dev/sr0
DEBUG:whipper.program.utils:possibly unmount real path '/dev/sr0'
DEBUG:whipper.extern.task.task:run task <whipper.program.cdrdao.ReadTOCTask object at 0x7f3e7854aca0>
DEBUG:whipper.extern.task.task:Adding listener <whipper.common.task.SyncRunner object at 0x7f3e7854ae50>
DEBUG:whipper.extern.task.task:run loop
DEBUG:whipper.extern.task.task:start task <whipper.program.cdrdao.ReadTOCTask object at 0x7f3e7854aca0>
DEBUG:whipper.extern.task.task:starting
DEBUG:whipper.extern.task.task:notifying progress: 0.0 on 'Reading TOC'
DEBUG:whipper.extern.task.task:notifying progress: 1.0 on 'Reading TOC'
DEBUG:whipper.image.table:set logName
DEBUG:whipper.extern.task.task:exception when calling scheduled callable <bound method ReadTOCTask._read of <whipper.program.cdrdao.ReadTOCTask object at 0x7f3e7854aca0>>
DEBUG:whipper.extern.task.task:set exception, FileNotFoundError(2, 'No such file or directory'), "exception FileNotFoundError at /usr/lib/python3.9/site-packages/whipper/image/toc.py:191: parse(): [Errno 2] No such file or directory: '/tmp/tmpbl3apng7.cdrdao.read-toc.whipper.task'"
DEBUG:whipper.extern.task.task:stopped task <whipper.program.cdrdao.ReadTOCTask object at 0x7f3e7854aca0>
DEBUG:whipper.extern.task.task:done running task <whipper.program.cdrdao.ReadTOCTask object at 0x7f3e7854aca0>
DEBUG:whipper.extern.task.task:raising TaskException for "exception FileNotFoundError at /usr/lib/python3.9/site-packages/whipper/image/toc.py:191: parse(): [Errno 2] No such file or directory: '/tmp/tmpbl3apng7.cdrdao.read-toc.whipper.task'", 'Traceback (most recent call last):\n File "/usr/lib/python3.9/site-packages/whipper/extern/task/task.py", line 518, in c\n callable_task(*args, **kwargs)\n File "/usr/lib/python3.9/site-packages/whipper/program/cdrdao.py", line 111, in _read\n self._done()\n File "/usr/lib/python3.9/site-packages/whipper/program/cdrdao.py", line 149, in _done\n self.toc.parse()\n File "/usr/lib/python3.9/site-packages/whipper/image/toc.py", line 191, in parse\n with open(self._path) as f:\nFileNotFoundError: [Errno 2] No such file or directory: \'/tmp/tmpbl3apng7.cdrdao.read-toc.whipper.task\'\n'
CRITICAL:whipper.command.main:exception FileNotFoundError at /usr/lib/python3.9/site-packages/whipper/image/toc.py:191: parse(): [Errno 2] No such file or directory: '/tmp/tmpbl3apng7.cdrdao.read-toc.whipper.task'
Traceback (most recent call last):
File "/usr/lib/python3.9/site-packages/whipper/extern/task/task.py", line 518, in c
callable_task(*args, **kwargs)
File "/usr/lib/python3.9/site-packages/whipper/program/cdrdao.py", line 111, in _read
self._done()
File "/usr/lib/python3.9/site-packages/whipper/program/cdrdao.py", line 149, in _done
self.toc.parse()
File "/usr/lib/python3.9/site-packages/whipper/image/toc.py", line 191, in parse
with open(self._path) as f:
FileNotFoundError: [Errno 2] No such file or directory: '/tmp/tmpbl3apng7.cdrdao.read-toc.whipper.task'
This is now reproduced on the latest Arch release of whipper, 0.9.0-2.
I would not oppose hearing this is a device fault as it's so sporadic, but next is to look into the code.
It could either be a bug in whipper's code (race condition, for example), a transient failure of cdrdao (which, I guess, sporadically fails to rip that CD) or a device fault. Maybe you could try running cdrdao multiple times against that same CD to see if that's where the failure is coming from.
sudo umount /dev/sr1
cdrdao disk-info --device /dev/sr1 > cdrdao_disk-info.log 2>&1
cdrdao read-toc --device /dev/sr1 --fast-toc cdrdao_fast.toc > cdrdao_read-toc_fast.log 2>&1
cdrdao read-toc --device /dev/sr1 cdrdao_slow.toc > cdrdao_read-toc_slow.log 2>&1
If cdrdao does fail, please attach the following files: cdrdao_disk-info.log, cdrdao_read-toc_fast.log, cdrdao_read-toc_slow.log, cdrdao_fast.toc, cdrdao_slow.toc.
I've run it a couple times and based on how it has behaved over hundreds of imports through whipper and other programs where the drive is very stable and returning Accurate Rips, I'd put my vote on race condition or device fault here.
I am leaning towards race condition with that tmp file. Are there any best places to notice device faults otherwise to disprove that leading theory?
Hello, I seem to be able to reproduce this problem. I am also on Arch Linux, with kernel 5.12.10-zen1-1-zen x86_64 and have tried both whipper 0.10.0 and whipper-git 0.10.1.dev8+g09f6bf1-1
About half of my CDs will rip successfully every time I try, while others fail in a strange way every time. (Edit: Upon setting the correct offset, now all CDs that would have worked before will fail to read the last track, but that's a separate issue due to upstream rocky/libcdio-paranoia#14. Some still fail to read TOC.)
For the CDs that fail, whipper hangs for several minutes at reading the TOC, and doesn't appear to succeed in doing so. It then eventually returns the MusicBrainz info, and attempting to confirm it results in whipper incorrectly claiming the CD is a CD-R:
INFO:whipper.command.cd:using configured read offset 587
INFO:whipper.command.cd:checking device /dev/sr0
CDDB disc id: f6122910
MusicBrainz disc id 0dfqq.yaBIBrAW.aIgjY1KOv0hU-
MusicBrainz lookup URL https://musicbrainz.org/cdtoc/attach?toc=1+16+348888+150+33979+57362+73103+91992+114878+134806+152638+173865+199264+221763+242674+264619+279836+299031+324994&tracks=16&id=0dfqq.yaBIBrAW.aIgjY1KOv0hU-
Disc duration: 01:17:29.840, 16 audio tracks
Matching releases:
Artist : Judge Jules
Title : Ministry of Sound: The Very Best of Tried & Tested Euphoria (Disc 3 of 3)
Duration: 01:17:31.000
URL : https://musicbrainz.org/release/ce9e4d56-202f-3cc1-a3c5-d1d2dfb657f0
Release : ce9e4d56-202f-3cc1-a3c5-d1d2dfb657f0
Type : Compilation
Country : United States
Artist : Judge Jules
Title : Euphoria: The Very Best of Tried & Tested (Disc 3 of 3)
Duration: 01:17:31.000
URL : https://musicbrainz.org/release/13619f4d-87b3-4403-987b-6615cc64ebd0
Release : 13619f4d-87b3-4403-987b-6615cc64ebd0
Type : Compilation
Barcode : 5026535512325
Country : United Kingdom
Cat no : EUPCD5
Please select a release [ce9e4d56-202f-3cc1-a3c5-d1d2dfb657f0]: 13619f4d-87b3-4403-987b-6615cc64ebd0
INFO:whipper.common.program:picked requested release id 13619f4d-87b3-4403-987b-6615cc64ebd0
Artist: Judge Jules
Title : Euphoria: The Very Best of Tried & Tested (Disc 3 of 3)
CRITICAL:whipper.command.cd:inserted disc seems to be a CD-R, --cdr not passed
At this moment, the CD drive shuts off and becomes unresponsive. Attempting to run the command again results in No CD-DA drives found, and I have to unplug and replug the CD drive for anything to happen again. Note that this is a 3-disc set, and discs 1 and 2 ripped perfectly fine. I have several other unrelated CDs that either work fine or fail in the same exact ways, so I don't think it's a weird quirk with this particular CD. abcde and k3b rip all these CDs perfectly fine.
If I run it with the --cdr option as suggested, I get the same result but with the following appended:
Traceback (most recent call last):
File "/usr/lib/python3.9/site-packages/whipper/extern/task/task.py", line 523, in c
callable_task(*args, **kwargs)
File "/usr/lib/python3.9/site-packages/whipper/program/cdrdao.py", line 115, in _read
self._done()
File "/usr/lib/python3.9/site-packages/whipper/program/cdrdao.py", line 153, in _done
self.toc.parse()
File "/usr/lib/python3.9/site-packages/whipper/image/toc.py", line 202, in parse
with open(self._path) as f:
FileNotFoundError: [Errno 2] No such file or directory: '/tmp/tmp29jh3ns0.cdrdao.read-toc.whipper.task'
CRITICAL:whipper.command.main:exception FileNotFoundError at /usr/lib/python3.9/site-packages/whipper/image/toc.py:202: parse(): [Errno 2] No such file or directory: '/tmp/tmp29jh3ns0.cdrdao.read-toc.whipper.task'
Traceback (most recent call last):
File "/usr/lib/python3.9/site-packages/whipper/extern/task/task.py", line 523, in c
callable_task(*args, **kwargs)
File "/usr/lib/python3.9/site-packages/whipper/program/cdrdao.py", line 115, in _read
self._done()
File "/usr/lib/python3.9/site-packages/whipper/program/cdrdao.py", line 153, in _done
self.toc.parse()
File "/usr/lib/python3.9/site-packages/whipper/image/toc.py", line 202, in parse
with open(self._path) as f:
FileNotFoundError: [Errno 2] No such file or directory: '/tmp/tmp29jh3ns0.cdrdao.read-toc.whipper.task'
While this occurs, journalctl reports the following:
Jun 13 13:49:11 ArchDesktop kernel: usb 1-3: reset high-speed USB device number 5 using xhci_hcd
Jun 13 13:49:16 ArchDesktop kernel: usb 1-3: device descriptor read/64, error -110
Jun 13 13:49:32 ArchDesktop kernel: usb 1-3: device descriptor read/64, error -110
Jun 13 13:49:32 ArchDesktop kernel: usb 1-3: reset high-speed USB device number 5 using xhci_hcd
Jun 13 13:49:38 ArchDesktop kernel: usb 1-3: device descriptor read/64, error -110
Jun 13 13:49:50 ArchDesktop rtkit-daemon[1782]: Supervising 7 threads of 4 processes of 1 users.
Jun 13 13:49:50 ArchDesktop rtkit-daemon[1782]: Supervising 7 threads of 4 processes of 1 users.
Jun 13 13:49:54 ArchDesktop kernel: usb 1-3: device descriptor read/64, error -110
Jun 13 13:49:54 ArchDesktop kernel: usb 1-3: reset high-speed USB device number 5 using xhci_hcd
Jun 13 13:49:59 ArchDesktop kernel: usb 1-3: device descriptor read/8, error -110
Jun 13 13:50:04 ArchDesktop kernel: usb 1-3: device descriptor read/8, error -110
Jun 13 13:50:04 ArchDesktop kernel: usb 1-3: reset high-speed USB device number 5 using xhci_hcd
Jun 13 13:50:10 ArchDesktop kernel: usb 1-3: device descriptor read/8, error -110
Jun 13 13:50:15 ArchDesktop kernel: usb 1-3: device descriptor read/8, error -110
Jun 13 13:50:15 ArchDesktop kernel: usb 1-3: USB disconnect, device number 5
Jun 13 13:50:15 ArchDesktop kernel: usb 1-3: new high-speed USB device number 6 using xhci_hcd
Jun 13 13:50:21 ArchDesktop kernel: usb 1-3: device descriptor read/64, error -110
Based on the suggestion from this article, I tried unplugging my computer and all its devices overnight in case it was some weird power supply issue, but that didn't make a difference.
I have attached the whipper debug log and cdrdao logs listed by Joe.
- whipper.log.gz
- cdrdao_disk-info.log
- cdrdao_read-toc_fast.log
- cdrdao_read-toc_slow.log
- cdrdao_fast.toc.txt
- cdrdao_slow.toc.txt
i actually had this error when trying to read the wrong disk in a stack of CDRs. the error from cdrdao was the very helpful:
anarcat@angela:~$ cdrdao read-toc --device /dev/sr0 --fast-toc cdrdao_fast.toc
Cdrdao version 1.2.4 - (C) Andreas Mueller <[email protected]>
/dev/sr0: TSSTcorp CDDVDW TS-L633A Rev: TO01
Using driver: Generic SCSI-3/MMC - Version 2.0 (options 0x0000)
ERROR: Inserted disk is empty.
anarcat@angela:mp3[1]$
it might have been nice to answer that instead of throwing an exception. ;)
I got the same exception but cdrdao fails with Unit not ready, giving up.
$ whipper -v
whipper 0.10.0
$ whipper cd rip --prompt --output-directory .
INFO:whipper.command.cd:using configured read offset 102
INFO:whipper.command.cd:checking device /dev/sr0
Traceback (most recent call last):
File "/usr/lib/python3/dist-packages/whipper/extern/task/task.py", line 523, in c
callable_task(*args, **kwargs)
File "/usr/lib/python3/dist-packages/whipper/program/cdrdao.py", line 115, in _read
self._done()
File "/usr/lib/python3/dist-packages/whipper/program/cdrdao.py", line 153, in _done
self.toc.parse()
File "/usr/lib/python3/dist-packages/whipper/image/toc.py", line 202, in parse
with open(self._path) as f:
FileNotFoundError: [Errno 2] No such file or directory: '/tmp/tmpk0q0bj2l.cdrdao.read-toc.whipper.task'
CRITICAL:whipper.command.main:exception FileNotFoundError at /usr/lib/python3/dist-packages/whipper/image/toc.py:202: parse(): [Errno 2] No such file or directory: '/tmp/tmpk0q0bj2l.cdrdao.read-toc.whipper.task'
Traceback (most recent call last):
File "/usr/lib/python3/dist-packages/whipper/extern/task/task.py", line 523, in c
callable_task(*args, **kwargs)
File "/usr/lib/python3/dist-packages/whipper/program/cdrdao.py", line 115, in _read
self._done()
File "/usr/lib/python3/dist-packages/whipper/program/cdrdao.py", line 153, in _done
self.toc.parse()
File "/usr/lib/python3/dist-packages/whipper/image/toc.py", line 202, in parse
with open(self._path) as f:
FileNotFoundError: [Errno 2] No such file or directory: '/tmp/tmpk0q0bj2l.cdrdao.read-toc.whipper.task'
$ cdrdao read-toc --device /dev/sr0 --fast-toc cdrdao_fast.toc
Cdrdao version 1.2.4 - (C) Andreas Mueller <[email protected]>
/dev/sr0: HL-DT-ST DVDRAM GT80N Rev: LT21
Using driver: Generic SCSI-3/MMC - Version 2.0 (options 0x0000)
WARNING: Unit not ready, still trying...
WARNING: Unit not ready, still trying...
WARNING: Unit not ready, still trying...
WARNING: Unit not ready, still trying...
WARNING: Unit not ready, still trying...
WARNING: Unit not ready, still trying...
WARNING: Unit not ready, still trying...
WARNING: Unit not ready, still trying...
WARNING: Unit not ready, still trying...
WARNING: Unit not ready, still trying...
ERROR: Unit not ready, giving up.
ERROR: Cannot setup device /dev/sr0.
In this case, everything worked again after ejecting and reinserting the disc.
