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

[Thomas Schmitt]

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 address@hidden at Nov  6 08:47:42 ...
   kernel:[ 1961.576375] Oops: 0000 [#1] SMP 

  Message from address@hidden 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 address@hidden at Nov  6 08:47:42 ...
   kernel:[ 1961.576598] Stack:

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

  Message from address@hidden 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 address@hidden 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