Note: This is a public test instance of Red Hat Bugzilla. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback at bugzilla.redhat.com.

Bug 132399

Summary:	eggcups not working for local printers
Product:	[Fedora] Fedora	Reporter:	Daniel Malmgren <dm>
Component:	desktop-printing	Assignee:	Colin Walters <walters>
Status:	CLOSED RAWHIDE	QA Contact:
Severity:	medium	Docs Contact:
Priority:	medium
Version:	rawhide
Target Milestone:	---
Target Release:	---
Hardware:	All
OS:	Linux
Whiteboard:
Fixed In Version:	0.13-1	Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2004-09-21 20:44:37 UTC	Type:	---
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:
Bug Depends On:
Bug Blocks:	131589

Description Daniel Malmgren 2004-09-12 14:55:41 UTC

Description of problem:
In the printer information window (the one that pops up when clicking
the printer icon in the notification area), all print jobs has the
status "unknown" (my translation from swedish).

Version-Release number of selected component (if applicable):
0.10.2-2

How reproducible:
100%

Steps to Reproduce:
1. Print something
2. click the printer on the NA
3. Check the list

Additional info:
I get loads of the following line in my .xsession-errors:
** (eggcups:2507): WARNING **: couldn't connect to session bus: Unable
to determ ine the address of the message bus

Comment 1 Colin Walters 2004-09-13 18:15:16 UTC

Ok, do this: Go to Preferences->Sessions.  Click on "Current Session".
Scroll through the list until you see "eggcups".  Click it, and then
click "Remove".  Click "Apply", then "Close".

Now, open up a terminal, and run:

eggcups -d --sm-disable

Then start a print job, and paste the output here.

Comment 2 Daniel Malmgren 2004-09-14 07:37:06 UTC

[~$] eggcups -d --sm-disable
[0x8069dd8] [rb_debug_init] rb-debug.c:128 (09:33:00): Debugging enabled
[0x8069dd8] [tray_destroy_cb] main.c:181 (09:33:00): creating new tray
icon
[0x8069dd8] [idle_check_system_dbus] ec-tray-icon.c:776 (09:33:00):
acquired sys tem bus
[0x8069dd8] [ec_driver_prompt_dbus_init] ec-driver-prompt.c:318
(09:33:00): acqu iring service: com.redhat.PrintDriverSelection
[0x8069dd8] [ec_driver_prompt_dbus_init] ec-driver-prompt.c:321
(09:33:00): coul dn't acquire service: Connection ":1.38" is not
allowed to own the service " 7
                                                                     
       " due to security policies in the configuration file

** (eggcups:24198): WARNING **: couldn't connect to session bus:
Unable to deter mine the address of the message bus
[0x8069dd8] [sync_state] ec-tray-icon.c:907 (09:33:00): 0 jobs outstanding
[0x8069dd8] [handle_system_dbus_message] ec-tray-icon.c:562
(09:33:00): received  system bus message:
org.freedesktop.DBus.ServiceAcquired
[0x8069dd8] [handle_system_dbus_message] ec-tray-icon.c:562
(09:33:00): received  system bus message: (null).(null)

** (eggcups:24198): WARNING **: couldn't connect to session bus:
Unable to deter mine the address of the message bus
[0x8069dd8] [handle_system_dbus_message] ec-tray-icon.c:562
(09:33:28): received  system bus message:
com.redhat.PrinterSpooler.QueueChanged
[0x8069dd8] [handle_system_dbus_message] ec-tray-icon.c:562
(09:33:28): received  system bus message:
com.redhat.PrinterSpooler.JobQueuedLocal
[0x8069dd8] [handle_dbus_local_queue] ec-tray-icon.c:397 (09:33:28):
eggcups: jo b 14 locally queued for printer hp_psc1110
[0x8069dd8] [ec_job_model_job_submitted_local] ec-job-model.c:449
(09:33:28): jo b 14 queued local on hp_psc1110

[0x8069dd8] [sync_state] ec-tray-icon.c:907 (09:33:28): 1 jobs outstanding
[0x8069dd8] [sync_state] ec-tray-icon.c:907 (09:33:28): 1 jobs outstanding
[0x8069dd8] [handle_system_dbus_message] ec-tray-icon.c:562
(09:33:28): received  system bus message:
com.redhat.PrinterSpooler.JobStartedLocal
[0x8069dd8] [handle_dbus_local_start] ec-tray-icon.c:437 (09:33:28):
eggcups: jo b 14 has started printing for local printer hp_psc1110
[0x8069dd8] [ec_job_model_job_started_local] ec-job-model.c:475
(09:33:28): job 14 (135108696) destined for local printer       L

[0x8069dd8] [sync_state] ec-tray-icon.c:907 (09:33:28): 1 jobs outstanding

** (eggcups:24198): WARNING **: couldn't connect to session bus:
Unable to deter mine the address of the message bus
[0x8069dd8] [handle_system_dbus_message] ec-tray-icon.c:562
(09:33:32): received  system bus message:
com.redhat.PrinterSpooler.QueueChanged

** (eggcups:24198): WARNING **: couldn't connect to session bus:
Unable to deter mine the address of the message bus

** (eggcups:24198): WARNING **: couldn't connect to session bus:
Unable to deter mine the address of the message bus
[0x8069dd8] [handle_die_signal] main.c:75 (09:33:58): got die input
[0x8069dd8] [handle_die_signal] main.c:79 (09:33:58): destroying icon!
[0x8069dd8] [ec_tray_icon_dispose] ec-tray-icon.c:225 (09:33:58):
disposing

Comment 3 Colin Walters 2004-09-14 19:51:50 UTC

Also, could you try this RPM?

