OpenPrinting / cups

OpenPrinting CUPS Sources
https://openprinting.github.io/cups
Apache License 2.0
1.05k stars 187 forks source link

"The printer is not responding." / "Report: printers=%d" - the actual name of the printer #996

Closed jirib closed 3 months ago

jirib commented 3 months ago

Is your feature request related to a problem? Please describe.

A customer asked to provide a RCA for a printing issue. I see that some printer was not available in that time but it is impossible to correlate the supposed issue with a printer and jobs in the history, if the issue is gone. That is, I see some jobs and a vague "The printer is not responding", but since the issue is gone currently, how can I correlate done jobs with the printer in that historical time?

# /var/log/cups/error_log - Last 500 Lines
E [05/Jun/2024:13:50:46 -0400] [Job 1026332] The printer is not responding.
E [05/Jun/2024:13:53:26 -0400] [Job 1026332] The printer is not responding.
E [05/Jun/2024:13:56:06 -0400] [Job 1026332] The printer is not responding.
E [05/Jun/2024:13:58:35 -0400] [Job 1026475] The printer is not responding.
E [05/Jun/2024:13:58:45 -0400] [Job 1026332] The printer is not responding.

In my test debug level with a printer unreachable, even in debug level one cannot see real printer name:

D [26/Jun/2024:10:48:45 +0200] [Job 1] Connection error: Connection refused
W [26/Jun/2024:10:48:45 +0200] [Job 1] The printer is in use.
D [26/Jun/2024:10:48:45 +0200] Report: clients=0
D [26/Jun/2024:10:48:45 +0200] Report: jobs=3
D [26/Jun/2024:10:48:45 +0200] Report: jobs-active=3
D [26/Jun/2024:10:48:45 +0200] Report: printers=1
D [26/Jun/2024:10:48:45 +0200] Report: stringpool-string-count=380
D [26/Jun/2024:10:48:45 +0200] Report: stringpool-alloc-bytes=5088
D [26/Jun/2024:10:48:45 +0200] Report: stringpool-total-bytes=6440

We can see printers=1, but if later some printer would be deleted, the "index" might be changed and again we can't be sure what was the printer (name) in that old historical issue.

Describe the solution you'd like Add name of the printer in the time the cupsd logs the message.

Describe alternatives you've considered

Hardly, since modification of the printers is possible without restart, then even in debug mode, the index might change and the stable reference to printers list is not guaranteed.

Additional context

The whole point is to be able to say that an unreachable printer logged message is really relevant to the printer issue we are interested in. If many printers are present, one cannot say so.

michaelrsweet commented 3 months ago

The printer is logged when the job is created, and again in the argv debug logging for the job.

