Date:	Wed, 25 Apr 2007 22:53:00 +0000 (GMT)
From:	William Heimbigner <icxcnika@....tar.cc>
To:	Andrew Morton <akpm@...ux-foundation.org>
cc:	linux-kernel@...r.kernel.org, Jens Axboe <jens.axboe@...cle.com>
Subject: Re: BUG: Null pointer dereference in fs/open.c

On Wed, 25 Apr 2007, Andrew Morton wrote:
<snip>
> OK.  I am able to use the pktcdvd driver OK in mainline with a piix/sata
> drive.  It could be that something is going wrong at the IDE level for you.
Perhaps; I'll try an external usb cd burner, and see where that goes.

> Are you able to identify the most recent kernel which actually worked?
No, because I haven't set packet writing up in Linux before - however, I do know 
that I've successfully set up packet writing (using 2 of the 3 cd burners I 
have) in another operating system before. I'll try 2.6.18 and see if that gets
me anywhere different, though.

dmesg.1.txt is the dmesg output from immediately after system finishes booting 
(the unusually large printk times are due to kexec)

# pktsetup 0 /dev/hdc
[19861.831160] pktcdvd: writer pktcdvd0 mapped to hdc
[19861.837138]
[19861.837142] =============================================
[19861.844343] [ INFO: possible recursive locking detected ]
[19861.849738] 2.6.21-rc7 #2
[19861.852361] ---------------------------------------------
[19861.857750] vol_id/4433 is trying to acquire lock:
[19861.862533]  (&bdev->bd_mutex){--..}, at: [<c019bb8f>] do_open+0x4f/0x2c0
[19861.869386]
[19861.869387] but task is already holding lock:
[19861.875225]  (&bdev->bd_mutex){--..}, at: [<c019bb8f>] do_open+0x4f/0x2c0
[19861.882070]
[19861.882071] other info that might help us debug this:
[19861.888602] 2 locks held by vol_id/4433:
[19861.892518]  #0:  (&bdev->bd_mutex){--..}, at: [<c019bb8f>] 
do_open+0x4f/0x2c0
[19861.899813]  #1:  (&ctl_mutex#2){--..}, at: [<c04c615c>] mutex_lock+0x1c/0x20
[19861.907046]
[19861.907047] stack backtrace:
[19861.911415]  [<c010521a>] show_trace_log_lvl+0x1a/0x30
[19861.916569]  [<c0105952>] show_trace+0x12/0x20
[19861.921021]  [<c0105a46>] dump_stack+0x16/0x20
[19861.925475]  [<c013ede0>] __lock_acquire+0xbc0/0x1040
[19861.930542]  [<c013f2d0>] lock_acquire+0x70/0x90
[19861.935169]  [<c04c61de>] mutex_lock_nested+0x7e/0x2e0
[19861.940315]  [<c019bb8f>] do_open+0x4f/0x2c0
[19861.944595]  [<c019be79>] __blkdev_get+0x79/0x90
[19861.949222]  [<c019bea5>] blkdev_get+0x15/0x20
[19861.953674]  [<c032a987>] pkt_open+0xb7/0xd80
[19861.958050]  [<c019bbc5>] do_open+0x85/0x2c0
[19861.962330]  [<c019c023>] blkdev_open+0x33/0x70
[19861.966870]  [<c0175084>] __dentry_open+0xf4/0x220
[19861.971678]  [<c0175255>] nameidata_to_filp+0x35/0x40
[19861.976738]  [<c01752a9>] do_filp_open+0x49/0x50
[19861.981365]  [<c01752f7>] do_sys_open+0x47/0xd0
[19861.985904]  [<c01753bc>] sys_open+0x1c/0x20
[19861.990184]  [<c01041c6>] sysenter_past_esp+0x5f/0x99
[19861.995243]  =======================

