CUPS fails to start, or starts very slowly, in RHEL

Root Cause

Delay in CUPS starting up can be due to a DNS failure when connecting to the DNS server. If the connection to the DNS server times out, that can cause a five-second delay every time a printer is loaded. If there are hundreds of printers defined in the system, the cumulative effect of hundreds of five-second delays can be significant.

A more detailed description, including snippets of log files follows.

1. When CUPS starts up, it loads information about each of the printers that are defined in /etc/cups/printers.conf. You can see this process occurring in the CUPS error_log (when LogLevel is set to debug in /etc/cups/cupsd.conf) in messages like the following:

   D [29/May/2015:22:25:16 +0300] Loading printer PR_LAB_LABEL...
   d [29/May/2015:22:25:16 +0300] cupsdAddPrinter("PR_LAB_LABEL")
   d [29/May/2015:22:25:16 +0300] cupsdAddPrinter: Adding PR_LAB_LABEL to Printers
   d [29/May/2015:22:25:16 +0300] cupsdSetPrinterReasons(p=0x7ff0275dedb0(PR_LAB_LABEL),
     s="-cups-insecure-filter-warning,cups-missing-filter-warning"
   d [29/May/2015:22:25:16 +0300] cupsdFindBest: uri = "/printers/PR_LAB_LABEL"...
   d [29/May/2015:22:25:16 +0300] cupsdFindBest: Location CUPS_INTERNAL_BROWSE_ACL Limit 0
   d [29/May/2015:22:25:16 +0300] cupsdFindBest: Location /admin/conf Limit 7f
   d [29/May/2015:22:25:16 +0300] cupsdFindBest: Location /admin Limit 7f
   d [29/May/2015:22:25:16 +0300] cupsdFindBest: Location / Limit 7f
   d [29/May/2015:22:25:16 +0300] cupsdFindBest: best = /
   d [29/May/2015:22:25:16 +0300] cupsdFindPolicyOp(p=0x7ff02755ad10, op=2(Print-Job))
   d [29/May/2015:22:25:16 +0300] cupsdFindPolicyOp: Found wildcard match...
   D [29/May/2015:22:25:21 +0300] load_ppd: Loading /var/cache/cups/PR_LAB_LABEL.ipp...
   

   Note the five-second delay between the "cupsdFindPolicyOp" message and the "load_ppd" message.

2. During the gap between the two aforementioned message, CUPS is sending a message to the audit log with information about the printer that is being added. These messages can be seen in the file /var/log/audit/audit.log:

   type=LABEL_LEVEL_CHANGE msg=audit(1432847988.216:4567376): user pid=12345 uid=0 auid=123 ses=146886
   subj=unconfined_u:system_r:cupsd_t:s0-s0:c0.c1023 msg='printer=PR_LAB_LABEL
   uri=lpd://10.1.2.3/lpt1 banners=none,none range=unknown exe="/usr/sbin/cupsd"
   hostname=dc1-bg.example.com addr=? terminal=? res=success'
   

3. The code that adds the message to the audit log also attempts to resolve the address of the "hostname" field (dc1-bg.example.com). As as result, the system connects to the DNS servers defined in /etc/resolve.conf:

   nameserver 10.1.2.4
   nameserver 10.1.2.5
   

   The connection to the first nameserver (10.1.2.4) fails after five seconds. The connection to the
   second nameserver (10.1.2.5) returns immediately with a result. We can see this in the strace of the
   cupsd executable during startup:

   First, a socket is allocated and a connection to 10.1.2.4 is made:

   26485 1432927233.944436 socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 7 <0.000031>
   26485 1432927233.944517 connect(7, {sa_family=AF_INET, sin_port=htons(53),
         sin_addr=inet_addr("10.1.2.4")}, 16) = 0 <0.000020>
   26485 1432927233.944587 poll([{fd=7, events=POLLOUT}], 1, 0) = 1 ([{fd=7, revents=POLLOUT}]) <0.000016>
   

   The DNS query is sent to the server:

   26485 1432927233.944655 sendto(7, "UV\1\0\0\1\0\0\0\0\0\0\10dc1-vc-1\3phh\3gov\0\0\1\0\1", 34,
         MSG_NOSIGNAL, NULL, 0) = 34 <0.000028>
   26485 1432927233.944739 poll([{fd=7, events=POLLIN|POLLOUT}], 1, 5000) = 1
         ([{fd=7, revents=POLLOUT}]) <0.000017>
   26485 1432927233.944804 sendto(7, "\217T\1\0\0\1\0\0\0\0\0\0\10dc1-vc-1\3phh\3gov\0\0\34\0\1", 34,
         MSG_NOSIGNAL, NULL, 0) = 34 <0.000022>
   26485 1432927233.944882 poll([{fd=7, events=POLLIN}], 1, 4999 <unfinished ...>
   

   After approximately five seconds, the connection times out:

   26485 1432927238.949004 <... poll resumed> ) = 0 (Timeout) <5.004097>
   

   Another connection is made to the DNS server at 10.1.2.5 and another query is sent to that server:

   26485 1432927238.949071 socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 8 <0.000033>
   26485 1432927238.949158 connect(8, {sa_family=AF_INET, sin_port=htons(53),
         sin_addr=inet_addr("10.1.2.5")}, 16) = 0 <0.000025>
   26485 1432927238.949242 poll([{fd=8, events=POLLOUT}], 1, 0) = 1 ([{fd=8, revents=POLLOUT}]) <0.000017>
   26485 1432927238.949311 sendto(8, "UV\1\0\0\1\0\0\0\0\0\0\10dc1-bg\3example\3com\0\0\1\0\1", 34,
         MSG_NOSIGNAL, NULL, 0) = 34 <0.000034>
   26485 1432927238.949405 poll([{fd=8, events=POLLIN|POLLOUT}], 1, 5000) = 1
         ([{fd=8, revents=POLLOUT}]) <0.000017>
   26485 1432927238.949537 sendto(8, "\217T\1\0\0\1\0\0\0\0\0\0\10dc1-bg\3example\3com\0\0\34\0\1", 34,
         MSG_NOSIGNAL, NULL, 0) = 34 <0.000022>
   26485 1432927238.949641 poll([{fd=8, events=POLLIN}], 1, 4999) = 1 ([{fd=8, revents=POLLIN}]) <0.001390>
   26485 1432927238.951117 ioctl(8, FIONREAD, [107]) = 0 <0.000020>
   

   This time, a response is received from the DNS server immediately:

   26485 1432927238.951191 recvfrom(8, "...", 2048, 0,
         {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.1.2.5")}, [16]) = 107 <0.000022>
   

This five-second delay is repeated for each of the printers that are loaded as part of the CUPS startup process.
So diagnosing and resolving the issue with the DNS server should also resolve the issue with CUPS startup.