CUPS: Printer always waits for more data, and finally times out.

fsavigny · 2014-02-16 13:18:12

I apologise if this should be categorised as" system administration" rather than "installation". The reason why I chose this category was that the error happened right after installing and setting up cups, so it should not have to do with fine-tuning or be the result of a particularly specific situation.

I have had a novel kind of problem with printing since I first installed Arch Linux:

Whenever I print - regardless of application -, my OKI 431 printer will always wait for more data after having completed the print job (as shown in its small display, where it keeps saying 'DATA' even after the last printed page has come out). After 25 to 30 seconds of such waiting, it will print out two pages, the first one empty, the second one saying:

ERROR:
timeout
OFFENDING COMMAND:
timeout
STACK:

The printer display then goes back to saying 'ONLINE'. If I print several documents WITHIN this 25 to 30 sec delay, i.e. in fast succession, I only get the two pages once, i.e. after the last of these jobs has been printed.

What seems to be related to that is the status message on the "Printers" page of CUPS' Web interface: It says

Idle - "Sending data to printer."

all the time, even though I am not printing anything. (And this was the same before the update.)

Printing is otherwise completely fine - the one practical problem is I have an ever-growing pile of empty pages mixed with pages containing the above error message next to my printer, i.e. two extra pages after each printout. (The one workaround I have found so far is quickly switching off the printer after within the 25 - 30 secs time window.) I have tried to google this problem with various search term combinations, but have not been able to find pages specific to this problem anywhere.

What I have tried out was wiping the /etc/cups directory, updating cups, adding the printer again using lpadmin, and setting it as the default printer with lpoptions (both as explained in the Arch Wiki page). This has not changed anything relevant about the behaviour.

(The one effect this has had is that pointing some browsers (Opera, Dillo) to localhost:631 now gets a "Bad request" response from CUPS, but on most browsers (Mozilla, Qupzilla, Midori, Google Chrome, Lynx) it gets the normal Web interface. But this is probably not related to the problem.)

I will try to give some basic context:

> uname -a
Linux bertrandrussell 3.12.9-2-ARCH #1 SMP PREEMPT Fri Jan 31 10:22:54 CET 2014 x86_64 GNU/Linux

> pacman -Qi cups
Version              : 1.7.1-3
...

> cat /etc/cups/printers.conf
# Printer configuration file for CUPS v1.7.1
# Written by cupsd on 2014-02-16 12:24
# DO NOT EDIT THIS FILE WHEN CUPSD IS RUNNING
<Printer OKI>
UUID urn:uuid:6414e199-9c1c-3330-4b66-5311b2bff8e8
Info OKI
MakeModel OKI DATA CORP B431(PS)
DeviceURI usb://OKI%20DATA%20CORP/B431?serial=AK17008654
State Idle
StateTime 1392549811
Type 8425556
Accepting Yes
Shared Yes
JobSheets none none
QuotaPeriod 0
PageLimit 0
KLimit 0
OpPolicy default
ErrorPolicy abort-job
</Printer>

Can anybody help me on where to start looking?

Thank you very much for any help!

Florian

Rexilion · 2014-02-17 12:01:44

Go to 127.0.0.1:631/admin

Tick: 'Save debugging information for troubleshooting'

Save and then reboot. Reproduce the bug, and then goto 127.0.0.1:631/admin again. Post the output of the Access, Page and Error log.

fsavigny · 2014-02-19 19:03:14

Hi Rexilion,

thank you for your reply.

I have done as you have instructed me, and I have trimmed down the error_log file to what was logged after switching the computer on again. I have also inserted a long, dashed line at the moment where I printed the document. (Yes, result was the same: Printing the document was flawless; and 30 seconds later ... see above.)

However, even after trimming, error_log is still 2,720 lines long (about 404 k).

The other two files do not seem to be interesting: page_log simply contains one new line - the name of the file I printed -, and access_log contains a few new HTTP commands, which I am posting here directly, and two of which seem to be caused by my looking at the logs via the web interface:

localhost - - [19/Feb/2014:19:07:08 +0100] "GET /admin/log/access_log HTTP/1.1" 200 60659 - -
localhost - - [19/Feb/2014:19:08:02 +0100] "GET /admin/log/page_log HTTP/1.1" 200 72483 - -
localhost - - [19/Feb/2014:19:15:25 +0100] "POST /printers/OKI HTTP/1.1" 200 240 Create-Job successful-ok
localhost - - [19/Feb/2014:19:15:25 +0100] "POST /printers/OKI HTTP/1.1" 200 30592 Send-Document successful-ok
localhost - - [19/Feb/2014:19:17:02 +0100] "GET /admin/log/error_log HTTP/1.1" 200 1048586 - -
localhost - - [19/Feb/2014:19:28:29 +0100] "GET /admin/log/page_log HTTP/1.1" 200 72586 - -

But what am I going to do with the huge amount of logging in error_log (which is probably what is interesting)? Is there any facility, or the possibility of making it available as a zip file, perhaps?

(I HAVE noticed that a sticky post in the newbie forum specifically asks me to post complete logs, and I am of course perfectly willing to do that if I am wrong in assuming that only what was blogged after I had rebooted the computer actually does matter. For the moment, I am just trying to reduce the noise. And is it really a good idea to post such long files?)

Thank you very much again!

Florian

Rexilion · 2014-02-20 07:36:18

You could use services like pastebin.com for this.

I think it's also safe to use the wrapper in this forum as this will trim the log for you.

fsavigny · 2014-02-22 17:31:32

It seems I have lost my first error_log, but I have produced a fresh one. It contains precisely what was logged since the reboot (albeit not the marker of when exactly I printed the document):

I'll try the wrapper - here goes:

I [22/Feb/2014:18:13:07 +0100] Listening to [v1.::1]:631 (IPv6)
I [22/Feb/2014:18:13:07 +0100] Listening to 127.0.0.1:631 (IPv4)
I [22/Feb/2014:18:13:07 +0100] Listening to /run/cups/cups.sock (Domain)
I [22/Feb/2014:18:13:07 +0100] Remote access is disabled.
D [22/Feb/2014:18:13:07 +0100] Added auto ServerAlias bertrandrussell
I [22/Feb/2014:18:13:07 +0100] Loaded configuration file "/etc/cups/cupsd.conf"
D [22/Feb/2014:18:13:07 +0100] Repairing ownership of "/run/cups"
D [22/Feb/2014:18:13:07 +0100] Creating missing directory "/run/cups/certs"
D [22/Feb/2014:18:13:07 +0100] Repairing ownership of "/run/cups/certs"
D [22/Feb/2014:18:13:07 +0100] Repairing access permissions of "/run/cups/certs"
I [22/Feb/2014:18:13:07 +0100] Using default TempDir of /var/spool/cups/tmp...
I [22/Feb/2014:18:13:07 +0100] Configured for up to 100 clients.
I [22/Feb/2014:18:13:07 +0100] Allowing up to 100 client connections per host.
I [22/Feb/2014:18:13:07 +0100] Using policy "default" as the default.
I [22/Feb/2014:18:13:07 +0100] Full reload is required.
I [22/Feb/2014:18:13:07 +0100] Loaded MIME database from "/usr/share/cups/mime" and "/etc/cups": 39 types, 52 filters...
D [22/Feb/2014:18:13:07 +0100] Loading printer OKI...
D [22/Feb/2014:18:13:07 +0100] load_ppd: Loading /var/cache/cups/OKI.data...
D [22/Feb/2014:18:13:07 +0100] cupsdRegisterPrinter(p=0x7fa99aa6d130(OKI))
I [22/Feb/2014:18:13:07 +0100] Loading job cache file "/var/cache/cups/job.cache"...
D [22/Feb/2014:18:13:07 +0100] [Job 1] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 2] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 3] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 4] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 5] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 6] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 7] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 8] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 9] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 10] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 11] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 12] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 13] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 14] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 15] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 16] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 17] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 18] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 19] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 20] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 21] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 22] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 23] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 24] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 25] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 26] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 27] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 28] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 29] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 30] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 31] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 32] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 33] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 34] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 35] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 36] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 37] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 38] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 39] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 40] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 41] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 42] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 43] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 44] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 45] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 46] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 47] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 48] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 49] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 50] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 51] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 52] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 53] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 54] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 55] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 56] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 57] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 58] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 59] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 60] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 61] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 62] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 63] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 64] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 65] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 66] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 67] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 68] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 69] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 70] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 71] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 72] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 73] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 74] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 75] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 76] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 77] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 78] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 79] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 80] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 81] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 82] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 83] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 84] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 85] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 86] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 87] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 88] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 89] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 90] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 91] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 92] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 93] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 94] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 95] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 96] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 97] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 98] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 99] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 100] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 101] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 102] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 103] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 104] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 105] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 106] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 107] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 108] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 109] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 110] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 111] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 112] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 113] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 114] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 115] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 116] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 117] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 118] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 119] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 120] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 121] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 122] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 123] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 124] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 125] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 126] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 127] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 128] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 129] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 130] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 131] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 132] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 133] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 134] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 135] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 136] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 137] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 138] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 139] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 140] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 141] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 142] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 143] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 144] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 145] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 146] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 147] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 148] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 149] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 150] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 151] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 152] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 153] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 154] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 155] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 156] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 157] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 158] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 159] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 160] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 161] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 162] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 163] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 164] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 165] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 166] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 167] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 168] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 169] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 170] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 171] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 172] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 173] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 174] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 175] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 176] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 177] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 178] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 179] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 180] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 181] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 182] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 183] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 184] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 185] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 186] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 187] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 188] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 189] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 190] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 191] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 192] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 193] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 194] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 195] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 196] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 197] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 198] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 199] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 200] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 201] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 202] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 203] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 204] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 205] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 206] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 207] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 208] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 209] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 210] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 211] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 212] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 213] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 214] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 215] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 216] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 217] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 218] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 219] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 220] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 221] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 222] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 223] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 224] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 225] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 226] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 227] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 228] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 229] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 230] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 231] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 232] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 233] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 234] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 235] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 236] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 237] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 238] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 239] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 240] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 241] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 242] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 243] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 244] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 245] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 246] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 247] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 248] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 249] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 250] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 251] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 252] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 253] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 254] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 255] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 256] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 257] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 258] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 259] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 260] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 261] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 262] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 263] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 264] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 265] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 266] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 267] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 268] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 269] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 270] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 271] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 272] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 273] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 274] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 275] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 276] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 277] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 278] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 279] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 280] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 281] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 282] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 283] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 284] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 285] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 286] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 287] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 288] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 289] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 290] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 291] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 292] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 293] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 294] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 295] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 296] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 297] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 298] Loading from cache...
D [22/Feb/2014:18:13:07 +0100] [Job 299] Loading from cache...
I [22/Feb/2014:18:13:07 +0100] Full reload complete.
D [22/Feb/2014:18:13:07 +0100] cupsdCleanFiles(path="/var/spool/cups/tmp", pattern="(null)")
I [22/Feb/2014:18:13:07 +0100] Cleaning out old files in "/var/spool/cups/tmp".
D [22/Feb/2014:18:13:07 +0100] cupsdCleanFiles(path="/var/cache/cups", pattern="*.ipp")
I [22/Feb/2014:18:13:07 +0100] Cleaning out old files in "/var/cache/cups".
D [22/Feb/2014:18:13:07 +0100] systemd_checkin: Matched existing listener /run/cups/cups.sock with fd 3...
D [22/Feb/2014:18:13:07 +0100] systemd_checkin: Adding new listener [v1.::] with fd 4...
D [22/Feb/2014:18:13:07 +0100] Calling FindDeviceById(cups-OKI)
D [22/Feb/2014:18:13:08 +0100] FindDeviceById failed: org.freedesktop.ColorManager.NotFound:device id 'cups-OKI' does not exist
D [22/Feb/2014:18:13:08 +0100] Using profile ID "OKI-Gray..".
D [22/Feb/2014:18:13:08 +0100] Calling CreateProfile(OKI-Gray..,temp)
D [22/Feb/2014:18:13:09 +0100] Created profile "/org/freedesktop/ColorManager/profiles/OKI_Gray__".
I [22/Feb/2014:18:13:09 +0100] Registering ICC color profiles for "OKI".
D [22/Feb/2014:18:13:09 +0100] Calling CreateDevice(cups-OKI,temp)
D [22/Feb/2014:18:13:09 +0100] Created device "/org/freedesktop/ColorManager/devices/cups_OKI".
D [22/Feb/2014:18:13:09 +0100] Calling /org/freedesktop/ColorManager/devices/cups_OKI:AddProfile(/org/freedesktop/ColorManager/profiles/OKI_Gray__) [soft]
E [22/Feb/2014:18:13:09 +0100] Unable to bind socket for address [v1.::1]:631 - Address already in use.
E [22/Feb/2014:18:13:09 +0100] Unable to bind socket for address 127.0.0.1:631 - Address already in use.
I [22/Feb/2014:18:13:09 +0100] Listening to /run/cups/cups.sock:631 on fd 3...
I [22/Feb/2014:18:13:09 +0100] Listening to [v1.::]:631 on fd 4...
I [22/Feb/2014:18:13:09 +0100] Resuming new connection processing...
D [22/Feb/2014:18:13:09 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [22/Feb/2014:18:13:09 +0100] Discarding unused server-started event...
D [22/Feb/2014:18:13:10 +0100] Report: clients=0
D [22/Feb/2014:18:13:10 +0100] Report: jobs=299
D [22/Feb/2014:18:13:10 +0100] Report: jobs-active=0
D [22/Feb/2014:18:13:10 +0100] Report: printers=1
D [22/Feb/2014:18:13:10 +0100] Report: stringpool-string-count=1578
D [22/Feb/2014:18:13:10 +0100] Report: stringpool-alloc-bytes=8880
D [22/Feb/2014:18:13:10 +0100] Report: stringpool-total-bytes=27352
D [22/Feb/2014:18:13:56 +0100] [Client 13] Accepted from localhost:631 (IPv6)
D [22/Feb/2014:18:13:56 +0100] [Client 13] Waiting for request.
D [22/Feb/2014:18:13:59 +0100] [Client 13] GET / HTTP/1.1
D [22/Feb/2014:18:13:59 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [22/Feb/2014:18:13:59 +0100] [Client 13] No authentication data provided.
D [22/Feb/2014:18:13:59 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [22/Feb/2014:18:13:59 +0100] [Client 13] GET /cups.css HTTP/1.1
D [22/Feb/2014:18:13:59 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [22/Feb/2014:18:13:59 +0100] [Client 13] No authentication data provided.
D [22/Feb/2014:18:13:59 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [22/Feb/2014:18:13:59 +0100] [Client 13] GET /images/left.gif HTTP/1.1
D [22/Feb/2014:18:13:59 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [22/Feb/2014:18:13:59 +0100] [Client 13] No authentication data provided.
D [22/Feb/2014:18:13:59 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [22/Feb/2014:18:13:59 +0100] [Client 14] Accepted from localhost:631 (IPv6)
D [22/Feb/2014:18:13:59 +0100] [Client 14] Waiting for request.
D [22/Feb/2014:18:13:59 +0100] [Client 15] Accepted from localhost:631 (IPv6)
D [22/Feb/2014:18:13:59 +0100] [Client 15] Waiting for request.
D [22/Feb/2014:18:13:59 +0100] [Client 14] GET /images/right.gif HTTP/1.1
D [22/Feb/2014:18:13:59 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [22/Feb/2014:18:13:59 +0100] [Client 14] No authentication data provided.
D [22/Feb/2014:18:13:59 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [22/Feb/2014:18:13:59 +0100] [Client 16] Accepted from localhost:631 (IPv6)
D [22/Feb/2014:18:13:59 +0100] [Client 16] Waiting for request.
D [22/Feb/2014:18:13:59 +0100] [Client 15] GET /images/cups-icon.png HTTP/1.1
D [22/Feb/2014:18:13:59 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [22/Feb/2014:18:13:59 +0100] [Client 15] No authentication data provided.
D [22/Feb/2014:18:13:59 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [22/Feb/2014:18:13:59 +0100] [Client 16] GET /images/sel.gif HTTP/1.1
D [22/Feb/2014:18:13:59 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [22/Feb/2014:18:13:59 +0100] [Client 16] No authentication data provided.
D [22/Feb/2014:18:13:59 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [22/Feb/2014:18:13:59 +0100] [Client 13] GET /images/unsel.gif HTTP/1.1
D [22/Feb/2014:18:13:59 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [22/Feb/2014:18:13:59 +0100] [Client 13] No authentication data provided.
D [22/Feb/2014:18:13:59 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [22/Feb/2014:18:14:02 +0100] [Client 14] GET /printers/ HTTP/1.1
D [22/Feb/2014:18:14:02 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [22/Feb/2014:18:14:02 +0100] [Client 14] No authentication data provided.
D [22/Feb/2014:18:14:02 +0100] [CGI] argv[0] = "/usr/lib/cups/cgi-bin/printers.cgi"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[0] = "CUPS_CACHEDIR=/var/cache/cups"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[1] = "CUPS_DATADIR=/usr/share/cups"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[2] = "CUPS_DOCROOT=/usr/share/cups/doc"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[3] = "CUPS_FONTPATH=/usr/share/cups/fonts"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[4] = "CUPS_REQUESTROOT=/var/spool/cups"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[5] = "CUPS_SERVERBIN=/usr/lib/cups"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[6] = "CUPS_SERVERROOT=/etc/cups"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[7] = "CUPS_STATEDIR=/run/cups"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[8] = "HOME=/var/spool/cups/tmp"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[9] = "PATH=/usr/lib/cups/filter:/usr/bin:/usr/bin:/bin:/usr/bin"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[10] = "SERVER_ADMIN=root@bertrandrussell"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[11] = "SOFTWARE=CUPS/1.7.1"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[12] = "TMPDIR=/var/spool/cups/tmp"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[13] = "USER=root"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[14] = "CUPS_MAX_MESSAGE=2047"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[15] = "CUPS_SERVER=/run/cups/cups.sock"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[16] = "CUPS_ENCRYPTION=IfRequested"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[17] = "IPP_PORT=631"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[18] = "LANG=en_US.UTF8"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[19] = "REDIRECT_STATUS=1"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[20] = "GATEWAY_INTERFACE=CGI/1.1"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[21] = "SERVER_NAME=localhost"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[22] = "SERVER_PORT=631"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[23] = "REMOTE_ADDR=[v1.::1]"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[24] = "REMOTE_HOST=localhost"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[25] = "SCRIPT_NAME=/printers/"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[26] = "SCRIPT_FILENAME=/usr/share/cups/doc/printers/"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[27] = "SERVER_PROTOCOL=HTTP/1.1"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[28] = "HTTP_USER_AGENT=Mozilla/5.0 (X11; Linux x86_64; rv:27.0) Gecko/20100101 Firefox/27.0"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[29] = "HTTP_REFERER=http://localhost:631/"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[30] = "REQUEST_METHOD=GET"
D [22/Feb/2014:18:14:02 +0100] [CGI] envp[31] = "QUERY_STRING="
D [22/Feb/2014:18:14:02 +0100] [CGI] Started /usr/lib/cups/cgi-bin/printers.cgi (PID 668)
I [22/Feb/2014:18:14:02 +0100] [Client 14] Started "/usr/lib/cups/cgi-bin/printers.cgi" (pid=668)
D [22/Feb/2014:18:14:02 +0100] [Client 14] file=17
D [22/Feb/2014:18:14:02 +0100] [Client 14] Waiting for CGI data.
D [22/Feb/2014:18:14:02 +0100] [CGI] org.cups.sid cookie not found, initializing!
D [22/Feb/2014:18:14:02 +0100] [CGI] org.cups.sid cookie is "4d43abea28d1837cbb1175a07cd5bb45"
D [22/Feb/2014:18:14:02 +0100] [CGI] cgiSetVariable: SECTION="printers"
D [22/Feb/2014:18:14:02 +0100] [CGI] cgiSetVariable: REFRESH_PAGE=""
D [22/Feb/2014:18:14:02 +0100] [Client 18] Accepted from localhost (Domain)
D [22/Feb/2014:18:14:02 +0100] [Client 18] Waiting for request.
D [22/Feb/2014:18:14:02 +0100] [Client 18] POST / HTTP/1.1
D [22/Feb/2014:18:14:02 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [22/Feb/2014:18:14:02 +0100] [Client 18] No authentication data provided.
D [22/Feb/2014:18:14:02 +0100] [Client 18] 2.0 CUPS-Get-Default 1
D [22/Feb/2014:18:14:02 +0100] CUPS-Get-Default
D [22/Feb/2014:18:14:02 +0100] CUPS-Get-Default client-error-not-found: No default printer.
D [22/Feb/2014:18:14:02 +0100] [Client 18] Returning IPP client-error-not-found for CUPS-Get-Default (no URI) from localhost
D [22/Feb/2014:18:14:02 +0100] [Client 18] Content-Length: 113
D [22/Feb/2014:18:14:02 +0100] [Client 18] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=113, response=0x7fa99aaad580(IPP_IDLE), pipe_pid=0, file=-1
D [22/Feb/2014:18:14:02 +0100] [Client 18] Writing IPP response, ipp_state=DATA, old wused=0, new wused=0
D [22/Feb/2014:18:14:02 +0100] [Client 18] bytes=0, http_state=0, data_remaining=0
D [22/Feb/2014:18:14:02 +0100] [Client 18] Waiting for request.
D [22/Feb/2014:18:14:02 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [22/Feb/2014:18:14:02 +0100] [CGI] show_all_printers(http=0x7f1162e63260, user="(null)")
D [22/Feb/2014:18:14:02 +0100] [CGI] cgiSetVariable: TITLE="Printers"
D [22/Feb/2014:18:14:02 +0100] [CGI] cgiSetVariable: SERVER_NAME="localhost"
D [22/Feb/2014:18:14:02 +0100] [CGI] cgiSetVariable: CUPS_VERSION="CUPS v1.7.1"
D [22/Feb/2014:18:14:02 +0100] [Client 14] CGI data ready to be sent.
D [22/Feb/2014:18:14:02 +0100] [Client 14] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, response=(nil)(), pipe_pid=668, file=17
D [22/Feb/2014:18:14:02 +0100] [Client 14] Waiting for CGI data.
D [22/Feb/2014:18:14:02 +0100] Script header: Set-Cookie: org.cups.sid=4d43abea28d1837cbb1175a07cd5bb45; path=/;
D [22/Feb/2014:18:14:02 +0100] Script header: Content-Type: text/html;charset=utf-8
D [22/Feb/2014:18:14:02 +0100] Script header: 
D [22/Feb/2014:18:14:02 +0100] [Client 14] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=668, file=17
D [22/Feb/2014:18:14:02 +0100] [Client 14] Waiting for CGI data.
D [22/Feb/2014:18:14:02 +0100] [Client 14] CGI data ready to be sent.
D [22/Feb/2014:18:14:02 +0100] [Client 14] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=668, file=17
D [22/Feb/2014:18:14:02 +0100] [Client 14] Waiting for CGI data.
D [22/Feb/2014:18:14:02 +0100] [Client 14] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=668, file=17
D [22/Feb/2014:18:14:02 +0100] [Client 14] Waiting for CGI data.
D [22/Feb/2014:18:14:02 +0100] [Client 18] POST / HTTP/1.1
D [22/Feb/2014:18:14:02 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [22/Feb/2014:18:14:02 +0100] [Client 18] No authentication data provided.
D [22/Feb/2014:18:14:02 +0100] [Client 18] 2.0 CUPS-Get-Printers 2
D [22/Feb/2014:18:14:02 +0100] CUPS-Get-Printers
D [22/Feb/2014:18:14:02 +0100] [Client 18] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [22/Feb/2014:18:14:02 +0100] [Client 18] Content-Length: 292
D [22/Feb/2014:18:14:02 +0100] [Client 18] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=292, response=0x7fa99aadf780(IPP_IDLE), pipe_pid=0, file=-1
D [22/Feb/2014:18:14:02 +0100] [Client 18] Writing IPP response, ipp_state=DATA, old wused=0, new wused=0
D [22/Feb/2014:18:14:02 +0100] [Client 18] bytes=0, http_state=0, data_remaining=0
D [22/Feb/2014:18:14:02 +0100] [Client 18] Waiting for request.
D [22/Feb/2014:18:14:02 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [22/Feb/2014:18:14:02 +0100] [CGI] cgiSetVariable: TOTAL="1"
D [22/Feb/2014:18:14:02 +0100] [CGI] cgiSetVariable: SERVER_NAME="localhost"
D [22/Feb/2014:18:14:02 +0100] [CGI] cgiSetVariable: CUPS_VERSION="CUPS v1.7.1"
D [22/Feb/2014:18:14:02 +0100] [CGI] cgiSetArray: printer_state[0]="3"
D [22/Feb/2014:18:14:02 +0100] [CGI] cgiSetArray: printer_state_message[0]=""
D [22/Feb/2014:18:14:02 +0100] [CGI] cgiSetArray: admin_uri[0]="/admin/"
D [22/Feb/2014:18:14:02 +0100] [CGI] cgiSetArray: printer_uri_supported[0]="/printers/OKI"
D [22/Feb/2014:18:14:02 +0100] [CGI] cgiSetArray: printer_name[0]="OKI"
D [22/Feb/2014:18:14:02 +0100] [CGI] cgiSetArray: printer_location[0]=""
D [22/Feb/2014:18:14:02 +0100] [CGI] cgiSetArray: printer_info[0]="OKI"
D [22/Feb/2014:18:14:02 +0100] [CGI] cgiSetArray: printer_make_and_model[0]="OKI DATA CORP B431(PS)"
D [22/Feb/2014:18:14:02 +0100] [CGI] cgiSetVariable: THISURL="/printers/"
D [22/Feb/2014:18:14:02 +0100] [Client 14] CGI data ready to be sent.
D [22/Feb/2014:18:14:02 +0100] [Client 14] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=668, file=17
D [22/Feb/2014:18:14:02 +0100] [Client 14] Waiting for CGI data.
D [22/Feb/2014:18:14:02 +0100] [Client 14] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=668, file=17
D [22/Feb/2014:18:14:02 +0100] [Client 14] Waiting for CGI data.
D [22/Feb/2014:18:14:02 +0100] [Client 14] CGI data ready to be sent.
D [22/Feb/2014:18:14:02 +0100] [Client 14] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=668, file=17
D [22/Feb/2014:18:14:02 +0100] [Client 14] Waiting for CGI data.
D [22/Feb/2014:18:14:02 +0100] [Client 14] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=668, file=17
D [22/Feb/2014:18:14:02 +0100] [Client 14] Waiting for CGI data.
D [22/Feb/2014:18:14:02 +0100] [Client 14] CGI data ready to be sent.
D [22/Feb/2014:18:14:02 +0100] [Client 18] HTTP_STATE_WAITING Closing on EOF
D [22/Feb/2014:18:14:02 +0100] [Client 18] Closing connection.
D [22/Feb/2014:18:14:02 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [22/Feb/2014:18:14:02 +0100] [Client 14] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=668, file=17
D [22/Feb/2014:18:14:02 +0100] [Client 14] Waiting for CGI data.
D [22/Feb/2014:18:14:02 +0100] [Client 14] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=668, file=17
D [22/Feb/2014:18:14:02 +0100] [Client 14] Waiting for CGI data.
D [22/Feb/2014:18:14:02 +0100] [Client 14] CGI data ready to be sent.
D [22/Feb/2014:18:14:02 +0100] PID 668 (/usr/lib/cups/cgi-bin/printers.cgi) exited with no errors.
D [22/Feb/2014:18:14:02 +0100] [Client 14] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=668, file=17
D [22/Feb/2014:18:14:02 +0100] [Client 14] Waiting for CGI data.
D [22/Feb/2014:18:14:02 +0100] [Client 14] Waiting for request.
D [22/Feb/2014:18:14:02 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [22/Feb/2014:18:14:21 +0100] [Client 17] Accepted from localhost (Domain)
D [22/Feb/2014:18:14:21 +0100] [Client 17] Waiting for request.
D [22/Feb/2014:18:14:21 +0100] Report: clients=5
D [22/Feb/2014:18:14:21 +0100] Report: jobs=299
D [22/Feb/2014:18:14:21 +0100] Report: jobs-active=0
D [22/Feb/2014:18:14:21 +0100] Report: printers=1
D [22/Feb/2014:18:14:21 +0100] Report: stringpool-string-count=1582
D [22/Feb/2014:18:14:21 +0100] Report: stringpool-alloc-bytes=8904
D [22/Feb/2014:18:14:21 +0100] Report: stringpool-total-bytes=27416
D [22/Feb/2014:18:14:21 +0100] [Client 17] HTTP_STATE_WAITING Closing on EOF
D [22/Feb/2014:18:14:21 +0100] [Client 17] Closing connection.
D [22/Feb/2014:18:14:21 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [22/Feb/2014:18:14:21 +0100] [Client 17] Accepted from localhost (Domain)
D [22/Feb/2014:18:14:21 +0100] [Client 17] Waiting for request.
D [22/Feb/2014:18:14:21 +0100] [Client 17] POST / HTTP/1.1
D [22/Feb/2014:18:14:21 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [22/Feb/2014:18:14:21 +0100] [Client 17] No authentication data provided.
D [22/Feb/2014:18:14:21 +0100] [Client 17] 2.0 CUPS-Get-Printers 1
D [22/Feb/2014:18:14:21 +0100] CUPS-Get-Printers
D [22/Feb/2014:18:14:21 +0100] [Client 17] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [22/Feb/2014:18:14:21 +0100] [Client 17] Content-Length: 1073
D [22/Feb/2014:18:14:21 +0100] [Client 17] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1073, response=0x7fa99aaad7c0(IPP_IDLE), pipe_pid=0, file=-1
D [22/Feb/2014:18:14:21 +0100] [Client 17] Writing IPP response, ipp_state=DATA, old wused=0, new wused=0
D [22/Feb/2014:18:14:21 +0100] [Client 17] bytes=0, http_state=0, data_remaining=0
D [22/Feb/2014:18:14:21 +0100] [Client 17] Waiting for request.
D [22/Feb/2014:18:14:21 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [22/Feb/2014:18:14:21 +0100] [Client 17] POST / HTTP/1.1
D [22/Feb/2014:18:14:21 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [22/Feb/2014:18:14:21 +0100] [Client 17] No authentication data provided.
D [22/Feb/2014:18:14:21 +0100] [Client 17] 2.0 CUPS-Get-Default 2
D [22/Feb/2014:18:14:21 +0100] CUPS-Get-Default
D [22/Feb/2014:18:14:21 +0100] CUPS-Get-Default client-error-not-found: No default printer.
D [22/Feb/2014:18:14:21 +0100] [Client 17] Returning IPP client-error-not-found for CUPS-Get-Default (no URI) from localhost
D [22/Feb/2014:18:14:21 +0100] [Client 17] Content-Length: 113
D [22/Feb/2014:18:14:21 +0100] [Client 17] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=113, response=0x7fa99aae73c0(IPP_IDLE), pipe_pid=0, file=-1
D [22/Feb/2014:18:14:21 +0100] [Client 17] Writing IPP response, ipp_state=DATA, old wused=0, new wused=0
D [22/Feb/2014:18:14:21 +0100] [Client 17] bytes=0, http_state=0, data_remaining=0
D [22/Feb/2014:18:14:21 +0100] [Client 17] Waiting for request.
D [22/Feb/2014:18:14:21 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [22/Feb/2014:18:14:21 +0100] [Client 17] HTTP_STATE_WAITING Closing on EOF
D [22/Feb/2014:18:14:21 +0100] [Client 17] Closing connection.
D [22/Feb/2014:18:14:21 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [22/Feb/2014:18:14:30 +0100] [Client 16] HTTP_STATE_WAITING Closing on EOF
D [22/Feb/2014:18:14:30 +0100] [Client 16] Closing connection.
D [22/Feb/2014:18:14:30 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [22/Feb/2014:18:14:30 +0100] [Client 15] HTTP_STATE_WAITING Closing on EOF
D [22/Feb/2014:18:14:30 +0100] [Client 15] Closing connection.
D [22/Feb/2014:18:14:30 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [22/Feb/2014:18:14:30 +0100] [Client 13] HTTP_STATE_WAITING Closing on EOF
D [22/Feb/2014:18:14:30 +0100] [Client 13] Closing connection.
D [22/Feb/2014:18:14:30 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [22/Feb/2014:18:14:32 +0100] [Client 13] Accepted from localhost (Domain)
D [22/Feb/2014:18:14:32 +0100] [Client 13] Waiting for request.
D [22/Feb/2014:18:14:32 +0100] [Client 13] HTTP_STATE_WAITING Closing on EOF
D [22/Feb/2014:18:14:32 +0100] [Client 13] Closing connection.
D [22/Feb/2014:18:14:32 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [22/Feb/2014:18:14:32 +0100] [Client 13] Accepted from localhost (Domain)
D [22/Feb/2014:18:14:32 +0100] [Client 13] Waiting for request.
D [22/Feb/2014:18:14:32 +0100] [Client 13] POST / HTTP/1.1
D [22/Feb/2014:18:14:32 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [22/Feb/2014:18:14:32 +0100] [Client 13] No authentication data provided.
D [22/Feb/2014:18:14:32 +0100] [Client 13] 2.0 CUPS-Get-Printers 3
D [22/Feb/2014:18:14:32 +0100] CUPS-Get-Printers
D [22/Feb/2014:18:14:32 +0100] [Client 13] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [22/Feb/2014:18:14:32 +0100] [Client 13] Content-Length: 1073
D [22/Feb/2014:18:14:32 +0100] [Client 13] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1073, response=0x7fa99aaad750(IPP_IDLE), pipe_pid=0, file=-1
D [22/Feb/2014:18:14:32 +0100] [Client 13] Writing IPP response, ipp_state=DATA, old wused=0, new wused=0
D [22/Feb/2014:18:14:32 +0100] [Client 13] bytes=0, http_state=0, data_remaining=0
D [22/Feb/2014:18:14:32 +0100] [Client 13] Waiting for request.
D [22/Feb/2014:18:14:32 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [22/Feb/2014:18:14:32 +0100] [Client 13] POST / HTTP/1.1
D [22/Feb/2014:18:14:32 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [22/Feb/2014:18:14:32 +0100] [Client 13] No authentication data provided.
D [22/Feb/2014:18:14:32 +0100] [Client 13] 2.0 CUPS-Get-Default 4
D [22/Feb/2014:18:14:32 +0100] CUPS-Get-Default
D [22/Feb/2014:18:14:32 +0100] CUPS-Get-Default client-error-not-found: No default printer.
D [22/Feb/2014:18:14:32 +0100] [Client 13] Returning IPP client-error-not-found for CUPS-Get-Default (no URI) from localhost
D [22/Feb/2014:18:14:32 +0100] [Client 13] Content-Length: 113
D [22/Feb/2014:18:14:32 +0100] [Client 13] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=113, response=0x7fa99aaad7a0(IPP_IDLE), pipe_pid=0, file=-1
D [22/Feb/2014:18:14:32 +0100] [Client 13] Writing IPP response, ipp_state=DATA, old wused=0, new wused=0
D [22/Feb/2014:18:14:32 +0100] [Client 13] bytes=0, http_state=0, data_remaining=0
D [22/Feb/2014:18:14:32 +0100] [Client 13] Waiting for request.
D [22/Feb/2014:18:14:32 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [22/Feb/2014:18:14:33 +0100] [Client 14] HTTP_STATE_WAITING Closing on EOF
D [22/Feb/2014:18:14:33 +0100] [Client 14] Closing connection.
D [22/Feb/2014:18:14:33 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [22/Feb/2014:18:14:44 +0100] [Client 13] POST /printers/OKI HTTP/1.1
D [22/Feb/2014:18:14:44 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [22/Feb/2014:18:14:44 +0100] [Client 13] No authentication data provided.
D [22/Feb/2014:18:14:44 +0100] [Client 13] 2.0 Create-Job 5
D [22/Feb/2014:18:14:44 +0100] Create-Job ipp://localhost:631/printers/OKI
D [22/Feb/2014:18:14:44 +0100] cupsdMarkDirty(---J-)
D [22/Feb/2014:18:14:44 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients"
D [22/Feb/2014:18:14:44 +0100] add_job: requesting-user-name="lehrer"
D [22/Feb/2014:18:14:44 +0100] Adding default job-sheets values "none,none"...
I [22/Feb/2014:18:14:44 +0100] [Job 300] Adding start banner page "none".
D [22/Feb/2014:18:14:44 +0100] Discarding unused job-created event...
I [22/Feb/2014:18:14:44 +0100] [Job 300] Queued on "OKI" by "lehrer".
D [22/Feb/2014:18:14:44 +0100] [Client 13] Returning IPP successful-ok for Create-Job (ipp://localhost:631/printers/OKI) from localhost
D [22/Feb/2014:18:14:44 +0100] [Client 13] Content-Length: 183
D [22/Feb/2014:18:14:44 +0100] [Client 13] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=183, response=0x7fa99aaad890(IPP_IDLE), pipe_pid=0, file=-1
D [22/Feb/2014:18:14:44 +0100] [Client 13] Writing IPP response, ipp_state=DATA, old wused=0, new wused=0
D [22/Feb/2014:18:14:44 +0100] [Client 13] bytes=0, http_state=0, data_remaining=0
D [22/Feb/2014:18:14:44 +0100] [Client 13] Waiting for request.
D [22/Feb/2014:18:14:44 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [22/Feb/2014:18:14:44 +0100] [Client 13] POST /printers/OKI HTTP/1.1
D [22/Feb/2014:18:14:44 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [22/Feb/2014:18:14:44 +0100] [Client 13] No authentication data provided.
D [22/Feb/2014:18:14:44 +0100] [Client 13] 2.0 Send-Document 6
D [22/Feb/2014:18:14:44 +0100] Send-Document ipp://localhost:631/printers/OKI
D [22/Feb/2014:18:14:44 +0100] cupsdIsAuthorized: requesting-user-name="lehrer"
D [22/Feb/2014:18:14:44 +0100] [Job 300] Auto-typing file...
D [22/Feb/2014:18:14:44 +0100] [Job 300] Request file type is application/pdf.
D [22/Feb/2014:18:14:44 +0100] cupsdMarkDirty(---J-)
D [22/Feb/2014:18:14:44 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
I [22/Feb/2014:18:14:44 +0100] [Job 300] File of type application/pdf queued by "lehrer".
I [22/Feb/2014:18:14:44 +0100] [Job 300] Adding end banner page "none".
D [22/Feb/2014:18:14:44 +0100] cupsdMarkDirty(---J-)
D [22/Feb/2014:18:14:44 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [22/Feb/2014:18:14:44 +0100] [Job 300] time-at-processing=1393089284
D [22/Feb/2014:18:14:44 +0100] cupsdMarkDirty(---J-)
D [22/Feb/2014:18:14:44 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [22/Feb/2014:18:14:44 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [22/Feb/2014:18:14:44 +0100] Discarding unused printer-state-changed event...
D [22/Feb/2014:18:14:44 +0100] [Job 300] 3 filters for job:
D [22/Feb/2014:18:14:44 +0100] [Job 300] pdftopdf (application/pdf to application/vnd.cups-pdf, cost 66)
D [22/Feb/2014:18:14:44 +0100] [Job 300] pdftops (application/vnd.cups-pdf to application/vnd.cups-postscript, cost 100)
D [22/Feb/2014:18:14:44 +0100] [Job 300] - (application/vnd.cups-postscript to printer/OKI, cost 0)
D [22/Feb/2014:18:14:44 +0100] [Job 300] job-sheets=none,none
D [22/Feb/2014:18:14:44 +0100] [Job 300] argv[0]="OKI"
D [22/Feb/2014:18:14:44 +0100] [Job 300] argv[1]="300"
D [22/Feb/2014:18:14:44 +0100] [Job 300] argv[2]="lehrer"
D [22/Feb/2014:18:14:44 +0100] [Job 300] argv[3]="32_noun_clauses"
D [22/Feb/2014:18:14:44 +0100] [Job 300] argv[4]="1"
D [22/Feb/2014:18:14:44 +0100] [Job 300] argv[5]="Duplex=None InputSlot=Upper PageSize=A4 job-uuid=urn:uuid:f6fd7095-afa2-3a84-4db2-7a65f497728a job-originating-host-name=localhost time-at-creation=1393089284 time-at-processing=1393089284"
D [22/Feb/2014:18:14:44 +0100] [Job 300] argv[6]="/var/spool/cups/d00300-001"
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc"
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[7]="CUPS_STATEDIR=/run/cups"
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[8]="HOME=/var/spool/cups/tmp"
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/bin:/bin:/usr/bin"
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[10]="SERVER_ADMIN=root@bertrandrussell"
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[11]="SOFTWARE=CUPS/1.7.1"
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[12]="TMPDIR=/var/spool/cups/tmp"
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[13]="USER=root"
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[14]="CUPS_MAX_MESSAGE=2047"
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[15]="CUPS_SERVER=/run/cups/cups.sock"
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[16]="CUPS_ENCRYPTION=IfRequested"
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[17]="IPP_PORT=631"
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[18]="CHARSET=utf-8"
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[19]="LANG=de_DE.UTF-8"
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[20]="PPD=/etc/cups/ppd/OKI.ppd"
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[21]="RIP_MAX_CACHE=128m"
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[22]="CONTENT_TYPE=application/pdf"
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[23]="DEVICE_URI=usb://OKI%20DATA%20CORP/B431?serial=AK17008654"
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[24]="PRINTER_INFO=OKI"
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[25]="PRINTER_LOCATION="
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[26]="PRINTER=OKI"
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[27]="PRINTER_STATE_REASONS=none"
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[28]="CUPS_FILETYPE=document"
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[29]="FINAL_CONTENT_TYPE=printer/OKI"
D [22/Feb/2014:18:14:44 +0100] [Job 300] envp[30]="AUTH_I****"
I [22/Feb/2014:18:14:44 +0100] [Job 300] Started filter /usr/lib/cups/filter/pdftopdf (PID 703)
I [22/Feb/2014:18:14:44 +0100] [Job 300] Started filter /usr/lib/cups/filter/pdftops (PID 704)
I [22/Feb/2014:18:14:44 +0100] [Job 300] Started backend /usr/lib/cups/backend/usb (PID 705)
D [22/Feb/2014:18:14:44 +0100] Discarding unused job-state-changed event...
D [22/Feb/2014:18:14:44 +0100] [Client 13] Returning IPP successful-ok for Send-Document (ipp://localhost:631/printers/OKI) from localhost
D [22/Feb/2014:18:14:44 +0100] [Client 13] Content-Length: 175
D [22/Feb/2014:18:14:44 +0100] [Client 13] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=175, response=0x7fa99aae6ec0(IPP_IDLE), pipe_pid=0, file=-1
D [22/Feb/2014:18:14:44 +0100] [Client 13] Writing IPP response, ipp_state=DATA, old wused=0, new wused=0
D [22/Feb/2014:18:14:44 +0100] [Client 13] bytes=0, http_state=0, data_remaining=0
D [22/Feb/2014:18:14:44 +0100] [Client 13] Waiting for request.
D [22/Feb/2014:18:14:44 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients and dirty files"
D [22/Feb/2014:18:14:44 +0100] [Job 300] pdftops - copying to temp print file "/var/spool/cups/tmp/002c0530d3451"
D [22/Feb/2014:18:14:44 +0100] [Job 300] Loading USB quirks from "/usr/share/cups/usb".
D [22/Feb/2014:18:14:44 +0100] [Job 300] Loaded 67 quirks.
D [22/Feb/2014:18:14:44 +0100] [Job 300] Printing on printer with URI: usb://OKI%20DATA%20CORP/B431?serial=AK17008654
D [22/Feb/2014:18:14:44 +0100] [Job 300] libusb_get_device_list=12
I [22/Feb/2014:18:14:44 +0100] [Job 300] Waiting for printer to become available.
D [22/Feb/2014:18:14:44 +0100] cupsdMarkDirty(---J-)
D [22/Feb/2014:18:14:44 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [22/Feb/2014:18:14:44 +0100] cupsdMarkDirty(---J-)
D [22/Feb/2014:18:14:44 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [22/Feb/2014:18:14:44 +0100] [Job 300] Set job-printer-state-message to "Waiting for printer to become available.", current level=INFO
D [22/Feb/2014:18:14:44 +0100] Discarding unused job-progress event...
D [22/Feb/2014:18:14:44 +0100] Discarding unused printer-state-changed event...
D [22/Feb/2014:18:14:44 +0100] [Job 300] PID 703 (/usr/lib/cups/filter/pdftopdf) exited with no errors.
D [22/Feb/2014:18:14:44 +0100] [Job 300] Printer make and model: Oki B431
D [22/Feb/2014:18:14:44 +0100] [Job 300] Running command line for pstops: pstops 300 lehrer 32_noun_clauses 1 'Duplex=None InputSlot=Upper PageSize=A4 job-uuid=urn:uuid:f6fd7095-afa2-3a84-4db2-7a65f497728a job-originating-host-name=localhost time-at-creation=1393089284 time-at-processing=1393089284'
D [22/Feb/2014:18:14:44 +0100] [Job 300] Using image rendering resolution 600 dpi
D [22/Feb/2014:18:14:44 +0100] [Job 300] Running command line for gs: gs -q -dNOPAUSE -dBATCH -dSAFER -sDEVICE=ps2write -sOUTPUTFILE=%stdout -dLanguageLevel=3 -r600 -dCompressFonts=false -dNoT3CCITT -dNOINTERPOLATE -c 'save pop' -f /var/spool/cups/tmp/002c0530d3451
D [22/Feb/2014:18:14:44 +0100] [Job 300] Started filter gs (PID 707)
D [22/Feb/2014:18:14:44 +0100] [Job 300] Started filter pstops (PID 708)
D [22/Feb/2014:18:14:45 +0100] [Job 300] Page = 595x842; 13,13 to 582,829
D [22/Feb/2014:18:14:45 +0100] [Job 300] slow_collate=0, slow_duplex=0, slow_order=0
D [22/Feb/2014:18:14:45 +0100] [Job 300] Before copy_comments - %!PS-Adobe-3.0
D [22/Feb/2014:18:14:45 +0100] [Job 300] %!PS-Adobe-3.0
D [22/Feb/2014:18:14:45 +0100] [Job 300] %%BoundingBox: 0 0 595 842
D [22/Feb/2014:18:14:45 +0100] [Job 300] %%HiResBoundingBox: 0 0 595.00 842.00
D [22/Feb/2014:18:14:45 +0100] [Job 300] %%Creator: GPL Ghostscript 910 (ps2write)
D [22/Feb/2014:18:14:45 +0100] [Job 300] %%LanguageLevel: 2
D [22/Feb/2014:18:14:45 +0100] [Job 300] %%CreationDate: D:20140222181445+01'00'
D [22/Feb/2014:18:14:45 +0100] [Job 300] %%Pages: 1
D [22/Feb/2014:18:14:45 +0100] [Job 300] %%EndComments
D [22/Feb/2014:18:14:45 +0100] [Job 300] Before copy_prolog - %%BeginProlog
D [22/Feb/2014:18:14:49 +0100] [Job 300] libusb_get_device_list=12
I [22/Feb/2014:18:14:49 +0100] [Job 300] Waiting for printer to become available.
D [22/Feb/2014:18:14:54 +0100] [Job 300] libusb_get_device_list=12
I [22/Feb/2014:18:14:54 +0100] [Job 300] Waiting for printer to become available.
D [22/Feb/2014:18:14:59 +0100] [Job 300] libusb_get_device_list=12
I [22/Feb/2014:18:14:59 +0100] [Job 300] Waiting for printer to become available.
D [22/Feb/2014:18:15:04 +0100] [Job 300] libusb_get_device_list=12
I [22/Feb/2014:18:15:04 +0100] [Job 300] Waiting for printer to become available.
D [22/Feb/2014:18:15:09 +0100] [Job 300] libusb_get_device_list=13
D [22/Feb/2014:18:15:09 +0100] [Job 300] STATE: +connecting-to-device
D [22/Feb/2014:18:15:09 +0100] cupsdMarkDirty(---J-)
D [22/Feb/2014:18:15:09 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Printing jobs and dirty files"
D [22/Feb/2014:18:15:09 +0100] Discarding unused printer-state-changed event...
D [22/Feb/2014:18:15:09 +0100] [Job 300] STATE: -connecting-to-device
D [22/Feb/2014:18:15:09 +0100] cupsdMarkDirty(---J-)
D [22/Feb/2014:18:15:09 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Dirty files"
D [22/Feb/2014:18:15:09 +0100] Discarding unused printer-state-changed event...
D [22/Feb/2014:18:15:09 +0100] [Job 300] Device protocol: 2
I [22/Feb/2014:18:15:09 +0100] [Job 300] Sending data to printer.
D [22/Feb/2014:18:15:09 +0100] cupsdMarkDirty(---J-)
D [22/Feb/2014:18:15:09 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [22/Feb/2014:18:15:09 +0100] [Job 300] Set job-printer-state-message to "Sending data to printer.", current level=INFO
D [22/Feb/2014:18:15:09 +0100] [Job 300] Read 8192 bytes of print data...
D [22/Feb/2014:18:15:09 +0100] [Job 300] Wrote 8192 bytes of print data...
D [22/Feb/2014:18:15:09 +0100] [Job 300] Read 8192 bytes of print data...
D [22/Feb/2014:18:15:09 +0100] [Job 300] Wrote 8192 bytes of print data...
D [22/Feb/2014:18:15:09 +0100] [Job 300] Read 8192 bytes of print data...
D [22/Feb/2014:18:15:09 +0100] [Job 300] Wrote 8192 bytes of print data...
D [22/Feb/2014:18:15:09 +0100] [Job 300] Read 8192 bytes of print data...
D [22/Feb/2014:18:15:09 +0100] [Job 300] Wrote 8192 bytes of print data...
D [22/Feb/2014:18:15:09 +0100] [Job 300] Read 8192 bytes of print data...
D [22/Feb/2014:18:15:09 +0100] [Job 300] Wrote 8192 bytes of print data...
D [22/Feb/2014:18:15:09 +0100] [Job 300] Read 8192 bytes of print data...
D [22/Feb/2014:18:15:09 +0100] [Job 300] Wrote 8192 bytes of print data...
D [22/Feb/2014:18:15:09 +0100] [Job 300] Read 8192 bytes of print data...
D [22/Feb/2014:18:15:09 +0100] [Job 300] Wrote 8192 bytes of print data...
D [22/Feb/2014:18:15:09 +0100] [Job 300] Read 8192 bytes of print data...
D [22/Feb/2014:18:15:09 +0100] [Job 300] Wrote 8192 bytes of print data...
D [22/Feb/2014:18:15:09 +0100] [Job 300] Read 8192 bytes of print data...
D [22/Feb/2014:18:15:09 +0100] [Job 300] Wrote 8192 bytes of print data...
D [22/Feb/2014:18:15:09 +0100] [Job 300] Read 8192 bytes of print data...
D [22/Feb/2014:18:15:09 +0100] Discarding unused job-progress event...
D [22/Feb/2014:18:15:09 +0100] Discarding unused printer-state-changed event...
D [22/Feb/2014:18:15:10 +0100] [Job 300] Wrote 8192 bytes of print data...
D [22/Feb/2014:18:15:10 +0100] [Job 300] Read 8192 bytes of print data...
D [22/Feb/2014:18:15:10 +0100] [Job 300] Wrote 8192 bytes of print data...
D [22/Feb/2014:18:15:10 +0100] [Job 300] Read 8192 bytes of print data...
D [22/Feb/2014:18:15:10 +0100] [Job 300] PID 707 (gs) exited with no errors.
D [22/Feb/2014:18:15:10 +0100] [Job 300] Wrote 8192 bytes of print data...
D [22/Feb/2014:18:15:10 +0100] [Job 300] Read 8192 bytes of print data...
D [22/Feb/2014:18:15:10 +0100] [Job 300] Wrote 8192 bytes of print data...
D [22/Feb/2014:18:15:10 +0100] [Job 300] Read 8192 bytes of print data...
D [22/Feb/2014:18:15:10 +0100] [Job 300] Wrote 8192 bytes of print data...
D [22/Feb/2014:18:15:10 +0100] [Job 300] Read 8192 bytes of print data...
D [22/Feb/2014:18:15:10 +0100] [Job 300] Wrote 8192 bytes of print data...
D [22/Feb/2014:18:15:10 +0100] [Job 300] Read 8192 bytes of print data...
D [22/Feb/2014:18:15:10 +0100] [Job 300] Wrote 8192 bytes of print data...
D [22/Feb/2014:18:15:10 +0100] [Job 300] Before copy_setup - %%Page: 1 1
D [22/Feb/2014:18:15:10 +0100] [Job 300] Before page loop - %%Page: 1 1
D [22/Feb/2014:18:15:10 +0100] [Job 300] Copying page 1...
D [22/Feb/2014:18:15:10 +0100] [Job 300] PAGE: 1 1
D [22/Feb/2014:18:15:10 +0100] Discarding unused job-progress event...
D [22/Feb/2014:18:15:10 +0100] [Job 300] pagew = 569.0, pagel = 816.0
D [22/Feb/2014:18:15:10 +0100] [Job 300] bboxx = 0, bboxy = 0, bboxw = 595, bboxl = 842
D [22/Feb/2014:18:15:10 +0100] [Job 300] PageLeft = 13.0, PageRight = 582.0
D [22/Feb/2014:18:15:10 +0100] [Job 300] PageTop = 829.0, PageBottom = 13.0
D [22/Feb/2014:18:15:10 +0100] [Job 300] PageWidth = 595.0, PageLength = 842.0
D [22/Feb/2014:18:15:10 +0100] [Job 300] Read 8192 bytes of print data...
D [22/Feb/2014:18:15:10 +0100] [Job 300] Wrote 8192 bytes of print data...
D [22/Feb/2014:18:15:10 +0100] [Job 300] Read 8192 bytes of print data...
D [22/Feb/2014:18:15:10 +0100] [Job 300] Wrote 8192 bytes of print data...
D [22/Feb/2014:18:15:10 +0100] [Job 300] Wrote 1 pages...
D [22/Feb/2014:18:15:10 +0100] [Job 300] Read 8192 bytes of print data...
D [22/Feb/2014:18:15:10 +0100] [Job 300] PID 708 (pstops) exited with no errors.
D [22/Feb/2014:18:15:10 +0100] [Job 300] Wrote 8192 bytes of print data...
D [22/Feb/2014:18:15:10 +0100] [Job 300] Read 8192 bytes of print data...
D [22/Feb/2014:18:15:10 +0100] [Job 300] PID 704 (/usr/lib/cups/filter/pdftops) exited with no errors.
D [22/Feb/2014:18:15:10 +0100] [Job 300] Wrote 8192 bytes of print data...
D [22/Feb/2014:18:15:10 +0100] [Job 300] Read 8192 bytes of print data...
D [22/Feb/2014:18:15:10 +0100] [Job 300] Wrote 8192 bytes of print data...
D [22/Feb/2014:18:15:10 +0100] [Job 300] Read 8192 bytes of print data...
D [22/Feb/2014:18:15:10 +0100] [Job 300] Wrote 8192 bytes of print data...
D [22/Feb/2014:18:15:10 +0100] [Job 300] Read 8192 bytes of print data...
D [22/Feb/2014:18:15:10 +0100] [Job 300] Wrote 8192 bytes of print data...
D [22/Feb/2014:18:15:10 +0100] [Job 300] Read 8192 bytes of print data...
D [22/Feb/2014:18:15:11 +0100] [Job 300] Wrote 8192 bytes of print data...
D [22/Feb/2014:18:15:11 +0100] [Job 300] Read 8192 bytes of print data...
D [22/Feb/2014:18:15:11 +0100] [Job 300] Wrote 8192 bytes of print data...
D [22/Feb/2014:18:15:11 +0100] [Job 300] Read 8192 bytes of print data...
D [22/Feb/2014:18:15:11 +0100] [Job 300] Wrote 8192 bytes of print data...
D [22/Feb/2014:18:15:11 +0100] [Job 300] Read 3272 bytes of print data...
D [22/Feb/2014:18:15:11 +0100] [Job 300] Wrote 3272 bytes of print data...
D [22/Feb/2014:18:15:11 +0100] [Job 300] Sent 216264 bytes...
D [22/Feb/2014:18:15:11 +0100] [Job 300] Waiting for read thread to exit...
I [22/Feb/2014:18:15:15 +0100] Saving job.cache...
D [22/Feb/2014:18:15:15 +0100] cupsdSetBusyState: newbusy="Printing jobs", busy="Printing jobs and dirty files"
D [22/Feb/2014:18:15:18 +0100] [Job 300] Read thread still active, aborting the pending read...
D [22/Feb/2014:18:15:19 +0100] [Job 300] PID 705 (/usr/lib/cups/backend/usb) exited with no errors.
D [22/Feb/2014:18:15:19 +0100] [Job 300] time-at-completed=1393089319
D [22/Feb/2014:18:15:19 +0100] Discarding unused job-completed event...
I [22/Feb/2014:18:15:19 +0100] [Job 300] Job completed.
D [22/Feb/2014:18:15:19 +0100] cupsdMarkDirty(---J-)
D [22/Feb/2014:18:15:19 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs"
D [22/Feb/2014:18:15:19 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [22/Feb/2014:18:15:19 +0100] Discarding unused printer-state-changed event...
D [22/Feb/2014:18:15:19 +0100] cupsdMarkDirty(---J-)
D [22/Feb/2014:18:15:19 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [22/Feb/2014:18:15:20 +0100] [Job 300] Unloading...
I [22/Feb/2014:18:15:50 +0100] Saving job.cache...
D [22/Feb/2014:18:15:50 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Printing jobs and dirty files"
D [22/Feb/2014:18:15:50 +0100] Report: clients=1
D [22/Feb/2014:18:15:50 +0100] Report: jobs=300
D [22/Feb/2014:18:15:50 +0100] Report: jobs-active=0
D [22/Feb/2014:18:15:50 +0100] Report: printers=1
D [22/Feb/2014:18:15:50 +0100] Report: stringpool-string-count=1580
D [22/Feb/2014:18:15:50 +0100] Report: stringpool-alloc-bytes=8880
D [22/Feb/2014:18:15:50 +0100] Report: stringpool-total-bytes=27368
D [22/Feb/2014:18:16:31 +0100] [Client 13] HTTP_STATE_WAITING Closing on EOF
D [22/Feb/2014:18:16:31 +0100] [Client 13] Closing connection.
D [22/Feb/2014:18:16:31 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [22/Feb/2014:18:16:32 +0100] [Client 13] Accepted from localhost:631 (IPv6)
D [22/Feb/2014:18:16:32 +0100] [Client 13] Waiting for request.
D [22/Feb/2014:18:16:32 +0100] [Client 13] GET /printers/ HTTP/1.1
D [22/Feb/2014:18:16:32 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [22/Feb/2014:18:16:32 +0100] [Client 13] No authentication data provided.
D [22/Feb/2014:18:16:32 +0100] [CGI] argv[0] = "/usr/lib/cups/cgi-bin/printers.cgi"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[0] = "CUPS_CACHEDIR=/var/cache/cups"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[1] = "CUPS_DATADIR=/usr/share/cups"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[2] = "CUPS_DOCROOT=/usr/share/cups/doc"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[3] = "CUPS_FONTPATH=/usr/share/cups/fonts"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[4] = "CUPS_REQUESTROOT=/var/spool/cups"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[5] = "CUPS_SERVERBIN=/usr/lib/cups"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[6] = "CUPS_SERVERROOT=/etc/cups"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[7] = "CUPS_STATEDIR=/run/cups"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[8] = "HOME=/var/spool/cups/tmp"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[9] = "PATH=/usr/lib/cups/filter:/usr/bin:/usr/bin:/bin:/usr/bin"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[10] = "SERVER_ADMIN=root@bertrandrussell"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[11] = "SOFTWARE=CUPS/1.7.1"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[12] = "TMPDIR=/var/spool/cups/tmp"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[13] = "USER=root"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[14] = "CUPS_MAX_MESSAGE=2047"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[15] = "CUPS_SERVER=/run/cups/cups.sock"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[16] = "CUPS_ENCRYPTION=IfRequested"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[17] = "IPP_PORT=631"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[18] = "LANG=en_US.UTF8"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[19] = "REDIRECT_STATUS=1"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[20] = "GATEWAY_INTERFACE=CGI/1.1"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[21] = "SERVER_NAME=localhost"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[22] = "SERVER_PORT=631"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[23] = "REMOTE_ADDR=[v1.::1]"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[24] = "REMOTE_HOST=localhost"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[25] = "SCRIPT_NAME=/printers/"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[26] = "SCRIPT_FILENAME=/usr/share/cups/doc/printers/"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[27] = "SERVER_PROTOCOL=HTTP/1.1"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[28] = "HTTP_COOKIE=org.cups.sid=4d43abea28d1837cbb1175a07cd5bb45"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[29] = "HTTP_USER_AGENT=Mozilla/5.0 (X11; Linux x86_64; rv:27.0) Gecko/20100101 Firefox/27.0"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[30] = "HTTP_REFERER=http://localhost:631/"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[31] = "REQUEST_METHOD=GET"
D [22/Feb/2014:18:16:32 +0100] [CGI] envp[32] = "QUERY_STRING="
D [22/Feb/2014:18:16:32 +0100] [CGI] Started /usr/lib/cups/cgi-bin/printers.cgi (PID 738)
I [22/Feb/2014:18:16:32 +0100] [Client 13] Started "/usr/lib/cups/cgi-bin/printers.cgi" (pid=738)
D [22/Feb/2014:18:16:32 +0100] [Client 13] file=14
D [22/Feb/2014:18:16:32 +0100] [Client 13] Waiting for CGI data.
D [22/Feb/2014:18:16:32 +0100] [CGI] org.cups.sid cookie is "4d43abea28d1837cbb1175a07cd5bb45"
D [22/Feb/2014:18:16:32 +0100] [CGI] cgiSetVariable: SECTION="printers"
D [22/Feb/2014:18:16:32 +0100] [CGI] cgiSetVariable: REFRESH_PAGE=""
D [22/Feb/2014:18:16:32 +0100] [Client 15] Accepted from localhost (Domain)
D [22/Feb/2014:18:16:32 +0100] [Client 15] Waiting for request.
D [22/Feb/2014:18:16:32 +0100] [Client 15] POST / HTTP/1.1
D [22/Feb/2014:18:16:32 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [22/Feb/2014:18:16:32 +0100] [Client 15] No authentication data provided.
D [22/Feb/2014:18:16:32 +0100] [Client 15] 2.0 CUPS-Get-Default 1
D [22/Feb/2014:18:16:32 +0100] CUPS-Get-Default
D [22/Feb/2014:18:16:32 +0100] CUPS-Get-Default client-error-not-found: No default printer.
D [22/Feb/2014:18:16:32 +0100] [Client 15] Returning IPP client-error-not-found for CUPS-Get-Default (no URI) from localhost
D [22/Feb/2014:18:16:32 +0100] [Client 15] Content-Length: 113
D [22/Feb/2014:18:16:32 +0100] [Client 15] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=113, response=0x7fa99aadf780(IPP_IDLE), pipe_pid=0, file=-1
D [22/Feb/2014:18:16:32 +0100] [Client 15] Writing IPP response, ipp_state=DATA, old wused=0, new wused=0
D [22/Feb/2014:18:16:32 +0100] [Client 15] bytes=0, http_state=0, data_remaining=0
D [22/Feb/2014:18:16:32 +0100] [Client 15] Waiting for request.
D [22/Feb/2014:18:16:32 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [22/Feb/2014:18:16:32 +0100] [CGI] show_all_printers(http=0x7f7e8b7cb260, user="(null)")
D [22/Feb/2014:18:16:32 +0100] [CGI] cgiSetVariable: TITLE="Printers"
D [22/Feb/2014:18:16:32 +0100] [CGI] cgiSetVariable: SERVER_NAME="localhost"
D [22/Feb/2014:18:16:32 +0100] [CGI] cgiSetVariable: CUPS_VERSION="CUPS v1.7.1"
D [22/Feb/2014:18:16:32 +0100] [Client 13] CGI data ready to be sent.
D [22/Feb/2014:18:16:32 +0100] [Client 13] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, response=(nil)(), pipe_pid=738, file=14
D [22/Feb/2014:18:16:32 +0100] [Client 13] Waiting for CGI data.
D [22/Feb/2014:18:16:32 +0100] Script header: Content-Type: text/html;charset=utf-8
D [22/Feb/2014:18:16:32 +0100] Script header: 
D [22/Feb/2014:18:16:32 +0100] [Client 13] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=738, file=14
D [22/Feb/2014:18:16:32 +0100] [Client 13] Waiting for CGI data.
D [22/Feb/2014:18:16:32 +0100] [Client 13] CGI data ready to be sent.
D [22/Feb/2014:18:16:32 +0100] [Client 15] POST / HTTP/1.1
D [22/Feb/2014:18:16:32 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [22/Feb/2014:18:16:32 +0100] [Client 15] No authentication data provided.
D [22/Feb/2014:18:16:32 +0100] [Client 15] 2.0 CUPS-Get-Printers 2
D [22/Feb/2014:18:16:32 +0100] CUPS-Get-Printers
D [22/Feb/2014:18:16:32 +0100] [Client 15] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [22/Feb/2014:18:16:32 +0100] [Client 15] Content-Length: 316
D [22/Feb/2014:18:16:32 +0100] [Client 13] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=738, file=14
D [22/Feb/2014:18:16:32 +0100] [Client 13] Waiting for CGI data.
D [22/Feb/2014:18:16:32 +0100] [Client 15] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=316, response=0x7fa99aaded10(IPP_IDLE), pipe_pid=0, file=-1
D [22/Feb/2014:18:16:32 +0100] [Client 15] Writing IPP response, ipp_state=DATA, old wused=0, new wused=0
D [22/Feb/2014:18:16:32 +0100] [Client 15] bytes=0, http_state=0, data_remaining=0
D [22/Feb/2014:18:16:32 +0100] [Client 15] Waiting for request.
D [22/Feb/2014:18:16:32 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [22/Feb/2014:18:16:32 +0100] [Client 13] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=738, file=14
D [22/Feb/2014:18:16:32 +0100] [Client 13] Waiting for CGI data.
D [22/Feb/2014:18:16:32 +0100] [CGI] cgiSetVariable: TOTAL="1"
D [22/Feb/2014:18:16:32 +0100] [CGI] cgiSetVariable: SERVER_NAME="localhost"
D [22/Feb/2014:18:16:32 +0100] [CGI] cgiSetVariable: CUPS_VERSION="CUPS v1.7.1"
D [22/Feb/2014:18:16:32 +0100] [CGI] cgiSetArray: printer_state[0]="3"
D [22/Feb/2014:18:16:32 +0100] [CGI] cgiSetArray: printer_state_message[0]="Sending data to printer."
D [22/Feb/2014:18:16:32 +0100] [CGI] cgiSetArray: admin_uri[0]="/admin/"
D [22/Feb/2014:18:16:32 +0100] [CGI] cgiSetArray: printer_uri_supported[0]="/printers/OKI"
D [22/Feb/2014:18:16:32 +0100] [CGI] cgiSetArray: printer_name[0]="OKI"
D [22/Feb/2014:18:16:32 +0100] [CGI] cgiSetArray: printer_location[0]=""
D [22/Feb/2014:18:16:32 +0100] [CGI] cgiSetArray: printer_info[0]="OKI"
D [22/Feb/2014:18:16:32 +0100] [CGI] cgiSetArray: printer_make_and_model[0]="OKI DATA CORP B431(PS)"
D [22/Feb/2014:18:16:32 +0100] [CGI] cgiSetVariable: THISURL="/printers/"
D [22/Feb/2014:18:16:32 +0100] [Client 13] CGI data ready to be sent.
D [22/Feb/2014:18:16:32 +0100] [Client 15] HTTP_STATE_WAITING Closing on EOF
D [22/Feb/2014:18:16:32 +0100] [Client 15] Closing connection.
D [22/Feb/2014:18:16:32 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [22/Feb/2014:18:16:32 +0100] PID 738 (/usr/lib/cups/cgi-bin/printers.cgi) exited with no errors.
D [22/Feb/2014:18:16:32 +0100] [Client 13] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=738, file=14
D [22/Feb/2014:18:16:32 +0100] [Client 13] Waiting for CGI data.
D [22/Feb/2014:18:16:32 +0100] [Client 13] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=738, file=14
D [22/Feb/2014:18:16:32 +0100] [Client 13] Waiting for CGI data.
D [22/Feb/2014:18:16:32 +0100] [Client 13] CGI data ready to be sent.
D [22/Feb/2014:18:16:32 +0100] [Client 13] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=738, file=14
D [22/Feb/2014:18:16:32 +0100] [Client 13] Waiting for CGI data.
D [22/Feb/2014:18:16:32 +0100] [Client 13] Waiting for request.
D [22/Feb/2014:18:16:32 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [22/Feb/2014:18:16:32 +0100] [Client 13] GET /cups.css HTTP/1.1
D [22/Feb/2014:18:16:32 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [22/Feb/2014:18:16:32 +0100] [Client 13] No authentication data provided.
D [22/Feb/2014:18:16:32 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [22/Feb/2014:18:16:32 +0100] [Client 13] GET /images/left.gif HTTP/1.1
D [22/Feb/2014:18:16:32 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [22/Feb/2014:18:16:32 +0100] [Client 13] No authentication data provided.
D [22/Feb/2014:18:16:32 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [22/Feb/2014:18:16:32 +0100] [Client 13] GET /images/right.gif HTTP/1.1
D [22/Feb/2014:18:16:32 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [22/Feb/2014:18:16:32 +0100] [Client 13] No authentication data provided.
D [22/Feb/2014:18:16:32 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [22/Feb/2014:18:16:32 +0100] [Client 13] GET /images/unsel.gif HTTP/1.1
D [22/Feb/2014:18:16:32 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [22/Feb/2014:18:16:32 +0100] [Client 13] No authentication data provided.
D [22/Feb/2014:18:16:32 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [22/Feb/2014:18:16:32 +0100] [Client 14] Accepted from localhost:631 (IPv6)
D [22/Feb/2014:18:16:32 +0100] [Client 14] Waiting for request.
D [22/Feb/2014:18:16:32 +0100] [Client 13] GET /images/sel.gif HTTP/1.1
D [22/Feb/2014:18:16:32 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [22/Feb/2014:18:16:32 +0100] [Client 13] No authentication data provided.
D [22/Feb/2014:18:16:32 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [22/Feb/2014:18:16:37 +0100] [Client 14] HTTP_STATE_WAITING Closing on EOF
D [22/Feb/2014:18:16:37 +0100] [Client 14] Closing connection.
D [22/Feb/2014:18:16:37 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [22/Feb/2014:18:17:02 +0100] [Client 13] HTTP_STATE_WAITING Closing on EOF
D [22/Feb/2014:18:17:02 +0100] [Client 13] Closing connection.
D [22/Feb/2014:18:17:02 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [22/Feb/2014:18:17:02 +0100] Report: clients=0
D [22/Feb/2014:18:17:02 +0100] Report: jobs=300
D [22/Feb/2014:18:17:02 +0100] Report: jobs-active=0
D [22/Feb/2014:18:17:02 +0100] Report: printers=1
D [22/Feb/2014:18:17:02 +0100] Report: stringpool-string-count=1580
D [22/Feb/2014:18:17:02 +0100] Report: stringpool-alloc-bytes=8880
D [22/Feb/2014:18:17:02 +0100] Report: stringpool-total-bytes=27368

Rexilion · 2014-02-22 18:48:50

I only see a pdf provided by 'lehrer' (teacher?). No more data was send to the printer right?

fsavigny · 2014-02-22 19:07:11

Thank you for your quick reply!

Yes, I only printed out one document, however, weirdly, not a PDF, but an ODT file (somewhere at roughly two thirds of the log, it says "32_noun_clauses", which is the basename - the file is actually called "32_noun_clauses.odt", not "32_noun_clauses.pdf"), from LibreOffice's printing dialog.

I did notice this fact, but assumed LibreOffice uses it somehow as an intermediate format, even though that does not make too much sense to me.

Best regards,

Florian

[PS: Yes, "lehrer" means teacher. It's the user account I use when I do work for school.]

Rexilion · 2014-02-23 08:09:38

Weird, I only see one job. And it makes perfect sense for the fact that a .pdf is used btw.

Could you reboot and then print a document and then immediatly after do this:

ps aux

Post the output here. Make sure you scan it first, it could contain private information.

Arch Linux

#1 2014-02-16 13:18:12

CUPS: Printer always waits for more data, and finally times out.

#2 2014-02-17 12:01:44

Re: CUPS: Printer always waits for more data, and finally times out.

#3 2014-02-19 19:03:14

Re: CUPS: Printer always waits for more data, and finally times out.

#4 2014-02-20 07:36:18

Re: CUPS: Printer always waits for more data, and finally times out.

#5 2014-02-22 17:31:32

Re: CUPS: Printer always waits for more data, and finally times out.

#6 2014-02-22 18:48:50

Re: CUPS: Printer always waits for more data, and finally times out.

#7 2014-02-22 19:07:11

Re: CUPS: Printer always waits for more data, and finally times out.

#8 2014-02-23 08:09:38

Re: CUPS: Printer always waits for more data, and finally times out.

Board footer