http://people.redhat.com/walters/desktop-printing-0.12-1.i386.rpm

Comment 4 Daniel Malmgren 2004-09-15 13:47:55 UTC

No change. This definitely has with dbus to do. I tried fiddling
around with dbus policies, and now I've changed the error message to:

[0x806fdd8] [ec_driver_prompt_dbus_init] ec-driver-prompt.c:337
(15:40:57): acquiring service: com.redhat.PrintDriverSelection
[0x806fdd8] [ec_driver_prompt_dbus_init] ec-driver-prompt.c:340
(15:40:57): couldn't acquire service: Disconnected prior to receiving
a reply

Don't know if that makes me happier thouh :-/

Comment 5 Daniel Malmgren 2004-09-15 14:45:21 UTC

Oh. Forgot to mention. With this new rpm the icon in the na doesn't
appear at all.

Comment 6 Colin Walters 2004-09-15 15:20:27 UTC

Can you give me the debugging output with the new version?

Also can you tell me a little bit about your setup?  It looks to me
like you configured your local cups server to queue for a networked
IPP printer?  Is that right?

Comment 7 Daniel Malmgren 2004-09-15 15:30:32 UTC

Nope. It's a usb connected hp psc1110C (combined printer/scanner)
using hpoj/hpij.

Debug with new version gives:

[~$] eggcups -d --sm-disable
[0x806fdd8] [rb_debug_init] rb-debug.c:128 (17:30:39): Debugging enabled
[0x806fdd8] [tray_destroy_cb] main.c:191 (17:30:39): creating new tray
icon
[0x806fdd8] [idle_check_system_dbus] ec-tray-icon.c:781 (17:30:39):
acquired system bus
[0x806fdd8] [ec_driver_prompt_dbus_init] ec-driver-prompt.c:337
(17:30:39): acquiring service: com.redhat.PrintDriverSelection
[0x806fdd8] [ec_driver_prompt_dbus_init] ec-driver-prompt.c:340
(17:30:39): couldn't acquire service: Disconnected prior to receiving
a reply

** (eggcups:14939): WARNING **: couldn't connect to session bus:
Unable to determine the address of the message bus
[0x806fdd8] [sync_state] ec-tray-icon.c:925 (17:30:39): 0 jobs outstanding
[0x806fdd8] [handle_system_dbus_message] ec-tray-icon.c:567
(17:30:39): received system bus message:
org.freedesktop.DBus.ServiceAcquired
[0x806fdd8] [handle_system_dbus_message] ec-tray-icon.c:567
(17:30:39): received system bus message: (null).(null)
[0x806fdd8] [handle_system_dbus_message] ec-tray-icon.c:567
(17:30:39): received system bus message:
org.freedesktop.Local.Disconnected
[0x806fdd8] [handle_generic_dbus_message] ec-tray-icon.c:543
(17:30:39): DISCONNECTED from system bus!

** (eggcups:14939): WARNING **: couldn't connect to session bus:
Unable to determine the address of the message bus

** (eggcups:14939): WARNING **: couldn't connect to session bus:
Unable to determine the address of the message bus

Comment 8 Colin Walters 2004-09-15 15:43:15 UTC

And this is with the 0.12 RPM?  eggcups --version says 0.12?  Do you
have a file /etc/dbus-1/system.d/printdriverselector.conf?

Ohhh...also, can you do an /etc/init.d/messagebus restart?

Comment 9 Daniel Malmgren 2004-09-15 18:00:09 UTC

Oh. You're right. I forgot to restart the messagebus. Now it works!

