* Re: Media autochanger driver changed behavior.
2008-07-11 19:15 ` Jesper Krogh
@ 2008-09-10 11:10 ` Jesper Krogh
2008-09-10 11:37 ` Jesper Krogh
1 sibling, 0 replies; 9+ messages in thread
From: Jesper Krogh @ 2008-09-10 11:10 UTC (permalink / raw)
To: James Bottomley; +Cc: Linux-Scsi
Jesper Krogh wrote:
> James Bottomley wrote:
>> On Thu, 2008-07-10 at 07:59 +0200, Jesper Krogh wrote:
>>> James Bottomley wrote:
>>>> On Wed, 2008-07-09 at 23:56 +0200, Jesper Krogh wrote:
>>>>> James Bottomley wrote:
>>>>>> On Wed, 2008-07-09 at 22:51 +0200, Jesper Krogh wrote:
>>>>>>> Hi.
>>>>>>>
>>>>>>> Upgrading the OS from an quite old kernel to a newer (2.6.24)
>>>>>>> changed
>>>>>>> the behavior of the "ch" driver. Now it does a inventory to the
>>>>>>> changer
>>>>>>> on load. This command makes the barcode-reader scan the entire
>>>>>>> library
>>>>>>> at driver load time.
>>>>>> Do I take it from this that your old kernel simply didn't auto
>>>>>> load the
>>>>>> ch driver? or that something has changed in the way the driver now
>>>>>> works?
>>>>> It sure did load the driver and it worked just fine. It just didnt
>>>>> make the library unit force scan the barcodes. (the library do that
>>>>> on bootup by itself, but it can be forced with mtx over the changer
>>>>> device).
>>>>>
>>>>> mtx -f /dev/changer inventory => Force scans barcodes
>>>>> mtx -f /dev/changer status => Reads out the barcodes labels and slots
>>>>> from the changer device without forcing the library to scan.
>>>>> (note I dont know if it is library specific).
>>>> OK, so it's not the autoloading code which I thought it might be.
>>>>
>>>> Which is the latest version of the kernel that works? ... that will at
>>>> least give me the set of changes to look at.
>>> I cant give you that, since I havent testet all, but I'm quite sure
>>> 2.6.20 worked,
>>> completely sure that 2.6.15 was Ok.
>>>
>>> I know this is a large timespan, sorry.
>>
>> It would be enormously helpful if you could boot 2.6.20 and confirm.
>> There are 3 changes to ch between 2.6.20 and 2.6.24. There are 8
>> between 2.6.15 and 2.6.24.
>
> I'll get it done and report but, but we're a bit behind on the
> backup-schedules. So when the system has catched up I'll do some testing.
>
It troubled med to get back to "that old" a kernel. I have a fresh dmesg
here from a 2.6.26.1 kernel. New stuff is that I get the 120 seconds
message.
[ 28.475059] ch0: type #1 (mt): 0x0+1 [medium transport]
[ 28.475111] ch0: type #2 (st): 0x100+100 [storage]
[ 28.475157] ch0: type #3 (ie): 0x500+0 [import/export]
[ 28.475203] ch0: type #4 (dt): 0x80+1 [data transfer]
[ 28.496792] ch0: dt 0x80: ID 3, LUN 0, name: HP Ultrium 3-SCSI
G39Z
[ 28.496812] ch0: INITIALIZE ELEMENT STATUS, may take some time ...
[ 29.561479] e1000: eth0: e1000_watchdog: NIC Link is Up 1000 Mbps
Full Duplex, Flow Control: RX
[ 29.965913] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
[ 30.009427] shpchp: HPC vendor_id 1022 device_id 7458 ss_vid 0 ss_did 0
[ 30.009427] shpchp: shpc_init: cannot reserve MMIO region
[ 30.009427] shpchp: HPC vendor_id 1022 device_id 7458 ss_vid 0 ss_did 0
[ 30.009427] shpchp: shpc_init: cannot reserve MMIO region
[ 30.013471] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
[ 30.208019] i2c-adapter i2c-0: nForce2 SMBus adapter at 0x6000
[ 30.208096] i2c-adapter i2c-1: nForce2 SMBus adapter at 0x6040
[ 30.354692] input: Power Button (FF) as /class/input/input4
[ 30.412413] input: PC Speaker as /class/input/input5
[ 30.431263] ACPI: Power Button (FF) [PWRF]
[ 30.431416] input: Power Button (CM) as /class/input/input6
[ 30.497468] ACPI: Power Button (CM) [PWRB]
[ 30.613129] NET: Registered protocol family 10
[ 30.613706] lo: Disabled Privacy Extensions
[ 31.140157] warning: `ntpd' uses 32-bit capabilities (legacy support
in use)
[ 41.121412] eth0: no IPv6 routers present
[ 157.841224] INFO: task modprobe:3924 blocked for more than 120 seconds.
[ 157.841280] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 157.841629] modprobe D ffff810001044280 0 3924 1
[ 157.842550] ffff8102fe4a7918 0000000000000086 0000000000000000
ffff8102fe4d2280
[ 157.842711] ffffffff8061e280 ffffffff8061e280 ffffffff8061a4e0
ffffffff8061e280
[ 157.842869] ffff8102fb1b0dc8 ffff8102fe4a78e4 ffff8102fe4a78d8
ffff8102fe4a78c8
[ 157.842990] Call Trace:
[ 157.843089] [<ffffffffa01084eb>] :mptscsih:mptscsih_qcmd+0x22b/0x5c0
[ 157.843146] [<ffffffff8044d175>] schedule_timeout+0x95/0xd0
[ 157.843198] [<ffffffff8031fd8b>] elv_next_request+0x5b/0x250
[ 157.843271] [<ffffffffa006cf2f>] :scsi_mod:scsi_dispatch_cmd+0x12f/0x2e0
[ 157.843323] [<ffffffff8044cec5>] wait_for_common+0xa5/0x160
[ 157.843374] [<ffffffff8022a9b0>] default_wake_function+0x0/0x10
[ 157.843428] [<ffffffff8032553f>] blk_execute_rq+0x9f/0x110
[ 157.843477] [<ffffffff803227b1>] get_request_wait+0x21/0x180
[ 157.843539] [<ffffffffa007367c>] :scsi_mod:scsi_execute+0xec/0x150
[ 157.843597] [<ffffffffa0073771>] :scsi_mod:scsi_execute_req+0x91/0x100
[ 157.843653] [<ffffffffa01ad12b>] :ch:ch_do_scsi+0x7b/0x1b0
[ 157.843705] [<ffffffffa01ad425>] :ch:ch_read_element_status+0x135/0x1a0
[ 157.843758] [<ffffffffa01ad2a8>] :ch:ch_init_elem+0x48/0x90
[ 157.843808] [<ffffffffa01ae80c>] :ch:ch_probe+0x4bc/0x760
[ 157.843864] [<ffffffff803a0e56>] driver_probe_device+0x96/0x190
[ 157.843915] [<ffffffff803a0fd9>] __driver_attach+0x89/0x90
[ 157.843964] [<ffffffff803a0f50>] __driver_attach+0x0/0x90
[ 157.844013] [<ffffffff803a046d>] bus_for_each_dev+0x4d/0x80
[ 157.844064] [<ffffffff80293a15>] kmem_cache_alloc+0x65/0xa0
[ 157.844114] [<ffffffff803a0ab5>] bus_add_driver+0x1f5/0x270
[ 157.844165] [<ffffffff803a1265>] driver_register+0x55/0x140
[ 157.844216] [<ffffffffa005b05d>] :ch:init_ch_module+0x5d/0xa6
[ 157.844266] [<ffffffff80257a2a>] sys_init_module+0x17a/0x1d00
[ 157.844333] [<ffffffff8020c2ab>] system_call_after_swapgs+0x7b/0x80
[ 157.844386]
[ 157.844427] INFO: task modprobe:3939 blocked for more than 120 seconds.
[ 157.844478] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 157.844544] modprobe D ffff810001044280 0 3939 3938
[ 157.844641] ffff8105fb6bbbf8 0000000000000086 0000000000000000
0000000000000000
[ 157.844800] ffffffff8061e280 ffffffff8061e280 ffffffff8061a4e0
ffffffff8061e280
[ 157.844956] ffff8105fb4eef88 ffff8105fb6bbbc4 ffff8105fb6bbbb8
ffff8105fb6bbba8
[ 157.845078] Call Trace:
[ 157.845164] [<ffffffff802ef36b>] create_dir+0x6b/0xb0
[ 157.845214] [<ffffffff8044d175>] schedule_timeout+0x95/0xd0
[ 157.845265] [<ffffffff80331bcf>] kobject_add_internal+0xdf/0x1c0
[ 157.846597] [<ffffffff80331e3e>] kobject_init_and_add+0x6e/0x90
[ 157.846647] [<ffffffff8044da46>] __down+0x56/0x90
[ 157.846696] [<ffffffff8024cf07>] down+0x47/0x50
[ 157.846744] [<ffffffff803a0f80>] __driver_attach+0x30/0x90
[ 157.846792] [<ffffffff803a0f50>] __driver_attach+0x0/0x90
[ 157.846841] [<ffffffff803a046d>] bus_for_each_dev+0x4d/0x80
[ 157.846891] [<ffffffff80293a15>] kmem_cache_alloc+0x65/0xa0
[ 157.846940] [<ffffffff803a0ab5>] bus_add_driver+0x1f5/0x270
[ 157.846991] [<ffffffff803a1265>] driver_register+0x55/0x140
[ 157.847044] [<ffffffffa00610bc>] :st:init_st+0xbc/0x1be
[ 157.847092] [<ffffffff80257a2a>] sys_init_module+0x17a/0x1d00
[ 157.847150] [<ffffffff8028bb30>] alloc_pages_current+0x0/0xe0
[ 157.847205] [<ffffffff8020c2ab>] system_call_after_swapgs+0x7b/0x80
[ 157.847258]
[ 210.928038] loop: module loaded
[ 210.985319] lp: driver loaded but no devices found
[ 286.691381] INFO: task modprobe:3924 blocked for more than 120 seconds.
[ 286.691436] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 286.692482] modprobe D ffff810001044280 0 3924 1
[ 286.692580] ffff8102fe4a7918 0000000000000086 0000000000000000
ffff8102fe4d2280
[ 286.693507] ffffffff8061e280 ffffffff8061e280 ffffffff8061a4e0
ffffffff8061e280
[ 286.693665] ffff8102fb1b0dc8 ffff8102fe4a78e4 ffff8102fe4a78d8
ffff8102fe4a78c8
[ 286.693787] Call Trace:
[ 286.693883] [<ffffffffa01084eb>] :mptscsih:mptscsih_qcmd+0x22b/0x5c0
[ 286.693939] [<ffffffff8044d175>] schedule_timeout+0x95/0xd0
[ 286.693991] [<ffffffff8031fd8b>] elv_next_request+0x5b/0x250
[ 286.694063] [<ffffffffa006cf2f>] :scsi_mod:scsi_dispatch_cmd+0x12f/0x2e0
[ 286.694116] [<ffffffff8044cec5>] wait_for_common+0xa5/0x160
[ 286.694167] [<ffffffff8022a9b0>] default_wake_function+0x0/0x10
[ 286.694220] [<ffffffff8032553f>] blk_execute_rq+0x9f/0x110
[ 286.694270] [<ffffffff803227b1>] get_request_wait+0x21/0x180
[ 286.694332] [<ffffffffa007367c>] :scsi_mod:scsi_execute+0xec/0x150
[ 286.694391] [<ffffffffa0073771>] :scsi_mod:scsi_execute_req+0x91/0x100
[ 286.694447] [<ffffffffa01ad12b>] :ch:ch_do_scsi+0x7b/0x1b0
[ 286.694498] [<ffffffffa01ad425>] :ch:ch_read_element_status+0x135/0x1a0
[ 286.694551] [<ffffffffa01ad2a8>] :ch:ch_init_elem+0x48/0x90
[ 286.694604] [<ffffffffa01ae80c>] :ch:ch_probe+0x4bc/0x760
[ 286.694660] [<ffffffff803a0e56>] driver_probe_device+0x96/0x190
[ 286.694712] [<ffffffff803a0fd9>] __driver_attach+0x89/0x90
[ 286.694761] [<ffffffff803a0f50>] __driver_attach+0x0/0x90
[ 286.694810] [<ffffffff803a046d>] bus_for_each_dev+0x4d/0x80
[ 286.694861] [<ffffffff80293a15>] kmem_cache_alloc+0x65/0xa0
[ 286.694913] [<ffffffff803a0ab5>] bus_add_driver+0x1f5/0x270
[ 286.694964] [<ffffffff803a1265>] driver_register+0x55/0x140
[ 286.695017] [<ffffffffa005b05d>] :ch:init_ch_module+0x5d/0xa6
[ 286.695067] [<ffffffff80257a2a>] sys_init_module+0x17a/0x1d00
[ 286.695135] [<ffffffff8020c2ab>] system_call_after_swapgs+0x7b/0x80
[ 286.695188]
[ 286.695229] INFO: task modprobe:3939 blocked for more than 120 seconds.
[ 286.695279] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 286.695345] modprobe D ffff810001044280 0 3939 3938
[ 286.695440] ffff8105fb6bbbf8 0000000000000086 0000000000000000
0000000000000000
[ 286.695600] ffffffff8061e280 ffffffff8061e280 ffffffff8061a4e0
ffffffff8061e280
[ 286.695759] ffff8105fb4eef88 ffff8105fb6bbbc4 ffff8105fb6bbbb8
ffff8105fb6bbba8
[ 286.695880] Call Trace:
[ 286.695966] [<ffffffff802ef36b>] create_dir+0x6b/0xb0
[ 286.696016] [<ffffffff8044d175>] schedule_timeout+0x95/0xd0
[ 286.696067] [<ffffffff80331bcf>] kobject_add_internal+0xdf/0x1c0
[ 286.696117] [<ffffffff80331e3e>] kobject_init_and_add+0x6e/0x90
[ 286.696168] [<ffffffff8044da46>] __down+0x56/0x90
[ 286.696218] [<ffffffff8024cf07>] down+0x47/0x50
[ 286.696266] [<ffffffff803a0f80>] __driver_attach+0x30/0x90
[ 286.696316] [<ffffffff803a0f50>] __driver_attach+0x0/0x90
[ 286.696364] [<ffffffff803a046d>] bus_for_each_dev+0x4d/0x80
[ 286.696413] [<ffffffff80293a15>] kmem_cache_alloc+0x65/0xa0
[ 286.696463] [<ffffffff803a0ab5>] bus_add_driver+0x1f5/0x270
[ 286.696514] [<ffffffff803a1265>] driver_register+0x55/0x140
[ 286.696567] [<ffffffffa00610bc>] :st:init_st+0xbc/0x1be
[ 286.696616] [<ffffffff80257a2a>] sys_init_module+0x17a/0x1d00
[ 286.696676] [<ffffffff8028bb30>] alloc_pages_current+0x0/0xe0
[ 286.696731] [<ffffffff8020c2ab>] system_call_after_swapgs+0x7b/0x80
[ 286.696784]
[ 320.909411] ch0: ... finished
[ 320.909411] ch 3:0:0:0: Attached scsi changer ch0
[ 320.909858] st 3:0:3:0: Attached scsi tape st0
[ 320.909905] st 3:0:3:0: st0: try direct i/o: yes (alignment 4 B)
[ 321.183325] Adding 5831552k swap on /dev/sdc5. Priority:-1 extents:1
across:5831552k
[ 321.352153] st0: Block limits 1 - 16777215 bytes.
I also get:
jk@bacula:~$ dmesg | grep bus_type
[ 13.252144] Driver 'sd' needs updating - please use bus_type methods
[ 13.253901] Driver 'sr' needs updating - please use bus_type methods
[ 27.670335] Driver 'ch' needs updating - please use bus_type methods
[ 27.680156] Driver 'st' needs updating - please use bus_type methods
jk@bacula:~$
Should I be worried about that?
--
Jesper
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: Media autochanger driver changed behavior.
2008-07-11 19:15 ` Jesper Krogh
2008-09-10 11:10 ` Jesper Krogh
@ 2008-09-10 11:37 ` Jesper Krogh
1 sibling, 0 replies; 9+ messages in thread
From: Jesper Krogh @ 2008-09-10 11:37 UTC (permalink / raw)
To: James Bottomley; +Cc: Linux-Scsi
> I'll get it done and report but, but we're a bit behind on the
> backup-schedules. So when the system has catched up I'll do some testing.
On 2.6.26.1 I also get quite strange behavior .. sometimes the changer
id discovered as a "sgX" device and sometimes it is discovered as a
"schX".. the schX doesnt work:
$ lsscsi
[0:0:0:0] cd/dvd AMI Virtual CDROM 1.00 /dev/scd0
[1:0:0:0] disk AMI Virtual Floppy 1.00 /dev/sda
[2:0:0:0] disk HITACHI H101414SCSUN146G SA23 -
[2:0:1:0] disk HITACHI H101414SCSUN146G SA23 -
[2:0:2:0] disk FUJITSU MBB2147RCSUN146G 0505 -
[2:0:3:0] disk FUJITSU MBB2147RCSUN146G 0505 -
[2:1:0:0] disk LSILOGIC Logical Volume 3000 /dev/sdc
[2:1:2:0] disk LSILOGIC Logical Volume 3000 /dev/sdb
[3:0:0:0] mediumx QUANTUM PX500 002A /dev/sch0
[3:0:3:0] tape HP Ultrium 3-SCSI G39Z /dev/st0
When it works.. I dont have any device put onto the mediumx-thing in
this list. And none of the sgX devices actually works. Rebooting the
system "might" bring it correcly up.
Full dmesg: http://krogh.cc/~jesper/dmesg-broken.txt
/dev/changer is made by this udev rule:
/etc/udev/rules.d/60-symlinks.rules:SYSFS{vendor}=="QUANTUM",
SYSFS{model}=="PX500" SYMLINK+="changer"
jk@bacula:~$ sudo mtx -f /dev/sch0 status
/dev/sch0 is not an sg device, or old sg driver
$ sudo strace mtx -f /dev/sch0 status
execve("/usr/sbin/mtx", ["mtx", "-f", "/dev/sch0", "status"], [/* 16
vars */]) = 0
brk(0) = 0x60b000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x7f049f174000
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or
directory)
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x7f049f172000
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or
directory)
open("/etc/ld.so.cache", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=38937, ...}) = 0
mmap(NULL, 38937, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f049f168000
close(3) = 0
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or
directory)
open("/lib/libc.so.6", O_RDONLY) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\340\342"...,
832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1436976, ...}) = 0
mmap(NULL, 3543672, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3,
0) = 0x7f049ebf6000
mprotect(0x7f049ed4e000, 2097152, PROT_NONE) = 0
mmap(0x7f049ef4e000, 20480, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x158000) = 0x7f049ef4e000
mmap(0x7f049ef53000, 17016, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f049ef53000
close(3) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x7f049f167000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x7f049f166000
arch_prctl(ARCH_SET_FS, 0x7f049f1666e0) = 0
mprotect(0x7f049ef4e000, 12288, PROT_READ) = 0
munmap(0x7f049f168000, 38937) = 0
open("/dev/sch0", O_RDWR) = 3
ioctl(3, SG_GET_VERSION_NUM, 0x7fffa7175b30) = -1 EINVAL (Invalid argument)
write(2, "/dev/sch0 is not an sg device, o"..., 48/dev/sch0 is not an sg
device, or old sg driver
) = 48
exit_group(1) = ?
Process 8139 detached
jk@bacula:~$
--
Jesper
^ permalink raw reply [flat|nested] 9+ messages in thread