kernel: WARNING: at drivers/usb/host/ehci-hcd.c:1178 ehci_endpoint_reset+0xee/0x100()

[Jiri Popelka]

Dear HPLIP developers,

several Fedora users see this problem (see Summary) when using HP printer over USB.

Here's a reply from Alan Stern (upstream USB maintainer):

I took a look at the source code for the hplip package. In
io/hpmud/musb.c, the musb_raw_channel_close() routine always calls
usb_clear_halt() for each bulk-in and bulk-out endpoint that it uses,
whether the endpoint needs it or not. If one of those endpoints had a
read or write going on in another thread at the same time, the
usb_clear_halt() call would cause the WARN to trigger.

It's hard to tell exactly what the program is doing. You'd think that
all I/O to a printer would be serialized, and ongoing reads or writes
would be completed before anything was closed. But the use of multiple
threads and callback routines makes the code difficult to follow.

Anyway, removing those usb_clear_halt() calls would most likely
eliminate the problem. Of course, they might be needed for some
printers. Still, it's best not to clear a halted endpoint until you
know that it is halted, and then it is best to clear the halt condition
right away instead of waiting until some I/O channel is closed.

[Kenneth (kenneth-redhat-bugs)]

libreport version: 2.0.8
abrt_version: 2.0.7
cmdline: BOOT_IMAGE=/vmlinuz-3.2.3-2.fc16.i686.PAE root=/dev/mapper/vg_atlas-lv_root ro rd.md=0 rd.dm=0 rd.lvm.lv=vg_atlas/lv_swap KEYTABLE=us quiet SYSFONT=latarcyrheb-sun16 rhgb rd.luks=0 LANG=en_US.UTF-8 rd.lvm.lv=vg_atlas/lv_root
comment: I have Fedora 16 installed with a USB Photosmart C3150 All-in-one Printer. I have hplip installed with CUPS using that. I requested a print.
event_log: 2012-02-05-17:21:30> Smolt profile successfully saved
kernel: 3.2.3-2.fc16.i686.PAE
reason: WARNING: at drivers/usb/host/ehci-hcd.c:1178 ehci_endpoint_reset+0xee/0x100()
time: Sun 05 Feb 2012 04:49:47 PM PST

backtrace:
:WARNING: at drivers/usb/host/ehci-hcd.c:1178 ehci_endpoint_reset+0xee/0x100()
:Hardware name: To Be Filled By O.E.M.
:clear_halt for a busy endpoint
:Modules linked in: nls_utf8 fuse lockd nf_conntrack_netbios_ns nf_conntrack_broadcast ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ipv6 nf_conntrack_ipv4 nf_defrag_ipv4 ip6table_filter xt_state nf_conntrack ip6_tables snd_emu10k1_synth snd_emux_synth snd_seq_virmidi snd_seq_midi_event snd_seq_midi_emul snd_emu10k1 snd_rawmidi ppdev snd_intel8x0 snd_ac97_codec ac97_bus snd_seq gspca_spca501 gspca_main snd_pcm usblp videodev media emu10k1_gp gameport serio_raw parport_pc parport sis900 mii microcode snd_seq_device snd_util_mem snd_timer snd_hwdep snd soundcore snd_page_alloc binfmt_misc sunrpc ata_generic pata_acpi usb_storage aic7xxx scsi_transport_spi sata_sis pata_sis nouveau ttm drm_kms_helper drm i2c_algo_bit i2c_core mxm_wmi wmi video [last unloaded: scsi_wait_scan]
:Pid: 1146, comm: hp Not tainted 3.2.3-2.fc16.i686.PAE #1
:Call Trace:
: [<c045e352>] warn_slowpath_common+0x72/0xa0
: [<c07a85ce>] ? ehci_endpoint_reset+0xee/0x100
: [<c07a85ce>] ? ehci_endpoint_reset+0xee/0x100
: [<c045e423>] warn_slowpath_fmt+0x33/0x40
: [<c07a85ce>] ehci_endpoint_reset+0xee/0x100
: [<c0790d85>] usb_hcd_reset_endpoint+0x25/0x70
: [<c0791e65>] usb_reset_endpoint+0x25/0x40
: [<c0792993>] usb_clear_halt+0x73/0x80
: [<c079af4d>] usbdev_do_ioctl+0x89d/0x1d90
: [<c06134ab>] ? file_has_perm+0xcb/0xe0
: [<c079c440>] ? usbdev_do_ioctl+0x1d90/0x1d90
: [<c079c44d>] usbdev_ioctl+0xd/0x10
: [<c054ff26>] do_vfs_ioctl+0x86/0x5a0
: [<c0613924>] ? selinux_file_ioctl+0x54/0x110
: [<c05504af>] sys_ioctl+0x6f/0x80
: [<c093c4e4>] syscall_call+0x7/0xb
: [<c0930000>] ? powernowk8_cpu_init+0x471/0xe1a

