Re: [Qemu-devel] Do you have a use for a tester of virtio-scsi with CD drives ?

["Thomas Schmitt" <scdbackup@gmx.net>]

Hi,

i wanted to test Blu-ray burning and attached a BD recorder via USB
to the host. Its power was switched on, before i booted the host.

The host can operate this drive.
But the qemu guest obviously has severe problems with it.

There is a 'QEMU DVD-ROM' at /dev/sr0.
There is also a /dev/sr1, which does not show up in the udev file
  /etc/udev/rules.d/70-persistent-cd.rules 
which usually reacts on new drives. 
Neither the superuser (nor the normal user after chmod a+rw) can
operate /dev/sr1.
xorriso gets

  INQUIRY
  12 00 00 00 24 00 
  +++ sense data = F0 00 0B 00 00 00 00 0A 00 00 00 00 00 06 00 00 00 00
  +++ key=B  asc=00h  ascq=06h   ( 30992 ms)

and my qemu printf reports

  posix-aio-compat.c: handle_aiocb_ioctl: ioctl(12, 0x2285, ),
                      ret= -1 , errno= 19

That's ENODEV /* No such device */.

Note well, that for having a failing iotcl() i first had to open the
device file successfully.
So "No such device" is probably related to an unprovoked re-attaching
of the drive which i found in the host system log. (See below.)

----------------------------------------------------------------------

