Print job fails with "Unable to add document to print job" error in CUPS-to-CUPS setup

[hxvxt2]

Describe the bug I have multiple copies of a PDF file ranging only in size/pages but essentially generated from the same long PDF file. I am trying to load test in a cups-to-cups setup. I test by giving manual print from a Central CUPS server to a printer added on the Remote CUPS server. Sharing the printer config from the Central CUPS server below. The test results in successful print for files with 100, 125, 200 pages but fails for 500 pages and upwards.

> lpstat -v | grep printer_on_central_cups
device for printer_on_central_cups: https://remote-cups.mytld.com/printers/printer_on_remote_cups

Steps to reproduce the behavior:

1. Give a manual print (pdf with 200 pages) from the Central CUPS server, the job shows up on the remote CUPS server (with the state as "Held" and file size 0KB). The job starts printing after the processing is complete.
2. Give a manual print (pdf with 500 pages) from the Central CUPS server, the job shows up on the remote CUPS server (with the state as "Held" and file size 0KB). Meanwhile, the Central CUPS keeps processing the pages, at some points, the job on the Central CUPS server fails with Unable to add document to print job. Unfortunately, the debug level was also not very helpful, it doesn't show anything more than what we already know from the CUPS "Web Interface".

tldr logs:

D [04/Oct/2023:18:30:38 +0530] [Notifier] PrinterStateChanged
D [04/Oct/2023:18:30:38 +0530] [Job 101] Send-Document: server-error-internal-error (No request sent.)
D [04/Oct/2023:18:30:38 +0530] [Job 101] ---- end-of-attributes-tag ----
E [04/Oct/2023:18:30:38 +0530] [Job 101] Unable to add document to print job.

Sharing more lines, that might be relevant in providing more context, from the error_log :

EDIT by zdohnal: error_log.txt

Expected behavior After processing all the pages on the Central CUPS the corresponding job on the Remote CUPS server should have progressed from "Held" to "Processing".

Actual Observation But that doesn't happen. The Job failed on the Central CUPS server with the error Unable to add document to print job. A new job gets created on Remote CUPS (the old one stays in "Held"). The jobs keep piling up on remote CUPS like that meanwhile the job on Central CUPS stays in Unable to add document to print job , until I manually cancel the job.

System Information:

• Central Cups Server: v2.4.2 on Debian 12 (laptop)
• Remote Cups Server: v2.3.3op2 on Debian 11-based Raspberry Pi OS
  • Remote Cups(variation): v2.3.3op2 on Debian 11 Laptop (tested on laptop to eliminate resource limitation)

Additional context I have been able to replicate this issue enough times, so I hope it's fair to rule out the following:-

1. Compute resource limitation on remote CUPS. (tried on Raspi 4GB and Laptop 8GB)
2. Network fluctuations.
3. CUPS misconfiguration cupsd.conf (made sure the following attributes are set on both Remote and Central CUPS server )
   • Timeout 3600
   • LimitRequestBody 0
   • Any PDF version-related issue. (all test files are subsets of the same 1000-page long PDF).
   • 100 pages (27MB)
   • 200 pages (58MB)
   • 500 pages (155MB)
   • 1000 pages (425MB)

Perhaps, the fact that files smaller than 500 pages get printed without any issue and the file with 500 pages fails every time, it's fair to assume it's a bug? Would anyone be able to help in fixing or troubleshooting this further?

Ciao ☕ -v

[zdohnal]

Hi,

please attach logs from central server and remote CUPS server as files here (add .txt suffix and attach them by clicking on 'selecting'), so I have matching logs and see how the job flow goes - it should give us info what happens on the remote server.

[childish-gambino]

Hi,

Attaching logs here. Also sharing job ID for reference:-

• Job ID on Central CUPS: 101
• Job ID on Remote CUPS: 8256

central_cups_error_101.txt remote_cups_error_8256.txt

[zdohnal]

@childish-gambino thank you for the logs!

It looks like HTTP state of connection is not in the correct state when it should when the process tries to get IPP response, and it is reported like there was no IPP request sent at all after approx. 7 minutes. The captured decrypted network traffic between the servers could help, if it is possible for you to capture it with SSL keys to decrypt it (or switch temporarily to plain IPP), because right now I'm not sure whether the issue happened in cupsSendRequest() and hung there, or document data was sent via cupsWriteRequestData().

