The recent log attachments for both xsession and syslog cover an incident from 10th August.

On this occasion, I had my debug-patch version of hplip-2.8.12 running, i.e.:

$ rpm -q --changelog hplip|more
* Wed Aug 05 2009 Ted Rule <email address hidden> 2.8.12-6c
- Add hpmud debug patch

* Tue Jul 14 2009 Ted Rule <email address hidden> 2.8.12-6b
- Add bug throttle patch

* Tue Jan 27 2009 Tim Waugh <email address hidden> 2.8.12-6
- Only ship compressed PPD files.

where the extra debugging can be seen in the syslog trail.



At the same time, I tweaked gnome a bit to get some debugging out of the printer applet, as in:

$ diff -u /usr/share/system-config-printer/applet.py.orig /usr/share/system-config-printer/applet.py
--- /usr/share/system-config-printer/applet.py.orig	2009-03-25 18:55:26.000000000 +0000
+++ /usr/share/system-config-printer/applet.py	2009-08-07 12:11:18.000000000 +0100
@@ -251,6 +251,12 @@
         show_help ()
         sys.exit (1)
 
+    set_debugging (True)
+    if get_debugging () == False:
+        print >> sys.stderr, ("%s: unable to initialize debugging" %PROGRAM_NAME)
+    elif get_debugging () == True:
+        print >> sys.stderr, ("%s: able to initialize debugging" %PROGRAM_NAME)
+
     for opt, optarg in opts:
         if opt == "--help":
             show_help ()
$ 


$ diff -u /usr/share/system-config-printer/debug.py.orig /usr/share/system-config-printer/debug.py
--- /usr/share/system-config-printer/debug.py.orig	2009-03-25 18:55:26.000000000 +0000
+++ /usr/share/system-config-printer/debug.py	2009-08-07 12:13:39.000000000 +0100
@@ -19,12 +19,13 @@
 
 import sys
 import traceback
+import time
 
 _debug=False
 def debugprint (x):
     if _debug:
         try:
-            print >>sys.stderr, x
+            print >>sys.stderr, time.strftime("%b %d %Y %H:%M:%S"), x
         except:
             pass
 
$ 


The incident happened when I tried to print a 5 page Email, and it was the first print Job after the initial boot-up of the system. As it happened, the printer had too little paper to complete the Job.

When the print Job "stalled", I had this in the process list:


[ejtr@topaz ~]$ ps axfu
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root         2  0.0  0.0      0     0 ?        S<   17:25   0:00 [kthreadd]
root         3  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [migration/0]
root         4  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [ksoftirqd/0]
root         5  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [watchdog/0]
root         6  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [migration/1]
root         7  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [ksoftirqd/1]
root         8  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [watchdog/1]
root         9  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [events/0]
root        10  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [events/1]
root        11  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [khelper]
root        85  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [kintegrityd/0]
root        86  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [kintegrityd/1]
root        88  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [kblockd/0]
root        89  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [kblockd/1]
root        91  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [kacpid]
root        92  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [kacpi_notify]
root       174  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [cqueue]
root       178  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [ata/0]
root       179  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [ata/1]
root       180  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [ata_aux]
root       182  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [ksuspend_usbd]
root       187  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [khubd]
root       190  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [kseriod]
root       240  0.0  0.0      0     0 ?        S    17:25   0:00  \_ [pdflush]
root       241  0.0  0.0      0     0 ?        S    17:25   0:00  \_ [pdflush]
root       242  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [kswapd0]
root       290  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [aio/0]
root       291  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [aio/1]
root       485  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [scsi_eh_0]
root       488  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [scsi_eh_1]
root       607  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [kpsmoused]
root       614  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [kstriped]
root       617  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [ksnapd]
root       675  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [kdmflush]
root       676  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [kdmflush]
root       677  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [kdmflush]
root       678  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [kdmflush]
root       679  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [kdmflush]
root       680  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [kdmflush]
root       681  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [kjournald]
root      1173  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [scsi_eh_2]
root      1174  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [usb-storage]
root      1176  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [scsi_eh_3]
root      1177  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [usb-storage]
root      1582  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [kauditd]
root      1651  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [kmpathd/0]
root      1652  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [kmpathd/1]
root      1653  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [kmpath_handlerd]
root      1681  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [kjournald]
root      1682  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [kjournald]
root      1683  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [kjournald]
root      1684  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [kjournald]
root      1685  0.0  0.0      0     0 ?        S<   17:25   0:00  \_ [kjournald]
root         1  0.0  0.0   2012   776 ?        Ss   17:25   0:00 /sbin/init
root       736  0.0  0.0   2588  1160 ?        S<s  17:25   0:00 /sbin/udevd -d
root      2019  0.0  0.0  12780   792 ?        S<sl 17:25   0:00 auditd
root      2021  0.0  0.0  12300   752 ?        S<sl 17:25   0:00  \_ /sbin/audispd
root      2046  0.0  0.0   3524  1224 ?        Ss   17:25   0:00 /sbin/syslog-ng -p /var/run/syslogd.pid
dbus      2067  0.0  0.0  13528  1556 ?        Ssl  17:25   0:00 dbus-daemon --system
root      2077  0.0  0.0   1884   584 ?        Ss   17:25   0:00 /usr/sbin/acpid
68        2085  0.0  0.2   6948  4508 ?        Ss   17:25   0:00 hald
root      2089  0.0  0.0   3548  1052 ?        S    17:25   0:00  \_ hald-runner
root      2248  0.0  0.0   3628   920 ?        S    17:25   0:00      \_ hald-addon-storage: polling /dev/sdb (every 2 sec)
root      2250  0.0  0.0   3628   924 ?        S    17:25   0:00      \_ hald-addon-storage: polling /dev/sr0 (every 2 sec)
68        2252  0.0  0.0   3188   940 ?        S    17:25   0:00      \_ hald-addon-acpi: listening on acpid socket /var/run/acpid.socket
root      2323  0.0  0.0   3624  1032 ?        S    17:25   0:00      \_ hald-addon-input: Listening on /dev/input/event4 /dev/input/event5 
root      2088  0.0  0.1   9468  2140 ?        Ssl  17:25   0:00 /usr/sbin/console-kit-daemon
root      2241  0.0  0.1  17304  2168 ?        Ssl  17:25   0:00 NetworkManager --pid-file=/var/run/NetworkManager/NetworkManager.pid
root      2331  0.0  0.0   2580  1096 ?        S    17:25   0:00  \_ /sbin/dhclient -d -sf /usr/libexec/nm-dhcp-client.action -pf /var/run/d
root      2256  0.0  0.0   5624  1196 ?        S    17:25   0:00 /usr/sbin/wpa_supplicant -c /etc/wpa_supplicant/wpa_supplicant.conf -u -f /
root      2262  0.0  0.1   8136  3632 ?        S    17:25   0:00 /usr/sbin/nm-system-settings --config /etc/NetworkManager/nm-system-setting
root      2263  0.0  0.0   6200  1096 ?        Ssl  17:25   0:00 automount
root      2281  0.0  1.4  63944 30944 ?        Ssl  17:25   0:01 /usr/bin/python -E /usr/sbin/setroubleshootd
root      2299  0.0  0.0   7252  1024 ?        Ss   17:25   0:00 /usr/sbin/sshd
root      2307  0.0  0.0   2720   860 ?        Ss   17:25   0:00 xinetd -stayalive -pidfile /var/run/xinetd.pid
ntp       2315  0.0  0.0   4696  1396 ?        Ss   17:25   0:00 ntpd -u ntp:ntp -p /var/run/ntpd.pid -g
root      2335  0.0  1.4  35360 29476 ?        Ss   17:25   0:01 /usr/bin/spamd -d -c -m5 -H -r /var/run/spamd.pid                    
root      2664  0.0  1.3  35360 27072 ?        S    17:25   0:00  \_ spamd child                                                          
root      2665  0.0  1.3  35360 27072 ?        S    17:25   0:00  \_ spamd child                                                          
root      2370  0.0  0.0   2120   380 ?        Ss   17:25   0:00 /usr/sbin/gpm -m /dev/input/mice -t exps2
root      2383  0.0  0.0   5268  1220 ?        Ss   17:25   0:00 crond
root      2406  0.0  0.0   9888  1120 ?        Ss   17:25   0:00 kerneloops
smmsp     2434  0.0  0.0   8808  1480 ?        Ss   17:25   0:00 sendmail: Queue runner@01:00:00 for /var/spool/clientmqueue
root      2436  0.0  0.0   9092  1700 ?        Ss   17:25   0:00 sendmail: accepting connections   
root      2440  0.0  0.1  17092  2628 ?        Ss   17:25   0:00 smbd -D
root      2459  0.0  0.0  17092  1080 ?        S    17:25   0:00  \_ smbd -D
root      2451  0.0  0.0   2236   332 ?        Ss   17:25   0:00 /usr/sbin/atd
avahi     2461  0.0  0.0   2880  1404 ?        Ss   17:25   0:00 avahi-daemon: running [topaz.local]
avahi     2462  0.0  0.0   2880   324 ?        Ss   17:25   0:00  \_ avahi-daemon: chroot helper
root      2471  0.0  0.1  10636  3060 ?        Ss   17:25   0:00 cupsd
lp        3584  0.0  0.3  10908  6272 ?        S    17:34   0:00  \_ /usr/bin/perl /usr/lib/cups/filter/foomatic-rip 273 ejtr evolution job 
lp        3589  0.0  0.2  10908  4620 ?        S    17:34   0:00  |   \_ /usr/bin/perl /usr/lib/cups/filter/foomatic-rip 273 ejtr evolution 
lp        3590  0.0  0.1  10908  4060 ?        S    17:34   0:00  |       \_ /usr/bin/perl /usr/lib/cups/filter/foomatic-rip 273 ejtr evolut
lp        3591  0.0  1.4  55192 30384 ?        S    17:34   0:00  |       \_ gs -sstdout=%stderr -dBATCH -dPARANOIDSAFER -dQUIET -dNOPAUSE -
lp        3599  0.0  0.0   7596  1480 ?        S    17:34   0:00  |           \_ hpijs
lp        3585  0.0  0.0  15872  1252 ?        S    17:34   0:00  \_ hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY 273 ejtr evolution
root      2482  0.0  0.0   1884   528 ?        SNs  17:25   0:00 anacron -s
root      2495  0.0  0.0   3520   520 ?        S    17:25   0:00 /usr/sbin/smartd -q never
root      2498  0.0  0.0   7232  2052 ?        Ss   17:25   0:00 /usr/sbin/gdm-binary -nodaemon
root      2565  0.0  0.1   7604  2672 ?        S    17:25   0:00  \_ /usr/libexec/gdm-simple-slave --display-id /org/gnome/DisplayManager/Di
root      2566  4.1  2.2  56688 46028 tty1     Ss+  17:25   1:15      \_ /usr/bin/Xorg :0 -nr -verbose -auth /var/run/gdm/auth-for-gdm-TgoeQ
root      2667  0.0  0.1   6160  2784 ?        S    17:25   0:00      \_ /usr/libexec/gdm-session-worker
ejtr      2707  0.0  0.3  31804  7076 ?        Ssl  17:25   0:00          \_ gnome-session
ejtr      2983  0.0  0.1  15552  2920 ?        S    17:25   0:00              \_ /usr/lib/gnome-session/helpers/gnome-keyring-daemon-wrapper
ejtr      2995  0.0  0.6  26532 13724 ?        S    17:25   0:01              \_ metacity
ejtr      2997  0.0  0.8  56696 17156 ?        S    17:25   0:00              \_ gnome-panel
ejtr      2998  0.1  1.7 109992 36020 ?        S    17:25   0:03              \_ nautilus --no-desktop --browser
ejtr      3001  0.0  0.5  70272 11656 ?        S    17:25   0:00              \_ nm-applet --sm-disable
ejtr      3004  0.0  0.5  29520 11272 ?        S    17:25   0:00              \_ gnome-power-manager
ejtr      3008  0.0  0.3  20456  7124 ?        S    17:25   0:00              \_ imsettings-applet --disable-xsettings
ejtr      3010  0.0  0.3  20256  6572 ?        S    17:25   0:00              \_ bluetooth-applet
ejtr      3011  0.0  0.5  46280 10452 ?        S    17:25   0:00              \_ gpk-update-icon
ejtr      3012  0.1  1.0  60620 21028 ?        S    17:25   0:01              \_ python /usr/share/system-config-printer/applet.py
ejtr      3016  0.0  0.2  18856  5596 ?        S    17:25   0:00              \_ kerneloops-applet
root      2499  0.0  0.0   1872   456 tty4     Ss+  17:25   0:00 /sbin/mingetty tty4
root      2500  0.0  0.0   1872   456 tty5     Ss+  17:25   0:00 /sbin/mingetty tty5
root      2501  0.0  0.0   1872   456 tty2     Ss+  17:25   0:00 /sbin/mingetty tty2
root      2502  0.0  0.0   1872   452 tty3     Ss+  17:25   0:00 /sbin/mingetty tty3
root      2503  0.0  0.0   1872   452 tty6     Ss+  17:25   0:00 /sbin/mingetty tty6
gdm       2587  0.0  0.0   3156   544 ?        S    17:25   0:00 /usr/bin/dbus-launch --exit-with-session
ejtr      2705  0.0  0.1  26056  2224 ?        S    17:25   0:00 /usr/bin/gnome-keyring-daemon -d --login
ejtr      2765  0.0  0.0   3156   548 ?        S    17:25   0:00 dbus-launch --sh-syntax --exit-with-session
ejtr      2766  0.0  0.0  13528  1444 ?        Ssl  17:25   0:00 /bin/dbus-daemon --fork --print-pid 7 --print-address 9 --session
ejtr      2809  0.0  0.0   5528  2044 ?        S    17:25   0:00 /usr/libexec/im-settings-daemon
ejtr      2811  0.0  0.1   4788  2592 ?        S    17:25   0:00 /usr/libexec/im-info-daemon
ejtr      2813  0.0  0.0   6572  1964 ?        S    17:25   0:00 /usr/libexec/gvfsd
ejtr      2883  0.0  0.1  35652  2164 ?        Ssl  17:25   0:00 /usr/libexec//gvfs-fuse-daemon /home/ejtr/.gvfs
ejtr      2941  0.0  0.0   4956  2036 ?        S    17:25   0:00 /usr/libexec/gconf-im-settings-daemon
ejtr      2943  0.1  0.2   9380  5108 ?        S    17:25   0:03 /usr/libexec/gconfd-2
ejtr      2988  0.0  0.4  40672 10212 ?        Ssl  17:25   0:00 /usr/libexec/gnome-settings-daemon
ejtr      2996  0.0  0.1  28892  3184 ?        Ss   17:25   0:01 gnome-screensaver
ejtr      3000  0.0  0.1  40796  3100 ?        Ssl  17:25   0:00 /usr/libexec/bonobo-activation-server --ac-activate --ior-output-fd=17
ejtr      3007  0.0  0.6  51244 14284 ?        S    17:25   0:00 /usr/libexec/notification-daemon
ejtr      3024  0.0  0.2  98064  4488 ?        Ssl  17:25   0:00 /usr/bin/pulseaudio --start
ejtr      3032  0.0  0.0   7912  2044 ?        S    17:25   0:00  \_ /usr/libexec/pulse/gconf-helper
ejtr      3046  0.0  0.1   7056  2660 ?        S    17:25   0:00 /usr/libexec/gvfs-hal-volume-monitor
ejtr      3048  0.0  0.0   6752  1952 ?        S    17:25   0:00 /usr/libexec/gvfs-gphoto2-volume-monitor
ejtr      3050  0.1  0.7  55884 16336 ?        S    17:25   0:02 /usr/libexec/wnck-applet --oaf-activate-iid=OAFIID:GNOME_Wncklet_Factory --
ejtr      3052  0.0  0.4  50912  9656 ?        S    17:25   0:00 /usr/libexec/trashapplet --oaf-activate-iid=OAFIID:GNOME_Panel_TrashApplet_
ejtr      3055  0.0  0.1  17072  2544 ?        S    17:25   0:00 /usr/libexec/gvfsd-trash --spawner :1.4 /org/gtk/gvfs/exec_spaw/0
ejtr      3061  0.0  0.0   6540  1960 ?        S    17:25   0:00 /usr/libexec/gvfsd-burn --spawner :1.4 /org/gtk/gvfs/exec_spaw/2
ejtr      3069  0.0  0.7  77192 15572 ?        Sl   17:25   0:00 /usr/libexec/mixer_applet2 --oaf-activate-iid=OAFIID:GNOME_MixerApplet_Fact
ejtr      3071  0.0  0.7  37300 15408 ?        S    17:25   0:00 /usr/libexec/clock-applet --oaf-activate-iid=OAFIID:GNOME_ClockApplet_Facto
ejtr      3075  0.0  0.6  52860 13532 ?        S    17:25   0:00 /usr/libexec/gdm-user-switch-applet --oaf-activate-iid=OAFIID:GNOME_FastUse
ejtr      3080  0.0  0.3  26792  8112 ?        S    17:25   0:00 /usr/libexec/notification-area-applet --oaf-activate-iid=OAFIID:GNOME_Notif
ejtr      3096  0.0  0.0   4812  1164 ?        S    17:25   0:00 /bin/sh /usr/lib/firefox-3.0.13/run-mozilla.sh /usr/lib/firefox-3.0.13/fire
ejtr      3115  1.3  4.9 260312 102892 ?       Sl   17:25   0:24  \_ /usr/lib/firefox-3.0.13/firefox
ejtr      3103  4.5  4.6 338276 96268 ?        Sl   17:25   1:20 evolution
ejtr      3123  0.0  0.5  89008 12104 ?        Sl   17:25   0:00 /usr/libexec/evolution-data-server-2.24 --oaf-activate-iid=OAFIID:GNOME_Evo
ejtr      3161  0.2  1.5 123612 32656 ?        Sl   17:26   0:05 gnome-terminal --geometry 140x45
ejtr      3172  0.0  0.0   2844   624 ?        S    17:26   0:00  \_ gnome-pty-helper
ejtr      3173  0.0  0.0   5004  1624 pts/0    Ss   17:26   0:00  \_ bash
ejtr      4009  0.0  0.0   5004  1612 pts/3    Ss+  17:37   0:00  \_ bash
ejtr      4104  0.0  0.0   5004  1640 pts/4    Ss   17:39   0:00  \_ bash
ejtr      4583  0.0  0.0   4636   956 pts/4    R+   17:55   0:00      \_ ps axfu
ejtr      3189  0.0  0.5  69620 11368 ?        Sl   17:26   0:00 /usr/libexec/evolution/2.24/evolution-alarm-notify --oaf-activate-iid=OAFII
...
$ 

