HP Linux Imaging and Printing

hplip filled user.log with 2.2Gb of log on error in 10 minutes

Reported by zebul666 on 2009-03-12
28
This bug affects 4 people
Affects Status Importance Assigned to Milestone
HPLIP
Undecided
Unassigned
Baltix
Undecided
Unassigned
Fedora
Won't Fix
Unknown
hplip (Debian)
Confirmed
Unknown

Bug Description

i tried to print on my photosmart C3180
and it didn't work.
then i wondered why my hdd was making that noise. then i found that syslog-ng was using almost 100% of my cpu
and then found that user.log was 2.2Gb in size and growing.

/var/log/user.log is full of lines like that
Mar 12 15:39:21 soho Photosmart_C3100_series?serial=MY716D32F804P9: io/hpmud/musb.c 1022: bulk_write failed buf=0xbffdf15c size=8192 len=-19: No data available
Mar 12 15:39:21 soho Photosmart_C3100_series?serial=MY716D32F804P9: io/hpmud/musb.c 1384: unable to write data hp:/usb/Photosmart_C3100_series?serial=MY716D32F804P9: No data available
Mar 12 15:39:21 soho Photosmart_C3100_series?serial=MY716D32F804P9: io/hpmud/musb.c 725: invalid deviceid wIndex=1, retrying wIndex=100: No such device
Mar 12 15:39:21 soho Photosmart_C3100_series?serial=MY716D32F804P9: io/hpmud/musb.c 734: invalid deviceid retry ret=-19: No such device
Mar 12 15:39:21 soho Photosmart_C3100_series?serial=MY716D32F804P9: io/hpmud/musb.c 777: invalid device_status: No such device
[...]
and the same is repeated 3070670 times !

it has grown of 1.6Gb of data in 10 minutes. i guess my harddrive would have been full if i had leave at that moment.
so the only way i found to stop this mess is to reboot.
I couldn't unload any module because there is none. how do i had stop this mess in a proper way without rebooting ?

it is one thing that my printer dies (to be confirmed). but the hplip driver has _not_ to fill my drive with its log!

is my printer dead ?

zebul666 (zebul666) wrote :
zebul666 (zebul666) wrote :

no it is not dead. i had to remove any document in cups queue so that my printer began again to print.

is only one document could have cause that ? the acrobat reader plugin ?

David Suffield (david-suffield) wrote :

What kind of system are you running? Distro?

Is there more syslog info? I see USB IO (musb.c) messages but no up-stream caller messages. There are no loops at this level of the code.

Based on the error messages something hung your printer...

zebul666 (zebul666) wrote :

it's linux 32 bit. distro is archlinux (current of the date above)

i got in user.log the lines above repeated a big number of times.
there is the same errors line in /var/log/errors.log

in everything.log, i got those lines just before the errors given above, i switch on the printer at 15:38
Mar 12 15:38:37 soho kernel: usb 1-4: new high speed USB device using ehci_hcd and address 5
Mar 12 15:38:37 soho kernel: usb 1-4: configuration #1 chosen from 1 choice
Mar 12 15:38:37 soho kernel: usblp0: USB Bidirectional printer dev 5 if 1 alt 0 proto 2 vid 0x03F0 pid 0x5611
Mar 12 15:38:37 soho kernel: usbcore: registered new interface driver usblp
Mar 12 15:38:37 soho load-modules.sh: 'usb:v03F0p5611d0100dc00dsc00dp00icFFiscCCip00' is not a valid module or alias name
Mar 12 15:38:37 soho kernel: Initializing USB Mass Storage driver...
Mar 12 15:38:37 soho kernel: scsi4 : SCSI emulation for USB Mass Storage devices
Mar 12 15:38:37 soho kernel: usb-storage: device found at 5
Mar 12 15:38:37 soho kernel: usbcore: registered new interface driver usb-storage
Mar 12 15:38:37 soho kernel: USB Mass Storage support registered.
Mar 12 15:38:37 soho kernel: usb-storage: waiting for device to settle before scanning
Mar 12 15:38:37 soho load-modules.sh: 'usb:v03F0p5611d0100dc00dsc00dp00icFFiscFFipFF' is not a valid module or alias name
Mar 12 15:38:42 soho kernel: scsi 4:0:0:0: Direct-Access HP Photosmart C3180 1.00 PQ: 0 ANSI: 2
Mar 12 15:38:42 soho kernel: sd 4:0:0:0: [sdb] Attached SCSI removable disk
Mar 12 15:38:42 soho kernel: sd 4:0:0:0: Attached scsi generic sg2 type 0
Mar 12 15:38:42 soho kernel: usb-storage: device scan complete
Mar 12 15:39:19 soho kernel: usblp0: removed
Mar 12 15:39:21 soho kernel: usb 1-4: USB disconnect, address 5