However, I still get the error messages ("couldn't connect to session
bus: Unable to determine the address of the message bus") every fifth
second, quickly filling up my .xsession errors when run from the Gnome
session. I'll give you another debug trace just in case:

[~$] eggcups -d --sm-disable
[0x806fdd8] [rb_debug_init] rb-debug.c:128 (19:58:24): Debugging enabled
[0x806fdd8] [tray_destroy_cb] main.c:191 (19:58:24): creating new tray
icon
[0x806fdd8] [idle_check_system_dbus] ec-tray-icon.c:781 (19:58:24):
acquired system bus
[0x806fdd8] [ec_driver_prompt_dbus_init] ec-driver-prompt.c:337
(19:58:24): acquiring service: com.redhat.PrintDriverSelection

** (eggcups:15448): WARNING **: couldn't connect to session bus:
Unable to determine the address of the message bus
[0x806fdd8] [sync_state] ec-tray-icon.c:925 (19:58:24): 0 jobs outstanding
[0x806fdd8] [handle_system_dbus_message] ec-tray-icon.c:567
(19:58:24): received system bus message:
org.freedesktop.DBus.ServiceAcquired
[0x806fdd8] [handle_system_dbus_message] ec-tray-icon.c:567
(19:58:24): received system bus message: (null).(null)
[0x806fdd8] [handle_system_dbus_message] ec-tray-icon.c:567
(19:58:24): received system bus message:
org.freedesktop.DBus.ServiceAcquired

** (eggcups:15448): WARNING **: couldn't connect to session bus:
Unable to determine the address of the message bus

** (eggcups:15448): WARNING **: couldn't connect to session bus:
Unable to determine the address of the message bus
[0x806fdd8] [handle_system_dbus_message] ec-tray-icon.c:567
(19:58:36): received system bus message:
com.redhat.PrinterSpooler.JobQueuedLocal
[0x806fdd8] [handle_dbus_local_queue] ec-tray-icon.c:402 (19:58:36):
eggcups: job 17 locally queued for printer hp_psc1110
[0x806fdd8] [ec_job_model_job_submitted_local] ec-job-model.c:446
(19:58:36): job 17 queued local on hp_psc1110

[0x806fdd8] [sync_state] ec-tray-icon.c:925 (19:58:36): 1 jobs outstanding
[0x806fdd8] [sync_state] ec-tray-icon.c:925 (19:58:36): 1 jobs outstanding
[0x806fdd8] [handle_system_dbus_message] ec-tray-icon.c:567
(19:58:36): received system bus message:
com.redhat.PrinterSpooler.JobStartedLocal
[0x806fdd8] [handle_dbus_local_start] ec-tray-icon.c:442 (19:58:36):
eggcups: job 17 has started printing for local printer hp_psc1110
[0x806fdd8] [ec_job_model_job_started_local] ec-job-model.c:472
(19:58:36): job 17 (135188928) destined for local printer ï¿½

[0x806fdd8] [sync_state] ec-tray-icon.c:925 (19:58:36): 1 jobs outstanding
[0x806fdd8] [handle_system_dbus_message] ec-tray-icon.c:567
(19:58:38): received system bus message:
com.redhat.PrinterSpooler.QueueChanged

** (eggcups:15448): WARNING **: couldn't connect to session bus:
Unable to determine the address of the message bus

** (eggcups:15448): WARNING **: couldn't connect to session bus:
Unable to determine the address of the message bus

Comment 10 Colin Walters 2004-09-15 18:05:02 UTC

You actually need to log out and log back in to get the session bus. 
Can you confirm that works?

Comment 11 Daniel Malmgren 2004-09-15 18:27:31 UTC

Yes, I can confirm everything in my last post. It works, but I still
get the warnings.

Comment 12 Colin Walters 2004-09-15 18:48:19 UTC

I mean, if you log out and log back in, (and you have dbus-x11
installed , right?) do you still get the warnings?

Comment 13 Daniel Malmgren 2004-09-15 18:52:21 UTC

And I mean, "Yep. I do". I even restarted the computer. (And yes, I
have dbus-x11 (0.22-4)).

Comment 14 Colin Walters 2004-09-15 19:01:21 UTC

How do you log into X?  The D-BUS session should be set up by
/etc/X11/xdm/Xsession.

Comment 15 Daniel Malmgren 2004-09-15 20:02:15 UTC

Ha! That's it! Everything in my /etc/X11/xdm directory was really
_old_, but there were new .rpmnew replacements as well. Fixed it, and
I get no more warnings. And my entire system somehow feels much faster
(?).

I don't know if this should be filed as a bug elsewhere? Should the
user really be expected to do this by his own?

Comment 16 Colin Walters 2004-09-15 20:08:48 UTC

Did you ever modify those files?

Comment 17 Colin Walters 2004-09-15 20:24:29 UTC

I'm going to go ahead and mark this bug as fixed, we can open another
bug for the X init bits if you determine it's not a local issue.

Comment 18 Daniel Malmgren 2004-09-16 09:52:39 UTC

I don't think I ever modified them, but I'm not sure. They might have
been from rh 7.x days. My memory is not _that_ good, so I'll just
leave it. Anyway, thanks!

Comment 19 Daniel Malmgren 2004-09-17 11:34:21 UTC

Darn! I was too happy about the icon appearing and the system going
faster that I forgot to actually look at the list of print jobs.
Sorry... The list of print jobs still looks something like this:

Document   Printer     Size   Time sent       Status
Unknown    hp_psc1110  ?      one minute ago  Unknown

And the printer icon stays in the na until eggcups is killed (probobly
because it doesn't know when the print jobs are done). A debug looks
like this (With a job sent at 13:31:25):

[~$] eggcups -d --sm-disable
[0x806fdd8] [rb_debug_init] rb-debug.c:128 (13:16:26): Debugging enabled
[0x806fdd8] [tray_destroy_cb] main.c:191 (13:16:26): creating new tray
icon
[0x806fdd8] [idle_check_system_dbus] ec-tray-icon.c:781 (13:16:26):
acquired system bus
[0x806fdd8] [ec_driver_prompt_dbus_init] ec-driver-prompt.c:337
(13:16:26): acquiring service: com.redhat.PrintDriverSelection
[0x806fdd8] [idle_check_session_dbus] ec-tray-icon.c:814 (13:16:26):
acquired session bus
[0x806fdd8] [idle_check_session_dbus] ec-tray-icon.c:822 (13:16:26):
acquired com.redhat.PrinterManager
[0x806fdd8] [idle_check_session_dbus] ec-tray-icon.c:833 (13:16:26):
acquired session bus
[0x806fdd8] [sync_state] ec-tray-icon.c:925 (13:16:26): 0 jobs outstanding
[0x806fdd8] [handle_system_dbus_message] ec-tray-icon.c:567
(13:16:26): received system bus message:
org.freedesktop.DBus.ServiceAcquired
[0x806fdd8] [handle_system_dbus_message] ec-tray-icon.c:567
(13:16:26): received system bus message: (null).(null)
[0x806fdd8] [handle_system_dbus_message] ec-tray-icon.c:567
(13:16:26): received system bus message:
org.freedesktop.DBus.ServiceAcquired
[0x806fdd8] [handle_session_dbus_message] ec-tray-icon.c:583
(13:16:26): received session bus message:
org.freedesktop.DBus.ServiceAcquired
[0x806fdd8] [handle_session_dbus_message] ec-tray-icon.c:583
(13:16:26): received session bus message:
org.freedesktop.DBus.ServiceAcquired
[0x806fdd8] [handle_session_dbus_message] ec-tray-icon.c:583
(13:16:26): received session bus message: (null).(null)
[0x806fdd8] [idle_relative_time_update] ec-job-model.c:220 (13:17:26):
relative time update
[0x806fdd8] [idle_relative_time_update] ec-job-model.c:220 (13:18:26):
relative time update
[0x806fdd8] [idle_relative_time_update] ec-job-model.c:220 (13:19:26):
relative time update
[0x806fdd8] [idle_relative_time_update] ec-job-model.c:220 (13:20:26):
relative time update
[0x806fdd8] [idle_relative_time_update] ec-job-model.c:220 (13:21:26):
relative time update
[0x806fdd8] [idle_relative_time_update] ec-job-model.c:220 (13:22:26):
relative time update
[0x806fdd8] [idle_relative_time_update] ec-job-model.c:220 (13:23:26):
relative time update
[0x806fdd8] [idle_relative_time_update] ec-job-model.c:220 (13:24:26):
relative time update
[0x806fdd8] [idle_relative_time_update] ec-job-model.c:220 (13:25:26):
relative time update
[0x806fdd8] [idle_relative_time_update] ec-job-model.c:220 (13:26:26):
relative time update
[0x806fdd8] [idle_relative_time_update] ec-job-model.c:220 (13:27:26):
relative time update
[0x806fdd8] [idle_relative_time_update] ec-job-model.c:220 (13:28:26):
relative time update
[0x806fdd8] [idle_relative_time_update] ec-job-model.c:220 (13:29:26):
relative time update
[0x806fdd8] [idle_relative_time_update] ec-job-model.c:220 (13:30:26):
relative time update
[0x806fdd8] [handle_system_dbus_message] ec-tray-icon.c:567
(13:31:25): received system bus message:
com.redhat.PrinterSpooler.QueueChanged
[0x806fdd8] [handle_system_dbus_message] ec-tray-icon.c:567
(13:31:25): received system bus message:
com.redhat.PrinterSpooler.JobQueuedLocal
[0x806fdd8] [handle_dbus_local_queue] ec-tray-icon.c:402 (13:31:25):
eggcups: job 21 locally queued for printer hp_psc1110
[0x806fdd8] [ec_job_model_job_submitted_local] ec-job-model.c:446
(13:31:25): job 21 queued local on hp_psc1110

[0x806fdd8] [sync_state] ec-tray-icon.c:925 (13:31:25): 1 jobs outstanding
[0x806fdd8] [sync_state] ec-tray-icon.c:925 (13:31:26): 1 jobs outstanding
[0x806fdd8] [handle_system_dbus_message] ec-tray-icon.c:567
(13:31:26): received system bus message:
com.redhat.PrinterSpooler.JobStartedLocal[0x806fdd8]
[handle_dbus_local_start] ec-tray-icon.c:442 (13:31:26): eggcups: job
21 has started printing for local printer hp_psc1110
[0x806fdd8] [ec_job_model_job_started_local] ec-job-model.c:472
(13:31:26): job 21 (135070408) destined for local printer ï¿½

[0x806fdd8] [sync_state] ec-tray-icon.c:925 (13:31:26): 1 jobs outstanding
[0x806fdd8] [idle_relative_time_update] ec-job-model.c:220 (13:31:26):
relative time update
[0x806fdd8] [idle_relative_time_update] ec-job-model.c:240 (13:31:26):
updating local job time
[0x806fdd8] [sync_state] ec-tray-icon.c:925 (13:31:26): 1 jobs outstanding
[0x806fdd8] [handle_system_dbus_message] ec-tray-icon.c:567
(13:31:51): received system bus message:
com.redhat.PrinterSpooler.QueueChanged
[0x806fdd8] [idle_relative_time_update] ec-job-model.c:220 (13:32:26):
relative time update
[0x806fdd8] [idle_relative_time_update] ec-job-model.c:240 (13:32:26):
updating local job time
[0x806fdd8] [sync_state] ec-tray-icon.c:925 (13:32:26): 1 jobs outstanding
[0x806fdd8] [idle_relative_time_update] ec-job-model.c:220 (13:33:26):
relative time update
[0x806fdd8] [idle_relative_time_update] ec-job-model.c:240 (13:33:26):
updating local job time
[0x806fdd8] [sync_state] ec-tray-icon.c:925 (13:33:26): 1 jobs outstanding
[0x806fdd8] [idle_relative_time_update] ec-job-model.c:220 (13:34:26):
relative time update
[0x806fdd8] [idle_relative_time_update] ec-job-model.c:240 (13:34:26):
updating local job time
[0x806fdd8] [sync_state] ec-tray-icon.c:925 (13:34:26): 1 jobs outstanding
[0x806fdd8] [handle_die_signal] main.c:86 (13:34:43): got die input
[0x806fdd8] [destroy_icon] main.c:48 (13:34:43): destroying icon!
[0x806fdd8] [ec_tray_icon_dispose] ec-tray-icon.c:228 (13:34:43):
disposing
[0x806fdd8] [ec_dbus_unregister_handler] ec-tray-icon.c:592
(13:34:43): unregistered
[0x806fdd8] [ec_job_list_finalize] ec-job-list.c:379 (13:34:43):
finalizing

Comment 20 Colin Walters 2004-09-17 18:53:18 UTC

Right after you print a job, can you go to:

http://localhost:631/printers

Then click on your printer.  Is your job listed?

It may be that hpoj just isn't able to give any status feedback.

Comment 21 Daniel Malmgren 2004-09-18 17:39:28 UTC

Yes it is. And the size, state etc seems to be correct there.

One more thing I just discovered: When clicking "Print handler" in the
"system utilities" menu (my translation, I'm running swedish) I get a
fully working list of print jobs (state, size etc is showed correctly
here). However, every time I start it I get a requester saying "No
printers found.  Run the printer configuration tool?". Clicking cancel
works fine, and my printer displays just fine. Guess this has nothing
with desktop-printing to do, guess there is some strangeness somewhere
else in my printing system...

Comment 22 Colin Walters 2004-09-20 16:11:41 UTC

Hm, it looks like monitoring isn't working for local printers.

Comment 23 Colin Walters 2004-09-20 19:17:17 UTC

Can you try this RPM?

http://people.redhat.com/walters/desktop-printing-0.13-1.i386.rpm

Comment 24 Daniel Malmgren 2004-09-21 12:05:03 UTC

Yes. That's a lot better! The list showed all information I wanted to
have now.

I don't know if it's a problem, but for one of the documents I printed
the status said "Printing (?)" for a while when the printing was
finished before changing to "ready" status. If that is no problem then
I guess you may close this bug. Here comes a debug trace just for the
sake of it:

[~$] eggcups -d --sm-disable
[0x806fdd8] [rb_debug_init] rb-debug.c:128 (13:59:56): Debugging enabled
[0x806fdd8] [main] main.c:147 (13:59:56): getting session bus
[0x806fdd8] [main] main.c:159 (13:59:56): acquisition success: TRUE
result: 0 error: NO
[0x806fdd8] [main] main.c:170 (13:59:56): activated, starting up
[0x806fdd8] [tray_destroy_cb] main.c:221 (13:59:56): creating new tray
icon
[0x806fdd8] [idle_check_system_dbus] ec-tray-icon.c:811 (13:59:56):
acquired system bus
[0x806fdd8] [ec_driver_prompt_dbus_init] ec-driver-prompt.c:337
(13:59:56): acquiring service: com.redhat.PrintDriverSelection
[0x806fdd8] [idle_check_session_dbus] ec-tray-icon.c:843 (13:59:56):
acquired session bus
[0x806fdd8] [idle_check_session_dbus] ec-tray-icon.c:850 (13:59:56):
acquired com.redhat.PrinterManager
[0x806fdd8] [idle_check_session_dbus] ec-tray-icon.c:861 (13:59:56):
acquired session bus
[0x806fdd8] [sync_state] ec-tray-icon.c:998 (13:59:56): 0 jobs outstanding
[0x806fdd8] [handle_system_dbus_message] ec-tray-icon.c:597
(13:59:56): received system bus message:
org.freedesktop.DBus.ServiceAcquired
[0x806fdd8] [handle_system_dbus_message] ec-tray-icon.c:597
(13:59:56): received system bus message: (null).(null)
[0x806fdd8] [handle_system_dbus_message] ec-tray-icon.c:597
(13:59:56): received system bus message:
org.freedesktop.DBus.ServiceAcquired
[0x806fdd8] [handle_session_dbus_message] ec-tray-icon.c:613
(13:59:56): received session bus message:
org.freedesktop.DBus.ServiceAcquired
[0x806fdd8] [handle_session_dbus_message] ec-tray-icon.c:613
(13:59:56): received session bus message:
org.freedesktop.DBus.ServiceAcquired
[0x806fdd8] [handle_session_dbus_message] ec-tray-icon.c:613
(13:59:56): received session bus message: (null).(null)
[0x806fdd8] [handle_system_dbus_message] ec-tray-icon.c:597
(14:00:18): received system bus message:
com.redhat.PrinterSpooler.QueueChanged
[0x806fdd8] [handle_system_dbus_message] ec-tray-icon.c:597
(14:00:18): received system bus message:
com.redhat.PrinterSpooler.JobQueuedLocal
[0x806fdd8] [handle_dbus_local_queue] ec-tray-icon.c:432 (14:00:18):
eggcups: job 25 locally queued for printer hp_psc1110
[0x806fdd8] [job_submitted_local_internal] ec-job-model.c:440
(14:00:18): job 25 queued local on hp_psc1110

[0x806fdd8] [sync_state] ec-tray-icon.c:998 (14:00:18): 1 jobs outstanding
[0x806fdd8] [sync_state] ec-tray-icon.c:998 (14:00:18): 1 jobs outstanding
[0x806fdd8] [sync_state] ec-tray-icon.c:998 (14:00:18): 1 jobs outstanding
[0x806fdd8] [handle_system_dbus_message] ec-tray-icon.c:597
(14:00:18): received system bus message:
com.redhat.PrinterSpooler.JobStartedLocal
[0x806fdd8] [handle_dbus_local_start] ec-tray-icon.c:472 (14:00:18):
eggcups: job 25 has started printing for local printer hp_psc1110
[0x806fdd8] [ec_job_model_job_started_local] ec-job-model.c:485
(14:00:18): job 25 destined for local printer hp_psc1110

[0x806fdd8] [sync_state] ec-tray-icon.c:998 (14:00:18): 1 jobs outstanding
[0x806fdd8] [ec_cups_job_monitor_add_job] ec-cups-job-monitor.c:540
(14:00:18): monitoring job 25 on localhost
[0x806fdd8] [monitored_job_new] ec-cups-job-monitor.c:648 (14:00:18):
creating job 25
[0x806fdd8] [ec_cups_job_monitor_add_job] ec-cups-job-monitor.c:551
(14:00:18): first job; kicking off polling
[0x806fdd8] [ec_job_model_job_started_local] ec-job-model.c:496
(14:00:18): job state: 5
[0x806fdd8] [ec_job_model_job_started_local] ec-job-model.c:497
(14:00:18): job state: Skriver ut
[0x806fdd8] [sync_state] ec-tray-icon.c:998 (14:00:18): 1 jobs outstanding
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:00:18):
polling all queues
[0x806fdd8] [poll_jobs] ec-cups-job-monitor.c:458 (14:00:18): polling
localhost
[0x806fdd8] [poll_job] ec-cups-job-monitor.c:451 (14:00:18): kicking
off request 3 for job 25 on localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:491 (14:00:18): 1
remaining jobs to monitor
[0x806fdd8] [get_job_cb] ec-cups-job-monitor.c:390 (14:00:19): got
callback for job 25 on localhost
[0x806fdd8] [get_job_cb] ec-cups-job-monitor.c:398 (14:00:19): job 25
FOUND
[0x806fdd8] [handle_job_changed] ec-cups-job-monitor.c:221 (14:00:19):
handling job change: 25 daniel PROCESSING
[0x806fdd8] [job_changed_cb] ec-job-model.c:399 (14:00:19): handling
job 25 changed
[0x806fdd8] [job_changed_cb] ec-job-model.c:400 (14:00:19):
state_reason: job-printing
[0x806fdd8] [sync_state] ec-tray-icon.c:998 (14:00:19): 1 jobs outstanding
[0x806fdd8] [handle_system_dbus_message] ec-tray-icon.c:597
(14:00:21): received system bus message:
com.redhat.PrinterSpooler.QueueChanged
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:00:23):
polling all queues
[0x806fdd8] [poll_jobs] ec-cups-job-monitor.c:458 (14:00:23): polling
localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:491 (14:00:23): 1
remaining jobs to monitor
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:00:28):
polling all queues
[0x806fdd8] [poll_jobs] ec-cups-job-monitor.c:458 (14:00:28): polling
localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:491 (14:00:28): 1
remaining jobs to monitor
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:00:33):
polling all queues
[0x806fdd8] [poll_jobs] ec-cups-job-monitor.c:458 (14:00:33): polling
localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:491 (14:00:33): 1
remaining jobs to monitor
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:00:38):
polling all queues
[0x806fdd8] [poll_jobs] ec-cups-job-monitor.c:458 (14:00:38): polling
localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:491 (14:00:38): 1
remaining jobs to monitor
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:00:43):
polling all queues
[0x806fdd8] [poll_jobs] ec-cups-job-monitor.c:458 (14:00:43): polling
localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:491 (14:00:43): 1
remaining jobs to monitor
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:00:48):
polling all queues
[0x806fdd8] [poll_jobs] ec-cups-job-monitor.c:458 (14:00:48): polling
localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:491 (14:00:48): 1
remaining jobs to monitor
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:00:53):
polling all queues
[0x806fdd8] [poll_jobs] ec-cups-job-monitor.c:458 (14:00:53): polling
localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:491 (14:00:53): 1
remaining jobs to monitor
[0x806fdd8] [idle_relative_time_update] ec-job-model.c:220 (14:00:56):
relative time update
[0x806fdd8] [idle_relative_time_update] ec-job-model.c:240 (14:00:56):
updating local job time
[0x806fdd8] [sync_state] ec-tray-icon.c:998 (14:00:56): 1 jobs outstanding
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:00:58):
polling all queues
[0x806fdd8] [poll_jobs] ec-cups-job-monitor.c:458 (14:00:58): polling
localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:491 (14:00:58): 1
remaining jobs to monitor
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:01:03):
polling all queues
[0x806fdd8] [poll_jobs] ec-cups-job-monitor.c:458 (14:01:03): polling
localhost
[0x806fdd8] [check_emit_job_timeout] ec-cups-job-monitor.c:350
(14:01:03): job 25 on localhost has timed out!
[0x806fdd8] [job_timeout_cb] ec-job-model.c:359 (14:01:03): handling
job 25 timeout
[0x806fdd8] [sync_state] ec-tray-icon.c:998 (14:01:03): 1 jobs outstanding
[0x806fdd8] [poll_job] ec-cups-job-monitor.c:430 (14:01:03):
cancelling request 3 for job 25 on localhost
[0x806fdd8] [poll_job] ec-cups-job-monitor.c:451 (14:01:03): kicking
off request 4 for job 25 on localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:491 (14:01:03): 1
remaining jobs to monitor
[0x806fdd8] [get_job_cb] ec-cups-job-monitor.c:390 (14:01:04): got
callback for job 25 on localhost
[0x806fdd8] [handle_job_changed] ec-cups-job-monitor.c:221 (14:01:04):
handling job change: 25 daniel COMPLETED
[0x806fdd8] [remove_job_deferred] ec-cups-job-monitor.c:601
(14:01:04): deferring removal of 25
[0x806fdd8] [job_changed_cb] ec-job-model.c:399 (14:01:04): handling
job 25 changed
[0x806fdd8] [job_changed_cb] ec-job-model.c:400 (14:01:04):
state_reason: job-completed-successfully
[0x806fdd8] [sync_state] ec-tray-icon.c:998 (14:01:04): 0 jobs outstanding
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:01:08):
polling all queues
[0x806fdd8] [process_deferred_removals] ec-cups-job-monitor.c:468
(14:01:08): processing deferred removals on localhost
[0x806fdd8] [remove_job_internal] ec-cups-job-monitor.c:573
(14:01:08): unmonitoring job 25 on localhost
[0x806fdd8] [monitored_job_destroy] ec-cups-job-monitor.c:655
(14:01:08): unreffing job 25
[0x806fdd8] [remove_job_internal] ec-cups-job-monitor.c:581
(14:01:08): 0 jobs remaining on localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:494 (14:01:08): no
more jobs to monitor; not requeuing idle poll
[0x806fdd8] [handle_system_dbus_message] ec-tray-icon.c:597
(14:01:40): received system bus message:
com.redhat.PrinterSpooler.QueueChanged
[0x806fdd8] [handle_system_dbus_message] ec-tray-icon.c:597
(14:01:40): received system bus message:
com.redhat.PrinterSpooler.JobQueuedLocal
[0x806fdd8] [handle_dbus_local_queue] ec-tray-icon.c:432 (14:01:40):
eggcups: job 26 locally queued for printer hp_psc1110
[0x806fdd8] [job_submitted_local_internal] ec-job-model.c:440
(14:01:40): job 26 queued local on hp_psc1110

