From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1754906AbZELXYZ (ORCPT ); Tue, 12 May 2009 19:24:25 -0400 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1751271AbZELXYJ (ORCPT ); Tue, 12 May 2009 19:24:09 -0400 Received: from mail-bw0-f222.google.com ([209.85.218.222]:48415 "EHLO mail-bw0-f222.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1750832AbZELXYG (ORCPT ); Tue, 12 May 2009 19:24:06 -0400 DomainKey-Signature: a=rsa-sha1; c=nofws; d=gmail.com; s=gamma; h=message-id:date:from:user-agent:mime-version:to:cc:subject :references:in-reply-to:content-type:content-transfer-encoding; b=j7lNETZlj+0JLyu97yqwGkEuua3hG5qjV++PgrWErdBB7nWX0TsmmT5jRUA3+1zFs2 4bnR1wP/own+bf3zuBmCErlxgntfXyxPTxcJRtqm0OwGxb/qqa73vu+1K7iyBGLt1eIN qf1xyfjWHzW3XRclBBi2Biyw6+8VkrtxlzvQA= Message-ID: <4A0A050D.4000804@gmail.com> Date: Tue, 12 May 2009 17:23:57 -0600 From: Robert Hancock User-Agent: Thunderbird 2.0.0.21 (X11/20090320) MIME-Version: 1.0 To: Andy Isaacson CC: Andrew Morton , linux-kernel@vger.kernel.org, linux-ide@vger.kernel.org, linux-scsi Subject: Re: [2.6.30-rc2] CD-R: wodim intermittent failures: [sr0] Add. Sense: Logical block address out of range, sector 0 References: <20090421015234.GA7014@hexapodia.org> <20090422144904.407df635.akpm@linux-foundation.org> <49F00EBB.7040504@gmail.com> <20090423070713.GF19113@hexapodia.org> <20090512215256.GA22095@hexapodia.org> In-Reply-To: <20090512215256.GA22095@hexapodia.org> Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Andy Isaacson wrote: > On Thu, Apr 23, 2009 at 12:07:13AM -0700, Andy Isaacson wrote: >> On Thu, Apr 23, 2009 at 12:46:19AM -0600, Robert Hancock wrote: >>>> Oh well, let's tentatively assume that we have a post-2.6.29 regression >>>> in the libata ahci driver. >>> I tend to doubt it's a problem in ahci itself, I would guess it's higher >>> up the stack. Or could be that it's not a kernel bug, just some change >>> in timing that triggers the problem. >>> >>> What's supposed to stop udev/hal from poking at the drive while wodim is >>> writing to the disc, anyway? >> wodim opens O_EXCL, and it does occasionally complain about not being >> able to open, then sleeping and retrying. > > I just saw this again with 2.6.30-rc5-00096-ga4d7749 and got some nice > stack traces, for both hald-addon-storage and wodim: > > [ 2041.201084] INFO: task hald-addon-stor:3804 blocked for more than 120 seconds. > [ 2041.201108] ffff8801145056f8 0000000000000086 ffff880118c66120 0000000000000086 > [ 2041.201118] 00000000000110c0 000000000000c848 ffff8801144b2cc0 ffff8800d8008000 > [ 2041.201127] ffff8801144b3060 0000000118ddd460 ffff8801145056b8 ffffffff81296405 > [ 2041.201135] Call Trace: > [ 2041.201153] [] ? scsi_setup_blk_pc_cmnd+0x145/0x180 > [ 2041.201162] [] ? scsi_pool_alloc_command+0x2c/0x80 > [ 2041.201171] [] ? sr_prep_fn+0x4d/0x5b0 > [ 2041.201180] [] schedule+0x9/0x20 > [ 2041.201187] [] schedule_timeout+0x145/0x180 > [ 2041.201196] [] ? kobject_put+0x27/0x60 > [ 2041.201203] [] wait_for_common+0x14d/0x180 > [ 2041.201214] [] ? default_wake_function+0x0/0x10 > [ 2041.201224] [] ? __generic_unplug_device+0x33/0x40 > [ 2041.201231] [] wait_for_completion+0x18/0x20 > [ 2041.201239] [] blk_execute_rq+0x65/0xb0 > [ 2041.201246] [] ? freed_request+0x30/0x60 > [ 2041.201255] [] scsi_execute+0xf2/0x150 > [ 2041.201262] [] scsi_execute_req+0xd8/0x150 > [ 2041.201271] [] sr_test_unit_ready+0x66/0x100 > [ 2041.201280] [] ? kmem_cache_alloc+0x79/0x110 > [ 2041.201288] [] sr_media_change+0xba/0x2f0 > [ 2041.201298] [] ? lock_hrtimer_base+0x2c/0x60 > [ 2041.201308] [] media_changed+0x68/0xb0 > [ 2041.201316] [] cdrom_media_changed+0x37/0x40 > [ 2041.201324] [] sr_block_media_changed+0x14/0x20 > [ 2041.201333] [] check_disk_change+0x2e/0x70 > [ 2041.201341] [] cdrom_open+0x1ab/0xb60 > [ 2041.201349] [] ? remove_wait_queue+0x46/0x60 > [ 2041.201357] [] ? poll_freewait+0x46/0xb0 > [ 2041.201365] [] ? do_sys_poll+0x3e9/0x4c0 > [ 2041.201372] [] ? __pollwait+0x0/0x100 > [ 2041.201380] [] ? pollwake+0x0/0x50 > [ 2041.201387] [] ? kobject_get+0x1a/0x30 > [ 2041.201394] [] ? get_disk+0x2f/0x90 > [ 2041.201401] [] ? kobject_get+0x1a/0x30 > [ 2041.201409] [] sr_block_open+0x7a/0xd0 > [ 2041.201417] [] __blkdev_get+0x21e/0x3a0 > [ 2041.201426] [] ? mntput_no_expire+0x2a/0x140 > [ 2041.201433] [] blkdev_get+0xb/0x10 > [ 2041.201440] [] blkdev_open+0x6c/0xc0 > [ 2041.201449] [] __dentry_open+0xe6/0x2e0 > [ 2041.201456] [] ? blkdev_open+0x0/0xc0 > [ 2041.201463] [] nameidata_to_filp+0x57/0x70 > [ 2041.201471] [] do_filp_open+0x2a2/0x9d0 > [ 2041.201479] [] ? free_pages_and_swap_cache+0x8d/0xb0 > [ 2041.201489] [] ? unmap_region+0x140/0x160 > [ 2041.201496] [] ? alloc_fd+0x4a/0x140 > [ 2041.201503] [] do_sys_open+0x7b/0x100 > [ 2041.201510] [] sys_open+0x1b/0x20 > [ 2041.201519] [] system_call_fastpath+0x16/0x1b > [ 2041.201542] INFO: task wodim:6398 blocked for more than 120 seconds. > [ 2041.201562] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [ 2041.201568] wodim D 0000000000000000 0 6398 5313 > [ 2041.201575] ffff8800d805d868 0000000000000082 ffff880118ed40d0 0000000000000000 > [ 2041.201584] 00000000000110c0 000000000000c848 ffff8800d4164320 ffff88011b884320 > [ 2041.201593] ffff8800d41646c0 0000000118ed5e48 000000010005d5b2 ffff880118ed4000 > [ 2041.201602] Call Trace: > [ 2041.201610] [] schedule+0x9/0x20 > [ 2041.201617] [] schedule_timeout+0x145/0x180 > [ 2041.201625] [] ? scsi_request_fn+0xd0/0x570 > [ 2041.201632] [] wait_for_common+0x14d/0x180 > [ 2041.201641] [] ? default_wake_function+0x0/0x10 > [ 2041.201649] [] ? __generic_unplug_device+0x1a/0x40 > [ 2041.201656] [] wait_for_completion+0x18/0x20 > [ 2041.201663] [] blk_execute_rq+0x65/0xb0 > [ 2041.201669] [] ? blk_rq_append_bio+0x26/0x70 > [ 2041.201676] [] ? blk_rq_map_user+0x1aa/0x2a0 > [ 2041.201684] [] ? capable+0xe/0x50 > [ 2041.201691] [] sg_io+0x1d4/0x400 > [ 2041.201699] [] ? mempool_free_slab+0x12/0x20 > [ 2041.201707] [] scsi_cmd_ioctl+0x2e5/0x4d0 > [ 2041.201715] [] ? try_to_wake_up+0x148/0x330 > [ 2041.201723] [] ? default_wake_function+0xd/0x10 > [ 2041.201732] [] cdrom_ioctl+0x3d/0x1050 > [ 2041.201741] [] ? n_tty_receive_buf+0x772/0x11e0 > [ 2041.201750] [] sr_block_ioctl+0x5b/0xb0 > [ 2041.201757] [] __blkdev_driver_ioctl+0x8e/0xa0 > [ 2041.201765] [] blkdev_ioctl+0xad/0x9e0 > [ 2041.201772] [] ? filemap_fault+0x144/0x450 > [ 2041.201778] [] ? unlock_page+0x22/0x30 > [ 2041.201786] [] ? __do_fault+0x42d/0x4e0 > [ 2041.201795] [] block_ioctl+0x35/0x40 > [ 2041.201802] [] vfs_ioctl+0x31/0xa0 > [ 2041.201809] [] do_vfs_ioctl+0x8a/0x570 > [ 2041.201816] [] ? __up_read+0x91/0xb0 > [ 2041.201824] [] ? up_read+0x9/0x10 > [ 2041.201831] [] sys_ioctl+0x99/0xa0 > [ 2041.201840] [] system_call_fastpath+0x16/0x1b > > Looking at hald/linux/addons/addon-storage.c it does appear to > open(O_EXCL) as well, so perhaps the O_EXCL multiple-open logic broke > recently? > > Complete dmesg, kconfig, and so on at > > http://web.hexapodia.org/~adi/sysinfo/1242164411_cvpe4300_2.6.30-rc5-dmar-00096-ga4d7749/ > > -andy I'm not sure how this is supposed to work. The only place I can see any O_EXCL handling is in the sg driver. But if you access the sr device directly, it doesn't seem like that would have any effect. CCing linux-scsi. Could be there's a bad user-space assumption here, or something.