[cups] Attempt printing CUPS jobs to ImageWriter II on Mac OS Catalina

St T <[email protected]>
Newsgroups gmane.comp.printing.cups.general
Message-ID <CAB22qUZxBJ=ymj_DA=y_j2QgXYZZ2nfau83WqbFFxCmpv77yaA@mail.gmail.com> 
I appreciate the help this group has provided others and thought I would
try the same.

GOAL:
Use CUPS v2.3.1 on Mac OS Catalina and print jobs to Apple Imagewriter II.

ENVIRONMENT SETUP:

1/ MacBook Operating System: macOS X Catalina 10.15.7


2/ MacOS CUPS Version Number: 2.3.1 (web admin enabled and accessible
localhost:631)


3/ Local Printer Connection Path:  macbook usb port to Keyspan serial
adapter to apple printer

MacBook Air USB port --> USB:Serial adapter (Tripp Lite Keyspan USH-19) -->
DE9:DIN8 converter cable --> Apple ImageWriter II DIN-8 port


4/ Installed USB to Serial adapter driver: KeyspanUSADriver v4.0
(installed, loaded, showing up in /Extensions and lpinfo as
usb:/dev/usb/KeySerial1)


5/ installed GhostScript v8.71


6/ installed Linux Foundation foomatic-rip v4.06


7/ PPD file: downloaded from http://www.openprinting.org/driver/iwhi (Apple
ImageWriter II) and copied gz version to
/Extensions/Printers/PPDs/Content/Resources


8/ Backend: CoolTerm app (select  usb:/dev/usb/KeySerial1 and Connect
9600:N:8:1)

9/ CUPS printer status:
Name: IW2
Driver: Apple ImageWriter II Foomatic /iwhi (recommended) (color)
Connection: usb: /dev/cu.KeySerial1
Defaults: job-sheets=none, non media=na_letter_8.5x11in sides=one-sided

10/ CUPS updated cupsd.conf to LogLevel debug2 and PreserveJobFiles On
11/ Try and print from Mac OS TextEdit or CUPS web admin interface

PROBLEM:
The print job does not complete. In the CUPS web admin interface the Jobs
status update shows:
"process since Thu Oct 8 22:24:47 2020  "Filter Failed"

For additional information, I looked at the cups log_error output (sorry
for the high number of timestamp log entries) and noticed several EOF
processing errors but I am not certain where I should continue my
investigation.

D [08/Oct/2020:21:34:54 -0700] [Client 16] con->http=0x7fee13013a00

D [08/Oct/2020:21:34:54 -0700] [Client 16] cupsdWriteClient error=0,
used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH,
data_remaining=355, response=0x7fee1251d910(IPP_STATE_DATA), pipe_pid=0,
file=-1

D [08/Oct/2020:21:34:54 -0700] [Client 16] Writing IPP response,
ipp_state=IPP_STATE_DATA, old wused=0, new wused=0

D [08/Oct/2020:21:34:54 -0700] [Client 16] bytes=0, http_state=0,
data_remaining=355

D [08/Oct/2020:21:34:54 -0700] [Client 16] Flushing write buffer.

D [08/Oct/2020:21:34:54 -0700] [Client 16] New state is HTTP_STATE_WAITING

d [08/Oct/2020:21:34:54 -0700] cupsdAddSelect(fd=15, read_cb=0x10275fcbd,
write_cb=0x0, data=0x7fee1300d800)

D [08/Oct/2020:21:34:54 -0700] [Client 16] Waiting for request.

D [08/Oct/2020:21:34:54 -0700] cupsdSetBusyState: newbusy="Active clients
and dirty files", busy="Active clients and dirty files"

d [08/Oct/2020:21:34:54 -0700] select_timeout: JobHistoryUpdate=2147483647

d [08/Oct/2020:21:34:54 -0700] [Client 17] cupsdReadClient: error=0,
used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH,
data_remaining=0, request=0x0(), file=-1

D [08/Oct/2020:21:34:54 -0700] [Client 17] GET /cups.css HTTP/1.1

D [08/Oct/2020:21:34:54 -0700] cupsdSetBusyState: newbusy="Active clients
and dirty files", busy="Active clients and dirty files"

