Das Werkstatt

[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:

• http://www.rsyslog.com/how-to-use-rate- ... n-rsyslog/