[cups] cups daemon stops working

Fri Sep 29 03:48:55 PDT 2017

Hi.

Last night we encountered (second time in a week) a problem with one of our cups instances. Here excerpts from our (debug-)lpr.log:
—

Sep 28 17:47:23 mycups cupsd[31915]: [Client 23] Waiting for CGI data.
Sep 28 17:47:23 mycups cupsd[31915]: cupsd is not idle any more, canceling shutdown.
Sep 28 17:47:23 mycups cupsd[31915]: [CGI] cgiSetArray: job_printer_name[45]="R053"
Sep 28 17:47:23 mycups cupsd[31915]: [CGI] cgiSetArray: job_printer_uri[45]="/printers/R053"
Sep 28 17:47:23 mycups cupsd[31915]: [CGI] cgiSetArray: job_originating_user_name[45]="Spooler"
Sep 28 17:47:23 mycups cupsd[31915]: [CGI] cgiSetArray: job_name[45]="Untitled"
Sep 28 17:47:23 mycups cupsd[31915]: [CGI] cgiSetArray: time_at_creation[45]="Thu 28 Sep 2017 01:18:18 PM EDT"
Sep 28 17:47:23 mycups cupsd[31915]: [CGI] cgiSetArray: time_at_processing[45]="Thu 28 Sep 2017 01:18:19 PM EDT"
Sep 28 17:47:23 mycups cupsd[31915]: [CGI] cgiSetArray: time_at_completed[45]="Thu 28 Sep 2017 01:18:19 PM EDT"
Sep 28 17:47:23 mycups cupsd[31915]: [CGI] cgiSetArray: job_id[45]="1914042"
Sep 28 17:47:23 mycups cupsd[31915]: [CGI] cgiSetArray: job_state[45]="9"
Sep 28 17:47:23 mycups cupsd[31915]: [CGI] cgiSetArray: job_media_sheets_completed[45]="1"
Sep 28 17:47:23 mycups cupsd[31915]: [CGI] cgiSetArray: job_k_octets[45]="3"
Sep 28 17:47:23 mycups cupsd[31915]: [CGI] cgiSetArray: job_printer_state_message[45]=""
Sep 28 17:47:23 mycups cupsd[31915]: [CGI] cgiSetVariable: THISURL="/jobs/"
Sep 28 17:47:23 mycups cupsd[31915]: [Client 23] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=10040, file=20
Sep 28 17:47:23 mycups cupsd[31915]: [Client 23] Waiting for CGI data.
Sep 28 17:47:23 mycups cupsd[31915]: [Client 21] CGI data ready to be sent.
Sep 28 17:47:23 mycups cupsd[31915]: cupsd is not idle any more, canceling shutdown.
Sep 28 17:47:23 mycups cupsd[31915]: [Client 21] cupsdWriteClient error=2, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=10038, file=16
Sep 28 17:47:23 mycups cupsd[31915]: [Client 21] Waiting for CGI data.
Sep 28 17:47:23 mycups cupsd[31915]: cupsd is not idle any more, canceling shutdown.
Sep 28 17:47:23 mycups cupsd[31915]: [Client 21] cupsdWriteClient error=2, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=10038, file=16
Sep 28 17:47:23 mycups cupsd[31915]: [Client 21] Waiting for CGI data.
Sep 28 17:47:23 mycups cupsd[31915]: [Client 23] CGI data ready to be sent.
Sep 28 17:47:23 mycups cupsd[31915]: cupsd is not idle any more, canceling shutdown.
Sep 28 17:47:23 mycups cupsd[31915]: [Client 23] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=10040, file=20
Sep 28 17:47:23 mycups cupsd[31915]: [Client 23] Waiting for CGI data.
Sep 28 17:47:23 mycups cupsd[31915]: cupsd is not idle any more, canceling shutdown.
Sep 28 17:47:23 mycups cupsd[31915]: [Client 23] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=10040, file=20

—
… and after about a second with hundreds of the last three lines:
—