smolt_data:
:
:
:General
:=================================
:UUID: c3269a5b-6c8e-495e-8a42-f7d1db5e39ee
:OS: Fedora release 16 (Verne)
:Default run level: Unknown
:Language: en_US.utf8
:Platform: i686
:BogoMIPS: 4801.83
:CPU Vendor: GenuineIntel
:CPU Model: Intel(R) Pentium(R) 4 CPU 2.40GHz
:CPU Stepping: 4
:CPU Family: 15
:CPU Model Num: 2
:Number of CPUs: 1
:CPU Speed: 2399
:System Memory: 3025
:System Swap: 5087
:Vendor: To Be Filled By O.E.M.
:System: To Be Filled By O.E.M. To Be Filled By O.E.M.
:Form factor: Desktop
:Kernel: 3.2.3-2.fc16.i686.PAE
:SELinux Enabled: 1
:SELinux Policy: targeted
:SELinux Enforce: Permissive
:MythTV Remote: Unknown
:MythTV Role: Unknown
:MythTV Theme: Unknown
:MythTV Plugin:
:MythTV Tuner: -1
:
:
:Devices
:==...

[Dave (dave-redhat-bugs)]

to diagnose this, we are going to need a usbmon trace.
You can find instructions on how to do this at https://www.kernel.org/doc/Documentation/usb/usbmon.txt

[Dave (dave-redhat-bugs)]

also, what package does that 'hp' app come from ?
make sure you have the latest version of that.

[Kenneth (kenneth-redhat-bugs)]

Created attachment 559788
usbmon log when trying to print to Photosmart C3150 printer.

Tried to print a few files. Thanks for looking at this.

[Kenneth (kenneth-redhat-bugs)]

Version of hplip is hplip-3.10.6

[Dave (dave-redhat-bugs)]

*** Bug 781762 has been marked as a duplicate of this bug. ***

[Dave (dave-redhat-bugs)]

I discussed this problem upstream with the USB maintainers.
Here's what Alan Stern replied:

I took a look at the source code for the hplip package. In
io/hpmud/musb.c, the musb_raw_channel_close() routine always calls
usb_clear_halt() for each bulk-in and bulk-out endpoint that it uses,
whether the endpoint needs it or not. If one of those endpoints had a
read or write going on in another thread at the same time, the
usb_clear_halt() call would cause the WARN to trigger.

It's hard to tell exactly what the program is doing. You'd think that
all I/O to a printer would be serialized, and ongoing reads or writes
would be completed before anything was closed. But the use of multiple
threads and callback routines makes the code difficult to follow.

Anyway, removing those usb_clear_halt() calls would most likely
eliminate the problem. Of course, they might be needed for some
printers. Still, it's best not to clear a halted endpoint until you
know that it is halted, and then it is best to clear the halt condition
right away instead of waiting until some I/O channel is closed.

[Tim (tim-redhat-bugs)]

*** Bug 749907 has been marked as a duplicate of this bug. ***

[Hin-Tak (hin-tak-redhat-bugs)]

Adding myself to cc: . saw something similar with DVB-T and mplayer.

[Fedora (fedora-redhat-bugs)]

This message is a reminder that Fedora 16 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 16. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as WONTFIX if it remains open with a Fedora
'version' of '16'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version'
to a later Fedora version prior to Fedora 16's end of life.

Bug Reporter: Thank you for reporting this issue and we are sorry that
we may not be able to fix it before Fedora 16 is end of life. If you
would still like to see this bug fixed and are able to reproduce it
against a later version of Fedora, you are encouraged to click on
"Clone This Bug" and open it against that version of Fedora.

Although we aim to fix as many bugs as possible during every release's
lifetime, sometimes those efforts are overtaken by events. Often a
more recent Fedora release includes newer upstream software that fixes
bugs or makes them obsolete.

The process we are following is described here:
http://fedoraproject.org/wiki/BugZappers/HouseKeeping

[Fedora (fedora-redhat-bugs)]

Fedora 16 changed to end-of-life (EOL) status on 2013-02-12. Fedora 16 is
no longer maintained, which means that it will not receive any further
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version.

Thank you for reporting this bug and we are sorry it could not be fixed.