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
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?
> 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.
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.
sorry, I do not remember any words of the error message. But I promise never again deleting such a log :)
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)
And I find "client-error-not-found" in redhat-config-printer
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.
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.
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 ?
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).
[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]#
cat printers.conf |grep -v ^#|grep -v "" I'm not surprised that gives no output. Take off '|grep -v ""'.
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.
Just show me what's in the file. :-)
Created attachment 100211 [details] at your wish, Sir! well, only comments as far as I can see
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..)
[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
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?
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.
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]#
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.
Created attachment 100509 [details] error log after about 1 min cups running
Thanks. Can you attach the c00007 file too please?
Created attachment 100531 [details] c00007 as requested, during status "cupsd is stopped"
Thanks. I've identified the problem, and backported a fix from 1.1.20.
Created attachment 100533 [details] cups-devnull.patch Here is the fix I intend to use.
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 ?
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.
Thanks. Florenz is also content. You did a great job for the community and me. Please show this to your manager.
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
Thanks for spotting that. Looks like the commented-out line is no longer there, so I used a patch instead.
Not sure what you mean, but the following line is still in cupsd.conf.in (even in CVS): #MaxLogSize 0
Can I get confirmation that the latest U3-candidate package resolves this issue?
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.
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.
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