# Print temp.txt - OK d cupsdAcceptClient(lis=0x8085e4b8(11)) Clients=0 D [Client 1] Accepted from localhost (Domain) d cupsdAddSelect(fd=14, read_cb=0x800321f3, write_cb=(nil), data=0x8086c7a0) D [Client 1] Waiting for request. d cupsdCheckJobs: 0 active jobs, sleeping=0, ac-power=-1, reload=0, curtime=1468198853 D Report: clients=1 D Report: jobs=0 D Report: jobs-active=0 D Report: printers=1 D Report: stringpool-string-count=16172 D Report: stringpool-alloc-bytes=8592 D Report: stringpool-total-bytes=289208 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=0x808580b0(/) D [Client 1] No authentication data provided. d cupsdIsAuthorized: con->uri="/", con->best=0x808580b0(/) 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(0x8086c7a0[1]): operation_id = 000b D Get-Printer-Attributes ipp://localhost:631/printers/alexPR d get_printer_attrs(0x8086c7a0[1], ipp://localhost:631/printers/alexPR) d cupsdFindPolicyOp(p=0x8085eb80, op=b(Get-Printer-Attributes)) d cupsdFindPolicyOp: Found wildcard match... d cupsdIsAuthorized: con->uri="/", con->best=0x80862168((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(0x8086c7a0[1], 0x80869750[alexPR]) d printer-uri-supported="ipp://localhost/printers/alexPR" d copy_attrs(to=0x8087b180, from=0x8086b868, ra=0x8086dab0, group=0, quickcopy=0) d copy_attrs(to=0x8087b180, from=0x80870c20, ra=0x8086dab0, group=0, quickcopy=0) d copy_attrs(to=0x8087b180, from=0x80869ee8, ra=0x8086dab0, 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: 1134 D [Client 1] cupsdSendHeader: code=200, type="application/ipp", auth_type=0 d cupsdAddSelect(fd=14, read_cb=0x800321f3, write_cb=0x8003197e, data=0x8086c7a0) d select_timeout: JobHistoryUpdate=0 D [Client 1] con->http=0x8093feb8 D [Client 1] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1134, response=0x8087b180(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=1134 D [Client 1] Flushing write buffer. D [Client 1] New state is HTTP_STATE_WAITING d cupsdAddSelect(fd=14, read_cb=0x800321f3, write_cb=(nil), data=0x8086c7a0) 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=0x8085e4b8(11)) Clients=0 D [Client 2] Accepted from localhost (Domain) d cupsdAddSelect(fd=14, read_cb=0x800321f3, write_cb=(nil), data=0x8086c7a0) 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=0x808580b0(/) D [Client 2] No authentication data provided. d cupsdIsAuthorized: con->uri="/printers/alexPR", con->best=0x808580b0(/) 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(0x8086c7a0[2]): operation_id = 0005 D Create-Job ipp://localhost:631/printers/alexPR d create_job(0x8086c7a0[2], ipp://localhost:631/printers/alexPR) d add_job(0x8086c7a0[2], 0x80869750(alexPR), (nil)(none/none)) d cupsdFindPolicyOp(p=0x8085eb80, op=5(Create-Job)) d cupsdFindPolicyOp: Found exact match... d cupsdIsAuthorized: con->uri="/printers/alexPR", con->best=0x8085f398((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(0x8086c7a0[2], 0x80869750[alexPR]) D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients" D add_job: requesting-user-name="root" I [Job 1788] Adding start banner page "none". d copy_banner(con=0x8086c7a0[2], job=0x8086d918[1788], name="none") d cupsdAddEvent(event=job-created, dest=0x80869750(alexPR), job=0x8086d918(1788), text="Job created.", ...) D Discarding unused job-created event... I [Job 1788] 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=0x800321f3, write_cb=0x8003197e, data=0x8086c7a0) d select_timeout: JobHistoryUpdate=0 D [Client 2] con->http=0x8093feb8 D [Client 2] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=202, response=0x8087b1c8(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=0x800321f3, write_cb=(nil), data=0x8086c7a0) 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=0x8085e4b8(11)) Clients=0 D [Client 3] Accepted from localhost (Domain) d cupsdAddSelect(fd=14, read_cb=0x800321f3, write_cb=(nil), data=0x8086c7a0) 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=0x808580b0(/) D [Client 3] No authentication data provided. d cupsdIsAuthorized: con->uri="/printers/alexPR", con->best=0x808580b0(/) 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 select_timeout: JobHistoryUpdate=0 d [Client 3] cupsdReadClient: error=0, used=0, state=HTTP_STATE_POST_RECV, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, request=0x8087b1c8(IPP_STATE_DATA), file=15 D [Client 3] Read: status=100 d cupsdProcessIPPRequest(0x8086c7a0[3]): operation_id = 0006 D Send-Document ipp://localhost:631/printers/alexPR d send_document(0x8086c7a0[3], ipp://localhost:631/printers/alexPR) d validate_user(job=1788, con=3, owner="root", username=0xbf86b3dc, userlen=1024) d cupsdFindPolicyOp(p=0x8085eb80, op=6(Send-Document)) d cupsdFindPolicyOp: Found exact match... d cupsdIsAuthorized: con->uri="/printers/alexPR", con->best=0x8085f4c0((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 1788] Auto-typing file... D [Job 1788] Request file type is text/plain. d add_file(con=0x8086c7a0[3], job=1788, filetype=text/plain, compression=0) D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files" I [Job 1788] File of type text/plain queued by "root". I [Job 1788] Adding end banner page "none". d copy_banner(con=(nil)[-1], job=0x8086d918[1788], 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=1468198853 d cupsdCheckJobs: Job 1788 - dest="alexPR", printer=(nil), state=3, cancel_time=0, hold_until=1468199153, kill_time=0, pending_cost=0, pending_timeout=0 d start_job(job=0x8086d918(1788), printer=0x80869750(alexPR)) d cupsdSetJobState(job=0x8086d918(1788), state=3, newstate=5, action=0, message="(null)") D [Job 1788] time-at-processing=1468198853 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=0x80869750(alexPR), job=(nil)(0), text="%s \"%s\" state changed to %s.", ...) D Discarding unused printer-state-changed event... d cupsdSetPrinterReasons(p=0x80869750(alexPR),s="-paused" d cupsdSetPrinterReasons(p=0x80869750(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=0x80869750(alexPR),s="-cups-missing-filter-warning,cups-insecure-filter-warning" d cupsdCreateProfile(job_id=1788, allow_networking=0) = NULL d cupsdCreateProfile(job_id=1788, allow_networking=1) = NULL d cupsdContinueJob(job=0x8086d918(1788)): current_file=0, num_files=1 D [Job 1788] 4 filters for job: D [Job 1788] texttopdf (text/plain to application/pdf, cost 32) D [Job 1788] pdftopdf (application/pdf to application/vnd.cups-pdf, cost 66) D [Job 1788] gstoraster (application/vnd.cups-pdf to application/vnd.cups-raster, cost 66) D [Job 1788] rastertohp (application/vnd.cups-raster to printer/alexPR, cost 50) D [Job 1788] job-sheets=none,none D [Job 1788] argv[0]="alexPR" D [Job 1788] argv[1]="1788" D [Job 1788] argv[2]="root" D [Job 1788] argv[3]="temp.txt" D [Job 1788] argv[4]="1" D [Job 1788] argv[5]="finishings=3 number-up=1 job-uuid=urn:uuid:1d682d51-53d3-3888-6683-a07ff10ec415 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1468198853 time-at-processing=1468198853 document-name-supplied=temp.txt" D [Job 1788] argv[6]="/var/spool/cups/d01788-001" D [Job 1788] envp[0]="CUPS_CACHEDIR=/var/cache/cups" D [Job 1788] envp[1]="CUPS_DATADIR=/usr/share/cups" D [Job 1788] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc-2.1.4" D [Job 1788] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts" D [Job 1788] envp[4]="CUPS_REQUESTROOT=/var/spool/cups" D [Job 1788] envp[5]="CUPS_SERVERBIN=/usr/lib/cups" D [Job 1788] envp[6]="CUPS_SERVERROOT=/etc/cups" D [Job 1788] envp[7]="CUPS_STATEDIR=/var/run/cups" D [Job 1788] envp[8]="HOME=/var/spool/cups/tmp" D [Job 1788] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin" D [Job 1788] envp[10]="SERVER_ADMIN=root@AlexP8" D [Job 1788] envp[11]="SOFTWARE=CUPS/2.1.4" D [Job 1788] envp[12]="TMPDIR=/var/spool/cups/tmp" D [Job 1788] envp[13]="TZ=America/New_York" D [Job 1788] envp[14]="USER=root" D [Job 1788] envp[15]="CUPS_MAX_MESSAGE=2047" D [Job 1788] envp[16]="CUPS_SERVER=/var/run/cups/cups.sock" D [Job 1788] envp[17]="CUPS_ENCRYPTION=IfRequested" D [Job 1788] envp[18]="IPP_PORT=631" D [Job 1788] envp[19]="CHARSET=utf-8" D [Job 1788] envp[20]="LANG=en_US.UTF-8" D [Job 1788] envp[21]="PPD=/etc/cups/ppd/alexPR.ppd" D [Job 1788] envp[22]="RIP_MAX_CACHE=128m" D [Job 1788] envp[23]="CONTENT_TYPE=text/plain" D [Job 1788] envp[24]="DEVICE_URI=usb://HP/LaserJet%20Pro%20M201dw?serial=VNB3F12583" D [Job 1788] envp[25]="PRINTER_INFO=alexPR" D [Job 1788] envp[26]="PRINTER_LOCATION=" D [Job 1788] envp[27]="PRINTER=alexPR" D [Job 1788] envp[28]="PRINTER_STATE_REASONS=none" D [Job 1788] envp[29]="CUPS_FILETYPE=document" D [Job 1788] envp[30]="FINAL_CONTENT_TYPE=application/vnd.cups-raster" D [Job 1788] 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] = "1788" 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:1d682d51-53d3-3888-6683-a07ff10ec415 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1468198853 time-at-processing=1468198853 document-name-supplied=temp.txt" d cupsdStartProcess: argv[15] = "/var/spool/cups/d01788-001" d cupsdStartProcess: Setting spawn attributes. d cupsdStartProcess: Setting file actions. d cupsdStartProcess: Calling posix_spawn. d cupsdStartProcess: pid=1646 d cupsdStartProcess(command="/usr/lib/cups/filter/texttopdf", argv=0xbf867654, envp=0xbf867da0, infd=-1, outfd=22, errfd=16, backfd=17, sidefd=19, root=0, profile=(nil), job=0x8086d918(1788), pid=0x8086d9c4) = 1646 I [Job 1788] Started filter /usr/lib/cups/filter/texttopdf (PID 1646) 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] = "1788" 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:1d682d51-53d3-3888-6683-a07ff10ec415 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1468198853 time-at-processing=1468198853 document-name-supplied=temp.txt" d cupsdStartProcess: Setting spawn attributes. d cupsdStartProcess: Setting file actions. d cupsdStartProcess: Calling posix_spawn. d cupsdStartProcess: pid=1647 d cupsdStartProcess(command="/usr/lib/cups/filter/pdftopdf", argv=0xbf867654, envp=0xbf867da0, infd=21, outfd=24, errfd=16, backfd=17, sidefd=19, root=0, profile=(nil), job=0x8086d918(1788), pid=0x8086d9c8) = 1647 I [Job 1788] Started filter /usr/lib/cups/filter/pdftopdf (PID 1647) d alexPR: File \"/usr/lib/cups/filter/gstoraster\" permissions OK (040755/uid=0/gid=0). d cupsdStartProcess: Preparing to start "/usr/lib/cups/filter/gstoraster", 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/gstoraster" d cupsdStartProcess: argv[9] = "alexPR" d cupsdStartProcess: argv[10] = "1788" 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:1d682d51-53d3-3888-6683-a07ff10ec415 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1468198853 time-at-processing=1468198853 document-name-supplied=temp.txt" d cupsdStartProcess: Setting spawn attributes. d cupsdStartProcess: Setting file actions. d cupsdStartProcess: Calling posix_spawn. d cupsdStartProcess: pid=1648 d cupsdStartProcess(command="/usr/lib/cups/filter/gstoraster", argv=0xbf867654, envp=0xbf867da0, infd=23, outfd=22, errfd=16, backfd=17, sidefd=19, root=0, profile=(nil), job=0x8086d918(1788), pid=0x8086d9cc) = 1648 I [Job 1788] Started filter /usr/lib/cups/filter/gstoraster (PID 1648) d alexPR: File \"/usr/lib/cups/filter/rastertohp\" permissions OK (040755/uid=0/gid=0). d cupsdStartProcess: Preparing to start "/usr/lib/cups/filter/rastertohp", 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/rastertohp" d cupsdStartProcess: argv[9] = "alexPR" d cupsdStartProcess: argv[10] = "1788" 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:1d682d51-53d3-3888-6683-a07ff10ec415 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1468198853 time-at-processing=1468198853 document-name-supplied=temp.txt" d cupsdStartProcess: Setting spawn attributes. d cupsdStartProcess: Setting file actions. d cupsdStartProcess: Calling posix_spawn. d cupsdStartProcess: pid=1649 d cupsdStartProcess(command="/usr/lib/cups/filter/rastertohp", argv=0xbf867654, envp=0xbf867da0, infd=21, outfd=24, errfd=16, backfd=17, sidefd=19, root=0, profile=(nil), job=0x8086d918(1788), pid=0x8086d9d0) = 1649 I [Job 1788] Started filter /usr/lib/cups/filter/rastertohp (PID 1649) 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] = "1788" 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:1d682d51-53d3-3888-6683-a07ff10ec415 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1468198853 time-at-processing=1468198853 document-name-supplied=temp.txt" d cupsdStartProcess: Setting spawn attributes. d cupsdStartProcess: Setting file actions. d cupsdStartProcess: Calling posix_spawn. d cupsdStartProcess: pid=1650 d cupsdStartProcess(command="/usr/lib/cups/backend/usb", argv=0xbf867654, envp=0xbf867da0, infd=23, outfd=-1, errfd=16, backfd=18, sidefd=20, root=0, profile=(nil), job=0x8086d918(1788), pid=0x8086da18) = 1650 I [Job 1788] Started backend /usr/lib/cups/backend/usb (PID 1650) d cupsdAddSelect(fd=15, read_cb=0x800471da, write_cb=(nil), data=0x8086d918) d cupsdAddEvent(event=job-state-changed, dest=0x80869750(alexPR), job=0x8086d918(1788), 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=0x800321f3, write_cb=0x8003197e, data=0x8086c7a0) d select_timeout: JobHistoryUpdate=0 D [Client 3] con->http=0x8093feb8 D [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=172, response=0x809433c0(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=0x800321f3, write_cb=(nil), data=0x8086c7a0) 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 1788] Page = 612x792; 12,12 to 600,780 d select_timeout: JobHistoryUpdate=0 D [Job 1788] pdftopdf: Last filter determined by the PPD: rastertohp; FINAL_CONTENT_TYPE: application/vnd.cups-raster => pdftopdf will not log pages in page_log. d select_timeout: JobHistoryUpdate=0 D [Job 1788] Loading USB quirks from \"/usr/share/cups/usb\". d select_timeout: JobHistoryUpdate=0 D [Job 1788] Loaded 121 quirks. D [Job 1788] Printing on printer with URI: usb://HP/LaserJet%20Pro%20M201dw?serial=VNB3F12583 d select_timeout: JobHistoryUpdate=0 D [Job 1788] libusb_get_device_list=10 d select_timeout: JobHistoryUpdate=0 D [Job 1788] STATE: +connecting-to-device d cupsdSetPrinterReasons(p=0x80869750(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=0x80869750(alexPR), job=(nil)(0), text="Printer \"%s\" state changed.", ...) D Discarding unused printer-state-changed event... d select_timeout: JobHistoryUpdate=0 D [Job 1788] STATE: -connecting-to-device d cupsdSetPrinterReasons(p=0x80869750(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=0x80869750(alexPR), job=(nil)(0), text="Printer \"%s\" state changed.", ...) D Discarding unused printer-state-changed event... d select_timeout: JobHistoryUpdate=0 d [Job 1788] 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 1788] Device protocol: 2 d select_timeout: JobHistoryUpdate=0 I [Job 1788] Sending data to printer. D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [Job 1788] Set job-printer-state-message to "Sending data to printer.", current level=INFO d cupsdAddEvent(event=job-progress, dest=0x80869750(alexPR), job=0x8086d918(1788), text="%s", ...) D Discarding unused job-progress event... d cupsdAddEvent(event=printer-state-changed, dest=0x80869750(alexPR), job=(nil)(0), text="Printer \"%s\" state changed.", ...) D Discarding unused printer-state-changed event... d select_timeout: JobHistoryUpdate=0 d process_children() d cupsdFinishProcess(pid=1646, name=0xbf878abc, namelen=1024, job_id=0xbf878ab8(1788)) = "/usr/lib/cups/filter/texttopdf" D [Job 1788] PID 1646 (/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 process_children() d cupsdFinishProcess(pid=1647, name=0xbf878abc, namelen=1024, job_id=0xbf878ab8(1788)) = "/usr/lib/cups/filter/pdftopdf" D [Job 1788] PID 1647 (/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 1788] Color Manager: Calibration Mode/Off d select_timeout: JobHistoryUpdate=0 D [Job 1788] Calling FindDeviceById(cups-alexPR) d select_timeout: JobHistoryUpdate=0 D [Job 1788] Failed to send: org.freedesktop.DBus.Error.ServiceUnknown:The name org.freedesktop.ColorManager was not provided by any .service files D [Job 1788] Failed to get find device cups-alexPR d select_timeout: JobHistoryUpdate=0 D [Job 1788] Calling FindDeviceById(cups-alexPR) d select_timeout: JobHistoryUpdate=0 D [Job 1788] Failed to send: org.freedesktop.DBus.Error.ServiceUnknown:The name org.freedesktop.ColorManager was not provided by any .service files D [Job 1788] Failed to get device cups-alexPR I [Job 1788] Color Manager: no profiles specified in PPD D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [Job 1788] Set job-printer-state-message to "Color Manager: no profiles specified in PPD", current level=INFO D [Job 1788] Color Manager: ICC Profile: None d cupsdAddEvent(event=job-progress, dest=0x80869750(alexPR), job=0x8086d918(1788), text="%s", ...) D Discarding unused job-progress event... d cupsdAddEvent(event=printer-state-changed, dest=0x80869750(alexPR), job=(nil)(0), text="Printer \"%s\" state changed.", ...) D Discarding unused printer-state-changed event... d select_timeout: JobHistoryUpdate=0 d select_timeout: JobHistoryUpdate=0 d select_timeout: JobHistoryUpdate=0 d select_timeout: JobHistoryUpdate=0 d select_timeout: JobHistoryUpdate=0 d select_timeout: JobHistoryUpdate=0 d select_timeout: JobHistoryUpdate=0 D [Job 1788] Ghostscript command line: /usr/bin/gs -dQUIET -dPARANOIDSAFER -dNOPAUSE -dBATCH -dNOINTERPOLATE -sDEVICE=cups -sstdout=%stderr -sOutputFile=%stdout -r100x100 -dMediaPosition=7 -dDEVICEWIDTHPOINTS=612 -dDEVICEHEIGHTPOINTS=792 -dcupsBitsPerColor=1 -dcupsColorOrder=0 -dcupsColorSpace=3 -scupsPageSizeName=Letter -I/usr/share/cups/fonts -c \'<>setpagedevice\' -f -_ d select_timeout: JobHistoryUpdate=0 D [Job 1788] envp[0]=\"CUPS_CACHEDIR=/var/cache/cups\" D [Job 1788] envp[1]=\"CUPS_DATADIR=/usr/share/cups\" D [Job 1788] envp[2]=\"CUPS_DOCROOT=/usr/share/cups/doc-2.1.4\" D [Job 1788] envp[3]=\"CUPS_FONTPATH=/usr/share/cups/fonts\" D [Job 1788] envp[4]=\"CUPS_REQUESTROOT=/var/spool/cups\" D [Job 1788] envp[5]=\"CUPS_SERVERBIN=/usr/lib/cups\" D [Job 1788] envp[6]=\"CUPS_SERVERROOT=/etc/cups\" D [Job 1788] envp[7]=\"CUPS_STATEDIR=/var/run/cups\" D [Job 1788] envp[8]=\"HOME=/var/spool/cups/tmp\" D [Job 1788] envp[9]=\"PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin\" d select_timeout: JobHistoryUpdate=0 D [Job 1788] envp[10]=\"SERVER_ADMIN=root@AlexP8\" D [Job 1788] envp[11]=\"SOFTWARE=CUPS/2.1.4\" D [Job 1788] envp[12]=\"TMPDIR=/var/spool/cups/tmp\" D [Job 1788] envp[13]=\"TZ=America/New_York\" D [Job 1788] envp[14]=\"USER=root\" D [Job 1788] envp[15]=\"CUPS_MAX_MESSAGE=2047\" D [Job 1788] envp[16]=\"CUPS_SERVER=/var/run/cups/cups.sock\" D [Job 1788] envp[17]=\"CUPS_ENCRYPTION=IfRequested\" D [Job 1788] envp[18]=\"IPP_PORT=631\" D [Job 1788] envp[19]=\"CHARSET=utf-8\" D [Job 1788] envp[20]=\"LANG=en_US.UTF-8\" D [Job 1788] envp[21]=\"PPD=/etc/cups/ppd/alexPR.ppd\" D [Job 1788] envp[22]=\"RIP_MAX_CACHE=128m\" D [Job 1788] envp[23]=\"CONTENT_TYPE=text/plain\" D [Job 1788] envp[24]=\"DEVICE_URI=usb://HP/LaserJet%20Pro%20M201dw?serial=VNB3F12583\" D [Job 1788] envp[25]=\"PRINTER_INFO=alexPR\" D [Job 1788] envp[26]=\"PRINTER_LOCATION=\" D [Job 1788] envp[27]=\"PRINTER=alexPR\" D [Job 1788] envp[28]=\"PRINTER_STATE_REASONS=none\" D [Job 1788] envp[29]=\"CUPS_FILETYPE=document\" D [Job 1788] envp[30]=\"FINAL_CONTENT_TYPE=application/vnd.cups-raster\" D [Job 1788] envp[31]=\"AUTH_INFO_REQUIRED=none\" d select_timeout: JobHistoryUpdate=0 I [Job 1788] Start rendering... D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [Job 1788] Set job-printer-state-message to "Start rendering...", current level=INFO I [Job 1788] Processing page 1... D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [Job 1788] Set job-printer-state-message to "Processing page 1...", current level=INFO d cupsdAddEvent(event=job-progress, dest=0x80869750(alexPR), job=0x8086d918(1788), text="%s", ...) D Discarding unused job-progress event... d cupsdAddEvent(event=printer-state-changed, dest=0x80869750(alexPR), job=(nil)(0), text="Printer \"%s\" state changed.", ...) D Discarding unused printer-state-changed event... d select_timeout: JobHistoryUpdate=0 D [Job 1788] 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=0x80869750(alexPR), job=0x8086d918(1788), text="Printed %d page(s).", ...) D Discarding unused job-progress event... I [Job 1788] Starting page 1. D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [Job 1788] Set job-printer-state-message to "Starting page 1.", current level=INFO D [Job 1788] StartPage... D [Job 1788] Duplex = 0 D [Job 1788] HWResolution = [ 100 100 ] D [Job 1788] ImagingBoundingBox = [ 12 12 600 780 ] D [Job 1788] Margins = [ 12 12 ] D [Job 1788] ManualFeed = 0 D [Job 1788] MediaPosition = 7 D [Job 1788] NumCopies = 1 D [Job 1788] Orientation = 0 D [Job 1788] PageSize = [ 612 792 ] D [Job 1788] cupsWidth = 817 D [Job 1788] cupsHeight = 1067 D [Job 1788] cupsMediaType = 0 d cupsdAddEvent(event=job-progress, dest=0x80869750(alexPR), job=0x8086d918(1788), text="%s", ...) D Discarding unused job-progress event... d cupsdAddEvent(event=printer-state-changed, dest=0x80869750(alexPR), job=(nil)(0), text="Printer \"%s\" state changed.", ...) D Discarding unused printer-state-changed event... d select_timeout: JobHistoryUpdate=0 D [Job 1788] cupsBitsPerColor = 1 D [Job 1788] cupsBitsPerPixel = 1 D [Job 1788] cupsBytesPerLine = 103 D [Job 1788] cupsColorOrder = 0 D [Job 1788] cupsColorSpace = 3 D [Job 1788] cupsCompression = 0 I [Job 1788] Printing page 1, 0% complete. D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [Job 1788] Set job-printer-state-message to "Printing page 1, 0% complete.", current level=INFO D [Job 1788] ATTR: job-media-progress=0 d cupsdAddEvent(event=job-progress, dest=0x80869750(alexPR), job=0x8086d918(1788), text="Printing page %d, %d%%", ...) D Discarding unused job-progress event... D [Job 1788] Read 1088 bytes of print data... I [Job 1788] Printing page 1, 11% complete. D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [Job 1788] Set job-printer-state-message to "Printing page 1, 11% complete.", current level=INFO D [Job 1788] ATTR: job-media-progress=11 d cupsdAddEvent(event=job-progress, dest=0x80869750(alexPR), job=0x8086d918(1788), text="Printing page %d, %d%%", ...) D Discarding unused job-progress event... d cupsdAddEvent(event=job-progress, dest=0x80869750(alexPR), job=0x8086d918(1788), text="%s", ...) D Discarding unused job-progress event... d cupsdAddEvent(event=printer-state-changed, dest=0x80869750(alexPR), job=(nil)(0), text="Printer \"%s\" state changed.", ...) D Discarding unused printer-state-changed event... d select_timeout: JobHistoryUpdate=0 I [Job 1788] Printing page 1, 23% complete. D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [Job 1788] Set job-printer-state-message to "Printing page 1, 23% complete.", current level=INFO D [Job 1788] ATTR: job-media-progress=23 d cupsdAddEvent(event=job-progress, dest=0x80869750(alexPR), job=0x8086d918(1788), text="Printing page %d, %d%%", ...) D Discarding unused job-progress event... d cupsdAddEvent(event=job-progress, dest=0x80869750(alexPR), job=0x8086d918(1788), text="%s", ...) D Discarding unused job-progress event... d cupsdAddEvent(event=printer-state-changed, dest=0x80869750(alexPR), job=(nil)(0), text="Printer \"%s\" state changed.", ...) D Discarding unused printer-state-changed event... d select_timeout: JobHistoryUpdate=0 I [Job 1788] Printing page 1, 35% complete. D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [Job 1788] Set job-printer-state-message to "Printing page 1, 35% complete.", current level=INFO D [Job 1788] ATTR: job-media-progress=35 d cupsdAddEvent(event=job-progress, dest=0x80869750(alexPR), job=0x8086d918(1788), text="Printing page %d, %d%%", ...) D Discarding unused job-progress event... d cupsdAddEvent(event=job-progress, dest=0x80869750(alexPR), job=0x8086d918(1788), text="%s", ...) D Discarding unused job-progress event... d cupsdAddEvent(event=printer-state-changed, dest=0x80869750(alexPR), job=(nil)(0), text="Printer \"%s\" state changed.", ...) D Discarding unused printer-state-changed event... d select_timeout: JobHistoryUpdate=0 D [Job 1788] Wrote 1088 bytes of print data... d select_timeout: JobHistoryUpdate=0 I [Job 1788] Printing page 1, 47% complete. D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [Job 1788] Set job-printer-state-message to "Printing page 1, 47% complete.", current level=INFO D [Job 1788] ATTR: job-media-progress=47 d cupsdAddEvent(event=job-progress, dest=0x80869750(alexPR), job=0x8086d918(1788), text="Printing page %d, %d%%", ...) D Discarding unused job-progress event... I [Job 1788] Processing page 2... D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [Job 1788] Set job-printer-state-message to "Processing page 2...", current level=INFO d cupsdAddEvent(event=job-progress, dest=0x80869750(alexPR), job=0x8086d918(1788), text="%s", ...) D Discarding unused job-progress event... d cupsdAddEvent(event=printer-state-changed, dest=0x80869750(alexPR), job=(nil)(0), text="Printer \"%s\" state changed.", ...) D Discarding unused printer-state-changed event... d select_timeout: JobHistoryUpdate=0 I [Job 1788] Printing page 1, 59% complete. D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [Job 1788] Set job-printer-state-message to "Printing page 1, 59% complete.", current level=INFO D [Job 1788] ATTR: job-media-progress=59 d cupsdAddEvent(event=job-progress, dest=0x80869750(alexPR), job=0x8086d918(1788), text="Printing page %d, %d%%", ...) D Discarding unused job-progress event... I [Job 1788] Printing page 1, 71% complete. D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [Job 1788] Set job-printer-state-message to "Printing page 1, 71% complete.", current level=INFO D [Job 1788] ATTR: job-media-progress=71 d cupsdAddEvent(event=job-progress, dest=0x80869750(alexPR), job=0x8086d918(1788), text="Printing page %d, %d%%", ...) D Discarding unused job-progress event... d cupsdAddEvent(event=job-progress, dest=0x80869750(alexPR), job=0x8086d918(1788), text="%s", ...) D Discarding unused job-progress event... d cupsdAddEvent(event=printer-state-changed, dest=0x80869750(alexPR), job=(nil)(0), text="Printer \"%s\" state changed.", ...) D Discarding unused printer-state-changed event... d select_timeout: JobHistoryUpdate=0 I [Job 1788] Printing page 1, 83% complete. D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [Job 1788] Set job-printer-state-message to "Printing page 1, 83% complete.", current level=INFO D [Job 1788] ATTR: job-media-progress=83 d cupsdAddEvent(event=job-progress, dest=0x80869750(alexPR), job=0x8086d918(1788), text="Printing page %d, %d%%", ...) D Discarding unused job-progress event... I [Job 1788] Printing page 1, 95% complete. D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [Job 1788] Set job-printer-state-message to "Printing page 1, 95% complete.", current level=INFO d cupsdAddEvent(event=job-progress, dest=0x80869750(alexPR), job=0x8086d918(1788), text="%s", ...) D Discarding unused job-progress event... d cupsdAddEvent(event=printer-state-changed, dest=0x80869750(alexPR), job=(nil)(0), text="Printer \"%s\" state changed.", ...) D Discarding unused printer-state-changed event... d select_timeout: JobHistoryUpdate=0 D [Job 1788] ATTR: job-media-progress=95 d cupsdAddEvent(event=job-progress, dest=0x80869750(alexPR), job=0x8086d918(1788), text="Printing page %d, %d%%", ...) D Discarding unused job-progress event... I [Job 1788] Finished page 1. D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [Job 1788] Set job-printer-state-message to "Finished page 1.", current level=INFO d cupsdAddEvent(event=job-progress, dest=0x80869750(alexPR), job=0x8086d918(1788), text="%s", ...) D Discarding unused job-progress event... d cupsdAddEvent(event=printer-state-changed, dest=0x80869750(alexPR), job=(nil)(0), text="Printer \"%s\" state changed.", ...) D Discarding unused printer-state-changed event... d select_timeout: JobHistoryUpdate=0 D [Job 1788] Read 6 bytes of print data... d select_timeout: JobHistoryUpdate=0 D [Job 1788] Wrote 6 bytes of print data... d select_timeout: JobHistoryUpdate=0 I [Job 1788] Rendering completed D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [Job 1788] Set job-printer-state-message to "Rendering completed", current level=INFO d cupsdAddEvent(event=job-progress, dest=0x80869750(alexPR), job=0x8086d918(1788), text="%s", ...) D Discarding unused job-progress event... d cupsdAddEvent(event=printer-state-changed, dest=0x80869750(alexPR), job=(nil)(0), text="Printer \"%s\" state changed.", ...) D Discarding unused printer-state-changed event... d select_timeout: JobHistoryUpdate=0 d process_children() d cupsdFinishProcess(pid=1648, name=0xbf878abc, namelen=1024, job_id=0xbf878ab8(1788)) = "/usr/lib/cups/filter/gstoraster" D [Job 1788] PID 1648 (/usr/lib/cups/filter/gstoraster) exited with no errors. d select_timeout: JobHistoryUpdate=0 d select_timeout(-1): 31 seconds to write dirty config/state files D [Job 1788] Read 2 bytes of print data... d select_timeout: JobHistoryUpdate=0 D [Job 1788] Wrote 2 bytes of print data... D [Job 1788] Sent 1096 bytes... d process_children() d cupsdFinishProcess(pid=1649, name=0xbf878abc, namelen=1024, job_id=0xbf878ab8(1788)) = "/usr/lib/cups/filter/rastertohp" D [Job 1788] PID 1649 (/usr/lib/cups/filter/rastertohp) exited with no errors. d select_timeout: JobHistoryUpdate=0 D [Job 1788] Waiting for read thread to exit... d select_timeout: JobHistoryUpdate=0 d process_children() d cupsdFinishProcess(pid=1650, name=0xbf878abc, namelen=1024, job_id=0xbf878ab8(1788)) = "/usr/lib/cups/backend/usb" D [Job 1788] PID 1650 (/usr/lib/cups/backend/usb) exited with no errors. d select_timeout: JobHistoryUpdate=0 d finalize_job(job=0x8086d918(1788)) d cupsdSetPrinterReasons(p=0x80869750(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=0x8086d918(1788), state=5, newstate=9, action=0, message="%s") d stop_job(job=0x8086d918(1788), action=0) D [Job 1788] time-at-completed=1468198853 d set_time: JobHistoryUpdate=185151879 d cupsdAddEvent(event=job-completed, dest=0x80869750(alexPR), job=0x8086d918(1788), text="%s", ...) D Discarding unused job-completed event... I [Job 1788] Job completed. I Expiring subscriptions... 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=0x80869750(alexPR), job=(nil)(0), text="%s \"%s\" state changed to %s.", ...) D Discarding unused printer-state-changed event... d cupsdSetPrinterReasons(p=0x80869750(alexPR),s="-paused" D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" d cupsdCheckJobs: 0 active jobs, sleeping=0, ac-power=-1, reload=0, curtime=1468198853 d cupsdCleanJobs: MaxJobs=500, JobHistory=2147483647, JobFiles=86400 D [Job 1788] Removing document files. D cupsdMarkDirty(---J-) D cupsdSetBusyState: newbusy="Dirty files", busy="Printing jobs and dirty files" d cupsdCleanJobs: JobHistoryUpdate=2147483647 d select_timeout: JobHistoryUpdate=2147483647 d cupsdSaveJob(job=0x8086d918(1788)): job->attrs=0x80943018 D [Job 1788] Unloading... d select_timeout: JobHistoryUpdate=2147483647 d select_timeout(0): 30 seconds to write dirty config/state files I Saving job.cache... D cupsdSetBusyState: newbusy="Not busy", busy="Dirty files" d cupsdCheckJobs: 0 active jobs, sleeping=0, ac-power=-1, reload=0, curtime=1468198884 d select_timeout: JobHistoryUpdate=2147483647 d select_timeout(0): 86400 seconds to do nothing