rsyslogd: imuxsock begins to drop messages from pid xxx

Linux howto's, compile information, information on whatever we learned on working with linux, MACOs and - of course - Products of the big evil....
Post Reply
User avatar
^rooker
Site Admin
Posts: 1481
Joined: Fri Aug 29, 2003 8:39 pm

rsyslogd: imuxsock begins to drop messages from pid xxx

Post by ^rooker »

[PROBLEM]
I saw some very strange activity in /var/log/messages on our Raspberry Pi server over more than 11 hours - out of nowhere:
  • There was an incredibly high system load
  • CPU usage constantly around 40%
  • Steadily increasing data on the system disk
There were 2 lines kept repeating exactly every 6 seconds, over exactly the same duration as the other phenomena:
Mar 27 09:36:14 hostname rsyslogd-2177: imuxsock lost 2383 messages from pid 26079 due to rate-limiting
Mar 27 09:36:14 hostname rsyslogd-2177: imuxsock begins to drop messages from pid 26079 due to rate-limiting
In /var/log/daemon.log, I found something that pointed towards the printer being involved in this mess:
Mar 27 07:26:32 hostname hp[25185]: prnt/backend/hp.c 371: read new pjl status: 40017
Mar 27 07:26:44 hostname hp[25185]: prnt/backend/hp.c 371: read new pjl status: 10023
Mar 27 07:26:48 hostname hp[25185]: prnt/backend/hp.c 373: read pjl job_end: 12
Mar 27 07:26:49 hostname hp[25185]: prnt/backend/hp.c 371: read new pjl status: 40017
Mar 27 07:34:16 hostname hp[26079]: prnt/backend/hp.c 371: read new pjl status: 40017
Mar 27 07:35:01 hostname hp[26079]: prnt/backend/hp.c 371: read new pjl status: 10023
Mar 27 07:46:24 hostname hp[26079]: io/hpmud/musb.c 1442: unable to write data hp:/usb/HP_LaserJet_Professional_P_1102w?serial=000000000XXX: 45 second io timeout
This correlated with entries in /var/log/messages that showed when the printer went to standby ("usblp0: removed").

The "unable to write data" line was repeated every 45 seconds, until something else happened to the printing device at 8h31:
Mar 27 08:31:02 hostname kernel: [1072849.846184] usb 1-1.3.4: USB disconnect, device number 14
Which was followed by entries in /var/log/daemon.log, which appeared around 50 times every 6 seconds:
Mar 27 08:31:02 hostname hp[26079]: io/hpmud/musb.c 977: invalid bulk out endpoint

[SOLUTION]
It seems that this odd behavior was caused by stuck printing processes.
The printer had gone to suspend, but somehow the print jobs didn't time out, but kept banging the server for hours.

The log entries, as well as load/CPU/disk usage went immediately back to normal after removing the unhappy print jobs on the client.


Links:
Jumping out of an airplane is not a basic instinct. Neither is breathing underwater. But put the two together and you're traveling through space!
Top
Post Reply

Return to “Knowledge Base”