[cups.general] problem printing with DELL AIO V505 wireless

Sat Jan 10 09:22:43 PST 2009

Dear list,

Despite my first reluctance to do so, I finally bought a wireless
all-in-one printer DELL 505 with wireless extension. These cheap
printers do not have a good reputation on the web but yes, they are
cheap, have a lot of features and in the case of the 505, the linux
driver can be downloaded from the Dell web site under the form of a deb
and rpm package !

I am running

Ubuntu 7.04 (Linux 2.6.20-17-386).

I installed the .deb package from Dell and located the ppd file.I
selected that file when the installation system asked for it.

The printer was detected  when I used the "New Printer" from the Ubuntu
System->Administration->printing menu.

The device is reported by cups as follows
(http://localhost:631/printers/V505)

Description: V505
Location:
Make and Model: Dell V505, 1.0
Printer State: idle, accepting jobs, published.
Device URI: socket://192.168.1.4

Note that I tried different protocols (IPP, LPD, socket)
The first lines of /etc/cups/ppd/V505.ppd are

*PPD-Adobe: "4.3"
*% PPD file for V505 with CUPS.
*% Created by the CUPS PPD Compiler v1.2.3.
*FormatVersion: "4.3"
*FileVersion: "1.0"
*LanguageVersion: English
*LanguageEncoding: ISOLatin1
*PCFileName: "dlV505.ppd"
*Product: "(Dell V505)"
*Manufacturer: "Dell"
*ModelName: "Dell V505"
*ShortNickName: "Dell V505"
*NickName: "Dell V505, 1.0"

When printing a test page, I got a very large error_log file:
 cat error_log | grep --count "Job 62"
gives 18537 lines !

The file looks as follows  (Sorry for the length, only the lines
matching "Job 62" are shown)

I [09/Jan/2009:18:34:37 +0100] Job 62 queued on "V505" by "vinsz".
D [09/Jan/2009:18:34:37 +0100] Job 62 hold_until = 0
D [09/Jan/2009:18:34:37 +0100] [Job 62] argv[0]="V505"
D [09/Jan/2009:18:34:37 +0100] [Job 62] argv[1]="62"
D [09/Jan/2009:18:34:37 +0100] [Job 62] argv[2]="vinsz"
D [09/Jan/2009:18:34:37 +0100] [Job 62] argv[3]="Test Page"
D [09/Jan/2009:18:34:37 +0100] [Job 62] argv[4]="1"
D [09/Jan/2009:18:34:37 +0100] [Job 62]
argv[5]="job-uuid=urn:uuid:cc56ab33-48bf-362d-6e0d-6c1d272777f9"
D [09/Jan/2009:18:34:37 +0100] [Job 62] argv[6]="/var/spool/cups/d00062-001"
D [09/Jan/2009:18:34:37 +0100] [Job 62]
envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [09/Jan/2009:18:34:37 +0100] [Job 62]
envp[1]="CUPS_DATADIR=/usr/share/cups"
D [09/Jan/2009:18:34:37 +0100] [Job 62]
envp[2]="CUPS_DOCROOT=/usr/share/cups/doc-root"
D [09/Jan/2009:18:34:37 +0100] [Job 62]
envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [09/Jan/2009:18:34:37 +0100] [Job 62]
envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [09/Jan/2009:18:34:37 +0100] [Job 62]
envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [09/Jan/2009:18:34:37 +0100] [Job 62] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [09/Jan/2009:18:34:37 +0100] [Job 62]
envp[7]="CUPS_STATEDIR=/var/run/cups"
D [09/Jan/2009:18:34:37 +0100] [Job 62]
envp[8]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [09/Jan/2009:18:34:37 +0100] [Job 62]
envp[9]="SERVER_ADMIN=root at localhost.localdomain"
D [09/Jan/2009:18:34:37 +0100] [Job 62] envp[10]="SOFTWARE=CUPS/1.2.8"
D [09/Jan/2009:18:34:37 +0100] [Job 62]
envp[11]="TMPDIR=/var/spool/cups/tmp"
D [09/Jan/2009:18:34:37 +0100] [Job 62] envp[12]="TZ=Europe/Brussels"
D [09/Jan/2009:18:34:37 +0100] [Job 62] envp[13]="USER=root"
D [09/Jan/2009:18:34:37 +0100] [Job 62]
envp[14]="CUPS_SERVER=/var/run/cups/cups.sock"
D [09/Jan/2009:18:34:37 +0100] [Job 62]
envp[15]="CUPS_ENCRYPTION=IfRequested"
D [09/Jan/2009:18:34:37 +0100] [Job 62] envp[16]="IPP_PORT=631"
D [09/Jan/2009:18:34:37 +0100] [Job 62] envp[17]="CHARSET=utf-8"
D [09/Jan/2009:18:34:37 +0100] [Job 62] envp[18]="LANG=en_GB"
D [09/Jan/2009:18:34:37 +0100] [Job 62]
envp[19]="PPD=/etc/cups/ppd/V505.ppd"
D [09/Jan/2009:18:34:37 +0100] [Job 62] envp[20]="RIP_MAX_CACHE=8m"
D [09/Jan/2009:18:34:37 +0100] [Job 62]
envp[21]="CONTENT_TYPE=application/postscript"
D [09/Jan/2009:18:34:37 +0100] [Job 62]
envp[22]="DEVICE_URI=socket://192.168.1.4"
D [09/Jan/2009:18:34:37 +0100] [Job 62] envp[23]="PRINTER=V505"
D [09/Jan/2009:18:34:37 +0100] [Job 62]
envp[24]="FINAL_CONTENT_TYPE=printer/V505"
D [09/Jan/2009:18:34:37 +0100] [Job 62] Page = 595x842; 10,36 to 586,837
D [09/Jan/2009:18:34:37 +0100] [Job 62] slow_collate=0, slow_duplex=0,
slow_order=0
D [09/Jan/2009:18:34:37 +0100] [Job 62] Before copy_comments -
%!PS-Adobe-3.0
D [09/Jan/2009:18:34:37 +0100] [Job 62] %!PS-Adobe-3.0
D [09/Jan/2009:18:34:37 +0100] [Job 62] %%BoundingBox: 0 0 612 792
D [09/Jan/2009:18:34:37 +0100] [Job 62] %%Pages: 1
D [09/Jan/2009:18:34:37 +0100] [Job 62]
envp[22]="DEVICE_URI=socket://192.168.1.4"
D [09/Jan/2009:18:34:37 +0100] [Job 62] envp[23]="PRINTER=V505"
D [09/Jan/2009:18:34:37 +0100] [Job 62]
envp[24]="FINAL_CONTENT_TYPE=printer/V505"
D [09/Jan/2009:18:34:37 +0100] [Job 62] Page = 595x842; 10,36 to 586,837
D [09/Jan/2009:18:34:37 +0100] [Job 62] slow_collate=0, slow_duplex=0,
slow_order=0
D [09/Jan/2009:18:34:37 +0100] [Job 62] Before copy_comments -
%!PS-Adobe-3.0
D [09/Jan/2009:18:34:37 +0100] [Job 62] %!PS-Adobe-3.0
D [09/Jan/2009:18:34:37 +0100] [Job 62] %%BoundingBox: 0 0 612 792
D [09/Jan/2009:18:34:37 +0100] [Job 62] %%Pages: 1
D [09/Jan/2009:18:34:37 +0100] [Job 62] %%LanguageLevel: 1
D [09/Jan/2009:18:34:37 +0100] [Job 62] %%DocumentData: Clean7Bit
D [09/Jan/2009:18:34:37 +0100] [Job 62] %%DocumentSuppliedResources:
procset testprint/1.2
D [09/Jan/2009:18:34:37 +0100] [Job 62] %%DocumentNeededResources: font
Helvetica Helvetica-Bold Times-Roman
D [09/Jan/2009:18:34:37 +0100] [Job 62] %%Creator: Michael Sweet, Easy
Software Products
D [09/Jan/2009:18:34:37 +0100] [Job 62] %%CreationDate:
D:20070220113000+0500
D [09/Jan/2009:18:34:37 +0100] [Job 62] %%Title: Test Page
D [09/Jan/2009:18:34:37 +0100] [Job 62] %%EndComments
D [09/Jan/2009:18:34:37 +0100] [Job 62] Before copy_prolog - %%BeginProlog
D [09/Jan/2009:18:34:37 +0100] [Job 62] Before copy_setup - %%Page: 1 1
D [09/Jan/2009:18:34:37 +0100] [Job 62] Before page loop - %%Page: 1 1
D [09/Jan/2009:18:34:37 +0100] [Job 62] Copying page 1...
D [09/Jan/2009:18:34:37 +0100] [Job 62] pagew = 576.0, pagel = 801.0
D [09/Jan/2009:18:34:37 +0100] [Job 62] bboxw = 595, bboxl = 841
D [09/Jan/2009:18:34:37 +0100] [Job 62] PageLeft = 9.6, PageRight = 585.6
D [09/Jan/2009:18:34:37 +0100] [Job 62] PageTop = 837.0, PageBottom = 36.0
D [09/Jan/2009:18:34:37 +0100] [Job 62] PageWidth = 595.2, PageLength =
841.8
D [09/Jan/2009:18:34:37 +0100] [Job 62] Wrote 1 pages...
D [09/Jan/2009:18:34:37 +0100] [Job 62] Running /usr/bin/gs-esp -dQUIET
-dDEBUG -dPARANOIDSAFER -dNOPAUSE -dBATCH -dNOMEDIAATTRS -sDEVICE=cups
-sstdout=%stderr -sOUTPUTFILE=%stdout -c -
D [09/Jan/2009:18:34:37 +0100] [Job 62] Connected to 192.168.1.4:9100
(IPv4)...
D [09/Jan/2009:18:34:37 +0100] [Job 62] backendRunLoop(print_fd=0,
device_fd=4, use_bc=1)
D [09/Jan/2009:18:34:37 +0100] [Job 62] START 0 1397176 113678 1300844
11688 true 512 3 <0>
D [09/Jan/2009:18:34:37 +0100] [Job 62] END PROCS 2 1417272 130828
1300844 13056 true 632 3 <0>

< ... >

 [09/Jan/2009:18:34:38 +0100] [Job 62] /cupsRowFeed
D [09/Jan/2009:18:34:38 +0100] [Job 62] 0
D [09/Jan/2009:18:34:38 +0100] [Job 62] /MediaPosition
D [09/Jan/2009:18:34:38 +0100] [Job 62] -mark-
D [09/Jan/2009:18:34:38 +0100] [Job 62] true
D [09/Jan/2009:18:34:38 +0100] [Job 62] -dict-
D [09/Jan/2009:18:34:38 +0100] [Job 62] -device-
D [09/Jan/2009:18:34:38 +0100] [Job 62] -dict-
D [09/Jan/2009:18:34:38 +0100] [Job 62] -dict-
D [09/Jan/2009:18:34:38 +0100] [Job 62] -dict-
D [09/Jan/2009:18:34:38 +0100] [Job 62] -dict-
D [09/Jan/2009:18:34:38 +0100] [Job 62] -mark-
D [09/Jan/2009:18:34:38 +0100] [Job 62] -dict-
D [09/Jan/2009:18:34:38 +0100] [Job 62] -mark-
D [09/Jan/2009:18:34:38 +0100] [Job 62] -mark-
D [09/Jan/2009:18:34:38 +0100] [Job 62] Setting MediaPosition to 0...
D [09/Jan/2009:18:34:38 +0100] [Job 62] Setting cupsRowFeed to 1...
D [09/Jan/2009:18:34:38 +0100] [Job 62] cupsEncodeLUT[0] = 0
D [09/Jan/2009:18:34:38 +0100] [Job 62] cupsEncodeLUT[65535] = 1
D [09/Jan/2009:18:34:38 +0100] [Job 62] num_components = 1, depth = 1
D [09/Jan/2009:18:34:38 +0100] [Job 62] cupsColorSpace = 3,
cupsColorOrder = 0
D [09/Jan/2009:18:34:38 +0100] [Job 62] cupsBitsPerPixel = 1,
cupsBitsPerColor = 1
D [09/Jan/2009:18:34:38 +0100] [Job 62] max_gray = 1, dither_grays = 2
D [09/Jan/2009:18:34:38 +0100] [Job 62] max_color = 0, dither_colors = 0
D [09/Jan/2009:18:34:38 +0100] [Job 62] Updating PageSize to [612 792]...
D [09/Jan/2009:18:34:38 +0100] [Job 62] size = Letter
D [09/Jan/2009:18:34:38 +0100] [Job 62] margins[] = [ 0.250000 0.500000
0.250000 0.066666 ]
D [09/Jan/2009:18:34:38 +0100] [Job 62] Reallocating memory, [612 792] =
800x1043 pixels...
D [09/Jan/2009:18:34:38 +0100] [Job 62] cache_size = 8388608
D [09/Jan/2009:18:34:38 +0100] [Job 62] Result of putting.
D [09/Jan/2009:18:34:38 +0100] [Job 62] false

< ... after a lot of block as above ...>

D [09/Jan/2009:18:43:46 +0100] [Job 62] Read 8140 bytes of print data...
D [09/Jan/2009:18:43:46 +0100] [Job 62] Wrote 8140 bytes of print data...
D [09/Jan/2009:18:43:46 +0100] [Job 62] Received 9 bytes of back-channel
data!
D [09/Jan/2009:18:43:46 +0100] [Job 62] Received 9 bytes of back-channel
data!
D [09/Jan/2009:18:43:47 +0100] [Job 62] Read 8140 bytes of print data...
D [09/Jan/2009:18:43:47 +0100] [Job 62] Wrote 8140 bytes of print data...
D [09/Jan/2009:18:43:47 +0100] [Job 62] Received 9 bytes of back-channel
data!
D [09/Jan/2009:18:43:47 +0100] [Job 62] Received 9 bytes of back-channel
data!
D [09/Jan/2009:18:43:47 +0100] [Job 62] Read 8140 bytes of print data...
D [09/Jan/2009:18:43:47 +0100] [Job 62] Wrote 8140 bytes of print data...
D [09/Jan/2009:18:43:47 +0100] [Job 62] Received 9 bytes of back-channel
data!
D [09/Jan/2009:18:43:48 +0100] [Job 62] Read 8140 bytes of print data...
D [09/Jan/2009:18:43:48 +0100] [Job 62] Wrote 8140 bytes of print data...
D [09/Jan/2009:18:43:48 +0100] [Job 62] Received 9 bytes of back-channel
data!
D [09/Jan/2009:18:43:48 +0100] [Job 62] Received 9 bytes of back-channel
data!
D [09/Jan/2009:18:43:48 +0100] [Job 62] Read 8140 bytes of print data...
D [09/Jan/2009:18:43:48 +0100] [Job 62] Wrote 8140 bytes of print data...
D [09/Jan/2009:18:43:48 +0100] [Job 62] Received 9 bytes of back-channel
data!
D [09/Jan/2009:18:43:48 +0100] [Job 62] Received 9 bytes of back-channel
data!
D [09/Jan/2009:18:43:49 +0100] [Job 62] Read 8140 bytes of print data...
D [09/Jan/2009:18:43:49 +0100] [Job 62] Wrote 8140 bytes of print data...
D [09/Jan/2009:18:43:49 +0100] [Job 62] Received 9 bytes of back-channel
data!
D [09/Jan/2009:18:43:49 +0100] [Job 62] Received 9 bytes of back-channel
data!
D [09/Jan/2009:18:43:49 +0100] [Job 62] Read 8140 bytes of print data...
D [09/Jan/2009:18:43:49 +0100] [Job 62] Wrote 8140 bytes of print data...
D [09/Jan/2009:18:43:49 +0100] [Job 62] Received 9 bytes of back-channel
data!
D [09/Jan/2009:18:43:50 +0100] [Job 62] Received 9 bytes of back-channel
data!

< ... the block above is again repeadted many times ...  >

Could anyone give me some advices on how to go ahead troubleshooting
this problem ?

Thanks in advance,

--
	Vincent