Bug 123003 - service cups start fails with signal 25
service cups start fails with signal 25
Status: CLOSED ERRATA
Product: Red Hat Enterprise Linux 3
Classification: Red Hat
Component: cups (Show other bugs)
3.0
i686 Linux
medium Severity medium
: ---
: ---
Assigned To: Tim Waugh
Ben Levenson
:
Depends On:
Blocks: 116727
  Show dependency treegraph
 
Reported: 2004-05-11 04:42 EDT by Thorsten Stärk
Modified: 2007-11-30 17:07 EST (History)
1 user (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2004-09-01 22:10:56 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
at your wish, Sir! (2.68 KB, text/plain)
2004-05-13 09:04 EDT, Thorsten Stärk
no flags Details
error log after about 1 min cups running (32.06 KB, text/plain)
2004-05-24 12:26 EDT, Thorsten Stärk
no flags Details
c00007 as requested, during status "cupsd is stopped" (598 bytes, text/plain)
2004-05-25 04:01 EDT, Thorsten Stärk
no flags Details
cups-devnull.patch (493 bytes, patch)
2004-05-25 06:16 EDT, Tim Waugh
no flags Details | Diff

  None (edit)
Description Thorsten Stärk 2004-05-11 04:42:41 EDT
From Bugzilla Helper:
User-Agent: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.4.2)
Gecko/20040301

Description of problem:
There was no printer access any longer. Starting cups failed with
signal 25. Problem was that size of /var/log/cups/error_log reached 2GB. 

In my opinion, /etc/init.d/cups should check if this limit is reached,
delete the file, and post a message about that to dmesg (as no one
will read 2G of plaintext). That would be user-friendly.

If you are not a developer, the error messages you get from
redhat-config-printer are not leading to a solution.

easyfix

Version-Release number of selected component (if applicable):
cups-1.1.17-13.3.6

How reproducible:
Always

Steps to Reproduce:
1.have /var/log/cups/error_log reached 2GB.
2./etc/init.d/cups restart
    

Actual Results:  failed ... signal 25

Expected Results:  cups should start ([done])

Additional info:

easyfix
Comment 1 Tim Waugh 2004-05-11 04:57:40 EDT
I'm not quite sure how you got into that situation in the first place.
 I don't disagree with you about having a large value for the
MaxLogSize parameter instead of disabling size-based log rotating, but
2Gb is a very large error log and I'd like to understand how it got
that large.

Is the problem that you were out of disk space, or that CUPS cannot
write to files larger than 2Gb? (Or perhaps a filesystem limit?)

The error log is subject to log rotation by the logrotate program, so
the 2Gb must have accumulated within one week.  Was LogLevel set to
debug?  Was there a particular error message responsible for the bulk
of the messages in the error_log file?
Comment 2 Thorsten Stärk 2004-05-11 07:03:59 EDT
> I don't disagree with you about having a large value for the
> MaxLogSize parameter instead of disabling size-based log rotating,

I do not understand, but I think, it is not necessary.

I was not out of disk space, ext2fs cannot really handle filesizes > 2
GB. Signal 25 is thrown when a file exceeds 2Gb.

Yes, the 2GB came together within one week. I deleted the log, one
particular error message reoccurred often, I think, a printer was
failing. And I did not touch the LogLevel.
Comment 3 Tim Waugh 2004-05-11 07:19:27 EDT
So we'll need to set MaxLogSize to some reasonable size below 2Gb to
avoid this problem -- thanks for reporting this, by the way.

Do you happen to remember any of the words from the recurring error
message?  Perhaps that ought to be throttled too.
Comment 4 Thorsten Stärk 2004-05-11 07:26:50 EDT
sorry, I do not remember any words of the error message. But I promise
never again deleting such a log :)
Comment 5 Thorsten Stärk 2004-05-12 07:51:46 EDT
here it is again

