[cups] High Sierra and CUPS SMB printing

Fri Mar 16 08:20:32 PDT 2018

Stephan,

This is a Xerox driver issue we are tracking, and seems to be caused by the CUPS command filter included with the Xerox driver.

Try copying the PPD from /etc/cups/ppd and deleting the following lines from it using your favorite text editor:

    *cupsFilter: "application/vnd.cups-command ..."
    *cupsCommands: "..."

and then update CUPS with the changes:

    lpadmin -p queuename -i filename.ppd

> On Mar 16, 2018, at 8:36 AM, Jonker, S.A. (Stephan) <S.A.Jonker at uu.nl> wrote:
> 
> I am having troubles with printing on our Universiy's windows spools printer the moment I upgraded to MacOSX High Sierra (OSX 10.13) in september last year (!) and updating the Xerox printer driver, and it all revolves around an error AUTH_INFO_REQUIRED that is generated seemingly randomly by whatever…. I have no clue, started a thread at apple:
> https://discussions.apple.com/thread/8114926
> Lots of people seem to be in trouble around the world, in most cases academic environments, but it is very very hard to get through both Apple and Xerox. I have seen three newer versions of the Xerox driver and some OSX upgrades, but nothing works. I can print with the xerox driver to an HP printer and it works fine, When I print with the Apple generic postscript driver to the Xerox spools server it works fine, but i cannot print A3 or use any other fancy Xerox feature so it is basically useless to use this generic postscript driver, it is not an option. I don’t know if this is a CUPS issue or an SMB issue, or the windows printserver at our university, or a combination of these. I am completely ignorant about anything under the hood of my Mac in terms of Unix-SMB-CUPS, but I am quite frustrated about what I have been dealing with for the last 6 months.
> 
> The problems starts when i try to print using the Xerox driver on the windows spools queue, via our so-called Xerox follow me system smb://print.uuu.nl. I work around it by typing the  cancel -a “printername” command whenever the cups qeue is stuck, get my prints done, until the cups is dirty again. I check its “stuck” status with lpsta -o to see if I am in trouble. Trouble = print job generated every minute or so, up to over 4000 files in the cups file.
> 
> I tried to find out how I can trigger the problem, but I it appears to emerge randomly. Recently I found out that an AUTH_INFO_REQUIRED error is generated the moment I choose the print command in any document. I do not have to print really, the error emerges the moment the print dialogue window pops up. If I start the print dialogue with an alternative printer as default nothing happens, but the moment I change to the SMB printer the error emerges instantaneously.
> 
> When I look at the error log (see below), and (below below) the logs when log level was set to debug, I see the following loops basically continuing infinitely. Is there anybody who could help or guide me as to where to look for the solution?
> 
> Any help is mostly appreciated.
> 
> Stephan Jonker
> 
> E [16/Mar/2018:12:26:12 +0100] [Job 543] Unable to handle AUTH_INFO_REQUIRED
> E [16/Mar/2018:12:26:16 +0100] [Job 543] Job stopped due to filter errors; please consult the error_log file for details.
> D [16/Mar/2018:12:26:16 +0100] [Job 543] The following messages were recorded from 12:06:33 to 12:26:16
> D [16/Mar/2018:12:26:16 +0100] [Job 543] Adding start banner page "none".
> D [16/Mar/2018:12:26:16 +0100] [Job 543] Queued on "FollowMe" by "jonke".
> D [16/Mar/2018:12:26:16 +0100] [Job 543] File of type application/vnd.cups-command queued by "jonke".
> D [16/Mar/2018:12:26:16 +0100] [Job 543] Adding end banner page "none".
> D [16/Mar/2018:12:26:16 +0100] [Job 543] time-at-processing=1521199572
> D [16/Mar/2018:12:26:16 +0100] [Job 543] 2 filters for job:
> D [16/Mar/2018:12:26:16 +0100] [Job 543] /Library/Printers/Xerox/Filters/commandtoxbds.app/Contents/MacOS/commandtoxbds (application/vnd.cups-command to printer/FollowMe/application/vnd.cups-postscript, cost 0)
> D [16/Mar/2018:12:26:16 +0100] [Job 543] - (printer/FollowMe/application/vnd.cups-postscript to printer/FollowMe, cost 0)
> D [16/Mar/2018:12:26:16 +0100] [Job 543] job-sheets=none,none
> D [16/Mar/2018:12:26:16 +0100] [Job 543] argv[0]="FollowMe"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] argv[1]="543"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] argv[2]="jonke"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] argv[3]="Printer Status"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] argv[4]="1"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] argv[5]="job-uuid=urn:uuid:61cb60a6-762b-3272-42ee-669542366f09 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1521198393 time-at-processing=1521199572 document-name-supplied=Printer\\ Status"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] argv[6]="/private/var/spool/cups/d00543-001"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[0]="<CFProcessPath>"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[1]="CUPS_CACHEDIR=/private/var/spool/cups/cache"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[2]="CUPS_DATADIR=/usr/share/cups"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[3]="CUPS_DOCROOT=/usr/share/doc/cups"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[4]="CUPS_FONTPATH=/usr/share/cups/fonts"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[5]="CUPS_REQUESTROOT=/private/var/spool/cups"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[6]="CUPS_SERVERBIN=/usr/libexec/cups"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[7]="CUPS_SERVERROOT=/private/etc/cups"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[8]="CUPS_STATEDIR=/private/etc/cups"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[9]="HOME=/private/var/spool/cups/tmp"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[10]="PATH=/usr/libexec/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[11]="SERVER_ADMIN=root at stephans-imac.soliscom.uu.nl<mailto:SERVER_ADMIN=root at stephans-imac.soliscom.uu.nl>"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[12]="SOFTWARE=CUPS/2.2.5"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[13]="TMPDIR=/private/var/spool/cups/tmp"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[14]="USER=root"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[15]="CUPS_MAX_MESSAGE=2047"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[16]="CUPS_SERVER=/private/var/run/cupsd"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[17]="CUPS_ENCRYPTION=IfRequested"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[18]="IPP_PORT=631"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[19]="CHARSET=utf-8"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[20]="LANG=en_US.UTF-8"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[21]="APPLE_LANGUAGE=en-US"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[22]="PPD=/private/etc/cups/ppd/FollowMe.ppd"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[23]="RIP_MAX_CACHE=128m"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[24]="CONTENT_TYPE=application/vnd.cups-command"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[25]="DEVICE_URI=smb://print.uu.nl/black"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[26]="PRINTER_INFO=FollowMe"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[27]="PRINTER_LOCATION="
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[28]="PRINTER=FollowMe"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[29]="PRINTER_STATE_REASONS=none"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[30]="CUPS_FILETYPE=document"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[31]="FINAL_CONTENT_TYPE=application/vnd.cups-postscript"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[32]="AUTH_I****"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[33]="AUTH_U****"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[34]="AUTH_P****"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] envp[35]="AUTH_U****"
> D [16/Mar/2018:12:26:16 +0100] [Job 543] Started filter /Library/Printers/Xerox/Filters/commandtoxbds.app/Contents/MacOS/commandtoxbds (PID 8113)
> D [16/Mar/2018:12:26:16 +0100] [Job 543] Started backend /usr/libexec/cups/backend/smb (PID 8114)
> D [16/Mar/2018:12:26:16 +0100] [Job 543] smb will run as user 501
> D [16/Mar/2018:12:26:16 +0100] [Job 543] print job starting...
> D [16/Mar/2018:12:26:16 +0100] [Job 543] adding fd 0 to xpc_dictionary
> D [16/Mar/2018:12:26:16 +0100] [Job 543] adding fd 2 to xpc_dictionary
> D [16/Mar/2018:12:26:16 +0100] [Job 543] adding fd 4 to xpc_dictionary
> D [16/Mar/2018:12:26:16 +0100] [Job 543] Starting backend /usr/libexec/cups/apple/smb...
> D [16/Mar/2018:12:26:16 +0100] [Job 543] Started backend (PID 8115)
> D [16/Mar/2018:12:26:16 +0100] [Job 543] print job started
> D [16/Mar/2018:12:26:16 +0100] [Job 543] waiting for print job (pid = 8115) to finish
> D [16/Mar/2018:12:26:16 +0100] [Job 543] adding fd 2 to xpc_dictionary
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: +connecting-to-device
> D [16/Mar/2018:12:26:16 +0100] [Job 543] Connecting to printer...
> D [16/Mar/2018:12:26:16 +0100] [Job 543] Set job-printer-state-message to "Connecting to printer...", current level=INFO
> D [16/Mar/2018:12:26:16 +0100] [Job 543] Looking up \"print.uu.nl<http://print.uu.nl>\"...
> D [16/Mar/2018:12:26:16 +0100] [Job 543] Set job-printer-state-message to "Unable to handle AUTH_INFO_REQUIRED", current level=ERROR
> D [16/Mar/2018:12:26:16 +0100] [Job 543] PID 8113 (/Library/Printers/Xerox/Filters/commandtoxbds.app/Contents/MacOS/commandtoxbds) stopped with status 1.
> D [16/Mar/2018:12:26:16 +0100] [Job 543] Hint: Try setting the LogLevel to "debug" to find out more.
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -connecting-to-device
> D [16/Mar/2018:12:26:16 +0100] [Job 543] Connected to printer...
> D [16/Mar/2018:12:26:16 +0100] [Job 543] job id is 234...
> D [16/Mar/2018:12:26:16 +0100] [Job 543] Sending print data...
> D [16/Mar/2018:12:26:16 +0100] [Job 543] Waiting for job to complete...
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -apple-job-blocked
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -job-completed-successfully
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -job-canceled-at-device
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -processing-to-stop-point
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -apple-job-error
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -offline-report
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -media-needed-warning
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -paused-report
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -job-completed-successfully
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -job-printing
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -apple-job-restart
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -job-incoming
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -apple-job-intervention
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -apple-printer-busy
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -door-open-warning
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -apple-printer-errorstate
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -apple-printer-warming-up
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -apple-printer-active
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -apple-printer-manual-feed
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -apple-printer-unavailable
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -marker-supply-empty-report
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -offline-report
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -output-area-full-report
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -interpreter-resource-unavailable-warning
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -apple-printer-page-punt
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -media-jam-warning
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -media-empty-warning
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -media-jam-warning
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -paused-report
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -apple-printer-deleting
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -apple-printer-lowpower
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -apple-printer-printing
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -apple-printer-processing
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -offline-report
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -apple-printer-unknown
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -toner-low-report
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -apple-printer-intervention
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -apple-printer-waiting
> D [16/Mar/2018:12:26:16 +0100] [Job 543] STATE: -apple-printer-warming-up
> D [16/Mar/2018:12:26:16 +0100] [Job 543] Cleaning up printer-state-reasons...
> D [16/Mar/2018:12:26:16 +0100] [Job 543] Ready to print.
> D [16/Mar/2018:12:26:16 +0100] [Job 543] backend (PID=8115) exited with no errors
> D [16/Mar/2018:12:26:16 +0100] [Job 543] smb backend will exit with status 0
> D [16/Mar/2018:12:26:16 +0100] [Job 543] PID 8114 (/usr/libexec/cups/backend/smb) exited with no errors.
> D [16/Mar/2018:12:26:16 +0100] [Job 543] End of messages
> D [16/Mar/2018:12:26:16 +0100] [Job 543] printer-state=3(idle)
> D [16/Mar/2018:12:26:16 +0100] [Job 543] printer-state-message="Ready to print."
> D [16/Mar/2018:12:26:16 +0100] [Job 543] printer-state-reasons=none
> E [16/Mar/2018:12:26:16 +0100] [Job 544] Unable to handle AUTH_INFO_REQUIRED
> E [16/Mar/2018:12:26:21 +0100] [Job 544] Job stopped due to filter errors; please consult the error_log file for details.
> D [16/Mar/2018:12:26:21 +0100] [Job 544] The following messages were recorded from 12:07:12 to 12:26:21
> D [16/Mar/2018:12:26:21 +0100] [Job 544] Adding start banner page "none".
> D [16/Mar/2018:12:26:21 +0100] [Job 544] Queued on "FollowMe" by "jonke”.
> 
> Log lever set to debug
> When printing from Word
> D [16/Mar/2018:13:28:00 +0100] [Client 1678] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=2575, response=0x7fe3b290ec80(IPP_STATE_DATA), pipe_pid=0, file=-1
> D [16/Mar/2018:13:28:00 +0100] [Client 1678] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
> D [16/Mar/2018:13:28:00 +0100] [Client 1678] bytes=0, http_state=0, data_remaining=2575
> D [16/Mar/2018:13:28:00 +0100] [Client 1678] Flushing write buffer.
> D [16/Mar/2018:13:28:00 +0100] [Client 1678] New state is HTTP_STATE_WAITING
> D [16/Mar/2018:13:28:00 +0100] [Client 1678] Waiting for request.
> D [16/Mar/2018:13:28:00 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
> D [16/Mar/2018:13:28:00 +0100] [Client 1678] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
> D [16/Mar/2018:13:28:00 +0100] [Client 1678] Closing connection.
> D [16/Mar/2018:13:28:00 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
> D [16/Mar/2018:13:28:00 +0100] [Client 1679] Server address is "/private/var/run/cupsd".
> D [16/Mar/2018:13:28:00 +0100] [Client 1679] Accepted from localhost (Domain Microsoft Word[843])
> D [16/Mar/2018:13:28:00 +0100] [Client 1679] Waiting for request.
> D [16/Mar/2018:13:28:00 +0100] [Client 1679] POST / HTTP/1.1
> D [16/Mar/2018:13:28:00 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
> D [16/Mar/2018:13:28:00 +0100] [Client 1679] Read: status=200, state=6
> D [16/Mar/2018:13:28:00 +0100] [Client 1679] No authentication data provided.
> D [16/Mar/2018:13:28:00 +0100] [Client 1679] 2.0 Get-Jobs 1628242
> D [16/Mar/2018:13:28:00 +0100] Get-Jobs ipp://localhost/printers/FollowMe
> D [16/Mar/2018:13:28:00 +0100] [Client 1679] Returning IPP successful-ok for Get-Jobs (ipp://localhost/printers/FollowMe) from localhost
> D [16/Mar/2018:13:28:00 +0100] [Client 1679] Content-Length: 2575
> D [16/Mar/2018:13:28:00 +0100] [Client 1679] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
> D [16/Mar/2018:13:28:00 +0100] [Client 1679] con->http=0x7fe3b4804400
> 
> When printing from Preview
> D [16/Mar/2018:13:29:59 +0100] [Client 2994] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=98, response=0x7fe3b2b02860(IPP_STATE_DATA), pipe_pid=0, file=-1
> D [16/Mar/2018:13:29:59 +0100] [Client 2994] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
> D [16/Mar/2018:13:29:59 +0100] [Client 2994] bytes=0, http_state=0, data_remaining=98
> D [16/Mar/2018:13:29:59 +0100] [Client 2994] Flushing write buffer.
> D [16/Mar/2018:13:29:59 +0100] [Client 2994] New state is HTTP_STATE_WAITING
> D [16/Mar/2018:13:29:59 +0100] [Client 2994] Waiting for request.
> D [16/Mar/2018:13:29:59 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
> D [16/Mar/2018:13:29:59 +0100] [Client 2994] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
> D [16/Mar/2018:13:29:59 +0100] [Client 2994] Closing connection.
> D [16/Mar/2018:13:29:59 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
> D [16/Mar/2018:13:29:59 +0100] [Client 2995] Server address is "/private/var/run/cupsd".
> D [16/Mar/2018:13:29:59 +0100] [Client 2995] Accepted from localhost (Domain Preview[312])
> D [16/Mar/2018:13:29:59 +0100] [Client 2995] Waiting for request.
> D [16/Mar/2018:13:29:59 +0100] [Client 2995] POST /printers/FollowMe HTTP/1.1
> D [16/Mar/2018:13:29:59 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
> D [16/Mar/2018:13:29:59 +0100] [Client 2995] Read: status=200, state=6
> D [16/Mar/2018:13:29:59 +0100] [Client 2995] No authentication data provided.
> D [16/Mar/2018:13:29:59 +0100] [Client 2995] 2.0 Get-Printer-Attributes 172
> D [16/Mar/2018:13:29:59 +0100] Get-Printer-Attributes ipp://localhost/printers/FollowMe
> D [16/Mar/2018:13:29:59 +0100] [Client 2995] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost/printers/FollowMe) from localhost
> D [16/Mar/2018:13:29:59 +0100] [Client 2995] Content-Length: 245
> D [16/Mar/2018:13:29:59 +0100] [Client 2995] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
> D [16/Mar/2018:13:29:59 +0100] [Client 2995] con->http=0x7fe3b4019200
> 
> _______________________________________________
> cups mailing list
> cups at cups.org
> https://lists.cups.org/mailman/listinfo/cups

_________________________________________________________
Michael Sweet, Senior Printing System Engineer