Arch Linux

WorksAsIntended

Member

Registered: 2017-03-25

Posts: 13

cupsd not working correctly

Hi there,

I got some issues with cups on the machine  of my wife running Arch with current kernel 4.10.5., everything up to date. 
First of all, if I boot the machine, the cups service does not start altough it is enabled. If I start it manually it is running without error message, but still localhost:631 is dead.
I guess it gets loaded before some dependency during boot, but I do not understand why it doesnt run, although the systemd service is running. Journalctl doesnt show any error massage, in /var/log/cups/error_log is nothing either. I already run cups in Verbose mode.
Now it gets even stranger, if I manually start cups via /usr/bin/cupsd -f it starts (localhost:631 also working). BUT if I submit a job to the printer (brother mfn 2700 dn, driver from aur) it just is displayed as finished succesfully immidiatly and nothing happens. Nothing in logs either.
I tried reinstalling everthing a couple of times. During installation of printer I get the wellknown cannot create Profile, already exists message. Even if I remove every file related to cups (at least all I can find) and reinstall it, the job id count is continuing after I add the printer again. There must be some file left which might be corrupt? I also removed the Profile file from dbus, nothing changed.
I got the same machine running for myself, only difference is I run awesome instead of xfce, it is working perfectly there.
Any guess, what I can do? I am pretty much out of ideas, espacially as there is no error log anywhere.

Edit: One issue that might be related: If I try to start cupsd with wrong flag it segfaults. I dont know if that is an issue at my machine or there is just not any testing of flags and it therefore runs into death by the way it is programmed.

I would be really thanfull for any kind of help!

Greatings

seth

Member

Registered: 2012-09-03

Posts: 51,235

Re: cupsd not working correctly

systemctl list-units| grep -i cups

Wild guess: ensure to "systemctl enable cups-browsed.service"

---

How to upload text · How to boot w/o GUI · Disable Windows Fast-Start! · Fix your xinitrc

WorksAsIntended

Member

Registered: 2017-03-25

Posts: 13

Re: cupsd not working correctly

This actually resolved the minor issue of cups not working at boot. I still got the problem that the printer is not working. The job is "completed" but nothing happend and cups doesnt even know the page count.

[pia@pias_laptop ~]$ cat /var/log/cups/error_log
I [25/Mar/2017:18:55:47 +0100] Expiring subscriptions...
I [25/Mar/2017:18:55:48 +0100] Expiring subscriptions...


[pia@pias_laptop ~]$ cat /var/log/cups/access_log
localhost - root [25/Mar/2017:18:55:30 +0100] "POST /admin HTTP/1.1" 200 2404 - -
localhost - - [25/Mar/2017:18:55:34 +0100] "POST /printers/swLaser HTTP/1.1" 200 423 Print-Job successful-ok

Edit:

systemctl list-units| grep -i cups
org.cups.cupsd.path                                                                                                   loaded active waiting   CUPS Scheduler                                                             
cups-browsed.service                                                                                                loaded active running   Make remote CUPS printers available locally                                
org.cups.cupsd.service                                                                                              loaded active running   CUPS Scheduler                                                             
org.cups.cupsd.socket                                                                                               loaded active running   CUPS Scheduler

Last edited by WorksAsIntended (2017-03-25 18:03:16)

seth

Member

Registered: 2012-09-03

Posts: 51,235

Re: cupsd not working correctly

Raise the LogLevel in /etc/cups/cupsd.conf to at least "debug", maybe "debug2", restart the cups-browsed service, try to print sth. and inspect the log.
Also about "try to print": use the test page (not! self test) in the cups web admin interface (localhost:631), not some probably broken client ;-)

---

How to upload text · How to boot w/o GUI · Disable Windows Fast-Start! · Fix your xinitrc

WorksAsIntended

Member

Registered: 2017-03-25

Posts: 13

Re: cupsd not working correctly

The last output i posted was already on debug. debug2 didnt change anythng,
The expiring subscriptions is the ony valuable information.

WorksAsIntended

Member

Registered: 2017-03-25

Posts: 13

Re: cupsd not working correctly

Meh, forgot to reload module after debug2....
Actually these lines seem to be interesting: (it is a very long output)