E [10/May/2004:19:38:54 +0200] [Job 7] Unable to get printer status
(client-erro
r-not-found)!
E [10/May/2004:19:38:54 +0200] get_jobs: resource name
'/printers/queue1' no goo
d!
E [10/May/2004:19:38:54 +0200] [Job 7] Unable to get printer status
(client-erro
r-not-found)!

(last error msg occurring ca. 1 000 000 times)
Comment 6 Thorsten Stärk 2004-05-12 08:04:19 EDT
And I find  "client-error-not-found" in redhat-config-printer
Comment 7 Tim Waugh 2004-05-12 12:23:07 EDT
Okay.  Looks like that error only happens once every 10 seconds, from
the source code, so it is at least slightly throttled already.

For what it's worth, that looks like you have a queue defined for
something like 'ipp://localhost/printers/queue1' even though there
isn't a 'queue1' queue.
Comment 8 Florenz Kley 2004-05-13 06:14:48 EDT
I noticed my CUPS logs growing faster than usual, so here's it from
the server logs:

the CUPS server received a POST ten times a second, and the error log
shows "get_printer_attrs: resource name '/' no good!". So I guess that
your assumption is correct - the client tries to get info about a
resource that's not there, but retries - however it's seems to be 10
times a second, not once ever 10s.
Comment 9 Thorsten Stärk 2004-05-13 06:23:18 EDT
to the above comment: I am in Florenz' team.

redhat-config-printer says, I have no queue defined, and
/etc/cups/cups.conf does not contain an active line containing ipp.

Where else can I check if I have defined a queue that should be erased ?
Comment 10 Tim Waugh 2004-05-13 08:00:49 EDT
Aha.  This code has changed since Red Hat Enterprse Linux 3 -- in
Fedora Core 2 there is a 'sleep(10)' after that error message, but now
I see that it wasn't there in the version you are using.