In particular, of course, I had this:

...
root      2471  0.0  0.1  10636  3060 ?        Ss   17:25   0:00 cupsd
lp        3584  0.0  0.3  10908  6272 ?        S    17:34   0:00  \_ /usr/bin/perl /usr/lib/cups/filter/foomatic-rip 273 ejtr evolution job 
lp        3589  0.0  0.2  10908  4620 ?        S    17:34   0:00  |   \_ /usr/bin/perl /usr/lib/cups/filter/foomatic-rip 273 ejtr evolution 
lp        3590  0.0  0.1  10908  4060 ?        S    17:34   0:00  |       \_ /usr/bin/perl /usr/lib/cups/filter/foomatic-rip 273 ejtr evolut
lp        3591  0.0  1.4  55192 30384 ?        S    17:34   0:00  |       \_ gs -sstdout=%stderr -dBATCH -dPARANOIDSAFER -dQUIET -dNOPAUSE -
lp        3599  0.0  0.0   7596  1480 ?        S    17:34   0:00  |           \_ hpijs
lp        3585  0.0  0.0  15872  1252 ?        S    17:34   0:00  \_ hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY 273 ejtr evolution
...



/var/log/debug shows this as the first sign of the error:

...
1981 Aug 10 17:34:37 topaz kernel: usb 1-7: usbfs: process 3793 (hp) did not claim interface 1 before use
...

preceded by this:
...
1976 Aug 10 17:34:37 topaz kernel: usb 1-7: reset high speed USB device using ehci_hcd and address 3
...


We note that the printer-applet seems to have this in its debug:

Aug 10 2009 17:34:06 <monitor.Monitor instance at 0xa021d4c>: printer `Photosmart_2570_series' has event `printer-state-changed'

but nothing thereafter.... which seems wrong.

Once I had gathered as much debug as I could, such as the process list, I restarted CUPS. Thereafter, I get more debug - interestingly enough the printer applet reports "Out of Paper" as soon as I restart cups..... This can be seen in the xsession debug, by tallying the timestamps with syslog.


Maybe this means that I can provoke the error if I print a multi-page document, but fill the printer with less paper than is needed to finish the Job? If I can guarantee to provoke the issue with a known set of conditions, we'd be much closer to fixing the issue.