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

whipper cd rip results in error reading TOC #531

Open
Bujiraso opened this issue Mar 22, 2021 · 9 comments
Open

whipper cd rip results in error reading TOC #531

Bujiraso opened this issue Mar 22, 2021 · 9 comments
Labels
Bug Generic bug: can be used together with more specific labels Needed: replication Bug replication is required On Hold Waiting for other actions

Comments

@Bujiraso
Copy link

Bujiraso commented Mar 22, 2021

Steps to Reproduce

  1. Insert specific CDs (https://musicbrainz.org/release-group/e1ba148a-2a49-3a64-8c27-0d894aff56fe)
  2. $ 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
@Bujiraso
Copy link
Author

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.

@Bujiraso
Copy link
Author

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!

@Bujiraso
Copy link
Author

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.

@JoeLametta
Copy link
Collaborator

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.

@Bujiraso
Copy link
Author

Can do!

@Bujiraso
Copy link
Author

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?

@JoeLametta JoeLametta added Bug Generic bug: can be used together with more specific labels Needed: replication Bug replication is required On Hold Waiting for other actions labels May 14, 2021
@tsweet64
Copy link

tsweet64 commented Jun 13, 2021

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 libcdio/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.

@anarcat
Copy link
Contributor

anarcat commented May 20, 2022

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 <andreas@daneb.de>
/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. ;)

@owenh000
Copy link

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 <andreas@daneb.de>
/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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Bug Generic bug: can be used together with more specific labels Needed: replication Bug replication is required On Hold Waiting for other actions
Projects
None yet
Development

No branches or pull requests

5 participants