CUPS: Printer crashes after a few prints

SidNex · 2013-03-26 21:27:21

Hi all,

I have a Canon MP600 printer/scanner connected via USB to a small print- and scan-server running Arch (last update was yesterday). The printer is shared over the network and can be accessed from a Windows 7 client. But from time to time after 1-2 prints the printer crashes. I that happens, only a power disconnect can bring it back. In addition, I have to delete the printer from the CUPS config and add it again. While this happens, CUPS shows the status "Sending data to printer". The printer is set as a raw printer. Same happens, when the printer is installed with the gutenprint driver and accessed from a Linux machine. "usblp" is blacklisted.

dmesg gives:

[  221.211652] usb 1-5: USB disconnect, device number 2
[  222.833497] usb 1-1: new high-speed USB device number 3 using ehci_hcd
[  222.961616] scsi3 : usb-storage 1-1:1.2
[  223.965090] scsi 3:0:0:0: Direct-Access     Canon    MP600Storage     0104 PQ: 0 ANSI: 2
[  223.969173] sd 3:0:0:0: [sdb] Attached SCSI removable disk
[  258.294210] usb 1-1: USB disconnect, device number 3
[  299.210036] usb 1-1: new high-speed USB device number 4 using ehci_hcd
[  299.339622] scsi4 : usb-storage 1-1:1.2
[  300.342038] scsi 4:0:0:0: Direct-Access     Canon    MP600Storage     0104 PQ: 0 ANSI: 2
[  300.349238] sd 4:0:0:0: [sdb] Attached SCSI removable disk
[  552.210232] usb 1-1: USB disconnect, device number 4
[ 1820.219867] usb 1-1: new high-speed USB device number 5 using ehci_hcd
[ 1820.356590] scsi5 : usb-storage 1-1:1.2
[ 1821.361801] scsi 5:0:0:0: Direct-Access     Canon    MP600Storage     0104 PQ: 0 ANSI: 2
[ 1821.368532] sd 5:0:0:0: [sdb] Attached SCSI removable disk
[ 2012.524423] usb 1-1: USB disconnect, device number 5
[ 2025.253317] usb 1-1: new high-speed USB device number 6 using ehci_hcd
[ 2025.381665] scsi6 : usb-storage 1-1:1.2
[ 2026.384912] scsi 6:0:0:0: Direct-Access     Canon    MP600Storage     0104 PQ: 0 ANSI: 2
[ 2026.388869] sd 6:0:0:0: [sdb] Attached SCSI removable disk
[ 2077.981402] usb 1-1: USB disconnect, device number 6
[ 2108.876643] usb 1-1: new high-speed USB device number 7 using ehci_hcd
[ 2109.005865] scsi7 : usb-storage 1-1:1.2
[ 2110.008467] scsi 7:0:0:0: Direct-Access     Canon    MP600Storage     0104 PQ: 0 ANSI: 2
[ 2110.014556] sd 7:0:0:0: [sdb] Attached SCSI removable disk

CUPS error.log:

...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:19 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:23 +0100] [Job 51] Wrote 8192 bytes of print data...
D [25/Mar/2013:22:52:23 +0100] [Job 51] Sending print file, 131072 bytes...
D [25/Mar/2013:22:52:23 +0100] [Job 51] Read 8192 bytes of print data...
D [25/Mar/2013:22:52:23 +0100] [Job 51] Wrote 8192 bytes of print data...
D [25/Mar/2013:22:52:23 +0100] [Job 51] Sending print file, 139264 bytes...
D [25/Mar/2013:22:52:23 +0100] [Job 51] Read 4818 bytes of print data...
D [25/Mar/2013:22:52:23 +0100] [Job 51] Wrote 4818 bytes of print data...
D [25/Mar/2013:22:52:23 +0100] [Job 51] Sending print file, 144082 bytes...
D [25/Mar/2013:22:52:23 +0100] [Job 51] Sent 144082 bytes...
D [25/Mar/2013:22:52:23 +0100] [Job 51] Waiting for read thread to exit...
D [25/Mar/2013:22:52:25 +0100] [Client 17] GET /admin HTTP/1.1
D [25/Mar/2013:22:52:25 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [25/Mar/2013:22:52:25 +0100] [Client 17] Authorized as root using Basic
D [25/Mar/2013:22:52:25 +0100] [CGI] argv[0] = "/usr/lib/cups/cgi-bin/admin.cgi"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[0] = "CUPS_CACHEDIR=/var/cache/cups"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[1] = "CUPS_DATADIR=/usr/share/cups"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[2] = "CUPS_DOCROOT=/usr/share/cups/doc"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[3] = "CUPS_FONTPATH=/usr/share/cups/fonts"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[4] = "CUPS_REQUESTROOT=/var/spool/cups"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[5] = "CUPS_SERVERBIN=/usr/lib/cups"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[6] = "CUPS_SERVERROOT=/etc/cups"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[7] = "CUPS_STATEDIR=/var/run/cups"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[8] = "HOME=/var/spool/cups/tmp"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[9] = "PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[10] = "SERVER_ADMIN=root@server"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[11] = "SOFTWARE=CUPS/1.6.2"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[12] = "TMPDIR=/var/spool/cups/tmp"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[13] = "USER=root"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[14] = "CUPS_MAX_MESSAGE=2047"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[15] = "CUPS_SERVER=/var/run/cups/cups.sock"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[16] = "CUPS_ENCRYPTION=IfRequested"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[17] = "IPP_PORT=631"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[18] = "AUTH_TYPE=Basic"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[19] = "LANG=de_DE.UTF8"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[20] = "REDIRECT_STATUS=1"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[21] = "GATEWAY_INTERFACE=CGI/1.1"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[22] = "SERVER_NAME=192.168.0.10"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[23] = "SERVER_PORT=631"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[24] = "REMOTE_ADDR=192.168.0.2"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[25] = "REMOTE_HOST=192.168.0.2"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[26] = "SCRIPT_NAME=/admin"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[27] = "SCRIPT_FILENAME=/usr/share/cups/doc/admin"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[28] = "REMOTE_USER=root"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[29] = "SERVER_PROTOCOL=HTTP/1.1"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[30] = "HTTP_COOKIE=org.cups.sid=46b3c74e188f3ce89daffca4078e5fc8"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[31] = "HTTP_USER_AGENT=Mozilla/5.0 (X11; Linux x86_64; rv:20.0) Gecko/20100101 Firefox/20.0 Iceweasel/20.0"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[32] = "HTTP_REFERER=https://192.168.0.10:631/printers/"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[33] = "REQUEST_METHOD=GET"
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[34] = "QUERY_STRING="
D [25/Mar/2013:22:52:25 +0100] [CGI] envp[35] = "HTTPS=ON"
D [25/Mar/2013:22:52:25 +0100] [CGI] Started /usr/lib/cups/cgi-bin/admin.cgi (PID 3272)
I [25/Mar/2013:22:52:25 +0100] [Client 17] Started "/usr/lib/cups/cgi-bin/admin.cgi" (pid=3272)
D [25/Mar/2013:22:52:25 +0100] [Client 17] file=20
D [25/Mar/2013:22:52:25 +0100] [CGI] admin.cgi started...
D [25/Mar/2013:22:52:25 +0100] [Client 21] Accepted from localhost (Domain)
D [25/Mar/2013:22:52:25 +0100] [CGI] http=0xb95549e0
D [25/Mar/2013:22:52:25 +0100] [CGI] cgiSetVariable: SECTION="admin"
D [25/Mar/2013:22:52:25 +0100] [CGI] cgiSetVariable: REFRESH_PAGE=""
D [25/Mar/2013:22:52:25 +0100] [CGI] org.cups.sid cookie is "46b3c74e188f3ce89daffca4078e5fc8"
D [25/Mar/2013:22:52:25 +0100] [CGI] No form data, showing main menu...
D [25/Mar/2013:22:52:25 +0100] [CGI] cgiSetVariable: DEBUG_LOGGING="CHECKED"
D [25/Mar/2013:22:52:25 +0100] [CGI] cgiSetVariable: REMOTE_ADMIN="CHECKED"
D [25/Mar/2013:22:52:25 +0100] [CGI] cgiSetVariable: SHARE_PRINTERS="CHECKED"
D [25/Mar/2013:22:52:25 +0100] [CGI] cgiSetVariable: USER_CANCEL_ANY="CHECKED"
D [25/Mar/2013:22:52:25 +0100] [CGI] cgiSetVariable: HAVE_GSSAPI="1"
D [25/Mar/2013:22:52:25 +0100] [CGI] cgiSetVariable: KERBEROS=""
D [25/Mar/2013:22:52:25 +0100] [CGI] cgiSetVariable: PRESERVE_JOBS="CHECKED"
D [25/Mar/2013:22:52:25 +0100] [CGI] cgiSetVariable: PRESERVE_JOB_HISTORY="Yes"
D [25/Mar/2013:22:52:25 +0100] [CGI] cgiSetVariable: PRESERVE_JOB_FILES="1d"
D [25/Mar/2013:22:52:25 +0100] [CGI] cgiSetVariable: MAX_CLIENTS="100"
D [25/Mar/2013:22:52:25 +0100] [CGI] cgiSetVariable: MAX_JOBS="500"
D [25/Mar/2013:22:52:25 +0100] [CGI] cgiSetVariable: MAX_LOG_SIZE="0"
D [25/Mar/2013:22:52:25 +0100] [CGI] /usr/share/cups/drivers/pscript5.dll: Datei oder Verzeichnis nicht gefunden
D [25/Mar/2013:22:52:25 +0100] [Client 21] POST / HTTP/1.1
D [25/Mar/2013:22:52:25 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [25/Mar/2013:22:52:25 +0100] [Client 21] No authentication data provided.
D [25/Mar/2013:22:52:25 +0100] [Client 21] 2.0 Get-Subscriptions 1
D [25/Mar/2013:22:52:25 +0100] Get-Subscriptions ipp://localhost/
D [25/Mar/2013:22:52:25 +0100] Get-Subscriptions client-error-not-found: No subscriptions found.
D [25/Mar/2013:22:52:25 +0100] Returning IPP client-error-not-found for Get-Subscriptions (ipp://localhost/) from localhost
D [25/Mar/2013:22:52:25 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [25/Mar/2013:22:52:25 +0100] [CGI] cgiSetVariable: SERVER_NAME="192.168.0.10"
D [25/Mar/2013:22:52:25 +0100] [CGI] cgiSetVariable: REMOTE_USER="root"
D [25/Mar/2013:22:52:25 +0100] [CGI] cgiSetVariable: CUPS_VERSION="CUPS v1.6.2"
D [25/Mar/2013:22:52:25 +0100] [CGI] cgiSetVariable: TITLE="Administration"
D [25/Mar/2013:22:52:25 +0100] [CGI] cgiSetVariable: SERVER_NAME="192.168.0.10"
D [25/Mar/2013:22:52:25 +0100] [CGI] cgiSetVariable: REMOTE_USER="root"
D [25/Mar/2013:22:52:25 +0100] [CGI] cgiSetVariable: CUPS_VERSION="CUPS v1.6.2"
D [25/Mar/2013:22:52:25 +0100] Script header: Content-Type: text/html;charset=utf-8
D [25/Mar/2013:22:52:25 +0100] Script header: 
D [25/Mar/2013:22:52:25 +0100] [Client 21] HTTP_WAITING Closing on EOF
D [25/Mar/2013:22:52:25 +0100] [Client 21] Closing connection.
D [25/Mar/2013:22:52:25 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [25/Mar/2013:22:52:25 +0100] PID 3272 (/usr/lib/cups/cgi-bin/admin.cgi) exited with no errors.
D [25/Mar/2013:22:52:25 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [25/Mar/2013:22:52:28 +0100] [Job 51] Read 271 bytes of back-channel data...
D [25/Mar/2013:22:52:28 +0100] [Job 51] PID 3269 (/usr/lib/cups/backend/usb) exited with no errors.
D [25/Mar/2013:22:52:28 +0100] [Job 51] time-at-completed=1364248348
D [25/Mar/2013:22:52:28 +0100] Discarding unused job-completed event...
I [25/Mar/2013:22:52:28 +0100] [Job 51] Job completed.
D [25/Mar/2013:22:52:28 +0100] cupsdMarkDirty(---J-)
D [25/Mar/2013:22:52:28 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [25/Mar/2013:22:52:28 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [25/Mar/2013:22:52:28 +0100] Discarding unused printer-state-changed event...
D [25/Mar/2013:22:52:28 +0100] cupsdMarkDirty(---J-)
D [25/Mar/2013:22:52:28 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [25/Mar/2013:22:52:29 +0100] [Job 51] Unloading...
D [25/Mar/2013:22:52:31 +0100] [Client 17] GET /admin/log/error_log HTTP/1.1
D [25/Mar/2013:22:52:31 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Printing jobs and dirty files"
D [25/Mar/2013:22:52:31 +0100] [Client 17] Authorized as root using Basic
I [25/Mar/2013:22:52:34 +0100] Saving printers.conf...
I [25/Mar/2013:22:52:34 +0100] Generating printcap /etc/printcap...
I [25/Mar/2013:22:52:34 +0100] Saving job.cache...
D [25/Mar/2013:22:52:34 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Active clients and dirty files"
D [25/Mar/2013:22:52:41 +0100] Report: clients=2
D [25/Mar/2013:22:52:41 +0100] Report: jobs=1
D [25/Mar/2013:22:52:41 +0100] Report: jobs-active=0
D [25/Mar/2013:22:52:41 +0100] Report: printers=1
D [25/Mar/2013:22:52:41 +0100] Report: stringpool-string-count=1224
D [25/Mar/2013:22:52:41 +0100] Report: stringpool-alloc-bytes=6184
D [25/Mar/2013:22:52:41 +0100] Report: stringpool-total-bytes=26384
D [25/Mar/2013:22:52:47 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [25/Mar/2013:22:53:17 +0100] [Client 18] HTTP_WAITING Closing on EOF
D [25/Mar/2013:22:53:17 +0100] [Client 18] Closing connection.
D [25/Mar/2013:22:53:17 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [25/Mar/2013:22:53:18 +0100] [Client 17] HTTP_WAITING Closing on EOF
D [25/Mar/2013:22:53:18 +0100] [Client 17] Closing connection.
D [25/Mar/2013:22:53:18 +0100] SSL shutdown successful!
D [25/Mar/2013:22:53:18 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [25/Mar/2013:22:53:18 +0100] [Client 17] HTTP_WAITING Closing on EOF
D [25/Mar/2013:22:53:18 +0100] [Client 17] Closing connection.
D [25/Mar/2013:22:53:18 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [25/Mar/2013:22:54:57 +0100] [Client 17] Accepted from 192.168.0.2:631 (IPv4)
D [25/Mar/2013:22:54:57 +0100] Report: clients=1
D [25/Mar/2013:22:54:57 +0100] Report: jobs=1
D [25/Mar/2013:22:54:57 +0100] Report: jobs-active=0
D [25/Mar/2013:22:54:57 +0100] Report: printers=1
D [25/Mar/2013:22:54:57 +0100] Report: stringpool-string-count=1224
D [25/Mar/2013:22:54:57 +0100] Report: stringpool-alloc-bytes=6184
D [25/Mar/2013:22:54:57 +0100] Report: stringpool-total-bytes=26384
D [25/Mar/2013:22:54:57 +0100] [Client 17] POST / HTTP/1.1
D [25/Mar/2013:22:54:57 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [25/Mar/2013:22:54:57 +0100] [Client 17] No authentication data provided.
D [25/Mar/2013:22:54:57 +0100] cupsdNetIFUpdate: "lo" = localhost:631
D [25/Mar/2013:22:54:57 +0100] cupsdNetIFUpdate: "enp2s10" = 192.168.0.10:631
D [25/Mar/2013:22:54:57 +0100] cupsdNetIFUpdate: "lo" = localhost:631
D [25/Mar/2013:22:54:57 +0100] cupsdNetIFUpdate: "enp2s10" = [v1.fe80::203:dff:fe18:ec05+enp2s10]:631
D [25/Mar/2013:22:54:57 +0100] [Client 17] 1.1 CUPS-Get-Printers 1
D [25/Mar/2013:22:54:57 +0100] CUPS-Get-Printers
D [25/Mar/2013:22:54:57 +0100] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from 192.168.0.2
D [25/Mar/2013:22:54:57 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [25/Mar/2013:22:54:57 +0100] [Client 17] POST / HTTP/1.1
D [25/Mar/2013:22:54:57 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [25/Mar/2013:22:54:57 +0100] [Client 17] No authentication data provided.
D [25/Mar/2013:22:54:57 +0100] [Client 17] 1.1 CUPS-Get-Classes 1
D [25/Mar/2013:22:54:57 +0100] CUPS-Get-Classes
D [25/Mar/2013:22:54:57 +0100] Returning IPP successful-ok for CUPS-Get-Classes (no URI) from 192.168.0.2
D [25/Mar/2013:22:54:57 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [25/Mar/2013:22:54:57 +0100] [Client 17] HTTP_WAITING Closing on EOF
D [25/Mar/2013:22:54:57 +0100] [Client 17] Closing connection.
D [25/Mar/2013:22:54:57 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [25/Mar/2013:23:07:58 +0100] [Client 17] Accepted from 192.168.0.2:631 (IPv4)
D [25/Mar/2013:23:07:58 +0100] Report: clients=1
D [25/Mar/2013:23:07:58 +0100] Report: jobs=1
D [25/Mar/2013:23:07:58 +0100] Report: jobs-active=0
D [25/Mar/2013:23:07:58 +0100] Report: printers=1
D [25/Mar/2013:23:07:58 +0100] Report: stringpool-string-count=1263
D [25/Mar/2013:23:07:58 +0100] Report: stringpool-alloc-bytes=6184
D [25/Mar/2013:23:07:58 +0100] Report: stringpool-total-bytes=27288
D [25/Mar/2013:23:07:58 +0100] [Client 17] POST / HTTP/1.1
D [25/Mar/2013:23:07:58 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [25/Mar/2013:23:07:58 +0100] [Client 17] No authentication data provided.
D [25/Mar/2013:23:07:58 +0100] cupsdNetIFUpdate: "lo" = localhost:631
D [25/Mar/2013:23:07:58 +0100] cupsdNetIFUpdate: "enp2s10" = 192.168.0.10:631
D [25/Mar/2013:23:07:58 +0100] cupsdNetIFUpdate: "lo" = localhost:631
D [25/Mar/2013:23:07:58 +0100] cupsdNetIFUpdate: "enp2s10" = [v1.fe80::203:dff:fe18:ec05+enp2s10]:631
D [25/Mar/2013:23:07:58 +0100] [Client 17] 1.1 CUPS-Get-Printers 1
D [25/Mar/2013:23:07:58 +0100] CUPS-Get-Printers
D [25/Mar/2013:23:07:58 +0100] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from 192.168.0.2
D [25/Mar/2013:23:07:58 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [25/Mar/2013:23:07:58 +0100] [Client 17] POST / HTTP/1.1
D [25/Mar/2013:23:07:58 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [25/Mar/2013:23:07:58 +0100] [Client 17] No authentication data provided.
D [25/Mar/2013:23:07:58 +0100] [Client 17] 1.1 CUPS-Get-Classes 1
D [25/Mar/2013:23:07:58 +0100] CUPS-Get-Classes
D [25/Mar/2013:23:07:58 +0100] Returning IPP successful-ok for CUPS-Get-Classes (no URI) from 192.168.0.2
D [25/Mar/2013:23:07:58 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [25/Mar/2013:23:07:58 +0100] [Client 17] HTTP_WAITING Closing on EOF
D [25/Mar/2013:23:07:58 +0100] [Client 17] Closing connection.
D [25/Mar/2013:23:07:58 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"

I am a little bit confused by "Read ... bytes of back channel data ...". These lines appears hundreds of times in the error.log.

access.log

192.168.0.102 - - [25/Mar/2013:21:49:02 +0100] "POST /printers/Canon_MP600_Windows HTTP/1.1" 200 145651 Print-Job successful-ok
192.168.0.102 - - [25/Mar/2013:21:49:10 +0100] "POST /printers/Canon_MP600_Windows HTTP/1.1" 200 140374 Print-Job successful-ok
192.168.0.102 - - [25/Mar/2013:21:49:19 +0100] "POST /printers/Canon_MP600_Windows HTTP/1.1" 200 142503 Print-Job successful-ok
192.168.0.102 - - [25/Mar/2013:21:49:53 +0100] "POST /printers/Canon_MP600_Windows HTTP/1.1" 200 142503 Print-Job successful-ok
192.168.0.102 - - [25/Mar/2013:21:50:44 +0100] "POST /printers/Canon_MP600_Windows HTTP/1.1" 200 142503 Print-Job successful-ok
localhost - - [25/Mar/2013:21:52:28 +0100] "POST /jobs HTTP/1.1" 200 140 Cancel-Job successful-ok
192.168.0.102 - - [25/Mar/2013:21:54:39 +0100] "POST /printers/Canon_MP600_Windows HTTP/1.1" 200 142503 Print-Job successful-ok
localhost - - [25/Mar/2013:21:55:18 +0100] "POST /jobs HTTP/1.1" 200 140 Cancel-Job client-error-not-possible
localhost - - [25/Mar/2013:21:56:36 +0100] "POST /jobs HTTP/1.1" 200 140 Cancel-Job successful-ok
localhost - - [25/Mar/2013:21:56:39 +0100] "POST /jobs HTTP/1.1" 200 140 Cancel-Job successful-ok
localhost - - [25/Mar/2013:21:56:42 +0100] "POST /jobs HTTP/1.1" 200 140 Cancel-Job successful-ok
192.168.0.102 - - [25/Mar/2013:21:57:39 +0100] "POST /printers/Canon_MP600_Windows HTTP/1.1" 200 142503 Print-Job successful-ok
localhost - - [25/Mar/2013:21:58:43 +0100] "POST /jobs HTTP/1.1" 200 140 Cancel-Job successful-ok
192.168.0.2 - - [25/Mar/2013:22:00:09 +0100] "POST /admin/ HTTP/1.1" 200 94 - -
192.168.0.2 - - [25/Mar/2013:22:00:09 +0100] "POST /admin/ HTTP/1.1" 200 2273 - -
192.168.0.2 - - [25/Mar/2013:22:00:11 +0100] "POST /admin/ HTTP/1.1" 200 117 - -
localhost - - [25/Mar/2013:22:00:11 +0100] "POST /admin/ HTTP/1.1" 401 133 CUPS-Delete-Printer successful-ok
192.168.0.2 - - [25/Mar/2013:22:00:11 +0100] "POST /admin/ HTTP/1.1" 426 117 - -
192.168.0.2 - - [25/Mar/2013:22:00:11 +0100] "POST /admin/ HTTP/1.1" 200 117 - -
192.168.0.2 - - [25/Mar/2013:22:00:38 +0100] "POST /admin/ HTTP/1.1" 200 94 - -
192.168.0.2 - - [25/Mar/2013:22:00:38 +0100] "POST /admin/ HTTP/1.1" 200 2273 - -
192.168.0.2 - - [25/Mar/2013:22:00:40 +0100] "POST /admin/ HTTP/1.1" 200 117 - -
localhost - - [25/Mar/2013:22:00:40 +0100] "POST /admin/ HTTP/1.1" 401 133 CUPS-Delete-Printer successful-ok
192.168.0.2 - - [25/Mar/2013:22:00:40 +0100] "POST /admin/ HTTP/1.1" 401 117 - -
192.168.0.2 - - [25/Mar/2013:22:00:40 +0100] "POST /admin/ HTTP/1.1" 200 117 - -
192.168.0.2 - root [25/Mar/2013:22:00:51 +0100] "POST /admin/ HTTP/1.1" 200 117 - -
localhost - - [25/Mar/2013:22:00:51 +0100] "POST /admin/ HTTP/1.1" 401 133 CUPS-Delete-Printer successful-ok
localhost - root [25/Mar/2013:22:00:51 +0100] "POST /admin/ HTTP/1.1" 200 133 CUPS-Delete-Printer successful-ok
192.168.0.2 - root [25/Mar/2013:22:00:51 +0100] "POST /admin/ HTTP/1.1" 200 2025 - -
localhost - - [25/Mar/2013:22:01:02 +0100] "POST /jobs HTTP/1.1" 200 140 Cancel-Job successful-ok
192.168.0.102 - - [25/Mar/2013:22:01:40 +0100] "POST /printers/Canon_MP600_Windows HTTP/1.1" 200 142503 Print-Job successful-ok
192.168.0.102 - - [25/Mar/2013:22:02:44 +0100] "POST /printers/Canon_MP600_Windows HTTP/1.1" 200 142503 Print-Job successful-ok
localhost - - [25/Mar/2013:22:03:03 +0100] "POST /jobs HTTP/1.1" 200 140 Cancel-Job successful-ok
localhost - - [25/Mar/2013:22:03:40 +0100] "POST /jobs HTTP/1.1" 200 140 Cancel-Job successful-ok
192.168.0.2 - root [25/Mar/2013:22:04:36 +0100] "POST /admin/ HTTP/1.1" 200 96 - -
192.168.0.2 - root [25/Mar/2013:22:04:36 +0100] "POST /admin/ HTTP/1.1" 200 2281 - -
192.168.0.2 - root [25/Mar/2013:22:04:37 +0100] "POST /admin/ HTTP/1.1" 200 119 - -
localhost - - [25/Mar/2013:22:04:37 +0100] "POST /admin/ HTTP/1.1" 401 135 CUPS-Delete-Printer successful-ok
localhost - root [25/Mar/2013:22:04:37 +0100] "POST /admin/ HTTP/1.1" 200 135 CUPS-Delete-Printer successful-ok
192.168.0.2 - root [25/Mar/2013:22:04:37 +0100] "POST /admin/ HTTP/1.1" 200 2031 - -
192.168.0.2 - root [25/Mar/2013:22:04:51 +0100] "POST /admin/ HTTP/1.1" 200 60 - -
localhost - - [25/Mar/2013:22:04:51 +0100] "POST / HTTP/1.1" 401 91 CUPS-Get-Devices successful-ok
localhost - root [25/Mar/2013:22:04:51 +0100] "POST / HTTP/1.1" 200 1410 CUPS-Get-Devices -
192.168.0.2 - root [25/Mar/2013:22:04:51 +0100] "POST /admin/ HTTP/1.1" 200 2945 - -
192.168.0.2 - - [25/Mar/2013:22:04:56 +0100] "POST /admin HTTP/1.1" 200 145 - -
192.168.0.2 - - [25/Mar/2013:22:04:56 +0100] "POST /admin HTTP/1.1" 200 3415 - -
192.168.0.2 - - [25/Mar/2013:22:05:05 +0100] "POST /admin HTTP/1.1" 200 312 - -
localhost - - [25/Mar/2013:22:05:05 +0100] "POST / HTTP/1.1" 200 148355 CUPS-Get-PPDs -
192.168.0.2 - - [25/Mar/2013:22:05:05 +0100] "POST /admin HTTP/1.1" 200 55450 - -
192.168.0.2 - - [25/Mar/2013:22:05:11 +0100] "POST /admin HTTP/1.1" 200 2156 - -
localhost - - [25/Mar/2013:22:05:11 +0100] "POST / HTTP/1.1" 200 1087 CUPS-Get-PPDs -
192.168.0.2 - - [25/Mar/2013:22:05:11 +0100] "POST /admin HTTP/1.1" 200 6794 - -
192.168.0.2 - - [25/Mar/2013:22:05:17 +0100] "POST /admin HTTP/1.1" 200 1964 - -
localhost - - [25/Mar/2013:22:05:17 +0100] "POST / HTTP/1.1" 200 396 CUPS-Get-PPDs -
192.168.0.2 - - [25/Mar/2013:22:05:17 +0100] "POST /admin HTTP/1.1" 200 5389 - -
192.168.0.2 - - [25/Mar/2013:22:05:20 +0100] "POST /admin HTTP/1.1" 200 1996 - -
localhost - - [25/Mar/2013:22:05:20 +0100] "POST /admin/ HTTP/1.1" 401 335 CUPS-Add-Modify-Printer successful-ok
192.168.0.2 - - [25/Mar/2013:22:05:20 +0100] "POST /admin HTTP/1.1" 401 1996 - -
192.168.0.2 - - [25/Mar/2013:22:05:20 +0100] "POST /admin HTTP/1.1" 200 1996 - -
192.168.0.2 - root [25/Mar/2013:22:05:20 +0100] "POST /admin HTTP/1.1" 200 1996 - -
localhost - - [25/Mar/2013:22:05:20 +0100] "POST /admin/ HTTP/1.1" 401 335 CUPS-Add-Modify-Printer successful-ok
localhost - root [25/Mar/2013:22:05:20 +0100] "POST /admin/ HTTP/1.1" 200 335 CUPS-Add-Modify-Printer successful-ok
192.168.0.2 - root [25/Mar/2013:22:05:20 +0100] "POST /admin HTTP/1.1" 200 7012 - -
192.168.0.2 - root [25/Mar/2013:22:05:23 +0100] "POST /admin HTTP/1.1" 200 203 - -
localhost - - [25/Mar/2013:22:05:23 +0100] "POST /admin/ HTTP/1.1" 401 238 CUPS-Add-Modify-Printer successful-ok
localhost - root [25/Mar/2013:22:05:23 +0100] "POST /admin/ HTTP/1.1" 200 238 CUPS-Add-Modify-Printer successful-ok
192.168.0.2 - root [25/Mar/2013:22:05:23 +0100] "POST /admin HTTP/1.1" 200 2211 - -
192.168.0.102 - - [25/Mar/2013:22:07:20 +0100] "POST /printers/Canon_MP600_Windows HTTP/1.1" 200 142503 Print-Job successful-ok
192.168.0.102 - - [25/Mar/2013:22:29:48 +0100] "POST /printers/Canon_MP600_Windows HTTP/1.1" 200 139170 Print-Job successful-ok
192.168.0.102 - - [25/Mar/2013:22:30:57 +0100] "POST /printers/Canon_MP600_Windows HTTP/1.1" 200 139170 Print-Job successful-ok
localhost - - [25/Mar/2013:22:31:37 +0100] "POST /jobs HTTP/1.1" 200 140 Cancel-Job successful-ok
localhost - - [25/Mar/2013:22:35:37 +0100] "POST /jobs HTTP/1.1" 200 140 Cancel-Job successful-ok
localhost - - [25/Mar/2013:22:36:32 +0100] "POST / HTTP/1.1" 401 75 CUPS-Get-Devices successful-ok
localhost - root [25/Mar/2013:22:36:32 +0100] "POST / HTTP/1.1" 200 1394 CUPS-Get-Devices -
192.168.0.102 - - [25/Mar/2013:22:36:37 +0100] "POST /printers/Canon_MP600_Windows HTTP/1.1" 200 144360 Print-Job successful-ok
192.168.0.2 - - [25/Mar/2013:22:37:02 +0100] "POST /admin/ HTTP/1.1" 200 96 - -
192.168.0.2 - - [25/Mar/2013:22:37:02 +0100] "POST /admin/ HTTP/1.1" 200 2273 - -
192.168.0.2 - - [25/Mar/2013:22:37:03 +0100] "POST /admin/ HTTP/1.1" 200 119 - -
localhost - - [25/Mar/2013:22:37:03 +0100] "POST /admin/ HTTP/1.1" 401 135 CUPS-Delete-Printer successful-ok
192.168.0.2 - - [25/Mar/2013:22:37:03 +0100] "POST /admin/ HTTP/1.1" 426 119 - -
192.168.0.2 - - [25/Mar/2013:22:37:03 +0100] "POST /admin/ HTTP/1.1" 200 119 - -
192.168.0.2 - root [25/Mar/2013:22:37:24 +0100] "POST /admin/ HTTP/1.1" 200 96 - -
192.168.0.2 - root [25/Mar/2013:22:37:24 +0100] "POST /admin/ HTTP/1.1" 200 2273 - -
192.168.0.2 - root [25/Mar/2013:22:37:25 +0100] "POST /admin/ HTTP/1.1" 200 119 - -
localhost - - [25/Mar/2013:22:37:26 +0100] "POST /admin/ HTTP/1.1" 401 135 CUPS-Delete-Printer successful-ok
localhost - root [25/Mar/2013:22:37:26 +0100] "POST /admin/ HTTP/1.1" 200 135 CUPS-Delete-Printer successful-ok
192.168.0.2 - root [25/Mar/2013:22:37:25 +0100] "POST /admin/ HTTP/1.1" 200 2023 - -
192.168.0.2 - root [25/Mar/2013:22:37:33 +0100] "POST /admin/ HTTP/1.1" 200 60 - -
localhost - - [25/Mar/2013:22:37:33 +0100] "POST / HTTP/1.1" 401 91 CUPS-Get-Devices successful-ok
localhost - root [25/Mar/2013:22:37:33 +0100] "POST / HTTP/1.1" 200 1410 CUPS-Get-Devices -
192.168.0.2 - root [25/Mar/2013:22:37:33 +0100] "POST /admin/ HTTP/1.1" 200 2937 - -
192.168.0.2 - root [25/Mar/2013:22:37:37 +0100] "POST /admin HTTP/1.1" 200 145 - -
192.168.0.2 - root [25/Mar/2013:22:37:37 +0100] "POST /admin HTTP/1.1" 200 3407 - -
192.168.0.2 - root [25/Mar/2013:22:37:43 +0100] "POST /admin HTTP/1.1" 200 312 - -
localhost - - [25/Mar/2013:22:37:43 +0100] "POST / HTTP/1.1" 200 148355 CUPS-Get-PPDs -
192.168.0.2 - root [25/Mar/2013:22:37:43 +0100] "POST /admin HTTP/1.1" 200 55442 - -
192.168.0.2 - root [25/Mar/2013:22:37:47 +0100] "POST /admin HTTP/1.1" 200 2139 - -
localhost - - [25/Mar/2013:22:37:47 +0100] "POST / HTTP/1.1" 200 1087 CUPS-Get-PPDs -
192.168.0.2 - root [25/Mar/2013:22:37:47 +0100] "POST /admin HTTP/1.1" 200 6769 - -
192.168.0.2 - root [25/Mar/2013:22:37:54 +0100] "POST /admin HTTP/1.1" 200 1980 - -
localhost - - [25/Mar/2013:22:37:54 +0100] "POST / HTTP/1.1" 200 396 CUPS-Get-PPDs -
192.168.0.2 - root [25/Mar/2013:22:37:54 +0100] "POST /admin HTTP/1.1" 200 5397 - -
192.168.0.2 - root [25/Mar/2013:22:37:56 +0100] "POST /admin HTTP/1.1" 200 1964 - -
localhost - - [25/Mar/2013:22:37:56 +0100] "POST /admin/ HTTP/1.1" 401 335 CUPS-Add-Modify-Printer successful-ok
localhost - root [25/Mar/2013:22:37:56 +0100] "POST /admin/ HTTP/1.1" 200 335 CUPS-Add-Modify-Printer successful-ok
192.168.0.2 - root [25/Mar/2013:22:37:56 +0100] "POST /admin HTTP/1.1" 200 6972 - -
192.168.0.2 - root [25/Mar/2013:22:37:58 +0100] "POST /admin HTTP/1.1" 200 203 - -
localhost - - [25/Mar/2013:22:37:58 +0100] "POST /admin/ HTTP/1.1" 401 238 CUPS-Add-Modify-Printer successful-ok
localhost - root [25/Mar/2013:22:37:58 +0100] "POST /admin/ HTTP/1.1" 200 238 CUPS-Add-Modify-Printer successful-ok
192.168.0.2 - root [25/Mar/2013:22:37:58 +0100] "POST /admin HTTP/1.1" 200 2203 - -
192.168.0.102 - - [25/Mar/2013:22:38:11 +0100] "POST /printers/Canon_MP600_Windows HTTP/1.1" 200 139170 Print-Job successful-ok
192.168.0.102 - - [25/Mar/2013:22:49:36 +0100] "POST /printers/Canon_MP600_Windows HTTP/1.1" 200 144348 Print-Job successful-ok
localhost - - [25/Mar/2013:22:50:37 +0100] "POST /jobs HTTP/1.1" 200 139 Cancel-Job successful-ok
192.168.0.2 - root [25/Mar/2013:22:50:44 +0100] "POST /admin/ HTTP/1.1" 200 96 - -
192.168.0.2 - root [25/Mar/2013:22:50:44 +0100] "POST /admin/ HTTP/1.1" 200 2273 - -
192.168.0.2 - root [25/Mar/2013:22:50:46 +0100] "POST /admin/ HTTP/1.1" 200 119 - -
localhost - - [25/Mar/2013:22:50:46 +0100] "POST /admin/ HTTP/1.1" 401 135 CUPS-Delete-Printer successful-ok
localhost - root [25/Mar/2013:22:50:46 +0100] "POST /admin/ HTTP/1.1" 200 135 CUPS-Delete-Printer successful-ok
192.168.0.2 - root [25/Mar/2013:22:50:46 +0100] "POST /admin/ HTTP/1.1" 200 2023 - -
192.168.0.2 - root [25/Mar/2013:22:50:50 +0100] "POST /admin/ HTTP/1.1" 200 60 - -
localhost - - [25/Mar/2013:22:50:50 +0100] "POST / HTTP/1.1" 401 91 CUPS-Get-Devices successful-ok
localhost - root [25/Mar/2013:22:50:50 +0100] "POST / HTTP/1.1" 200 1106 CUPS-Get-Devices -
192.168.0.2 - root [25/Mar/2013:22:50:50 +0100] "POST /admin/ HTTP/1.1" 200 2800 - -
192.168.0.2 - root [25/Mar/2013:22:51:41 +0100] "POST /admin/ HTTP/1.1" 200 60 - -
localhost - - [25/Mar/2013:22:51:41 +0100] "POST / HTTP/1.1" 401 91 CUPS-Get-Devices successful-ok
localhost - root [25/Mar/2013:22:51:41 +0100] "POST / HTTP/1.1" 200 1410 CUPS-Get-Devices -
192.168.0.2 - root [25/Mar/2013:22:51:41 +0100] "POST /admin/ HTTP/1.1" 200 2937 - -
192.168.0.2 - root [25/Mar/2013:22:51:46 +0100] "POST /admin HTTP/1.1" 200 145 - -
192.168.0.2 - root [25/Mar/2013:22:51:46 +0100] "POST /admin HTTP/1.1" 200 3407 - -
192.168.0.2 - root [25/Mar/2013:22:51:51 +0100] "POST /admin HTTP/1.1" 200 312 - -
localhost - - [25/Mar/2013:22:51:51 +0100] "POST / HTTP/1.1" 200 148355 CUPS-Get-PPDs -
192.168.0.2 - root [25/Mar/2013:22:51:51 +0100] "POST /admin HTTP/1.1" 200 55442 - -
192.168.0.2 - root [25/Mar/2013:22:51:54 +0100] "POST /admin HTTP/1.1" 200 2173 - -
localhost - - [25/Mar/2013:22:51:54 +0100] "POST / HTTP/1.1" 200 1087 CUPS-Get-PPDs -
192.168.0.2 - root [25/Mar/2013:22:51:54 +0100] "POST /admin HTTP/1.1" 200 6803 - -
192.168.0.2 - root [25/Mar/2013:22:52:02 +0100] "POST /admin HTTP/1.1" 200 1964 - -
localhost - - [25/Mar/2013:22:52:02 +0100] "POST / HTTP/1.1" 200 396 CUPS-Get-PPDs -
192.168.0.2 - root [25/Mar/2013:22:52:02 +0100] "POST /admin HTTP/1.1" 200 5381 - -
192.168.0.2 - root [25/Mar/2013:22:52:04 +0100] "POST /admin HTTP/1.1" 200 1964 - -
localhost - - [25/Mar/2013:22:52:04 +0100] "POST /admin/ HTTP/1.1" 401 335 CUPS-Add-Modify-Printer successful-ok
localhost - root [25/Mar/2013:22:52:04 +0100] "POST /admin/ HTTP/1.1" 200 335 CUPS-Add-Modify-Printer successful-ok
192.168.0.2 - root [25/Mar/2013:22:52:04 +0100] "POST /admin HTTP/1.1" 200 6972 - -
192.168.0.2 - root [25/Mar/2013:22:52:06 +0100] "POST /admin HTTP/1.1" 200 203 - -
localhost - - [25/Mar/2013:22:52:06 +0100] "POST /admin/ HTTP/1.1" 401 238 CUPS-Add-Modify-Printer successful-ok
localhost - root [25/Mar/2013:22:52:06 +0100] "POST /admin/ HTTP/1.1" 200 238 CUPS-Add-Modify-Printer successful-ok
192.168.0.2 - root [25/Mar/2013:22:52:06 +0100] "POST /admin HTTP/1.1" 200 2203 - -
192.168.0.102 - - [25/Mar/2013:22:52:17 +0100] "POST /printers/Canon_MP600_Windows HTTP/1.1" 200 144348 Print-Job successful-ok
192.168.0.2 - root [25/Mar/2013:22:52:31 +0100] "GET /admin/log/error_log HTTP/1.1" 200 41751296 - -

I do not have any idea what to do here. A Google search did not help. Every hint is appreciated Thanks in advance!

I posted the problem also in the German Archlinux forum.

Best regards

Arch Linux

#1 2013-03-26 21:27:21

CUPS: Printer crashes after a few prints

Board footer