Bug 128319

Summary: kernel paging failure on usb printer disconnect
Product: [Fedora] Fedora Reporter: Tom London <selinux>
Component: kernelAssignee: Pete Zaitcev <zaitcev>
Status: CLOSED WORKSFORME QA Contact: Brian Brock <bbrock>
Severity: medium Docs Contact:
Priority: medium    
Version: rawhideCC: wtogami
Target Milestone: ---   
Target Release: ---   
Hardware: i686   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2005-01-14 06:41:44 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
log with kernel page fault
none
Moving usb_buffer_free none

Description Tom London 2004-07-21 18:31:04 UTC 
From Bugzilla Helper:
User-Agent: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.7) Gecko/20040625

Description of problem:
I disconnected a misbehaving usb printer and got the following kernel
paging error in the log:

Jul 21 11:03:21 fedora udev[3681]: removing device node '/dev/usb/lp0'
Jul 21 11:03:21 fedora kernel: usb 1-5.3: USB disconnect, address 3
Jul 21 11:03:21 fedora kernel: audit(1090433001.667:0): avc:  denied 
{ rmdir } for  pid=3681 exe=/sbin/udev name=usb dev=hda2 ino=2719883
scontext=system_u:system_r:udev_t tcontext=system_u:object_r:device_t
tclass=dir
Jul 21 11:03:21 fedora ptal-mlcd: ERROR at ExMgr.cpp:3209,
dev=<mlc:usb:PSC_900_Series@/dev/usb/lp0>, pid=2018, e=19,
t=1090433001         llioSubprocess: llioRead returns -1, expected=6!
Jul 21 11:03:21 fedora ptal-mlcd: ERROR at ExMgr.cpp:2820,
dev=<mlc:usb:PSC_900_Series@/dev/usb/lp0>, pid=1995, e=11,
t=1090433001         llioService: fdRead returns 0, expected=6!
Jul 21 11:03:21 fedora ptal-mlcd: ERROR at ExMgr.cpp:871,
dev=<mlc:usb:PSC_900_Series@/dev/usb/lp0>, pid=1995, e=32,
t=1090433001         exClose(reason=0x0010)                          
                                                     
