# USB printer always busy, doesn't process queue [SOLVED]

## Silenzium

Hey,

I'm using a Canon PIXMA IP4000 printer with CUPS and Turboprint. This combination has been working for quite a long time, but some weeks ago it stopped working and I don't know why. I'm updating pretty often and so I did not notice when an update broke my config.

The symptoms are as follows: I want to print something and everything looks fine in CUPS and the GUI of Turboprint, but the file remains in the waitingline and nothing happens. The CUPS interface says "USB port busy; will retry in 30 seconds..."

I have already played around with different versions of udev (094, 098, 100-r2) and CUPS (1.1.23-r8, 1.2.2, 1.2.4), but nothing has changed until then. I tried to stop ivman and executed revdep-rebuild, but nothing helped. With udev-100-r2 "Finalizing udev configuration ..." fails.

The hardware is ok, printing with a different OS works.

Maybe wrong permissions, a udev problem or sth totally different? I don't know. Please help.

Here's the output of /var/log/cups/error_log, when I use the Testpage-function in the Turboprint GUI:

```
D [28/Sep/2006:17:05:16 +0200] AcceptClient: 6 from localhost:631.

D [28/Sep/2006:17:05:16 +0200] ReadClient: 6 GET /printers/Canon_PIXMA_iP4000 HTTP/1.1

D [28/Sep/2006:17:05:16 +0200] CGI /usr/lib/cups/cgi-bin/printers.cgi started - PID = 23964

I [28/Sep/2006:17:05:16 +0200] Started "/usr/lib/cups/cgi-bin/printers.cgi" (pid=23964)

D [28/Sep/2006:17:05:16 +0200] SendCommand: 6 file=9

D [28/Sep/2006:17:05:16 +0200] AcceptClient: 8 from localhost:631.

D [28/Sep/2006:17:05:16 +0200] ReadClient: 8 POST / HTTP/1.1

D [28/Sep/2006:17:05:16 +0200] ProcessIPPRequest: 8 status_code=1

D [28/Sep/2006:17:05:16 +0200] ReadClient: 8 POST / HTTP/1.1

D [28/Sep/2006:17:05:16 +0200] ProcessIPPRequest: 8 status_code=1

D [28/Sep/2006:17:05:16 +0200] ReadClient: 8 POST / HTTP/1.1

D [28/Sep/2006:17:05:16 +0200] ProcessIPPRequest: 8 status_code=1

D [28/Sep/2006:17:05:16 +0200] CloseClient: 8

D [28/Sep/2006:17:05:33 +0200] AcceptClient: 8 from localhost:631.

D [28/Sep/2006:17:05:33 +0200] CloseClient: 8

D [28/Sep/2006:17:05:33 +0200] AcceptClient: 8 from localhost:631.

D [28/Sep/2006:17:05:33 +0200] ReadClient: 8 POST / HTTP/1.1

D [28/Sep/2006:17:05:33 +0200] ProcessIPPRequest: 8 status_code=1

D [28/Sep/2006:17:05:33 +0200] ReadClient: 8 POST /printers/ HTTP/1.1

D [28/Sep/2006:17:05:33 +0200] ProcessIPPRequest: 8 status_code=1

D [28/Sep/2006:17:05:34 +0200] AcceptClient: 9 from localhost:631.

D [28/Sep/2006:17:05:34 +0200] CloseClient: 8

D [28/Sep/2006:17:05:34 +0200] ReadClient: 9 POST /admin/ HTTP/1.1

D [28/Sep/2006:17:05:34 +0200] SendError: 9 code=401 (Unauthorized)

D [28/Sep/2006:17:05:34 +0200] CloseClient: 9

D [28/Sep/2006:17:05:34 +0200] AcceptClient: 8 from localhost:631.

D [28/Sep/2006:17:05:34 +0200] ReadClient: 8 POST /admin/ HTTP/1.1

D [28/Sep/2006:17:05:34 +0200] ProcessIPPRequest: 8 status_code=0

D [28/Sep/2006:17:05:34 +0200] CloseClient: 8

D [28/Sep/2006:17:05:43 +0200] AcceptClient: 8 from localhost:631.

D [28/Sep/2006:17:05:43 +0200] ReadClient: 8 POST / HTTP/1.1

D [28/Sep/2006:17:05:43 +0200] ProcessIPPRequest: 8 status_code=1

D [28/Sep/2006:17:05:43 +0200] ReadClient: 8 POST / HTTP/1.1

D [28/Sep/2006:17:05:43 +0200] ProcessIPPRequest: 8 status_code=1

D [28/Sep/2006:17:05:43 +0200] ReadClient: 8 POST / HTTP/1.1

D [28/Sep/2006:17:05:43 +0200] ProcessIPPRequest: 8 status_code=0

D [28/Sep/2006:17:05:43 +0200] AcceptClient: 9 from localhost:631.

D [28/Sep/2006:17:05:43 +0200] CloseClient: 8

D [28/Sep/2006:17:05:43 +0200] ReadClient: 9 POST /printers/Canon_PIXMA_iP4000 HTTP/1.1

D [28/Sep/2006:17:05:43 +0200] print_job: auto-typing file...

D [28/Sep/2006:17:05:43 +0200] print_job: request file type is application/postscript.

D [28/Sep/2006:17:05:43 +0200] check_quotas: requesting-user-name = 'root'

D [28/Sep/2006:17:05:43 +0200] print_job: requesting-user-name = 'root'

I [28/Sep/2006:17:05:43 +0200] Adding start banner page "none" to job 5.

I [28/Sep/2006:17:05:43 +0200] Adding end banner page "none" to job 5.

I [28/Sep/2006:17:05:43 +0200] Job 5 queued on 'Canon_PIXMA_iP4000' by 'root'.

D [28/Sep/2006:17:05:43 +0200] Job 5 hold_until = 0

D [28/Sep/2006:17:05:43 +0200] StartJob(5, 0x80d5900)

D [28/Sep/2006:17:05:43 +0200] StartJob() id = 5, file = 0/1

D [28/Sep/2006:17:05:43 +0200] job-sheets=none,none

D [28/Sep/2006:17:05:43 +0200] banner_page = 0

D [28/Sep/2006:17:05:43 +0200] StartJob: argv = "Canon_PIXMA_iP4000","5","root","tp23977_0.tmp","1","cpi=10 lpi=6 turboprint=bt1x0u0","/var/spool/cups/d00005-001"

D [28/Sep/2006:17:05:43 +0200] StartJob: envp[0]="PATH=/usr/lib/cups/filter:/bin:/usr/bin"

D [28/Sep/2006:17:05:43 +0200] StartJob: envp[1]="SOFTWARE=CUPS/1.1"

D [28/Sep/2006:17:05:43 +0200] StartJob: envp[2]="USER=root"

D [28/Sep/2006:17:05:43 +0200] StartJob: envp[3]="CHARSET=iso-8859-15"

D [28/Sep/2006:17:05:43 +0200] StartJob: envp[4]="LANG=de"

D [28/Sep/2006:17:05:43 +0200] StartJob: envp[5]="PPD=/etc/cups/ppd/Canon_PIXMA_iP4000.ppd"

D [28/Sep/2006:17:05:43 +0200] StartJob: envp[6]="CUPS_SERVERROOT=/etc/cups"

D [28/Sep/2006:17:05:43 +0200] StartJob: envp[7]="RIP_MAX_CACHE=8m"

D [28/Sep/2006:17:05:43 +0200] StartJob: envp[8]="TMPDIR=/var/spool/cups/tmp"

D [28/Sep/2006:17:05:43 +0200] StartJob: envp[9]="CONTENT_TYPE=application/postscript"

D [28/Sep/2006:17:05:43 +0200] StartJob: envp[10]="DEVICE_URI=usb:/dev/usb/lp0"

D [28/Sep/2006:17:05:43 +0200] StartJob: envp[11]="PRINTER=Canon_PIXMA_iP4000"

D [28/Sep/2006:17:05:43 +0200] StartJob: envp[12]="CUPS_DATADIR=/usr/share/cups"

D [28/Sep/2006:17:05:43 +0200] StartJob: envp[13]="CUPS_FONTPATH=/usr/share/cups/fonts"

D [28/Sep/2006:17:05:43 +0200] StartJob: envp[14]="CUPS_SERVER=localhost"

D [28/Sep/2006:17:05:43 +0200] StartJob: envp[15]="IPP_PORT=631"

D [28/Sep/2006:17:05:43 +0200] StartJob: statusfds = [ 8 10 ]

D [28/Sep/2006:17:05:43 +0200] StartJob: filterfds[1] = [ 11 -1 ]

D [28/Sep/2006:17:05:43 +0200] StartJob: filter = "/usr/lib/cups/filter/pstops"

D [28/Sep/2006:17:05:43 +0200] StartJob: filterfds[0] = [ 12 13 ]

D [28/Sep/2006:17:05:43 +0200] start_process("/usr/lib/cups/filter/pstops", 0xbfbc9490, 0xbfbc8800, 11, 13, 10)

I [28/Sep/2006:17:05:43 +0200] Started filter /usr/lib/cups/filter/pstops (PID 23979) for job 5.

D [28/Sep/2006:17:05:43 +0200] StartJob: filter = "/usr/lib/cups/filter/pstoturboprint"

D [28/Sep/2006:17:05:43 +0200] StartJob: filterfds[1] = [ 11 14 ]

D [28/Sep/2006:17:05:43 +0200] start_process("/usr/lib/cups/filter/pstoturboprint", 0xbfbc9490, 0xbfbc8800, 12, 14, 10)

I [28/Sep/2006:17:05:43 +0200] Started filter /usr/lib/cups/filter/pstoturboprint (PID 23980) for job 5.

D [28/Sep/2006:17:05:43 +0200] StartJob: backend = "/usr/lib/cups/backend/usb"

D [28/Sep/2006:17:05:43 +0200] StartJob: filterfds[0] = [ -1 12 ]

D [28/Sep/2006:17:05:43 +0200] start_process("/usr/lib/cups/backend/usb", 0xbfbc9490, 0xbfbc8800, 11, 12, 10)

I [28/Sep/2006:17:05:43 +0200] Started backend /usr/lib/cups/backend/usb (PID 23983) for job 5.

D [28/Sep/2006:17:05:43 +0200] ProcessIPPRequest: 9 status_code=0

D [28/Sep/2006:17:05:43 +0200] [Job 5] Page = 595x842; 10,20 to 586,833

D [28/Sep/2006:17:05:43 +0200] [Job 5] slowcollate=0, slowduplex=0, sloworder=0

D [28/Sep/2006:17:05:43 +0200] [Job 5] 0 %%BoundingBox: 10 20 585 832

D [28/Sep/2006:17:05:43 +0200] [Job 5] 0 %%Creator: TurboPrint generic testpage

D [28/Sep/2006:17:05:43 +0200] [Job 5] 0 %%DocumentData: Clean7Bit

D [28/Sep/2006:17:05:43 +0200] [Job 5] 0 %%Orientation: Portrait

D [28/Sep/2006:17:05:43 +0200] [Job 5] 0 %%Pages: 1

D [28/Sep/2006:17:05:43 +0200] [Job 5] 0 %%PageOrder: Ascend

D [28/Sep/2006:17:05:43 +0200] [Job 5] 0 %%Title: status sheet and color gradients

D [28/Sep/2006:17:05:43 +0200] [Job 5] 0 %%EndComments

D [28/Sep/2006:17:05:43 +0200] [Job 5] 0 %%BeginProlog

D [28/Sep/2006:17:05:43 +0200] [Job 5] 0 %%EndProlog

D [28/Sep/2006:17:05:43 +0200] [Job 5] 0 %%Page: 1 1

D [28/Sep/2006:17:05:43 +0200] [Job 5] 0 %%Page: 1 1

D [28/Sep/2006:17:05:43 +0200] CloseClient: 9

D [28/Sep/2006:17:05:43 +0200] [Job 5] pw = 576.0, pl = 813.6

D [28/Sep/2006:17:05:43 +0200] [Job 5] PageLeft = 9.6, PageRight = 585.7

D [28/Sep/2006:17:05:43 +0200] [Job 5] PageTop = 833.4, PageBottom = 19.8

D [28/Sep/2006:17:05:43 +0200] [Job 5] PageWidth = 595.0, PageLength = 842.0

D [28/Sep/2006:17:05:43 +0200] [Job 5] 0 %%BeginPageSetup

D [28/Sep/2006:17:05:43 +0200] [Job 5] 0 %%EndPageSetup

D [28/Sep/2006:17:05:43 +0200] [Job 5] 0 %%EOF

D [28/Sep/2006:17:05:43 +0200] [Job 5] Saw EOF!

D [28/Sep/2006:17:05:43 +0200] [Job 5] LPGETSTATUS returned a port status of 18...

D [28/Sep/2006:17:05:43 +0200] [Job 5] ESP Ghostscript 815.02: **** Could not open temporary file /var/spool/cups/tmp/gs_AvCaQ0

D [28/Sep/2006:17:05:43 +0200] [Job 5] ESP Ghostscript 815.02: Could not open the scratch file /var/spool/cups/tmp/gs_AvCaQ0.

D [28/Sep/2006:17:06:23 +0200] CloseClient: 6

D [28/Sep/2006:17:08:37 +0200] AcceptClient: 6 from localhost:631.

D [28/Sep/2006:17:08:37 +0200] ReadClient: 6 GET /printers/Canon_PIXMA_iP4000 HTTP/1.1

D [28/Sep/2006:17:08:37 +0200] CGI /usr/lib/cups/cgi-bin/printers.cgi started - PID = 24858

I [28/Sep/2006:17:08:37 +0200] Started "/usr/lib/cups/cgi-bin/printers.cgi" (pid=24858)

D [28/Sep/2006:17:08:37 +0200] SendCommand: 6 file=10

D [28/Sep/2006:17:08:39 +0200] AcceptClient: 9 from localhost:631.

D [28/Sep/2006:17:08:39 +0200] ReadClient: 9 POST / HTTP/1.1

D [28/Sep/2006:17:08:39 +0200] ProcessIPPRequest: 9 status_code=1

D [28/Sep/2006:17:08:39 +0200] ReadClient: 9 POST / HTTP/1.1

D [28/Sep/2006:17:08:39 +0200] ProcessIPPRequest: 9 status_code=1

D [28/Sep/2006:17:08:39 +0200] ReadClient: 9 POST / HTTP/1.1

D [28/Sep/2006:17:08:39 +0200] ProcessIPPRequest: 9 status_code=1

D [28/Sep/2006:17:08:39 +0200] CloseClient: 9

D [28/Sep/2006:17:08:41 +0200] ReadClient: 6 GET /jobs/?op=cancel-job&job_id=5 HTTP/1.1

D [28/Sep/2006:17:08:41 +0200] CGI /usr/lib/cups/cgi-bin/jobs.cgi started - PID = 24860

I [28/Sep/2006:17:08:41 +0200] Started "/usr/lib/cups/cgi-bin/jobs.cgi" (pid=24860)

D [28/Sep/2006:17:08:41 +0200] SendCommand: 6 file=10

D [28/Sep/2006:17:08:41 +0200] AcceptClient: 9 from localhost:631.

D [28/Sep/2006:17:08:41 +0200] ReadClient: 9 POST /jobs HTTP/1.1

E [28/Sep/2006:17:08:41 +0200] Unable to open /etc/cups/passwd.md5 - Datei oder Verzeichnis nicht gefunden

E [28/Sep/2006:17:08:41 +0200] cancel_job: "" not authorized to delete job id 5 owned by "root"!

D [28/Sep/2006:17:08:41 +0200] Sending error: client-error-forbidden

D [28/Sep/2006:17:08:41 +0200] ProcessIPPRequest: 9 status_code=401

D [28/Sep/2006:17:08:41 +0200] CloseClient: 9

D [28/Sep/2006:17:08:52 +0200] ReadClient: 6 GET /admin/?op=config-printer&printer_name=Canon_PIXMA_iP4000 HTTP/1.1

D [28/Sep/2006:17:08:52 +0200] CGI /usr/lib/cups/cgi-bin/admin.cgi started - PID = 24861

I [28/Sep/2006:17:08:52 +0200] Started "/usr/lib/cups/cgi-bin/admin.cgi" (pid=24861)

D [28/Sep/2006:17:08:52 +0200] SendCommand: 6 file=10

D [28/Sep/2006:17:08:52 +0200] AcceptClient: 9 from localhost:631.

D [28/Sep/2006:17:08:52 +0200] AcceptClient: 11 from localhost:631.

D [28/Sep/2006:17:08:52 +0200] ReadClient: 11 POST / HTTP/1.1

D [28/Sep/2006:17:08:52 +0200] ProcessIPPRequest: 11 status_code=0

D [28/Sep/2006:17:08:52 +0200] CloseClient: 9

D [28/Sep/2006:17:08:52 +0200] CloseClient: 11

D [28/Sep/2006:17:08:56 +0200] ReadClient: 6 GET /admin/?op=modify-printer&printer_name=Canon_PIXMA_iP4000 HTTP/1.1

D [28/Sep/2006:17:08:56 +0200] CGI /usr/lib/cups/cgi-bin/admin.cgi started - PID = 24862

I [28/Sep/2006:17:08:56 +0200] Started "/usr/lib/cups/cgi-bin/admin.cgi" (pid=24862)

D [28/Sep/2006:17:08:56 +0200] SendCommand: 6 file=10

D [28/Sep/2006:17:08:56 +0200] AcceptClient: 9 from localhost:631.

D [28/Sep/2006:17:08:56 +0200] ReadClient: 9 POST / HTTP/1.1

D [28/Sep/2006:17:08:56 +0200] ProcessIPPRequest: 9 status_code=0

D [28/Sep/2006:17:08:57 +0200] CloseClient: 9

```

