[cups] High Sierra and CUPS SMB printing

Fri Mar 16 05:36:26 PDT 2018

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