Jul 21 11:03:21 fedora kernel: drivers/usb/class/usblp.c: usblp0: removed
Jul 21 11:03:21 fedora kernel: Unable to handle kernel paging request
at virtual address 6b6b6b8f
Jul 21 11:03:21 fedora kernel:  printing eip:
Jul 21 11:03:21 fedora kernel: 0226f5c1
Jul 21 11:03:21 fedora kernel: *pde = 00000000
Jul 21 11:03:21 fedora kernel: Oops: 0000 [#1]
Jul 21 11:03:21 fedora kernel: Modules linked in: appletalk ipx p8022
psnap llc snd_mixer_oss snd_intel8x0 snd_ac97_codec snd_pcm snd_timer
snd_page_alloc gameport snd_mpu401_uart snd_rawmidi snd_seq_device snd
soundcore nfsd exportfs lockd ipv6 parport_pc lp parport autofs4
sunrpc sis900 8139too mii ipt_REJECT ipt_state ip_conntrack
iptable_filter ip_tables floppy sg scsi_mod microcode dm_mod usblp
ohci_hcd ehci_hcd button battery asus_acpi ac ext3 jbd
Jul 21 11:03:21 fedora kernel: CPU:    0
Jul 21 11:03:21 fedora kernel: EIP:    0060:[<0226f5c1>]    Not tainted
Jul 21 11:03:21 fedora kernel: EFLAGS: 00010202   (2.6.7-1.494)
Jul 21 11:03:21 fedora kernel: EIP is at usb_buffer_free+0xf/0x26
Jul 21 11:03:21 fedora kernel: eax: 6b6b6b6b   ebx: 2ffa8578   ecx:
2cf54000   edx: 00002000
Jul 21 11:03:21 fedora kernel: esi: 2ffa857c   edi: 2fa805fc   ebp:
2fa74728   esp: 2e82ff74
Jul 21 11:03:21 fedora kernel: ds: 007b   es: 007b   ss: 0068
Jul 21 11:03:21 fedora kernel: Process ptal-mlcd (pid: 1995,
threadinfo=2e82f000 task=281e8c30)
Jul 21 11:03:21 fedora kernel: Stack: 2ffa8578 3085941b 2af54000
3085a765 3085a600 00000000 2ffa8578 308594d1
Jul 21 11:03:21 fedora kernel:        27e389e8 2ff8c9c0 0216210f
27e389e8 00000000 2ce428f0 2e82f000 02160a3d
Jul 21 11:03:21 fedora kernel:        2e82ffc4 00000010 0993b668
ffff3200 00000009 00000005 09936008 00000010
Jul 21 11:03:21 fedora kernel: Call Trace:
Jul 21 11:03:21 fedora kernel:  [<3085941b>] usblp_cleanup+0x2d/0x70
[usblp]
Jul 21 11:03:21 fedora kernel:  [<308594d1>] usblp_release+0x54/0x59
[usblp]
Jul 21 11:03:21 fedora kernel:  [<0216210f>] __fput+0x3f/0xd8
Jul 21 11:03:21 fedora kernel:  [<02160a3d>] filp_close+0x59/0x5f
Jul 21 11:03:21 fedora kernel: Code: 8b 58 24 85 db 74 0e 83 7b 18 00
74 08 ff 74 24 08 ff 53 18
Jul 21 11:03:29 fedora kernel:  <6>usb 1-5.3: new full speed USB
device using address 4
Jul 21 11:03:30 fedora kernel: drivers/usb/class/usblp.c: usblp0: USB
Bidirectional printer dev 4 if 0 alt 1 proto 2 vid 0x03F0 pid 0x1E11
Jul 21 11:03:32 fedora udev[3770]: configured rule in
'/etc/udev/rules.d/50-udev.rules' at line 29 applied, 'lp0' becomes
'usb/%k'
Jul 21 11:03:32 fedora udev[3770]: creating device node '/dev/usb/lp0'

Correct functioning resumed when printer was reconnected.

Version-Release number of selected component (if applicable):
kernel-2.6.7-1.494

How reproducible:
Couldn't Reproduce

Steps to Reproduce:
1. disconnect usb printer
2. reconnect usb printer
3.
    

Additional info:
Comment 1 Tom London 2004-07-23 16:09:25 UTC 
Created attachment 102182 [details]
log with kernel page fault

I've recreated this 'error': I attach a longer extract from /var/log/messages.

I've noticed the following messages that may be somehow related:
Jul 23 07:01:31 fedora kernel: ohci1394: fw-host0: Unexpected PCI resource
length of 1000!
Jul 23 07:01:31 fedora kernel: ohci1394: fw-host0: OHCI-1394 1.0 (PCI):
IRQ=[11]  MMIO=[ed100000-ed1007ff]  Max Packet=[2048]

and

Jul 23 07:01:37 fedora kernel: drivers/usb/class/usblp.c: usblp0: nonzero
read/write bulk status received: -2
Jul 23 07:01:37 fedora kernel: drivers/usb/class/usblp.c: usblp0: error -2
reading from printer

and

[The following happened at the moment of disconnect, just prior
to the page fault:]

Jul 23 07:01:53 fedora kernel: drivers/usb/class/usblp.c: usblp0: nonzero
read/write bulk status received: -32
Jul 23 07:01:53 fedora udev[2492]: removing device node '/dev/usb/lp0'
Jul 23 07:01:53 fedora kernel: usb 1-5.3: USB disconnect, address 3
Comment 2 Tom London 2004-08-05 15:52:09 UTC 
same behavior in .509
Comment 3 Tom London 2004-08-11 15:31:55 UTC 
Initial test indicates this is working correctly in .515.  Thanks!
(I'll test more later)

Here is the log:

Aug 11 08:28:34 fedora kernel: drivers/usb/class/usblp.c: usblp0:
nonzero read/write bulk status received: -32
Aug 11 08:28:34 fedora udev[3927]: removing device node '/dev/usb/lp0'
Aug 11 08:28:34 fedora kernel: usb 1-5.3: USB disconnect, address 3
Aug 11 08:28:34 fedora kernel: audit(1092238114.877:0): avc:  denied 
{ dac_read_search } for  pid=3926 exe=/bin/bash capability=2
scontext=system_u:system_r:udev_t tcontext=system_u:system_r:udev_t
tclass=capability
Aug 11 08:28:34 fedora kernel: audit(1092238114.888:0): avc:  denied 
{ dac_read_search } for  pid=3930 exe=/bin/bash capability=2
scontext=system_u:system_r:udev_t tcontext=system_u:system_r:udev_t
tclass=capability
Aug 11 08:28:34 fedora kernel: audit(1092238114.894:0): avc:  denied 
{ dac_read_search } for  pid=3931 exe=/bin/bash capability=2
scontext=system_u:system_r:udev_t tcontext=system_u:system_r:udev_t
tclass=capability
Aug 11 08:28:34 fedora kernel: audit(1092238114.896:0): avc:  denied 
{ rmdir } for  pid=3927 exe=/sbin/udev name=usb dev=hda2 ino=2719948
scontext=system_u:system_r:udev_t tcontext=system_u:object_r:device_t
tclass=dir
Aug 11 08:28:34 fedora kernel: audit(1092238114.983:0): avc:  denied 
{ dac_read_search } for  pid=3954 exe=/bin/bash capability=2
scontext=system_u:system_r:udev_t tcontext=system_u:system_r:udev_t
tclass=capability
Aug 11 08:28:34 fedora dbus: avc:  denied  { send_msg } for 
scontext=system_u:system_r:hotplug_t
tcontext=system_u:system_r:dbusd_t tclass=dbus
Aug 11 08:28:34 fedora dbus: avc:  denied  { send_msg } for 
scontext=system_u:system_r:hotplug_t
tcontext=system_u:system_r:dbusd_t tclass=dbus
Aug 11 08:28:35 fedora kernel: audit(1092238115.089:0): avc:  denied 
{ dac_read_search } for  pid=3958 exe=/bin/bash capability=2
scontext=system_u:system_r:udev_t tcontext=system_u:system_r:udev_t
tclass=capability
Aug 11 08:28:35 fedora dbus: avc:  denied  { send_msg } for 
scontext=system_u:system_r:hotplug_t
tcontext=system_u:system_r:dbusd_t tclass=dbus
Aug 11 08:28:35 fedora ptal-mlcd: ERROR at ExMgr.cpp:3209,
dev=<mlc:usb:PSC_900_Series@/dev/usb/lp0>, pid=2215, e=19,
t=1092238115         llioSubprocess: llioRead returns -1, expected=6!
Aug 11 08:28:35 fedora ptal-mlcd: ERROR at ExMgr.cpp:2820,
dev=<mlc:usb:PSC_900_Series@/dev/usb/lp0>, pid=2192, e=5, t=1092238115
        llioService: fdRead returns 0, expected=6!
Aug 11 08:28:35 fedora ptal-mlcd: ERROR at ExMgr.cpp:871,
dev=<mlc:usb:PSC_900_Series@/dev/usb/lp0>, pid=2192, e=32,
t=1092238115         exClose(reason=0x0010)                          
                                                     
Aug 11 08:28:35 fedora kernel: drivers/usb/class/usblp.c: usblp0: removed
Aug 11 08:28:43 fedora kernel: usb 1-5.3: new full speed USB device
using address 4
Aug 11 08:28:43 fedora kernel: drivers/usb/class/usblp.c: usblp0: USB
Bidirectional printer dev 4 if 0 alt 1 proto 2 vid 0x03F0 pid 0x1E11
Comment 4 Tom London 2004-08-25 02:20:34 UTC 
This seems to be back in .524. (Running strict/permissive with latest
from Rawhide, except for kernel).

This one looks different from the ones above. The virtual address is
reported as 00091abe (the ones above were consistently reporting
virtual address of 6b6b6b8f)

Here are the log entries......

Aug 24 19:17:35 fedora udev[5707]: removing device node '/dev/usb/lp0'
Aug 24 19:17:35 fedora kernel: usb 1-5.3: USB disconnect, address 3
Aug 24 19:17:35 fedora kernel: audit(1093400255.628:0): avc:  denied 
{ rmdir } for  pid=5707 exe=/sbin/udev name=usb dev=hda2 ino=2719948
scontext=system_u:system_r:udev_t tcontext=system_u:object_r:device_t
tclass=dir
Aug 24 19:17:35 fedora dbus: avc:  received policyload notice (seqno=1)
Aug 24 19:17:35 fedora dbus: avc:  7 AV entries and 7/512 buckets
used, longest chain length 1
Aug 24 19:17:35 fedora dbus: avc:  denied  { send_msg } for 
scontext=system_u:system_r:hald_t tcontext=user_u:user_r:user_t
tclass=dbus
Aug 24 19:17:35 fedora dbus: avc:  denied  { send_msg } for 
scontext=system_u:system_r:hald_t tcontext=user_u:user_r:user_t
tclass=dbus
Aug 24 19:17:35 fedora ptal-mlcd: ERROR at ExMgr.cpp:3209,
dev=<mlc:usb:PSC_900_Series@/dev/usb/lp0>, pid=2372, e=19,
t=1093400255         llioSubprocess: llioRead returns -1, expected=6!
Aug 24 19:17:35 fedora ptal-mlcd: ERROR at ExMgr.cpp:2820,
dev=<mlc:usb:PSC_900_Series@/dev/usb/lp0>, pid=2349, e=5, t=1093400255
        llioService: fdRead returns 0, expected=6!
Aug 24 19:17:35 fedora ptal-mlcd: ERROR at ExMgr.cpp:871,
dev=<mlc:usb:PSC_900_Series@/dev/usb/lp0>, pid=2349, e=32,
t=1093400255         exClose(reason=0x0010)                          
                                                     
Aug 24 19:17:35 fedora kernel: drivers/usb/class/usblp.c: usblp0: removed
Aug 24 19:17:35 fedora kernel: Unable to handle kernel paging request
at virtual address 00091abe
Aug 24 19:17:35 fedora kernel:  printing eip:
Aug 24 19:17:35 fedora kernel: 0226e7e1
Aug 24 19:17:35 fedora kernel: *pde = 00000000
Aug 24 19:17:35 fedora kernel: Oops: 0000 [#1]
Aug 24 19:17:35 fedora kernel: Modules linked in: snd_pcm_oss
snd_mixer_oss snd_intel8x0 snd_ac97_codec snd_pcm snd_timer
snd_page_alloc gameport snd_mpu401_uart snd_rawmidi snd_seq_device snd
soundcore nfsd exportfs lockd parport_pc lp parport deflate
zlib_deflate twofish serpent aes_i586 blowfish des sha256 crypto_null
ipcomp esp4 ah4 af_key autofs4 sunrpc sis900 8139too mii ipt_REJECT
ipt_state ip_conntrack iptable_filter ip_tables floppy microcode
dm_mod usblp ohci_hcd ehci_hcd button battery asus_acpi ac md5 ipv6
ext3 jbd
Aug 24 19:17:35 fedora kernel: CPU:    0
Aug 24 19:17:35 fedora kernel: EIP:    0060:[<0226e7e1>]    Not tainted
Aug 24 19:17:35 fedora kernel: EFLAGS: 00010206   (2.6.8-1.524)
Aug 24 19:17:35 fedora kernel: EIP is at usb_buffer_free+0xf/0x26
Aug 24 19:17:35 fedora kernel: eax: 00091a9a   ebx: 2ffac880   ecx:
2b8a2000   edx: 00002000
Aug 24 19:17:35 fedora kernel: esi: 2ffac884   edi: 2b418144   ebp:
2b96a2e8   esp: 26211f74
Aug 24 19:17:35 fedora kernel: ds: 007b   es: 007b   ss: 0068
Aug 24 19:17:35 fedora kernel: Process ptal-mlcd (pid: 2349,
threadinfo=26211000 task=262012e0)
Aug 24 19:17:35 fedora kernel: Stack: 2ffac880 3085c41b 298a2000
3085d765 3085d600 00000000 2ffac880 3085c4d1
Aug 24 19:17:35 fedora kernel:        26373080 2ff8ff80 02160f32
26373080 00000000 2ee9e900 26211000 0215f7a0
Aug 24 19:17:35 fedora kernel:        26211fc4 00000010 08fbf668
ffff3200 00000009 00000005 08fba008 00000010
Aug 24 19:17:35 fedora kernel: Call Trace:
Aug 24 19:17:35 fedora kernel:  [<3085c41b>] usblp_cleanup+0x2d/0x70
[usblp]
Aug 24 19:17:35 fedora kernel:  [<3085c4d1>] usblp_release+0x54/0x59
[usblp]
Aug 24 19:17:35 fedora kernel:  [<02160f32>] __fput+0x3f/0xd8
Aug 24 19:17:35 fedora kernel:  [<0215f7a0>] filp_close+0x59/0x5f
Aug 24 19:17:35 fedora kernel: Code: 8b 58 24 85 db 74 0e 83 7b 18 00
74 08 ff 74 24 08 ff 53 18
Aug 24 19:17:51 fedora kernel:  <6>usb 1-5.3: new full speed USB
device using address 4
Aug 24 19:17:51 fedora kernel: drivers/usb/class/usblp.c: usblp0: USB
Bidirectional printer dev 4 if 0 alt 1 proto 2 vid 0x03F0 pid 0x1E11
Aug 24 19:17:53 fedora dbus: avc:  denied  { send_msg } for 
scontext=system_u:system_r:hald_t tcontext=user_u:user_r:user_t
tclass=dbus
Aug 24 19:17:53 fedora dbus: avc:  denied  { send_msg } for 
scontext=system_u:system_r:hald_t tcontext=user_u:user_r:user_t
tclass=dbus
Aug 24 19:17:53 fedora dbus: avc:  denied  { send_msg } for 
scontext=user_u:user_r:user_t tcontext=system_u:system_r:hald_t
tclass=dbus
Aug 24 19:17:53 fedora dbus: avc:  denied  { send_msg } for 
scontext=system_u:system_r:hald_t tcontext=user_u:user_r:user_t
tclass=dbus
Aug 24 19:17:53 fedora dbus: avc:  denied  { send_msg } for 
scontext=user_u:user_r:user_t tcontext=system_u:system_r:hald_t
tclass=dbus
Aug 24 19:17:53 fedora dbus: avc:  denied  { send_msg } for 
scontext=system_u:system_r:hald_t tcontext=user_u:user_r:user_t
tclass=dbus
Aug 24 19:18:13 fedora hal.hotplug[5790]: timed out for /class/usb/lp0
(waited 20000 ms)
Aug 24 19:18:14 fedora udev[5792]: configured rule in
'/etc/udev/rules.d/50-udev.rules' at line 29 applied, 'lp0' becomes
'usb/%k'
Aug 24 19:18:14 fedora udev[5792]: creating device node '/dev/usb/lp0'
Aug 24 19:18:15 fedora kernel: audit(1093400294.923:0): avc:  denied 
{ search } for  pid=5792 exe=/sbin/udev name=contexts dev=hda2
ino=4509745 scontext=system_u:system_r:udev_t
tcontext=system_u:object_r:default_context_t tclass=dir
Aug 24 19:18:15 fedora kernel: audit(1093400294.923:0): avc:  denied 
{ search } for  pid=5792 exe=/sbin/udev name=files dev=hda2
ino=4509746 scontext=system_u:system_r:udev_t
tcontext=system_u:object_r:file_context_t tclass=dir
Aug 24 19:18:15 fedora kernel: audit(1093400294.923:0): avc:  denied 
{ read } for  pid=5792 exe=/sbin/udev name=file_contexts dev=hda2
ino=4505700 scontext=system_u:system_r:udev_t
tcontext=system_u:object_r:file_context_t tclass=file
Aug 24 19:18:15 fedora kernel: audit(1093400294.923:0): avc:  denied 
{ getattr } for  pid=5792 exe=/sbin/udev
path=/etc/selinux/strict/contexts/files/file_contexts dev=hda2
ino=4505700 scontext=system_u:system_r:udev_t
tcontext=system_u:object_r:file_context_t tclass=file
Aug 24 19:18:15 fedora kernel: audit(1093400295.045:0): avc:  denied 
{ write } for  pid=5792 exe=/sbin/udev name=fscreate dev=proc
ino=379584534 scontext=system_u:system_r:udev_t
tcontext=system_u:system_r:udev_t tclass=file
Aug 24 19:18:15 fedora kernel: audit(1093400295.045:0): avc:  denied 
{ setfscreate } for  pid=5792 exe=/sbin/udev
scontext=system_u:system_r:udev_t tcontext=system_u:system_r:udev_t
tclass=process
Aug 24 19:18:15 fedora kernel: audit(1093400295.070:0): avc:  denied 
{ search } for  pid=5794 exe=/bin/bash name=console dev=hda2
ino=4456494 scontext=system_u:system_r:udev_t
tcontext=system_u:object_r:pam_var_console_t tclass=dir
Aug 24 19:18:15 fedora kernel: audit(1093400295.070:0): avc:  denied 
{ getattr } for  pid=5794 exe=/bin/bash
path=/var/run/console/console.lock dev=hda2 ino=4457624
scontext=system_u:system_r:udev_t
tcontext=system_u:object_r:pam_var_console_t tclass=file
Aug 24 19:18:15 fedora kernel: audit(1093400295.073:0): avc:  denied 
{ read write } for  pid=2860 exe=/usr/sbin/hald name=lp0 dev=hda2
ino=2719883 scontext=system_u:system_r:hald_t
tcontext=system_u:object_r:printer_device_t tclass=chr_file
Aug 24 19:18:15 fedora kernel: audit(1093400295.073:0): avc:  denied 
{ ioctl } for  pid=2860 exe=/usr/sbin/hald path=/dev/usb/lp0 dev=hda2
ino=2719883 scontext=system_u:system_r:hald_t
tcontext=system_u:object_r:printer_device_t tclass=chr_file
Aug 24 19:18:15 fedora dbus: avc:  denied  { send_msg } for 
scontext=system_u:system_r:hald_t tcontext=user_u:user_r:user_t
tclass=dbus
Aug 24 19:18:15 fedora kernel: audit(1093400295.118:0): avc:  denied 
{ read } for  pid=5794 exe=/sbin/pam_console_setowner
name=console.lock dev=hda2 ino=4457624
scontext=system_u:system_r:udev_t
tcontext=system_u:object_r:pam_var_console_t tclass=file
Aug 24 19:18:15 fedora dbus: avc:  denied  { send_msg } for 
scontext=system_u:system_r:hald_t tcontext=user_u:user_r:user_t
tclass=dbus
Comment 5 Tom London 2004-08-30 00:59:44 UTC 
Continues to be a problem in .533, running SELinux strict/enforcing.

Here's the log entries generated when I 'pull the plug' on the USB
printer.

Aug 29 17:58:54 fedora ptal-mlcd: ERROR at ExMgr.cpp:3209,
dev=<mlc:usb:PSC_900_Series@/dev/usb/lp0>, pid=2917, e=19,
t=1093827534         llioSubprocess: llioRead returns -1, expected=6!
Aug 29 17:58:54 fedora kernel: usb 1-5.3: USB disconnect, address 3
Aug 29 17:58:54 fedora ptal-mlcd: ERROR at ExMgr.cpp:2820,
dev=<mlc:usb:PSC_900_Series@/dev/usb/lp0>, pid=2894, e=5, t=1093827534
        llioService: fdRead returns 0, expected=6!
Aug 29 17:58:54 fedora ptal-mlcd: ERROR at ExMgr.cpp:871,
dev=<mlc:usb:PSC_900_Series@/dev/usb/lp0>, pid=2894, e=32,
t=1093827534         exClose(reason=0x0010)
Aug 29 17:58:54 fedora kernel: drivers/usb/class/usblp.c: usblp0: removed
Aug 29 17:58:54 fedora kernel: Unable to handle kernel paging request
at virtual address 0011002c
Aug 29 17:58:54 fedora kernel:  printing eip:
Aug 29 17:58:54 fedora kernel: 0227279b
Aug 29 17:58:54 fedora kernel: *pde = 00000000
Aug 29 17:58:54 fedora kernel: Oops: 0000 [#1]
Aug 29 17:58:54 fedora kernel: Modules linked in: ipcomp esp4 ah4
af_key snd_pcm_oss snd_mixer_oss nfsd exportfs lockd md5 ipv6
parport_pc lp parport autofs4 sunrpc ipt_REJECT ipt_state ip_conntrack
iptable_filter ip_tables microcode dm_mod button battery asus_acpi ac
usblp ohci1394 ieee1394 ohci_hcd ehci_hcd snd_intel8x0 snd_ac97_codec
snd_pcm snd_timer snd_page_alloc gameport snd_mpu401_uart snd_rawmidi
snd_seq_device snd soundcore sis900 8139too mii floppy sg scsi_mod
ext3 jbd
Aug 29 17:58:54 fedora kernel: CPU:    0
Aug 29 17:58:54 fedora kernel: EIP:    0060:[<0227279b>]    Not
tainted VLI
Aug 29 17:58:54 fedora kernel: EFLAGS: 00010202   (2.6.8-1.533)
Aug 29 17:58:54 fedora kernel: EIP is at usb_buffer_free+0xf/0x26
Aug 29 17:58:54 fedora kernel: eax: 00110008   ebx: 2ff8b280   ecx:
2e12e000   edx: 00002000
Aug 29 17:58:54 fedora kernel: esi: 2ff8b284   edi: 2de5b4d8   ebp:
2de662e8   esp: 27410f74
Aug 29 17:58:54 fedora kernel: ds: 007b   es: 007b   ss: 0068
Aug 29 17:58:54 fedora kernel: Process ptal-mlcd (pid: 2894,
threadinfo=27410000 task=27d62c70)
Aug 29 17:58:54 fedora kernel: Stack: 2ff8b280 3092a41b 2c12e000
3092b765 3092b600 00000000 2ff8b280 3092a4d1
Aug 29 17:58:54 fedora kernel:        2f742480 2ff81e00 0216200a
2f742480 00000000 2e93e700 27410000 021608e4
Aug 29 17:58:54 fedora kernel:        27410fc4 00000010 08c46668
ffff4200 00000009 00000005 08c41008 00000010
Aug 29 17:58:54 fedora kernel: Call Trace:
Aug 29 17:58:54 fedora kernel:  [<3092a41b>] usblp_cleanup+0x2d/0x70
[usblp]
Aug 29 17:58:54 fedora kernel:  [<3092a4d1>] usblp_release+0x54/0x59
[usblp]
Aug 29 17:58:54 fedora kernel:  [<0216200a>] __fput+0x55/0xee
Aug 29 17:58:54 fedora kernel:  [<021608e4>] filp_close+0x59/0x5f
Aug 29 17:58:54 fedora kernel: Code: <3>Debug: sleeping function
called from invalid context at include/linux/rwsem.h:43
Aug 29 17:58:54 fedora kernel: in_atomic():0[expected: 0],
irqs_disabled():1
Aug 29 17:58:54 fedora kernel:  [<0211c50c>] __might_sleep+0x7d/0x89
Aug 29 17:58:54 fedora kernel:  [<0215df76>] rw_vm+0x216/0x482
Aug 29 17:58:54 fedora kernel:  [<02272770>] usb_buffer_alloc+0xe/0x2a
Aug 29 17:58:54 fedora kernel:  [<02272770>] usb_buffer_alloc+0xe/0x2a
Aug 29 17:58:54 fedora kernel:  [<0215e6c8>] get_user_size+0x30/0x57
Aug 29 17:58:54 fedora kernel:  [<02272770>] usb_buffer_alloc+0xe/0x2a
Aug 29 17:58:54 fedora kernel:  [<0210664d>] show_registers+0x109/0x15e
Aug 29 17:58:54 fedora kernel:  [<02106822>] die+0x11b/0x1f9
Aug 29 17:58:54 fedora kernel:  [<02119110>] do_page_fault+0x0/0x4a0
Aug 29 17:58:54 fedora kernel:  [<02119454>] do_page_fault+0x344/0x4a0
Aug 29 17:58:54 fedora kernel:  [<0227279b>] usb_buffer_free+0xf/0x26
Aug 29 17:58:54 fedora kernel:  [<0211ab73>] activate_task+0x53/0x5f
Aug 29 17:58:54 fedora kernel:  [<0211cbbc>]
autoremove_wake_function+0xd/0x2d
Aug 29 17:58:54 fedora kernel:  [<0211b5ff>] __wake_up_common+0x36/0x51
Aug 29 17:58:54 fedora kernel:  [<02119110>] do_page_fault+0x0/0x4a0
Aug 29 17:58:54 fedora kernel:  [<0227279b>] usb_buffer_free+0xf/0x26
Aug 29 17:58:54 fedora kernel:  [<3092a41b>] usblp_cleanup+0x2d/0x70
[usblp]
Aug 29 17:58:54 fedora kernel:  [<3092a4d1>] usblp_release+0x54/0x59
[usblp]
Aug 29 17:58:54 fedora kernel:  [<0216200a>] __fput+0x55/0xee
Aug 29 17:58:54 fedora kernel:  [<021608e4>] filp_close+0x59/0x5f
Aug 29 17:58:54 fedora kernel:  Bad EIP value.
Aug 29 17:59:06 fedora kernel:  <6>usb 1-5.3: new full speed USB
device using address 4
Comment 6 Pete Zaitcev 2004-08-30 01:20:32 UTC 
I was sure the relocation of usb_buffer_free to the ->release
fixed that, but apparently not.
Comment 7 Tom London 2004-08-30 14:05:39 UTC 
This only seems to happen when I get something like the following
during boot:

Jul 23 07:01:37 fedora kernel: drivers/usb/class/usblp.c: usblp0:
nonzero read/write bulk status received: -2
Jul 23 07:01:37 fedora kernel: drivers/usb/class/usblp.c: usblp0:
error -2 reading from printer

Is it possible that because of this error, the usb_buffer was not
really fully allocated?
Comment 8 Tom London 2004-09-10 13:57:53 UTC 
Still get this in .541, running strict, either enforcing or permissive.

Sep 10 06:57:30 fedora kernel: drivers/usb/class/usblp.c: usblp0:
nonzero read/write bulk status received: -110
Sep 10 06:57:30 fedora kernel: drivers/usb/class/usblp.c: usblp0:
nonzero read/write bulk status received: -110
Sep 10 06:57:30 fedora kernel: drivers/usb/class/usblp.c: usblp0:
error -110 reading printer status
Sep 10 06:57:31 fedora last message repeated 242 times
Sep 10 06:57:31 fedora kernel: usb 3-2: USB disconnect, address 3
Sep 10 06:57:31 fedora kernel: drivers/usb/class/usblp.c: usblp0:
error -108 reading printer status
Sep 10 06:57:31 fedora kernel: audit(1094824651.415:0): avc:  denied 
{ read } for  pid=4370 exe=/usr/sbin/fstab-sync name=config dev=hda2
ino=4509759 scontext=system_u:system_r:updfstab_t
tcontext=system_u:object_r:selinux_config_t tclass=file
Sep 10 06:57:31 fedora kernel: audit(1094824651.415:0): avc:  denied 
{ getattr } for  pid=4370 exe=/usr/sbin/fstab-sync
path=/etc/selinux/config dev=hda2 ino=4509759
scontext=system_u:system_r:updfstab_t
tcontext=system_u:object_r:selinux_config_t tclass=file
Sep 10 06:57:31 fedora kernel: drivers/usb/class/usblp.c: usblp0: removed
Sep 10 06:57:31 fedora kernel: Unable to handle kernel paging request
at virtual address 6f3a7583
Sep 10 06:57:31 fedora kernel:  printing eip:
Sep 10 06:57:31 fedora kernel: 02272f2b
Sep 10 06:57:31 fedora kernel: *pde = 00000000
Sep 10 06:57:31 fedora kernel: Oops: 0000 [#2]
Sep 10 06:57:31 fedora kernel: Modules linked in: appletalk ipx p8022
psnap llc nfsd exportfs lockd md5 ipv6 parport_pc lp parport autofs4
sunrpc ipt_REJECT ipt_state ip_conntrack iptable_filter ip_tables
microcode dm_mod button battery asus_acpi ac usblp ohci1394 ieee1394
ohci_hcd ehci_hcd snd_intel8x0 snd_ac97_codec snd_pcm_oss
snd_mixer_oss snd_pcm snd_timer snd_page_alloc gameport
snd_mpu401_uart snd_rawmidi snd_seq_device snd soundcore sis900
8139too mii floppy ext3 jbd
Sep 10 06:57:31 fedora kernel: CPU:    0
Sep 10 06:57:31 fedora kernel: EIP:    0060:[<02272f2b>]    Not
tainted VLI
Sep 10 06:57:31 fedora kernel: EFLAGS: 00010206   (2.6.8-1.541)
Sep 10 06:57:31 fedora kernel: EIP is at usb_buffer_free+0xf/0x26
Sep 10 06:57:31 fedora kernel: eax: 6f3a755f   ebx: 2ffdba80   ecx:
0fe7a000   edx: 00002000
Sep 10 06:57:31 fedora kernel: esi: 2ffdba84   edi: 2bedc5f4   ebp:
2b4d7e10   esp: 0f5dcf74
Sep 10 06:57:31 fedora kernel: ds: 007b   es: 007b   ss: 0068
Sep 10 06:57:31 fedora kernel: Process usb (pid: 4294,
threadinfo=0f5dc000 task=0fe9acf0)
Sep 10 06:57:31 fedora kernel: Stack: 2ffdba80 3091a41b 0de7a000
3091b765 3091b600 00000000 2ffdba80 3091a4d1
Sep 10 06:57:31 fedora kernel:        10582680 2ff02d00 02162452
10582680 00000000 2de47d80 0f5dc000 02160d2c
Sep 10 06:57:31 fedora kernel:        0f5dcfc4 ffffffff fef72520
ffff4200 00000003 00231480 00000000 ffffffff
Sep 10 06:57:31 fedora kernel: Call Trace:
Sep 10 06:57:31 fedora kernel:  [<3091a41b>] usblp_cleanup+0x2d/0x70
[usblp]
Sep 10 06:57:31 fedora kernel:  [<3091a4d1>] usblp_release+0x54/0x59
[usblp]
Sep 10 06:57:31 fedora kernel:  [<02162452>] __fput+0x55/0xee
Sep 10 06:57:31 fedora kernel:  [<02160d2c>] filp_close+0x59/0x5f
Sep 10 06:57:31 fedora kernel: Code: <3>Debug: sleeping function
called from invalid context at include/linux/rwsem.h:43
Sep 10 06:57:31 fedora kernel: in_atomic():0[expected: 0],
irqs_disabled():1
Sep 10 06:57:31 fedora kernel:  [<0211c50c>] __might_sleep+0x7d/0x89
Sep 10 06:57:31 fedora kernel:  [<0215e0fe>] rw_vm+0x216/0x482
Sep 10 06:57:31 fedora kernel:  [<02272f00>] usb_buffer_alloc+0xe/0x2a
Sep 10 06:57:31 fedora kernel:  [<02272f00>] usb_buffer_alloc+0xe/0x2a
Sep 10 06:57:31 fedora kernel:  [<0215e850>] get_user_size+0x30/0x57
Sep 10 06:57:31 fedora kernel:  [<02272f00>] usb_buffer_alloc+0xe/0x2a
Sep 10 06:57:31 fedora kernel:  [<0210664d>] show_registers+0x109/0x15e
Sep 10 06:57:31 fedora kernel:  [<02106822>] die+0x11b/0x219
Sep 10 06:57:31 fedora kernel:  [<02119110>] do_page_fault+0x0/0x4a0
Sep 10 06:57:31 fedora kernel:  [<02119454>] do_page_fault+0x344/0x4a0
Sep 10 06:57:31 fedora kernel:  [<02272f2b>] usb_buffer_free+0xf/0x26
Sep 10 06:57:31 fedora kernel:  [<0211ab73>] activate_task+0x53/0x5f
Sep 10 06:57:31 fedora kernel:  [<0211cbbc>]
autoremove_wake_function+0xd/0x2d
Sep 10 06:57:31 fedora kernel:  [<0211b5ff>] __wake_up_common+0x36/0x51
Sep 10 06:57:31 fedora kernel:  [<02119110>] do_page_fault+0x0/0x4a0
Sep 10 06:57:31 fedora kernel:  [<02272f2b>] usb_buffer_free+0xf/0x26
Sep 10 06:57:31 fedora kernel:  [<3091a41b>] usblp_cleanup+0x2d/0x70
[usblp]
Sep 10 06:57:31 fedora kernel:  [<3091a4d1>] usblp_release+0x54/0x59
[usblp]
Sep 10 06:57:31 fedora kernel:  [<02162452>] __fput+0x55/0xee
Sep 10 06:57:31 fedora kernel:  [<02160d2c>] filp_close+0x59/0x5f
Sep 10 06:57:31 fedora kernel:  Bad EIP value.
Comment 9 Tom London 2004-09-16 14:38:15 UTC 
Got another one in .541

Sep 16 07:39:19 fedora kernel: usb 3-2: USB disconnect, address 2
Sep 16 07:39:19 fedora kernel: audit(1095345559.781:0): avc:  denied 
{ execute } for  pid=4882 exe=/usr/sbin/hald name=bash dev=hda2
ino=229395 scontext=system_u:system_r:hald_t
tcontext=system_u:object_r:shell_exec_t tclass=file
Sep 16 07:39:19 fedora ptal-mlcd: ERROR at ExMgr.cpp:3209,
dev=<mlc:usb:PSC_900_Series@/dev/usb/lp0>, pid=2722, e=19,
t=1095345559         llioSubprocess: llioRead returns -1, expected=6!
Sep 16 07:39:19 fedora ptal-mlcd: ERROR at ExMgr.cpp:2820,
dev=<mlc:usb:PSC_900_Series@/dev/usb/lp0>, pid=2699, e=5, t=1095345559
        llioService: fdRead returns 0, expected=6!
Sep 16 07:39:19 fedora ptal-mlcd: ERROR at ExMgr.cpp:871,
dev=<mlc:usb:PSC_900_Series@/dev/usb/lp0>, pid=2699, e=32,
t=1095345559         exClose(reason=0x0010)
Sep 16 07:39:19 fedora kernel: drivers/usb/class/usblp.c: usblp0: removed
Sep 16 07:39:19 fedora kernel: Unable to handle kernel paging request
at virtual address 01e00051
Sep 16 07:39:19 fedora kernel:  printing eip:
Sep 16 07:39:19 fedora kernel: 02272f2b
Sep 16 07:39:19 fedora kernel: *pde = 00000000
Sep 16 07:39:19 fedora kernel: Oops: 0000 [#1]
Sep 16 07:39:19 fedora kernel: Modules linked in: appletalk ipx p8022
psnap llc nfsd exportfs lockd md5 ipv6 parport_pc lp parport autofs4
sunrpc ipt_REJECT ipt_state ip_conntrack iptable_filter ip_tables
microcode dm_mod button battery asus_acpi ac usblp ohci1394 ieee1394
ohci_hcd ehci_hcd snd_intel8x0 snd_ac97_codec snd_pcm_oss
snd_mixer_oss snd_pcm snd_timer snd_page_alloc gameport
snd_mpu401_uart snd_rawmidi snd_seq_device snd soundcore sis900
8139too mii floppy ext3 jbd
Sep 16 07:39:19 fedora kernel: CPU:    0
Sep 16 07:39:19 fedora kernel: EIP:    0060:[<02272f2b>]    Not
tainted VLI
Sep 16 07:39:19 fedora kernel: EFLAGS: 00010206   (2.6.8-1.541)
Sep 16 07:39:19 fedora kernel: EIP is at usb_buffer_free+0xf/0x26
Sep 16 07:39:19 fedora kernel: eax: 01e0002d   ebx: 2ff0a580   ecx:
2be50000   edx: 00002000
Sep 16 07:39:19 fedora kernel: esi: 2ff0a584   edi: 2a436874   ebp:
2ed41a20   esp: 28606f74
Sep 16 07:39:19 fedora kernel: ds: 007b   es: 007b   ss: 0068
Sep 16 07:39:19 fedora kernel: Process ptal-mlcd (pid: 2699,
threadinfo=28606000 task=28051290)
Sep 16 07:39:19 fedora kernel: Stack: 2ff0a580 3091a41b 29e50000
3091b765 3091b600 00000000 2ff0a580 3091a4d1
Sep 16 07:39:19 fedora kernel:        2f650380 2ff02d00 02162452
2f650380 00000000 2ff1d880 28606000 02160d2c
Sep 16 07:39:19 fedora kernel:        28606fc4 00000010 0851b668
ffff4200 00000009 00000005 08516008 00000010
Sep 16 07:39:19 fedora kernel: Call Trace:
Sep 16 07:39:19 fedora kernel:  [<3091a41b>] usblp_cleanup+0x2d/0x70
[usblp]
Sep 16 07:39:19 fedora kernel:  [<3091a4d1>] usblp_release+0x54/0x59
[usblp]
Sep 16 07:39:19 fedora kernel:  [<02162452>] __fput+0x55/0xee
Sep 16 07:39:19 fedora kernel:  [<02160d2c>] filp_close+0x59/0x5f
Sep 16 07:39:19 fedora kernel: Code: <3>Debug: sleeping function
called from invalid context at include/linux/rwsem.h:43
Sep 16 07:39:19 fedora kernel: in_atomic():0[expected: 0],
irqs_disabled():1
Sep 16 07:39:19 fedora kernel:  [<0211c50c>] __might_sleep+0x7d/0x89
Sep 16 07:39:19 fedora kernel:  [<0215e0fe>] rw_vm+0x216/0x482
Sep 16 07:39:19 fedora kernel:  [<02272f00>] usb_buffer_alloc+0xe/0x2a
Sep 16 07:39:19 fedora kernel:  [<02272f00>] usb_buffer_alloc+0xe/0x2a
Sep 16 07:39:19 fedora kernel:  [<0215e850>] get_user_size+0x30/0x57
Sep 16 07:39:19 fedora kernel:  [<02272f00>] usb_buffer_alloc+0xe/0x2a
Sep 16 07:39:19 fedora kernel:  [<0210664d>] show_registers+0x109/0x15e
Sep 16 07:39:19 fedora kernel:  [<02106822>] die+0x11b/0x219
Sep 16 07:39:19 fedora kernel:  [<02119110>] do_page_fault+0x0/0x4a0
Sep 16 07:39:19 fedora kernel:  [<02119454>] do_page_fault+0x344/0x4a0
Sep 16 07:39:19 fedora kernel:  [<02272f2b>] usb_buffer_free+0xf/0x26
Sep 16 07:39:19 fedora kernel:  [<0211ab73>] activate_task+0x53/0x5f
Sep 16 07:39:19 fedora kernel:  [<0211cbbc>]
autoremove_wake_function+0xd/0x2d
Sep 16 07:39:19 fedora kernel:  [<0211b5ff>] __wake_up_common+0x36/0x51
Sep 16 07:39:19 fedora kernel:  [<02119110>] do_page_fault+0x0/0x4a0
Sep 16 07:39:19 fedora kernel:  [<02272f2b>] usb_buffer_free+0xf/0x26
Sep 16 07:39:19 fedora kernel:  [<3091a41b>] usblp_cleanup+0x2d/0x70
[usblp]
Sep 16 07:39:19 fedora kernel:  [<3091a4d1>] usblp_release+0x54/0x59
[usblp]
Sep 16 07:39:19 fedora kernel:  [<02162452>] __fput+0x55/0xee
Sep 16 07:39:19 fedora kernel:  [<02160d2c>] filp_close+0x59/0x5f
Sep 16 07:39:19 fedora kernel:  Bad EIP value.
Comment 10 Pete Zaitcev 2004-10-05 01:45:43 UTC 
Oh, so we don't have it in 1.541 after all. Sorry for the confusion.
The good news is that the hope still exists that my hunch was right.
The bad news is that we need a rebasing in FC3 before the fix can
be applied.
Comment 11 Pete Zaitcev 2004-10-05 01:47:20 UTC 
Created attachment 104762 [details]
Moving usb_buffer_free
Comment 12 Tom London 2004-10-16 18:12:17 UTC 
I haven't been able to reproduce this with the latest few Rawhide kernels.

Has the above fix been applied?
Comment 13 Tom London 2005-01-14 06:41:44 UTC 
Believe this has been fixed for a while.

Closing.....