[cups.general] parallel priner on sparc u5 stop working suddenly,parallel process dies

Mon Sep 18 03:53:32 PDT 2006

张韡武 wrote:
> Printers are really behaving strangely these days. Yesterday my laserjet
> 3015 (directly connected to computer with parallel port) suddenly
> stopped working (send print job, no response, gs eat up 100% CPU
> resource, killing gs makes printer printed one page with nothing on it
> -- white page). After restart the computer several times, the behavior
> become like this:
> 
> 1) send a test page;
> 2) nothing happens. No job in the queue.
> 
> This happens if I use either PS (ppd file from foomatic) or use PCL
> (hpijs and ppd file from foomatic).
> 
> Meanwhile:
> 1) two other inkjet USB printers on the same computer works fine.
> 2) echo Hello World > /dev/lp0 result correct (printed correctly)
> 
> I also tried to decrypt the error_log, these lines looks strange:
> 
> I [16/Sep/2006:10:57:28 +0800] Started backend /usr/lib/cups/backend/parallel (PID 1929) for job 1116.
> D [16/Sep/2006:10:57:28 +0800] ProcessIPPRequest: 7 status_code=0
> E [16/Sep/2006:10:57:28 +0800] PID 1928 stopped with status 22!
> D [16/Sep/2006:10:57:28 +0800] CloseClient: 7
> 
> My dmesg for experts:
> 
> sun ~ # dmesg | grep lp0 | grep --invert-match usb
> lp0: using parport0 (interrupt-driven).
> lp0: ECP mode
> lp0: ECP mode
> lp0: ECP mode
> sab82532: receive_chars: RFOsab82532: receive_chars: RFOsab82532:
> receive_chars: RFO<6>lp0: ECP mode
> lp0: ECP mode
> lp0: ECP mode
> lp0: ECP mode
> 
> all the error_log is full of information I cannot understand, thus I
> attached the error_log here (only the part since last restart cups):
> 
> I [16/Sep/2006:10:56:54 +0800] Listening to 0:631
> D [16/Sep/2006:10:56:54 +0800] AddLocation: added location '/'
> D [16/Sep/2006:10:56:54 +0800] DenyIP: / deny 00000000/00000000
> D [16/Sep/2006:10:56:54 +0800] AllowIP: / allow 00000000/00000000
> D [16/Sep/2006:10:56:54 +0800] AddLocation: added location '/admin'
> D [16/Sep/2006:10:56:54 +0800] DenyIP: /admin deny 00000000/00000000
> D [16/Sep/2006:10:56:54 +0800] AllowIP: /admin allow 00000000/00000000
> I [16/Sep/2006:10:56:54 +0800] Loaded configuration file "/etc/cups/cupsd.conf"
> I [16/Sep/2006:10:56:54 +0800] Configured for up to 100 clients.
> I [16/Sep/2006:10:56:54 +0800] Allowing up to 50 client connections per host.
> I [16/Sep/2006:10:56:54 +0800] Full reload is required.
> D [16/Sep/2006:10:56:54 +0800] LoadAllPrinters: Loading printer epson_stylus_830...
> D [16/Sep/2006:10:56:55 +0800] LoadAllPrinters: Loading printer epson_stylus_r350...
> D [16/Sep/2006:10:56:55 +0800] LoadAllPrinters: Loading printer hp_laserjet_3015...
> D [16/Sep/2006:10:56:55 +0800] LoadAllPrinters: Loading printer Virtual_PDF...
> D [16/Sep/2006:10:56:55 +0800] LoadDevices: Added device "ipp"...
> D [16/Sep/2006:10:56:55 +0800] LoadDevices: Added device "lpd"...
> D [16/Sep/2006:10:56:55 +0800] LoadDevices: Added device "parallel:/dev/lp0"...
> D [16/Sep/2006:10:56:55 +0800] LoadDevices: Added device "scsi"...
> D [16/Sep/2006:10:56:57 +0800] LoadDevices: Added device "serial:/dev/ttyS0?baud=115200"...
> D [16/Sep/2006:10:56:57 +0800] LoadDevices: Added device "serial:/dev/ttyS1?baud=115200"...
> D [16/Sep/2006:10:56:57 +0800] LoadDevices: Added device "socket"...
> D [16/Sep/2006:10:56:57 +0800] LoadDevices: Added device "usb:/dev/usb/lp0"...
> D [16/Sep/2006:10:56:57 +0800] LoadDevices: Added device "usb:/dev/usb/lp1"...
> D [16/Sep/2006:10:56:57 +0800] LoadDevices: Added device "usb:/dev/usb/lp2"...
> D [16/Sep/2006:10:56:57 +0800] LoadDevices: Added device "usb:/dev/usb/lp3"...
> D [16/Sep/2006:10:56:57 +0800] LoadDevices: Added device "usb:/dev/usb/lp4"...
> D [16/Sep/2006:10:56:57 +0800] LoadDevices: Added device "usb:/dev/usb/lp5"...
> D [16/Sep/2006:10:56:57 +0800] LoadDevices: Added device "usb:/dev/usb/lp6"...
> D [16/Sep/2006:10:56:57 +0800] LoadDevices: Added device "usb:/dev/usb/lp7"...
> D [16/Sep/2006:10:56:57 +0800] LoadDevices: Added device "usb:/dev/usb/lp8"...
> D [16/Sep/2006:10:56:57 +0800] LoadDevices: Added device "usb:/dev/usb/lp9"...
> D [16/Sep/2006:10:56:57 +0800] LoadDevices: Added device "usb:/dev/usb/lp10"...
> D [16/Sep/2006:10:56:57 +0800] LoadDevices: Added device "usb:/dev/usb/lp11"...
> D [16/Sep/2006:10:56:57 +0800] LoadDevices: Added device "usb:/dev/usb/lp12"...
> D [16/Sep/2006:10:56:57 +0800] LoadDevices: Added device "usb:/dev/usb/lp13"...
> D [16/Sep/2006:10:56:57 +0800] LoadDevices: Added device "usb:/dev/usb/lp14"...
> D [16/Sep/2006:10:56:57 +0800] LoadDevices: Added device "usb:/dev/usb/lp15"...
> D [16/Sep/2006:10:56:57 +0800] LoadDevices: Added device "http"...
> D [16/Sep/2006:10:56:57 +0800] LoadDevices: Added device "cups-pdf:/"...
> D [16/Sep/2006:10:56:57 +0800] LoadDevices: Added device "epson:/dev/lp0"...
> D [16/Sep/2006:10:56:57 +0800] LoadDevices: Added device "canon:/dev/lp0"...
> I [16/Sep/2006:10:56:57 +0800] LoadPPDs: Read "/etc/cups/ppds.dat", 3488 PPDs...
> I [16/Sep/2006:10:56:58 +0800] LoadPPDs: No new or changed PPDs...
> D [16/Sep/2006:10:56:58 +0800] LoadAllJobs: Scanning /var/spool/cups...
> D [16/Sep/2006:10:56:58 +0800] LoadAllJobs: Loading attributes for job 1106...
> D [16/Sep/2006:10:56:58 +0800] LoadAllJobs: Loading attributes for job 1107...
> D [16/Sep/2006:10:56:58 +0800] LoadAllJobs: Loading attributes for job 1108...
> D [16/Sep/2006:10:56:58 +0800] LoadAllJobs: Loading attributes for job 1109...
> D [16/Sep/2006:10:56:58 +0800] LoadAllJobs: Loading attributes for job 1110...
> D [16/Sep/2006:10:56:58 +0800] LoadAllJobs: Loading attributes for job 1111...
> D [16/Sep/2006:10:56:58 +0800] LoadAllJobs: Loading attributes for job 1112...
> D [16/Sep/2006:10:56:58 +0800] LoadAllJobs: Loading attributes for job 1113...
> D [16/Sep/2006:10:56:58 +0800] LoadAllJobs: Loading attributes for job 1114...
> D [16/Sep/2006:10:56:58 +0800] LoadAllJobs: Loading attributes for job 1115...
> D [16/Sep/2006:10:56:58 +0800] LoadAllJobs: Loading attributes for job 1102...
> D [16/Sep/2006:10:56:58 +0800] LoadAllJobs: Loading attributes for job 836...
> D [16/Sep/2006:10:56:58 +0800] LoadAllJobs: Loading attributes for job 837...
> I [16/Sep/2006:10:56:58 +0800] Full reload complete.
> D [16/Sep/2006:10:56:58 +0800] StartListening: NumListeners=1
> D [16/Sep/2006:10:56:58 +0800] StartListening: address=00000000 port=631
> D [16/Sep/2006:10:56:58 +0800] ResumeListening: setting input bits...
> D [16/Sep/2006:10:57:24 +0800] AcceptClient: 5 from 10.0.0.4:631.
> D [16/Sep/2006:10:57:24 +0800] ReadClient: 5 GET /printers HTTP/1.1
> D [16/Sep/2006:10:57:24 +0800] CGI /usr/lib/cups/cgi-bin/printers.cgi started - PID = 1925
> I [16/Sep/2006:10:57:24 +0800] Started "/usr/lib/cups/cgi-bin/printers.cgi" (pid=1925)
> D [16/Sep/2006:10:57:24 +0800] SendCommand: 5 file=7
> D [16/Sep/2006:10:57:24 +0800] AcceptClient: 8 from localhost:631.
> D [16/Sep/2006:10:57:24 +0800] ReadClient: 8 POST / HTTP/1.1
> D [16/Sep/2006:10:57:24 +0800] ProcessIPPRequest: 8 status_code=1
> D [16/Sep/2006:10:57:24 +0800] ReadClient: 8 POST / HTTP/1.1
> D [16/Sep/2006:10:57:24 +0800] ProcessIPPRequest: 8 status_code=1
> D [16/Sep/2006:10:57:24 +0800] AcceptClient: 9 from 10.0.0.4:631.
> D [16/Sep/2006:10:57:24 +0800] ReadClient: 9 GET /cups.css HTTP/1.1
> D [16/Sep/2006:10:57:24 +0800] SendFile: 9 file=10
> D [16/Sep/2006:10:57:24 +0800] ReadClient: 9 GET /images/navbar.gif HTTP/1.1
> D [16/Sep/2006:10:57:24 +0800] SendFile: 9 file=10
> D [16/Sep/2006:10:57:24 +0800] CloseClient: 8
> D [16/Sep/2006:10:57:24 +0800] ReadClient: 5 GET /images/left.gif HTTP/1.1
> D [16/Sep/2006:10:57:24 +0800] SendFile: 5 file=7
> D [16/Sep/2006:10:57:24 +0800] ReadClient: 9 GET /images/right.gif HTTP/1.1
> D [16/Sep/2006:10:57:24 +0800] SendFile: 9 file=8
> D [16/Sep/2006:10:57:24 +0800] ReadClient: 5 GET /images/printer-idle.gif HTTP/1.1
> D [16/Sep/2006:10:57:24 +0800] SendFile: 5 file=7
> D [16/Sep/2006:10:57:24 +0800] ReadClient: 9 GET /images/print-test-page.gif HTTP/1.1
> D [16/Sep/2006:10:57:24 +0800] SendFile: 9 file=7
> D [16/Sep/2006:10:57:24 +0800] ReadClient: 5 GET /images/stop-printer.gif HTTP/1.1
> D [16/Sep/2006:10:57:24 +0800] SendFile: 5 file=8
> D [16/Sep/2006:10:57:24 +0800] ReadClient: 9 GET /images/reject-jobs.gif HTTP/1.1
> D [16/Sep/2006:10:57:24 +0800] SendFile: 9 file=7
> D [16/Sep/2006:10:57:24 +0800] ReadClient: 5 GET /images/modify-printer.gif HTTP/1.1
> D [16/Sep/2006:10:57:24 +0800] SendFile: 5 file=7
> D [16/Sep/2006:10:57:24 +0800] ReadClient: 9 GET /images/config-printer.gif HTTP/1.1
> D [16/Sep/2006:10:57:24 +0800] SendFile: 9 file=8
> D [16/Sep/2006:10:57:24 +0800] ReadClient: 5 GET /images/delete-printer.gif HTTP/1.1
> D [16/Sep/2006:10:57:24 +0800] SendFile: 5 file=7
> D [16/Sep/2006:10:57:24 +0800] ReadClient: 5 GET /images/set-as-default.gif HTTP/1.1
> D [16/Sep/2006:10:57:24 +0800] SendFile: 5 file=7
> D [16/Sep/2006:10:57:24 +0800] ReadClient: 5 GET /images/add-printer.gif HTTP/1.1
> D [16/Sep/2006:10:57:25 +0800] SendFile: 5 file=7
> D [16/Sep/2006:10:57:28 +0800] ReadClient: 5 GET /printers/hp_laserjet_3015?op=print-test-page HTTP/1.1
> D [16/Sep/2006:10:57:28 +0800] CGI /usr/lib/cups/cgi-bin/printers.cgi started - PID = 1926
> I [16/Sep/2006:10:57:28 +0800] Started "/usr/lib/cups/cgi-bin/printers.cgi" (pid=1926)
> D [16/Sep/2006:10:57:28 +0800] SendCommand: 5 file=8
> D [16/Sep/2006:10:57:28 +0800] AcceptClient: 7 from localhost:631.
> D [16/Sep/2006:10:57:28 +0800] ReadClient: 7 POST /printers/hp_laserjet_3015 HTTP/1.1
> D [16/Sep/2006:10:57:28 +0800] print_job: request file type is application/postscript.
> D [16/Sep/2006:10:57:28 +0800] check_quotas: requesting-user-name = ''
> D [16/Sep/2006:10:57:28 +0800] print_job: requesting-user-name = ''
> D [16/Sep/2006:10:57:28 +0800] Adding default job-sheets values "none,none"...
> I [16/Sep/2006:10:57:28 +0800] Adding start banner page "none" to job 1116.
> I [16/Sep/2006:10:57:28 +0800] Adding end banner page "none" to job 1116.
> I [16/Sep/2006:10:57:28 +0800] Job 1116 queued on 'hp_laserjet_3015' by ''.
> D [16/Sep/2006:10:57:28 +0800] Job 1116 hold_until = 0
> D [16/Sep/2006:10:57:28 +0800] StartJob(1116, 0xb7828)
> D [16/Sep/2006:10:57:28 +0800] StartJob() id = 1116, file = 0/1
> D [16/Sep/2006:10:57:28 +0800] job-sheets=none,none
> D [16/Sep/2006:10:57:28 +0800] banner_page = 0
> D [16/Sep/2006:10:57:28 +0800] StartJob: argv = "hp_laserjet_3015","1116","","Test Page","1","","/var/spool/cups/d01116-001"
> D [16/Sep/2006:10:57:28 +0800] StartJob: envp[0]="PATH=/usr/lib/cups/filter:/bin:/usr/bin"
> D [16/Sep/2006:10:57:28 +0800] StartJob: envp[1]="SOFTWARE=CUPS/1.1"
> D [16/Sep/2006:10:57:28 +0800] StartJob: envp[2]="USER=root"
> D [16/Sep/2006:10:57:28 +0800] StartJob: envp[3]="CHARSET=utf-8"
> D [16/Sep/2006:10:57:28 +0800] StartJob: envp[4]="LANG=en"
> D [16/Sep/2006:10:57:28 +0800] StartJob: envp[5]="PPD=/etc/cups/ppd/hp_laserjet_3015.ppd"
> D [16/Sep/2006:10:57:28 +0800] StartJob: envp[6]="CUPS_SERVERROOT=/etc/cups"
> D [16/Sep/2006:10:57:28 +0800] StartJob: envp[7]="RIP_MAX_CACHE=8m"
> D [16/Sep/2006:10:57:28 +0800] StartJob: envp[8]="TMPDIR=/var/spool/cups/tmp"
> D [16/Sep/2006:10:57:28 +0800] StartJob: envp[9]="CONTENT_TYPE=application/postscript"
> D [16/Sep/2006:10:57:28 +0800] StartJob: envp[10]="DEVICE_URI=parallel:/dev/lp0"
> D [16/Sep/2006:10:57:28 +0800] StartJob: envp[11]="PRINTER=hp_laserjet_3015"
> D [16/Sep/2006:10:57:28 +0800] StartJob: envp[12]="CUPS_DATADIR=/usr/share/cups"
> D [16/Sep/2006:10:57:28 +0800] StartJob: envp[13]="CUPS_FONTPATH=/usr/share/cups/fonts"
> D [16/Sep/2006:10:57:28 +0800] StartJob: envp[14]="CUPS_SERVER=localhost"
> D [16/Sep/2006:10:57:28 +0800] StartJob: envp[15]="IPP_PORT=631"
> D [16/Sep/2006:10:57:28 +0800] StartJob: statusfds = [ 10 11 ]
> D [16/Sep/2006:10:57:28 +0800] StartJob: filterfds[1] = [ 12 -1 ]
> D [16/Sep/2006:10:57:28 +0800] StartJob: filter = "/usr/lib/cups/filter/pstops"
> D [16/Sep/2006:10:57:28 +0800] StartJob: filterfds[0] = [ 13 14 ]
> D [16/Sep/2006:10:57:28 +0800] start_process("/usr/lib/cups/filter/pstops", 0xeffee9a8, 0xeffedd18, 12, 14, 11)
> I [16/Sep/2006:10:57:28 +0800] Started filter /usr/lib/cups/filter/pstops (PID 1927) for job 1116.
> D [16/Sep/2006:10:57:28 +0800] StartJob: filter = "/usr/lib/cups/filter/foomatic-rip"
> D [16/Sep/2006:10:57:28 +0800] StartJob: filterfds[1] = [ 12 15 ]
> D [16/Sep/2006:10:57:28 +0800] start_process("/usr/lib/cups/filter/foomatic-rip", 0xeffee9a8, 0xeffedd18, 13, 15, 11)
> I [16/Sep/2006:10:57:28 +0800] Started filter /usr/lib/cups/filter/foomatic-rip (PID 1928) for job 1116.
> D [16/Sep/2006:10:57:28 +0800] StartJob: backend = "/usr/lib/cups/backend/parallel"
> D [16/Sep/2006:10:57:28 +0800] StartJob: filterfds[0] = [ -1 13 ]
> D [16/Sep/2006:10:57:28 +0800] start_process("/usr/lib/cups/backend/parallel", 0xeffee9a8, 0xeffedd18, 12, 13, 11)
> I [16/Sep/2006:10:57:28 +0800] Started backend /usr/lib/cups/backend/parallel (PID 1929) for job 1116.
> D [16/Sep/2006:10:57:28 +0800] ProcessIPPRequest: 7 status_code=0
> E [16/Sep/2006:10:57:28 +0800] PID 1928 stopped with status 22!
> D [16/Sep/2006:10:57:28 +0800] CloseClient: 7
> D [16/Sep/2006:10:57:28 +0800] [Job 1116] /usr/lib/cups/filter/foomatic-rip: No such file or directory
> D [16/Sep/2006:10:57:28 +0800] [Job 1116] Page = 612x792; 0,0 to 612,792
> D [16/Sep/2006:10:57:28 +0800] [Job 1116] slowcollate=0, slowduplex=0, sloworder=0
> D [16/Sep/2006:10:57:28 +0800] [Job 1116] 0 %%BoundingBox: 0 0 612 792
> D [16/Sep/2006:10:57:28 +0800] [Job 1116] 0 %%Pages: 1
> D [16/Sep/2006:10:57:28 +0800] [Job 1116] 0 %%LanguageLevel: 1
> D [16/Sep/2006:10:57:28 +0800] [Job 1116] 0 %%DocumentData: Clean7Bit
> D [16/Sep/2006:10:57:28 +0800] [Job 1116] 0 %%DocumentSuppliedResources: procset testprint/1.1
> D [16/Sep/2006:10:57:28 +0800] [Job 1116] 0 %%DocumentNeededResources: font Helvetica Helvetica-Bold Times-Roman
> D [16/Sep/2006:10:57:28 +0800] [Job 1116] 0 %%Creator: Michael Sweet, Easy Software Products
> D [16/Sep/2006:10:57:28 +0800] [Job 1116] 0 %%CreationDate: May 11, 1999
> D [16/Sep/2006:10:57:28 +0800] [Job 1116] 0 %%Title: Test Page
> D [16/Sep/2006:10:57:28 +0800] [Job 1116] 0 %%EndComments
> D [16/Sep/2006:10:57:28 +0800] [Job 1116] 0 %%BeginProlog
> D [16/Sep/2006:10:57:28 +0800] [Job 1116] 0 %%BeginResource procset testprint 1.1 0
> D [16/Sep/2006:10:57:28 +0800] [Job 1116] 0 %%EndResource
> D [16/Sep/2006:10:57:28 +0800] [Job 1116] 0 %%EndProlog
> D [16/Sep/2006:10:57:28 +0800] [Job 1116] 0 %%Page: 1 1
> D [16/Sep/2006:10:57:28 +0800] [Job 1116] 0 %%Page: 1 1
> D [16/Sep/2006:10:57:28 +0800] [Job 1116] pw = 612.0, pl = 792.0
> D [16/Sep/2006:10:57:28 +0800] [Job 1116] PageLeft = 0.0, PageRight = 612.0
> D [16/Sep/2006:10:57:28 +0800] [Job 1116] PageTop = 792.0, PageBottom = 0.0
> D [16/Sep/2006:10:57:28 +0800] [Job 1116] PageWidth = 612.0, PageLength = 792.0
> D [16/Sep/2006:10:57:28 +0800] [Job 1116] 0 %%EOF
> D [16/Sep/2006:10:57:28 +0800] [Job 1116] Saw EOF!
> D [16/Sep/2006:10:57:28 +0800] UpdateJob: job 1116, file 0 is complete.
> D [16/Sep/2006:10:57:28 +0800] CancelJob: id = 1116
> D [16/Sep/2006:10:57:28 +0800] StopJob: id = 1116, force = 0
> D [16/Sep/2006:10:57:28 +0800] StopJob: printer state is 3
> D [16/Sep/2006:10:57:29 +0800] ReadClient: 9 GET /printers/hp_laserjet_3015 HTTP/1.1
> D [16/Sep/2006:10:57:29 +0800] CGI /usr/lib/cups/cgi-bin/printers.cgi started - PID = 1930
> I [16/Sep/2006:10:57:29 +0800] Started "/usr/lib/cups/cgi-bin/printers.cgi" (pid=1930)
> D [16/Sep/2006:10:57:29 +0800] SendCommand: 9 file=8
> D [16/Sep/2006:10:57:29 +0800] AcceptClient: 7 from localhost:631.
> D [16/Sep/2006:10:57:29 +0800] ReadClient: 7 POST / HTTP/1.1
> D [16/Sep/2006:10:57:30 +0800] ProcessIPPRequest: 7 status_code=1
> D [16/Sep/2006:10:57:30 +0800] ReadClient: 7 POST / HTTP/1.1
> D [16/Sep/2006:10:57:30 +0800] ProcessIPPRequest: 7 status_code=1
> D [16/Sep/2006:10:57:30 +0800] ReadClient: 7 POST / HTTP/1.1
> D [16/Sep/2006:10:57:30 +0800] ProcessIPPRequest: 7 status_code=1
> D [16/Sep/2006:10:57:30 +0800] CloseClient: 7
> D [16/Sep/2006:10:57:30 +0800] ReadClient: 5 GET /images/show-completed.gif HTTP/1.1
> D [16/Sep/2006:10:57:30 +0800] SendFile: 5 file=7
> 
> 

You should have seen in your error log that one of the filters, foomatic-rip, died with
status 22. To get more diagnostic information, look into the foomatic-rip script and modify
the statement
	$debug = 0;
to
	$debug = 1;
which will cause foomatic-rip to spit out lots of diagnostic information. That should give
you hints on why this filter died.

Helge


-- 
Helge Blischke
Softwareentwicklung
SRZ Berlin | Firmengruppe besscom
http://www.srz.de