d [26/Mar/2017:12:28:08 +0200] [Client 10] cupsdSendError code=304, auth_type=0
D [26/Mar/2017:12:28:08 +0200] [Client 10] cupsdSendHeader: code=304, type="(null)", auth_type=0
D [26/Mar/2017:12:28:08 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
d [26/Mar/2017:12:28:08 +0200] select_timeout: JobHistoryUpdate=2147483647

Edit: seems to be from the webserver, but lp is also failing so i guess still not the reason
edit 2: full output

d [26/Mar/2017:12:28:08 +0200] [CGI] printer_name[0]=\"swLaser\"
D [26/Mar/2017:12:28:08 +0200] [CGI] cgiSetArray: printer_location[0]=\"\"
d [26/Mar/2017:12:28:08 +0200] [CGI] printer_location[0]=\"\"
D [26/Mar/2017:12:28:08 +0200] [CGI] cgiSetArray: printer_info[0]=\"Brother MFC-L2700DN series\"
d [26/Mar/2017:12:28:08 +0200] [CGI] printer_info[0]=\"Brother MFC-L2700DN series\"
D [26/Mar/2017:12:28:08 +0200] [CGI] cgiSetArray: job_sheets_default[0]=\"none, none\"
d [26/Mar/2017:12:28:08 +0200] [CGI] job_sheets_default[0]=\"none, none\"
D [26/Mar/2017:12:28:08 +0200] [CGI] cgiSetArray: device_uri[0]=\"lpd://BRN30055C90089B/BINARY_P1\"
d [26/Mar/2017:12:28:08 +0200] [CGI] device_uri[0]=\"lpd://BRN30055C90089B/BINARY_P1\"
D [26/Mar/2017:12:28:08 +0200] [CGI] cgiSetArray: color_supported[0]=\"0\"
d [26/Mar/2017:12:28:08 +0200] [CGI] color_supported[0]=\"0\"
D [26/Mar/2017:12:28:08 +0200] [CGI] cgiSetArray: printer_make_and_model[0]=\"Brother MFC-L2700DN for CUPS \"
d [26/Mar/2017:12:28:08 +0200] [CGI] printer_make_and_model[0]=\"Brother MFC-L2700DN for CUPS \"
D [26/Mar/2017:12:28:08 +0200] [CGI] cgiSetArray: media_default[0]=\"iso_a4_210x297mm\"
d [26/Mar/2017:12:28:08 +0200] [CGI] media_default[0]=\"iso_a4_210x297mm\"
D [26/Mar/2017:12:28:08 +0200] [CGI] cgiSetArray: sides_supported[0]=\"one-sided, two-sided-long-edge, two-sided-short-edge\"
d [26/Mar/2017:12:28:08 +0200] [CGI] sides_supported[0]=\"one-sided, two-sided-long-edge, two-sided-short-edge\"
D [26/Mar/2017:12:28:08 +0200] [CGI] cgiSetArray: sides_default[0]=\"two-sided-long-edge\"
d [26/Mar/2017:12:28:08 +0200] [CGI] sides_default[0]=\"two-sided-long-edge\"
D [26/Mar/2017:12:28:08 +0200] [CGI] cgiSetArray: printer_commands[0]=\"AutoConfigure, Clean, PrintSelfTestPage\"
d [26/Mar/2017:12:28:08 +0200] [CGI] printer_commands[0]=\"AutoConfigure, Clean, PrintSelfTestPage\"
D [26/Mar/2017:12:28:08 +0200] [CGI] cgiSetArray: server_is_sharing_printers[0]=\"0\"
d [26/Mar/2017:12:28:08 +0200] select_timeout: JobHistoryUpdate=2147483647
d [26/Mar/2017:12:28:08 +0200] [CGI] server_is_sharing_printers[0]=\"0\"
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning 1 from cgiSetIPPVars()...
D [26/Mar/2017:12:28:08 +0200] [CGI] cgiSetVariable: TITLE=\"swLaser\"
D [26/Mar/2017:12:28:08 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [26/Mar/2017:12:28:08 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"root\"
D [26/Mar/2017:12:28:08 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.2\"
d [26/Mar/2017:12:28:08 +0200] [CGI] cgiCopyTemplateLang(tmpl=\"header.tmpl\")
d [26/Mar/2017:12:28:08 +0200] [CGI] lang=\"en_US.UTF8\", locale=\"/en_US\"...
d [26/Mar/2017:12:28:08 +0200] [CGI] Template file is \"/usr/share/cups/templates/header.tmpl\"...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{refresh_page?\" at 287, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 287...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{refresh_page}\" at 337...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 340 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 340...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 341 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{refresh_page?\", out=0x7fc98ee0a5e0...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{display:none;}\" at 483...
d [26/Mar/2017:12:28:08 +0200] [CGI] Lone { at 619...
d [26/Mar/2017:12:28:08 +0200] [CGI] Lone { at 692...
d [26/Mar/2017:12:28:08 +0200] [CGI] Lone { at 822...
d [26/Mar/2017:12:28:08 +0200] [CGI] Lone { at 855...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{title}\" at 1055...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{SECTION=admin\" at 1282, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 1282...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 1298 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 1298...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 1299 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{SECTION=admin\", out=0x7fc98ee0a5e0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{SECTION=classes\" at 1362, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 1362...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 1378 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 1378...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 1379 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{SECTION=classes\", out=0x7fc98ee0a5e0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{SECTION=help\" at 1435, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 1435...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 1451 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 1451...
d [26/Mar/2017:12:28:08 +0200] [Client 10] write_pipe: CGI output on fd 17.
d [26/Mar/2017:12:28:08 +0200] cupsdRemoveSelect(fd=17)
d [26/Mar/2017:12:28:08 +0200] cupsdAddSelect(fd=14, read_cb=(nil), write_cb=0x55ec460e99a0, data=0x55ec47ca5bb0)
D [26/Mar/2017:12:28:08 +0200] [Client 10] CGI data ready to be sent.
d [26/Mar/2017:12:28:08 +0200] select_timeout: JobHistoryUpdate=2147483647
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 1452 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{SECTION=help\", out=0x7fc98ee0a5e0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{SECTION=jobs\" at 1502, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 1502...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 1518 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 1518...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 1519 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{SECTION=jobs\", out=0x7fc98ee0a5e0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{SECTION=printers\" at 1573, result=1...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 1573...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 1589 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 1589...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 1590 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{SECTION=printers\", out=0x7fc98ee0a5e0...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{title}\" at 1708...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 1714 on EOF...
d [26/Mar/2017:12:28:08 +0200] [CGI] cgiCopyTemplateLang(tmpl=\"printer.tmpl\")
d [26/Mar/2017:12:28:08 +0200] [CGI] lang=\"en_US.UTF8\", locale=\"/en_US\"...
d [26/Mar/2017:12:28:08 +0200] [CGI] Template file is \"/usr/share/cups/templates/printer.tmpl\"...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 0...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{printer_uri_supported}\" at 50...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{printer_name}\" at 66...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{printer_state=3\" at 89, result=1...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 89...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 94 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 94...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{printer_state=4\" at 111, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 111...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 122 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 122...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 129 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{printer_state=4\", out=(nil)...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 130 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{printer_state=3\", out=0x7fc98ee0a5e0...
D [26/Mar/2017:12:28:08 +0200] [Client 10] con->http=0x55ec47ca8840
D [26/Mar/2017:12:28:08 +0200] [Client 10] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=2147483647, response=(nil)(), pipe_pid=1065, file=17
d [26/Mar/2017:12:28:08 +0200] cupsdAddSelect(fd=17, read_cb=0x55ec460e7840, write_cb=(nil), data=0x55ec47ca5bb0)
D [26/Mar/2017:12:28:08 +0200] [Client 10] Waiting for CGI data.
D [26/Mar/2017:12:28:08 +0200] [Client 10] Script header: Content-Type: text/html;charset=utf-8
D [26/Mar/2017:12:28:08 +0200] [Client 10] Script header: 
D [26/Mar/2017:12:28:08 +0200] [Client 10] Sending status 200 for CGI.
D [26/Mar/2017:12:28:08 +0200] [Client 10] cupsdSendHeader: code=200, type="(null)", auth_type=0
d [26/Mar/2017:12:28:08 +0200] select_timeout: JobHistoryUpdate=2147483647
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{printer_is_accepting_jobs=0\" at 161, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 161...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 176 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 176...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 191 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{printer_is_accepting_jobs=0\", out=0x7fc98ee0a5e0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{server_is_sharing_printers=0\" at 223, result=1...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 223...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 227 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 227...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{printer_is_shared=0\" at 248, result=1...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 248...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 252 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 252...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 253 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{printer_is_shared=0\", out=(nil)...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 254 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{server_is_sharing_printers=0\", out=0x7fc98ee0a5e0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{default_name=swLaser\" at 290, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 290...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 307 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 307...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 308 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{default_name=swLaser\", out=0x7fc98ee0a5e0...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{printer_uri_supported}\" at 367...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{$org.cups.sid}\" at 452...
D [26/Mar/2017:12:28:08 +0200] [CGI] Regular expression \".*Clean.*\"
D [26/Mar/2017:12:28:08 +0200] [CGI] matches[0].rm_so=0
D [26/Mar/2017:12:28:08 +0200] [CGI] matches[1].rm_so=-1
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{printer_commands~.*Clean.*\" at 639, result=1...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 639...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 700 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 700...
D [26/Mar/2017:12:28:08 +0200] [Client 10] con->http=0x55ec47ca8840
D [26/Mar/2017:12:28:08 +0200] [Client 10] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=1065, file=17
d [26/Mar/2017:12:28:08 +0200] cupsdAddSelect(fd=17, read_cb=0x55ec460e7840, write_cb=(nil), data=0x55ec47ca5bb0)
D [26/Mar/2017:12:28:08 +0200] [Client 10] Waiting for CGI data.
d [26/Mar/2017:12:28:08 +0200] cupsdRemoveSelect(fd=14)
d [26/Mar/2017:12:28:08 +0200] [Client 15] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1
D [26/Mar/2017:12:28:08 +0200] [Client 15] POST / HTTP/1.1
D [26/Mar/2017:12:28:08 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [26/Mar/2017:12:28:08 +0200] [Client 15] Read: status=200, state=6
d [26/Mar/2017:12:28:08 +0200] cupsdFindBest: uri="/", limit=10...
d [26/Mar/2017:12:28:08 +0200] cupsdFindBest: Location /admin/log(10) Limit 7f
d [26/Mar/2017:12:28:08 +0200] cupsdFindBest: Location /admin/conf(11) Limit 7f
d [26/Mar/2017:12:28:08 +0200] cupsdFindBest: Location /admin(6) Limit 7f
d [26/Mar/2017:12:28:08 +0200] cupsdFindBest: Location /(1) Limit 7f
d [26/Mar/2017:12:28:08 +0200] cupsdFindBest: best=/
d [26/Mar/2017:12:28:08 +0200] [Client 15] con->uri="/", con->best=0x55ec47bf29f0(/)
D [26/Mar/2017:12:28:08 +0200] [Client 15] No authentication data provided.
d [26/Mar/2017:12:28:08 +0200] cupsdIsAuthorized: con->uri="/", con->best=0x55ec47bf29f0(/)
d [26/Mar/2017:12:28:08 +0200] cupsdIsAuthorized: level=CUPSD_AUTH_ANON, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0
d [26/Mar/2017:12:28:08 +0200] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
D [26/Mar/2017:12:28:08 +0200] [Client 15] 2.0 Get-Jobs 3
d [26/Mar/2017:12:28:08 +0200] cupsdProcessIPPRequest(0x55ec47cb2f40[15]): operation_id = 000a
D [26/Mar/2017:12:28:08 +0200] Get-Jobs ipp://localhost:631/printers/swLaser
d [26/Mar/2017:12:28:08 +0200] get_jobs(0x55ec47cb2f40[15], ipp://localhost:631/printers/swLaser)
d [26/Mar/2017:12:28:08 +0200] cupsdFindPolicyOp(p=0x55ec47bf7b90, op=a(Get-Jobs))
d [26/Mar/2017:12:28:08 +0200] cupsdFindPolicyOp: Found wildcard match...
d [26/Mar/2017:12:28:08 +0200] cupsdIsAuthorized: con->uri="/", con->best=0x55ec47bfbfd0((null))
d [26/Mar/2017:12:28:08 +0200] cupsdIsAuthorized: level=CUPSD_AUTH_ANON, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0
d [26/Mar/2017:12:28:08 +0200] cupsdIsAuthorized: op=0(0x0000)
d [26/Mar/2017:12:28:08 +0200] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
d [26/Mar/2017:12:28:08 +0200] get_jobs: count=0
D [26/Mar/2017:12:28:08 +0200] [Client 15] Returning IPP successful-ok for Get-Jobs (ipp://localhost:631/printers/swLaser) from localhost
D [26/Mar/2017:12:28:08 +0200] [Client 15] Content-Length: 75
D [26/Mar/2017:12:28:08 +0200] [Client 15] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
d [26/Mar/2017:12:28:08 +0200] cupsdAddSelect(fd=18, read_cb=0x55ec460ea2c0, write_cb=0x55ec460e99a0, data=0x55ec47cb2f40)
d [26/Mar/2017:12:28:08 +0200] [Client 10] write_pipe: CGI output on fd 17.
d [26/Mar/2017:12:28:08 +0200] cupsdRemoveSelect(fd=17)
d [26/Mar/2017:12:28:08 +0200] cupsdAddSelect(fd=14, read_cb=(nil), write_cb=0x55ec460e99a0, data=0x55ec47ca5bb0)
D [26/Mar/2017:12:28:08 +0200] [Client 10] CGI data ready to be sent.
d [26/Mar/2017:12:28:08 +0200] select_timeout: JobHistoryUpdate=2147483647
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 701 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{printer_commands~.*Clean.*\", out=0x7fc98ee0a5e0...
D [26/Mar/2017:12:28:08 +0200] [CGI] Regular expression \".*PrintSelfTestPage.*\"
D [26/Mar/2017:12:28:08 +0200] [CGI] matches[0].rm_so=0
D [26/Mar/2017:12:28:08 +0200] [CGI] matches[1].rm_so=-1
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{printer_commands~.*PrintSelfTestPage.*\" at 742, result=1...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 742...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 809 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 809...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 810 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{printer_commands~.*PrintSelfTestPage.*\", out=0x7fc98ee0a5e0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{printer_state=5\" at 828, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 828...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 882 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 882...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 934 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{printer_state=5\", out=0x7fc98ee0a5e0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{printer_is_accepting_jobs=0\" at 964, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 964...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 1013 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 1013...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 1062 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{printer_is_accepting_jobs=0\", out=0x7fc98ee0a5e0...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{admin_uri}\" at 1277...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{$org.cups.sid}\" at 1365...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{printer_name}\" at 1430...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{printer_name}\" at 1939...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{printer_info}\" at 2012...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{printer_location}\" at 2094...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{printer_make_and_model}\" at 2180...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{color_supported=1\" at 2201, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 2201...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 2207 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 2207...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 2217 on character \'}\'...
D [26/Mar/2017:12:28:08 +0200] [Client 15] con->http=0x55ec47cb7d30
D [26/Mar/2017:12:28:08 +0200] [Client 15] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=75, response=0x55ec47c9f1b0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [26/Mar/2017:12:28:08 +0200] [Client 15] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [26/Mar/2017:12:28:08 +0200] [Client 15] bytes=0, http_state=0, data_remaining=75
D [26/Mar/2017:12:28:08 +0200] [Client 15] Flushing write buffer.
D [26/Mar/2017:12:28:08 +0200] [Client 15] New state is HTTP_STATE_WAITING
d [26/Mar/2017:12:28:08 +0200] cupsdAddSelect(fd=18, read_cb=0x55ec460ea2c0, write_cb=(nil), data=0x55ec47cb2f40)
D [26/Mar/2017:12:28:08 +0200] [Client 15] Waiting for request.
D [26/Mar/2017:12:28:08 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [26/Mar/2017:12:28:08 +0200] [Client 10] con->http=0x55ec47ca8840
D [26/Mar/2017:12:28:08 +0200] [Client 10] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=1065, file=17
d [26/Mar/2017:12:28:08 +0200] cupsdAddSelect(fd=17, read_cb=0x55ec460e7840, write_cb=(nil), data=0x55ec47ca5bb0)
D [26/Mar/2017:12:28:08 +0200] [Client 10] Waiting for CGI data.
d [26/Mar/2017:12:28:08 +0200] select_timeout: JobHistoryUpdate=2147483647
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{color_supported=1\", out=0x7fc98ee0a5e0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{sides_supported=one-sided\" at 2244, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 2244...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 2245 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 2245...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 2264 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{sides_supported=one-sided\", out=0x7fc98ee0a5e0...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{device_uri}\" at 2337...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{job_sheets_default}\" at 2432...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{media_default?\" at 2454, result=1...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 2454...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{media_default}\" at 2469...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 2470 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 2470...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 2478 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{media_default?\", out=0x7fc98ee0a5e0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{sides_default?\" at 2494, result=1...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 2494...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{sides_default}\" at 2515...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 2516 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 2516...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 2517 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{sides_default?\", out=0x7fc98ee0a5e0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 2537 on EOF...
d [26/Mar/2017:12:28:08 +0200] [CGI] cgiCopyTemplateLang(tmpl=\"printer-jobs-header.tmpl\")
d [26/Mar/2017:12:28:08 +0200] [CGI] lang=\"en_US.UTF8\", locale=\"/en_US\"...
d [26/Mar/2017:12:28:08 +0200] [CGI] Template file is \"/usr/share/cups/templates/printer-jobs-header.tmpl\"...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 28 on EOF...
D [26/Mar/2017:12:28:08 +0200] [CGI] cgiClearVariables called.
D [26/Mar/2017:12:28:08 +0200] [CGI] cgiSetVariable: SECTION=\"printers\"
D [26/Mar/2017:12:28:08 +0200] [CGI] cgiSetVariable: TOTAL=\"0\"
D [26/Mar/2017:12:28:08 +0200] [CGI] cgiSetVariable: PRINTER_NAME=\"swLaser\"
D [26/Mar/2017:12:28:08 +0200] [CGI] cgiSetVariable: PRINTER_URI_SUPPORTED=\"/printers/swLaser\"
D [26/Mar/2017:12:28:08 +0200] [CGI] cgiSetVariable: THISURL=\"/printers/swLaser\"
D [26/Mar/2017:12:28:08 +0200] [CGI] cgiSetVariable: SEARCH_DEST=\"swLaser\"
d [26/Mar/2017:12:28:08 +0200] [CGI] cgiCopyTemplateLang(tmpl=\"search.tmpl\")
D [26/Mar/2017:12:28:08 +0200] [Client 10] con->http=0x55ec47ca8840
D [26/Mar/2017:12:28:08 +0200] [Client 10] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=1065, file=17
d [26/Mar/2017:12:28:08 +0200] cupsdAddSelect(fd=17, read_cb=0x55ec460e7840, write_cb=(nil), data=0x55ec47ca5bb0)
D [26/Mar/2017:12:28:08 +0200] [Client 10] Waiting for CGI data.
d [26/Mar/2017:12:28:08 +0200] cupsdRemoveSelect(fd=14)
d [26/Mar/2017:12:28:08 +0200] [Client 10] write_pipe: CGI output on fd 17.
d [26/Mar/2017:12:28:08 +0200] cupsdRemoveSelect(fd=17)
d [26/Mar/2017:12:28:08 +0200] cupsdAddSelect(fd=14, read_cb=(nil), write_cb=0x55ec460e99a0, data=0x55ec47ca5bb0)
D [26/Mar/2017:12:28:08 +0200] [Client 10] CGI data ready to be sent.
d [26/Mar/2017:12:28:08 +0200] select_timeout: JobHistoryUpdate=2147483647
d [26/Mar/2017:12:28:08 +0200] [CGI] lang=\"en_US.UTF8\", locale=\"/en_US\"...
d [26/Mar/2017:12:28:08 +0200] [CGI] Template file is \"/usr/share/cups/templates/search.tmpl\"...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 0...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{SECTION}\" at 24...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{?SEARCH_DEST}\" at 39...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{WHICH_JOBS?\" at 67, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 67...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{WHICH_JOBS}\" at 125...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 128 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 128...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 129 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{WHICH_JOBS?\", out=0x7fc98ee0a5e0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{ORDER?\" at 137, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 137...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{ORDER}\" at 185...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 188 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 188...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 189 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{ORDER?\", out=0x7fc98ee0a5e0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{SEARCH_DEST?\" at 235, result=1...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 235...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{SEARCH_DEST}\" at 248...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 249 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 249...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{SECTION=classes\" at 266, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 266...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 274 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 274...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{SECTION=jobs\" at 288, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 288...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 293 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 293...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 302 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{SECTION=jobs\", out=(nil)...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 303 on character \'}\'...
D [26/Mar/2017:12:28:08 +0200] [Client 10] con->http=0x55ec47ca8840
D [26/Mar/2017:12:28:08 +0200] [Client 10] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=1065, file=17
d [26/Mar/2017:12:28:08 +0200] cupsdAddSelect(fd=17, read_cb=0x55ec460e7840, write_cb=(nil), data=0x55ec47ca5bb0)
D [26/Mar/2017:12:28:08 +0200] [Client 10] Waiting for CGI data.
d [26/Mar/2017:12:28:08 +0200] select_timeout: JobHistoryUpdate=2147483647
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{SECTION=classes\", out=(nil)...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 304 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{SEARCH_DEST?\", out=0x7fc98ee0a5e0...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{?QUERY}\" at 359...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{SECTION}\" at 415...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 530 on EOF...
d [26/Mar/2017:12:28:08 +0200] [CGI] cgiCopyTemplateLang(tmpl=\"jobs-header.tmpl\")
d [26/Mar/2017:12:28:08 +0200] [CGI] lang=\"en_US.UTF8\", locale=\"/en_US\"...
d [26/Mar/2017:12:28:08 +0200] [CGI] Template file is \"/usr/share/cups/templates/jobs-header.tmpl\"...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{?which_jobs=\" at 14, result=1...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 14...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 15 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 15...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{?printer_name=\" at 45, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 45...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 51 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 51...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{printer_uri_supported}\" at 74...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 75 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{?printer_name=\", out=(nil)...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 144 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{?which_jobs=\", out=0x7fc98ee0a5e0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{?which_jobs=completed\" at 168, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 168...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 169 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 169...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{?printer_name=\" at 199, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 199...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 205 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 205...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{printer_uri_supported}\" at 228...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 229 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{?printer_name=\", out=0x7fc98ee0a5e0...
D [26/Mar/2017:12:28:08 +0200] [Client 10] con->http=0x55ec47ca8840
D [26/Mar/2017:12:28:08 +0200] [Client 10] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=1065, file=17
d [26/Mar/2017:12:28:08 +0200] cupsdAddSelect(fd=17, read_cb=0x55ec460e7840, write_cb=(nil), data=0x55ec47ca5bb0)
D [26/Mar/2017:12:28:08 +0200] [Client 10] Waiting for CGI data.
d [26/Mar/2017:12:28:08 +0200] cupsdRemoveSelect(fd=14)
d [26/Mar/2017:12:28:08 +0200] [Client 15] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1
D [26/Mar/2017:12:28:08 +0200] [Client 15] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [26/Mar/2017:12:28:08 +0200] [Client 15] Closing connection.
D [26/Mar/2017:12:28:08 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
d [26/Mar/2017:12:28:08 +0200] cupsdRemoveSelect(fd=18)
d [26/Mar/2017:12:28:08 +0200] cupsdRemoveSelect(fd=-1)
d [26/Mar/2017:12:28:08 +0200] process_children()
d [26/Mar/2017:12:28:08 +0200] cupsdFinishProcess(pid=1065, name=0x7fffcf4dfc10, namelen=1024, job_id=0x7fffcf4dfaf8(0)) = "/usr/lib/cups/cgi-bin/printers.cgi"
d [26/Mar/2017:12:28:08 +0200] cupsdDeleteCert: Removing certificate for PID 1065.
D [26/Mar/2017:12:28:08 +0200] PID 1065 (/usr/lib/cups/cgi-bin/printers.cgi) exited with no errors.
d [26/Mar/2017:12:28:08 +0200] select_timeout: JobHistoryUpdate=2147483647
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 358 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{?which_jobs=completed\", out=0x7fc98ee0a5e0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{?which_jobs=all\" at 376, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 376...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 377 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 377...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{?printer_name=\" at 407, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 407...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 413 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 413...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{printer_uri_supported}\" at 436...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 437 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{?printer_name=\", out=0x7fc98ee0a5e0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 554 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{?which_jobs=all\", out=0x7fc98ee0a5e0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{total=0\" at 583, result=1...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 583...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 591 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 591...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{#job_id}\" at 608...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{total}\" at 619...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{?which_jobs=\" at 634, result=1...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 634...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 641 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 641...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{which_jobs=all\" at 657, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 657...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 658 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 658...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 668 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{which_jobs=all\", out=(nil)...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 669 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{?which_jobs=\", out=(nil)...
d [26/Mar/2017:12:28:08 +0200] [Client 10] write_pipe: CGI output on fd 17.
d [26/Mar/2017:12:28:08 +0200] cupsdRemoveSelect(fd=17)
d [26/Mar/2017:12:28:08 +0200] cupsdAddSelect(fd=14, read_cb=(nil), write_cb=0x55ec460e99a0, data=0x55ec47ca5bb0)
D [26/Mar/2017:12:28:08 +0200] [Client 10] CGI data ready to be sent.
d [26/Mar/2017:12:28:08 +0200] select_timeout: JobHistoryUpdate=2147483647
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{total=1\" at 682, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 682...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 683 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 683...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 685 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{total=1\", out=(nil)...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 686 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{total=0\", out=0x7fc98ee0a5e0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 692 on EOF...
d [26/Mar/2017:12:28:08 +0200] [CGI] cgiCopyTemplateLang(tmpl=\"jobs.tmpl\")
d [26/Mar/2017:12:28:08 +0200] [CGI] lang=\"en_US.UTF8\", locale=\"/en_US\"...
d [26/Mar/2017:12:28:08 +0200] [CGI] Template file is \"/usr/share/cups/templates/jobs.tmpl\"...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{#job_id=0\" at 11, result=1...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 11...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 12 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 12...
d [26/Mar/2017:12:28:08 +0200] [CGI] Looping on \"job_id\" at 191, count=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 191...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{job_printer_uri}\" at 240...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{job_printer_name}\" at 260...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{job_id}\" at 273...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{?phone?\" at 281, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 281...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{phone}\" at 290...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 292 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 292...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 293 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{?phone?\", out=(nil)...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{?job_name=\" at 321, result=1...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 321...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 329 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 329...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{job_name}\" at 339...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 340 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{?job_name=\", out=(nil)...
D [26/Mar/2017:12:28:08 +0200] [Client 10] con->http=0x55ec47ca8840
D [26/Mar/2017:12:28:08 +0200] [Client 10] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=1065, file=17
d [26/Mar/2017:12:28:08 +0200] cupsdAddSelect(fd=17, read_cb=0x55ec460e7840, write_cb=(nil), data=0x55ec47ca5bb0)
D [26/Mar/2017:12:28:08 +0200] [Client 10] Waiting for CGI data.
D [26/Mar/2017:12:28:08 +0200] [Client 10] Sending 0-length chunk.
D [26/Mar/2017:12:28:08 +0200] [Client 10] Flushing write buffer.
D [26/Mar/2017:12:28:08 +0200] [Client 10] New state is HTTP_STATE_WAITING
d [26/Mar/2017:12:28:08 +0200] cupsdAddSelect(fd=14, read_cb=0x55ec460ea2c0, write_cb=(nil), data=0x55ec47ca5bb0)
D [26/Mar/2017:12:28:08 +0200] [Client 10] Waiting for request.
d [26/Mar/2017:12:28:08 +0200] cupsdRemoveSelect(fd=17)
d [26/Mar/2017:12:28:08 +0200] cupsdEndProcess(pid=1065, force=0)
D [26/Mar/2017:12:28:08 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
d [26/Mar/2017:12:28:08 +0200] select_timeout: JobHistoryUpdate=2147483647
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{?job_originating_user_name=\" at 385, result=1...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 385...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 394 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 394...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{job_originating_user_name}\" at 421...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 422 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{?job_originating_user_name=\", out=(nil)...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{job_k_octets}\" at 452...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{job_impressions_completed=0\" at 498, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 498...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 506 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 506...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{?job_impressions_completed}\" at 534...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 535 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{job_impressions_completed=0\", out=(nil)...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{job_state=3\" at 564, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 564...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{?time_at_creation=\" at 601, result=1...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 601...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 609 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 609...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{time_at_creation}\" at 627...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 628 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{?time_at_creation=\", out=(nil)...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 629 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 629...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{job_state=4\" at 642, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 642...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{?time_at_creation=\" at 676, result=1...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output first part...
d [26/Mar/2017:12:28:08 +0200] select_timeout: JobHistoryUpdate=2147483647
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 676...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 684 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 684...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{time_at_creation}\" at 702...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 703 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{?time_at_creation=\", out=(nil)...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 704 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 704...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{job_state=5\" at 718, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 718...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{?time_at_processing=\" at 760, result=1...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 760...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 768 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 768...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{time_at_processing}\" at 788...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 789 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{?time_at_processing=\", out=(nil)...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 790 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 790...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{job_state=6\" at 803, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 803...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 811 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 811...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{job_state=7\" at 825, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 825...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{?time_at_completed=\" at 861, result=1...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 861...
d [26/Mar/2017:12:28:08 +0200] select_timeout: JobHistoryUpdate=2147483647
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 869 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 869...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{time_at_completed}\" at 888...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 889 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{?time_at_completed=\", out=(nil)...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 890 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 890...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{job_state=8\" at 903, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 903...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 911 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 911...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{?time_at_completed=\" at 948, result=1...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 948...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 956 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 956...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{time_at_completed}\" at 975...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 976 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{?time_at_completed=\", out=(nil)...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 977 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{job_state=8\", out=(nil)...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 978 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{job_state=7\", out=(nil)...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 979 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{job_state=6\", out=(nil)...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 980 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{job_state=5\", out=(nil)...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 981 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] select_timeout: JobHistoryUpdate=2147483647
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{job_state=4\", out=(nil)...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 982 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{job_state=3\", out=(nil)...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{job_printer_state_message?\" at 1015, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 1015...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{job_printer_state_message}\" at 1052...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 1059 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 1059...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 1060 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{job_printer_state_message?\", out=(nil)...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{job_preserved>0\" at 1088, result=1...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 1088...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{job_state>5\" at 1101, result=1...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 1101...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{$org.cups.sid}\" at 1201...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{job_id}\" at 1304...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{job_printer_uri}\" at 1374...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 1425 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 1425...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 1426 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{job_state>5\", out=(nil)...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 1427 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 1427...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 1428 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{job_preserved>0\", out=(nil)...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{job_state=4\" at 1442, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 1442...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{$org.cups.sid}\" at 1542...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{job_id}\" at 1645...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{job_printer_uri}\" at 1715...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 1767 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 1767...
d [26/Mar/2017:12:28:08 +0200] select_timeout: JobHistoryUpdate=2147483647
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 1768 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{job_state=4\", out=(nil)...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{job_state=3\" at 1782, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 1782...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{$org.cups.sid}\" at 1882...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{job_id}\" at 1982...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{job_printer_uri}\" at 2052...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 2101 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 2101...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 2102 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{job_state=3\", out=(nil)...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting \"{job_state<7\" at 2116, result=0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Skip first part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 2116...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{$org.cups.sid}\" at 2216...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{job_id}\" at 2318...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{job_printer_uri}\" at 2388...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{$org.cups.sid}\" at 2538...
d [26/Mar/2017:12:28:08 +0200] [CGI] \"{job_id}\" at 2638...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 2686 on character \':\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Output second part...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 2686...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 2687 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{job_state<7\", out=(nil)...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 2707 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished looping on \"job_id\"...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 2727 on character \'}\'...
d [26/Mar/2017:12:28:08 +0200] [CGI] Finished \"{#job_id=0\", out=0x7fc98ee0a5e0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 2728 on EOF...
d [26/Mar/2017:12:28:08 +0200] [CGI] cgiCopyTemplateLang(tmpl=\"trailer.tmpl\")
d [26/Mar/2017:12:28:08 +0200] [CGI] lang=\"en_US.UTF8\", locale=\"/en_US\"...
d [26/Mar/2017:12:28:08 +0200] [CGI] Template file is \"/usr/share/cups/templates/trailer.tmpl\"...
d [26/Mar/2017:12:28:08 +0200] [CGI] Starting at file position 0...
d [26/Mar/2017:12:28:08 +0200] [CGI] Returning at file position 218 on EOF...
d [26/Mar/2017:12:28:08 +0200] select_timeout: JobHistoryUpdate=2147483647
d [26/Mar/2017:12:28:08 +0200] [Client 10] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1
D [26/Mar/2017:12:28:08 +0200] [Client 10] GET /cups.css HTTP/1.1
D [26/Mar/2017:12:28:08 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [26/Mar/2017:12:28:08 +0200] [Client 10] Read: status=200, state=3
d [26/Mar/2017:12:28:08 +0200] cupsdFindBest: uri="/cups.css", limit=2...
d [26/Mar/2017:12:28:08 +0200] cupsdFindBest: Location /admin/log(10) Limit 7f
d [26/Mar/2017:12:28:08 +0200] cupsdFindBest: Location /admin/conf(11) Limit 7f
d [26/Mar/2017:12:28:08 +0200] cupsdFindBest: Location /admin(6) Limit 7f
d [26/Mar/2017:12:28:08 +0200] cupsdFindBest: Location /(1) Limit 7f
d [26/Mar/2017:12:28:08 +0200] cupsdFindBest: best=/
d [26/Mar/2017:12:28:08 +0200] [Client 10] con->uri="/cups.css", con->best=0x55ec47bf29f0(/)
D [26/Mar/2017:12:28:08 +0200] [Client 10] Authorized as "root" using Basic.
d [26/Mar/2017:12:28:08 +0200] cupsdIsAuthorized: con->uri="/cups.css", con->best=0x55ec47bf29f0(/)
d [26/Mar/2017:12:28:08 +0200] cupsdIsAuthorized: level=CUPSD_AUTH_ANON, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0
d [26/Mar/2017:12:28:08 +0200] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
D [26/Mar/2017:12:28:08 +0200] [Client 10] Processing GET /cups.css
d [26/Mar/2017:12:28:08 +0200] [Client 10] get_file: filestats=0x7fffcf4d2d60, filename=0x7fffcf4d2df0, len=1024, returning "/usr/share/cups/doc/cups.css".
D [26/Mar/2017:12:28:08 +0200] [Client 10] filename="/usr/share/cups/doc/cups.css", type=text/css
d [26/Mar/2017:12:28:08 +0200] [Client 10] is_cgi: filename="/usr/share/cups/doc/cups.css", filestats=0x7fffcf4d2d60, type=text/css, returning 0.
d [26/Mar/2017:12:28:08 +0200] [Client 10] check_if_modified: filestats=0x7fffcf4d2d60(9961, 1485605800)) If-Modified-Since="Sat, 28 Jan 2017 12:16:40 GMT"
d [26/Mar/2017:12:28:08 +0200] [Client 10] cupsdSendError code=304, auth_type=0
D [26/Mar/2017:12:28:08 +0200] [Client 10] cupsdSendHeader: code=304, type="(null)", auth_type=0
D [26/Mar/2017:12:28:08 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
d [26/Mar/2017:12:28:08 +0200] select_timeout: JobHistoryUpdate=2147483647
I [26/Mar/2017:12:28:09 +0200] Expiring subscriptions...
d [26/Mar/2017:12:28:09 +0200] select_timeout: JobHistoryUpdate=2147483647
d [26/Mar/2017:12:28:09 +0200] select_timeout(0): 20 seconds to write dirty config/state files
d [26/Mar/2017:12:28:12 +0200] [Client 13] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1
D [26/Mar/2017:12:28:12 +0200] [Client 13] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [26/Mar/2017:12:28:12 +0200] [Client 13] Closing connection.
D [26/Mar/2017:12:28:12 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
d [26/Mar/2017:12:28:12 +0200] cupsdRemoveSelect(fd=16)
d [26/Mar/2017:12:28:12 +0200] cupsdRemoveSelect(fd=-1)
I [26/Mar/2017:12:28:12 +0200] Expiring subscriptions...
d [26/Mar/2017:12:28:12 +0200] select_timeout: JobHistoryUpdate=2147483647
I [26/Mar/2017:12:28:13 +0200] Expiring subscriptions...
d [26/Mar/2017:12:28:13 +0200] select_timeout: JobHistoryUpdate=2147483647
d [26/Mar/2017:12:28:13 +0200] select_timeout(0): 16 seconds to write dirty config/state files
d [26/Mar/2017:12:28:19 +0200] [Client 10] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1
D [26/Mar/2017:12:28:19 +0200] [Client 10] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [26/Mar/2017:12:28:19 +0200] [Client 10] Closing connection.
D [26/Mar/2017:12:28:19 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
d [26/Mar/2017:12:28:19 +0200] cupsdRemoveSelect(fd=14)
d [26/Mar/2017:12:28:19 +0200] cupsdRemoveSelect(fd=-1)
I [26/Mar/2017:12:28:19 +0200] Expiring subscriptions...
d [26/Mar/2017:12:28:19 +0200] cupsdCheckJobs: 0 active jobs, sleeping=0, ac-power=-1, reload=0, curtime=1490524099
d [26/Mar/2017:12:28:19 +0200] select_timeout: JobHistoryUpdate=2147483647
I [26/Mar/2017:12:28:20 +0200] Expiring subscriptions...
d [26/Mar/2017:12:28:20 +0200] select_timeout: JobHistoryUpdate=2147483647
d [26/Mar/2017:12:28:20 +0200] select_timeout(0): 9 seconds to write dirty config/state files
I [26/Mar/2017:12:28:29 +0200] Saving job.cache...
I [26/Mar/2017:12:28:29 +0200] Saving subscriptions.conf...
D [26/Mar/2017:12:28:29 +0200] cupsdSetBusyState: newbusy="Not busy", busy="Dirty files"
I [26/Mar/2017:12:28:29 +0200] Expiring subscriptions...
d [26/Mar/2017:12:28:29 +0200] cupsdCheckJobs: 0 active jobs, sleeping=0, ac-power=-1, reload=0, curtime=1490524109
d [26/Mar/2017:12:28:29 +0200] select_timeout: JobHistoryUpdate=2147483647
d [26/Mar/2017:12:28:29 +0200] select_timeout(0): 86400 seconds to do nothing
d [26/Mar/2017:12:29:52 +0200] cupsdAcceptClient(lis=0x55ec47bf2cf0(8)) Clients=0
D [26/Mar/2017:12:29:52 +0200] [Client 16] Server address is "[v1.::1]".
D [26/Mar/2017:12:29:52 +0200] [Client 16] Accepted from localhost:34788 (IPv6)
d [26/Mar/2017:12:29:52 +0200] cupsdAddSelect(fd=14, read_cb=0x55ec460ea2c0, write_cb=(nil), data=0x55ec47ca5bb0)
D [26/Mar/2017:12:29:52 +0200] [Client 16] Waiting for request.
I [26/Mar/2017:12:29:52 +0200] Expiring subscriptions...
d [26/Mar/2017:12:29:52 +0200] cupsdCheckJobs: 0 active jobs, sleeping=0, ac-power=-1, reload=0, curtime=1490524192
D [26/Mar/2017:12:29:52 +0200] Report: clients=1
D [26/Mar/2017:12:29:52 +0200] Report: jobs=13
D [26/Mar/2017:12:29:52 +0200] Report: jobs-active=0
D [26/Mar/2017:12:29:52 +0200] Report: printers=2
D [26/Mar/2017:12:29:52 +0200] Report: stringpool-string-count=2653
D [26/Mar/2017:12:29:52 +0200] Report: stringpool-alloc-bytes=9256
D [26/Mar/2017:12:29:52 +0200] Report: stringpool-total-bytes=51120
d [26/Mar/2017:12:29:52 +0200] select_timeout: JobHistoryUpdate=2147483647
I [26/Mar/2017:12:29:53 +0200] Expiring subscriptions...
d [26/Mar/2017:12:29:53 +0200] select_timeout: JobHistoryUpdate=2147483647
d [26/Mar/2017:12:29:53 +0200] select_timeout(0): 300 seconds to timeout a client connection
d [26/Mar/2017:12:29:57 +0200] [Client 16] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1
D [26/Mar/2017:12:29:57 +0200] [Client 16] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [26/Mar/2017:12:29:57 +0200] [Client 16] Closing connection.
D [26/Mar/2017:12:29:57 +0200] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
d [26/Mar/2017:12:29:57 +0200] cupsdRemoveSelect(fd=14)
d [26/Mar/2017:12:29:57 +0200] cupsdRemoveSelect(fd=-1)
I [26/Mar/2017:12:29:57 +0200] Expiring subscriptions...
d [26/Mar/2017:12:29:57 +0200] select_timeout: JobHistoryUpdate=2147483647
I [26/Mar/2017:12:29:58 +0200] Expiring subscriptions...
d [26/Mar/2017:12:29:58 +0200] select_timeout: JobHistoryUpdate=2147483647
d [26/Mar/2017:12:29:58 +0200] select_timeout(0): 86400 seconds to do nothing

Last edited by WorksAsIntended (2017-03-26 10:34:54)

seth

Member

Registered: 2012-09-03

Posts: 51,235

Re: cupsd not working correctly

broken pipe error. what's the output of "uname -a" ?

edit: "uname -a" ;-)

Last edited by seth (2017-03-26 15:00:47)

---

How to upload text · How to boot w/o GUI · Disable Windows Fast-Start! · Fix your xinitrc

WorksAsIntended

Member

Registered: 2017-03-25

Posts: 13

Re: cupsd not working correctly

As written before I use the 4.10.5 Kernel:

[pia@pias_laptop ~]$ uname -a
Linux pias_laptop 4.10.5-1-ARCH #1 SMP PREEMPT Wed Mar 22 14:42:03 CET 2017 x86_64 GNU/Linux

seth

Member

Registered: 2012-09-03

Posts: 51,235

Re: cupsd not working correctly

I was more curious about the architecture - the package I found in AUR downloads some i386 packages.
a) is it the one you use?
b) is the other system x86-64 as well?
c) if so, is there a difference in installed lib32 packages?

---

How to upload text · How to boot w/o GUI · Disable Windows Fast-Start! · Fix your xinitrc

paulkerry

Member

From: Sheffield, UK

Registered: 2014-10-02

Posts: 611

Re: cupsd not working correctly

Coming in late to this for cupsd not starting at boot - see #10 at https://bbs.archlinux.org/viewtopic.php?id=216216

WorksAsIntended

Member

Registered: 2017-03-25

Posts: 13

Re: cupsd not working correctly

Well first of all sry for the really late reply. My wife, my 1y old son and myself all got sick and I simply had no chance to turn the pc on.

The 32bit problem might be the key. Both systems are on 64bit, but I have multilib enabled and a few 32bit packages installed on the other system. I will have a look at this.

Yes, the package I use is aur/brother-mfc-l2700dn, but afaik this is not a 32bit package. They only extract the ppd and a few other files from the 32bit rpm as source.

@paulkerry: thanks, I added this line manually in the past, but a update must have destroyed it...

seth

Member

Registered: 2012-09-03

Posts: 51,235

Re: cupsd not working correctly

The "few other files" will likely be "filters" ie. executables - if those are 32bit ELF binaries, well... you see my point ;-)

---

How to upload text · How to boot w/o GUI · Disable Windows Fast-Start! · Fix your xinitrc

Stumpjumper

Member

From: Netherlands

Registered: 2011-02-20

Posts: 3

Re: cupsd not working correctly

broken pipe error. what's the output of "uname -a" ?

edit: "uname -a" ;-)

I came across the same warning (error?) while trying to set up my DCP-L2540DN using the lib32-libcups from the multilib repo.

When I try to print a test page using the CUPS web-interface, I noticed a soft 'click' coming from the printer. However no printed output. Hence it seems it's trying to do something, but is unsuccesful. No errors pop up in the error log though.

Previously, I was able to get the printer to work under Slackware14.2, using the compat32-packages created by Alien BOB. If I remember correctly, that meant running CUPS completely 32-bit. Here we are having a 64 bit CUPS that has to cooperate with a 32-bit printer driver. No clue where to look next to fix this issue. Any help or suggestions are highly appreciated!

cheers!

Stumpjumper

Member

From: Netherlands

Registered: 2011-02-20

Posts: 3

Re: cupsd not working correctly

I came across the same warning (error?) while trying to set up my DCP-L2540DN using the lib32-libcups from the multilib repo.

When I try to print a test page using the CUPS web-interface, I noticed a soft 'click' coming from the printer. However no printed output. Hence it seems it's trying to do something, but is unsuccesful. No errors pop up in the error log though.

Previously, I was able to get the printer to work under Slackware14.2, using the compat32-packages created by Alien BOB. If I remember correctly, that meant running CUPS completely 32-bit. Here we are having a 64 bit CUPS that has to cooperate with a 32-bit printer driver. No clue where to look next to fix this issue. Any help or suggestions are highly appreciated!

cheers!

Solved it.

In my case it had nothing to do with incompatibility between 32- and 64-bit binaries. The real problem lied in the fact that ghostscript was not installed on my machine, which the Brother drivers turned out to be dependent upon. Trivial, but it took a bit of time before I figured it out. Hint: The drivers report logfiles in /tmp/. In my case

 # tail -n100 -f /tmp/br_cupswrapper_ml1_lpderr 
which: no gs in (/usr/lib/cups/filter:/usr/bin:/usr/bin:/bin:/usr/bin)

gave the answer. It now works fine combining a 32-bit driver with a 64-bit cupsd.

cheers!