# pktsetup 1 /dev/hdd
[19909.635795] cdrom: This disc doesn't have any tracks I recognize!
[19909.689394] pktcdvd: writer pktcdvd1 mapped to hdd
[19909.820337] drivers/ide/ide-cd.c:729: setting error to 2
[19909.825649]  [<c010521a>] show_trace_log_lvl+0x1a/0x30
[19909.830810]  [<c0105952>] show_trace+0x12/0x20
[19909.835263]  [<c0105a46>] dump_stack+0x16/0x20
[19909.839716]  [<c033f6e4>] cdrom_decode_status+0x1f4/0x3b0
[19909.845131]  [<c033fae8>] cdrom_newpc_intr+0x38/0x320
[19909.850190]  [<c0331106>] ide_intr+0x96/0x200
[19909.854557]  [<c0150cf8>] handle_IRQ_event+0x28/0x60
[19909.859538]  [<c0151f96>] handle_edge_irq+0xa6/0x130
[19909.864511]  [<c0106449>] do_IRQ+0x49/0xa0
[19909.868618]  [<c0104c3a>] common_interrupt+0x2e/0x34
[19909.873591]  [<c01022d2>] mwait_idle+0x12/0x20
[19909.878044]  [<c01023ca>] cpu_idle+0x4a/0x80
[19909.882324]  [<c0101147>] rest_init+0x37/0x40
[19909.886690]  [<c068ac7b>] start_kernel+0x34b/0x420
[19909.891499]  [<00000000>] 0x0
[19909.894488]  =======================
[19909.921518] pktcdvd: pkt_get_last_written failed

# pktsetup 2 /dev/sr0
[19982.934793] drivers/scsi/scsi_lib.c:838: setting error to 134217730
[19982.941070]  [<c010521a>] show_trace_log_lvl+0x1a/0x30
[19982.946256]  [<c0105952>] show_trace+0x12/0x20
[19982.950744]  [<c0105a46>] dump_stack+0x16/0x20
[19982.955232]  [<c034543a>] scsi_io_completion+0x28a/0x3a0
[19982.960586]  [<c034556b>] scsi_blk_pc_done+0x1b/0x30
[19982.965594]  [<c0340d0c>] scsi_finish_command+0x4c/0x60
[19982.970861]  [<c0345c07>] scsi_softirq_done+0x77/0xe0
[19982.975955]  [<c0257f8b>] blk_done_softirq+0x6b/0x80
[19982.980962]  [<c01243a2>] __do_softirq+0x62/0xc0
[19982.985624]  [<c0124455>] do_softirq+0x55/0x60
[19982.990112]  [<c0124be5>] ksoftirqd+0x65/0x100
[19982.994599]  [<c0132963>] kthread+0xa3/0xd0
[19982.998827]  [<c0104e17>] kernel_thread_helper+0x7/0x10
[19983.004095]  =======================
[19983.009065] cdrom: This disc doesn't have any tracks I recognize!
[19983.017405] pktcdvd: writer pktcdvd2 mapped to sr0
[19983.032012] drivers/scsi/scsi_lib.c:838: setting error to 134217730
[19983.038295]  [<c010521a>] show_trace_log_lvl+0x1a/0x30
[19983.043481]  [<c0105952>] show_trace+0x12/0x20
[19983.047977]  [<c0105a46>] dump_stack+0x16/0x20
[19983.052465]  [<c034543a>] scsi_io_completion+0x28a/0x3a0
[19983.057819]  [<c034556b>] scsi_blk_pc_done+0x1b/0x30
[19983.062826]  [<c0340d0c>] scsi_finish_command+0x4c/0x60
[19983.068093]  [<c0345c07>] scsi_softirq_done+0x77/0xe0
[19983.073188]  [<c0257f8b>] blk_done_softirq+0x6b/0x80
[19983.078196]  [<c01243a2>] __do_softirq+0x62/0xc0
[19983.082857]  [<c0124455>] do_softirq+0x55/0x60
[19983.087345]  [<c0124be5>] ksoftirqd+0x65/0x100
[19983.091832]  [<c0132963>] kthread+0xa3/0xd0
[19983.096060]  [<c0104e17>] kernel_thread_helper+0x7/0x10
[19983.101328]  =======================
[19983.124101] drivers/scsi/scsi_lib.c:838: setting error to 134217730
[19983.130380]  [<c010521a>] show_trace_log_lvl+0x1a/0x30
[19983.135558]  [<c0105952>] show_trace+0x12/0x20
[19983.140045]  [<c0105a46>] dump_stack+0x16/0x20
[19983.144534]  [<c034543a>] scsi_io_completion+0x28a/0x3a0
[19983.149887]  [<c034556b>] scsi_blk_pc_done+0x1b/0x30
[19983.154895]  [<c0340d0c>] scsi_finish_command+0x4c/0x60
[19983.160163]  [<c0345c07>] scsi_softirq_done+0x77/0xe0
[19983.165257]  [<c0257f8b>] blk_done_softirq+0x6b/0x80
[19983.170265]  [<c01243a2>] __do_softirq+0x62/0xc0
[19983.174934]  [<c0124455>] do_softirq+0x55/0x60
[19983.179422]  [<c0124be5>] ksoftirqd+0x65/0x100
[19983.183911]  [<c0132963>] kthread+0xa3/0xd0
[19983.188138]  [<c0104e17>] kernel_thread_helper+0x7/0x10
[19983.193405]  =======================
[19983.198099] pktcdvd: pkt_get_last_written failed

