# Print temp.txt - doesn't print -> Filter failed (on 'lpstat -p') d cupsdAcceptClient(lis=0x81a004b8(11)) Clients=0 D [Client 1] Accepted from localhost (Domain) d cupsdAddSelect(fd=14, read_cb=0x800c91f3, write_cb=(nil), data=0x81a0e7a0) D [Client 1] Waiting for request. d cupsdDeleteCert: Removing certificate for PID 0. D cupsdAddCert: Adding certificate for PID 0 d cupsdAddCert: NumSystemGroups=1 d cupsdCheckJobs: 0 active jobs, sleeping=0, ac-power=-1, reload=0, curtime=1468197880 D Report: clients=1 D Report: jobs=0 D Report: jobs-active=0 D Report: printers=1 D Report: stringpool-string-count=16174 D Report: stringpool-alloc-bytes=8688 D Report: stringpool-total-bytes=289312 d select_timeout: JobHistoryUpdate=0 d [Client 1] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1 D [Client 1] POST / HTTP/1.1 D cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [Client 1] Read: status=200 d cupsdFindBest: uri="/", limit=10... d cupsdFindBest: Location /admin/conf(11) Limit 7f d cupsdFindBest: Location /admin(6) Limit 7f d cupsdFindBest: Location /(1) Limit 7f d cupsdFindBest: best=/ d [Client 1] con->uri="/", con->best=0x819fa0b0(/) D [Client 1] No authentication data provided. d cupsdIsAuthorized: con->uri="/", con->best=0x819fa0b0(/) d cupsdIsAuthorized: level=CUPSD_AUTH_ANON, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0 d cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW... D [Client 1] 2.0 Get-Printer-Attributes 1 d cupsdProcessIPPRequest(0x81a0e7a0[1]): operation_id = 000b D Get-Printer-Attributes ipp://localhost:631/printers/alexPR d get_printer_attrs(0x81a0e7a0[1], ipp://localhost:631/printers/alexPR) d cupsdFindPolicyOp(p=0x81a00b80, op=b(Get-Printer-Attributes)) d cupsdFindPolicyOp: Found wildcard match... d cupsdIsAuthorized: con->uri="/", con->best=0x81a04168((null)) d cupsdIsAuthorized: level=CUPSD_AUTH_ANON, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0 d cupsdIsAuthorized: op=0(0x0000) d cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW... d add_printer_state_reasons(0x81a0e7a0[1], 0x81a0b750[alexPR]) d printer-uri-supported="ipp://localhost/printers/alexPR" d copy_attrs(to=0x81a0fd90, from=0x81a0d868, ra=0x81a0f9a0, group=0, quickcopy=0) d copy_attrs(to=0x81a0fd90, from=0x81a12c70, ra=0x81a0f9a0, group=0, quickcopy=0) d copy_attrs(to=0x81a0fd90, from=0x81a0bee8, ra=0x81a0f9a0, group=0, quickcopy=-2147483648) D [Client 1] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost:631/printers/alexPR) from localhost D [Client 1] Content-Length: 1142 D [Client 1] cupsdSendHeader: code=200, type="application/ipp", auth_type=0 d cupsdAddSelect(fd=14, read_cb=0x800c91f3, write_cb=0x800c897e, data=0x81a0e7a0) d select_timeout: JobHistoryUpdate=0 D [Client 1] con->http=0x81ae1f18 D [Client 1] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1142, response=0x81a0fd90(IPP_STATE_DATA), pipe_pid=0, file=-1 D [Client 1] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0 D [Client 1] bytes=0, http_state=0, data_remaining=1142 D [Client 1] Flushing write buffer. D [Client 1] New state is HTTP_STATE_WAITING d cupsdAddSelect(fd=14, read_cb=0x800c91f3, write_cb=(nil), data=0x81a0e7a0) D [Client 1] Waiting for request. D cupsdSetBusyState: newbusy="Not busy", busy="Active clients" d select_timeout: JobHistoryUpdate=0 d [Client 1] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1 D [Client 1] HTTP_STATE_WAITING Closing for error 32 (Broken pipe) D [Client 1] Closing connection. D cupsdSetBusyState: newbusy="Not busy", busy="Not busy" d cupsdRemoveSelect(fd=14) d cupsdRemoveSelect(fd=-1) d cupsdAcceptClient(lis=0x81a004b8(11)) Clients=0 D [Client 2] Accepted from localhost (Domain) d cupsdAddSelect(fd=14, read_cb=0x800c91f3, write_cb=(nil), data=0x81a0e7a0) D [Client 2] Waiting for request. d select_timeout: JobHistoryUpdate=0 d [Client 2] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1 D [Client 2] POST /printers/alexPR HTTP/1.1 D cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [Client 2] Read: status=200 d cupsdFindBest: uri="/printers/alexPR", limit=10... d cupsdFindBest: Location /admin/conf(11) Limit 7f d cupsdFindBest: Location /admin(6) Limit 7f d cupsdFindBest: Location /(1) Limit 7f d cupsdFindBest: best=/ d [Client 2] con->uri="/printers/alexPR", con->best=0x819fa0b0(/) D [Client 2] No authentication data provided. d cupsdIsAuthorized: con->uri="/printers/alexPR", con->best=0x819fa0b0(/) d cupsdIsAuthorized: level=CUPSD_AUTH_ANON, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0 d cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW... D [Client 2] 2.0 Create-Job 2 d cupsdProcessIPPRequest(0x81a0e7a0[2]): operation_id = 0005 D Create-Job ipp://localhost:631/printers/alexPR d create_job(0x81a0e7a0[2], ipp://localhost:631/printers/alexPR) d add_job(0x81a0e7a0[2], 0x81a0b750(alexPR), (nil)(none/none)) d cupsdFindPolicyOp(p=0x81a00b80, op=5(Create-Job)) d cupsdFindPolicyOp: Found exact match... d cupsdIsAuthorized: con->uri="/printers/alexPR", con->best=0x81a01398((null)) d cupsdIsAuthorized: level=CUPSD_AUTH_ANON, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0 d cupsdIsAuthorized: op=5(Create-Job) d cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW... d check_quotas(0x81a0e7a0[2], 0x81a0b750[alexPR]) D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients" D add_job: requesting-user-name="root" I [Job 1787] Adding start banner page "none". d copy_banner(con=0x81a0e7a0[2], job=0x81a0f918[1787], name="none") d cupsdAddEvent(event=job-created, dest=0x81a0b750(alexPR), job=0x81a0f918(1787), text="Job created.", ...) D Discarding unused job-created event... I [Job 1787] Queued on "alexPR" by "root". D [Client 2] Returning IPP successful-ok for Create-Job (ipp://localhost:631/printers/alexPR) from localhost D [Client 2] Content-Length: 202 D [Client 2] cupsdSendHeader: code=200, type="application/ipp", auth_type=0 d cupsdAddSelect(fd=14, read_cb=0x800c91f3, write_cb=0x800c897e, data=0x81a0e7a0) d select_timeout: JobHistoryUpdate=0 D [Client 2] con->http=0x81ae1f18 D [Client 2] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=202, response=0x81ae5218(IPP_STATE_IDLE), pipe_pid=0, file=-1 D [Client 2] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0 D [Client 2] bytes=0, http_state=0, data_remaining=202 D [Client 2] Flushing write buffer. D [Client 2] New state is HTTP_STATE_WAITING d cupsdAddSelect(fd=14, read_cb=0x800c91f3, write_cb=(nil), data=0x81a0e7a0) D [Client 2] Waiting for request. D cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files" d select_timeout: JobHistoryUpdate=0 d [Client 2] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1 D [Client 2] HTTP_STATE_WAITING Closing for error 32 (Broken pipe) D [Client 2] Closing connection. D cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files" d cupsdRemoveSelect(fd=14) d cupsdRemoveSelect(fd=-1) d cupsdAcceptClient(lis=0x81a004b8(11)) Clients=0 D [Client 3] Accepted from localhost (Domain) d cupsdAddSelect(fd=14, read_cb=0x800c91f3, write_cb=(nil), data=0x81a0e7a0) D [Client 3] Waiting for request. d select_timeout: JobHistoryUpdate=0 d [Client 3] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1 D [Client 3] POST /printers/alexPR HTTP/1.1 D cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files" D [Client 3] Read: status=200 d cupsdFindBest: uri="/printers/alexPR", limit=10... d cupsdFindBest: Location /admin/conf(11) Limit 7f d cupsdFindBest: Location /admin(6) Limit 7f d cupsdFindBest: Location /(1) Limit 7f d cupsdFindBest: best=/ d [Client 3] con->uri="/printers/alexPR", con->best=0x819fa0b0(/) D [Client 3] No authentication data provided. d cupsdIsAuthorized: con->uri="/printers/alexPR", con->best=0x819fa0b0(/) d cupsdIsAuthorized: level=CUPSD_AUTH_ANON, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0 d cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW... D [Client 3] 2.0 Send-Document 3 d cupsdProcessIPPRequest(0x81a0e7a0[3]): operation_id = 0006 D Send-Document ipp://localhost:631/printers/alexPR d send_document(0x81a0e7a0[3], ipp://localhost:631/printers/alexPR) d validate_user(job=1787, con=3, owner="root", username=0xbfc3e26c, userlen=1024) d cupsdFindPolicyOp(p=0x81a00b80, op=6(Send-Document)) d cupsdFindPolicyOp: Found exact match... d cupsdIsAuthorized: con->uri="/printers/alexPR", con->best=0x81a014c0((null)) d cupsdIsAuthorized: owner="root" d cupsdIsAuthorized: level=CUPSD_AUTH_USER, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=2 d cupsdIsAuthorized: op=6(Send-Document) d cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW... D cupsdIsAuthorized: requesting-user-name="root" D [Job 1787] Auto-typing file... D [Job 1787] Request file type is text/plain. d add_file(con=0x81a0e7a0[3], job=1787, filetype=text/plain, compression=0) D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files" I [Job 1787] File of type text/plain queued by "root". I [Job 1787] Adding end banner page "none". d copy_banner(con=(nil)[-1], job=0x81a0f918[1787], name="none") D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files" d cupsdCheckJobs: 1 active jobs, sleeping=0, ac-power=-1, reload=0, curtime=1468197880 d cupsdCheckJobs: Job 1787 - dest="alexPR", printer=(nil), state=3, cancel_time=0, hold_until=1468198180, kill_time=0, pending_cost=0, pending_timeout=0 d start_job(job=0x81a0f918(1787), printer=0x81a0b750(alexPR)) d cupsdSetJobState(job=0x81a0f918(1787), state=3, newstate=5, action=0, message="(null)") D [Job 1787] time-at-processing=1468197880 D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files" D cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files" d cupsdAddEvent(event=printer-state-changed, dest=0x81a0b750(alexPR), job=(nil)(0), text="%s \"%s\" state changed to %s.", ...) D Discarding unused printer-state-changed event... d cupsdSetPrinterReasons(p=0x81a0b750(alexPR),s="-paused" d cupsdSetPrinterReasons(p=0x81a0b750(alexPR),s="-cups-remote-pending,cups-remote-pending-held,cups-remote-processing,cups-remote-stopped,cups-remote-canceled,cups-remote-aborted,cups-remote-completed" d cupsdSetPrinterReasons(p=0x81a0b750(alexPR),s="-cups-missing-filter-warning,cups-insecure-filter-warning" d cupsdCreateProfile(job_id=1787, allow_networking=0) = NULL d cupsdCreateProfile(job_id=1787, allow_networking=1) = NULL d cupsdContinueJob(job=0x81a0f918(1787)): current_file=0, num_files=1 D [Job 1787] 4 filters for job: D [Job 1787] texttopdf (text/plain to application/pdf, cost 32) D [Job 1787] pdftopdf (application/pdf to application/vnd.cups-pdf, cost 66) D [Job 1787] pdftops (application/vnd.cups-pdf to application/vnd.cups-postscript, cost 100) D [Job 1787] hpps (application/vnd.cups-postscript to printer/alexPR, cost 0) D [Job 1787] job-sheets=none,none D [Job 1787] argv[0]="alexPR" D [Job 1787] argv[1]="1787" D [Job 1787] argv[2]="root" D [Job 1787] argv[3]="temp.txt" D [Job 1787] argv[4]="1" D [Job 1787] argv[5]="finishings=3 number-up=1 job-uuid=urn:uuid:51f06e3c-9c93-3e9e-762a-db9af1ca8330 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1468197880 time-at-processing=1468197880 document-name-supplied=temp.txt" D [Job 1787] argv[6]="/var/spool/cups/d01787-001" D [Job 1787] envp[0]="CUPS_CACHEDIR=/var/cache/cups" D [Job 1787] envp[1]="CUPS_DATADIR=/usr/share/cups" D [Job 1787] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc-2.1.4" D [Job 1787] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts" D [Job 1787] envp[4]="CUPS_REQUESTROOT=/var/spool/cups" D [Job 1787] envp[5]="CUPS_SERVERBIN=/usr/lib/cups" D [Job 1787] envp[6]="CUPS_SERVERROOT=/etc/cups" D [Job 1787] envp[7]="CUPS_STATEDIR=/var/run/cups" D [Job 1787] envp[8]="HOME=/var/spool/cups/tmp" D [Job 1787] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin" D [Job 1787] envp[10]="SERVER_ADMIN=root@AlexP8" D [Job 1787] envp[11]="SOFTWARE=CUPS/2.1.4" D [Job 1787] envp[12]="TMPDIR=/var/spool/cups/tmp" D [Job 1787] envp[13]="TZ=America/New_York" D [Job 1787] envp[14]="USER=root" D [Job 1787] envp[15]="CUPS_MAX_MESSAGE=2047" D [Job 1787] envp[16]="CUPS_SERVER=/var/run/cups/cups.sock" D [Job 1787] envp[17]="CUPS_ENCRYPTION=IfRequested" D [Job 1787] envp[18]="IPP_PORT=631" D [Job 1787] envp[19]="CHARSET=utf-8" D [Job 1787] envp[20]="LANG=en_US.UTF-8" D [Job 1787] envp[21]="PPD=/etc/cups/ppd/alexPR.ppd" D [Job 1787] envp[22]="RIP_MAX_CACHE=128m" D [Job 1787] envp[23]="CONTENT_TYPE=text/plain" D [Job 1787] envp[24]="DEVICE_URI=usb://HP/LaserJet%20Pro%20M201dw?serial=VNB3F12583" D [Job 1787] envp[25]="PRINTER_INFO=alexPR" D [Job 1787] envp[26]="PRINTER_LOCATION=" D [Job 1787] envp[27]="PRINTER=alexPR" D [Job 1787] envp[28]="PRINTER_STATE_REASONS=none" D [Job 1787] envp[29]="CUPS_FILETYPE=document" D [Job 1787] envp[30]="FINAL_CONTENT_TYPE=application/vnd.cups-postscript" D [Job 1787] envp[31]="AUTH_I****" d alexPR: File \"/usr/lib/cups/filter/texttopdf\" permissions OK (040755/uid=0/gid=0). d cupsdStartProcess: Preparing to start "/usr/lib/cups/filter/texttopdf", arguments: d cupsdStartProcess: argv[0] = "/usr/lib/cups/daemon/cups-exec" d cupsdStartProcess: argv[1] = "-g" d cupsdStartProcess: argv[2] = "9" d cupsdStartProcess: argv[3] = "-n" d cupsdStartProcess: argv[4] = "0" d cupsdStartProcess: argv[5] = "-u" d cupsdStartProcess: argv[6] = "9" d cupsdStartProcess: argv[7] = "none" d cupsdStartProcess: argv[8] = "/usr/lib/cups/filter/texttopdf" d cupsdStartProcess: argv[9] = "alexPR" d cupsdStartProcess: argv[10] = "1787" d cupsdStartProcess: argv[11] = "root" d cupsdStartProcess: argv[12] = "temp.txt" d cupsdStartProcess: argv[13] = "1" d cupsdStartProcess: argv[14] = "finishings=3 number-up=1 job-uuid=urn:uuid:51f06e3c-9c93-3e9e-762a-db9af1ca8330 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1468197880 time-at-processing=1468197880 document-name-supplied=temp.txt" d cupsdStartProcess: argv[15] = "/var/spool/cups/d01787-001" d cupsdStartProcess: Setting spawn attributes. d cupsdStartProcess: Setting file actions. d cupsdStartProcess: Calling posix_spawn. d cupsdStartProcess: pid=1491 d cupsdStartProcess(command="/usr/lib/cups/filter/texttopdf", argv=0xbfc3a4e4, envp=0xbfc3ac30, infd=-1, outfd=22, errfd=16, backfd=17, sidefd=19, root=0, profile=(nil), job=0x81a0f918(1787), pid=0x81a0f9c4) = 1491 I [Job 1787] Started filter /usr/lib/cups/filter/texttopdf (PID 1491) d alexPR: File \"/usr/lib/cups/filter/pdftopdf\" permissions OK (040755/uid=0/gid=0). d cupsdStartProcess: Preparing to start "/usr/lib/cups/filter/pdftopdf", arguments: d cupsdStartProcess: argv[0] = "/usr/lib/cups/daemon/cups-exec" d cupsdStartProcess: argv[1] = "-g" d cupsdStartProcess: argv[2] = "9" d cupsdStartProcess: argv[3] = "-n" d cupsdStartProcess: argv[4] = "0" d cupsdStartProcess: argv[5] = "-u" d cupsdStartProcess: argv[6] = "9" d cupsdStartProcess: argv[7] = "none" d cupsdStartProcess: argv[8] = "/usr/lib/cups/filter/pdftopdf" d cupsdStartProcess: argv[9] = "alexPR" d cupsdStartProcess: argv[10] = "1787" d cupsdStartProcess: argv[11] = "root" d cupsdStartProcess: argv[12] = "temp.txt" d cupsdStartProcess: argv[13] = "1" d cupsdStartProcess: argv[14] = "finishings=3 number-up=1 job-uuid=urn:uuid:51f06e3c-9c93-3e9e-762a-db9af1ca8330 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1468197880 time-at-processing=1468197880 document-name-supplied=temp.txt" d cupsdStartProcess: Setting spawn attributes. d cupsdStartProcess: Setting file actions. d cupsdStartProcess: Calling posix_spawn. d cupsdStartProcess: pid=1492 d cupsdStartProcess(command="/usr/lib/cups/filter/pdftopdf", argv=0xbfc3a4e4, envp=0xbfc3ac30, infd=21, outfd=24, errfd=16, backfd=17, sidefd=19, root=0, profile=(nil), job=0x81a0f918(1787), pid=0x81a0f9c8) = 1492 I [Job 1787] Started filter /usr/lib/cups/filter/pdftopdf (PID 1492) d alexPR: File \"/usr/lib/cups/filter/pdftops\" permissions OK (040755/uid=0/gid=0). d cupsdStartProcess: Preparing to start "/usr/lib/cups/filter/pdftops", arguments: d cupsdStartProcess: argv[0] = "/usr/lib/cups/daemon/cups-exec" d cupsdStartProcess: argv[1] = "-g" d cupsdStartProcess: argv[2] = "9" d cupsdStartProcess: argv[3] = "-n" d cupsdStartProcess: argv[4] = "0" d cupsdStartProcess: argv[5] = "-u" d cupsdStartProcess: argv[6] = "9" d cupsdStartProcess: argv[7] = "none" d cupsdStartProcess: argv[8] = "/usr/lib/cups/filter/pdftops" d cupsdStartProcess: argv[9] = "alexPR" d cupsdStartProcess: argv[10] = "1787" d cupsdStartProcess: argv[11] = "root" d cupsdStartProcess: argv[12] = "temp.txt" d cupsdStartProcess: argv[13] = "1" d cupsdStartProcess: argv[14] = "finishings=3 number-up=1 job-uuid=urn:uuid:51f06e3c-9c93-3e9e-762a-db9af1ca8330 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1468197880 time-at-processing=1468197880 document-name-supplied=temp.txt" d cupsdStartProcess: Setting spawn attributes. d cupsdStartProcess: Setting file actions. d cupsdStartProcess: Calling posix_spawn. d cupsdStartProcess: pid=1493 d cupsdStartProcess(command="/usr/lib/cups/filter/pdftops", argv=0xbfc3a4e4, envp=0xbfc3ac30, infd=23, outfd=22, errfd=16, backfd=17, sidefd=19, root=0, profile=(nil), job=0x81a0f918(1787), pid=0x81a0f9cc) = 1493 I [Job 1787] Started filter /usr/lib/cups/filter/pdftops (PID 1493) d alexPR: File \"/usr/lib/cups/filter/hpps\" permissions OK (040755/uid=0/gid=0). d cupsdStartProcess: Preparing to start "/usr/lib/cups/filter/hpps", arguments: d cupsdStartProcess: argv[0] = "/usr/lib/cups/daemon/cups-exec" d cupsdStartProcess: argv[1] = "-g" d cupsdStartProcess: argv[2] = "9" d cupsdStartProcess: argv[3] = "-n" d cupsdStartProcess: argv[4] = "0" d cupsdStartProcess: argv[5] = "-u" d cupsdStartProcess: argv[6] = "9" d cupsdStartProcess: argv[7] = "none" d cupsdStartProcess: argv[8] = "/usr/lib/cups/filter/hpps" d cupsdStartProcess: argv[9] = "alexPR" d cupsdStartProcess: argv[10] = "1787" d cupsdStartProcess: argv[11] = "root" d cupsdStartProcess: argv[12] = "temp.txt" d cupsdStartProcess: argv[13] = "1" d cupsdStartProcess: argv[14] = "finishings=3 number-up=1 job-uuid=urn:uuid:51f06e3c-9c93-3e9e-762a-db9af1ca8330 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1468197880 time-at-processing=1468197880 document-name-supplied=temp.txt" d cupsdStartProcess: Setting spawn attributes. d cupsdStartProcess: Setting file actions. d cupsdStartProcess: Calling posix_spawn. d cupsdStartProcess: pid=1494 d cupsdStartProcess(command="/usr/lib/cups/filter/hpps", argv=0xbfc3a4e4, envp=0xbfc3ac30, infd=21, outfd=24, errfd=16, backfd=17, sidefd=19, root=0, profile=(nil), job=0x81a0f918(1787), pid=0x81a0f9d0) = 1494 I [Job 1787] Started filter /usr/lib/cups/filter/hpps (PID 1494) d alexPR: File \"/usr/lib/cups/backend/usb\" permissions OK (040755/uid=0/gid=0). d cupsdStartProcess: Preparing to start "/usr/lib/cups/backend/usb", arguments: d cupsdStartProcess: argv[0] = "/usr/lib/cups/daemon/cups-exec" d cupsdStartProcess: argv[1] = "-g" d cupsdStartProcess: argv[2] = "9" d cupsdStartProcess: argv[3] = "-n" d cupsdStartProcess: argv[4] = "0" d cupsdStartProcess: argv[5] = "-u" d cupsdStartProcess: argv[6] = "9" d cupsdStartProcess: argv[7] = "none" d cupsdStartProcess: argv[8] = "/usr/lib/cups/backend/usb" d cupsdStartProcess: argv[9] = "usb://HP/LaserJet%20Pro%20M201dw?serial=VNB3F12583" d cupsdStartProcess: argv[10] = "1787" d cupsdStartProcess: argv[11] = "root" d cupsdStartProcess: argv[12] = "temp.txt" d cupsdStartProcess: argv[13] = "1" d cupsdStartProcess: argv[14] = "finishings=3 number-up=1 job-uuid=urn:uuid:51f06e3c-9c93-3e9e-762a-db9af1ca8330 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1468197880 time-at-processing=1468197880 document-name-supplied=temp.txt" d cupsdStartProcess: Setting spawn attributes. d cupsdStartProcess: Setting file actions. d cupsdStartProcess: Calling posix_spawn. d cupsdStartProcess: pid=1495 d cupsdStartProcess(command="/usr/lib/cups/backend/usb", argv=0xbfc3a4e4, envp=0xbfc3ac30, infd=23, outfd=-1, errfd=16, backfd=18, sidefd=20, root=0, profile=(nil), job=0x81a0f918(1787), pid=0x81a0fa18) = 1495 I [Job 1787] Started backend /usr/lib/cups/backend/usb (PID 1495) d cupsdAddSelect(fd=15, read_cb=0x800de1da, write_cb=(nil), data=0x81a0f918) d cupsdAddEvent(event=job-state-changed, dest=0x81a0b750(alexPR), job=0x81a0f918(1787), text="Job #%d started.", ...) D Discarding unused job-state-changed event... D [Client 3] Returning IPP successful-ok for Send-Document (ipp://localhost:631/printers/alexPR) from localhost D [Client 3] Content-Length: 172 D [Client 3] cupsdSendHeader: code=200, type="application/ipp", auth_type=0 d cupsdAddSelect(fd=14, read_cb=0x800c91f3, write_cb=0x800c897e, data=0x81a0e7a0) d select_timeout: JobHistoryUpdate=0 D [Client 3] con->http=0x81ae1f18 D [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=172, response=0x81ae56a8(IPP_STATE_DATA), pipe_pid=0, file=-1 D [Client 3] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0 D [Client 3] bytes=0, http_state=0, data_remaining=172 D [Client 3] Flushing write buffer. D [Client 3] New state is HTTP_STATE_WAITING d cupsdAddSelect(fd=14, read_cb=0x800c91f3, write_cb=(nil), data=0x81a0e7a0) D [Client 3] Waiting for request. D cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients and dirty files" d select_timeout: JobHistoryUpdate=0 d [Client 3] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1 D [Client 3] HTTP_STATE_WAITING Closing for error 32 (Broken pipe) D [Client 3] Closing connection. D cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" d cupsdRemoveSelect(fd=14) d cupsdRemoveSelect(fd=-1) d select_timeout: JobHistoryUpdate=0 D [Job 1787] Loading USB quirks from \"/usr/share/cups/usb\". d select_timeout: JobHistoryUpdate=0 D [Job 1787] Loaded 121 quirks. d select_timeout: JobHistoryUpdate=0 D [Job 1787] Printing on printer with URI: usb://HP/LaserJet%20Pro%20M201dw?serial=VNB3F12583 d select_timeout: JobHistoryUpdate=0 D [Job 1787] libusb_get_device_list=10 d select_timeout: JobHistoryUpdate=0 D [Job 1787] STATE: +connecting-to-device d cupsdSetPrinterReasons(p=0x81a0b750(alexPR),s="+connecting-to-device" D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Dirty files", busy="Printing jobs and dirty files" d cupsdAddEvent(event=printer-state-changed, dest=0x81a0b750(alexPR), job=(nil)(0), text="Printer \"%s\" state changed.", ...) D Discarding unused printer-state-changed event... d select_timeout: JobHistoryUpdate=0 D [Job 1787] STATE: -connecting-to-device d cupsdSetPrinterReasons(p=0x81a0b750(alexPR),s="-connecting-to-device" D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Dirty files" d cupsdAddEvent(event=printer-state-changed, dest=0x81a0b750(alexPR), job=(nil)(0), text="Printer \"%s\" state changed.", ...) D Discarding unused printer-state-changed event... d select_timeout: JobHistoryUpdate=0 d [Job 1787] Printer found with device ID: MFG:Hewlett-Packard;CMD:PJL,PML,PCLXL,URP,PCL,PDF,POSTSCRIPT;MDL:HP LaserJet Pro M201dw;CLS:PRINTER;DES:Hewlett-Packard LaserJet Pro M201dw;MEM:MEM=106MB;COMMENT:RES=1200x1;LEDMDIS:USB#ff#04#01;CID:HPLJPDLV1; Device URI: usb://HP/LaserJet%20Pro%20M201dw?serial=VNB3F12583 D [Job 1787] Device protocol: 2 I [Job 1787] Sending data to printer. D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [Job 1787] Set job-printer-state-message to "Sending data to printer.", current level=INFO d cupsdAddEvent(event=job-progress, dest=0x81a0b750(alexPR), job=0x81a0f918(1787), text="%s", ...) D Discarding unused job-progress event... d cupsdAddEvent(event=printer-state-changed, dest=0x81a0b750(alexPR), job=(nil)(0), text="Printer \"%s\" state changed.", ...) D Discarding unused printer-state-changed event... d select_timeout: JobHistoryUpdate=0 D [Job 1787] pdftops - copying to temp print file \"/var/spool/cups/tmp/005d5578d4717\" d select_timeout: JobHistoryUpdate=0 D [Job 1787] Page = 612x792; 12,12 to 600,780 d select_timeout: JobHistoryUpdate=0 D [Job 1787] \033[31;01merror: Failed to create /var/spool/cups/tmp/.hplip\033[0m d select_timeout: JobHistoryUpdate=0 D [Job 1787] pdftopdf: Last filter determined by the PPD: hpps; FINAL_CONTENT_TYPE: application/vnd.cups-postscript => pdftopdf will log pages in page_log. d select_timeout: JobHistoryUpdate=0 d process_children() d cupsdFinishProcess(pid=1491, name=0xbfc4b94c, namelen=1024, job_id=0xbfc4b948(1787)) = "/usr/lib/cups/filter/texttopdf" D [Job 1787] PID 1491 (/usr/lib/cups/filter/texttopdf) exited with no errors. d select_timeout: JobHistoryUpdate=0 d select_timeout(-1): 31 seconds to write dirty config/state files D [Job 1787] PAGE: 1 1 D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" d cupsdAddEvent(event=job-progress, dest=0x81a0b750(alexPR), job=0x81a0f918(1787), text="Printed %d page(s).", ...) D Discarding unused job-progress event... d select_timeout: JobHistoryUpdate=0 d process_children() d cupsdFinishProcess(pid=1492, name=0xbfc4b94c, namelen=1024, job_id=0xbfc4b948(1787)) = "/usr/lib/cups/filter/pdftopdf" D [Job 1787] PID 1492 (/usr/lib/cups/filter/pdftopdf) exited with no errors. d select_timeout: JobHistoryUpdate=0 d select_timeout(-1): 31 seconds to write dirty config/state files D [Job 1787] Printer make and model: HP HP LaserJet Pro M202dw d select_timeout: JobHistoryUpdate=0 D [Job 1787] Running command line for pstops: pstops 1787 root temp.txt 1 \'finishings=3 job-uuid=urn:uuid:51f06e3c-9c93-3e9e-762a-db9af1ca8330 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1468197880 time-at-processing=1468197880 document-name-supplied=temp.txt\' d select_timeout: JobHistoryUpdate=0 D [Job 1787] Using image rendering resolution 600 dpi D [Job 1787] Running command line for gs: gs -q -dNOPAUSE -dBATCH -dSAFER -sDEVICE=pswrite -sOUTPUTFILE=%stdout -dLanguageLevel=3 -r600 -dCompressFonts=false -dNoT3CCITT -dNOINTERPOLATE -c \'save pop\' -f /var/spool/cups/tmp/005d5578d4717 d select_timeout: JobHistoryUpdate=0 D [Job 1787] Started filter gs (PID 1500) d select_timeout: JobHistoryUpdate=0 D [Job 1787] Started filter pstops (PID 1501) d select_timeout: JobHistoryUpdate=0 D [Job 1787] Traceback (most recent call last): D [Job 1787] File \"/usr/lib/cups/filter/hpps\", line 86, in d select_timeout: JobHistoryUpdate=0 D [Job 1787] from base import device D [Job 1787] File \"/usr/share/hplip/base/device.py\", line 71, in D [Job 1787] import dbus d select_timeout: JobHistoryUpdate=0 D [Job 1787] File \"/usr/lib/python2.7/site-packages/dbus/__init__.py\", line 81, in D [Job 1787] import dbus.exceptions as exceptions d select_timeout: JobHistoryUpdate=0 D [Job 1787] AttributeError: \'module\' object has no attribute \'exceptions\' d select_timeout: JobHistoryUpdate=0 D [Job 1787] Sent 0 bytes... d process_children() d cupsdFinishProcess(pid=1494, name=0xbfc4b94c, namelen=1024, job_id=0xbfc4b948(1787)) = "/usr/lib/cups/filter/hpps" D [Job 1787] PID 1494 (/usr/lib/cups/filter/hpps) stopped with status 1. d select_timeout: JobHistoryUpdate=0 D [Job 1787] ./base/gsicc_manage.c:1126: gsicc_open_search(): Could not find default_gray.icc D [Job 1787] | ./base/gsicc_manage.c:1754: gsicc_set_device_profile(): cannot find device profile d select_timeout: JobHistoryUpdate=0 D [Job 1787] Page = 612x792; 12,12 to 600,780 D [Job 1787] slow_collate=0, slow_duplex=0, slow_order=0 D [Job 1787] This document does not conform to the Adobe Document Structuring Conventions and may not print correctly. d select_timeout: JobHistoryUpdate=0 D [Job 1787] PID 1500 (gs) stopped with status 1! d select_timeout: JobHistoryUpdate=0 D [Job 1787] PID 1501 (pstops) exited with no errors. d select_timeout: JobHistoryUpdate=0 d process_children() d cupsdFinishProcess(pid=1493, name=0xbfc4b94c, namelen=1024, job_id=0xbfc4b948(1787)) = "/usr/lib/cups/filter/pdftops" D [Job 1787] PID 1493 (/usr/lib/cups/filter/pdftops) stopped with status 1. d select_timeout: JobHistoryUpdate=0 d select_timeout(-1): 31 seconds to write dirty config/state files D [Job 1787] Waiting for read thread to exit... d select_timeout: JobHistoryUpdate=0 d process_children() d cupsdFinishProcess(pid=1495, name=0xbfc4b94c, namelen=1024, job_id=0xbfc4b948(1787)) = "/usr/lib/cups/backend/usb" D [Job 1787] PID 1495 (/usr/lib/cups/backend/usb) exited with no errors. d select_timeout: JobHistoryUpdate=0 d finalize_job(job=0x81a0f918(1787)) d cupsdSetPrinterReasons(p=0x81a0b750(alexPR),s="-connecting-to-device,cups-waiting-for-job-completed,cups-remote-pending,cups-remote-pending-held,cups-remote-processing,cups-remote-stopped,cups-remote-canceled,cups-remote-aborted,cups-remote-completed" d cupsdDeleteProfile(profile="(null)") d cupsdDeleteProfile(profile="(null)") d cupsdRemoveSelect(fd=15) d cupsdSetJobState(job=0x81a0f918(1787), state=5, newstate=6, action=0, message="%s") d stop_job(job=0x81a0f918(1787), action=0) d cupsdAddEvent(event=job-state-changed, dest=0x81a0b750(alexPR), job=0x81a0f918(1787), text="%s", ...) D Discarding unused job-state-changed event... E [Job 1787] Job stopped due to filter errors; please consult the error_log file for details. D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" d cupsdAddEvent(event=printer-state-changed, dest=0x81a0b750(alexPR), job=(nil)(0), text="%s \"%s\" state changed to %s.", ...) D Discarding unused printer-state-changed event... d cupsdSetPrinterReasons(p=0x81a0b750(alexPR),s="-paused" d cupsdCheckJobs: 1 active jobs, sleeping=0, ac-power=-1, reload=0, curtime=1468197880 d cupsdCheckJobs: Job 1787 - dest="alexPR", printer=(nil), state=6, cancel_time=0, hold_until=1468198180, kill_time=0, pending_cost=0, pending_timeout=0 d select_timeout: JobHistoryUpdate=0 d cupsdSaveJob(job=0x81a0f918(1787)): job->attrs=0x81a1d128 D [Job 1787] Unloading... d select_timeout: JobHistoryUpdate=0 d select_timeout(0): 30 seconds to write dirty config/state files I Saving job.cache... D cupsdSetBusyState: newbusy="Not busy", busy="Printing jobs and dirty files" d cupsdCheckJobs: 1 active jobs, sleeping=0, ac-power=-1, reload=0, curtime=1468197911 d cupsdCheckJobs: Job 1787 - dest="alexPR", printer=(nil), state=6, cancel_time=0, hold_until=1468198180, kill_time=0, pending_cost=0, pending_timeout=0 d select_timeout: JobHistoryUpdate=0 d select_timeout(0): 86400 seconds to do nothing