I previously uploaded a print attempt with LogLevel set to "debug",
but I am trying to do that again now.
However, the system is behaving oddly. Here is what I did and what I
saw:
1) stop cupsd
/etc/init.d/cupsys stop
2) examine log files
/var/log/cups/error_log was empty - size 0
/var/log/cups/access_log was empty - size 0
3) modify cupsd.conf to set LogLevel to "debug"
NOTE: I used the setting "LogLevel debug"
4) restart cupsd
/etc/init.d/cupsys start
5) examine log files
/var/log/cups/access_log was still empty - size 0
/var/log/cups/error_log contained the following content:
I [11/Mar/2008:11:58:13 -0700] Listening to 127.0.0.1:631 (IPv4)
I [11/Mar/2008:11:58:13 -0700] Listening to /var/run/cups/cups.sock (Domain)
I [11/Mar/2008:11:58:13 -0700] Loaded configuration file "/etc/cups/cupsd.conf"
I [11/Mar/2008:11:58:13 -0700] Using default TempDir of /var/spool/cups/tmp...
I [11/Mar/2008:11:58:13 -0700] Configured for up to 100 clients.
I [11/Mar/2008:11:58:13 -0700] Allowing up to 100 client connections per host.
I [11/Mar/2008:11:58:13 -0700] Using policy "default" as the default!
I [11/Mar/2008:11:58:13 -0700] Full reload is required.
I [11/Mar/2008:11:58:13 -0700] Loaded MIME database from
'/usr/share/cups/mime:/etc/cups': 36 types, 40 filters...
D [11/Mar/2008:11:58:13 -0700] Loading printer Gutenprint_USB_Printer_1...
D [11/Mar/2008:11:58:13 -0700] Loading printer PDF...
D [11/Mar/2008:11:58:13 -0700] cupsdLoadRemoteCache: Not loading remote cache.
I [11/Mar/2008:11:58:13 -0700] Loading job cache file
"/var/cache/cups/job.cache"...
D [11/Mar/2008:11:58:13 -0700] [Job 49] Loading from cache...
D [11/Mar/2008:11:58:13 -0700] [Job 50] Loading from cache...
D [11/Mar/2008:11:58:13 -0700] [Job 51] Loading from cache...
D [11/Mar/2008:11:58:13 -0700] [Job 52] Loading from cache...
D [11/Mar/2008:11:58:13 -0700] [Job 53] Loading from cache...
D [11/Mar/2008:11:58:13 -0700] [Job 54] Loading from cache...
I [11/Mar/2008:11:58:13 -0700] Full reload complete.
I [11/Mar/2008:11:58:13 -0700] Cleaning out old temporary files in
"/var/spool/cups/tmp"...
I [11/Mar/2008:11:58:13 -0700] Listening to 127.0.0.1:631 on fd 3...
I [11/Mar/2008:11:58:13 -0700] Listening to /var/run/cups/cups.sock on fd 4...
I [11/Mar/2008:11:58:13 -0700] Resuming new connection processing...
6) from the command line, try printing a file using lp
$ lp schedule
The file (as simple text file in my home directory) does not print.
7) Examine the log files again
-rw-r--r-- 1 root lp 419 2008-03-11 11:59 access_log
-rw-r--r-- 1 root lp 55010 2008-03-11 12:00 error_log
cat the access_log file:
localhost - - [11/Mar/2008:11:59:49 -0700] "POST / HTTP/1.1" 200 417
CUPS-Get-Classes successful-ok
localhost - - [11/Mar/2008:11:59:49 -0700] "POST
/printers/Gutenprint_USB_Printer_1 HTTP/1.1" 200 4566 Print-Job successful-ok
localhost - - [11/Mar/2008:11:59:51 -0700] "POST / HTTP/1.1" 200 417
CUPS-Get-Classes successful-ok
localhost - - [11/Mar/2008:11:59:51 -0700] "POST / HTTP/1.1" 200 140 Get-Jobs
successful-ok
run ls again:
-rw-r--r-- 1 root lp 419 2008-03-11 11:59 access_log
-rw-r--r-- 1 root lp 602567 2008-03-11 12:00 error_log
OK. The error_log file has gotten huge. Load it into vi and
examine it. Nothing I see makes sense at a glance. Exit vi
and run ls again:
-rw-r--r-- 1 root lp 419 2008-03-11 11:59 access_log
-rw-r--r-- 1 root lp 131568 2008-03-11 12:00 error_log
Huh? I ran vi as a regular user, not as root. Thus I didn't have
write permission to the file and I didn't change anything, but now
the size of the file has dropped vastly. Strange. Load the file
into vi again. This time I note that the early part of the file -
the lines listed above that were put there when cupsd was started -
are gone. Now the file starts with:
D [11/Mar/2008:12:05:44 -0700] [Job 55] cups->header.Duplex = 0
D [11/Mar/2008:12:05:44 -0700] [Job 55] cups->page = 3
D [11/Mar/2008:12:05:44 -0700] [Job 55] cupsPPD = 0x8190f90
D [11/Mar/2008:12:05:44 -0700] [Job 55] cupsPPD->flip_duplex = 0
D [11/Mar/2008:12:05:44 -0700] [Job 55] width = 5940, height = 3960
D [11/Mar/2008:12:05:44 -0700] [Job 55] PageSize = [ 612 792 ], HWResolution =
[ 720 360 ]
D [11/Mar/2008:12:05:44 -0700] [Job 55] HWMargins = [ 9.000 0.000 9.000 0.000 ]
D [11/Mar/2008:12:05:44 -0700] [Job 55] matrix = [ 10.000 0.000 0.000 -5.000
-90.000 3960.000 ]
...
OK. As things are doing strange stuff, I stopped to write
this log of events up. That took several minutes to get all
caught up. Then run ls again:
-rw-r--r-- 1 root lp 419 2008-03-11 11:59 access_log
-rw-r--r-- 1 root lp 257405 2008-03-11 12:05 error_log
The job hasn't been canceled yet, and something is retrying.
Go cancel the print job:
$ lpq
Gutenprint_USB_Printer_1 is ready
Rank Owner Job File(s) Total Size
1st jeffp 55 schedule 5120 bytes
$ cancel 55
$ lpq
Gutenprint_USB_Printer_1 is ready
no entries
Run ls in the cups log directory again:
-rw-r--r-- 1 root lp 1002 2008-03-11 12:13 access_log
-rw-r--r-- 1 root lp 388513 2008-03-11 12:13 error_log
Now access_log contains:
localhost - - [11/Mar/2008:11:59:49 -0700] "POST / HTTP/1.1" 200 417
CUPS-Get-Classes successful-ok
localhost - - [11/Mar/2008:11:59:49 -0700] "POST
/printers/Gutenprint_USB_Printer_1 HTTP/1.1" 200 4566 Print-Job successful-ok
localhost - - [11/Mar/2008:11:59:51 -0700] "POST / HTTP/1.1" 200 417
CUPS-Get-Classes successful-ok
localhost - - [11/Mar/2008:11:59:51 -0700] "POST / HTTP/1.1" 200 140 Get-Jobs
successful-ok
localhost - - [11/Mar/2008:12:13:00 -0700] "POST / HTTP/1.1" 200 417
CUPS-Get-Classes successful-ok
localhost - - [11/Mar/2008:12:13:00 -0700] "POST / HTTP/1.1" 200 140 Get-Jobs
successful-ok
localhost - - [11/Mar/2008:12:13:14 -0700] "POST / HTTP/1.1" 200 417
CUPS-Get-Classes successful-ok
localhost - - [11/Mar/2008:12:13:14 -0700] "POST /jobs/ HTTP/1.1" 200 140
Cancel-Job successful-ok
localhost - - [11/Mar/2008:12:13:17 -0700] "POST / HTTP/1.1" 200 417
CUPS-Get-Classes successful-ok
localhost - - [11/Mar/2008:12:13:17 -0700] "POST / HTTP/1.1" 200 140 Get-Jobs
successful-ok
And the error_log file now ends with the following lines:
D [11/Mar/2008:12:13:14 -0700] cupsdCloseClient: 10
D [11/Mar/2008:12:13:15 -0700] [Job 55] Unloading...
D [11/Mar/2008:12:13:17 -0700] cupsdAcceptClient: 10 from localhost (Domain)
D [11/Mar/2008:12:13:17 -0700] cupsdReadClient: 10 POST / HTTP/1.1
D [11/Mar/2008:12:13:17 -0700] cupsdAuthorize: No authentication data provided.
D [11/Mar/2008:12:13:17 -0700] CUPS-Get-Printers
D [11/Mar/2008:12:13:17 -0700] cupsdProcessIPPRequest: 10 status_code=0
(successful-ok)
D [11/Mar/2008:12:13:17 -0700] cupsdReadClient: 10 POST / HTTP/1.1
D [11/Mar/2008:12:13:17 -0700] cupsdAuthorize: No authentication data provided.
D [11/Mar/2008:12:13:17 -0700] CUPS-Get-Classes
D [11/Mar/2008:12:13:17 -0700] cupsdProcessIPPRequest: 10 status_code=0
(successful-ok)
D [11/Mar/2008:12:13:17 -0700] cupsdReadClient: 10 POST / HTTP/1.1
D [11/Mar/2008:12:13:17 -0700] cupsdAuthorize: No authentication data provided.
D [11/Mar/2008:12:13:17 -0700] CUPS-Get-Default
D [11/Mar/2008:12:13:17 -0700] CUPS-Get-Default client-error-not-found: No
default printer
D [11/Mar/2008:12:13:17 -0700] cupsdProcessIPPRequest: 10 status_code=406
(client-error-not-found)
D [11/Mar/2008:12:13:17 -0700] cupsdReadClient: 10 POST / HTTP/1.1
D [11/Mar/2008:12:13:17 -0700] cupsdAuthorize: No authentication data provided.
D [11/Mar/2008:12:13:17 -0700] Get-Printer-Attributes
ipp://localhost/printers/Gutenprint_USB_Printer_1
D [11/Mar/2008:12:13:17 -0700] cupsdProcessIPPRequest: 10 status_code=0
(successful-ok)
D [11/Mar/2008:12:13:17 -0700] cupsdReadClient: 10 POST / HTTP/1.1
D [11/Mar/2008:12:13:17 -0700] cupsdAuthorize: No authentication data provided.
D [11/Mar/2008:12:13:17 -0700] Get-Jobs
ipp://localhost/printers/Gutenprint_USB_Printer_1
D [11/Mar/2008:12:13:17 -0700] cupsdProcessIPPRequest: 10 status_code=0
(successful-ok)
D [11/Mar/2008:12:13:17 -0700] cupsdCloseClient: 10
Finally, I set LogLevel back to "warning", and restarted cupsd
Here, again, are the lines from cupsd.conf
# Log general information in error_log - change "info" to "debug" for
# troubleshooting...
LogLevel warning
# LogLevel debug
I NEVER used the setting "debug2", and I cannot explain the huge change in
the size of error_log. A full ls of /var/log/cups show:
total 1505
-rw-r--r-- 1 root lp 1002 2008-03-11 12:13 access_log
-rw-r--r-- 1 root lp 129 2008-03-10 16:25 access_log.1.gz
-rw-r--r-- 1 root lp 349 2008-03-09 15:42 access_log.2.gz
-rw-r--r-- 1 root lp 10015 2008-03-08 21:36 access_log.3.gz
-rw-r--r-- 1 root lp 159 2008-03-07 19:43 access_log.4.gz
-rw-r--r-- 1 root lp 117 2008-03-06 16:11 access_log.5.gz
-rw-r--r-- 1 root lp 226 2008-03-05 19:49 access_log.6.gz
-rw-r--r-- 1 root lp 132 2008-03-05 03:07 access_log.7.gz
-rw------- 1 root lpadmin 0 2008-03-08 16:39 cups-pdf_log
-rw-r--r-- 1 root lp 388716 2008-03-11 12:17 error_log
-rw-r--r-- 1 root lp 2114 2008-03-09 09:21 error_log.1.gz
-rw-r--r-- 1 root lp 1098 2008-03-08 21:03 error_log.2.gz
-rw-r----- 1 root lpadmin 395 2008-03-03 13:45 error_log.3.gz
-rw-r----- 1 root lpadmin 97 2008-02-24 14:32 error_log.4.gz
-rw-r----- 1 root lpadmin 95 2008-02-23 16:38 error_log.5.gz
-rw-r--r-- 1 root lp 1014 2008-02-21 22:50 error_log.6.gz
-rw-r--r-- 1 root lp 1048632 2008-03-11 12:11 error_log.O
-rw-r--r-- 1 root lp 711 2008-03-11 12:11 page_log
-rw-r--r-- 1 root lp 245 2008-03-09 09:21 page_log.1.gz
-rw-r--r-- 1 root lp 271 2008-03-08 21:03 page_log.2.gz
-rw-r--r-- 1 root lp 102 2008-03-07 19:43 page_log.3.gz
-rw-r--r-- 1 root lp 125 2008-03-05 08:17 page_log.4.gz
-rw-r--r-- 1 root lp 229 2008-03-03 13:51 page_log.5.gz
-rw-r--r-- 1 root lp 132 2008-03-02 16:30 page_log.6.gz
-rw-r--r-- 1 root lp 103 2008-02-29 07:54 page_log.7.gz
And from that you can see that the most recently archived copy of
error_log was made on 2008-03-09. All of the above testing was done
at about noon on 2008-03-11, so none of the data from the run would
have rolled with the log.
I am attaching the full error_log file as it exists now, though I
expect it won't help any more than the file I attached a couple of
days ago.
--jeffp
** Attachment added: "error_log"
http://launchpadlibrarian.net/12585958/error_log
--
cannot print on Epson stylus C80 after 7.04 to 7.10 upgrade
https://bugs.launchpad.net/bugs/200060
You received this bug notification because you are a member of Ubuntu
Bugs, which is subscribed to Ubuntu.
--
ubuntu-bugs mailing list
ubuntu-bugs@lists.ubuntu.com
https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
