I have a CUPS server set up, to which Windows machines can print. Everything seems to work well (Microsoft Office and some other programs I've tried), except for Adobe Acrobat Pro. It takes a long time -- sometimes some 40 minutes -- before print jobs are successfully executed.
I set the CUPS LogLevel to Debug, and I observe that these are always the last couple lines before it hangs:
...
D [25/May/2012:15:09:24 -0700] cupsdSetBusyState: Not busy
D [25/May/2012:15:09:24 -0700] cupsdReadClient: 12 POST /printers/printer HTTP/1.1
D [25/May/2012:15:09:24 -0700] cupsdSetBusyState: Active clients
D [25/May/2012:15:09:24 -0700] cupsdAuthorize: No authentication data provided.
D [25/May/2012:15:09:24 -0700] cupsdReadClient: 12 1.0 Print-Job 2
After that last line, nothing happens for a while.
Nothing, that is, except for these lines, repeated over and over again:
D [25/May/2012:15:15:03 -0700] Report: clients=1
D [25/May/2012:15:15:03 -0700] Report: jobs=72
D [25/May/2012:15:15:03 -0700] Report: jobs-active=0
D [25/May/2012:15:15:03 -0700] Report: printers=2
D [25/May/2012:15:15:03 -0700] Report: printers-implicit=0
D [25/May/2012:15:15:03 -0700] Report: stringpool-string-count=8555
D [25/May/2012:15:15:03 -0700] Report: stringpool-alloc-bytes=11344
D [25/May/2012:15:15:03 -0700] Report: stringpool-total-bytes=163552
D [25/May/2012:15:15:15 -0700] cupsdNetIFUpdate: "lo" = localhost:631
D [25/May/2012:15:15:15 -0700] cupsdNetIFUpdate: "eth0" = <server-ip>:631
D [25/May/2012:15:15:15 -0700] cupsdNetIFUpdate: "lo" = localhost:631
D [25/May/2012:15:15:15 -0700] cupsdNetIFUpdate: "eth0" = <server-ip>%eth0:631
These keep repeating until some arbitrary (and varying) amount of time later, when I see these lines, and the document starts printing soon.
D [25/May/2012:15:15:35 -0700] Print-Job http://<server-ip>:631/printers/printer
D [25/May/2012:15:15:35 -0700] [Job ???] Auto-typing file...
I [25/May/2012:15:15:35 -0700] [Job ???] Request file type is application/postscript.
D [25/May/2012:15:15:35 -0700] cupsdMarkDirty(----J-)
...
Printing from Microsoft Word produces no such hang, however:
...
D [25/May/2012:14:17:25 -0700] cupsdReadClient: 17 1.0 Print-Job 2
D [25/May/2012:14:17:25 -0700] Print-Job http://<server-ip>:631/printers/printer
...
Wireshark and tcpdump indicate that communication is occurring at all times, however.
Would you have any ideas regarding how I might resolve this issue?
EDIT
I printed essentially the same document again. This time, I observed something different before the hang:
D [25/May/2012:15:50:02 -0700] cupsdReadClient: 17 POST /printers/printer HTTP/1.1
D [25/May/2012:15:50:02 -0700] cupsdAuthorize: No authentication data provided.
D [25/May/2012:15:50:02 -0700] cupsdReadClient: 17 1.0 Print-Job 2
D [25/May/2012:15:50:02 -0700] cupsdReadClient: 21 1.0 Get-Jobs 10
D [25/May/2012:15:50:02 -0700] Get-Jobs http://<server-ip>:631/printers/printer
D [25/May/2012:15:50:02 -0700] Returning IPP successful-ok for Get-Jobs (http://<server-ip>:631/printers/printer) from <client-ip>
D [25/May/2012:15:50:23 -0700] Report: clients=4
D [25/May/2012:15:50:23 -0700] Report: jobs=73
D [25/May/2012:15:50:23 -0700] Report: jobs-active=0
D [25/May/2012:15:50:23 -0700] Report: printers=2
...
D [25/May/2012:15:54:23 -0700] Report: stringpool-alloc-bytes=11376
D [25/May/2012:15:54:23 -0700] Report: stringpool-total-bytes=167048
D [25/May/2012:15:54:30 -0700] Closing client 12 after 300 seconds of inactivity...
D [25/May/2012:15:54:30 -0700] cupsdCloseClient: 12
D [25/May/2012:15:54:30 -0700] Closing client 13 after 300 seconds of inactivity...
D [25/May/2012:15:54:30 -0700] cupsdCloseClient: 13
D [25/May/2012:15:54:40 -0700] cupsdNetIFUpdate: "lo" = localhost:631
D [25/May/2012:15:54:40 -0700] cupsdNetIFUpdate: "eth0" = <server-ip>:631
...
D [25/May/2012:15:55:23 -0700] Report: stringpool-total-bytes=167048
D [25/May/2012:15:55:32 -0700] Print-Job http://<server-ip>:631/printers/printer
D [25/May/2012:15:55:32 -0700] [Job ???] Auto-typing file...
I [25/May/2012:15:55:32 -0700] [Job ???] Request file type is application/postscript.
D [25/May/2012:15:55:32 -0700] cupsdMarkDirty(----J-)
...
The file came out of the printer at 15:56, but this seems to be by far the largest part of the delay.
EDIT 2
I should note that printing to an XPS file from Adobe Acrobat, and then printing to the CUPS server printer from the XPS file produces no such delay. So it would appear that it is Adobe Acrobat that's the culprit.
SOLUTION
I finally solved the problem by choosing a non-generic postscript driver for the printer (in Windows).