CUPS 1.4.4 slows down with system-config-printer-applet

[John A. Murdie]

Tim - I'm continuing the thread "CUPS 1.4.4 slow - problem checklist?" I 
started in the cups.general forum, here. I'll summarise the problem.

We have two cupsd processes (staff, student) on a Slackware Linux 13.1 
print server running as a virtual machine on server hardware.

I found that only two users running system-config-printer-applet 
('scpa') on their Linux desktops was enough to take cupsd CPU% (as 
measured by top(1)) to 99% - just one will take it to 60-80%. I don't 
know what version of scpa we have as default on our system, but version 
1.2.5 from the 13th October also causes the problem.

Running scpa as 'system-config-printer-applet --debug', I saw:
> $ /usr/share/system-config-printer/system-config-printer.py --debug
> Connected as user john
> refresh
> <monitor.Monitor instance at 0x9b13eec>: CUPS IPP error (1025, 'client-error-forbidden')
> Created subscription -1
> <monitor.Monitor instance at 0x9b13eec>: printers and jobs lists provided
> update_jobs
> Authentication pass: 1
> Authentication: password callback set
> Authentication pass: 1
> Authentication: password callback set
> Authentication pass: 1
> Authentication: password callback set
> get_notifications
> refresh
> <monitor.Monitor instance at 0x9b13eec>: CUPS IPP error (1025, 'client-error-forbidden')
> Created subscription -1
> <monitor.Monitor instance at 0x989eeec>: printers and jobs lists provided
> update_jobs
> get_notifications
> refresh
> <monitor.Monitor instance at 0x989eeec>: CUPS IPP error (1025, 'client-error-forbidden')
> ...

Now, to discuss the problems:

1. You wrote:
> > <monitor.Monitor instance at 0x9b13eec>: CUPS IPP error (1025, 'client-er=
>
> ror-forbidden')
> > Created subscription -1
>
> This looks like IPP-Create-Subscription is not allowed for this client,
> due to the way CUPS is configured.  Subscriptions are more efficient for
> this sort of application because it can be told about relevant changes
> rather than having to fetch the entire list each time:

I attach our server's cupsd.conf file (bowdlerised with "whatever"s!), 
which contains:
> # Set the default printer/job policies...
>
> <Policy default>
>
> # Job-related operations must be done by the owner or an adminstrator...
>   # Note that we need to 'Allow from localhost' for Windows LPR printing
>   <Limit Send-Document Send-URI Hold-Job Release-Job Restart-Job Purge-Jobs
>         Set-Job-Attributes Create-Job-Subscription Renew-Subscription

Cancel-Subscription
>     Get-Notifications Reprocess-Job Cancel-Job Cancel-Current-Job 

Suspend-Current-Job
>     Resume-Job CUPS-Move-Job Get-Job-Attributes 

CUPS-Authenticate-Job>
> Order allow,deny
> AuthType Default	# required to force authentication
> Require user @OWNER @SYSTEM
> Allow from localhost
> Satisfy any
>
>   </Limit>

That has Create-Job-Subscription etc permissions for all users. Perhaps 
the 'Allow from localhost' - i.e. the print server - ought to be applied 
more selectively, but it was there to allow print jobs coming in by 
cups-lpr from Windows systems to proceed. I see from the CUPS document 
'Managing Operations Policies' - 
http://www.cups.org/documentation.php/doc-1.4/policies.html - that I'd 
missed various subscription-related policies (Yes: I have it; No - I 
don't have it):

Create-Printer-Subscription	No
Create-Job-Subscription		Yes
Get-Subscription-Attributes	No
Get-Subscriptions		No
Renew-Subscription		Yes
Cancel-Subscription		Yes
Get-Notifications		Yes
Send-Notifications		No

Do I need all of the ones I have not used? I think I took the original 
set from an example CUPS configuration file, long ago.

2. You also wrote:
> > <monitor.Monitor instance at 0x9b13eec>: printers and jobs lists provided
>
> But how often is it doing that?  Does it happen continuously even when
> there is no activity, or does it only happen whenever there is some
> change in the status of a job?

It does seem to happen continually even when there is no activity, as 
fast as CUPS can respond - which is presumably why the CPU% of cupsd 
rises to 99%.

John A. Murdie

[Tim Waugh]

On Wed, 2010-10-20 at 13:32 +0100, John A. Murdie wrote:
> > > <monitor.Monitor instance at 0x9b13eec>: CUPS IPP error (1025, 'client-er=
> >
> > ror-forbidden')
> > > Created subscription -1
> >
> > This looks like IPP-Create-Subscription is not allowed for this client,
> > due to the way CUPS is configured.  Subscriptions are more efficient for
> > this sort of application because it can be told about relevant changes
> > rather than having to fetch the entire list each time:
>
> I attach our server's cupsd.conf file (bowdlerised with "whatever"s!), 
> which contains:
> > # Set the default printer/job policies...
> >
> > <Policy default>
> >
> > # Job-related operations must be done by the owner or an adminstrator...
> >   # Note that we need to 'Allow from localhost' for Windows LPR printing
> >   <Limit Send-Document Send-URI Hold-Job Release-Job Restart-Job Purge-Jobs
> >         Set-Job-Attributes Create-Job-Subscription Renew-Subscription
>
> Cancel-Subscription
> >     Get-Notifications Reprocess-Job Cancel-Job Cancel-Current-Job 
>
> Suspend-Current-Job
> >     Resume-Job CUPS-Move-Job Get-Job-Attributes 
>
> CUPS-Authenticate-Job>
> > Order allow,deny
> > AuthType Default	# required to force authentication
> > Require user @OWNER @SYSTEM
> > Allow from localhost
> > Satisfy any
> >
> >   </Limit>

So yes, Create-Job-Subscription and Create-Printer-Subscription require
authentication.  Currently system-config-printer's CUPS monitor module
does not support using authentication for that, and it isn't really
meant to handle automatic updating if it can't use subscriptions.
> It does seem to happen continually even when there is no activity, as 
> fast as CUPS can respond - which is presumably why the CPU% of cupsd 
> rises to 99%.

I think I might have found the problem.  When it fails to get
notifications (because there is no subscription to use), it refreshes
the entire list of printers and jobs... and tries to create another
subscription.

Should be fixed upstream now, in that it won't try to automatically
update printers and jobs if subscriptions cannot be used.

Would you be able to try it out?  Just down monitor.py from the current
1.2.x branch and use it as a replacement for the one in 1.2.5:
http://git.fedorahosted.org/git/?p=system-config-printer.git;a=blob_plain;f=...

Thanks,
Tim.
*/

[John A. Murdie]

On 20/10/10 15:36, Tim Waugh wrote:
> So yes, Create-Job-Subscription and Create-Printer-Subscription require
> authentication.  Currently system-config-printer's CUPS monitor module
> does not support using authentication for that, and it isn't really
> meant to handle automatic updating if it can't use subscriptions.
> > It does seem to happen continually even when there is no activity, as
> > fast as CUPS can respond - which is presumably why the CPU% of cupsd
> > rises to 99%.
>
> I think I might have found the problem.  When it fails to get
> notifications (because there is no subscription to use), it refreshes
> the entire list of printers and jobs... and tries to create another
> subscription.
>
> Should be fixed upstream now, in that it won't try to automatically
> update printers and jobs if subscriptions cannot be used.
>
> Would you be able to try it out?  Just down monitor.py from the current
> 1.2.x branch and use it as a replacement for the one in 1.2.5:
> http://git.fedorahosted.org/git/?p=system-config-printer.git;a=blob_plain;f=...
>
> Thanks,
> Tim.

I tried 1.2.5 with the new monitor.py before adding 
Create-Printer-Subscription (we already had Create-Job-Subscription as 
my lisy showed) and saw:
> ./system-config-printer-applet --debug
> system-config-printer-applet: failed to start NewPrinterNotification service
> refresh
> <monitor.Monitor instance at 0x9320dac>: CUPS IPP error (1025, 'client-error-forbidden')
> <monitor.Monitor instance at 0x9320dac>: printers and jobs lists provided
> Upset printers: set([])
> open notifications: 0
> num_jobs: 0
> num_jobs_when_hidden: 0
> update_jobs
> Got 0 jobs, asked for 1
> update_jobs

Then I added Create-Printer-Subscription to the cupsd.conf and restarted 
cupsd and tried again:

; ./system-config-printer-applet --debug
system-config-printer-applet: failed to start NewPrinterNotification service
refresh
Created subscription 3, events=['printer-added', 'printer-deleted', 
'printer-state-changed', 'job-created', 'job-completed', 'job-stopped', 
'job-state-changed', 'job-progress']
Next notifications fetch in 1s
<monitor.Monitor instance at 0x9befdac>: printers and jobs lists provided
Upset printers: set([])
open notifications: 0
num_jobs: 0
num_jobs_when_hidden: 0
Deferred get_notifications by 200ms
update_jobs
Got 0 jobs, asked for 1
update_jobs
get_notifications
update_jobs
Next notifications fetch in 60s
get_notifications
1 job-created Job created.
{'job-impressions-completed': 0,
  'job-name': u'291010.pdf',
  'job-state': 4,
  'job-state-reasons': u'job-hold-until-specified',
  'notify-charset': u'utf-8',
  'notify-job-id': 22968,
  'notify-natural-langugage': u'en-us',
  'notify-printer-uri': u'ipp://ness.cs.york.ac.uk:631/printers/cp001',
  'notify-sequence-number': 1,
  'notify-subscribed-event': u'job-created',
  'notify-subscription-id': 3,
  'notify-text': u'Job created.',
  'printer-is-accepting-jobs': True,
  'printer-name': u'cp001',
  'printer-state': 3,
  'printer-state-reasons': [u'none'],
  'printer-up-time': 1287593697}
2 printer-state-changed Printer "cp001" state changed to password.
{'notify-charset': u'utf-8',
  'notify-natural-langugage': u'en-us',
  'notify-printer-uri': u'ipp://ness.cs.york.ac.uk:631/printers/cp001',
  'notify-sequence-number': 2,
  'notify-subscribed-event': u'printer-state-changed',
  'notify-subscription-id': 3,
  'notify-text': u'Printer "cp001" state changed to password.',
  'printer-is-accepting-jobs': True,
  'printer-name': u'cp001',
  'printer-state': 4,
  'printer-state-reasons': [u'none'],
  'printer-up-time': 1287593697}
3 job-state-changed Job #22968 started.
{'job-impressions-completed': 0,
  'job-name': u'291010.pdf',
  'job-state': 5,
  'job-state-reasons': u'job-printing',
  'notify-charset': u'utf-8',
  'notify-job-id': 22968,
  'notify-natural-langugage': u'en-us',
  'notify-printer-uri': u'ipp://ness.cs.york.ac.uk:631/printers/cp001',
  'notify-sequence-number': 3,
  'notify-subscribed-event': u'job-state-changed',
  'notify-subscription-id': 3,
  'notify-text': u'Job #22968 started.',
  'printer-is-accepting-jobs': True,
  'printer-name': u'cp001',
  'printer-state': 4,
  'printer-state-reasons': [u'none'],
  'printer-up-time': 1287593697}
update_jobs
<monitor.Monitor instance at 0x9befdac>: printer `cp001' has event 
`printer-state-changed'
Next notifications fetch in 60s
...

However, the %CPU of the cupsd doesn't rise greatly as it did before.
Though I never see the GUI display of printers, which is weird!

I'd like to know where the '60s' interval comes from - is it hard-wired 
in the code, or something configurable in CUPS?

[Tim Waugh]

On Wed, 2010-10-20 at 17:58 +0100, John A. Murdie wrote:
> However, the %CPU of the cupsd doesn't rise greatly as it did before.
> Though I never see the GUI display of printers, which is weird!

You don't see any printer icons?
> I'd like to know where the '60s' interval comes from - is it hard-wired 
> in the code, or something configurable in CUPS?

It is set by CUPS, although I think clients (such as
system-config-printer) can specify how frequently they would like to
connect when they create subscriptions.

Tim.
*/

[John A. Murdie]

On 20/10/10 18:25, Tim Waugh wrote:
> On Wed, 2010-10-20 at 17:58 +0100, John A. Murdie wrote:
> > However, the %CPU of the cupsd doesn't rise greatly as it did before.
> > Though I never see the GUI display of printers, which is weird!
>
> You don't see any printer icons?

No, no printer icon window appears.

[Tim Waugh]

On Wed, 2010-10-20 at 21:19 +0100, John A. Murdie wrote:
> No, no printer icon window appears.

Ah, it's because it is the applet we're debugging.  All that does is
register (and initially, hide) a status icon.  So that's expected.

Seems like it's solved?  Thanks for helping to pinpoint it.

Tim.
*/

[John A. Murdie]

On 21/10/10 10:54, Tim Waugh wrote:
> On Wed, 2010-10-20 at 21:19 +0100, John A. Murdie wrote:
> > No, no printer icon window appears.
>
> Ah, it's because it is the applet we're debugging.  All that does is
> register (and initially, hide) a status icon.  So that's expected.
>
> Seems like it's solved?  Thanks for helping to pinpoint it.
>
> Tim.
> */

Yes, solved, I think. By the way - the version we have is 1.2.2; I 
didn't think to do a 'Help' -> 'About' until later!

Oddly, we have seen similar behaviour (but apparently with a different 
cause) from gnome-cups-manager.

Many thanks for your assistance.