CUPS - Print jobs are taking a long time to print

Users are complaining that printing takes a long time to print. When they submit a print job, they may have to wait 5 - 15 minutes for jobs to finally start printing. This is intermittent and sometimes printing is immediate.

I am suspecting it is a networking issue as the users on the site where the CUPS server is located are not experiencing any issues. Only users from a remote site is experiencing this issue. However, users from the remote site says they do not experience any issues with the Internet or web application. Sites are connected via an IPSec tunnel.

The web application also runs on the CUPS server. I would expect the remote site to also have issues with both the web application and printer if it was the network. Strangely, they are only experiencing issues with printing and not the web application.

I did notice a lot of error messages in the CUPS logs which suggests that the printer is unable to connect to the printer. Unfortunately, there is no way of determining which printers is unreachable from the log as it only shows job ID.

 [08/Feb/2023:09:38:09 +1100] [Job 705435] The printer is unreachable at this time.
W [08/Feb/2023:09:40:21 +1100] [Job 705435] The printer is unreachable at this time.
W [08/Feb/2023:09:42:38 +1100] [Job 705435] The printer is unreachable at this time.
W [08/Feb/2023:09:45:01 +1100] [Job 705436] The printer is unreachable at this time.
W [08/Feb/2023:10:37:41 +1100] [Job 705557] The printer did not respond.
W [08/Feb/2023:10:37:51 +1100] [Job 705557] The printer did not respond.
W [08/Feb/2023:10:38:01 +1100] [Job 705557] The printer did not respond.
W [08/Feb/2023:10:38:11 +1100] [Job 705557] The printer did not respond.
W [08/Feb/2023:10:38:21 +1100] [Job 705557] The printer did not respond.
W [08/Feb/2023:10:38:31 +1100] [Job 705557] The printer did not respond.
W [08/Feb/2023:10:38:41 +1100] [Job 705557] The printer did not respond.
W [08/Feb/2023:10:38:51 +1100] [Job 705557] The printer did not respond.
W [08/Feb/2023:10:39:03 +1100] [Job 705557] The printer did not respond.
W [08/Feb/2023:10:39:13 +1100] [Job 705557] The printer did not respond.
W [08/Feb/2023:10:39:24 +1100] [Job 705557] The printer did not respond.
W [08/Feb/2023:10:39:34 +1100] [Job 705557] The printer did not respond.
W [08/Feb/2023:10:39:44 +1100] [Job 705557] The printer did not respond.
W [08/Feb/2023:10:39:55 +1100] [Job 705557] The printer did not respond.

ping from the computer to the CUPS server does not show any dropped packets. I am considering doing ping over the course of the day to see if there are intermittent drops. I might try restarting the CUPS daemon and see if it fixes the problem.

Is there anything else you can suggest to help me identify where the fault is?

There maybe an issue with the MTU setting on the IPsec gateway. You can try reducing it and see if it helps.

is the server , a server with gui ? have you try to a wireshark trace ?
if not gui you can use a wireshark with ncurse support .
how did you configure your connection ?

socket://
hp://
usb://
or lpr/lpd protocol

what king or printer is this . HP ? canon ? …

On the site with problems, printers are using LPD and printers are a mixture of Lexmark, Kyocera and Toshiba. I will look at setting Wireshark with ncurse some time.

After enable debugging I get these messages in the error logs

