lpd backend stops with status 1
ariovist at r.lowa.shuttle.de
ariovist at r.lowa.shuttle.de
Mon Sep 27 13:32:33 PDT 2004
Hi Folks!
After updating to SuSE 9.1, CUPS(1.1.20-103) cannot print to remote lpd server.
I extracted a debug2 -sequence which shows the CUPS server start and one try to connect to the remote lpd-raw queue (no lines dropped). The lpd-daemon refuses the cups-backend request with lpd-error 47 and the backend stops with status 1. All previous steps seem to be O.K.
A TCP-dump of this connect-sequence shows returned data from lpd containing a string "Malformed." where I suppose CUPS does not speak lpd-protocol correctly. I tried several configurations with compatible printer models, but the behaviour is always the same.
Thanks in advance for your Help
I [27/Sep/2004:21:38:36 +0200] Listening to 0:631
D [27/Sep/2004:21:38:36 +0200] AddLocation: added location 'CUPS_INTERNAL_BROWSE_ACL'
D [27/Sep/2004:21:38:36 +0200] AllowHost: CUPS_INTERNAL_BROWSE_ACL allow @LOCAL
D [27/Sep/2004:21:38:36 +0200] DenyIP: CUPS_INTERNAL_BROWSE_ACL deny 00000000/00000000
D [27/Sep/2004:21:38:36 +0200] AddLocation: added location '/'
D [27/Sep/2004:21:38:36 +0200] DenyIP: / deny 00000000/00000000
D [27/Sep/2004:21:38:36 +0200] AllowIP: / allow 7f000001/ffffffff
D [27/Sep/2004:21:38:36 +0200] AllowIP: / allow 7f000002/ffffffff
D [27/Sep/2004:21:38:36 +0200] AllowHost: / allow @LOCAL
D [27/Sep/2004:21:38:36 +0200] AddLocation: added location '/admin'
D [27/Sep/2004:21:38:36 +0200] DenyIP: /admin deny 00000000/00000000
D [27/Sep/2004:21:38:36 +0200] AllowIP: /admin allow 7f000001/ffffffff
I [27/Sep/2004:21:38:36 +0200] Loaded configuration file "/etc/cups/cupsd.conf"
I [27/Sep/2004:21:38:36 +0200] Configured for up to 100 clients.
I [27/Sep/2004:21:38:36 +0200] Allowing up to 100 client connections per host.
I [27/Sep/2004:21:38:36 +0200] Full reload is required.
D [27/Sep/2004:21:38:36 +0200] LoadAllPrinters: Loading printer lp0...
d [27/Sep/2004:21:38:36 +0200] AddPrinter("lp0")
d [27/Sep/2004:21:38:36 +0200] Adding filter application/vnd.cups-raw printer/lp0 0 -
d [27/Sep/2004:21:38:36 +0200] FindBest: uri = "/printers/lp0"...
d [27/Sep/2004:21:38:36 +0200] FindBest: Location CUPS_INTERNAL_BROWSE_ACL Limit 0
d [27/Sep/2004:21:38:36 +0200] FindBest: Location / Limit 7f
d [27/Sep/2004:21:38:36 +0200] FindBest: Location /admin Limit 7f
d [27/Sep/2004:21:38:36 +0200] FindBest: best = "/"
d [27/Sep/2004:21:38:36 +0200] Adding filter application/vnd.cups-postscript printer/lp0 0 foomatic-rip
D [27/Sep/2004:21:38:36 +0200] LoadAllPrinters: Loading printer lp1...
d [27/Sep/2004:21:38:36 +0200] AddPrinter("lp1")
d [27/Sep/2004:21:38:36 +0200] Adding filter application/vnd.cups-raw printer/lp1 0 -
d [27/Sep/2004:21:38:36 +0200] FindBest: uri = "/printers/lp1"...
d [27/Sep/2004:21:38:36 +0200] FindBest: Location CUPS_INTERNAL_BROWSE_ACL Limit 0
d [27/Sep/2004:21:38:36 +0200] FindBest: Location / Limit 7f
d [27/Sep/2004:21:38:36 +0200] FindBest: Location /admin Limit 7f
d [27/Sep/2004:21:38:36 +0200] FindBest: best = "/"
d [27/Sep/2004:21:38:36 +0200] Adding filter application/vnd.cups-postscript printer/lp1 0 foomatic-rip
D [27/Sep/2004:21:38:36 +0200] LoadAllPrinters: Loading printer lpdj...
d [27/Sep/2004:21:38:36 +0200] AddPrinter("lpdj")
d [27/Sep/2004:21:38:36 +0200] Adding filter application/vnd.cups-raw printer/lpdj 0 -
d [27/Sep/2004:21:38:36 +0200] FindBest: uri = "/printers/lpdj"...
d [27/Sep/2004:21:38:36 +0200] FindBest: Location CUPS_INTERNAL_BROWSE_ACL Limit 0
d [27/Sep/2004:21:38:36 +0200] FindBest: Location / Limit 7f
d [27/Sep/2004:21:38:36 +0200] FindBest: Location /admin Limit 7f
d [27/Sep/2004:21:38:36 +0200] FindBest: best = "/"
d [27/Sep/2004:21:38:36 +0200] Adding filter application/vnd.cups-raster printer/lpdj 100 rastertoprinter
D [27/Sep/2004:21:38:36 +0200] LoadDevices: Added device "parallel:/dev/lp0"...
D [27/Sep/2004:21:38:36 +0200] LoadDevices: Added device "http"...
D [27/Sep/2004:21:38:36 +0200] LoadDevices: Added device "ipp"...
D [27/Sep/2004:21:38:36 +0200] LoadDevices: Added device "lpd"...
D [27/Sep/2004:21:38:36 +0200] LoadDevices: Added device "novell"...
D [27/Sep/2004:21:38:36 +0200] LoadDevices: Added device "pipe"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "scsi"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "smb"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "serial:/dev/ttyS0?baud=115200"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "serial:/dev/ttyS1?baud=115200"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "serial:/dev/ttyS2?baud=115200"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "serial:/dev/ttyS3?baud=115200"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "serial:/dev/ttyS4?baud=115200"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "serial:/dev/ttyS5?baud=115200"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "serial:/dev/ttyS6?baud=115200"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "serial:/dev/ttyS7?baud=115200"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "serial:/dev/ttyS8?baud=115200"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "serial:/dev/ttyS9?baud=115200"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "serial:/dev/ttyS10?baud=115200"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "serial:/dev/ttyS11?baud=115200"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "serial:/dev/ttyS12?baud=115200"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "serial:/dev/ttyS13?baud=115200"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "serial:/dev/ttyS14?baud=115200"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "serial:/dev/ttyS15?baud=115200"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "serial:/dev/ttyS16?baud=115200"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "serial:/dev/ttyS17?baud=115200"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "serial:/dev/ttyS18?baud=115200"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "serial:/dev/ttyS19?baud=115200"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "serial:/dev/ttyS20?baud=115200"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "serial:/dev/ttyS21?baud=115200"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "serial:/dev/ttyS22?baud=115200"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "serial:/dev/ttyS23?baud=115200"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "socket"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "usb:/dev/usb/lp0"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "usb:/dev/usb/lp1"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "usb:/dev/usb/lp2"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "usb:/dev/usb/lp3"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "usb:/dev/usb/lp4"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "usb:/dev/usb/lp5"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "usb:/dev/usb/lp6"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "usb:/dev/usb/lp7"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "usb:/dev/usb/lp8"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "usb:/dev/usb/lp9"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "usb:/dev/usb/lp10"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "usb:/dev/usb/lp11"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "usb:/dev/usb/lp12"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "usb:/dev/usb/lp13"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "usb:/dev/usb/lp14"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "usb:/dev/usb/lp15"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "canon:/dev/lp0"...
D [27/Sep/2004:21:38:37 +0200] LoadDevices: Added device "epson:/dev/lp0"...
I [27/Sep/2004:21:38:37 +0200] LoadPPDs: Read "/etc/cups/ppds.dat", 3593 PPDs...
I [27/Sep/2004:21:38:37 +0200] LoadPPDs: No new or changed PPDs...
D [27/Sep/2004:21:38:37 +0200] LoadAllJobs: Scanning /var/spool/cups...
D [27/Sep/2004:21:38:37 +0200] LoadAllJobs: Loading attributes for job 1...
D [27/Sep/2004:21:38:37 +0200] LoadAllJobs: Loading attributes for job 4...
D [27/Sep/2004:21:38:37 +0200] LoadAllJobs: Loading attributes for job 2...
D [27/Sep/2004:21:38:37 +0200] LoadAllJobs: Auto-typing document file d00004-001...
I [27/Sep/2004:21:38:37 +0200] Full reload complete.
D [27/Sep/2004:21:38:37 +0200] StartListening: NumListeners=1
D [27/Sep/2004:21:38:37 +0200] StartListening: address=00000000 port=631
D [27/Sep/2004:21:38:37 +0200] ResumeListening: setting input bits...
d [27/Sep/2004:21:38:37 +0200] ResumeListening: Adding fd 0 to InputSet...
d [27/Sep/2004:21:38:37 +0200] StartBrowsing: Adding fd 2 to InputSet...
d [27/Sep/2004:21:38:37 +0200] StartServer: Adding fd 3 to InputSet...
d [27/Sep/2004:21:38:37 +0200] AddCert: adding certificate for pid 0
d [27/Sep/2004:21:39:59 +0200] AcceptClient(lis=0x808b770) 0 NumClients = 0
D [27/Sep/2004:21:39:59 +0200] AcceptClient: 9 from localhost:631.
d [27/Sep/2004:21:39:59 +0200] AcceptClient: Adding fd 9 to InputSet...
d [27/Sep/2004:21:39:59 +0200] ReadClient() 9, used=0, file=-1
D [27/Sep/2004:21:39:59 +0200] ReadClient() 9 GET /printers HTTP/1.1
d [27/Sep/2004:21:39:59 +0200] decode_auth(0x4038c008): Authorization string = "Basic cm9vdDpDaGlsZGVyaWNoMQ=="
d [27/Sep/2004:21:39:59 +0200] decode_auth() 9 username="root"
d [27/Sep/2004:21:39:59 +0200] IsAuthorized: con->uri = "/printers"
d [27/Sep/2004:21:39:59 +0200] FindBest: uri = "/printers"...
d [27/Sep/2004:21:39:59 +0200] FindBest: Location CUPS_INTERNAL_BROWSE_ACL Limit 0
d [27/Sep/2004:21:39:59 +0200] FindBest: Location / Limit 7f
d [27/Sep/2004:21:39:59 +0200] FindBest: Location /admin Limit 7f
d [27/Sep/2004:21:39:59 +0200] FindBest: best = "/"
d [27/Sep/2004:21:39:59 +0200] IsAuthorized: auth = 0, satisfy=0...
d [27/Sep/2004:21:39:59 +0200] argv[0] = "printers.cgi"
d [27/Sep/2004:21:39:59 +0200] envp[0] = "PATH=/bin:/usr/bin"
d [27/Sep/2004:21:39:59 +0200] envp[1] = "SERVER_SOFTWARE=CUPS/1.1"
d [27/Sep/2004:21:39:59 +0200] envp[2] = "GATEWAY_INTERFACE=CGI/1.1"
d [27/Sep/2004:21:39:59 +0200] envp[3] = "SERVER_PROTOCOL=HTTP/1.1"
d [27/Sep/2004:21:39:59 +0200] envp[4] = "REDIRECT_STATUS=1"
d [27/Sep/2004:21:39:59 +0200] envp[5] = "CUPS_SERVER=localhost"
d [27/Sep/2004:21:39:59 +0200] envp[6] = "IPP_PORT=631"
d [27/Sep/2004:21:39:59 +0200] envp[7] = "SERVER_NAME=localhost"
d [27/Sep/2004:21:39:59 +0200] envp[8] = "SERVER_PORT=631"
d [27/Sep/2004:21:39:59 +0200] envp[9] = "REMOTE_ADDR=127.0.0.1"
d [27/Sep/2004:21:39:59 +0200] envp[10] = "REMOTE_HOST=localhost"
d [27/Sep/2004:21:39:59 +0200] envp[11] = "REMOTE_USER=root"
d [27/Sep/2004:21:39:59 +0200] envp[12] = "LANG=de.UTF-8"
d [27/Sep/2004:21:39:59 +0200] envp[13] = ""
d [27/Sep/2004:21:39:59 +0200] envp[14] = "TMPDIR=/var/spool/cups/tmp"
d [27/Sep/2004:21:39:59 +0200] envp[15] = "CUPS_DATADIR=/usr/share/cups"
d [27/Sep/2004:21:39:59 +0200] envp[16] = "CUPS_SERVERROOT=/etc/cups"
d [27/Sep/2004:21:39:59 +0200] envp[17] = "HTTP_USER_AGENT=Mozilla/5.0 (compatible; Konqueror/3.2; Linux) (KHTML, like Gecko)"
d [27/Sep/2004:21:39:59 +0200] envp[18] = "SCRIPT_NAME=/printers"
d [27/Sep/2004:21:39:59 +0200] envp[19] = "REQUEST_METHOD=GET"
d [27/Sep/2004:21:39:59 +0200] AddCert: adding certificate for pid 5953
D [27/Sep/2004:21:39:59 +0200] CGI /usr/lib/cups/cgi-bin/printers.cgi started - PID = 5953
I [27/Sep/2004:21:39:59 +0200] Started "/usr/lib/cups/cgi-bin/printers.cgi" (pid=5953)
D [27/Sep/2004:21:39:59 +0200] SendCommand: 9 file=11
d [27/Sep/2004:21:39:59 +0200] SendCommand: Adding fd 11 to InputSet...
d [27/Sep/2004:21:39:59 +0200] SendCommand: Adding fd 9 to OutputSet...
d [27/Sep/2004:21:39:59 +0200] AcceptClient(lis=0x808b770) 0 NumClients = 1
D [27/Sep/2004:21:39:59 +0200] AcceptClient: 14 from localhost:631.
d [27/Sep/2004:21:39:59 +0200] AcceptClient: Adding fd 14 to InputSet...
d [27/Sep/2004:21:39:59 +0200] WriteClient: 9 Content-Type: text/html;charset=utf-8
d [27/Sep/2004:21:39:59 +0200] WriteClient: 9
d [27/Sep/2004:21:39:59 +0200] WriteClient: 9 1174 bytes
d [27/Sep/2004:21:39:59 +0200] ReadClient() 14, used=0, file=-1
D [27/Sep/2004:21:39:59 +0200] ReadClient() 14 POST / HTTP/1.1
d [27/Sep/2004:21:39:59 +0200] decode_auth(0x4038ec3c): Authorization string = ""
d [27/Sep/2004:21:39:59 +0200] decode_auth() 14 username=""
d [27/Sep/2004:21:39:59 +0200] IsAuthorized: con->uri = "/"
d [27/Sep/2004:21:39:59 +0200] FindBest: uri = "/"...
d [27/Sep/2004:21:39:59 +0200] FindBest: Location CUPS_INTERNAL_BROWSE_ACL Limit 0
d [27/Sep/2004:21:39:59 +0200] FindBest: Location / Limit 7f
d [27/Sep/2004:21:39:59 +0200] FindBest: Location /admin Limit 7f
d [27/Sep/2004:21:39:59 +0200] FindBest: best = "/"
d [27/Sep/2004:21:39:59 +0200] IsAuthorized: auth = 0, satisfy=0...
d [27/Sep/2004:21:39:59 +0200] POST /
d [27/Sep/2004:21:39:59 +0200] CONTENT_TYPE = application/ipp
d [27/Sep/2004:21:39:59 +0200] ReadClient() 14 con->data_encoding = length, con->data_remaining = 135, con->file = -1
d [27/Sep/2004:21:39:59 +0200] ReadClient() 14, used=0, file=-1
d [27/Sep/2004:21:39:59 +0200] ReadClient() 14 con->data_encoding = length, con->data_remaining = 127, con->file = -1
d [27/Sep/2004:21:39:59 +0200] ReadClient() 14, used=98, file=-1
d [27/Sep/2004:21:39:59 +0200] ReadClient() 14 con->data_encoding = length, con->data_remaining = 98, con->file = -1
d [27/Sep/2004:21:39:59 +0200] ProcessIPPRequest(0x4038ec3c[14]): operation_id = 4001
d [27/Sep/2004:21:39:59 +0200] get_default(0x4038ec3c[14])
d [27/Sep/2004:21:39:59 +0200] copy_attrs(0x8216c10, 0x80955c8, 0x8216b28, 0)
d [27/Sep/2004:21:39:59 +0200] copy_attribute(0x8216c10, 0x80955f0[printer-uri-supported,4,45])
d [27/Sep/2004:21:39:59 +0200] copy_attribute(0x8216c10, 0x8095728[printer-name,4,42])
d [27/Sep/2004:21:39:59 +0200] copy_attrs(0x8216c10, 0x80950d0, 0x8216b28, 0)
D [27/Sep/2004:21:39:59 +0200] ProcessIPPRequest: 14 status_code=1
d [27/Sep/2004:21:39:59 +0200] ProcessIPPRequest: Adding fd 14 to OutputSet...
d [27/Sep/2004:21:39:59 +0200] WriteClient: Removing fd 14 from OutputSet...
d [27/Sep/2004:21:39:59 +0200] ReadClient() 14, used=0, file=-1
D [27/Sep/2004:21:39:59 +0200] ReadClient() 14 POST / HTTP/1.1
d [27/Sep/2004:21:39:59 +0200] decode_auth(0x4038ec3c): Authorization string = ""
d [27/Sep/2004:21:39:59 +0200] decode_auth() 14 username=""
d [27/Sep/2004:21:39:59 +0200] IsAuthorized: con->uri = "/"
d [27/Sep/2004:21:39:59 +0200] FindBest: uri = "/"...
d [27/Sep/2004:21:39:59 +0200] FindBest: Location CUPS_INTERNAL_BROWSE_ACL Limit 0
d [27/Sep/2004:21:39:59 +0200] FindBest: Location / Limit 7f
d [27/Sep/2004:21:39:59 +0200] FindBest: Location /admin Limit 7f
d [27/Sep/2004:21:39:59 +0200] FindBest: best = "/"
d [27/Sep/2004:21:39:59 +0200] IsAuthorized: auth = 0, satisfy=0...
d [27/Sep/2004:21:39:59 +0200] POST /
d [27/Sep/2004:21:39:59 +0200] CONTENT_TYPE = application/ipp
d [27/Sep/2004:21:39:59 +0200] ReadClient() 14 con->data_encoding = length, con->data_remaining = 811, con->file = -1
d [27/Sep/2004:21:39:59 +0200] ProcessIPPRequest(0x4038ec3c[14]): operation_id = 4002
d [27/Sep/2004:21:39:59 +0200] get_printers(0x4038ec3c[14], 0)
d [27/Sep/2004:21:39:59 +0200] add_printer_state_reasons(0x4038ec3c[14], 0x8097c88[lp0])
d [27/Sep/2004:21:39:59 +0200] add_queued_job_count(0x4038ec3c[14], 0x8097c88[lp0])
d [27/Sep/2004:21:39:59 +0200] copy_attrs(0x8216d50, 0x80955c8, 0x8217070, 0)
d [27/Sep/2004:21:39:59 +0200] copy_attribute(0x8216d50, 0x80955f0[printer-uri-supported,4,45])
d [27/Sep/2004:21:39:59 +0200] copy_attribute(0x8216d50, 0x8095728[printer-name,4,42])
d [27/Sep/2004:21:39:59 +0200] copy_attribute(0x8216d50, 0x8095778[printer-location,4,41])
d [27/Sep/2004:21:39:59 +0200] copy_attribute(0x8216d50, 0x80957c8[printer-info,4,41])
d [27/Sep/2004:21:39:59 +0200] copy_attribute(0x8216d50, 0x80959a0[device-uri,4,45])
d [27/Sep/2004:21:39:59 +0200] copy_attribute(0x8216d50, 0x80a79b8[printer-make-and-model,4,41])
d [27/Sep/2004:21:39:59 +0200] copy_attrs(0x8216d50, 0x80950d0, 0x8217070, 0)
d [27/Sep/2004:21:39:59 +0200] add_printer_state_reasons(0x4038ec3c[14], 0x80a5dd8[lp1])
d [27/Sep/2004:21:39:59 +0200] add_queued_job_count(0x4038ec3c[14], 0x80a5dd8[lp1])
d [27/Sep/2004:21:39:59 +0200] copy_attrs(0x8216d50, 0x809bae8, 0x8217070, 0)
d [27/Sep/2004:21:39:59 +0200] copy_attribute(0x8216d50, 0x809bb10[printer-uri-supported,4,45])
d [27/Sep/2004:21:39:59 +0200] copy_attribute(0x8216d50, 0x809bce0[printer-name,4,42])
d [27/Sep/2004:21:39:59 +0200] copy_attribute(0x8216d50, 0x8095b68[printer-location,4,41])
d [27/Sep/2004:21:39:59 +0200] copy_attribute(0x8216d50, 0x8095ba0[printer-info,4,41])
d [27/Sep/2004:21:39:59 +0200] copy_attribute(0x8216d50, 0x80a7608[device-uri,4,45])
d [27/Sep/2004:21:39:59 +0200] copy_attribute(0x8216d50, 0x80a8b78[printer-make-and-model,4,41])
d [27/Sep/2004:21:39:59 +0200] copy_attrs(0x8216d50, 0x80950d0, 0x8217070, 0)
d [27/Sep/2004:21:39:59 +0200] add_printer_state_reasons(0x4038ec3c[14], 0x80a62a8[lpdj])
d [27/Sep/2004:21:39:59 +0200] add_queued_job_count(0x4038ec3c[14], 0x80a62a8[lpdj])
d [27/Sep/2004:21:39:59 +0200] copy_attrs(0x8216d50, 0x808c838, 0x8217070, 0)
d [27/Sep/2004:21:39:59 +0200] copy_attribute(0x8216d50, 0x80975c0[printer-uri-supported,4,45])
d [27/Sep/2004:21:39:59 +0200] copy_attribute(0x8216d50, 0x80a6ad8[printer-name,4,42])
d [27/Sep/2004:21:39:59 +0200] copy_attribute(0x8216d50, 0x80a6b28[printer-location,4,41])
d [27/Sep/2004:21:39:59 +0200] copy_attribute(0x8216d50, 0x8097a78[printer-info,4,41])
d [27/Sep/2004:21:39:59 +0200] copy_attribute(0x8216d50, 0x80a3348[device-uri,4,45])
d [27/Sep/2004:21:39:59 +0200] copy_attribute(0x8216d50, 0x80a1a38[printer-make-and-model,4,41])
d [27/Sep/2004:21:39:59 +0200] copy_attrs(0x8216d50, 0x80950d0, 0x8217070, 0)
D [27/Sep/2004:21:39:59 +0200] ProcessIPPRequest: 14 status_code=1
d [27/Sep/2004:21:39:59 +0200] ProcessIPPRequest: Adding fd 14 to OutputSet...
d [27/Sep/2004:21:39:59 +0200] WriteClient: Removing fd 14 from OutputSet...
d [27/Sep/2004:21:39:59 +0200] PID 5953 exited with no errors.
d [27/Sep/2004:21:39:59 +0200] DeleteCert: removing certificate for pid 5953
d [27/Sep/2004:21:39:59 +0200] ReadClient() 14, used=0, file=-1
d [27/Sep/2004:21:39:59 +0200] ReadClient: httpGets returned EOF...
D [27/Sep/2004:21:39:59 +0200] CloseClient() 14
d [27/Sep/2004:21:39:59 +0200] CloseClient: Removing fd 14 from InputSet and OutputSet...
d [27/Sep/2004:21:39:59 +0200] WriteClient: Removing fd 9 from OutputSet...
d [27/Sep/2004:21:39:59 +0200] WriteClient: Removing fd 11 from InputSet...
d [27/Sep/2004:21:39:59 +0200] WriteClient: 9 Closing data file 11.
d [27/Sep/2004:21:40:04 +0200] ReadClient() 9, used=0, file=-1
d [27/Sep/2004:21:40:04 +0200] ReadClient: httpGets returned EOF...
D [27/Sep/2004:21:40:04 +0200] CloseClient() 9
d [27/Sep/2004:21:40:04 +0200] CloseClient: Removing fd 9 from InputSet and OutputSet...
d [27/Sep/2004:21:40:04 +0200] AcceptClient(lis=0x808b770) 0 NumClients = 0
D [27/Sep/2004:21:40:04 +0200] AcceptClient: 9 from localhost:631.
d [27/Sep/2004:21:40:04 +0200] AcceptClient: Adding fd 9 to InputSet...
d [27/Sep/2004:21:40:04 +0200] ReadClient() 9, used=0, file=-1
D [27/Sep/2004:21:40:04 +0200] ReadClient() 9 GET /admin/?op=start-printer&printer_name=lp1 HTTP/1.1
d [27/Sep/2004:21:40:04 +0200] decode_auth(0x4038c008): Authorization string = "Basic cm9vdDpDaGlsZGVyaWNoMQ=="
d [27/Sep/2004:21:40:04 +0200] decode_auth() 9 username="root"
d [27/Sep/2004:21:40:04 +0200] IsAuthorized: con->uri = "/admin/?op=start-printer&printer_name=lp1"
d [27/Sep/2004:21:40:04 +0200] FindBest: uri = "/admin/?op=start-printer&printer_name=lp1"...
d [27/Sep/2004:21:40:04 +0200] FindBest: Location CUPS_INTERNAL_BROWSE_ACL Limit 0
d [27/Sep/2004:21:40:04 +0200] FindBest: Location / Limit 7f
d [27/Sep/2004:21:40:04 +0200] FindBest: Location /admin Limit 7f
d [27/Sep/2004:21:40:04 +0200] FindBest: best = "/admin"
d [27/Sep/2004:21:40:04 +0200] IsAuthorized: auth = 0, satisfy=0...
d [27/Sep/2004:21:40:04 +0200] IsAuthorized: username = "root" password = 11 chars
d [27/Sep/2004:21:40:04 +0200] IsAuthorized: Checking "root", address = 7f000001, hostname = "localhost"
d [27/Sep/2004:21:40:04 +0200] IsAuthorized: num_names = 1
d [27/Sep/2004:21:40:04 +0200] GetMD5Passwd(username="root", group="sys", passwd=0xbfff02f0)
d [27/Sep/2004:21:40:04 +0200] Found MD5 user root, group sys...
d [27/Sep/2004:21:40:04 +0200] argv[0] = ""
d [27/Sep/2004:21:40:04 +0200] envp[0] = "PATH=/bin:/usr/bin"
d [27/Sep/2004:21:40:04 +0200] envp[1] = "SERVER_SOFTWARE=CUPS/1.1"
d [27/Sep/2004:21:40:04 +0200] envp[2] = "GATEWAY_INTERFACE=CGI/1.1"
d [27/Sep/2004:21:40:04 +0200] envp[3] = "SERVER_PROTOCOL=HTTP/1.1"
d [27/Sep/2004:21:40:04 +0200] envp[4] = "REDIRECT_STATUS=1"
d [27/Sep/2004:21:40:04 +0200] envp[5] = "CUPS_SERVER=localhost"
d [27/Sep/2004:21:40:04 +0200] envp[6] = "IPP_PORT=631"
d [27/Sep/2004:21:40:04 +0200] envp[7] = "SERVER_NAME=localhost"
d [27/Sep/2004:21:40:04 +0200] envp[8] = "SERVER_PORT=631"
d [27/Sep/2004:21:40:04 +0200] envp[9] = "REMOTE_ADDR=127.0.0.1"
d [27/Sep/2004:21:40:04 +0200] envp[10] = "REMOTE_HOST=localhost"
d [27/Sep/2004:21:40:04 +0200] envp[11] = "REMOTE_USER=root"
d [27/Sep/2004:21:40:04 +0200] envp[12] = "LANG=de.UTF-8"
d [27/Sep/2004:21:40:04 +0200] envp[13] = ""
d [27/Sep/2004:21:40:04 +0200] envp[14] = "TMPDIR=/var/spool/cups/tmp"
d [27/Sep/2004:21:40:04 +0200] envp[15] = "CUPS_DATADIR=/usr/share/cups"
d [27/Sep/2004:21:40:04 +0200] envp[16] = "CUPS_SERVERROOT=/etc/cups"
d [27/Sep/2004:21:40:04 +0200] envp[17] = "HTTP_USER_AGENT=Mozilla/5.0 (compatible; Konqueror/3.2; Linux) (KHTML, like Gecko)"
d [27/Sep/2004:21:40:04 +0200] envp[18] = "SCRIPT_NAME=/admin/"
d [27/Sep/2004:21:40:04 +0200] envp[19] = "REQUEST_METHOD=GET"
d [27/Sep/2004:21:40:04 +0200] envp[20] = "QUERY_STRING=op=start-printer&printer_name=lp1"
d [27/Sep/2004:21:40:04 +0200] AddCert: adding certificate for pid 5954
D [27/Sep/2004:21:40:04 +0200] CGI /usr/lib/cups/cgi-bin/admin.cgi started - PID = 5954
I [27/Sep/2004:21:40:04 +0200] Started "/usr/lib/cups/cgi-bin/admin.cgi" (pid=5954)
D [27/Sep/2004:21:40:04 +0200] SendCommand: 9 file=14
d [27/Sep/2004:21:40:04 +0200] SendCommand: Adding fd 14 to InputSet...
d [27/Sep/2004:21:40:04 +0200] SendCommand: Adding fd 9 to OutputSet...
d [27/Sep/2004:21:40:04 +0200] WriteClient: 9 Content-Type: text/html;charset=utf-8
d [27/Sep/2004:21:40:04 +0200] WriteClient: 9
d [27/Sep/2004:21:40:04 +0200] WriteClient: 9 1170 bytes
d [27/Sep/2004:21:40:04 +0200] AcceptClient(lis=0x808b770) 0 NumClients = 1
D [27/Sep/2004:21:40:04 +0200] AcceptClient: 11 from localhost:631.
d [27/Sep/2004:21:40:04 +0200] AcceptClient: Adding fd 11 to InputSet...
d [27/Sep/2004:21:40:04 +0200] ReadClient() 11, used=0, file=-1
D [27/Sep/2004:21:40:04 +0200] ReadClient() 11 POST /admin/ HTTP/1.1
d [27/Sep/2004:21:40:04 +0200] decode_auth(0x4038ec3c): Authorization string = ""
d [27/Sep/2004:21:40:04 +0200] decode_auth() 11 username=""
d [27/Sep/2004:21:40:04 +0200] IsAuthorized: con->uri = "/admin/"
d [27/Sep/2004:21:40:04 +0200] FindBest: uri = "/admin/"...
d [27/Sep/2004:21:40:04 +0200] FindBest: Location CUPS_INTERNAL_BROWSE_ACL Limit 0
d [27/Sep/2004:21:40:04 +0200] FindBest: Location / Limit 7f
d [27/Sep/2004:21:40:04 +0200] FindBest: Location /admin Limit 7f
d [27/Sep/2004:21:40:04 +0200] FindBest: best = "/admin"
d [27/Sep/2004:21:40:04 +0200] IsAuthorized: auth = 0, satisfy=0...
d [27/Sep/2004:21:40:04 +0200] IsAuthorized: username = "" password = 0 chars
d [27/Sep/2004:21:40:04 +0200] ReadClient: Unauthorized request for /admin/...
D [27/Sep/2004:21:40:04 +0200] SendError() 11 code=401 (Unauthorized)
d [27/Sep/2004:21:40:04 +0200] FindBest: uri = "/admin/"...
d [27/Sep/2004:21:40:04 +0200] FindBest: Location CUPS_INTERNAL_BROWSE_ACL Limit 0
d [27/Sep/2004:21:40:04 +0200] FindBest: Location / Limit 7f
d [27/Sep/2004:21:40:04 +0200] FindBest: Location /admin Limit 7f
d [27/Sep/2004:21:40:04 +0200] FindBest: best = "/admin"
D [27/Sep/2004:21:40:04 +0200] CloseClient() 11
d [27/Sep/2004:21:40:04 +0200] CloseClient: Removing fd 11 from InputSet and OutputSet...
d [27/Sep/2004:21:40:04 +0200] AcceptClient(lis=0x808b770) 0 NumClients = 1
D [27/Sep/2004:21:40:04 +0200] AcceptClient: 11 from localhost:631.
d [27/Sep/2004:21:40:04 +0200] AcceptClient: Adding fd 11 to InputSet...
d [27/Sep/2004:21:40:04 +0200] ReadClient() 11, used=0, file=-1
D [27/Sep/2004:21:40:04 +0200] ReadClient() 11 POST /admin/ HTTP/1.1
d [27/Sep/2004:21:40:04 +0200] decode_auth(0x4038ec3c): Authorization string = "Local EA2A908A3B6E63CCD99CD45A27728707"
d [27/Sep/2004:21:40:04 +0200] decode_auth() 11 username="root"
d [27/Sep/2004:21:40:04 +0200] IsAuthorized: con->uri = "/admin/"
d [27/Sep/2004:21:40:04 +0200] FindBest: uri = "/admin/"...
d [27/Sep/2004:21:40:04 +0200] FindBest: Location CUPS_INTERNAL_BROWSE_ACL Limit 0
d [27/Sep/2004:21:40:04 +0200] FindBest: Location / Limit 7f
d [27/Sep/2004:21:40:04 +0200] FindBest: Location /admin Limit 7f
d [27/Sep/2004:21:40:04 +0200] FindBest: best = "/admin"
d [27/Sep/2004:21:40:04 +0200] IsAuthorized: auth = 0, satisfy=0...
d [27/Sep/2004:21:40:04 +0200] IsAuthorized: username = "root" password = 0 chars
d [27/Sep/2004:21:40:04 +0200] IsAuthorized: Checking "root", address = 7f000001, hostname = "localhost"
d [27/Sep/2004:21:40:04 +0200] POST /admin/
d [27/Sep/2004:21:40:04 +0200] CONTENT_TYPE = application/ipp
d [27/Sep/2004:21:40:04 +0200] ReadClient() 11 con->data_encoding = length, con->data_remaining = 116, con->file = -1
d [27/Sep/2004:21:40:04 +0200] ProcessIPPRequest(0x4038ec3c[11]): operation_id = 0011
d [27/Sep/2004:21:40:04 +0200] start_printer(0x4038ec3c[11], ipp://localhost/printers/lp1)
I [27/Sep/2004:21:40:04 +0200] Saving printers.conf...
I [27/Sep/2004:21:40:04 +0200] Printer 'lp1' started by 'root'.
D [27/Sep/2004:21:40:04 +0200] StartJob(4, 0x80a5dd8)
D [27/Sep/2004:21:40:04 +0200] StartJob() id = 4, file = 0/1
D [27/Sep/2004:21:40:04 +0200] job-sheets=none,none
D [27/Sep/2004:21:40:04 +0200] banner_page = 0
D [27/Sep/2004:21:40:04 +0200] StartJob: argv = "lp1","4","root","Test Page","1","","/var/spool/cups/d00004-001"
D [27/Sep/2004:21:40:04 +0200] StartJob: envp[0]="PATH=/usr/lib/cups/filter:/bin:/usr/bin"
D [27/Sep/2004:21:40:04 +0200] StartJob: envp[1]="SOFTWARE=CUPS/1.1"
D [27/Sep/2004:21:40:04 +0200] StartJob: envp[2]="USER=root"
D [27/Sep/2004:21:40:04 +0200] StartJob: envp[3]="CHARSET=utf-8"
D [27/Sep/2004:21:40:04 +0200] StartJob: envp[4]="LANG=de"
D [27/Sep/2004:21:40:04 +0200] StartJob: envp[5]="PPD=/etc/cups/ppd/lp1.ppd"
D [27/Sep/2004:21:40:04 +0200] StartJob: envp[6]="CUPS_SERVERROOT=/etc/cups"
D [27/Sep/2004:21:40:04 +0200] StartJob: envp[7]="RIP_MAX_CACHE=8m"
D [27/Sep/2004:21:40:04 +0200] StartJob: envp[8]="TMPDIR=/var/spool/cups/tmp"
D [27/Sep/2004:21:40:04 +0200] StartJob: envp[9]="CONTENT_TYPE=application/postscript"
D [27/Sep/2004:21:40:04 +0200] StartJob: envp[10]="DEVICE_URI=lpd://lowa/raw"
D [27/Sep/2004:21:40:04 +0200] StartJob: envp[11]="PRINTER=lp1"
D [27/Sep/2004:21:40:04 +0200] StartJob: envp[12]="CUPS_DATADIR=/usr/share/cups"
D [27/Sep/2004:21:40:04 +0200] StartJob: envp[13]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [27/Sep/2004:21:40:04 +0200] StartJob: envp[14]="CUPS_SERVER=localhost"
D [27/Sep/2004:21:40:04 +0200] StartJob: envp[15]="IPP_PORT=631"
d [27/Sep/2004:21:40:04 +0200] StartJob: Allocating status buffer...
D [27/Sep/2004:21:40:04 +0200] StartJob: statusfds = [ 15 16 ]
D [27/Sep/2004:21:40:04 +0200] StartJob: filterfds[1] = [ 17 -1 ]
D [27/Sep/2004:21:40:04 +0200] StartJob: filter = "/usr/lib/cups/filter/pstops"
D [27/Sep/2004:21:40:04 +0200] StartJob: filterfds[0] = [ 18 19 ]
D [27/Sep/2004:21:40:04 +0200] start_process("/usr/lib/cups/filter/pstops", 0xbffed180, 0xbffec4f0, 17, 19, 16)
I [27/Sep/2004:21:40:04 +0200] Started filter /usr/lib/cups/filter/pstops (PID 5955) for job 4.
D [27/Sep/2004:21:40:04 +0200] StartJob: filter = "/usr/lib/cups/filter/foomatic-rip"
D [27/Sep/2004:21:40:04 +0200] StartJob: filterfds[1] = [ 17 20 ]
D [27/Sep/2004:21:40:04 +0200] start_process("/usr/lib/cups/filter/foomatic-rip", 0xbffed180, 0xbffec4f0, 18, 20, 16)
I [27/Sep/2004:21:40:04 +0200] Started filter /usr/lib/cups/filter/foomatic-rip (PID 5956) for job 4.
D [27/Sep/2004:21:40:04 +0200] StartJob: backend = "/usr/lib/cups/backend/lpd"
D [27/Sep/2004:21:40:04 +0200] StartJob: filterfds[0] = [ -1 18 ]
D [27/Sep/2004:21:40:04 +0200] start_process("/usr/lib/cups/backend/lpd", 0xbffed180, 0xbffec4f0, 17, 18, 16)
I [27/Sep/2004:21:40:04 +0200] Started backend /usr/lib/cups/backend/lpd (PID 5957) for job 4.
d [27/Sep/2004:21:40:04 +0200] StartJob: Adding fd 15 to InputSet...
D [27/Sep/2004:21:40:04 +0200] ProcessIPPRequest: 11 status_code=0
d [27/Sep/2004:21:40:04 +0200] ProcessIPPRequest: Adding fd 11 to OutputSet...
D [27/Sep/2004:21:40:04 +0200] [Job 4] Page = 595x842; 24,48 to 571,818
D [27/Sep/2004:21:40:04 +0200] [Job 4] slowcollate=0, slowduplex=0, sloworder=0
D [27/Sep/2004:21:40:04 +0200] [Job 4] 0 %%BoundingBox: 0 0 612 792
D [27/Sep/2004:21:40:04 +0200] [Job 4] 0 %%Pages: 1
D [27/Sep/2004:21:40:04 +0200] [Job 4] 0 %%LanguageLevel: 1
D [27/Sep/2004:21:40:04 +0200] [Job 4] 0 %%DocumentData: Clean7Bit
D [27/Sep/2004:21:40:04 +0200] [Job 4] 0 %%DocumentSuppliedResources: procset testprint/1.0
D [27/Sep/2004:21:40:04 +0200] [Job 4] 0 %%DocumentNeededResources: font Helvetica Helvetica-Bold Times-Roman
D [27/Sep/2004:21:40:04 +0200] [Job 4] 0 %%Creator: Michael Sweet, Easy Software Products
D [27/Sep/2004:21:40:04 +0200] [Job 4] 0 %%CreationDate: May 11, 1999
D [27/Sep/2004:21:40:04 +0200] [Job 4] 0 %%Title: Test Page
D [27/Sep/2004:21:40:04 +0200] [Job 4] 0 %%EndComments
D [27/Sep/2004:21:40:04 +0200] [Job 4] 0 %%BeginProlog
D [27/Sep/2004:21:40:04 +0200] [Job 4] 0 %%BeginResource procset testprint 1.1 0
D [27/Sep/2004:21:40:04 +0200] [Job 4] 0 %%EndResource
D [27/Sep/2004:21:40:04 +0200] [Job 4] 0 %%EndProlog
D [27/Sep/2004:21:40:04 +0200] [Job 4] 0 %%Page: 1 1
D [27/Sep/2004:21:40:04 +0200] [Job 4] 0 %%Page: 1 1
D [27/Sep/2004:21:40:04 +0200] [Job 4] pw = 547.0, pl = 770.0
D [27/Sep/2004:21:40:04 +0200] [Job 4] PageLeft = 24.0, PageRight = 571.0
D [27/Sep/2004:21:40:04 +0200] [Job 4] PageTop = 818.0, PageBottom = 48.0
D [27/Sep/2004:21:40:04 +0200] [Job 4] PageWidth = 595.0, PageLength = 842.0
d [27/Sep/2004:21:40:04 +0200] WriteClient: Removing fd 11 from OutputSet...
d [27/Sep/2004:21:40:04 +0200] ReadClient() 11, used=0, file=-1
d [27/Sep/2004:21:40:04 +0200] ReadClient: httpGets returned EOF...
D [27/Sep/2004:21:40:04 +0200] CloseClient() 11
d [27/Sep/2004:21:40:04 +0200] CloseClient: Removing fd 11 from InputSet and OutputSet...
d [27/Sep/2004:21:40:04 +0200] PID 5954 exited with no errors.
d [27/Sep/2004:21:40:04 +0200] DeleteCert: removing certificate for pid 5954
d [27/Sep/2004:21:40:04 +0200] WriteClient: Removing fd 9 from OutputSet...
d [27/Sep/2004:21:40:04 +0200] WriteClient: Removing fd 14 from InputSet...
d [27/Sep/2004:21:40:04 +0200] WriteClient: 9 Closing data file 14.
D [27/Sep/2004:21:40:05 +0200] [Job 4] foomatic-rip version $Revision: 3.43.2.2 $ running...
D [27/Sep/2004:21:40:05 +0200] [Job 4] Parsing PPD file ...
D [27/Sep/2004:21:40:05 +0200] [Job 4] *cupsFilter: "application/vnd.cups-postscript 0 foomatic-rip"
D [27/Sep/2004:21:40:05 +0200] [Job 4] Added option ColorSpace
D [27/Sep/2004:21:40:05 +0200] [Job 4] Added option PageSize
D [27/Sep/2004:21:40:05 +0200] [Job 4] Added option PageRegion
D [27/Sep/2004:21:40:05 +0200] [Job 4] Added option ImageableArea
D [27/Sep/2004:21:40:05 +0200] [Job 4] Added option PaperDimension
D [27/Sep/2004:21:40:05 +0200] [Job 4] Added option ColorMode
D [27/Sep/2004:21:40:05 +0200] [Job 4] Added option BlackCorrect
D [27/Sep/2004:21:40:05 +0200] [Job 4] Added option Depletion
D [27/Sep/2004:21:40:05 +0200] [Job 4] Added option Passes
D [27/Sep/2004:21:40:05 +0200] [Job 4] Added option Font
D [27/Sep/2004:21:40:05 +0200] [Job 4]
D [27/Sep/2004:21:40:05 +0200] [Job 4] Parameter Summary
D [27/Sep/2004:21:40:05 +0200] [Job 4] -----------------
D [27/Sep/2004:21:40:05 +0200] [Job 4]
D [27/Sep/2004:21:40:05 +0200] [Job 4] Spooler: cups
D [27/Sep/2004:21:40:05 +0200] [Job 4] Printer: lp1
D [27/Sep/2004:21:40:05 +0200] [Job 4] PPD file: /etc/cups/ppd/lp1.ppd
D [27/Sep/2004:21:40:05 +0200] [Job 4] Printer model: Olivetti JP350S Foomatic/cdj500
D [27/Sep/2004:21:40:05 +0200] [Job 4] Job title: Test Page
D [27/Sep/2004:21:40:05 +0200] [Job 4] File(s) to be printed:
D [27/Sep/2004:21:40:05 +0200] [Job 4] <STDIN>
D [27/Sep/2004:21:40:05 +0200] [Job 4]
D [27/Sep/2004:21:40:05 +0200] [Job 4]
D [27/Sep/2004:21:40:05 +0200] [Job 4] ================================================
D [27/Sep/2004:21:40:05 +0200] [Job 4]
D [27/Sep/2004:21:40:05 +0200] [Job 4] File: <STDIN>
D [27/Sep/2004:21:40:05 +0200] [Job 4]
D [27/Sep/2004:21:40:05 +0200] [Job 4] ================================================
D [27/Sep/2004:21:40:05 +0200] [Job 4]
D [27/Sep/2004:21:40:05 +0200] [Job 4] Reading PostScript input ...
D [27/Sep/2004:21:40:05 +0200] [Job 4] --> This document is DSC-conforming!
D [27/Sep/2004:21:40:05 +0200] [Job 4]
D [27/Sep/2004:21:40:05 +0200] [Job 4] -----------
D [27/Sep/2004:21:40:05 +0200] [Job 4] Found: %%BeginProlog
D [27/Sep/2004:21:40:05 +0200] [Job 4] 0 %%EOF
D [27/Sep/2004:21:40:05 +0200] [Job 4] Saw EOF!
D [27/Sep/2004:21:40:05 +0200] [Job 4] Found: %%EndProlog
D [27/Sep/2004:21:40:05 +0200] [Job 4]
D [27/Sep/2004:21:40:05 +0200] [Job 4] -----------
D [27/Sep/2004:21:40:05 +0200] [Job 4] Found: %%BeginSetup
D [27/Sep/2004:21:40:05 +0200] [Job 4] Inserting PostScript code for CUPS' page accounting
D [27/Sep/2004:21:40:05 +0200] [Job 4] Found: %%BeginFeature: *ColorMode NormalColor
D [27/Sep/2004:21:40:05 +0200] [Job 4] Option: ColorMode=NormalColor --> Setting option
D [27/Sep/2004:21:40:05 +0200] [Job 4] Found: %% FoomaticRIPOptionSetting: ColorMode=NormalColor
D [27/Sep/2004:21:40:05 +0200] [Job 4] Option: ColorMode=NormalColor --> Setting option
D [27/Sep/2004:21:40:05 +0200] [Job 4] Found: %%BeginFeature: *PageSize A4
D [27/Sep/2004:21:40:05 +0200] [Job 4] Option: PageSize=A4 --> Option will be set by PostScript interpreter
D [27/Sep/2004:21:40:05 +0200] [Job 4] Found: %%BeginFeature: *BlackCorrect 4
D [27/Sep/2004:21:40:05 +0200] [Job 4] Option: BlackCorrect=4 --> Setting option
D [27/Sep/2004:21:40:05 +0200] [Job 4] Found: %% FoomaticRIPOptionSetting: BlackCorrect=4
D [27/Sep/2004:21:40:05 +0200] [Job 4] Option: BlackCorrect=4 --> Setting option
D [27/Sep/2004:21:40:05 +0200] [Job 4] Found: %%BeginFeature: *Depletion Default
D [27/Sep/2004:21:40:05 +0200] [Job 4] Option: Depletion=Default --> Setting option
D [27/Sep/2004:21:40:05 +0200] [Job 4] Found: %% FoomaticRIPOptionSetting: Depletion=Default
D [27/Sep/2004:21:40:05 +0200] [Job 4] Option: Depletion=Default --> Setting option
D [27/Sep/2004:21:40:05 +0200] [Job 4] Found: %%BeginFeature: *Passes Default
D [27/Sep/2004:21:40:05 +0200] [Job 4] Option: Passes=Default --> Setting option
D [27/Sep/2004:21:40:05 +0200] [Job 4] Found: %% FoomaticRIPOptionSetting: Passes=Default
D [27/Sep/2004:21:40:05 +0200] [Job 4] Option: Passes=Default --> Setting option
D [27/Sep/2004:21:40:05 +0200] [Job 4] Found: %%EndSetup
D [27/Sep/2004:21:40:05 +0200] [Job 4]
D [27/Sep/2004:21:40:05 +0200] [Job 4] -----------
D [27/Sep/2004:21:40:05 +0200] [Job 4] New page: 1 1
D [27/Sep/2004:21:40:05 +0200] [Job 4] Inserting option code into "PageSetup" section.
D [27/Sep/2004:21:40:05 +0200] [Job 4] No page header or page header not DSC-conforming
d [27/Sep/2004:21:40:05 +0200] PID 5955 exited with no errors.
D [27/Sep/2004:21:40:05 +0200] [Job 4] Stopping search for page header options
D [27/Sep/2004:21:40:05 +0200] [Job 4] Found:
D [27/Sep/2004:21:40:05 +0200] [Job 4] pageHeight sub % Move down...
D [27/Sep/2004:21:40:05 +0200] [Job 4] --> Output goes directly to the renderer now.
D [27/Sep/2004:21:40:05 +0200] [Job 4]
D [27/Sep/2004:21:40:05 +0200] [Job 4]
D [27/Sep/2004:21:40:05 +0200] [Job 4] Starting renderer
D [27/Sep/2004:21:40:05 +0200] [Job 4] JCL: <job data>
D [27/Sep/2004:21:40:05 +0200] [Job 4]
D [27/Sep/2004:21:40:05 +0200] [Job 4] renderer PID kid4=5959
D [27/Sep/2004:21:40:05 +0200] [Job 4] renderer command: gs -q -dBATCH -dPARANOIDSAFER -dQUIET -dNOPAUSE -r300x300 -sDEVICE=cdj500 -dBitsPerPixel=3 -dBlackCorrect=4 -sOutputFile=- -
D [27/Sep/2004:21:40:05 +0200] [Job 4] foomatic-gswrapper: gs '-dBATCH' '-dPARANOIDSAFER' '-dQUIET' '-dNOPAUSE' '-r300x300' '-sDEVICE=cdj500' '-dBitsPerPixel=3' '-dBlackCorrect=4' '-sOutputFile=| cat >&3' '/dev/fd/0' 3>&1 1>&2
D [27/Sep/2004:21:40:06 +0200] [Job 4]
D [27/Sep/2004:21:40:06 +0200] [Job 4] Closing renderer
D [27/Sep/2004:21:40:06 +0200] [Job 4] tail process done writing data to STDOUT
D [27/Sep/2004:21:40:06 +0200] [Job 4] KID4 finished
D [27/Sep/2004:21:40:06 +0200] [Job 4] KID3 exited with status 0
D [27/Sep/2004:21:40:06 +0200] [Job 4] KID4 exited with status 0
D [27/Sep/2004:21:40:06 +0200] [Job 4] Renderer exit stat: 0
D [27/Sep/2004:21:40:06 +0200] [Job 4] KID3 finished
D [27/Sep/2004:21:40:06 +0200] [Job 4] Renderer process finished
D [27/Sep/2004:21:40:06 +0200] [Job 4]
D [27/Sep/2004:21:40:06 +0200] [Job 4] Closing foomatic-rip.
d [27/Sep/2004:21:40:06 +0200] PID 5956 exited with no errors.
I [27/Sep/2004:21:40:06 +0200] [Job 4] Attempting to connect to host lowa for printer raw
I [27/Sep/2004:21:40:06 +0200] [Job 4] Connected to lowa...
D [27/Sep/2004:21:40:06 +0200] [Job 4] Connected on ports 515 (local 0)...
D [27/Sep/2004:21:40:06 +0200] [Job 4] lpd_command 02 raw
D [27/Sep/2004:21:40:06 +0200] [Job 4] Sending command string (5 bytes)...
D [27/Sep/2004:21:40:06 +0200] [Job 4] Reading command status...
D [27/Sep/2004:21:40:06 +0200] [Job 4] lpd_command returning 47
E [27/Sep/2004:21:40:06 +0200] PID 5957 stopped with status 1!
D [27/Sep/2004:21:40:06 +0200] UpdateJob: job 4, file 0 is complete.
d [27/Sep/2004:21:40:06 +0200] UpdateJob: Removing fd 15 from InputSet...
D [27/Sep/2004:21:40:06 +0200] StopJob: id = 4, force = 0
I [27/Sep/2004:21:40:06 +0200] Saving printers.conf...
D [27/Sep/2004:21:40:06 +0200] StopJob: printer state is 5
d [27/Sep/2004:21:40:06 +0200] StopJob: Freeing status buffer...
d [27/Sep/2004:21:40:06 +0200] SaveJob: Closing file 14...
d [27/Sep/2004:21:41:05 +0200] ReadClient() 9, used=0, file=-1
d [27/Sep/2004:21:41:05 +0200] ReadClient: httpGets returned EOF...
D [27/Sep/2004:21:41:05 +0200] CloseClient() 9
d [27/Sep/2004:21:41:05 +0200] CloseClient: Removing fd 9 from InputSet and OutputSet...
d [27/Sep/2004:21:43:37 +0200] DeleteCert: removing certificate for pid 0
d [27/Sep/2004:21:43:37 +0200] AddCert: adding certificate for pid 0
########## TCP-DUMP ##############################################
baldur:/home/ariovist # tcpdump -i eth0 -X tcp
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on eth0, link-type EN10MB (Ethernet), capture size 96 bytes
21:40:06.649789 IP baldur.lowa.r.shuttle.de.32962 > lowa.lowa.r.shuttle.de.printer: S 2249915913:2249915913(0) win 5840 <mss 1460,sackOK,timestamp 2857273 0,nop,wscale 0>
0x0000 4500 003c 6730 4000 4006 5038 c0a8 0101 E..<g0 at .@.P8....
0x0010 c0a8 0102 80c2 0203 861a fe09 0000 0000 ................
0x0020 a002 16d0 0d95 0000 0204 05b4 0402 080a ................
0x0030 002b 9939 0000 0000 0103 0300 .+.9........
21:40:06.661227 IP lowa.lowa.r.shuttle.de.printer > baldur.lowa.r.shuttle.de.32962: S 1803924147:1803924147(0) ack 2249915914 win 32120 <mss 1460,sackOK,timestamp 280807 2857273,nop,wscale 0>
0x0000 4500 003c 14c2 4000 4006 a2a6 c0a8 0102 E..<.. at .@.......
0x0010 c0a8 0101 0203 80c2 6b85 b2b3 861a fe0a ........k.......
0x0020 a012 7d78 3fb7 0000 0204 05b4 0402 080a ..}x?...........
0x0030 0004 48e7 002b 9939 0103 0300 ..H..+.9....
21:40:06.661391 IP baldur.lowa.r.shuttle.de.32962 > lowa.lowa.r.shuttle.de.printer: . ack 1 win 5840 <nop,nop,timestamp 2857285 280807>
0x0000 4500 0034 6731 4000 4006 503f c0a8 0101 E..4g1 at .@.P?....
0x0010 c0a8 0102 80c2 0203 861a fe0a 6b85 b2b4 ............k...
0x0020 8010 16d0 d518 0000 0101 080a 002b 9945 .............+.E
0x0030 0004 48e7 ..H.
21:40:06.661684 IP baldur.lowa.r.shuttle.de.32962 > lowa.lowa.r.shuttle.de.printer: P 1:6(5) ack 1 win 5840 <nop,nop,timestamp 2857285 280807>
0x0000 4500 0039 6732 4000 4006 5039 c0a8 0101 E..9g2 at .@.P9....
0x0010 c0a8 0102 80c2 0203 861a fe0a 6b85 b2b4 ............k...
0x0020 8018 16d0 6722 0000 0101 080a 002b 9945 ....g".......+.E
0x0030 0004 48e7 0272 6177 0a ..H..raw.
21:40:06.663445 IP lowa.lowa.r.shuttle.de.printer > baldur.lowa.r.shuttle.de.32962: . ack 6 win 32120 <nop,nop,timestamp 280807 2857285>
0x0000 4500 0034 14c3 4000 4006 a2ad c0a8 0102 E..4.. at .@.......
0x0010 c0a8 0101 0203 80c2 6b85 b2b4 861a fe0f ........k.......
0x0020 8010 7d78 6e6b 0000 0101 080a 0004 48e7 ..}xnk........H.
0x0030 002b 9945 .+.E
21:40:06.680799 IP lowa.lowa.r.shuttle.de.printer > baldur.lowa.r.shuttle.de.32962: P 1:44(43) ack 6 win 32120 <nop,nop,timestamp 280809 2857285>
0x0000 4500 005f 14c4 4000 4006 a281 c0a8 0102 E.._.. at .@.......
0x0010 c0a8 0101 0203 80c2 6b85 b2b4 861a fe0f ........k.......
0x0020 8018 7d78 f94f 0000 0101 080a 0004 48e9 ..}x.O........H.
0x0030 002b 9945 2f75 7372 2f73 6269 6e2f 6c70 .+.E/usr/sbin/lp
0x0040 643a 2072 6177 3a20 4d61 6c66 6f72 6d65 d:.raw:.Malforme
0x0050 6420 d.
21:40:06.681190 IP baldur.lowa.r.shuttle.de.32962 > lowa.lowa.r.shuttle.de.printer: . ack 44 win 5840 <nop,nop,timestamp 2857304 280809>
0x0000 4500 0034 6733 4000 4006 503d c0a8 0101 E..4g3 at .@.P=....
0x0010 c0a8 0102 80c2 0203 861a fe0f 6b85 b2df ............k...
0x0020 8010 16d0 d4d3 0000 0101 080a 002b 9958 .............+.X
0x0030 0004 48e9 ..H.
21:40:06.681909 IP baldur.lowa.r.shuttle.de.32962 > lowa.lowa.r.shuttle.de.printer: R 6:6(0) ack 44 win 5840 <nop,nop,timestamp 2857305 280809>
0x0000 4500 0034 6734 4000 4006 503c c0a8 0101 E..4g4 at .@.P<....
0x0010 c0a8 0102 80c2 0203 861a fe0f 6b85 b2df ............k...
0x0020 8014 16d0 d4ce 0000 0101 080a 002b 9959 .............+.Y
0x0030 0004 48e9 ..H.
21:40:06.685734 IP lowa.lowa.r.shuttle.de.printer > baldur.lowa.r.shuttle.de.32962: R 44:44(0) ack 6 win 32120 <nop,nop,timestamp 280809 2857305>
0x0000 4500 0034 14c5 4000 4006 a2ab c0a8 0102 E..4.. at .@.......
0x0010 c0a8 0101 0203 80c2 6b85 b2df 861a fe0f ........k.......
0x0020 8014 7d78 6e26 0000 0101 080a 0004 48e9 ..}xn&........H.
0x0030 002b 9959 .+.Y
More information about the cups
mailing list