The following happens whenever I am trying to print a test page in the CUPS interface:

```
D [28/Sep/2006:17:27:28 +0200] ReadClient: 10 GET /printers/Canon_PIXMA_iP4000?op=print-test-page HTTP/1.1

D [28/Sep/2006:17:27:28 +0200] CGI /usr/lib/cups/cgi-bin/printers.cgi started - PID = 25031

I [28/Sep/2006:17:27:28 +0200] Started "/usr/lib/cups/cgi-bin/printers.cgi" (pid=25031)

D [28/Sep/2006:17:27:28 +0200] SendCommand: 10 file=9

D [28/Sep/2006:17:27:28 +0200] AcceptClient: 8 from localhost:631.

D [28/Sep/2006:17:27:28 +0200] ReadClient: 8 POST /printers/Canon_PIXMA_iP4000 HTTP/1.1

D [28/Sep/2006:17:27:28 +0200] print_job: request file type is application/postscript.

D [28/Sep/2006:17:27:28 +0200] check_quotas: requesting-user-name = ''

D [28/Sep/2006:17:27:28 +0200] print_job: requesting-user-name = ''

D [28/Sep/2006:17:27:28 +0200] Adding default job-sheets values "none,none"...

I [28/Sep/2006:17:27:28 +0200] Adding start banner page "none" to job 6.

I [28/Sep/2006:17:27:28 +0200] Adding end banner page "none" to job 6.

I [28/Sep/2006:17:27:28 +0200] Job 6 queued on 'Canon_PIXMA_iP4000' by ''.

D [28/Sep/2006:17:27:28 +0200] Job 6 hold_until = 0

D [28/Sep/2006:17:27:28 +0200] StartJob(6, 0x80d5900)

D [28/Sep/2006:17:27:28 +0200] StartJob() id = 6, file = 0/1

D [28/Sep/2006:17:27:28 +0200] job-sheets=none,none

D [28/Sep/2006:17:27:28 +0200] banner_page = 0

D [28/Sep/2006:17:27:28 +0200] StartJob: argv = "Canon_PIXMA_iP4000","6","","Test Page","1","","/var/spool/cups/d00006-001"

D [28/Sep/2006:17:27:28 +0200] StartJob: envp[0]="PATH=/usr/lib/cups/filter:/bin:/usr/bin"

D [28/Sep/2006:17:27:28 +0200] StartJob: envp[1]="SOFTWARE=CUPS/1.1"

D [28/Sep/2006:17:27:28 +0200] StartJob: envp[2]="USER=root"

D [28/Sep/2006:17:27:28 +0200] StartJob: envp[3]="CHARSET=utf-8"

D [28/Sep/2006:17:27:28 +0200] StartJob: envp[4]="LANG=de"

D [28/Sep/2006:17:27:28 +0200] StartJob: envp[5]="PPD=/etc/cups/ppd/Canon_PIXMA_iP4000.ppd"

D [28/Sep/2006:17:27:28 +0200] StartJob: envp[6]="CUPS_SERVERROOT=/etc/cups"

D [28/Sep/2006:17:27:28 +0200] StartJob: envp[7]="RIP_MAX_CACHE=8m"

D [28/Sep/2006:17:27:28 +0200] StartJob: envp[8]="TMPDIR=/var/spool/cups/tmp"

D [28/Sep/2006:17:27:28 +0200] StartJob: envp[9]="CONTENT_TYPE=application/postscript"

D [28/Sep/2006:17:27:28 +0200] StartJob: envp[10]="DEVICE_URI=usb:/dev/usb/lp0"

D [28/Sep/2006:17:27:28 +0200] StartJob: envp[11]="PRINTER=Canon_PIXMA_iP4000"

D [28/Sep/2006:17:27:28 +0200] StartJob: envp[12]="CUPS_DATADIR=/usr/share/cups"

D [28/Sep/2006:17:27:28 +0200] StartJob: envp[13]="CUPS_FONTPATH=/usr/share/cups/fonts"

D [28/Sep/2006:17:27:28 +0200] StartJob: envp[14]="CUPS_SERVER=localhost"

D [28/Sep/2006:17:27:28 +0200] StartJob: envp[15]="IPP_PORT=631"

D [28/Sep/2006:17:27:28 +0200] StartJob: statusfds = [ 11 12 ]

D [28/Sep/2006:17:27:28 +0200] StartJob: filterfds[1] = [ 13 -1 ]

D [28/Sep/2006:17:27:28 +0200] StartJob: filter = "/usr/lib/cups/filter/pstops"

D [28/Sep/2006:17:27:28 +0200] StartJob: filterfds[0] = [ 14 15 ]

D [28/Sep/2006:17:27:28 +0200] start_process("/usr/lib/cups/filter/pstops", 0xbfbc9490, 0xbfbc8800, 13, 15, 12)

I [28/Sep/2006:17:27:28 +0200] Started filter /usr/lib/cups/filter/pstops (PID 25032) for job 6.

D [28/Sep/2006:17:27:28 +0200] StartJob: filter = "/usr/lib/cups/filter/pstoturboprint"

D [28/Sep/2006:17:27:28 +0200] StartJob: filterfds[1] = [ 13 16 ]

D [28/Sep/2006:17:27:28 +0200] start_process("/usr/lib/cups/filter/pstoturboprint", 0xbfbc9490, 0xbfbc8800, 14, 16, 12)

I [28/Sep/2006:17:27:28 +0200] Started filter /usr/lib/cups/filter/pstoturboprint (PID 25033) for job 6.

D [28/Sep/2006:17:27:28 +0200] StartJob: backend = "/usr/lib/cups/backend/usb"

D [28/Sep/2006:17:27:28 +0200] StartJob: filterfds[0] = [ -1 14 ]

D [28/Sep/2006:17:27:28 +0200] start_process("/usr/lib/cups/backend/usb", 0xbfbc9490, 0xbfbc8800, 13, 14, 12)

I [28/Sep/2006:17:27:28 +0200] Started backend /usr/lib/cups/backend/usb (PID 25035) for job 6.

D [28/Sep/2006:17:27:28 +0200] ProcessIPPRequest: 8 status_code=0

D [28/Sep/2006:17:27:28 +0200] [Job 6] Page = 595x842; 10,20 to 586,833

D [28/Sep/2006:17:27:28 +0200] [Job 6] slowcollate=0, slowduplex=0, sloworder=0

D [28/Sep/2006:17:27:28 +0200] [Job 6] 0 %%BoundingBox: 0 0 612 792

D [28/Sep/2006:17:27:28 +0200] [Job 6] 0 %%Pages: 1

D [28/Sep/2006:17:27:28 +0200] [Job 6] 0 %%LanguageLevel: 1

D [28/Sep/2006:17:27:28 +0200] [Job 6] 0 %%DocumentData: Clean7Bit

D [28/Sep/2006:17:27:28 +0200] [Job 6] 0 %%DocumentSuppliedResources: procset testprint/1.1

D [28/Sep/2006:17:27:28 +0200] [Job 6] 0 %%DocumentNeededResources: font Helvetica Helvetica-Bold Times-Roman

D [28/Sep/2006:17:27:28 +0200] [Job 6] 0 %%Creator: Michael Sweet, Easy Software Products

D [28/Sep/2006:17:27:28 +0200] [Job 6] 0 %%CreationDate: May 11, 1999

D [28/Sep/2006:17:27:28 +0200] [Job 6] 0 %%Title: Test Page

D [28/Sep/2006:17:27:28 +0200] [Job 6] 0 %%EndComments

D [28/Sep/2006:17:27:28 +0200] [Job 6] 0 %%BeginProlog

D [28/Sep/2006:17:27:28 +0200] [Job 6] 0 %%BeginResource procset testprint 1.1 0

D [28/Sep/2006:17:27:28 +0200] [Job 6] 0 %%EndResource

D [28/Sep/2006:17:27:28 +0200] [Job 6] 0 %%EndProlog

D [28/Sep/2006:17:27:28 +0200] [Job 6] 0 %%Page: 1 1

D [28/Sep/2006:17:27:28 +0200] [Job 6] 0 %%Page: 1 1

D [28/Sep/2006:17:27:28 +0200] [Job 6] pw = 576.0, pl = 813.6

D [28/Sep/2006:17:27:28 +0200] [Job 6] PageLeft = 9.6, PageRight = 585.7

D [28/Sep/2006:17:27:28 +0200] [Job 6] PageTop = 833.4, PageBottom = 19.8

D [28/Sep/2006:17:27:28 +0200] [Job 6] PageWidth = 595.0, PageLength = 842.0

D [28/Sep/2006:17:27:28 +0200] [Job 6] 0 %%EOF

D [28/Sep/2006:17:27:28 +0200] [Job 6] Saw EOF!

D [28/Sep/2006:17:27:29 +0200] CloseClient: 8

D [28/Sep/2006:17:27:29 +0200] [Job 6] LPGETSTATUS returned a port status of 18...

D [28/Sep/2006:17:27:30 +0200] [Job 6] ESP Ghostscript 815.02: **** Could not open temporary file /var/spool/cups/tmp/gs_O9Qbkb

D [28/Sep/2006:17:27:30 +0200] [Job 6] ESP Ghostscript 815.02: Could not open the scratch file /var/spool/cups/tmp/gs_O9Qbkb.

D [28/Sep/2006:17:27:39 +0200] CloseClient: 6

```

