CUPS problem: Only root can print

Hi all, I just got a brand new PC, installed Crux 3.0 from CD, and copied all important files from the old to the new system (including /etc/passwd, /etc/group, configuration files stc.). I installed CUPS and set up my WLAN printer, a HP LaserJet Pro 1102w. Everythings works fine, except CUPS: I can only print as root. A normal user's attempt to print is silently ignored. No authorization dialog, no error message, nothing in error_log, nothing left in the queue. As a normal user I can print via lp, so it must be a CUPS problem. I can also *not* print to a virtual pdf printer, so it's not a driver problem. The cupsd.conf I use is the default one, which works well on all my other systems. The user is in group "lp", /etc/hosts.allow and hosts.deny are set up correctly (all hosts allowed), all file modes are correct AFAICS. I guess I am missing something basic and important, but I'm at my wit's end now. Below is the ouput if the CUPS log level is to "debug". It looks unsuspicious to me, but maybe some expert can tell from it what exactly is happening. Any help is much appreciated! Regards, Bernd -------------------------------------------- I [10/Mar/2014:14:32:12 +0000] Listening to [v1.::1]:631 (IPv6) I [10/Mar/2014:14:32:12 +0000] Listening to 127.0.0.1:631 (IPv4) I [10/Mar/2014:14:32:12 +0000] Listening to /var/run/cups/cups.sock (Domain) I [10/Mar/2014:14:32:12 +0000] Remote access is disabled. D [10/Mar/2014:14:32:12 +0000] Added auto ServerAlias Black I [10/Mar/2014:14:32:12 +0000] Loaded configuration file "/etc/cups/cupsd.conf" D [10/Mar/2014:14:32:12 +0000] Repairing access permissions of "/etc/cups/classes.conf" I [10/Mar/2014:14:32:12 +0000] Using default TempDir of /var/spool/cups/tmp... I [10/Mar/2014:14:32:12 +0000] Configured for up to 100 clients. I [10/Mar/2014:14:32:12 +0000] Allowing up to 100 client connections per host. I [10/Mar/2014:14:32:12 +0000] Using policy "default" as the default. I [10/Mar/2014:14:32:12 +0000] Full reload is required. I [10/Mar/2014:14:32:12 +0000] Loaded MIME database from "/usr/share/cups/mime" and "/etc/cups": 39 types, 52 filters... D [10/Mar/2014:14:32:12 +0000] Loading printer hp... D [10/Mar/2014:14:32:12 +0000] load_ppd: Loading /var/cache/cups/hp.data... D [10/Mar/2014:14:32:12 +0000] cupsdRegisterPrinter(p=0x7fdd15846130(hp)) I [10/Mar/2014:14:32:12 +0000] Loading job cache file "/var/cache/cups/job.cache"... I [10/Mar/2014:14:32:12 +0000] Full reload complete. D [10/Mar/2014:14:32:12 +0000] cupsdCleanFiles(path="/var/spool/cups/tmp", pattern="(null)") I [10/Mar/2014:14:32:12 +0000] Cleaning out old files in "/var/spool/cups/tmp". D [10/Mar/2014:14:32:12 +0000] cupsdCleanFiles(path="/var/cache/cups", pattern="*.ipp") I [10/Mar/2014:14:32:12 +0000] Cleaning out old files in "/var/cache/cups". I [10/Mar/2014:14:32:12 +0000] Listening to [v1.::1]:631 on fd 7... I [10/Mar/2014:14:32:12 +0000] Listening to 127.0.0.1:631 on fd 8... I [10/Mar/2014:14:32:12 +0000] Listening to /var/run/cups/cups.sock:631 on fd 9... I [10/Mar/2014:14:32:12 +0000] Resuming new connection processing... D [10/Mar/2014:14:32:12 +0000] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [10/Mar/2014:14:32:12 +0000] Discarding unused server-started event... D [10/Mar/2014:14:32:13 +0000] Report: clients=0 D [10/Mar/2014:14:32:13 +0000] Report: jobs=0 D [10/Mar/2014:14:32:13 +0000] Report: jobs-active=0 D [10/Mar/2014:14:32:13 +0000] Report: printers=1 D [10/Mar/2014:14:32:13 +0000] Report: stringpool-string-count=17526 D [10/Mar/2014:14:32:13 +0000] Report: stringpool-alloc-bytes=9056 D [10/Mar/2014:14:32:13 +0000] Report: stringpool-total-bytes=317152 D [10/Mar/2014:14:32:17 +0000] [Client 12] Accepted from localhost:631 (IPv4) D [10/Mar/2014:14:32:17 +0000] [Client 12] Waiting for request. D [10/Mar/2014:14:32:17 +0000] [Client 12] POST /printers/hp HTTP/1.1 D [10/Mar/2014:14:32:17 +0000] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [10/Mar/2014:14:32:17 +0000] [Client 12] No authentication data provided. D [10/Mar/2014:14:32:17 +0000] [CGI] argv[0] = "/usr/lib/cups/cgi-bin/printers.cgi" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[0] = "CUPS_CACHEDIR=/var/cache/cups" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[1] = "CUPS_DATADIR=/usr/share/cups" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[2] = "CUPS_DOCROOT=/usr/share/cups/doc" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[3] = "CUPS_FONTPATH=/usr/share/cups/fonts" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[4] = "CUPS_REQUESTROOT=/var/spool/cups" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[5] = "CUPS_SERVERBIN=/usr/lib/cups" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[6] = "CUPS_SERVERROOT=/etc/cups" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[7] = "CUPS_STATEDIR=/var/run/cups" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[8] = "HOME=/var/spool/cups/tmp" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[9] = "PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[10] = "SERVER_ADMIN=root@Black" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[11] = "SOFTWARE=CUPS/1.7.1" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[12] = "TMPDIR=/var/spool/cups/tmp" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[13] = "USER=root" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[14] = "CUPS_MAX_MESSAGE=2047" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[15] = "CUPS_SERVER=/var/run/cups/cups.sock" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[16] = "CUPS_ENCRYPTION=IfRequested" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[17] = "IPP_PORT=631" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[18] = "LANG=en_US.UTF8" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[19] = "REDIRECT_STATUS=1" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[20] = "GATEWAY_INTERFACE=CGI/1.1" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[21] = "SERVER_NAME=localhost" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[22] = "SERVER_PORT=631" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[23] = "REMOTE_ADDR=127.0.0.1" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[24] = "REMOTE_HOST=localhost" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[25] = "SCRIPT_NAME=/printers/hp" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[26] = "SCRIPT_FILENAME=/usr/share/cups/doc/printers/hp" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[27] = "PATH_INFO=/hp" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[28] = "SERVER_PROTOCOL=HTTP/1.1" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[29] = "HTTP_COOKIE=TiddlyWiki=chkRegExpSearch:"false" chkCaseSensitiveSearch:"false" chkIncrementalSearch:"true" chkAnimate:"true" chkSaveBackups:"true" chkAutoSave:"true" chkGenerateAnRssFeed:"false" chkSaveEmptyTemplate:"false" chkOpenInNewWindow:"true" chkToggleLinks:"false" chkHttpReadOnly:"true" chkForceMinorUpdate:"false" chkConfirmDelete:"true" chkInsertTabs:"false" chkUsePreForStorage:"true" chkDisplayInstrumentation:"false" txtBackupFolder:"" txtEditorFocus:"text" txtMainTab:"Timeline" txtMoreTab:"moreTabAll" txtMaxEditRows:"30" txtFileSystemCharSet:"UTF-8" txtTheme:"" txtUserName:"Bernd" chkSliderOptionsPanel:"true"; org.cups.sid=820b669b6c51f1da8438e8ac559b8637" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[30] = "HTTP_USER_AGENT=Mozilla/5.0 (X11; Linux x86_64; rv:27.0) Gecko/20100101 Firefox/27.0" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[31] = "HTTP_REFERER=http://localhost:631/printers/hp" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[32] = "REQUEST_METHOD=POST" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[33] = "CONTENT_LENGTH=64" D [10/Mar/2014:14:32:17 +0000] [CGI] envp[34] = "CONTENT_TYPE=application/x-www-form-urlencoded" D [10/Mar/2014:14:32:17 +0000] [CGI] Started /usr/lib/cups/cgi-bin/printers.cgi (PID 24994) I [10/Mar/2014:14:32:17 +0000] [Client 12] Started "/usr/lib/cups/cgi-bin/printers.cgi" (pid=24994) D [10/Mar/2014:14:32:17 +0000] [Client 12] file=14 D [10/Mar/2014:14:32:17 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:17 +0000] [CGI] org.cups.sid cookie not found, initializing! D [10/Mar/2014:14:32:17 +0000] [CGI] org.cups.sid cookie is "25b496f62a8f3e51965df132fb58f5e7" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetVariable: org.cups.sid="97e89f367b2f8831b4e600909736d74f" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetVariable: OP="print-test-page" D [10/Mar/2014:14:32:17 +0000] [CGI] org.cups.sid form variable is "97e89f367b2f8831b4e600909736d74f" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiClearVariables called. D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetVariable: SECTION="printers" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetVariable: REFRESH_PAGE="" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetVariable: PRINTER_NAME="hp" D [10/Mar/2014:14:32:17 +0000] [Client 13] Accepted from localhost (Domain) D [10/Mar/2014:14:32:17 +0000] [Client 13] Waiting for request. D [10/Mar/2014:14:32:17 +0000] [Client 13] POST / HTTP/1.1 D [10/Mar/2014:14:32:17 +0000] cupsdSetBusyState: newbusy="Active clients", busy="Active clients" D [10/Mar/2014:14:32:17 +0000] [Client 13] No authentication data provided. D [10/Mar/2014:14:32:17 +0000] [Client 13] 2.0 CUPS-Get-Default 1 D [10/Mar/2014:14:32:17 +0000] CUPS-Get-Default D [10/Mar/2014:14:32:17 +0000] [Client 13] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost D [10/Mar/2014:14:32:17 +0000] [Client 13] Content-Length: 152 D [10/Mar/2014:14:32:17 +0000] [Client 13] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=152, response=0x7fdd1599fb10(IPP_IDLE), pipe_pid=0, file=-1 D [10/Mar/2014:14:32:17 +0000] [Client 13] Writing IPP response, ipp_state=DATA, old wused=0, new wused=0 D [10/Mar/2014:14:32:17 +0000] [Client 13] bytes=0, http_state=0, data_remaining=0 D [10/Mar/2014:14:32:17 +0000] [Client 13] Waiting for request. D [10/Mar/2014:14:32:17 +0000] cupsdSetBusyState: newbusy="Active clients", busy="Active clients" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetVariable: DEFAULT_NAME="hp" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetVariable: DEFAULT_URI="/printers/hp" D [10/Mar/2014:14:32:17 +0000] [CGI] show_printer(http=0x7f68d335f4e0, printer="hp") D [10/Mar/2014:14:32:17 +0000] [Client 13] POST / HTTP/1.1 D [10/Mar/2014:14:32:17 +0000] cupsdSetBusyState: newbusy="Active clients", busy="Active clients" D [10/Mar/2014:14:32:17 +0000] [Client 13] No authentication data provided. D [10/Mar/2014:14:32:17 +0000] [Client 13] 2.0 Get-Printer-Attributes 2 D [10/Mar/2014:14:32:17 +0000] Get-Printer-Attributes ipp://localhost/printers/hp D [10/Mar/2014:14:32:17 +0000] [Client 13] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost/printers/hp) from localhost D [10/Mar/2014:14:32:17 +0000] [Client 13] Content-Length: 627 D [10/Mar/2014:14:32:17 +0000] [Client 13] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=627, response=0x7fdd1599f850(IPP_IDLE), pipe_pid=0, file=-1 D [10/Mar/2014:14:32:17 +0000] [Client 13] Writing IPP response, ipp_state=DATA, old wused=0, new wused=0 D [10/Mar/2014:14:32:17 +0000] [Client 13] bytes=0, http_state=0, data_remaining=0 D [10/Mar/2014:14:32:17 +0000] [Client 13] Waiting for request. D [10/Mar/2014:14:32:17 +0000] cupsdSetBusyState: newbusy="Active clients", busy="Active clients" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetVariable: SERVER_NAME="localhost" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetVariable: CUPS_VERSION="CUPS v1.7.1" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetVariable: SERVER_NAME="localhost" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetVariable: CUPS_VERSION="CUPS v1.7.1" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetArray: printer_is_accepting_jobs[0]="0" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetArray: printer_is_shared[0]="1" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetArray: printer_state[0]="5" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetArray: admin_uri[0]="/admin/" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetArray: printer_uri_supported[0]="/printers/hp" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetArray: printer_name[0]="hp" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetArray: printer_location[0]="" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetArray: printer_info[0]="hp" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetArray: job_sheets_default[0]="none, none" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetArray: device_uri[0]="file:///dev/null" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetArray: color_supported[0]="0" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetArray: printer_make_and_model[0]="HP LaserJet Pro P1102w Foomatic/foo2zjs-z2 (recommended)" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetArray: media_default[0]="iso_a4_210x297mm" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetArray: sides_supported[0]="one-sided" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetArray: sides_default[0]="one-sided" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetArray: printer_commands[0]="AutoConfigure, Clean, PrintSelfTestPage" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetArray: server_is_sharing_printers[0]="0" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetVariable: TITLE="hp" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetVariable: SERVER_NAME="localhost" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetVariable: CUPS_VERSION="CUPS v1.7.1" D [10/Mar/2014:14:32:17 +0000] [Client 12] CGI data ready to be sent. D [10/Mar/2014:14:32:17 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, response=(nil)(), pipe_pid=24994, file=14 D [10/Mar/2014:14:32:17 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:17 +0000] Script header: Set-Cookie: org.cups.sid=25b496f62a8f3e51965df132fb58f5e7; path=/; D [10/Mar/2014:14:32:17 +0000] Script header: Content-Type: text/html;charset=utf-8 D [10/Mar/2014:14:32:17 +0000] Script header: D [10/Mar/2014:14:32:17 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24994, file=14 D [10/Mar/2014:14:32:17 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:17 +0000] [Client 12] CGI data ready to be sent. D [10/Mar/2014:14:32:17 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24994, file=14 D [10/Mar/2014:14:32:17 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:17 +0000] [CGI] Regular expression ".*Clean.*" D [10/Mar/2014:14:32:17 +0000] [CGI] matches[0].rm_so=0 D [10/Mar/2014:14:32:17 +0000] [CGI] matches[1].rm_so=-1 D [10/Mar/2014:14:32:17 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24994, file=14 D [10/Mar/2014:14:32:17 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:17 +0000] [CGI] Regular expression ".*PrintSelfTestPage.*" D [10/Mar/2014:14:32:17 +0000] [Client 12] CGI data ready to be sent. D [10/Mar/2014:14:32:17 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24994, file=14 D [10/Mar/2014:14:32:17 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:17 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24994, file=14 D [10/Mar/2014:14:32:17 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:17 +0000] [CGI] matches[0].rm_so=0 D [10/Mar/2014:14:32:17 +0000] [CGI] matches[1].rm_so=-1 D [10/Mar/2014:14:32:17 +0000] [Client 12] CGI data ready to be sent. D [10/Mar/2014:14:32:17 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24994, file=14 D [10/Mar/2014:14:32:17 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:17 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24994, file=14 D [10/Mar/2014:14:32:17 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:17 +0000] [Client 12] CGI data ready to be sent. D [10/Mar/2014:14:32:17 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24994, file=14 D [10/Mar/2014:14:32:17 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:17 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24994, file=14 D [10/Mar/2014:14:32:17 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:17 +0000] [Client 12] CGI data ready to be sent. D [10/Mar/2014:14:32:17 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24994, file=14 D [10/Mar/2014:14:32:17 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:17 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24994, file=14 D [10/Mar/2014:14:32:17 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:17 +0000] [Client 13] POST / HTTP/1.1 D [10/Mar/2014:14:32:17 +0000] cupsdSetBusyState: newbusy="Active clients", busy="Active clients" D [10/Mar/2014:14:32:17 +0000] [Client 13] No authentication data provided. D [10/Mar/2014:14:32:17 +0000] [Client 13] 2.0 Get-Jobs 3 D [10/Mar/2014:14:32:17 +0000] Get-Jobs ipp://localhost:631/printers/hp D [10/Mar/2014:14:32:17 +0000] [Client 13] Returning IPP successful-ok for Get-Jobs (ipp://localhost:631/printers/hp) from localhost D [10/Mar/2014:14:32:17 +0000] [Client 13] Content-Length: 75 D [10/Mar/2014:14:32:17 +0000] [Client 13] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=75, response=0x7fdd1599fb10(IPP_IDLE), pipe_pid=0, file=-1 D [10/Mar/2014:14:32:17 +0000] [Client 13] Writing IPP response, ipp_state=DATA, old wused=0, new wused=0 D [10/Mar/2014:14:32:17 +0000] [Client 13] bytes=0, http_state=0, data_remaining=0 D [10/Mar/2014:14:32:17 +0000] [Client 13] Waiting for request. D [10/Mar/2014:14:32:17 +0000] cupsdSetBusyState: newbusy="Active clients", busy="Active clients" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiClearVariables called. D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetVariable: ORDER="asc" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetVariable: SECTION="printers" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetVariable: TOTAL="0" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetVariable: PRINTER_NAME="hp" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetVariable: PRINTER_URI_SUPPORTED="/printers/hp" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetVariable: THISURL="/printers/hp" D [10/Mar/2014:14:32:17 +0000] [CGI] cgiSetVariable: SEARCH_DEST="hp" D [10/Mar/2014:14:32:17 +0000] [Client 12] CGI data ready to be sent. D [10/Mar/2014:14:32:17 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24994, file=14 D [10/Mar/2014:14:32:17 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:17 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24994, file=14 D [10/Mar/2014:14:32:17 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:17 +0000] [Client 12] CGI data ready to be sent. D [10/Mar/2014:14:32:17 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24994, file=14 D [10/Mar/2014:14:32:17 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:17 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24994, file=14 D [10/Mar/2014:14:32:17 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:17 +0000] [Client 12] CGI data ready to be sent. D [10/Mar/2014:14:32:17 +0000] [Client 13] HTTP_STATE_WAITING Closing on EOF D [10/Mar/2014:14:32:17 +0000] [Client 13] Closing connection. D [10/Mar/2014:14:32:17 +0000] cupsdSetBusyState: newbusy="Active clients", busy="Active clients" D [10/Mar/2014:14:32:17 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24994, file=14 D [10/Mar/2014:14:32:17 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:17 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24994, file=14 D [10/Mar/2014:14:32:17 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:17 +0000] [Client 12] CGI data ready to be sent. D [10/Mar/2014:14:32:17 +0000] PID 24994 (/usr/lib/cups/cgi-bin/printers.cgi) exited with no errors. D [10/Mar/2014:14:32:17 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24994, file=14 D [10/Mar/2014:14:32:17 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:17 +0000] [Client 12] Waiting for request. D [10/Mar/2014:14:32:17 +0000] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [10/Mar/2014:14:32:17 +0000] [Client 12] GET /cups.css HTTP/1.1 D [10/Mar/2014:14:32:17 +0000] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [10/Mar/2014:14:32:17 +0000] [Client 12] No authentication data provided. D [10/Mar/2014:14:32:17 +0000] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [10/Mar/2014:14:32:17 +0000] [Client 12] GET /images/left.gif HTTP/1.1 D [10/Mar/2014:14:32:17 +0000] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [10/Mar/2014:14:32:17 +0000] [Client 12] No authentication data provided. D [10/Mar/2014:14:32:17 +0000] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [10/Mar/2014:14:32:17 +0000] [Client 13] Accepted from localhost:631 (IPv4) D [10/Mar/2014:14:32:17 +0000] [Client 13] Waiting for request. D [10/Mar/2014:14:32:17 +0000] [Client 12] GET /images/right.gif HTTP/1.1 D [10/Mar/2014:14:32:17 +0000] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [10/Mar/2014:14:32:17 +0000] [Client 12] No authentication data provided. D [10/Mar/2014:14:32:17 +0000] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [10/Mar/2014:14:32:17 +0000] [Client 12] GET /images/unsel.gif HTTP/1.1 D [10/Mar/2014:14:32:17 +0000] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [10/Mar/2014:14:32:17 +0000] [Client 12] No authentication data provided. D [10/Mar/2014:14:32:17 +0000] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [10/Mar/2014:14:32:17 +0000] [Client 13] GET /images/sel.gif HTTP/1.1 D [10/Mar/2014:14:32:17 +0000] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [10/Mar/2014:14:32:17 +0000] [Client 13] No authentication data provided. D [10/Mar/2014:14:32:17 +0000] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [10/Mar/2014:14:32:20 +0000] [Client 12] POST /printers/hp HTTP/1.1 D [10/Mar/2014:14:32:20 +0000] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [10/Mar/2014:14:32:20 +0000] [Client 12] No authentication data provided. D [10/Mar/2014:14:32:20 +0000] [CGI] argv[0] = "/usr/lib/cups/cgi-bin/printers.cgi" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[0] = "CUPS_CACHEDIR=/var/cache/cups" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[1] = "CUPS_DATADIR=/usr/share/cups" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[2] = "CUPS_DOCROOT=/usr/share/cups/doc" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[3] = "CUPS_FONTPATH=/usr/share/cups/fonts" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[4] = "CUPS_REQUESTROOT=/var/spool/cups" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[5] = "CUPS_SERVERBIN=/usr/lib/cups" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[6] = "CUPS_SERVERROOT=/etc/cups" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[7] = "CUPS_STATEDIR=/var/run/cups" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[8] = "HOME=/var/spool/cups/tmp" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[9] = "PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[10] = "SERVER_ADMIN=root@Black" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[11] = "SOFTWARE=CUPS/1.7.1" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[12] = "TMPDIR=/var/spool/cups/tmp" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[13] = "USER=root" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[14] = "CUPS_MAX_MESSAGE=2047" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[15] = "CUPS_SERVER=/var/run/cups/cups.sock" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[16] = "CUPS_ENCRYPTION=IfRequested" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[17] = "IPP_PORT=631" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[18] = "LANG=en_US.UTF8" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[19] = "REDIRECT_STATUS=1" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[20] = "GATEWAY_INTERFACE=CGI/1.1" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[21] = "SERVER_NAME=localhost" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[22] = "SERVER_PORT=631" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[23] = "REMOTE_ADDR=127.0.0.1" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[24] = "REMOTE_HOST=localhost" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[25] = "SCRIPT_NAME=/printers/hp" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[26] = "SCRIPT_FILENAME=/usr/share/cups/doc/printers/hp" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[27] = "PATH_INFO=/hp" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[28] = "SERVER_PROTOCOL=HTTP/1.1" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[29] = "HTTP_COOKIE=TiddlyWiki=chkRegExpSearch:"false" chkCaseSensitiveSearch:"false" chkIncrementalSearch:"true" chkAnimate:"true" chkSaveBackups:"true" chkAutoSave:"true" chkGenerateAnRssFeed:"false" chkSaveEmptyTemplate:"false" chkOpenInNewWindow:"true" chkToggleLinks:"false" chkHttpReadOnly:"true" chkForceMinorUpdate:"false" chkConfirmDelete:"true" chkInsertTabs:"false" chkUsePreForStorage:"true" chkDisplayInstrumentation:"false" txtBackupFolder:"" txtEditorFocus:"text" txtMainTab:"Timeline" txtMoreTab:"moreTabAll" txtMaxEditRows:"30" txtFileSystemCharSet:"UTF-8" txtTheme:"" txtUserName:"Bernd" chkSliderOptionsPanel:"true"; org.cups.sid=25b496f62a8f3e51965df132fb58f5e7" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[30] = "HTTP_USER_AGENT=Mozilla/5.0 (X11; Linux x86_64; rv:27.0) Gecko/20100101 Firefox/27.0" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[31] = "HTTP_REFERER=http://localhost:631/printers/hp" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[32] = "REQUEST_METHOD=POST" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[33] = "CONTENT_LENGTH=64" D [10/Mar/2014:14:32:20 +0000] [CGI] envp[34] = "CONTENT_TYPE=application/x-www-form-urlencoded" D [10/Mar/2014:14:32:20 +0000] [CGI] Started /usr/lib/cups/cgi-bin/printers.cgi (PID 24996) I [10/Mar/2014:14:32:20 +0000] [Client 12] Started "/usr/lib/cups/cgi-bin/printers.cgi" (pid=24996) D [10/Mar/2014:14:32:20 +0000] [Client 12] file=15 D [10/Mar/2014:14:32:20 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:20 +0000] [CGI] org.cups.sid cookie not found, initializing! D [10/Mar/2014:14:32:20 +0000] [CGI] org.cups.sid cookie is "7c56dcd8976dc6722d73440d833a7be1" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetVariable: org.cups.sid="25b496f62a8f3e51965df132fb58f5e7" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetVariable: OP="print-test-page" D [10/Mar/2014:14:32:20 +0000] [CGI] org.cups.sid form variable is "25b496f62a8f3e51965df132fb58f5e7" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiClearVariables called. D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetVariable: SECTION="printers" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetVariable: REFRESH_PAGE="" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetVariable: PRINTER_NAME="hp" D [10/Mar/2014:14:32:20 +0000] [Client 14] Accepted from localhost (Domain) D [10/Mar/2014:14:32:20 +0000] [Client 14] Waiting for request. D [10/Mar/2014:14:32:20 +0000] [Client 14] POST / HTTP/1.1 D [10/Mar/2014:14:32:20 +0000] cupsdSetBusyState: newbusy="Active clients", busy="Active clients" D [10/Mar/2014:14:32:20 +0000] [Client 14] No authentication data provided. D [10/Mar/2014:14:32:20 +0000] [Client 14] 2.0 CUPS-Get-Default 1 D [10/Mar/2014:14:32:20 +0000] CUPS-Get-Default D [10/Mar/2014:14:32:20 +0000] [Client 14] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost D [10/Mar/2014:14:32:20 +0000] [Client 14] Content-Length: 152 D [10/Mar/2014:14:32:20 +0000] [Client 14] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=152, response=0x7fdd1599fde0(IPP_IDLE), pipe_pid=0, file=-1 D [10/Mar/2014:14:32:20 +0000] [Client 14] Writing IPP response, ipp_state=DATA, old wused=0, new wused=0 D [10/Mar/2014:14:32:20 +0000] [Client 14] bytes=0, http_state=0, data_remaining=0 D [10/Mar/2014:14:32:20 +0000] [Client 14] Waiting for request. D [10/Mar/2014:14:32:20 +0000] cupsdSetBusyState: newbusy="Active clients", busy="Active clients" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetVariable: DEFAULT_NAME="hp" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetVariable: DEFAULT_URI="/printers/hp" D [10/Mar/2014:14:32:20 +0000] [CGI] show_printer(http=0x7f8cb6b6f4e0, printer="hp") D [10/Mar/2014:14:32:20 +0000] [Client 14] POST / HTTP/1.1 D [10/Mar/2014:14:32:20 +0000] cupsdSetBusyState: newbusy="Active clients", busy="Active clients" D [10/Mar/2014:14:32:20 +0000] [Client 14] No authentication data provided. D [10/Mar/2014:14:32:20 +0000] [Client 14] 2.0 Get-Printer-Attributes 2 D [10/Mar/2014:14:32:20 +0000] Get-Printer-Attributes ipp://localhost/printers/hp D [10/Mar/2014:14:32:20 +0000] [Client 14] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost/printers/hp) from localhost D [10/Mar/2014:14:32:20 +0000] [Client 14] Content-Length: 627 D [10/Mar/2014:14:32:20 +0000] [Client 14] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=627, response=0x7fdd1599f850(IPP_IDLE), pipe_pid=0, file=-1 D [10/Mar/2014:14:32:20 +0000] [Client 14] Writing IPP response, ipp_state=DATA, old wused=0, new wused=0 D [10/Mar/2014:14:32:20 +0000] [Client 14] bytes=0, http_state=0, data_remaining=0 D [10/Mar/2014:14:32:20 +0000] [Client 14] Waiting for request. D [10/Mar/2014:14:32:20 +0000] cupsdSetBusyState: newbusy="Active clients", busy="Active clients" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetVariable: SERVER_NAME="localhost" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetVariable: CUPS_VERSION="CUPS v1.7.1" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetVariable: SERVER_NAME="localhost" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetVariable: CUPS_VERSION="CUPS v1.7.1" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetArray: printer_is_accepting_jobs[0]="0" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetArray: printer_is_shared[0]="1" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetArray: printer_state[0]="5" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetArray: admin_uri[0]="/admin/" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetArray: printer_uri_supported[0]="/printers/hp" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetArray: printer_name[0]="hp" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetArray: printer_location[0]="" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetArray: printer_info[0]="hp" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetArray: job_sheets_default[0]="none, none" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetArray: device_uri[0]="file:///dev/null" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetArray: color_supported[0]="0" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetArray: printer_make_and_model[0]="HP LaserJet Pro P1102w Foomatic/foo2zjs-z2 (recommended)" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetArray: media_default[0]="iso_a4_210x297mm" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetArray: sides_supported[0]="one-sided" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetArray: sides_default[0]="one-sided" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetArray: printer_commands[0]="AutoConfigure, Clean, PrintSelfTestPage" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetArray: server_is_sharing_printers[0]="0" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetVariable: TITLE="hp" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetVariable: SERVER_NAME="localhost" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetVariable: CUPS_VERSION="CUPS v1.7.1" D [10/Mar/2014:14:32:20 +0000] [Client 12] CGI data ready to be sent. D [10/Mar/2014:14:32:20 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, response=(nil)(), pipe_pid=24996, file=15 D [10/Mar/2014:14:32:20 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:20 +0000] Script header: Set-Cookie: org.cups.sid=7c56dcd8976dc6722d73440d833a7be1; path=/; D [10/Mar/2014:14:32:20 +0000] Script header: Content-Type: text/html;charset=utf-8 D [10/Mar/2014:14:32:20 +0000] Script header: D [10/Mar/2014:14:32:20 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24996, file=15 D [10/Mar/2014:14:32:20 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:20 +0000] [Client 12] CGI data ready to be sent. D [10/Mar/2014:14:32:20 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24996, file=15 D [10/Mar/2014:14:32:20 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:20 +0000] [CGI] Regular expression ".*Clean.*" D [10/Mar/2014:14:32:20 +0000] [CGI] matches[0].rm_so=0 D [10/Mar/2014:14:32:20 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24996, file=15 D [10/Mar/2014:14:32:20 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:20 +0000] [CGI] matches[1].rm_so=-1 D [10/Mar/2014:14:32:20 +0000] [CGI] Regular expression ".*PrintSelfTestPage.*" D [10/Mar/2014:14:32:20 +0000] [Client 12] CGI data ready to be sent. D [10/Mar/2014:14:32:20 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24996, file=15 D [10/Mar/2014:14:32:20 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:20 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24996, file=15 D [10/Mar/2014:14:32:20 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:20 +0000] [CGI] matches[0].rm_so=0 D [10/Mar/2014:14:32:20 +0000] [CGI] matches[1].rm_so=-1 D [10/Mar/2014:14:32:20 +0000] [Client 12] CGI data ready to be sent. D [10/Mar/2014:14:32:20 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24996, file=15 D [10/Mar/2014:14:32:20 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:20 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24996, file=15 D [10/Mar/2014:14:32:20 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:20 +0000] [Client 12] CGI data ready to be sent. D [10/Mar/2014:14:32:20 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24996, file=15 D [10/Mar/2014:14:32:20 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:20 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24996, file=15 D [10/Mar/2014:14:32:20 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:20 +0000] [Client 12] CGI data ready to be sent. D [10/Mar/2014:14:32:20 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24996, file=15 D [10/Mar/2014:14:32:20 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:20 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24996, file=15 D [10/Mar/2014:14:32:20 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:20 +0000] [Client 14] POST / HTTP/1.1 D [10/Mar/2014:14:32:20 +0000] cupsdSetBusyState: newbusy="Active clients", busy="Active clients" D [10/Mar/2014:14:32:20 +0000] [Client 14] No authentication data provided. D [10/Mar/2014:14:32:20 +0000] [Client 14] 2.0 Get-Jobs 3 D [10/Mar/2014:14:32:20 +0000] Get-Jobs ipp://localhost:631/printers/hp D [10/Mar/2014:14:32:20 +0000] [Client 14] Returning IPP successful-ok for Get-Jobs (ipp://localhost:631/printers/hp) from localhost D [10/Mar/2014:14:32:20 +0000] [Client 14] Content-Length: 75 D [10/Mar/2014:14:32:20 +0000] [Client 14] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=75, response=0x7fdd159a0170(IPP_IDLE), pipe_pid=0, file=-1 D [10/Mar/2014:14:32:20 +0000] [Client 14] Writing IPP response, ipp_state=DATA, old wused=0, new wused=0 D [10/Mar/2014:14:32:20 +0000] [Client 14] bytes=0, http_state=0, data_remaining=0 D [10/Mar/2014:14:32:20 +0000] [Client 14] Waiting for request. D [10/Mar/2014:14:32:20 +0000] cupsdSetBusyState: newbusy="Active clients", busy="Active clients" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiClearVariables called. D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetVariable: ORDER="asc" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetVariable: SECTION="printers" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetVariable: TOTAL="0" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetVariable: PRINTER_NAME="hp" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetVariable: PRINTER_URI_SUPPORTED="/printers/hp" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetVariable: THISURL="/printers/hp" D [10/Mar/2014:14:32:20 +0000] [CGI] cgiSetVariable: SEARCH_DEST="hp" D [10/Mar/2014:14:32:20 +0000] [Client 12] CGI data ready to be sent. D [10/Mar/2014:14:32:20 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24996, file=15 D [10/Mar/2014:14:32:20 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:20 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24996, file=15 D [10/Mar/2014:14:32:20 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:20 +0000] [Client 12] CGI data ready to be sent. D [10/Mar/2014:14:32:20 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24996, file=15 D [10/Mar/2014:14:32:20 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:20 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24996, file=15 D [10/Mar/2014:14:32:20 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:20 +0000] [Client 12] CGI data ready to be sent. D [10/Mar/2014:14:32:20 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24996, file=15 D [10/Mar/2014:14:32:20 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:20 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24996, file=15 D [10/Mar/2014:14:32:20 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:20 +0000] [Client 12] CGI data ready to be sent. D [10/Mar/2014:14:32:20 +0000] [Client 14] HTTP_STATE_WAITING Closing on EOF D [10/Mar/2014:14:32:20 +0000] [Client 14] Closing connection. D [10/Mar/2014:14:32:20 +0000] cupsdSetBusyState: newbusy="Active clients", busy="Active clients" D [10/Mar/2014:14:32:20 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24996, file=15 D [10/Mar/2014:14:32:20 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:20 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24996, file=15 D [10/Mar/2014:14:32:20 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:20 +0000] [Client 12] CGI data ready to be sent. D [10/Mar/2014:14:32:20 +0000] PID 24996 (/usr/lib/cups/cgi-bin/printers.cgi) exited with no errors. D [10/Mar/2014:14:32:20 +0000] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=24996, file=15 D [10/Mar/2014:14:32:20 +0000] [Client 12] Waiting for CGI data. D [10/Mar/2014:14:32:20 +0000] [Client 12] Waiting for request. D [10/Mar/2014:14:32:20 +0000] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [10/Mar/2014:14:32:48 +0000] [Client 13] HTTP_STATE_WAITING Closing on EOF D [10/Mar/2014:14:32:48 +0000] [Client 13] Closing connection. D [10/Mar/2014:14:32:48 +0000] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [10/Mar/2014:14:32:50 +0000] [Client 12] HTTP_STATE_WAITING Closing on EOF D [10/Mar/2014:14:32:50 +0000] [Client 12] Closing connection. D [10/Mar/2014:14:32:50 +0000] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"