d [28/Feb/2023:09:10:04 +1100] [Client 25] cupsdWriteClient error=0, used=0, state=HTTP_POST_SEND, data_encoding=HTTP_ENCODE_LENGTH, data_remaining=9109, response=0x
56469ecf5b40(IPP_ATTRIBUTE), pipe_pid=0, file=-1
d [28/Feb/2023:09:10:04 +1100] [Client 23] cupsdWriteClient error=0, used=0, state=HTTP_POST_SEND, data_encoding=HTTP_ENCODE_LENGTH, data_remaining=11694, response=0
x56469ed70540(IPP_ATTRIBUTE), pipe_pid=0, file=-1
d [28/Feb/2023:09:10:04 +1100] select_timeout: JobHistoryUpdate=1677606292
d [28/Feb/2023:09:10:04 +1100] [Client 25] cupsdWriteClient error=0, used=0, state=HTTP_POST_SEND, data_encoding=HTTP_ENCODE_LENGTH, data_remaining=9084, response=0x
56469ecf5b40(IPP_ATTRIBUTE), pipe_pid=0, file=-1
d [28/Feb/2023:09:10:04 +1100] [Client 23] cupsdWriteClient error=0, used=0, state=HTTP_POST_SEND, data_encoding=HTTP_ENCODE_LENGTH, data_remaining=11671, response=0
x56469ed70540(IPP_ATTRIBUTE), pipe_pid=0, file=-1
d [28/Feb/2023:09:10:04 +1100] select_timeout: JobHistoryUpdate=1677606292
d [28/Feb/2023:09:10:04 +1100] [Client 25] cupsdWriteClient error=0, used=0, state=HTTP_POST_SEND, data_encoding=HTTP_ENCODE_LENGTH, data_remaining=9063, response=0x
56469ecf5b40(IPP_ATTRIBUTE), pipe_pid=0, file=-1
d [28/Feb/2023:09:10:04 +1100] [Client 23] cupsdWriteClient error=0, used=0, state=HTTP_POST_SEND, data_encoding=HTTP_ENCODE_LENGTH, data_remaining=11619, response=0
x56469ed70540(IPP_ATTRIBUTE), pipe_pid=0, file=-1
d [28/Feb/2023:09:10:04 +1100] select_timeout: JobHistoryUpdate=1677606292
d [28/Feb/2023:09:10:04 +1100] [Client 25] cupsdWriteClient error=0, used=0, state=HTTP_POST_SEND, data_encoding=HTTP_ENCODE_LENGTH, data_remaining=9038, response=0x
56469ecf5b40(IPP_ATTRIBUTE), pipe_pid=0, file=-1
d [28/Feb/2023:09:10:04 +1100] [Client 23] cupsdWriteClient error=0, used=0, state=HTTP_POST_SEND, data_encoding=HTTP_ENCODE_LENGTH, data_remaining=11585, response=0
x56469ed70540(IPP_ATTRIBUTE), pipe_pid=0, file=-1
d [28/Feb/2023:09:10:04 +1100] select_timeout: JobHistoryUpdate=1677606292

There’s also these messages