The debug log reporting the number of printers is just that - logging how many printers, clients, jobs, etc. are present at a given time - and is present to help correlate potential memory leaks (we haven't seen that particular problem in a decade at least...)

jirib commented 3 months ago

Just for the archives:

I [26/Jun/2024:18:08:04 +0200] [Job 36] Queued on "testovic" by "root".
...
D [26/Jun/2024:18:08:04 +0200] [Job 36] Sending job to queue tagged as raw...
D [26/Jun/2024:18:08:04 +0200] [Job 36] job-sheets=none,none
D [26/Jun/2024:18:08:04 +0200] [Job 36] argv[0]="testovic"
D [26/Jun/2024:18:08:04 +0200] [Job 36] argv[1]="36"
D [26/Jun/2024:18:08:04 +0200] [Job 36] argv[2]="root"
D [26/Jun/2024:18:08:04 +0200] [Job 36] argv[3]="fstab"
D [26/Jun/2024:18:08:04 +0200] [Job 36] argv[4]="1"
D [26/Jun/2024:18:08:04 +0200] [Job 36] argv[5]="finishings=3 number-up=1 print-color-mode=monochrome job-uuid=urn:uuid:5d24d8bc-ea58-3dd1-423e-537915e2c4e6 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing
= time-at-creation=1719418084 time-at-processing=1719418084 document-name-supplied=fstab"
D [26/Jun/2024:18:08:04 +0200] [Job 36] argv[6]="/var/spool/cups/d00036-001"
D [26/Jun/2024:18:08:04 +0200] [Job 36] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [26/Jun/2024:18:08:04 +0200] [Job 36] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [26/Jun/2024:18:08:04 +0200] [Job 36] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc-root"
D [26/Jun/2024:18:08:04 +0200] [Job 36] envp[3]="CUPS_REQUESTROOT=/var/spool/cups"
D [26/Jun/2024:18:08:04 +0200] [Job 36] envp[4]="CUPS_SERVERBIN=/usr/lib/cups"
D [26/Jun/2024:18:08:04 +0200] [Job 36] envp[5]="CUPS_SERVERROOT=/etc/cups"
D [26/Jun/2024:18:08:04 +0200] [Job 36] envp[6]="CUPS_STATEDIR=/run/cups"
D [26/Jun/2024:18:08:04 +0200] [Job 36] envp[7]="HOME=/var/spool/cups/tmp"
D [26/Jun/2024:18:08:04 +0200] [Job 36] envp[8]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [26/Jun/2024:18:08:04 +0200] [Job 36] envp[9]="SERVER_ADMIN=root@t14s"
D [26/Jun/2024:18:08:04 +0200] [Job 36] envp[10]="SOFTWARE=CUPS/2.4.10"
D [26/Jun/2024:18:08:04 +0200] [Job 36] envp[11]="TMPDIR=/var/spool/cups/tmp"
D [26/Jun/2024:18:08:04 +0200] [Job 36] envp[12]="USER=root"
D [26/Jun/2024:18:08:04 +0200] [Job 36] envp[13]="CUPS_MAX_MESSAGE=2047"
D [26/Jun/2024:18:08:04 +0200] [Job 36] envp[14]="CUPS_SERVER=/run/cups/cups.sock"
D [26/Jun/2024:18:08:04 +0200] [Job 36] envp[15]="CUPS_ENCRYPTION=IfRequested"
D [26/Jun/2024:18:08:04 +0200] [Job 36] envp[16]="IPP_PORT=631"
D [26/Jun/2024:18:08:04 +0200] [Job 36] envp[17]="CHARSET=utf-8"
D [26/Jun/2024:18:08:04 +0200] [Job 36] envp[18]="LANG=en_US.UTF-8"
D [26/Jun/2024:18:08:04 +0200] [Job 36] envp[19]="PPD=/etc/cups/ppd/testovic.ppd"
D [26/Jun/2024:18:08:04 +0200] [Job 36] envp[20]="CONTENT_TYPE=text/plain"
D [26/Jun/2024:18:08:04 +0200] [Job 36] envp[21]="DEVICE_URI=socket://127.0.0.1:5170"
D [26/Jun/2024:18:08:04 +0200] [Job 36] envp[22]="PRINTER_INFO=testovic"
D [26/Jun/2024:18:08:04 +0200] [Job 36] envp[23]="PRINTER_LOCATION=test room"
D [26/Jun/2024:18:08:04 +0200] [Job 36] envp[24]="PRINTER=testovic"
D [26/Jun/2024:18:08:04 +0200] [Job 36] envp[25]="PRINTER_STATE_REASONS=none"
D [26/Jun/2024:18:08:04 +0200] [Job 36] envp[26]="CUPS_FILETYPE=document"
D [26/Jun/2024:18:08:04 +0200] [Job 36] envp[27]="AUTH_I****"

Thanks for the comment.

jirib commented 3 months ago

Plus, if control file for a job still exists, one can get the name of the printer from it.

# ./cups/testipp /var/spool/cups/*36 | grep -P '^\s*printer-uri' # testipp is a tool from cups source
    printer-uri (uri): ipp://localhost/printers/testovic

# strings /var/spool/cups/*36 | grep '^ipp'
ipp://t14s/printers/testovic!