what's strange, it seems the printer disapeared ?
could it be cause by hardware ?

so i need to lower the info level of syslog-ng for hplip ?

David Suffield (david-suffield) wrote :

I have never used archlinux, but your kernel did disconnect the device from the USB bus for some reason after initial connection. Linux kernel USB support can be a problem with some no-name PCs.

Try the following in order.

1. Remove any hubs, plug directly into PC.
2. Try a certified HIGH-SPEED or USB 2.0 cable.
3. Try a different USB port on the PC.
4. Try running FULL-SPEED or USB 1.1 (ie: BIOS setting or USB 1.1 hub).
5. Try a different PC or distro.

-dave

Are you still having a problem with this?

Thanks.

Aaron

Changed in hplip:
assignee: nobody → kalosaurusrex
status: New → Triaged
zebul666 (zebul666) wrote :

it's not a no-name PC, it's a DELL inspiron 531 ;-)
it is a usb 2.0 cable (certified high-speed i think)

this has happened only once.
but that's a problem that my log grows like that. in fact they were 3 logs that grows to 2.2GB : user.log, everything.log and errors.log that makes 6.6GB ! i know we have big hdd now but ... it was 2.2GB only because i stop this mess by rebooting

do you consider it's me that must configure syslog (if it's possible) so that such a thing never happen again ?
i think something must be done to avoid the repeat of the same message over and over.
something like that exist in kernel message (where you can see (repeated 6 times) after some message)

how do you properly stop such a thing to happen (i.e. stop the log to grow ) except by rebooting ???

zebul666 (zebul666) wrote :

and archlinux used almost vanilla kernel. it is not over patched like big distro used to do.

Ariel Faigon (ariel.faigon) wrote :

Seeing the same problem here: Ubuntu 8.10 (Intrepid). DIfferent HP printer.

The log spewing is a big problem. When it happens it can quickly fill the disk.

The printer is alive and well, but the software thinks it isn't and goes out of its way to make the problem much worse.

To add to the problem logcheck starts failing because syslog and user.log are filling up so fast it can never catch up. logcheck calls logtail which calls grep and this grep (with many regexps) is running more slowly than the logs get added to!

Here's what's repeated (hundreds per second) in the logs:

Apr 14 18:55:16 ze DeskJet_970C?serial=SG99E1V1SMJQ: io/hpmud/musb.c 688: invalid deviceid retry ret=-19: No such device
Apr 14 18:55:16 ze DeskJet_970C?serial=SG99E1V1SMJQ: io/hpmud/musb.c 731: invalid device_status: No such device
Apr 14 18:55:16 ze DeskJet_970C?serial=SG99E1V1SMJQ: io/hpmud/musb.c 976: bulk_write failed buf=0xbfb5dadc size=4736 len=-19: No such device
Apr 14 18:55:16 ze DeskJet_970C?serial=SG99E1V1SMJQ: io/hpmud/musb.c 1338: unable to write data hp:/usb/DeskJet_970C?serial=SG99E1V1SMJQ: No such device
Apr 14 18:55:16 ze DeskJet_970C?serial=SG99E1V1SMJQ: io/hpmud/musb.c 679: invalid deviceid wIndex=0, retrying wIndex=0: No such device

[the above 5 lines repeat at extremely high rate killing system performance and filling up the disk]

Thanks for the attention to this bug.

Based on the syslog errors you are still getting a USB device disconnect during the print job. Assuming you have not tried a different PC this is USB kernel issue with your PC.

I can't explain the syslog filling up. There should be a 30 second loop error message in the syslog, but there is none. We will try and reproduce the syslog failure.

maximi89 (maximi89) wrote :