To check for what queues you have configured, look in
/etc/cups/printers.conf (or use the web interface at
http://localhost:631).
Comment 11 Thorsten Stärk 2004-05-13 08:17:17 EDT
[root@ls3523 cups]# pwd
/etc/cups
[root@ls3523 cups]# cat printers.conf |grep -v ^#|grep -v ""
[root@ls3523 cups]# service cups status
cupsd (pid 11863) is running...
[root@ls3523 cups]# tail -f /var/log/cups/error_log
I [13/May/2004:14:12:22 +0200] Started backend /usr/lib/cups/backend/
(PID -11899) for job 7.
E [13/May/2004:14:12:32 +0200] PID 11902 stopped with status 22!
I [13/May/2004:14:12:32 +0200] Hint: Try setting the LogLevel to
"debug" to find out more.
I [13/May/2004:14:12:32 +0200] Started backend /usr/lib/cups/backend/
(PID -11902) for job 7.
E [13/May/2004:14:12:42 +0200] PID 11914 stopped with status 22!
I [13/May/2004:14:12:42 +0200] Hint: Try setting the LogLevel to
"debug" to find out more.
I [13/May/2004:14:12:42 +0200] Started backend /usr/lib/cups/backend/
(PID -11914) for job 7.
E [13/May/2004:14:12:52 +0200] PID 11915 stopped with status 22!
I [13/May/2004:14:12:52 +0200] Hint: Try setting the LogLevel to
"debug" to find out more.
I [13/May/2004:14:12:52 +0200] Started backend /usr/lib/cups/backend/
(PID -11915) for job 7.
E [13/May/2004:14:13:02 +0200] PID 11917 stopped with status 22!
I [13/May/2004:14:13:02 +0200] Hint: Try setting the LogLevel to
"debug" to find out more.
I [13/May/2004:14:13:02 +0200] Started backend /usr/lib/cups/backend/
(PID -11917) for job 7.
E [13/May/2004:14:13:12 +0200] PID 11918 stopped with status 22!
I [13/May/2004:14:13:12 +0200] Hint: Try setting the LogLevel to
"debug" to find out more.
I [13/May/2004:14:13:12 +0200] Started backend /usr/lib/cups/backend/
(PID -11918) for job 7.

[root@ls3523 cups]#
Comment 12 Tim Waugh 2004-05-13 08:48:25 EDT
cat printers.conf |grep -v ^#|grep -v ""

I'm not surprised that gives no output.  Take off '|grep -v ""'.
Comment 13 Thorsten Stärk 2004-05-13 08:54:48 EDT
I found that out in the meanwhile. I wanted to do a grep -v "\n".
If I take off '|grep -v ""', it delivers only blank lines.
Comment 14 Tim Waugh 2004-05-13 08:58:42 EDT
Just show me what's in the file. :-)
Comment 15 Thorsten Stärk 2004-05-13 09:04:55 EDT
Created attachment 100211 [details]
at your wish, Sir!

well, only comments as far as I can see
Comment 16 Tim Waugh 2004-05-13 10:03:02 EDT
Thanks.  Now what does 'lpstat -s' say, and what does 'lpstat -o' say?

(I note that the "status 22" messages only occur once every 10
seconds, so it doesn't look like they need further throttling.  But
I'd like to find out what they mean..)
Comment 17 Thorsten Stärk 2004-05-13 10:19:41 EDT
[root@ls3523 root]# service cups start
Starting cups:                                             [  OK  ]
[root@ls3523 root]# lpstat -s
system default destination: lt18
device for lt18: ipp://ls-cups.wdf.sap.corp:631/printers/lt18
device for p080: ipp://ls-cups.wdf.sap.corp:631/printers/p080
device for p802: ipp://ls-cups.wdf.sap.corp:631/printers/p802
device for p893: ipp://ls-cups.wdf.sap.corp:631/printers/p893
device for p958: ipp://ls-cups.wdf.sap.corp:631/printers/p958
device for printer: ipp://ls3523.wdf.sap.corp:631/printers/printer
device for wd3t: ipp://ls-cups.wdf.sap.corp:631/printers/wd3t
device for wd5u: ipp://ls-cups.wdf.sap.corp:631/printers/wd5u
device for wd9b: ipp://ls-cups.wdf.sap.corp:631/printers/wd9b
device for wdbe: ipp://ls-cups.wdf.sap.corp:631/printers/wdbe
[root@ls3523 root]# lpstat -o
printer-7               tstaerk       10083328
[root@ls3523 root]# service cups stop
Comment 18 Tim Waugh 2004-05-24 10:21:45 EDT
I'd really like to see the full debug output when you see this message:

I [13/May/2004:14:13:12 +0200] Started backend /usr/lib/cups/backend/
(PID -11918) for job 7.

Please set the 'LogLevel' line in /etc/cups/cupsd.conf to 'debug2' so
that we can see why this situation happens.  Do you know how to make
it happen on demand?
Comment 19 Thorsten Stärk 2004-05-24 10:46:42 EDT
I can make it happen on demand with service cups start ;-)

here is the cycle at least 2 times:

I [24/May/2004:16:40:59 +0200] Started backend /usr/lib/cups/backend/
(PID -9785) for job 7.
d [24/May/2004:16:40:59 +0200] StartJob: Adding fd 4 to InputSet...
D [24/May/2004:16:40:59 +0200] [Job 7] /usr/lib/cups/backend/: No such
file or directory
D [24/May/2004:16:40:59 +0200] UpdateJob: job 7, file 0 is complete.
d [24/May/2004:16:40:59 +0200] UpdateJob: Removing fd 4 from InputSet...
D [24/May/2004:16:40:59 +0200] StopJob: id = 7, force = 0
D [24/May/2004:16:40:59 +0200] StopJob: printer state is 5
d [24/May/2004:16:40:59 +0200] StopJob: Freeing status buffer...
d [24/May/2004:16:40:59 +0200] UpdateCUPSBrowse: (125 bytes from
127.0.0.1) 301e 3 ipp://ls-cups.wdf.sap.corp:631/printers/wdo2 "WDF03
I5.23" "Lexmark T522" "Lexmark Optra T610, Foomatic + Postscript"
I [24/May/2004:16:40:59 +0200] Added remote printer "wdo2"...
d [24/May/2004:16:40:59 +0200] Adding filter application/vnd.cups-raw
printer/wdo2 0 -
d [24/May/2004:16:41:00 +0200] UpdateCUPSBrowse: (149 bytes from
127.0.0.1) 301e 5 ipp://ls-cups.wdf.sap.corp:631/printers/wdyl "WDF03
I4.17b" "Lexmark Optra W810 (duplex capable)" "Lexmark Optra W810,
Foomatic + Postscript"
I [24/May/2004:16:41:00 +0200] Added remote printer "wdyl"...
d [24/May/2004:16:41:00 +0200] Adding filter application/vnd.cups-raw
printer/wdyl 0 -
D [24/May/2004:16:41:09 +0200] StartJob(7, 0x809fc00)
D [24/May/2004:16:41:09 +0200] StartJob() id = 7, file = 0/1
D [24/May/2004:16:41:09 +0200] StartJob: Sending job to queue tagged
as raw...
D [24/May/2004:16:41:09 +0200] job-sheets=none,none
D [24/May/2004:16:41:09 +0200] banner_page = 0
D [24/May/2004:16:41:09 +0200] StartJob: argv =
"printer","7","tstaerk","(stdin)","1","job-sheets=none,none
job-priority=50 job-hold-until=no-hold","/var/spool/cups/d00007-001"
D [24/May/2004:16:41:09 +0200] StartJob: envp =
"PATH=/usr/lib/cups/filter:/bin:/usr/bin","SOFTWARE=CUPS/1.1","USER=root","CHARSET=iso-8859-1","LANG=en_US","","PPD=/etc/cups/ppd/printer.ppd","CUPS_SERVERROOT=/etc/cups","RIP_MAX_CACHE=8m","TMPDIR=/var/spool/cups/tmp","CONTENT_TYPE=application/postscript","DEVICE_URI=","PRINTER=printer","CUPS_DATADIR=/usr/share/cups","CUPS_FONTPATH=/usr/share/cups/fonts","","",""
d [24/May/2004:16:41:09 +0200] UpdateJob: Allocating status buffer...
D [24/May/2004:16:41:09 +0200] StartJob: statusfds = 4, 5
D [24/May/2004:16:41:09 +0200] StartJob: filterfds[1] = 6, -1
D [24/May/2004:16:41:09 +0200] StartJob: backend =
"/usr/lib/cups/backend/"
D [24/May/2004:16:41:09 +0200] StartJob: filterfds[0] = -1, 7
D [24/May/2004:16:41:09 +0200] start_process("/usr/lib/cups/backend/",
0xbfff8850, 0xbfff7d00, 6, 7, 5)
E [24/May/2004:16:41:09 +0200] PID 9786 stopped with status 22!
I [24/May/2004:16:41:09 +0200] Started backend /usr/lib/cups/backend/
(PID -9786) for job 7.
d [24/May/2004:16:41:09 +0200] StartJob: Adding fd 4 to InputSet...
D [24/May/2004:16:41:09 +0200] [Job 7] /usr/lib/cups/backend/: No such
file or directory
D [24/May/2004:16:41:09 +0200] UpdateJob: job 7, file 0 is complete.
d [24/May/2004:16:41:09 +0200] UpdateJob: Removing fd 4 from InputSet...
D [24/May/2004:16:41:09 +0200] StopJob: id = 7, force = 0
D [24/May/2004:16:41:09 +0200] StopJob: printer state is 5
d [24/May/2004:16:41:09 +0200] StopJob: Freeing status buffer...
D [24/May/2004:16:41:19 +0200] StartJob(7, 0x809fc00)
D [24/May/2004:16:41:19 +0200] StartJob() id = 7, file = 0/1
D [24/May/2004:16:41:19 +0200] StartJob: Sending job to queue tagged
as raw...
D [24/May/2004:16:41:19 +0200] job-sheets=none,none
D [24/May/2004:16:41:19 +0200] banner_page = 0
D [24/May/2004:16:41:19 +0200] StartJob: argv =
"printer","7","tstaerk","(stdin)","1","job-sheets=none,none
job-priority=50 job-hold-until=no-hold","/var/spool/cups/d00007-001"
D [24/May/2004:16:41:19 +0200] StartJob: envp =
"PATH=/usr/lib/cups/filter:/bin:/usr/bin","SOFTWARE=CUPS/1.1","USER=root","CHARSET=iso-8859-1","LANG=en_US","","PPD=/etc/cups/ppd/printer.ppd","CUPS_SERVERROOT=/etc/cups","RIP_MAX_CACHE=8m","TMPDIR=/var/spool/cups/tmp","CONTENT_TYPE=application/postscript","DEVICE_URI=","PRINTER=printer","CUPS_DATADIR=/usr/share/cups","CUPS_FONTPATH=/usr/share/cups/fonts","","",""
d [24/May/2004:16:41:19 +0200] UpdateJob: Allocating status buffer...
D [24/May/2004:16:41:19 +0200] StartJob: statusfds = 4, 5
D [24/May/2004:16:41:19 +0200] StartJob: filterfds[1] = 6, -1
D [24/May/2004:16:41:19 +0200] StartJob: backend =
"/usr/lib/cups/backend/"
D [24/May/2004:16:41:19 +0200] StartJob: filterfds[0] = -1, 7
D [24/May/2004:16:41:19 +0200] start_process("/usr/lib/cups/backend/",
0xbfff8850, 0xbfff7d00, 6, 7, 5)
E [24/May/2004:16:41:19 +0200] PID 9787 stopped with status 22!
I [24/May/2004:16:41:19 +0200] Started backend /usr/lib/cups/backend/
(PID -9787) for job 7.
Comment 20 Thorsten Stärk 2004-05-24 10:50:47 EDT
thanks for working on it, BTW!

additionally:

[root@ls3523 cups]# ll /var/spool/cups/
total 9884
-rw-------    1 lp       sys           605 May 10 19:33 c00002
-rw-------    1 lp       sys           598 May 10 19:33 c00004
-rw-------    1 lp       sys           600 May 10 19:33 c00005
-rw-------    1 lp       sys           598 May 24 16:43 c00007
-rw-r-----    1 lp       sys      10082650 May 10 19:38 d00007-001
drwx-----T    2 lp       sys          4096 Sep  1  2003 tmp
[root@ls3523 cups]# ls /usr/lib/cups/backen*
http  ipp  lpd  ncp  parallel  ptal  scsi  serial  smb  socket  usb
[root@ls3523 cups]#
Comment 21 Tim Waugh 2004-05-24 12:04:24 EDT
I'd really like to see the whole file, from the beginning.  For some
reason it is getting a blank DEVICE_URI for 'printer', and I need to
see why that happens.  Thanks.
Comment 22 Thorsten Stärk 2004-05-24 12:26:47 EDT
Created attachment 100509 [details]
error log after about 1 min cups running
Comment 23 Tim Waugh 2004-05-24 12:41:08 EDT
Thanks.  Can you attach the c00007 file too please?
Comment 24 Thorsten Stärk 2004-05-25 04:01:38 EDT
Created attachment 100531 [details]
c00007 as requested, during status "cupsd is stopped"
Comment 25 Tim Waugh 2004-05-25 06:15:59 EDT
Thanks.  I've identified the problem, and backported a fix from 1.1.20.
Comment 26 Tim Waugh 2004-05-25 06:16:37 EDT
Created attachment 100533 [details]
cups-devnull.patch

Here is the fix I intend to use.
Comment 27 Thorsten Stärk 2004-05-25 07:05:10 EDT
OK, if I understand it correctly, you want to set p->device_uri to
file://dev/null, as only setting p->uri is not enough. I think it is a
code fragment that's only executed if a printer p does not exist and
therefore has to point to null.

OK, enough philosophy, I will look at printers.c later.
So, you patch Fedora and the next release will contain our fix ?

And I have to get the latest cups-sources (please tell me when) and
compile them, right ? Or what else can I do ?
Comment 28 Tim Waugh 2004-05-25 07:26:25 EDT
You understand correctly.  The queue doesn't exist (at least locally,
and hasn't been browsed yet) and so we need to initialize the device
URI to something sane.

The next Fedora Core release will contain both the fixes from this
report (including the log rotation one).

I plan to build the fixes for the next Red Hat Enterprise Linux Update
as well.

(A work around for this problem at the moment is to remove the c00007
file, resubmit the d00007-001 job if needed, and restart cups.)

Thanks for your help in tracking this down.
Comment 29 Thorsten Stärk 2004-05-25 11:09:55 EDT
Thanks. Florenz is also content.
You did a great job for the community and me.
Please show this to your manager.
Comment 30 Robert van den Aker 2004-05-27 15:22:39 EDT
There looks to be a typo in the line that sets the MaxLogSize to 2000000000 in
cups.spec. The specfile I looked at had
perl -pi -e 's,^#(MaxLogSize\s+2000000000),$1,' conf/cupsd.conf.in
I believe that should be
perl -pi -e 's,^#(MaxLogSize)\s+0,$1 2000000000,' conf/cupsd.conf.in
Comment 31 Tim Waugh 2004-05-27 15:39:45 EDT
Thanks for spotting that.  Looks like the commented-out line is no
longer there, so I used a patch instead.
Comment 32 Robert van den Aker 2004-05-27 17:01:02 EDT
Not sure what you mean, but the following line is still in cupsd.conf.in (even
in CVS):
#MaxLogSize 0
Comment 33 Jay Turner 2004-08-18 00:44:40 EDT
Can I get confirmation that the latest U3-candidate package resolves
this issue?
Comment 34 Tim Waugh 2004-08-18 05:56:32 EDT
There are two issues in this bug report:

- Starting cups fails when /var/log/cups/error_log reaches 2GB

The fix for this is to set MaxLogSize to a non-zero file size in
cupsd.conf.  This fix does not seem to be included.  However even if
it were, cupsd.conf is marked as %config(noreplace) and so the fix
would need to be made manually by sysadmins. :-(

Fedora development does contain this fix.

- When starting cups, previously-saved jobs for no-longer-existant
queues are not loaded correctly

This fix is included.  I had tested it myself before comment #26.  The
set-up for testing it is quite involved.
Comment 35 Ben Levenson 2004-08-24 16:53:49 EDT
regarding error_log > 2GB:
# ls -lh error_log
-rw-r--r--    1 lp       sys          2.1G Aug 24 15:33 error_log

# service cups start
Starting cups:                                             [  OK  ]

# service cups status
cupsd (pid 6712) is running...

# ps wax | grep [c]ups
 6712 ?        S      0:00 cupsd

cups starts and printing works as expected, but nothing is logged
to error_log if the size is greater than 2GB.
(NOTE: I was not able to get cups-1.1.17-13.3.6 to fail when 
error_log > 2GB)

The setting for log rotation (MaxLogSize) is the same in old and new
versions:  MaxLogSize 0
If the fix is to make MaxLogSize non-zero, then I'm guessing that we 
should eventually change this.  I understand that the change will not 
help currently installed systems, but I don't see any reason for
not changing the current default behavior.
Comment 36 Jay Turner 2004-09-01 22:10:56 EDT
An errata has been issued which should help the problem 
described in this bug report. This report is therefore being 
closed with a resolution of ERRATA. For more information
on the solution and/or where to find the updated files, 
please follow the link below. You may reopen this bug report 
if the solution does not work for you.

http://rhn.redhat.com/errata/RHBA-2004-228.html

Note You need to log in before you can comment on or make changes to this bug.