D [08/Oct/2020:21:34:54 -0700] [Client 17] Read: status=200, state=3

d [08/Oct/2020:21:34:54 -0700] cupsdFindBest: uri="/cups.css", limit=2...

d [08/Oct/2020:21:34:54 -0700] cupsdFindBest: Location /admin/log(10) Limit
7f

d [08/Oct/2020:21:34:54 -0700] cupsdFindBest: Location /admin/conf(11)
Limit 7f

d [08/Oct/2020:21:34:54 -0700] cupsdFindBest: Location /admin(6) Limit 7f

d [08/Oct/2020:21:34:54 -0700] cupsdFindBest: Location /(1) Limit 7f

d [08/Oct/2020:21:34:54 -0700] cupsdFindBest: best=/

d [08/Oct/2020:21:34:54 -0700] [Client 17] con->uri="/cups.css",
con->best=0x7fee125041d0(/)

D [08/Oct/2020:21:34:54 -0700] [Client 17] No authentication data provided.

d [08/Oct/2020:21:34:54 -0700] cupsdIsAuthorized: con->uri="/cups.css",
con->best=0x7fee125041d0(/)

d [08/Oct/2020:21:34:54 -0700] cupsdIsAuthorized: level=CUPSD_AUTH_ANON,
type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0

d [08/Oct/2020:21:34:54 -0700] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...

D [08/Oct/2020:21:34:54 -0700] [Client 17] Processing GET /cups.css

d [08/Oct/2020:21:34:54 -0700] [Client 17] get_file:
filestats=0x7ffeed498760, filename=0x7ffeed498b60, len=1024, returning
"/usr/share/doc/cups/cups.css".

D [08/Oct/2020:21:34:54 -0700] [Client 17]
filename="/usr/share/doc/cups/cups.css", type=text/css

d [08/Oct/2020:21:34:54 -0700] [Client 17] is_cgi:
filename="/usr/share/doc/cups/cups.css", filestats=0x7ffeed498760,
type=text/css, returning 0.

d [08/Oct/2020:21:34:54 -0700] [Client 17] check_if_modified:
filestats=0x7ffeed498760(11092, 1569468623)) If-Modified-Since="Thu, 26 Sep
2019 03:30:23 GMT"

d [08/Oct/2020:21:34:54 -0700] [Client 17] cupsdSendError code=304,
auth_type=0

D [08/Oct/2020:21:34:54 -0700] [Client 17] cupsdSendHeader: code=304,
type="(null)", auth_type=0

D [08/Oct/2020:21:34:54 -0700] cupsdSetBusyState: newbusy="Active clients
and dirty files", busy="Active clients and dirty files"

d [08/Oct/2020:21:34:54 -0700] select_timeout: JobHistoryUpdate=2147483647

D [08/Oct/2020:21:34:54 -0700] [CGI] cgiClearVariables called.

D [08/Oct/2020:21:34:54 -0700] [CGI] cgiSetVariable: SECTION=\"printers\"

D [08/Oct/2020:21:34:54 -0700] [CGI] cgiSetVariable: TOTAL=\"1\"