Either way, IMO the issue happens because your PDF file is filtered to PWG raster, which takes more time than sending it as PDF (since other cups supports it) - what driver do you use? Can you attach it? I would guess it is driverless driver from cups-filters, but I can't get your filter chain with the current versions, so there might be fix for this in newer versions.

[anirudhagarwal1]

@zdohnal Thanks for the response.

I have a few follow up questions -

1. Is there a way I can check my filter chain being applied if I am using the driverless driver?
2. Would it be possible for me to just pass along the PDF instead of the PWG raster to the remote CUPS server so that the bandwidth consumed is lower? I am thinking that the cups filter chain would be converting the PDF to PWG raster format. Am I correct here?
3. Also, wanted to understand on how setting up the connection url as ipp is different than http/https? Is there a documentation that I could refer to, to understand the differences?
4. What is the difference between cupsSendRequest() and cupsWriteRequestData()? Where can I read about these more in detail?

[zdohnal]

@zdohnal Thanks for the response.

I have a few follow up questions -

1. Is there a way I can check my filter chain being applied if I am using the driverless driver?

Every used filter is printed out in debug logs when you send a job to the print queue.

2. Would it be possible for me to just pass along the PDF instead of the PWG raster to the remote CUPS server so that the bandwidth consumed is lower? I am thinking that the cups filter chain would be converting the PDF to PWG raster format. Am I correct here?

That's exactly what IPP Everywhere driver does - CUPS creates filter chain based on the driver you install printer with - my suspicion is that your driver tells CUPS to convert to raster.

3. Also, wanted to understand on how setting up the connection url as ipp is different than http/https? Is there a documentation that I could refer to, to understand the differences?

ipps is IPP protocol encrypted by TLS, ipp is unencrypted IPP protocol. http is symlink to ipp in CUPS and https to ipps. So AFAIK http and ipp would work the same in CUPS (and https and ipps too). However other tools might get confused by the symlink.

4. What is the difference between cupsSendRequest() and cupsWriteRequestData()? Where can I read about these more in detail?

Unfortunately I was not able to find other documentation for them than comments in the code and this mention in https://openprinting.github.io/cups/doc/cupspm.html#submitting-a-print-job - cupsSendRequest() is a lower level function which sends a request, cupsWriteRequestData() sends files by chunks to the destination via HTTP.

[anirudhagarwal1]

That's exactly what IPP Everywhere driver does - CUPS creates filter chain based on the driver you install printer with - my suspicion is that your driver tells CUPS to convert to raster.

I did not install the printer with a driver per se. I am just using the open printing drivers that show up when I connect the printer to the system. Can you help me understand which drivers were you referring to here?

[zdohnal]

If you use an OpenPrinting driver which shows up when you connect the printer, it is driverless driver (I see the contradiction, but we have to generate the driver file for backward compatibility with applications expecting the driver file) - this driver is advertised when you install the printer permanently (is among the found printers) or is used when cups-browsed creates the printer. The driver I'm talking about is everywhere driver from OpenPrinting CUPS - this one is used when you don't install the printer at all (you connect the printer via ethernet/wifi/usb, make it seen on mDNS and open an application - and the printer is available in the dialog) or when you choose 'IPP Everywhere' model in CUPS web ui.

So both are from OpenPrinting - you can try installing your remote queue like this with IPP Everywhere:

$ lpadmin -p printer_eve -v ipps://remote-cups.mytld.com/printers/printer_on_remote_cups -m everywhere -E

, print to this new queue and see if behavior changes.

[zdohnal]

@childish-gambino @anirudhagarwal1 @hxvxt2 Hi, any changes? Did you change the driver and it works for you? If not, please upload decrypted network traffic to your print server at the time you print - thank you!

[childish-gambino]

@zdohnal sorry for the late reply. We did try installing with the -m everywhere option too but that didn't help either. We were not able to spend as much time as we would have liked to. For now, I suspect the issue to be with the DNS proxy we are using (CloudFlare) which also has a limitation of (100 MB) for data transfer. (But why would my print request fail around 35 MB is still something that I have not been able to figure out)

Thanks for your time. I'll reopen the issue if I have new findings.

[zdohnal]

Ok, I'll close the issue for now, let me know once you have the decrypted communication traffic capture.