# mkudffs /dev/pktcdvd/0
[20417.848314] drivers/ide/ide-cd.c:729: setting error to 2
[20417.853630]  [<c010521a>] show_trace_log_lvl+0x1a/0x30
[20417.858791]  [<c0105952>] show_trace+0x12/0x20
[20417.863243]  [<c0105a46>] dump_stack+0x16/0x20
[20417.867696]  [<c033f6e4>] cdrom_decode_status+0x1f4/0x3b0
[20417.873112]  [<c033fae8>] cdrom_newpc_intr+0x38/0x320
[20417.878171]  [<c0331106>] ide_intr+0x96/0x200
[20417.882546]  [<c0150cf8>] handle_IRQ_event+0x28/0x60
[20417.887528]  [<c0151f96>] handle_edge_irq+0xa6/0x130
[20417.892501]  [<c0106449>] do_IRQ+0x49/0xa0
[20417.896607]  [<c0104c3a>] common_interrupt+0x2e/0x34
[20417.901580]  [<c01022d2>] mwait_idle+0x12/0x20
[20417.906034]  [<c01023ca>] cpu_idle+0x4a/0x80
[20417.910313]  [<c0101147>] rest_init+0x37/0x40
[20417.914680]  [<c068ac7b>] start_kernel+0x34b/0x420
[20417.919488]  [<00000000>] 0x0
[20417.922468]  =======================
[20417.928941] pktcdvd: write speed 5540kB/s
[20424.114292] pktcdvd: 2816kB available on disc
start=0, blocks=16, type=RESERVED
start=16, blocks=3, type=VRS
start=19, blocks=237, type=USPACE
start=256, blocks=1, type=ANCHOR
start=257, blocks=16, type=PVDS
start=273, blocks=1, type=LVID
start=274, blocks=877, type=PSPACE
start=1151, blocks=1, type=ANCHOR
start=1152, blocks=239, type=USPACE
start=1391, blocks=16, type=RVDS
start=1407, blocks=1, type=ANCHOR

^ This was on a dvd, and it's reporting 2816kB ?

# mkudffs /dev/pktcdvd/1
[20712.696994] drivers/ide/ide-cd.c:729: setting error to 2
[20712.702306]  [<c010521a>] show_trace_log_lvl+0x1a/0x30
[20712.707467]  [<c0105952>] show_trace+0x12/0x20
[20712.711919]  [<c0105a46>] dump_stack+0x16/0x20
[20712.716373]  [<c033f6e4>] cdrom_decode_status+0x1f4/0x3b0
[20712.721788]  [<c033fae8>] cdrom_newpc_intr+0x38/0x320
[20712.726848]  [<c0331106>] ide_intr+0x96/0x200
[20712.731214]  [<c0150cf8>] handle_IRQ_event+0x28/0x60
[20712.736195]  [<c0151f96>] handle_edge_irq+0xa6/0x130
[20712.741168]  [<c0106449>] do_IRQ+0x49/0xa0
[20712.745275]  [<c0104c3a>] common_interrupt+0x2e/0x34
[20712.750248]  [<c01022d2>] mwait_idle+0x12/0x20
[20712.754701]  [<c01023ca>] cpu_idle+0x4a/0x80
[20712.758981]  [<c0101147>] rest_init+0x37/0x40
[20712.763348]  [<c068ac7b>] start_kernel+0x34b/0x420
[20712.768156]  [<00000000>] 0x0
[20712.771136]  =======================
[20712.798160] pktcdvd: pkt_get_last_written failed
trying to change type of multiple extents