d [08/Oct/2020:21:34:54 -0700] [CGI]
cgiSetIPPObjectVars(obj=0x7fdfc7604440, prefix=\"(null)\", element=0)

D [08/Oct/2020:21:34:54 -0700] [CGI] cgiSetVariable:
SERVER_NAME=\"localhost\"

D [08/Oct/2020:21:34:54 -0700] [CGI] cgiSetVariable: REMOTE_USER=\"st\"

D [08/Oct/2020:21:34:54 -0700] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS
v2.3.1\"

D [08/Oct/2020:21:34:54 -0700] [CGI] cgiSetArray:
job_printer_name[0]=\"iw2\"

D [08/Oct/2020:21:34:54 -0700] [CGI] cgiSetArray:
job_printer_uri[0]=\"/printers/iw2\"

d [08/Oct/2020:21:34:54 -0700] [CGI] job_printer_uri[0]=\"/printers/iw2\"

D [08/Oct/2020:21:34:54 -0700] [CGI] cgiSetArray:
time_at_completed[0]=\"novalue\"

d [08/Oct/2020:21:34:54 -0700] [CGI] time_at_completed[0]=\"novalue\"

d [08/Oct/2020:21:34:54 -0700] select_timeout: JobHistoryUpdate=2147483647

D [08/Oct/2020:21:34:54 -0700] [CGI] cgiSetArray: time_at_creation[0]=\"Thu
Oct  8 21:34:52 2020\"

d [08/Oct/2020:21:34:54 -0700] [CGI] time_at_creation[0]=\"Thu Oct  8
21:34:52 2020\"

D [08/Oct/2020:21:34:54 -0700] [CGI] cgiSetArray:
time_at_processing[0]=\"Thu Oct  8 21:34:52 2020\"

d [08/Oct/2020:21:34:54 -0700] [CGI] time_at_processing[0]=\"Thu Oct  8
21:34:52 2020\"

D [08/Oct/2020:21:34:54 -0700] [CGI] cgiSetArray: job_id[0]=\"11\"

d [08/Oct/2020:21:34:54 -0700] [CGI] job_id[0]=\"11\"

D [08/Oct/2020:21:34:54 -0700] [CGI] cgiSetArray: job_state[0]=\"5\"

d [08/Oct/2020:21:34:54 -0700] [CGI] job_state[0]=\"5\"

D [08/Oct/2020:21:34:54 -0700] [CGI] cgiSetArray:
job_impressions_completed[0]=\"0\"

d [08/Oct/2020:21:34:54 -0700] [CGI] job_impressions_completed[0]=\"0\"

D [08/Oct/2020:21:34:54 -0700] [CGI] cgiSetArray: job_k_octets[0]=\"1\"

d [08/Oct/2020:21:34:54 -0700] [CGI] job_k_octets[0]=\"1\"

D [08/Oct/2020:21:34:54 -0700] [CGI] cgiSetArray:
job_hold_until[0]=\"no-hold\"

d [08/Oct/2020:21:34:54 -0700] [CGI] job_hold_until[0]=\"no-hold\"

d [08/Oct/2020:21:34:54 -0700] select_timeout: JobHistoryUpdate=2147483647

D [08/Oct/2020:21:34:54 -0700] [CGI] cgiSetArray:
job_printer_state_message[0]=\"Filter failed\"

d [08/Oct/2020:21:34:54 -0700] [CGI] job_printer_state_message[0]=\"Filter
failed\"

D [08/Oct/2020:21:34:54 -0700] [CGI] cgiSetVariable: PRINTER_NAME=\"iw2\"

D [08/Oct/2020:21:34:54 -0700] [CGI] cgiSetVariable:
PRINTER_URI_SUPPORTED=\"/printers/iw2\"

D [08/Oct/2020:21:34:54 -0700] [CGI] cgiSetVariable:
THISURL=\"/printers/iw2\"

D [08/Oct/2020:21:34:54 -0700] [CGI] cgiSetVariable: SEARCH_DEST=\"iw2\"

d [08/Oct/2020:21:34:54 -0700] [CGI]
cgiCopyTemplateLang(tmpl=\"search.tmpl\")

d [08/Oct/2020:21:34:54 -0700] [CGI] lang=\"en_US.UTF8\",
locale=\"/en_US\"...

d [08/Oct/2020:21:34:54 -0700] [CGI] Template file is
\"/usr/share/cups/templates/search.tmpl\"...

d [08/Oct/2020:21:34:54 -0700] [CGI] Starting at file position 0...

d [08/Oct/2020:21:34:54 -0700] [CGI] \"{SECTION}\" at 24...

d [08/Oct/2020:21:34:54 -0700] [CGI] \"{?SEARCH_DEST}\" at 39...

d [08/Oct/2020:21:34:54 -0700] select_timeout: JobHistoryUpdate=2147483647

d [08/Oct/2020:21:34:54 -0700] [CGI] Starting \"{WHICH_JOBS?\" at 67,
result=0...

d [08/Oct/2020:21:34:54 -0700] [CGI] Skip first part...

d [08/Oct/2020:21:34:54 -0700] [CGI] Starting at file position 67...

d [08/Oct/2020:21:34:54 -0700] [CGI] \"{WHICH_JOBS}\" at 125...

d [08/Oct/2020:21:34:54 -0700] [CGI] Returning at file position 128 on
character \':\'...

d [08/Oct/2020:21:34:54 -0700] [CGI] Output second part...

d [08/Oct/2020:21:34:54 -0700] [CGI] Starting at file position 128...

d [08/Oct/2020:21:34:54 -0700] [CGI] Returning at file position 129 on
character \'}\'...

d [08/Oct/2020:21:34:54 -0700] [CGI] Finished \"{WHICH_JOBS?\",
out=0x7fff97850e28...

d [08/Oct/2020:21:34:54 -0700] [CGI] Starting \"{ORDER?\" at 137,
result=0...

d [08/Oct/2020:21:34:54 -0700] [CGI] Skip first part...

d [08/Oct/2020:21:34:54 -0700] [CGI] Starting at file position 137...

d [08/Oct/2020:21:34:54 -0700] [CGI] \"{ORDER}\" at 185...

d [08/Oct/2020:21:34:54 -0700] [CGI] Returning at file position 188 on
character \':\'...

d [08/Oct/2020:21:34:54 -0700] [CGI] Output second part...

d [08/Oct/2020:21:34:54 -0700] [CGI] Starting at file position 188...

d [08/Oct/2020:21:34:54 -0700] [CGI] Returning at file position 189 on
character \'}\'...

d [08/Oct/2020:21:34:54 -0700] [CGI] Finished \"{ORDER?\",
out=0x7fff97850e28...

d [08/Oct/2020:21:34:54 -0700] [CGI] Starting \"{SEARCH_DEST?\" at 235,
result=1...

d [08/Oct/2020:21:34:54 -0700] [CGI] Output first part...

d [08/Oct/2020:21:34:54 -0700] [CGI] Starting at file position 235...

d [08/Oct/2020:21:34:54 -0700] [CGI] \"{SEARCH_DEST}\" at 248...

d [08/Oct/2020:21:34:54 -0700] [CGI] Returning at file position 249 on
character \':\'...

d [08/Oct/2020:21:34:54 -0700] [CGI] Skip second part...

d [08/Oct/2020:21:34:54 -0700] [CGI] Starting at file position 249...

d [08/Oct/2020:21:34:54 -0700] [CGI] Starting \"{SECTION=classes\" at 266,
result=0...

d [08/Oct/2020:21:34:54 -0700] [CGI] Skip first part...

d [08/Oct/2020:21:34:54 -0700] [CGI] Starting at file position 266...

d [08/Oct/2020:21:34:54 -0700] [Client 14] write_pipe: CGI output on fd 14.

d [08/Oct/2020:21:34:54 -0700] cupsdRemoveSelect(fd=14)

d [08/Oct/2020:21:34:54 -0700] cupsdAddSelect(fd=12, read_cb=0x0,
write_cb=0x102764a7a, data=0x7fee1400ea00)

D [08/Oct/2020:21:34:54 -0700] [Client 14] CGI data ready to be sent.

d [08/Oct/2020:21:34:54 -0700] select_timeout: JobHistoryUpdate=2147483647

d [08/Oct/2020:21:34:54 -0700] [CGI] Returning at file position 274 on
character \':\'...

d [08/Oct/2020:21:34:54 -0700] [CGI] Output second part...

d [08/Oct/2020:21:34:54 -0700] [CGI] Starting at file position 274...

d [08/Oct/2020:21:34:54 -0700] [CGI] Starting \"{SECTION=jobs\" at 288,
result=0...

d [08/Oct/2020:21:34:54 -0700] [CGI] Skip first part...

d [08/Oct/2020:21:34:54 -0700] [CGI] Starting at file position 288...

d [08/Oct/2020:21:34:54 -0700] [CGI] Returning at file position 293 on
character \':\'...

d [08/Oct/2020:21:34:54 -0700] [CGI] Output second part...

d [08/Oct/2020:21:34:54 -0700] [CGI] Starting at file position 293...

d [08/Oct/2020:21:34:54 -0700] [CGI] Returning at file position 302 on
character \'}\'...

d [08/Oct/2020:21:34:54 -0700] [CGI] Finished \"{SECTION=jobs\", out=0x0...

d [08/Oct/2020:21:34:54 -0700] [CGI] Returning at file position 303 on
character \'}\'...

d [08/Oct/2020:21:34:54 -0700] [CGI] Finished \"{SECTION=classes\",
out=0x0...

d [08/Oct/2020:21:34:54 -0700] [CGI] Returning at file position 304 on
character \'}\'...

d [08/Oct/2020:21:34:54 -0700] [CGI] Finished \"{SEARCH_DEST?\",
out=0x7fff97850e28...

d [08/Oct/2020:21:34:54 -0700] [CGI] \"{?QUERY}\" at 359...

d [08/Oct/2020:21:34:54 -0700] [CGI] \"{SECTION}\" at 415...

d [08/Oct/2020:21:34:54 -0700] [CGI] Returning at file position 530 on
EOF...

d [08/Oct/2020:21:34:54 -0700] [CGI]
cgiCopyTemplateLang(tmpl=\"jobs-header.tmpl\")

d [08/Oct/2020:21:34:54 -0700] [CGI] lang=\"en_US.UTF8\",
locale=\"/en_US\"...

d [08/Oct/2020:21:34:54 -0700] [CGI] Template file is
\"/usr/share/cups/templates/jobs-header.tmpl\"...

d [08/Oct/2020:21:34:54 -0700] [CGI] Starting at file position 0...

d [08/Oct/2020:21:34:54 -0700] [CGI] Starting \"{?which_jobs=\" at 14,
result=1...

d [08/Oct/2020:21:34:54 -0700] [CGI] Output first part...

d [08/Oct/2020:21:34:54 -0700] [CGI] Starting at file position 14...

d [08/Oct/2020:21:34:54 -0700] [CGI] Returning at file position 15 on
character \':\'...

d [08/Oct/2020:21:34:54 -0700] [CGI] Skip second part...

d [08/Oct/2020:21:34:54 -0700] [CGI] Starting at file position 15...

d [08/Oct/2020:21:34:54 -0700] [CGI] Starting \"{?printer_name=\" at 45,
result=0...

d [08/Oct/2020:21:34:54 -0700] [CGI] Skip first part...

d [08/Oct/2020:21:34:54 -0700] [CGI] Starting at file position 45...

d [08/Oct/2020:21:34:54 -0700] [CGI] Returning at file position 51 on
character \':\'...

d [08/Oct/2020:21:34:54 -0700] [CGI] Output second part...

d [08/Oct/2020:21:34:54 -0700] [CGI] Starting at file position 51...

d [08/Oct/2020:21:34:54 -0700] [CGI] \"{printer_uri_supported}\" at 74...

d [08/Oct/2020:21:34:54 -0700] [CGI] Returning at file position 75 on
character \'}\'...

d [08/Oct/2020:21:34:54 -0700] [CGI] Finished \"{?printer_name=\",
out=0x0...

d [08/Oct/2020:21:34:54 -0700] [CGI] Returning at file position 144 on
character \'}\'...

d [08/Oct/2020:21:34:54 -0700] [CGI] Finished \"{?which_jobs=\",
out=0x7fff97850e28...

d [08/Oct/2020:21:34:54 -0700] [CGI] Starting \"{?which_jobs=completed\" at
168, result=0...

d [08/Oct/2020:21:34:54 -0700] [CGI] Skip first part...

d [08/Oct/2020:21:34:54 -0700] [CGI] Starting at file position 168...

D [08/Oct/2020:21:34:54 -0700] [Client 14] con->http=0x7fee14017a00

D [08/Oct/2020:21:34:54 -0700] [Client 14] cupsdWriteClient error=0,
used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED,
data_remaining=0, response=0x0(), pipe_pid=731, file=14

d [08/Oct/2020:21:34:54 -0700] cupsdAddSelect(fd=14, read_cb=0x10276492a,
write_cb=0x0, data=0x7fee1400ea00)

D [08/Oct/2020:21:34:54 -0700] [Client 14] Waiting for CGI data.


Thank you!
ST
_______________________________________________
cups mailing list
[email protected]
https://lists.cups.org/mailman/listinfo/cups
lmpx.com only provides a reader for public news (NNTP) servers. It is not affiliated with the servers or forums shown here and is not responsible for the content of articles, which is written by their respective authors.