[cups.general] (1.5.4) cupsd dies while trying to display a list of completed jobs

[Alex Korobkin]

Actually, my MaxJobs and MaxJobsPerPrinter parameters are set to 750 and
75.
Maybe I should lower this, but CUPS shouldn't really die if it cannot
process them fast enough.

On 18 October 2012 17:29, Alex Korobkin <korobkin+cups at gmail.com> wrote:

> Hi team,
>
> I've recently updated my Ubuntu 10.04 print server to CUPS 1.5.4 and
> encountered this problem:
>
> When i try to get a list of completed jobs via web-interface (Jobs > Show
> Completed Jobs), server prints page header, waits for about a minute, then
> displays nothing below the header.
>
> With help of *top* I see that as soon as i hit "Show Completed Jobs"
> button, CUPS starts to use 100% of CPU, then gets killed and respawned with
> a new PID. *error_log* shows that CUPS receives job listing request,
> finds out it needs to process 749 completed jobs from 53 printers, reads
> their attributes one by one, and then suddenly dies as if something has
> killed it.
>
> Is there an internal timeout (60 sec?) that would kill cupsd in this
> situation?
> Is there a way to make CUPS process these jobs page by page in order to
> reply faster, instead of going through all those completed jobs?
>
> Here is an excerpt from the error_log (debug2):
>
> == Server starts:
> I [18/Oct/2012:19:47:52 +0000] Resuming new connection processing...
> <snip>
> D [18/Oct/2012:19:47:52 +0000] cupsdSetBusyState: newbusy="Not busy",
> busy="Not busy"
> <snip>
> D [18/Oct/2012:19:47:52 +0000] Discarding unused server-started event...
> <snip>
> D [18/Oct/2012:19:47:52 +0000] Report: clients=1
> D [18/Oct/2012:19:47:52 +0000] Report: jobs=749
> D [18/Oct/2012:19:47:52 +0000] Report: jobs-active=0
> D [18/Oct/2012:19:47:52 +0000] Report: printers=53
> D [18/Oct/2012:19:47:52 +0000] Report: printers-implicit=0
> D [18/Oct/2012:19:47:52 +0000] Report: stringpool-string-count=648288
> D [18/Oct/2012:19:47:52 +0000] Report: stringpool-alloc-bytes=39360
> D [18/Oct/2012:19:47:52 +0000] Report: stringpool-total-bytes=11849752
> <snip>
>
> == Server tries to create a report on completed jobs:
> d [18/Oct/2012:19:49:48 +0000] get_jobs: job->id=167215,
> dest="james-color", username="johndoe", state_value=9, attrs=(nil)
> D [18/Oct/2012:19:49:48 +0000] [Job 167215] Loading attributes...
> d [18/Oct/2012:19:49:48 +0000] cupsdCheckGroup(username="anonymous",
> user=(nil), groupname="OWNER")
> d [18/Oct/2012:19:49:48 +0000] get_md5_password(username="anonymous",
> group="OWNER", passwd=0x7fff8fb6d3b0)
> d [18/Oct/2012:19:49:48 +0000] cupsdCheckGroup(username="anonymous",
> user=(nil), groupname="root")
> d [18/Oct/2012:19:49:48 +0000] get_md5_password(username="anonymous",
> group="root", passwd=0x7fff8fb6d3b0)
> d [18/Oct/2012:19:49:48 +0000] cupsdCheckGroup(username="anonymous",
> user=(nil), groupname="cups-admins")
> d [18/Oct/2012:19:49:48 +0000] get_md5_password(username="anonymous",
> group="cups-admins", passwd=0x7fff8fb6d3b0)
> d [18/Oct/2012:19:49:48 +0000] copy_attrs(to=0x7f0811633380,
> from=0x7f08113dd9b0, ra=0x7f081163dec0, group=2, quickcopy=0)
> d [18/Oct/2012:19:49:48 +0000] copy_attribute(0x7f0811633380,
> 0x7f08113ddcd0[time-at-creation,2,21])
> d [18/Oct/2012:19:49:48 +0000] copy_attribute(0x7f0811633380,
> 0x7f08113ddd10[time-at-processing,2,21])
> d [18/Oct/2012:19:49:48 +0000] copy_attribute(0x7f0811633380,
> 0x7f08113ddd50[time-at-completed,2,21])
> d [18/Oct/2012:19:49:48 +0000] copy_attribute(0x7f0811633380,
> 0x7f08113ddd90[job-id,2,21])
> d [18/Oct/2012:19:49:48 +0000] copy_attribute(0x7f0811633380,
> 0x7f08113dddd0[job-state,2,23])
> d [18/Oct/2012:19:49:48 +0000] copy_attribute(0x7f0811633380,
> 0x7f08113dde10[job-media-sheets-completed,2,21])
> d [18/Oct/2012:19:49:48 +0000] copy_attribute(0x7f0811633380,
> 0x7f08113dde90[job-k-octets,2,21])
> d [18/Oct/2012:19:49:48 +0000] copy_attribute(0x7f0811633380,
> 0x7f08113ddfd0[job-printer-state-message,2,41])
> d [18/Oct/2012:19:49:48 +0000] get_jobs: job->id=167216,
> dest="james-color", username="joesmith", state_value=9, attrs=(nil)
> *D [18/Oct/2012:19:49:48 +0000] [Job 167216] Loading attributes...*
> I [18/Oct/2012:19:49:48 +0000] Remote access is enabled.
> I [18/Oct/2012:19:49:48 +0000] Loaded configuration file
> "/etc/cups/cupsd.conf"
> I [18/Oct/2012:19:49:48 +0000] Using default TempDir of
> /var/spool/cups/tmp...
>
> Highlighted line is where server suddenly dies and restarts. No indication
> why would it die.
>
> Any hints are much appreciated.
> -Alex
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.cups.org/pipermail/cups/attachments/20121018/511e02f2/attachment-0001.html>