# mkudffs /dev/pktcdvd/2
[20742.293998] drivers/scsi/scsi_lib.c:838: setting error to 134217730
[20742.300273]  [<c010521a>] show_trace_log_lvl+0x1a/0x30
[20742.305460]  [<c0105952>] show_trace+0x12/0x20
[20742.309947]  [<c0105a46>] dump_stack+0x16/0x20
[20742.314436]  [<c034543a>] scsi_io_completion+0x28a/0x3a0
[20742.319790]  [<c034556b>] scsi_blk_pc_done+0x1b/0x30
[20742.324797]  [<c0340d0c>] scsi_finish_command+0x4c/0x60
[20742.330065]  [<c0345c07>] scsi_softirq_done+0x77/0xe0
[20742.335158]  [<c0257f8b>] blk_done_softirq+0x6b/0x80
[20742.340167]  [<c01243a2>] __do_softirq+0x62/0xc0
[20742.344827]  [<c0124455>] do_softirq+0x55/0x60
[20742.349314]  [<c0124be5>] ksoftirqd+0x65/0x100
[20742.353802]  [<c0132963>] kthread+0xa3/0xd0
[20742.358030]  [<c0104e17>] kernel_thread_helper+0x7/0x10
[20742.363298]  =======================
[20742.385965] drivers/scsi/scsi_lib.c:838: setting error to 134217730
[20742.392247]  [<c010521a>] show_trace_log_lvl+0x1a/0x30
[20742.397425]  [<c0105952>] show_trace+0x12/0x20
[20742.401912]  [<c0105a46>] dump_stack+0x16/0x20
[20742.406400]  [<c034543a>] scsi_io_completion+0x28a/0x3a0
[20742.411754]  [<c034556b>] scsi_blk_pc_done+0x1b/0x30
[20742.416761]  [<c0340d0c>] scsi_finish_command+0x4c/0x60
[20742.422029]  [<c0345c07>] scsi_softirq_done+0x77/0xe0
[20742.427124]  [<c0257f8b>] blk_done_softirq+0x6b/0x80
[20742.432131]  [<c01243a2>] __do_softirq+0x62/0xc0
[20742.436792]  [<c0124455>] do_softirq+0x55/0x60
[20742.441280]  [<c0124be5>] ksoftirqd+0x65/0x100
[20742.445767]  [<c0132963>] kthread+0xa3/0xd0
[20742.449996]  [<c0104e17>] kernel_thread_helper+0x7/0x10
[20742.455263]  =======================
[20742.460038] pktcdvd: pkt_get_last_written failed
trying to change type of multiple extents

# mount -t udf /dev/pktcdvd/0 /mnt/pkt0
[20912.824545] drivers/ide/ide-cd.c:729: setting error to 2
[20912.829857]  [<c010521a>] show_trace_log_lvl+0x1a/0x30
[20912.835019]  [<c0105952>] show_trace+0x12/0x20
[20912.839472]  [<c0105a46>] dump_stack+0x16/0x20
[20912.843924]  [<c033f6e4>] cdrom_decode_status+0x1f4/0x3b0
[20912.849338]  [<c033fae8>] cdrom_newpc_intr+0x38/0x320
[20912.854399]  [<c0331106>] ide_intr+0x96/0x200
[20912.858765]  [<c0150cf8>] handle_IRQ_event+0x28/0x60
[20912.863746]  [<c0151f96>] handle_edge_irq+0xa6/0x130
[20912.868720]  [<c0106449>] do_IRQ+0x49/0xa0
[20912.872826]  [<c0104c3a>] common_interrupt+0x2e/0x34
[20912.877799]  [<c01022d2>] mwait_idle+0x12/0x20
[20912.882252]  [<c01023ca>] cpu_idle+0x4a/0x80
[20912.886532]  [<c0101147>] rest_init+0x37/0x40
[20912.890899]  [<c068ac7b>] start_kernel+0x34b/0x420
[20912.895707]  [<00000000>] 0x0
[20912.898696]  =======================
[20912.905058] pktcdvd: write speed 5540kB/s
[20919.178571] pktcdvd: 2816kB available on disc
[20920.682973] UDF-fs INFO UDF 0.9.8.1 (2004/29/09) Mounting volume 'LinuxUDF', 
timestamp 2007/04/26 17:34 (1ed4)