i'm having the same problem, i think it is a problem with cups.
http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=525361
https://bugs.launchpad.net/bugs/344592

PJBrs (pjbeers) wrote :

I think I have the same problem on Ubuntu Karmic Koala (HPLIP 3.9.8). The printer model is HP Photosmart 2575. HPLIP fills up four different logfiles at high speed, quickly filling the root partition. I don't know how the error is provoked, although it appears that printing more than one page at one time gets the printer stuck, and at that moment the logs start fill, until the entire root partition is full.

/var/log/daemon.log is filled with repeated sequences of:

Nov 5 15:43:11 floor-laptop hp[27078]: io/hpmud/musb.c 725: invalid deviceid wIndex=1, retrying wIndex=100: Device or resource busy
Nov 5 15:43:11 floor-laptop hp[27078]: io/hpmud/musb.c 1022: bulk_write failed buf=0xbfdc3524 size=7680 len=-16: Device or resource busy
Nov 5 15:43:11 floor-laptop hp[27078]: io/hpmud/musb.c 1389: unable to write data hp:/usb/Photosmart_2570_series?serial=MY71C310G204DY: Device or resource busy

/var/log/syslog is filled with repeated messages like:

Nov 5 15:43:11 floor-laptop kernel: [ 7809.347948] usb 1-1: usbfs: process 27317 (hp) did not claim interface 1 before use
Nov 5 15:43:11 floor-laptop hp[27078]: io/hpmud/musb.c 1022: bulk_write failed buf=0xbfdc3524 size=7680 len=-16: Device or resource busy
Nov 5 15:43:11 floor-laptop kernel: [ 7809.347988] usb 1-1: usbfs: process 27078 (hp) did not claim interface 1 before use
Nov 5 15:43:11 floor-laptop hp[27078]: io/hpmud/musb.c 1389: unable to write data hp:/usb/Photosmart_2570_series?serial=MY71C310G204DY: Device or resource busy
Nov 5 15:43:11 floor-laptop hp[27078]: io/hpmud/musb.c 725: invalid deviceid wIndex=1, retrying wIndex=100: Device or resource busy
Nov 5 15:43:11 floor-laptop hp[27078]: io/hpmud/musb.c 1022: bulk_write failed buf=0xbfdc3524 size=7680 len=-16: Device or resource busy
Nov 5 15:43:11 floor-laptop hp[27078]: io/hpmud/musb.c 1389: unable to write data hp:/usb/Photosmart_2570_series?serial=MY71C310G204DY: Device or resource busy

/var/log/kern.log is filled with repeated messages like:

Nov 5 15:43:11 floor-laptop kernel: [ 7809.403956] usb 1-1: usbfs: process 27398 (hp) did not claim interface 1 before use

/var/log/messages also is filled with hplip-related messages, but they weren't different from what was in the other files.

Actually, I had the same problem with Ubuntu Jaunty Jackalope, but I had hoped that upgrading to Karmic Koala would solve it. In other words, this appears to be a quite long-standing bug.

In my view, the main problem with this bug is that novice and intermediate users are not able to solve the problems that are caused by this bug. They don't know where to look when to get error messages because their root partition is full. In the mean time, their computers are rendered useless because they often cannot open their documents any more, let alone save them. In fact, in my case I couldn't even save a draft email message in Thunderbird.

I noticed that the last message in this bugreport is from April 2009. Is their any activity regarding the solution of this problem?

PJBrs (pjbeers) wrote :

Oops! Type:

s/when to get/when they get/

PJBrs (pjbeers) wrote :

It's been a week since I posted; is there any way I can help solve this problem?

Try the hplip 3.9.10. I made a change musb.c to address this problem when the USB device disconnects intermittently.

Of coarse this only addresses the syslog filling up issue not your hardware issue.

Changed in fedora:
status: Unknown → In Progress
martin_jacobs (martin-jacobs) wrote :

Seems to be similar to bug #439550
https://bugs.launchpad.net/hplip/+bug/439550
This one happens if printer connected by LAN (in my case WLAN) is switched on after job processing has been started by CUPS.

Changed in fedora:
status: In Progress → Won't Fix
Changed in hplip (Debian):
status: Unknown → Confirmed
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.