When i shutdown the guest system, the host got a kernel Oops.
All my SSH sessions on the host are frozen.
Except a session which ran top, they all display:

  Message from syslogd@debian2 at Nov  6 08:47:42 ...
   kernel:[ 1961.576375] Oops: 0000 [#1] SMP 

  Message from syslogd@debian2 at Nov  6 08:47:42 ...
   kernel:[ 1961.576382] last sysfs file: /sys/devices/pci0000:00/0000:00:12.0/usb3/3-3/3-3:1.0/host9/target9:0:0/9:0:0:0/block/sr2/removable

  Message from syslogd@debian2 at Nov  6 08:47:42 ...
   kernel:[ 1961.576598] Stack:

  Message from syslogd@debian2 at Nov  6 08:47:42 ...
   kernel:[ 1961.576630] Call Trace:

  Message from syslogd@debian2 at Nov  6 08:47:42 ...
   kernel:[ 1961.576748] Code: 48 8b 47 18 48 8b 00 48 8b 40 60 48 85 c0 74 06 49 89 c3 41 ff e3 48 c7 86 a0 00 00 00 00 00 00 00 31 c0 c3 48 8b 47 18 48 8b 00 <48> 8b 40 68 48 85 c0 74 09 48 89 f7 49 89 c3 41 ff e3 c3 48 8b 

  Message from syslogd@debian2 at Nov  6 08:47:42 ...
   kernel:[ 1961.576824] CR2: 0000000000000068

Funnily the graphical login screen of the host did still react on the
keyboard but froze after i entered the desktop user password.

I had to press the hardware reset button.

------------------------------------------------------------------------

The qemu start command is the same as with the previous successful runs.
Only the /dev/sg address differs.
I double checked before starting qemu, it is the right /dev/sg for the
drive.

  .../x86_64-softmmu/qemu-system-x86_64 \
    -L .../qemu-git/pc-bios \
    -enable-kvm \
    -nographic \
    -m 512 \
    -net nic,model=ne2k_pci \
    -net user,hostfwd=tcp::5557-:22 \
    -hda /dvdbuffer/i386-install.qemu \
    -drive file=/dev/sg3,if=scsi \
    -cdrom /dvdbuffer/pseudo_drive

qemu was started by a normal user, not by the superuser.

------------------------------------------------------------------------

The drive is an

  'Optiarc' 'BD RW BD-5300S' revision '1.04'

attached via SATA to an USB box "Delock 5.25 inch enclosure eSATA/USB".

  Nov  6 08:15:06 debian2 kernel: [    1.294442] usb 1-3: Product: JM20336 SATA, USB Combo
  Nov  6 08:15:06 debian2 kernel: [    1.294444] usb 1-3: Manufacturer: JMicron
  Nov  6 08:15:06 debian2 kernel: [    1.294445] usb 1-3: SerialNumber: 306663601043

The drive attachment messages first talk of "8:0:0:0"

  Nov  6 08:15:06 debian2 kernel: [    6.301719] scsi 8:0:0:0: CD-ROM            Optiarc  BD RW BD-5300S   1.04 PQ: 0 ANSI: 0
  Nov  6 08:15:06 debian2 kernel: [    6.310686] sr2: scsi3-mmc drive: 48x/48x writer dvd-ram cd/rw xa/form2 cdda tray
  Nov  6 08:15:06 debian2 kernel: [    6.310868] sr 8:0:0:0: Attached scsi generic sg3 type 5

and later of "9:0:0:0" after a disconnect which i cannot relate
to a physical event on bus or power supply:
 
  Nov  6 08:35:31 debian2 kernel: [ 1232.103847] usb 1-3: USB disconnect, address 3
  Nov  6 08:35:31 debian2 kernel: [ 1232.111661] sg_rq_end_io: device detached
  Nov  6 08:35:32 debian2 kernel: [ 1233.480103] usb 1-3: new high speed USB device using ehci_hcd and address 5
  Nov  6 08:35:33 debian2 kernel: [ 1233.976106] usb 3-3: new full speed USB device using ohci_hcd and address 3
  Nov  6 08:35:33 debian2 kernel: [ 1234.135535] usb 3-3: not running at top speed; connect to a high speed hub
  Nov  6 08:35:33 debian2 kernel: [ 1234.147516] usb 3-3: New USB device found, idVendor=152d, idProduct=2336
  Nov  6 08:35:33 debian2 kernel: [ 1234.147525] usb 3-3: New USB device strings: Mfr=1, Product=2, SerialNumber=5
  Nov  6 08:35:33 debian2 kernel: [ 1234.147531] usb 3-3: Product: JM20336 SATA, USB Combo
  Nov  6 08:35:33 debian2 kernel: [ 1234.147536] usb 3-3: Manufacturer: JMicron
Nov  6 08:35:33 debian2 kernel: [ 1234.147540] usb 3-3: SerialNumber: 306663601043
  Nov  6 08:35:33 debian2 kernel: [ 1234.147752] usb 3-3: configuration #1 chosen from 1 choice
  Nov  6 08:35:33 debian2 kernel: [ 1234.153804] scsi9 : SCSI emulation for USB Mass Storage devices
  Nov  6 08:35:38 debian2 kernel: [ 1239.163858] scsi 9:0:0:0: CD-ROM            Optiarc  BD RW BD-5300S   1.04 PQ: 0 ANSI: 0
  Nov  6 08:35:38 debian2 kernel: [ 1239.173821] sr2: scsi3-mmc drive: 125x/125x writer dvd-ram cd/rw xa/form2 cdda tray
 Nov  6 08:35:38 debian2 kernel: [ 1239.174216] sr 9:0:0:0: Attached scsi generic sg4 type 5

This might have been the moment when i first accessed the drive from
within the guest. The timestamp is a bit late for the qemu start.
It is too early for the Oops and my graphical login attempt.

It would match somehow above "No such device" message of qemu
  posix-aio-compat.c: handle_aiocb_ioctl: ioctl(12, 0x2285, ),
                      ret= -1 , errno= 19

In any case the host switched the drive from sg3 to sg4, while qemu was
told to use it as sg3.

The next lines in the log are those from Oops event:

  Nov  6 08:47:42 debian2 kernel: [ 1961.576365] PGD 11894c067 PUD 118964067 PMD 0 
  Nov  6 08:47:42 debian2 kernel: [ 1961.576391] CPU 0
  Nov  6 08:47:42 debian2 kernel: [ 1961.576395] Modules linked in: sco powernow_k8 ppdev lp cpufreq_powersave bridge cpufreq_stats stp bnep cpufreq_conservative rfcomm cpufreq_userspace l2cap crc16 bluetooth rfkill kvm_amd kvm binfmt_misc fuse loop snd_hda_codec_atihdmi snd_hda_codec_realtek snd_hda_intel snd_hda_codec snd_hwdep snd_pcm snd_seq snd_timer snd_seq_device snd radeon ttm drm_kms_helper soundcore drm i2c_algo_bit i2c_piix4 shpchp snd_page_alloc i2c_core k10temp pci_hotplug edac_core edac_mce_amd evdev parport_pc parport button pcspkr processor ext3 jbd mbcache usbhid hid sg sr_mod sd_mod crc_t10dif cdrom ata_generic usb_storage ahci ohci_hcd thermal pata_atiixp libata ehci_hcd r8169 mii scsi_mod usbcore nls_base thermal_sys [last unloaded: scsi_wait_scan]
  Nov  6 08:47:42 debian2 kernel: [ 1961.576508] Pid: 15, comm: events/0 Not tainted 2.6.32-5-amd64 #1 GA-MA74GM-S2H
  Nov  6 08:47:42 debian2 kernel: [ 1961.576515] RIP: 0010:[<ffffffff81176533>]  [<ffffffff81176533>] elv_put_request+0x7/0x1a
  Nov  6 08:47:42 debian2 kernel: [ 1961.576528] RSP: 0018:ffff880127ac5db8  EFLAGS: 00010006
  Nov  6 08:47:42 debian2 kernel: [ 1961.576533] RAX: 0000000000000000 RBX: ffff8801100cfce0 RCX: 000000000000087d
  Nov  6 08:47:42 debian2 kernel: [ 1961.576539] RDX: ffff880124f62b80 RSI: ffff8801100cfce0 RDI: ffff880123fc11a0
  Nov  6 08:47:42 debian2 kernel: [ 1961.576545] RBP: 0000000001082c40 R08: ffff880127ac4000 R09: ffff880005215780
  Nov  6 08:47:42 debian2 kernel: [ 1961.576551] R10: ffff88012775a0c0 R11: ffff88012609cde8 R12: ffff880123fc11a0
  Nov  6 08:47:42 debian2 kernel: [ 1961.576556] R13: 0000000000000282 R14: ffff880127ac8000 R15: ffff880127ac8000
  Nov  6 08:47:42 debian2 kernel: [ 1961.576564] FS:  00007fb63e148700(0000) GS:ffff880005200000(0000) knlGS:0000000000000000
  Nov  6 08:47:42 debian2 kernel: [ 1961.576570] CS:  0010 DS: 0018 ES: 0018 CR0: 000000008005003b
  Nov  6 08:47:42 debian2 kernel: [ 1961.576575] CR2: 0000000000000068 CR3: 00000001189f4000 CR4: 00000000000006f0
  Nov  6 08:47:42 debian2 kernel: [ 1961.576581] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
  Nov  6 08:47:42 debian2 kernel: [ 1961.576587] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
  Nov  6 08:47:42 debian2 kernel: [ 1961.576594] Process events/0 (pid: 15, threadinfo ffff880127ac4000, task ffff880127ac8000)
  Nov  6 08:47:42 debian2 kernel: [ 1961.576602]  ffffffff8117e967 ffff880123fc11a0 0000000000000000 ffff8801100cfce0
  Nov  6 08:47:42 debian2 kernel: [ 1961.576610] <0> ffffffff8117ef14 ffff88012600e078 ffff88012600e000 ffff88012600f290
  Nov  6 08:47:42 debian2 kernel: [ 1961.576620] <0> ffffffffa00f775e ffff88012600f288 ffff88012600e000 ffff880123da86c0
  Nov  6 08:47:42 debian2 kernel: [ 1961.576640]  [<ffffffff8117e967>] ? __blk_put_request+0x7b/0xb0
  Nov  6 08:47:42 debian2 kernel: [ 1961.576649]  [<ffffffff8117ef14>] ? blk_put_request+0x26/0x3a
  Nov  6 08:47:42 debian2 kernel: [ 1961.576663]  [<ffffffffa00f775e>] ? sg_finish_rem_req+0x5e/0xda [sg]
  Nov  6 08:47:42 debian2 kernel: [ 1961.576675]  [<ffffffffa00f7821>] ? sg_remove_sfp_usercontext+0x1c/0xbb [sg]
  Nov  6 08:47:42 debian2 kernel: [ 1961.576675]  [<ffffffffa00f7821>] ? sg_remove_sfp_usercontext+0x1c/0xbb [sg]
  Nov  6 08:47:42 debian2 kernel: [ 1961.576686]  [<ffffffff810618e7>] ? worker_thread+0x188/0x21d
  Nov  6 08:47:42 debian2 kernel: [ 1961.576697]  [<ffffffffa00f7805>] ? sg_remove_sfp_usercontext+0x0/0xbb [sg]
  Nov  6 08:47:42 debian2 kernel: [ 1961.576706]  [<ffffffff81064f1a>] ? autoremove_wake_function+0x0/0x2e
  Nov  6 08:47:42 debian2 kernel: [ 1961.576715]  [<ffffffff8106175f>] ? worker_thread+0x0/0x21d
  Nov  6 08:47:42 debian2 kernel: [ 1961.576721]  [<ffffffff81064c4d>] ? kthread+0x79/0x81
  Nov  6 08:47:42 debian2 kernel: [ 1961.576731]  [<ffffffff81011baa>] ? child_rip+0xa/0x20
  Nov  6 08:47:42 debian2 kernel: [ 1961.576738]  [<ffffffff81064bd4>] ? kthread+0x0/0x81
  Nov  6 08:47:42 debian2 kernel: [ 1961.576744]  [<ffffffff81011ba0>] ? child_rip+0x0/0x20
  Nov  6 08:47:42 debian2 kernel: [ 1961.576821]  RSP <ffff880127ac5db8>
  Nov  6 08:47:42 debian2 kernel: [ 1961.576830] ---[ end trace c4a3be0d337e533d ]---

Then come lines from the reboot:
  Nov  6 08:56:19 debian2 kernel: imklog 4.6.4, log source = /proc/kmsg started.

------------------------------------------------------------------------------  

I will now try to attach the drive via eSATA.


Have a nice day :)

Thomas