Sep 28 17:47:23 mycups cupsd[31915]: [Client 23] Waiting for CGI data.
Sep 28 17:47:23 mycups cupsd[31915]: [Client 22] CGI data ready to be sent.
Sep 28 17:47:23 mycups cupsd[31915]: cupsd is not idle any more, canceling shutdown.
Sep 28 17:47:23 mycups cupsd[31915]: [Client 22] cupsdWriteClient error=2, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid
=10039, file=18
Sep 28 17:47:23 mycups cupsd[31915]: [Client 22] Waiting for CGI data.
Sep 28 17:47:23 mycups systemd[1]: Started CUPS Printing Service.
Sep 28 17:47:23 mycups cups-lpd[10042]: Unknown command-line option "document-format=application/octet-stream" ignored!
Sep 28 17:47:24 mycups cups-lpd[10042]: Connection from my-printjob-generator.server.com<http://my-printjob-generator.server.com> (IPv4 10.1.2.3)
Sep 28 17:47:24 mycups cups-lpd[10042]: Receive print job for R043
Sep 28 17:47:25 mycups cups-lpd[10043]: Unknown command-line option "document-format=application/octet-stream" ignored!
Sep 28 17:47:25 mycups cups-lpd[10043]: Connection from my-printjob-generator-2.server.com<http://my-printjob-generator-2.server.com> (IPv4 123.456.789.012)
Sep 28 17:47:25 mycups cups-lpd[10043]: Receive print job for R102

...
Sep 28 17:50:03 mycups cups-lpd[10052]: Unable to get list of printers - Success
Sep 28 17:50:03 mycups cups-lpd[10052]: Rejecting job because "R052" is not accepting jobs
Sep 28 17:50:03 mycups cups-lpd[10052]: Closing connection

...
Sep 28 17:57:49 mycups cups-lpd[10177]: Unknown command-line option "document-format=application/octet-stream" ignored!
Sep 28 17:57:50 mycups cups-lpd[10177]: Connection from my-printjob-generator-2.server.com<http://my-printjob-generator-2.server.com> (IPv4 123.456.789.012)
Sep 28 17:57:50 mycups cups-lpd[10177]: Receive print job for R059
Sep 28 17:57:50 mycups cups-lpd[10177]: Unable to connect to server: Bad file descriptor
Sep 28 17:57:50 mycups cups-lpd[10177]: Closing connection
Sep 28 17:57:55 mycups cups-lpd[10178]: Unknown command-line option "document-format=application/octet-stream" ignored!
Sep 28 17:57:55 mycups cups-lpd[10178]: Connection from my-printjob-generator.server.com<http://my-printjob-generator.server.com> (IPv4 10.1.2.3)
Sep 28 17:57:55 mycups cups-lpd[10178]: Receive print job for R041
Sep 28 17:57:55 mycups cups-lpd[10178]: Unable to connect to server: Bad file descriptor
Sep 28 17:57:55 mycups cups-lpd[10178]: Closing connection
Sep 28 17:58:04 mycups cups-lpd[10179]: Unknown command-line option "document-format=application/octet-stream" ignored!
Sep 28 17:58:05 mycups cups-lpd[10179]: Connection from my-printjob-generator-2.server.com<http://my-printjob-generator-2.server.com> (IPv4 123.456.789.012)
Sep 28 17:58:05 mycups cups-lpd[10179]: Receive print job for R021
Sep 28 17:58:05 mycups cups-lpd[10179]: Unable to connect to server: Bad file descriptor
Sep 28 17:58:05 mycups cups-lpd[10179]: Closing connection

—

… and so on, until the service got restarted.

System infos:

  *   Debian 8.9
  *   CUPS 1.7.5 (dpkg says 1.7.5-11+deb8u1)
  *   this machine usually has to do 5-7 thousand jobs per hour, most of them received by IPP from localhost, some by lpd from another machine.

Gruß / Regards,
Jan Dreyer