[0x806fdd8] [sync_state] ec-tray-icon.c:998 (14:01:40): 1 jobs outstanding
[0x806fdd8] [sync_state] ec-tray-icon.c:998 (14:01:40): 1 jobs outstanding
[0x806fdd8] [sync_state] ec-tray-icon.c:998 (14:01:40): 1 jobs outstanding
[0x806fdd8] [handle_system_dbus_message] ec-tray-icon.c:597
(14:01:40): received system bus message:
com.redhat.PrinterSpooler.JobStartedLocal
[0x806fdd8] [handle_dbus_local_start] ec-tray-icon.c:472 (14:01:40):
eggcups: job 26 has started printing for local printer hp_psc1110
[0x806fdd8] [ec_job_model_job_started_local] ec-job-model.c:485
(14:01:40): job 26 destined for local printer hp_psc1110

[0x806fdd8] [sync_state] ec-tray-icon.c:998 (14:01:40): 1 jobs outstanding
[0x806fdd8] [ec_cups_job_monitor_add_job] ec-cups-job-monitor.c:540
(14:01:40): monitoring job 26 on localhost
[0x806fdd8] [monitored_job_new] ec-cups-job-monitor.c:648 (14:01:40):
creating job 26
[0x806fdd8] [ec_cups_job_monitor_add_job] ec-cups-job-monitor.c:551
(14:01:40): first job; kicking off polling
[0x806fdd8] [ec_job_model_job_started_local] ec-job-model.c:496
(14:01:40): job state: 5
[0x806fdd8] [ec_job_model_job_started_local] ec-job-model.c:497
(14:01:40): job state: Skriver ut
[0x806fdd8] [sync_state] ec-tray-icon.c:998 (14:01:40): 1 jobs outstanding
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:01:40):
polling all queues
[0x806fdd8] [poll_jobs] ec-cups-job-monitor.c:458 (14:01:40): polling
localhost
[0x806fdd8] [poll_job] ec-cups-job-monitor.c:451 (14:01:40): kicking
off request 6 for job 26 on localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:491 (14:01:40): 1
remaining jobs to monitor
[0x806fdd8] [get_job_cb] ec-cups-job-monitor.c:390 (14:01:40): got
callback for job 26 on localhost
[0x806fdd8] [get_job_cb] ec-cups-job-monitor.c:398 (14:01:40): job 26
FOUND
[0x806fdd8] [handle_job_changed] ec-cups-job-monitor.c:221 (14:01:40):
handling job change: 26 daniel PROCESSING
[0x806fdd8] [job_changed_cb] ec-job-model.c:399 (14:01:40): handling
job 26 changed
[0x806fdd8] [job_changed_cb] ec-job-model.c:400 (14:01:40):
state_reason: job-printing
[0x806fdd8] [sync_state] ec-tray-icon.c:998 (14:01:40): 1 jobs outstanding
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:01:45):
polling all queues
[0x806fdd8] [poll_jobs] ec-cups-job-monitor.c:458 (14:01:45): polling
localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:491 (14:01:45): 1
remaining jobs to monitor
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:01:50):
polling all queues
[0x806fdd8] [poll_jobs] ec-cups-job-monitor.c:458 (14:01:50): polling
localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:491 (14:01:50): 1
remaining jobs to monitor
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:01:55):
polling all queues
[0x806fdd8] [poll_jobs] ec-cups-job-monitor.c:458 (14:01:55): polling
localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:491 (14:01:55): 1
remaining jobs to monitor
[0x806fdd8] [idle_relative_time_update] ec-job-model.c:220 (14:01:56):
relative time update
[0x806fdd8] [idle_relative_time_update] ec-job-model.c:240 (14:01:56):
updating local job time
[0x806fdd8] [idle_relative_time_update] ec-job-model.c:240 (14:01:56):
updating local job time
[0x806fdd8] [sync_state] ec-tray-icon.c:998 (14:01:56): 1 jobs outstanding
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:02:00):
polling all queues
[0x806fdd8] [poll_jobs] ec-cups-job-monitor.c:458 (14:02:00): polling
localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:491 (14:02:00): 1
remaining jobs to monitor
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:02:05):
polling all queues
[0x806fdd8] [poll_jobs] ec-cups-job-monitor.c:458 (14:02:05): polling
localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:491 (14:02:05): 1
remaining jobs to monitor
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:02:10):
polling all queues
[0x806fdd8] [poll_jobs] ec-cups-job-monitor.c:458 (14:02:10): polling
localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:491 (14:02:10): 1
remaining jobs to monitor
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:02:15):
polling all queues
[0x806fdd8] [poll_jobs] ec-cups-job-monitor.c:458 (14:02:15): polling
localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:491 (14:02:15): 1
remaining jobs to monitor
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:02:20):
polling all queues
[0x806fdd8] [poll_jobs] ec-cups-job-monitor.c:458 (14:02:20): polling
localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:491 (14:02:20): 1
remaining jobs to monitor
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:02:25):
polling all queues
[0x806fdd8] [poll_jobs] ec-cups-job-monitor.c:458 (14:02:25): polling
localhost
[0x806fdd8] [check_emit_job_timeout] ec-cups-job-monitor.c:350
(14:02:25): job 26 on localhost has timed out!
[0x806fdd8] [job_timeout_cb] ec-job-model.c:359 (14:02:25): handling
job 26 timeout
[0x806fdd8] [sync_state] ec-tray-icon.c:998 (14:02:25): 1 jobs outstanding
[0x806fdd8] [poll_job] ec-cups-job-monitor.c:430 (14:02:25):
cancelling request 6 for job 26 on localhost
[0x806fdd8] [poll_job] ec-cups-job-monitor.c:451 (14:02:25): kicking
off request 7 for job 26 on localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:491 (14:02:25): 1
remaining jobs to monitor
[0x806fdd8] [get_job_cb] ec-cups-job-monitor.c:390 (14:02:25): got
callback for job 26 on localhost
[0x806fdd8] [get_job_cb] ec-cups-job-monitor.c:409 (14:02:25): job 26
UNCHANGED
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:02:30):
polling all queues
[0x806fdd8] [poll_jobs] ec-cups-job-monitor.c:458 (14:02:30): polling
localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:491 (14:02:30): 1
remaining jobs to monitor
[0x806fdd8] [handle_system_dbus_message] ec-tray-icon.c:597
(14:02:30): received system bus message:
com.redhat.PrinterSpooler.QueueChanged
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:02:35):
polling all queues
[0x806fdd8] [poll_jobs] ec-cups-job-monitor.c:458 (14:02:35): polling
localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:491 (14:02:35): 1
remaining jobs to monitor
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:02:40):
polling all queues
[0x806fdd8] [poll_jobs] ec-cups-job-monitor.c:458 (14:02:40): polling
localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:491 (14:02:40): 1
remaining jobs to monitor
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:02:45):
polling all queues
[0x806fdd8] [poll_jobs] ec-cups-job-monitor.c:458 (14:02:45): polling
localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:491 (14:02:45): 1
remaining jobs to monitor
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:02:50):
polling all queues
[0x806fdd8] [poll_jobs] ec-cups-job-monitor.c:458 (14:02:50): polling
localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:491 (14:02:50): 1
remaining jobs to monitor
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:02:55):
polling all queues
[0x806fdd8] [poll_jobs] ec-cups-job-monitor.c:458 (14:02:55): polling
localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:491 (14:02:55): 1
remaining jobs to monitor
[0x806fdd8] [idle_relative_time_update] ec-job-model.c:220 (14:02:56):
relative time update
[0x806fdd8] [idle_relative_time_update] ec-job-model.c:240 (14:02:56):
updating local job time
[0x806fdd8] [idle_relative_time_update] ec-job-model.c:240 (14:02:56):
updating local job time
[0x806fdd8] [sync_state] ec-tray-icon.c:998 (14:02:56): 1 jobs outstanding
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:03:00):
polling all queues
[0x806fdd8] [poll_jobs] ec-cups-job-monitor.c:458 (14:03:00): polling
localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:491 (14:03:00): 1
remaining jobs to monitor
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:03:05):
polling all queues
[0x806fdd8] [poll_jobs] ec-cups-job-monitor.c:458 (14:03:05): polling
localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:491 (14:03:05): 1
remaining jobs to monitor
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:03:10):
polling all queues
[0x806fdd8] [poll_jobs] ec-cups-job-monitor.c:458 (14:03:10): polling
localhost
[0x806fdd8] [check_emit_job_timeout] ec-cups-job-monitor.c:350
(14:03:10): job 26 on localhost has timed out!
[0x806fdd8] [job_timeout_cb] ec-job-model.c:359 (14:03:10): handling
job 26 timeout
[0x806fdd8] [sync_state] ec-tray-icon.c:998 (14:03:10): 1 jobs outstanding
[0x806fdd8] [poll_job] ec-cups-job-monitor.c:430 (14:03:10):
cancelling request 7 for job 26 on localhost
[0x806fdd8] [poll_job] ec-cups-job-monitor.c:451 (14:03:10): kicking
off request 8 for job 26 on localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:491 (14:03:10): 1
remaining jobs to monitor
[0x806fdd8] [get_job_cb] ec-cups-job-monitor.c:390 (14:03:10): got
callback for job 26 on localhost
[0x806fdd8] [handle_job_changed] ec-cups-job-monitor.c:221 (14:03:10):
handling job change: 26 daniel COMPLETED
[0x806fdd8] [remove_job_deferred] ec-cups-job-monitor.c:601
(14:03:10): deferring removal of 26
[0x806fdd8] [job_changed_cb] ec-job-model.c:399 (14:03:10): handling
job 26 changed
[0x806fdd8] [job_changed_cb] ec-job-model.c:400 (14:03:10):
state_reason: job-completed-successfully
[0x806fdd8] [sync_state] ec-tray-icon.c:998 (14:03:10): 0 jobs outstanding
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:480 (14:03:15):
polling all queues
[0x806fdd8] [process_deferred_removals] ec-cups-job-monitor.c:468
(14:03:15): processing deferred removals on localhost
[0x806fdd8] [remove_job_internal] ec-cups-job-monitor.c:573
(14:03:15): unmonitoring job 26 on localhost
[0x806fdd8] [monitored_job_destroy] ec-cups-job-monitor.c:655
(14:03:15): unreffing job 26
[0x806fdd8] [remove_job_internal] ec-cups-job-monitor.c:581
(14:03:15): 0 jobs remaining on localhost
[0x806fdd8] [poll_all_queues] ec-cups-job-monitor.c:494 (14:03:15): no
more jobs to monitor; not requeuing idle poll

Comment 25 Colin Walters 2004-09-21 20:44:37 UTC

Well it sounds like the main bug is fixed.  Can you reproduce a long
delay on the status change each time, or did it just seem to be that
one job?