Both error logs are made with udev-094 and cups-1.1.23-r8, but the symptoms are the same with the newest versions.

My kernel is 2.6.15-gentoo-r1.

lsusb:

```
Bus 003 Device 003: ID 04a9:1093 Canon, Inc.
```

Thanks.Last edited by Silenzium on Thu Sep 28, 2006 9:11 pm; edited 1 time in total

----------

## wynn

Both jobs seem to fail at the same point

```
D [28/Sep/2006:17:27:30 +0200] [Job 6] ESP Ghostscript 815.02: **** Could not open temporary file /var/spool/cups/tmp/gs_O9Qbkb

D [28/Sep/2006:17:27:30 +0200] [Job 6] ESP Ghostscript 815.02: Could not open the scratch file /var/spool/cups/tmp/gs_O9Qbkb.
```

Here

```
# l /var/spool/cups

total 32

4 drwx--x--- 3 root lp   4096 Sep 28 11:27 ./

4 drwxr-xr-x 7 root root 4096 Sep  9 20:48 ../

4 -rw------- 1 root lp    665 Sep 25 20:54 c00015

4 -rw------- 1 root lp    705 Sep 25 20:59 c00016

4 -rw------- 1 root lp    657 Sep 25 21:46 c00017

4 -rw------- 1 root lp    658 Sep 25 21:47 c00018

4 -rw------- 1 root lp    747 Sep 28 11:27 c00019

4 drwxrwx--T 2 root lp   4096 Sep 25 21:47 tmp/

lightfoot ~ # l /var/spool/cups/tmp

total 8

4 drwxrwx--T 2 root lp 4096 Sep 25 21:47 ./

4 drwx--x--- 3 root lp 4096 Sep 28 11:27 ../

```

Would you like to check the permissions on /var/spool/cups and /var/spool/cups/tmp?

----------

## Silenzium

Ah, /var/spool/cups/tmp was missing. I must have been blind. (But I don't know, why it was missing.)

After adding it with correct permissions, I updated cups step by step to 1.2.4 and it works as well. Nice.

I don't know, if I should upgrade udev (094 atm). Version 100-r2 couldn't finalize my configuration.

Thanks a lot.  :Smile: 

----------