d [28/Feb/2023:09:10:04 +1100] cupsdAddSelect(fd=23, read_cb=0x56469e2dbb40, write_cb=(nil), data=0x56469ed41400)
D [28/Feb/2023:09:10:04 +1100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
d [28/Feb/2023:09:10:04 +1100] select_timeout: JobHistoryUpdate=1677606292
d [28/Feb/2023:09:10:04 +1100] [Client 25] cupsdReadClient error=0, used=0, state=HTTP_WAITING, data_encoding=HTTP_ENCODE_LENGTH, data_remaining=0, request=(nil)(),
file=-1
D [28/Feb/2023:09:10:04 +1100] [Client 25] POST / HTTP/1.1
D [28/Feb/2023:09:10:04 +1100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
d [28/Feb/2023:09:10:04 +1100] cupsdFindBest: uri = "/"...
d [28/Feb/2023:09:10:04 +1100] cupsdFindBest: Location /admin/conf Limit 7f
d [28/Feb/2023:09:10:04 +1100] cupsdFindBest: Location /admin Limit 7f
d [28/Feb/2023:09:10:04 +1100] cupsdFindBest: Location / Limit 7f
d [28/Feb/2023:09:10:04 +1100] cupsdFindBest: best = /
d [28/Feb/2023:09:10:04 +1100] [Client 25] con->uri="/", con->best=0x56469eae4150(/)
d [28/Feb/2023:09:10:04 +1100] [Client 25] Authorization=""
D [28/Feb/2023:09:10:04 +1100] [Client 25] No authentication data provided.
d [28/Feb/2023:09:10:04 +1100] cupsdIsAuthorized: con->uri="/", con->best=0x56469eae4150(/)
d [28/Feb/2023:09:10:04 +1100] cupsdIsAuthorized: level=CUPSD_AUTH_ANON, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0
d [28/Feb/2023:09:10:04 +1100] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
d [28/Feb/2023:09:10:04 +1100] [Client 25] cupsdReadClient error=0, used=67, state=HTTP_POST_RECV, data_encoding=HTTP_ENCODE_LENGTH, data_remaining=67, request=0x564
69ed70540(IPP_ATTRIBUTE), file=-1
d [28/Feb/2023:09:10:04 +1100] select_timeout: JobHistoryUpdate=1677606292
d [28/Feb/2023:09:10:04 +1100] [Client 25] cupsdReadClient error=0, used=38, state=HTTP_POST_RECV, data_encoding=HTTP_ENCODE_LENGTH, data_remaining=38, request=0x564
69ed70540(IPP_ATTRIBUTE), file=-1
d [28/Feb/2023:09:10:04 +1100] select_timeout: JobHistoryUpdate=1677606292
d [28/Feb/2023:09:10:04 +1100] [Client 25] cupsdReadClient error=0, used=1, state=HTTP_POST_RECV, data_encoding=HTTP_ENCODE_LENGTH, data_remaining=1, request=0x56469
ed70540(IPP_ATTRIBUTE), file=-1
D [28/Feb/2023:09:10:04 +1100] [Client 25] 1.1 CUPS-Get-Default 611583704
d [28/Feb/2023:09:10:04 +1100] cupsdProcessIPPRequest(0x56469edaf920[25]): operation_id = 4001
D [28/Feb/2023:09:10:04 +1100] CUPS-Get-Default
d [28/Feb/2023:09:10:04 +1100] get_default(0x56469edaf920[25])
d [28/Feb/2023:09:10:04 +1100] cupsdFindPolicyOp(p=0x56469eae96c0, op=4001(CUPS-Get-Default))
d [28/Feb/2023:09:10:04 +1100] cupsdFindPolicyOp: Found wildcard match...
d [28/Feb/2023:09:10:04 +1100] cupsdIsAuthorized: con->uri="/", con->best=0x56469eaee0d0((null))
d [28/Feb/2023:09:10:04 +1100] cupsdIsAuthorized: level=CUPSD_AUTH_ANON, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0
d [28/Feb/2023:09:10:04 +1100] cupsdIsAuthorized: op=0(0x0000)
d [28/Feb/2023:09:10:04 +1100] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
D [28/Feb/2023:09:10:04 +1100] CUPS-Get-Default client-error-not-found: No default printer.
D [28/Feb/2023:09:10:04 +1100] Returning IPP client-error-not-found for CUPS-Get-Default (no URI) from localhost
d [28/Feb/2023:09:10:04 +1100] cupsdProcessIPPRequest: ippLength(response)=113
d [28/Feb/2023:09:10:04 +1100] cupsdAddSelect(fd=25, read_cb=0x56469e2dbb40, write_cb=0x56469e2db420, data=0x56469edaf920)
d [28/Feb/2023:09:10:04 +1100] select_timeout: JobHistoryUpdate=1677606292
d [28/Feb/2023:09:10:04 +1100] select_timeout(0): 10 seconds to write dirty config/state files

Other parts of the error logs include these

d [28/Feb/2023:09:10:04 +1100] printer-uri-supported="ipp://localhost:631/printers/lilfin1"
d [28/Feb/2023:09:10:04 +1100] copy_attrs(to=0x56469ed67d30, from=0x56469eb15970, ra=0x56469ed89930, group=0, quickcopy=0)
d [28/Feb/2023:09:10:04 +1100] copy_attrs(to=0x56469ed67d30, from=0x56469eb148f0, ra=0x56469ed89930, group=0, quickcopy=0)
d [28/Feb/2023:09:10:04 +1100] copy_attrs(to=0x56469ed67d30, from=0x56469eaf73c0, ra=0x56469ed89930, group=0, quickcopy=-2147483648)
d [28/Feb/2023:09:10:04 +1100] add_printer_state_reasons(0x56469edaf920[25], 0x56469eb16600[lilnewcars1])
d [28/Feb/2023:09:10:04 +1100] printer-uri-supported="ipp://localhost:631/printers/lilnewcars1"
d [28/Feb/2023:09:10:04 +1100] copy_attrs(to=0x56469ed67d30, from=0x56469eb16e00, ra=0x56469ed89930, group=0, quickcopy=0)
d [28/Feb/2023:09:10:04 +1100] copy_attrs(to=0x56469ed67d30, from=0x56469eb15d40, ra=0x56469ed89930, group=0, quickcopy=0)
d [28/Feb/2023:09:10:04 +1100] copy_attrs(to=0x56469ed67d30, from=0x56469eaf73c0, ra=0x56469ed89930, group=0, quickcopy=-2147483648)
d [28/Feb/2023:09:10:04 +1100] add_printer_state_reasons(0x56469edaf920[25], 0x56469eb17aa0[lilparts1])

Hi,
Did you find a solution, i’m experiencing the same problem. Jobs a taking to 30mn to print
Eric

The debug mode has too much information and most of it makes no sense to me. I can’t find any documentation on how to decipher what they mean.

I reverted the log level back to default and it is display the same error as before:

/var/log/cups/error_log-20230312:W [09/Mar/2023:15:16:53 +1100] [Job 748384] The printer is unreachable at this time.
/var/log/cups/error_log-20230312:W [09/Mar/2023:15:58:45 +1100] [Job 748497] The printer did not respond.
/var/log/cups/error_log-20230312:W [09/Mar/2023:16:20:46 +1100] [Job 748577] The printer is unreachable at this time.
/var/log/cups/error_log-20230312:W [09/Mar/2023:16:55:41 +1100] [Job 748660] The printer is unreachable at this time.
/var/log/cups/error_log-20230312:W [09/Mar/2023:16:57:53 +1100] [Job 748660] The printer is unreachable at this time.
/var/log/cups/error_log-20230312:W [09/Mar/2023:17:00:17 +1100] [Job 748668] The printer is unreachable at this time.
/var/log/cups/error_log-20230312:W [10/Mar/2023:08:12:44 +1100] [Job 748990] The printer is unreachable at this time.
/var/log/cups/error_log-20230312:W [10/Mar/2023:08:14:57 +1100] [Job 748990] The printer is unreachable at this time.
/var/log/cups/error_log-20230312:W [10/Mar/2023:12:16:58 +1100] [Job 749662] The printer is unreachable at this time.
/var/log/cups/error_log-20230312:W [10/Mar/2023:12:19:17 +1100] [Job 749668] The printer is unreachable at this time.
/var/log/cups/error_log-20230312:W [10/Mar/2023:13:44:36 +1100] [Job 749865] The printer is unreachable at this time.
/var/log/cups/error_log-20230312:W [10/Mar/2023:13:57:36 +1100] [Job 749878] The printer is unreachable at this time.
/var/log/cups/error_log-20230312:W [10/Mar/2023:13:59:48 +1100] [Job 749878] The printer is unreachable at this time.
/var/log/cups/error_log-20230312:W [10/Mar/2023:14:11:58 +1100] [Job 749928] The printer did not respond.
/var/log/cups/error_log-20230312:W [10/Mar/2023:15:05:44 +1100] [Job 750038] The printer is unreachable at this time.
/var/log/cups/error_log-20230312:W [10/Mar/2023:15:07:56 +1100] [Job 750038] The printer is unreachable at this time.
.... ommitted ...

I wrote a script that runs the lpstat -o command and redirect output to file (print_jobs) and then used awk, sort and uniq to map the printers/jobs with the errors in the error_log. Some examples are as below:

cat /var/log/cups/error_log | awk '{print substr($5, 1, length($5)-1)}' | xargs -I %  grep % /var/log/cups/print_jobs
cat /var/log/cups/print_jobs | awk '{print $1}' | awk -F- '{print $NF}' | uniq -d > /root/print_job_id
cat /var/log/cups/print_jobs | awk '{print $1}' | sed -E 's/-[[:digit:]].*$//' | sort | uniq
cat /var/log/cups/print_jobs | awk '{print $1}' | sort | uniq -c |  awk '{print $2}' | sed -E 's/-[[:digit:]].*$//' | sort | uniq -c
cat /root/print_job_id | xargs -I %  grep % /var/log/cups/error_log* > /root/errors_match.txt

I’ve managed to reduce the errors to 10 printers out of 50 printers. I counted the jobs where CUPS did not get a response or where the printer was unreachable for each printer

571 prtsrv1- 10.29.138.10
117 prtsrv4 - 10.29.138.12
151 prtsrv5 - 10.29.138.14
7 prtcopier - 10.29.137.10
13 prtsvcpart - 10.29.138.109
69 prtadmin1 - 10.16.3.171
140 prtnewcars1 - 10.16.3.172
466 prtparts1 - 10.16.3.170
239 prtservice1 - 10.16.3.161
47 prtfc1 - 10.29.140.10
.... ommitted ...

I also counted error for each jobs meaning CUPS would have retried connecting to the printers again for these jobs:

635 prtsrv5-749053
635 prtsrv5-749052
635 prtsrv5-749051
635 prtsrv5-749050
617 prtsrv5-749054
616 prtsrv5-749055
538 prtsrv5-749063
535 prtsrv5-749064
527 prtsrv5-749065
521 prtsrv5-749070
520 prtsrv5-749071
.... ommitted ...