-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1
Mark Nelson wrote:
Hello
Further to the post I made last week (see below), I have investigated
the problem further and I have discovered that the cups server on the
client goes into error state with the following error message -
E [08/Aug/2005:10:47:34 +0100] [Job 5] Unable to get job 769 attributes
(client-error-bad-request)!
It then recovers and tries to send the second file again. The StartJob
function is called twice for the second file.
I have attached the full output from the cups error_log file running in
debug mode on the client.
I am tempted to rebuild the cups system from FC3 as an RPM and install
that on the print server, however I would like to stay as close to the
standard SL4 system as possible.
Mark.
> Hello
>
> I've upgraded our print server from FC3 to SL4, the client machines are
> on SL4 and have been for a few months without any problems. The problem
> I have is if I print out two documents in succession I get one copy of
> the first print out and several copies of the second print out.
> However, if I switch on debug mode within cups it doesn't happen. The
> client machines forward the print request to the server, it looks like
> the job gets stuck in the client cups queue. Eventually the job
> completes after printing out several copies of the file. The version of
> cups (cups-1.1.22-0.rc1.9.6) is the same on both machines and there are
> no .lpoptions file around. The version of cups on FC3 was
> cups-1.1.22-0.rc1.8.5
>
> Any ideas
>
>
> Mark.
>
>
- --
- -------------------------------------------------------------
Mark Nelson - [log in to unmask]
IPPP, Department of Physics, University of Durham,
Science Laboratories, South Road, Durham, DH1 3LE
Office: +44 (0)191 334 3811, Direct Dial: +44 (0)191 334 3653
PGP Key: http://www.ippp.dur.ac.uk/~mn/pgp_key.txt
This mail is for the addressee only
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.2.6 (GNU/Linux)
Comment: Using GnuPG with Red Hat - http://enigmail.mozdev.org
iD8DBQFC9y/UlzM++u0MgcERAlfoAJ0WycsDB+t395wQ2WKwNoBRUZQJsQCfVzI3
BA6DdvzQioGbWlA9XhRpdY0=
=UtPK
-----END PGP SIGNATURE-----
D [08/Aug/2005:10:46:42 +0100] AddLocation: added location '/'
D [08/Aug/2005:10:46:42 +0100] DenyIP: / deny 00000000/00000000
D [08/Aug/2005:10:46:42 +0100] AllowIP: / allow 7f000001/ffffffff
D [08/Aug/2005:10:46:42 +0100] AddLocation: added location '/admin'
D [08/Aug/2005:10:46:42 +0100] DenyIP: /admin deny 00000000/00000000
D [08/Aug/2005:10:46:42 +0100] AllowIP: /admin allow 7f000001/ffffffff
D [08/Aug/2005:10:46:42 +0100] AddLocation: added location 'CUPS_INTERNAL_BROWSE_ACL'
D [08/Aug/2005:10:46:42 +0100] AllowHost: CUPS_INTERNAL_BROWSE_ACL allow @LOCAL
I [08/Aug/2005:10:46:42 +0100] Listening to 7f000001:631
I [08/Aug/2005:10:46:42 +0100] Loaded configuration file "/etc/cups/cupsd.conf"
I [08/Aug/2005:10:46:42 +0100] Configured for up to 100 clients.
I [08/Aug/2005:10:46:42 +0100] Allowing up to 100 client connections per host.
I [08/Aug/2005:10:46:42 +0100] Full reload is required.
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "ipp"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "socket"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "smb"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "hal"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "usb:/dev/usb/lp0"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "usb:/dev/usb/lp1"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "usb:/dev/usb/lp2"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "usb:/dev/usb/lp3"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "usb:/dev/usb/lp4"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "usb:/dev/usb/lp5"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "usb:/dev/usb/lp6"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "usb:/dev/usb/lp7"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "usb:/dev/usb/lp8"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "usb:/dev/usb/lp9"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "usb:/dev/usb/lp10"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "usb:/dev/usb/lp11"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "usb:/dev/usb/lp12"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "usb:/dev/usb/lp13"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "usb:/dev/usb/lp14"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "usb:/dev/usb/lp15"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "lpd"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "serial:/dev/ttyS0?baud=115200"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "serial:/dev/ttyS1?baud=115200"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "serial:/dev/ttyS2?baud=115200"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "serial:/dev/ttyS3?baud=115200"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "serial:/dev/ttyS4?baud=115200"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "serial:/dev/ttyS5?baud=115200"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "serial:/dev/ttyS6?baud=115200"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "serial:/dev/ttyS7?baud=115200"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "http"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "parallel:/dev/lp0"...
D [08/Aug/2005:10:46:42 +0100] LoadDevices: Added device "scsi"...
I [08/Aug/2005:10:46:42 +0100] LoadPPDs: Read "/etc/cups/ppds.dat", 15 PPDs...
I [08/Aug/2005:10:46:42 +0100] LoadPPDs: No new or changed PPDs...
D [08/Aug/2005:10:46:42 +0100] LoadAllJobs: Scanning /var/spool/cups...
I [08/Aug/2005:10:46:42 +0100] Full reload complete.
D [08/Aug/2005:10:46:42 +0100] StartListening: NumListeners=1
D [08/Aug/2005:10:46:42 +0100] StartListening: address=7f000001 port=631
D [08/Aug/2005:10:46:42 +0100] ResumeListening: setting input bits...
I [08/Aug/2005:10:46:55 +0100] Added remote printer "hp2"...
I [08/Aug/2005:10:46:57 +0100] Added remote printer "hp1"...
D [08/Aug/2005:10:47:03 +0100] AcceptClient: 6 from localhost:631.
D [08/Aug/2005:10:47:03 +0100] ReadClient: 6 POST / HTTP/1.1
D [08/Aug/2005:10:47:03 +0100] ProcessIPPRequest: 6 status_code=1
D [08/Aug/2005:10:47:03 +0100] ReadClient: 6 POST / HTTP/1.1
D [08/Aug/2005:10:47:03 +0100] ProcessIPPRequest: 6 status_code=1
D [08/Aug/2005:10:47:03 +0100] ReadClient: 6 POST / HTTP/1.1
D [08/Aug/2005:10:47:03 +0100] ProcessIPPRequest: 6 status_code=0
D [08/Aug/2005:10:47:03 +0100] ReadClient: 6 POST / HTTP/1.1
D [08/Aug/2005:10:47:03 +0100] ProcessIPPRequest: 6 status_code=1
D [08/Aug/2005:10:47:03 +0100] ReadClient: 6 POST / HTTP/1.1
D [08/Aug/2005:10:47:03 +0100] ProcessIPPRequest: 6 status_code=1
D [08/Aug/2005:10:47:03 +0100] ReadClient: 6 POST / HTTP/1.1
D [08/Aug/2005:10:47:03 +0100] ProcessIPPRequest: 6 status_code=1
D [08/Aug/2005:10:47:03 +0100] ReadClient: 6 POST / HTTP/1.1
D [08/Aug/2005:10:47:03 +0100] ProcessIPPRequest: 6 status_code=1
D [08/Aug/2005:10:47:03 +0100] ReadClient: 6 POST / HTTP/1.1
D [08/Aug/2005:10:47:03 +0100] ProcessIPPRequest: 6 status_code=1
D [08/Aug/2005:10:47:03 +0100] ReadClient: 6 POST / HTTP/1.1
D [08/Aug/2005:10:47:03 +0100] ProcessIPPRequest: 6 status_code=1
D [08/Aug/2005:10:47:03 +0100] CloseClient: 6
I [08/Aug/2005:10:47:05 +0100] Added remote printer "hpcol"...
D [08/Aug/2005:10:47:05 +0100] AcceptClient: 6 from localhost:631.
D [08/Aug/2005:10:47:05 +0100] ReadClient: 6 POST / HTTP/1.1
D [08/Aug/2005:10:47:05 +0100] ProcessIPPRequest: 6 status_code=1
D [08/Aug/2005:10:47:05 +0100] ReadClient: 6 POST / HTTP/1.1
D [08/Aug/2005:10:47:05 +0100] ProcessIPPRequest: 6 status_code=1
D [08/Aug/2005:10:47:05 +0100] ReadClient: 6 POST / HTTP/1.1
D [08/Aug/2005:10:47:05 +0100] ProcessIPPRequest: 6 status_code=0
D [08/Aug/2005:10:47:06 +0100] ReadClient: 6 POST / HTTP/1.1
D [08/Aug/2005:10:47:06 +0100] ProcessIPPRequest: 6 status_code=1
I [08/Aug/2005:10:47:06 +0100] Added remote printer "Xerox"...
D [08/Aug/2005:10:47:06 +0100] ReadClient: 6 POST / HTTP/1.1
D [08/Aug/2005:10:47:06 +0100] ProcessIPPRequest: 6 status_code=1
D [08/Aug/2005:10:47:06 +0100] ReadClient: 6 POST / HTTP/1.1
D [08/Aug/2005:10:47:06 +0100] ProcessIPPRequest: 6 status_code=1
D [08/Aug/2005:10:47:06 +0100] ReadClient: 6 POST / HTTP/1.1
D [08/Aug/2005:10:47:06 +0100] ProcessIPPRequest: 6 status_code=1
D [08/Aug/2005:10:47:06 +0100] ReadClient: 6 POST / HTTP/1.1
D [08/Aug/2005:10:47:06 +0100] ProcessIPPRequest: 6 status_code=1
D [08/Aug/2005:10:47:06 +0100] ReadClient: 6 POST / HTTP/1.1
D [08/Aug/2005:10:47:06 +0100] ProcessIPPRequest: 6 status_code=1
D [08/Aug/2005:10:47:06 +0100] CloseClient: 6
D [08/Aug/2005:10:47:23 +0100] AcceptClient: 6 from localhost:631.
D [08/Aug/2005:10:47:23 +0100] ReadClient: 6 POST / HTTP/1.1
D [08/Aug/2005:10:47:23 +0100] ProcessIPPRequest: 6 status_code=1
D [08/Aug/2005:10:47:23 +0100] ReadClient: 6 POST / HTTP/1.1
D [08/Aug/2005:10:47:23 +0100] ProcessIPPRequest: 6 status_code=1
D [08/Aug/2005:10:47:23 +0100] CloseClient: 6
D [08/Aug/2005:10:47:23 +0100] AcceptClient: 6 from localhost:631.
D [08/Aug/2005:10:47:23 +0100] ReadClient: 6 POST /printers/hp2 HTTP/1.1
D [08/Aug/2005:10:47:23 +0100] check_quotas: requesting-user-name = 'mn'
D [08/Aug/2005:10:47:23 +0100] create_job: requesting-user-name = 'mn'
I [08/Aug/2005:10:47:23 +0100] Job 5 created on 'hp2' by 'mn'.
D [08/Aug/2005:10:47:23 +0100] ProcessIPPRequest: 6 status_code=0
D [08/Aug/2005:10:47:23 +0100] ReadClient: 6 POST /printers/hp2 HTTP/1.1
D [08/Aug/2005:10:47:24 +0100] send_document: auto-typing file...
D [08/Aug/2005:10:47:24 +0100] send_document: request file type is text/plain.
I [08/Aug/2005:10:47:24 +0100] File of type text/plain queued in job #5 by 'mn'.
D [08/Aug/2005:10:47:24 +0100] ProcessIPPRequest: 6 status_code=0
D [08/Aug/2005:10:47:24 +0100] ReadClient: 6 POST /printers/hp2 HTTP/1.1
D [08/Aug/2005:10:47:24 +0100] send_document: auto-typing file...
D [08/Aug/2005:10:47:24 +0100] send_document: request file type is text/plain.
I [08/Aug/2005:10:47:24 +0100] File of type text/plain queued in job #5 by 'mn'.
D [08/Aug/2005:10:47:24 +0100] StartJob(5, 0x96ab2a0)
D [08/Aug/2005:10:47:24 +0100] StartJob() id = 5, file = 0/2
D [08/Aug/2005:10:47:24 +0100] StartJob: Sending job to queue tagged as raw...
D [08/Aug/2005:10:47:24 +0100] No job-sheets attribute.
D [08/Aug/2005:10:47:24 +0100] banner_page = 0
D [08/Aug/2005:10:47:24 +0100] StartJob: argv = "hp2","5","mn","long_term_tasks.txt","1","job-priority=50 job-hold-until=no-hold","/var/spool/cups/d00005-001"
D [08/Aug/2005:10:47:24 +0100] StartJob: envp[0]="PATH=/usr/lib/cups/filter:/bin:/usr/bin"
D [08/Aug/2005:10:47:24 +0100] StartJob: envp[1]="SOFTWARE=CUPS/1.1"
D [08/Aug/2005:10:47:24 +0100] StartJob: envp[2]="USER=root"
D [08/Aug/2005:10:47:24 +0100] StartJob: envp[3]="CHARSET=utf-8"
D [08/Aug/2005:10:47:24 +0100] StartJob: envp[4]="LANG=en_GB"
D [08/Aug/2005:10:47:24 +0100] StartJob: envp[5]="PPD=/etc/cups/ppd/hp2.ppd"
D [08/Aug/2005:10:47:24 +0100] StartJob: envp[6]="CUPS_SERVERROOT=/etc/cups"
D [08/Aug/2005:10:47:24 +0100] StartJob: envp[7]="RIP_MAX_CACHE=8m"
D [08/Aug/2005:10:47:24 +0100] StartJob: envp[8]="TMPDIR=/var/spool/cups/tmp"
D [08/Aug/2005:10:47:24 +0100] StartJob: envp[9]="CONTENT_TYPE=text/plain"
D [08/Aug/2005:10:47:24 +0100] StartJob: envp[10]="DEVICE_URI=ipp://s7.phyip3.dur.ac.uk:631/printers/hp2"
D [08/Aug/2005:10:47:24 +0100] StartJob: envp[11]="PRINTER=hp2"
D [08/Aug/2005:10:47:24 +0100] StartJob: envp[12]="CUPS_DATADIR=/usr/share/cups"
D [08/Aug/2005:10:47:24 +0100] StartJob: envp[13]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [08/Aug/2005:10:47:24 +0100] StartJob: envp[14]="CUPS_SERVER=localhost"
D [08/Aug/2005:10:47:24 +0100] StartJob: envp[15]="IPP_PORT=631"
D [08/Aug/2005:10:47:24 +0100] StartJob: statusfds = [ 8 9 ]
D [08/Aug/2005:10:47:24 +0100] StartJob: filterfds[1] = [ 10 -1 ]
D [08/Aug/2005:10:47:24 +0100] StartJob: backend = "/usr/lib/cups/backend/ipp"
D [08/Aug/2005:10:47:24 +0100] StartJob: filterfds[0] = [ -1 11 ]
D [08/Aug/2005:10:47:24 +0100] start_process("/usr/lib/cups/backend/ipp", 0xbff46130, 0xbff454a0, 10, 11, 9)
I [08/Aug/2005:10:47:24 +0100] Started backend /usr/lib/cups/backend/ipp (PID 23737) for job 5.
D [08/Aug/2005:10:47:24 +0100] ProcessIPPRequest: 6 status_code=0
D [08/Aug/2005:10:47:24 +0100] [Job 5] Getting supported attributes...
D [08/Aug/2005:10:47:24 +0100] [Job 5] document-format-supported (29 values)
D [08/Aug/2005:10:47:24 +0100] [Job 5] [0] = "application/pdf"
D [08/Aug/2005:10:47:24 +0100] [Job 5] [1] = "application/postscript"
D [08/Aug/2005:10:47:24 +0100] [Job 5] [2] = "application/vnd.cups-command"
D [08/Aug/2005:10:47:24 +0100] [Job 5] [3] = "application/vnd.cups-form"
D [08/Aug/2005:10:47:24 +0100] [Job 5] [4] = "application/vnd.cups-postscript"
D [08/Aug/2005:10:47:24 +0100] [Job 5] [5] = "application/vnd.cups-raster"
D [08/Aug/2005:10:47:24 +0100] [Job 5] [6] = "application/vnd.cups-raw"
D [08/Aug/2005:10:47:24 +0100] [Job 5] [7] = "application/vnd.hp-hpgl"
D [08/Aug/2005:10:47:24 +0100] [Job 5] [8] = "application/x-cshell"
D [08/Aug/2005:10:47:24 +0100] [Job 5] [9] = "application/x-perl"
D [08/Aug/2005:10:47:24 +0100] [Job 5] [10] = "application/x-shell"
D [08/Aug/2005:10:47:24 +0100] [Job 5] [11] = "image/gif"
D [08/Aug/2005:10:47:24 +0100] [Job 5] [12] = "image/jpeg"
D [08/Aug/2005:10:47:24 +0100] [Job 5] [13] = "image/png"
D [08/Aug/2005:10:47:24 +0100] [Job 5] [14] = "image/tiff"
D [08/Aug/2005:10:47:24 +0100] [Job 5] [15] = "image/x-alias"
D [08/Aug/2005:10:47:24 +0100] [Job 5] [16] = "image/x-bitmap"
D [08/Aug/2005:10:47:24 +0100] [Job 5] [17] = "image/x-photocd"
D [08/Aug/2005:10:47:24 +0100] [Job 5] [18] = "image/x-portable-anymap"
D [08/Aug/2005:10:47:24 +0100] [Job 5] [19] = "image/x-portable-bitmap"
D [08/Aug/2005:10:47:24 +0100] [Job 5] [20] = "image/x-portable-graymap"
D [08/Aug/2005:10:47:24 +0100] [Job 5] [21] = "image/x-portable-pixmap"
D [08/Aug/2005:10:47:24 +0100] [Job 5] [22] = "image/x-sgi-rgb"
D [08/Aug/2005:10:47:24 +0100] [Job 5] [23] = "image/x-sun-raster"
D [08/Aug/2005:10:47:24 +0100] [Job 5] [24] = "image/x-xbitmap"
D [08/Aug/2005:10:47:24 +0100] [Job 5] [25] = "image/x-xpixmap"
D [08/Aug/2005:10:47:24 +0100] [Job 5] [26] = "text/html"
D [08/Aug/2005:10:47:24 +0100] [Job 5] [27] = "text/plain"
D [08/Aug/2005:10:47:24 +0100] [Job 5] [28] = "application/octet-stream"
D [08/Aug/2005:10:47:24 +0100] [Job 5] printer-uri = "ipp://s7.phyip3.dur.ac.uk:631/printers/hp2"
D [08/Aug/2005:10:47:24 +0100] [Job 5] requesting-user-name = "mn"
D [08/Aug/2005:10:47:24 +0100] [Job 5] job-name = "long_term_tasks.txt"
D [08/Aug/2005:10:47:24 +0100] CloseClient: 6
D [08/Aug/2005:10:47:29 +0100] AcceptClient: 9 from localhost:631.
D [08/Aug/2005:10:47:29 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:29 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:29 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:29 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:29 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:29 +0100] ProcessIPPRequest: 9 status_code=0
D [08/Aug/2005:10:47:29 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:29 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:29 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:29 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:29 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:29 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:29 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:29 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:29 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:29 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:29 +0100] CloseClient: 9
D [08/Aug/2005:10:47:31 +0100] AcceptClient: 9 from localhost:631.
D [08/Aug/2005:10:47:31 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:31 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:31 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:31 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:31 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:31 +0100] ProcessIPPRequest: 9 status_code=0
D [08/Aug/2005:10:47:31 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:31 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:32 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:32 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:32 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:32 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:32 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:32 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:32 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:32 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:32 +0100] CloseClient: 9
D [08/Aug/2005:10:47:34 +0100] AcceptClient: 9 from localhost:631.
D [08/Aug/2005:10:47:34 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:34 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:34 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:34 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:34 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:34 +0100] ProcessIPPRequest: 9 status_code=0
D [08/Aug/2005:10:47:34 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:34 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:34 +0100] UpdateJob: job 5, file 0 is complete.
D [08/Aug/2005:10:47:34 +0100] StartJob(5, 0x96ab2a0)
D [08/Aug/2005:10:47:34 +0100] StartJob() id = 5, file = 1/2
D [08/Aug/2005:10:47:34 +0100] StartJob: Sending job to queue tagged as raw...
D [08/Aug/2005:10:47:34 +0100] No job-sheets attribute.
D [08/Aug/2005:10:47:34 +0100] banner_page = 0
D [08/Aug/2005:10:47:34 +0100] StartJob: argv = "hp2","5","mn","long_term_tasks.txt","1","job-priority=50 job-hold-until=no-hold","/var/spool/cups/d00005-002"
D [08/Aug/2005:10:47:34 +0100] StartJob: envp[0]="PATH=/usr/lib/cups/filter:/bin:/usr/bin"
D [08/Aug/2005:10:47:34 +0100] StartJob: envp[1]="SOFTWARE=CUPS/1.1"
D [08/Aug/2005:10:47:34 +0100] StartJob: envp[2]="USER=root"
D [08/Aug/2005:10:47:34 +0100] StartJob: envp[3]="CHARSET=utf-8"
D [08/Aug/2005:10:47:34 +0100] StartJob: envp[4]="LANG=en_GB"
D [08/Aug/2005:10:47:34 +0100] StartJob: envp[5]="PPD=/etc/cups/ppd/hp2.ppd"
D [08/Aug/2005:10:47:34 +0100] StartJob: envp[6]="CUPS_SERVERROOT=/etc/cups"
D [08/Aug/2005:10:47:34 +0100] StartJob: envp[7]="RIP_MAX_CACHE=8m"
D [08/Aug/2005:10:47:34 +0100] StartJob: envp[8]="TMPDIR=/var/spool/cups/tmp"
D [08/Aug/2005:10:47:34 +0100] StartJob: envp[9]="CONTENT_TYPE=text/plain"
D [08/Aug/2005:10:47:34 +0100] StartJob: envp[10]="DEVICE_URI=ipp://s7.phyip3.dur.ac.uk:631/printers/hp2"
D [08/Aug/2005:10:47:34 +0100] StartJob: envp[11]="PRINTER=hp2"
D [08/Aug/2005:10:47:34 +0100] StartJob: envp[12]="CUPS_DATADIR=/usr/share/cups"
D [08/Aug/2005:10:47:34 +0100] StartJob: envp[13]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [08/Aug/2005:10:47:34 +0100] StartJob: envp[14]="CUPS_SERVER=localhost"
D [08/Aug/2005:10:47:34 +0100] StartJob: envp[15]="IPP_PORT=631"
D [08/Aug/2005:10:47:34 +0100] StartJob: statusfds = [ 8 10 ]
D [08/Aug/2005:10:47:34 +0100] StartJob: filterfds[1] = [ 11 -1 ]
D [08/Aug/2005:10:47:34 +0100] StartJob: backend = "/usr/lib/cups/backend/ipp"
D [08/Aug/2005:10:47:34 +0100] StartJob: filterfds[0] = [ -1 12 ]
D [08/Aug/2005:10:47:34 +0100] start_process("/usr/lib/cups/backend/ipp", 0xbff54820, 0xbff53b90, 11, 12, 10)
I [08/Aug/2005:10:47:34 +0100] Started backend /usr/lib/cups/backend/ipp (PID 23742) for job 5.
D [08/Aug/2005:10:47:34 +0100] [Job 5] Getting supported attributes...
D [08/Aug/2005:10:47:34 +0100] [Job 5] document-format-supported (29 values)
D [08/Aug/2005:10:47:34 +0100] [Job 5] [0] = "application/pdf"
D [08/Aug/2005:10:47:34 +0100] [Job 5] [1] = "application/postscript"
D [08/Aug/2005:10:47:34 +0100] [Job 5] [2] = "application/vnd.cups-command"
D [08/Aug/2005:10:47:34 +0100] [Job 5] [3] = "application/vnd.cups-form"
D [08/Aug/2005:10:47:34 +0100] [Job 5] [4] = "application/vnd.cups-postscript"
D [08/Aug/2005:10:47:34 +0100] [Job 5] [5] = "application/vnd.cups-raster"
D [08/Aug/2005:10:47:34 +0100] [Job 5] [6] = "application/vnd.cups-raw"
D [08/Aug/2005:10:47:34 +0100] [Job 5] [7] = "application/vnd.hp-hpgl"
D [08/Aug/2005:10:47:34 +0100] [Job 5] [8] = "application/x-cshell"
D [08/Aug/2005:10:47:34 +0100] [Job 5] [9] = "application/x-perl"
D [08/Aug/2005:10:47:34 +0100] [Job 5] [10] = "application/x-shell"
D [08/Aug/2005:10:47:34 +0100] [Job 5] [11] = "image/gif"
D [08/Aug/2005:10:47:34 +0100] [Job 5] [12] = "image/jpeg"
D [08/Aug/2005:10:47:34 +0100] [Job 5] [13] = "image/png"
D [08/Aug/2005:10:47:34 +0100] [Job 5] [14] = "image/tiff"
D [08/Aug/2005:10:47:34 +0100] [Job 5] [15] = "image/x-alias"
D [08/Aug/2005:10:47:34 +0100] [Job 5] [16] = "image/x-bitmap"
D [08/Aug/2005:10:47:34 +0100] [Job 5] [17] = "image/x-photocd"
D [08/Aug/2005:10:47:34 +0100] [Job 5] [18] = "image/x-portable-anymap"
D [08/Aug/2005:10:47:34 +0100] [Job 5] [19] = "image/x-portable-bitmap"
D [08/Aug/2005:10:47:34 +0100] [Job 5] [20] = "image/x-portable-graymap"
D [08/Aug/2005:10:47:34 +0100] [Job 5] [21] = "image/x-portable-pixmap"
D [08/Aug/2005:10:47:34 +0100] [Job 5] [22] = "image/x-sgi-rgb"
D [08/Aug/2005:10:47:34 +0100] [Job 5] [23] = "image/x-sun-raster"
D [08/Aug/2005:10:47:34 +0100] [Job 5] [24] = "image/x-xbitmap"
D [08/Aug/2005:10:47:34 +0100] [Job 5] [25] = "image/x-xpixmap"
D [08/Aug/2005:10:47:34 +0100] [Job 5] [26] = "text/html"
D [08/Aug/2005:10:47:34 +0100] [Job 5] [27] = "text/plain"
D [08/Aug/2005:10:47:34 +0100] [Job 5] [28] = "application/octet-stream"
D [08/Aug/2005:10:47:34 +0100] [Job 5] printer-uri = "ipp://s7.phyip3.dur.ac.uk:631/printers/hp2"
D [08/Aug/2005:10:47:34 +0100] [Job 5] requesting-user-name = "mn"
D [08/Aug/2005:10:47:34 +0100] [Job 5] job-name = "long_term_tasks.txt"
D [08/Aug/2005:10:47:34 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:34 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:34 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:34 +0100] ProcessIPPRequest: 9 status_code=1
E [08/Aug/2005:10:47:34 +0100] [Job 5] Unable to get job 769 attributes (client-error-bad-request)!
D [08/Aug/2005:10:47:34 +0100] ReadClient: 9 POST / HTTP/1.1
E [08/Aug/2005:10:47:34 +0100] PID 23742 stopped with status 1!
D [08/Aug/2005:10:47:34 +0100] UpdateJob: job 5, file 1 is complete.
D [08/Aug/2005:10:47:34 +0100] StopJob: id = 5, force = 0
D [08/Aug/2005:10:47:34 +0100] StopJob: printer state is 3
D [08/Aug/2005:10:47:34 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:34 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:34 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:34 +0100] CloseClient: 9
D [08/Aug/2005:10:47:40 +0100] AcceptClient: 8 from localhost:631.
D [08/Aug/2005:10:47:40 +0100] ReadClient: 8 POST / HTTP/1.1
D [08/Aug/2005:10:47:40 +0100] ProcessIPPRequest: 8 status_code=1
D [08/Aug/2005:10:47:40 +0100] ReadClient: 8 POST / HTTP/1.1
D [08/Aug/2005:10:47:40 +0100] ProcessIPPRequest: 8 status_code=1
D [08/Aug/2005:10:47:40 +0100] ReadClient: 8 POST / HTTP/1.1
D [08/Aug/2005:10:47:40 +0100] ProcessIPPRequest: 8 status_code=0
D [08/Aug/2005:10:47:40 +0100] ReadClient: 8 POST / HTTP/1.1
D [08/Aug/2005:10:47:40 +0100] ProcessIPPRequest: 8 status_code=1
D [08/Aug/2005:10:47:40 +0100] ReadClient: 8 POST / HTTP/1.1
D [08/Aug/2005:10:47:40 +0100] ProcessIPPRequest: 8 status_code=1
D [08/Aug/2005:10:47:40 +0100] ReadClient: 8 POST / HTTP/1.1
D [08/Aug/2005:10:47:40 +0100] ProcessIPPRequest: 8 status_code=1
D [08/Aug/2005:10:47:40 +0100] ReadClient: 8 POST / HTTP/1.1
D [08/Aug/2005:10:47:40 +0100] ProcessIPPRequest: 8 status_code=1
D [08/Aug/2005:10:47:40 +0100] ReadClient: 8 POST / HTTP/1.1
D [08/Aug/2005:10:47:40 +0100] ProcessIPPRequest: 8 status_code=1
D [08/Aug/2005:10:47:40 +0100] CloseClient: 8
D [08/Aug/2005:10:47:42 +0100] AcceptClient: 8 from localhost:631.
D [08/Aug/2005:10:47:42 +0100] ReadClient: 8 POST / HTTP/1.1
D [08/Aug/2005:10:47:42 +0100] ProcessIPPRequest: 8 status_code=1
D [08/Aug/2005:10:47:42 +0100] ReadClient: 8 POST / HTTP/1.1
D [08/Aug/2005:10:47:42 +0100] ProcessIPPRequest: 8 status_code=1
D [08/Aug/2005:10:47:42 +0100] ReadClient: 8 POST / HTTP/1.1
D [08/Aug/2005:10:47:42 +0100] ProcessIPPRequest: 8 status_code=0
D [08/Aug/2005:10:47:42 +0100] ReadClient: 8 POST / HTTP/1.1
D [08/Aug/2005:10:47:42 +0100] ProcessIPPRequest: 8 status_code=1
D [08/Aug/2005:10:47:42 +0100] ReadClient: 8 POST / HTTP/1.1
D [08/Aug/2005:10:47:42 +0100] ProcessIPPRequest: 8 status_code=1
D [08/Aug/2005:10:47:42 +0100] ReadClient: 8 POST / HTTP/1.1
D [08/Aug/2005:10:47:42 +0100] ProcessIPPRequest: 8 status_code=1
D [08/Aug/2005:10:47:42 +0100] ReadClient: 8 POST / HTTP/1.1
D [08/Aug/2005:10:47:42 +0100] ProcessIPPRequest: 8 status_code=1
D [08/Aug/2005:10:47:42 +0100] ReadClient: 8 POST / HTTP/1.1
D [08/Aug/2005:10:47:42 +0100] ProcessIPPRequest: 8 status_code=1
D [08/Aug/2005:10:47:42 +0100] CloseClient: 8
D [08/Aug/2005:10:47:43 +0100] StartJob(5, 0x96ab2a0)
D [08/Aug/2005:10:47:43 +0100] StartJob() id = 5, file = 1/2
D [08/Aug/2005:10:47:43 +0100] StartJob: Sending job to queue tagged as raw...
D [08/Aug/2005:10:47:43 +0100] No job-sheets attribute.
D [08/Aug/2005:10:47:43 +0100] banner_page = 0
D [08/Aug/2005:10:47:43 +0100] StartJob: argv = "hp2","5","mn","long_term_tasks.txt","1","job-priority=50 job-hold-until=no-hold","/var/spool/cups/d00005-002"
D [08/Aug/2005:10:47:43 +0100] StartJob: envp[0]="PATH=/usr/lib/cups/filter:/bin:/usr/bin"
D [08/Aug/2005:10:47:43 +0100] StartJob: envp[1]="SOFTWARE=CUPS/1.1"
D [08/Aug/2005:10:47:43 +0100] StartJob: envp[2]="USER=root"
D [08/Aug/2005:10:47:43 +0100] StartJob: envp[3]="CHARSET=utf-8"
D [08/Aug/2005:10:47:43 +0100] StartJob: envp[4]="LANG=en_GB"
D [08/Aug/2005:10:47:43 +0100] StartJob: envp[5]="PPD=/etc/cups/ppd/hp2.ppd"
D [08/Aug/2005:10:47:43 +0100] StartJob: envp[6]="CUPS_SERVERROOT=/etc/cups"
D [08/Aug/2005:10:47:43 +0100] StartJob: envp[7]="RIP_MAX_CACHE=8m"
D [08/Aug/2005:10:47:43 +0100] StartJob: envp[8]="TMPDIR=/var/spool/cups/tmp"
D [08/Aug/2005:10:47:43 +0100] StartJob: envp[9]="CONTENT_TYPE=text/plain"
D [08/Aug/2005:10:47:43 +0100] StartJob: envp[10]="DEVICE_URI=ipp://s7.phyip3.dur.ac.uk:631/printers/hp2"
D [08/Aug/2005:10:47:43 +0100] StartJob: envp[11]="PRINTER=hp2"
D [08/Aug/2005:10:47:43 +0100] StartJob: envp[12]="CUPS_DATADIR=/usr/share/cups"
D [08/Aug/2005:10:47:43 +0100] StartJob: envp[13]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [08/Aug/2005:10:47:43 +0100] StartJob: envp[14]="CUPS_SERVER=localhost"
D [08/Aug/2005:10:47:43 +0100] StartJob: envp[15]="IPP_PORT=631"
D [08/Aug/2005:10:47:43 +0100] StartJob: statusfds = [ 8 9 ]
D [08/Aug/2005:10:47:43 +0100] StartJob: filterfds[1] = [ 10 -1 ]
D [08/Aug/2005:10:47:43 +0100] StartJob: backend = "/usr/lib/cups/backend/ipp"
D [08/Aug/2005:10:47:43 +0100] StartJob: filterfds[0] = [ -1 11 ]
D [08/Aug/2005:10:47:43 +0100] start_process("/usr/lib/cups/backend/ipp", 0xbff548b0, 0xbff53c20, 10, 11, 9)
I [08/Aug/2005:10:47:43 +0100] Started backend /usr/lib/cups/backend/ipp (PID 23748) for job 5.
D [08/Aug/2005:10:47:43 +0100] [Job 5] Getting supported attributes...
D [08/Aug/2005:10:47:43 +0100] [Job 5] document-format-supported (29 values)
D [08/Aug/2005:10:47:43 +0100] [Job 5] [0] = "application/pdf"
D [08/Aug/2005:10:47:43 +0100] [Job 5] [1] = "application/postscript"
D [08/Aug/2005:10:47:43 +0100] [Job 5] [2] = "application/vnd.cups-command"
D [08/Aug/2005:10:47:43 +0100] [Job 5] [3] = "application/vnd.cups-form"
D [08/Aug/2005:10:47:43 +0100] [Job 5] [4] = "application/vnd.cups-postscript"
D [08/Aug/2005:10:47:43 +0100] [Job 5] [5] = "application/vnd.cups-raster"
D [08/Aug/2005:10:47:43 +0100] [Job 5] [6] = "application/vnd.cups-raw"
D [08/Aug/2005:10:47:43 +0100] [Job 5] [7] = "application/vnd.hp-hpgl"
D [08/Aug/2005:10:47:43 +0100] [Job 5] [8] = "application/x-cshell"
D [08/Aug/2005:10:47:43 +0100] [Job 5] [9] = "application/x-perl"
D [08/Aug/2005:10:47:43 +0100] [Job 5] [10] = "application/x-shell"
D [08/Aug/2005:10:47:43 +0100] [Job 5] [11] = "image/gif"
D [08/Aug/2005:10:47:43 +0100] [Job 5] [12] = "image/jpeg"
D [08/Aug/2005:10:47:43 +0100] [Job 5] [13] = "image/png"
D [08/Aug/2005:10:47:43 +0100] [Job 5] [14] = "image/tiff"
D [08/Aug/2005:10:47:43 +0100] [Job 5] [15] = "image/x-alias"
D [08/Aug/2005:10:47:43 +0100] [Job 5] [16] = "image/x-bitmap"
D [08/Aug/2005:10:47:43 +0100] [Job 5] [17] = "image/x-photocd"
D [08/Aug/2005:10:47:43 +0100] [Job 5] [18] = "image/x-portable-anymap"
D [08/Aug/2005:10:47:43 +0100] [Job 5] [19] = "image/x-portable-bitmap"
D [08/Aug/2005:10:47:43 +0100] [Job 5] [20] = "image/x-portable-graymap"
D [08/Aug/2005:10:47:43 +0100] [Job 5] [21] = "image/x-portable-pixmap"
D [08/Aug/2005:10:47:43 +0100] [Job 5] [22] = "image/x-sgi-rgb"
D [08/Aug/2005:10:47:43 +0100] [Job 5] [23] = "image/x-sun-raster"
D [08/Aug/2005:10:47:43 +0100] [Job 5] [24] = "image/x-xbitmap"
D [08/Aug/2005:10:47:43 +0100] [Job 5] [25] = "image/x-xpixmap"
D [08/Aug/2005:10:47:43 +0100] [Job 5] [26] = "text/html"
D [08/Aug/2005:10:47:43 +0100] [Job 5] [27] = "text/plain"
D [08/Aug/2005:10:47:43 +0100] [Job 5] [28] = "application/octet-stream"
D [08/Aug/2005:10:47:43 +0100] [Job 5] printer-uri = "ipp://s7.phyip3.dur.ac.uk:631/printers/hp2"
D [08/Aug/2005:10:47:43 +0100] [Job 5] requesting-user-name = "mn"
D [08/Aug/2005:10:47:43 +0100] [Job 5] job-name = "long_term_tasks.txt"
D [08/Aug/2005:10:47:44 +0100] AcceptClient: 9 from localhost:631.
D [08/Aug/2005:10:47:44 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:44 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:44 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:44 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:44 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:44 +0100] ProcessIPPRequest: 9 status_code=0
D [08/Aug/2005:10:47:44 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:44 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:44 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:44 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:44 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:44 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:44 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:44 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:44 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:44 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:44 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:44 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:44 +0100] CloseClient: 9
D [08/Aug/2005:10:47:45 +0100] AcceptClient: 9 from localhost:631.
D [08/Aug/2005:10:47:45 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:45 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:45 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:45 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:45 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:45 +0100] ProcessIPPRequest: 9 status_code=0
D [08/Aug/2005:10:47:45 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:45 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:45 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:45 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:45 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:45 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:45 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:45 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:45 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:45 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:45 +0100] ReadClient: 9 POST / HTTP/1.1
D [08/Aug/2005:10:47:45 +0100] ProcessIPPRequest: 9 status_code=1
D [08/Aug/2005:10:47:45 +0100] CloseClient: 9
D [08/Aug/2005:10:47:54 +0100] UpdateJob: job 5, file 1 is complete.
D [08/Aug/2005:10:47:54 +0100] CancelJob: id = 5
D [08/Aug/2005:10:47:54 +0100] StopJob: id = 5, force = 0
D [08/Aug/2005:10:47:54 +0100] StopJob: printer state is 3
|