# mount -t udf /dev/pktcdvd/1 /mnt/pkt1
[21007.153670] drivers/ide/ide-cd.c:729: setting error to 2
[21007.158985]  [<c010521a>] show_trace_log_lvl+0x1a/0x30
[21007.164146]  [<c0105952>] show_trace+0x12/0x20
[21007.168599]  [<c0105a46>] dump_stack+0x16/0x20
[21007.173052]  [<c033f6e4>] cdrom_decode_status+0x1f4/0x3b0
[21007.178466]  [<c033fae8>] cdrom_newpc_intr+0x38/0x320
[21007.183527]  [<c0331106>] ide_intr+0x96/0x200
[21007.187892]  [<c0150cf8>] handle_IRQ_event+0x28/0x60
[21007.192874]  [<c0151f96>] handle_edge_irq+0xa6/0x130
[21007.197848]  [<c0106449>] do_IRQ+0x49/0xa0
[21007.201954]  [<c0104c3a>] common_interrupt+0x2e/0x34
[21007.206927]  [<c01022d2>] mwait_idle+0x12/0x20
[21007.211380]  [<c01023ca>] cpu_idle+0x4a/0x80
[21007.215660]  [<c0101147>] rest_init+0x37/0x40
[21007.220026]  [<c068ac7b>] start_kernel+0x34b/0x420
[21007.224835]  [<00000000>] 0x0
[21007.227823]  =======================
[21007.254866] pktcdvd: pkt_get_last_written failed
mount: /dev/pktcdvd/1: can't read superblock

# mount -t udf /dev/pktcdvd/2 /mnt/pkt2
[21025.193414] drivers/scsi/scsi_lib.c:838: setting error to 134217730
[21025.199694]  [<c010521a>] show_trace_log_lvl+0x1a/0x30
[21025.204880]  [<c0105952>] show_trace+0x12/0x20
[21025.209368]  [<c0105a46>] dump_stack+0x16/0x20
[21025.213856]  [<c034543a>] scsi_io_completion+0x28a/0x3a0
[21025.219210]  [<c034556b>] scsi_blk_pc_done+0x1b/0x30
[21025.224217]  [<c0340d0c>] scsi_finish_command+0x4c/0x60
[21025.229486]  [<c0345c07>] scsi_softirq_done+0x77/0xe0
[21025.234579]  [<c0257f8b>] blk_done_softirq+0x6b/0x80
[21025.239586]  [<c01243a2>] __do_softirq+0x62/0xc0
[21025.244248]  [<c0124455>] do_softirq+0x55/0x60
[21025.248735]  [<c0124be5>] ksoftirqd+0x65/0x100
[21025.253223]  [<c0132963>] kthread+0xa3/0xd0
[21025.257452]  [<c0104e17>] kernel_thread_helper+0x7/0x10
[21025.262719]  =======================
[21025.285506] drivers/scsi/scsi_lib.c:838: setting error to 134217730
[21025.291781]  [<c010521a>] show_trace_log_lvl+0x1a/0x30
[21025.296959]  [<c0105952>] show_trace+0x12/0x20
[21025.301446]  [<c0105a46>] dump_stack+0x16/0x20
[21025.305933]  [<c034543a>] scsi_io_completion+0x28a/0x3a0
[21025.311287]  [<c034556b>] scsi_blk_pc_done+0x1b/0x30
[21025.316295]  [<c0340d0c>] scsi_finish_command+0x4c/0x60
[21025.321563]  [<c0345c07>] scsi_softirq_done+0x77/0xe0
[21025.326657]  [<c0257f8b>] blk_done_softirq+0x6b/0x80
[21025.331665]  [<c01243a2>] __do_softirq+0x62/0xc0
[21025.336325]  [<c0124455>] do_softirq+0x55/0x60
[21025.340814]  [<c0124be5>] ksoftirqd+0x65/0x100
[21025.345301]  [<c0132963>] kthread+0xa3/0xd0
[21025.349529]  [<c0104e17>] kernel_thread_helper+0x7/0x10
[21025.354797]  =======================
[21025.359503] pktcdvd: pkt_get_last_written failed
mount: /dev/pktcdvd/2: can't read superblock

/dev/sr0 is the USB cd-rw burner.

William Heimbigner
icxcnika@....tar.cc
View attachment "dmesg.1.txt" of type "TEXT/plain" (37167 bytes)

Powered by blists - more mailing lists