Using esup-cups-backend
- Pascal AUBRY
Owned by Pascal AUBRY
Setting up printers to use esup-cupsbackend
Once esup-cupsbackend is installed (see esup-cupsbackend - Install and upgrade), the CUPS interface (http://your-server:631) should now present a new backend name ESUP-Portail when modifying a printer.
URIS of printers with the ESUP-Portail backend look like:
esup://<printer_ip_or_fqdn>?model=<model>&options
Available models are hp, lexmark, xerox, toshiba, dell, jetdirectNoAccounting, jetdirectGenericSnmpAccounting, jetdirectGenericSnmpAccountingPjlInfo (have a look at /properties/domain/domain.xml to add your own models).
Options :
- socketPort=<socket_port> (jetdirect printers only)
- lpdPort=<lpd_port> (LPD printers only)
- lpdPath=<lpd_path> (LPD printers only)
- ippPort=<ipp_port> (IPP printers only)
- ippPath=<ipp_path> (IPP printers only)
- pjlPort=<pjl_port> (PJL printers only)
Configuring the logs
esup-cupsbackend uses log4j for the logs, thus the logs are configured by editing the file /properties/logging/log4j.properties.
To turn on debug for the whole esup-cups-backend application, use:
log4j.logger.esup-backend=DEBUG
To turn on debug for a specific printer xxx, use:
log4j.logger.esup-backend=INFO log4j.logger.esup-backend.printer-xxx=DEBUG
esup-cupsbackend should be redeployed when the log4j configuration files are changed for the changes to be taken into account.
Using scripts
esup-cupsbackend provides basic scripts to monitor CUPS, all located in your install directory (usually /usr/local/src/esup-cupsbackend/current):
ps.sh prints a list of the currently running processes of esup-cupsbackend:
[root@server current]# ./ps.sh ****************** queue=ie016023 (pid=18978, start=11:18:29, user=26005200) printer is not ready (OTHER), waiting... - view printer status: ./test-printer.sh ie016023 - trace process: ./trace.sh pid 18978 - trace job: ./trace.sh job 69619 - trace queue: ./trace.sh printer ie016023 - kill all processes: kill -9 18978 ****************** queue=IE016099 (pid=24023, start=11:44:26, user=24002688) printer info: status=READY, counter=548884 - view printer status: ./test-printer.sh IE016099 - trace process: ./trace.sh pid 24023 - trace job: ./trace.sh job 69755 - trace queue: ./trace.sh printer IE016099 - kill all processes: kill -9 24023 ****************** queue=ie031098 (pid=16570, start=11:00:44, user=28003111) printer is not ready (OTHER), waiting... - view printer status: ./test-printer.sh ie031098 - trace process: ./trace.sh pid 16570 - trace job: ./trace.sh job 69554 - trace queue: ./trace.sh printer ie031098 - kill all processes: kill -9 16570
test-printer.sh shows the status of a printer:
[root@server current]# ./test-printer.sh ie024015 status=OTHER, counter=101415
trace.sh shows the last logs related to a printer, a job or a process:
[root@server current]# ./trace.sh job 69753 | more 2007-12-03 11:44:10,797 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - testPage=[false] 2007-12-03 11:44:10,797 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - jobUser=[28002182] 2007-12-03 11:44:10,797 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - jobTitle=[gv_4753ddc9_1_a01examenjuin2007-3.ps.tmp] 2007-12-03 11:44:10,797 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - jobCopies=[1] 2007-12-03 11:44:10,797 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - jobPrintOptions=[job-uuid=urn:uuid:cccfae45-0eb1-3f3c-7e93-001a80b84463] 2007-12-03 11:44:10,797 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - jobFilename=[/var/spool/cups/d69753-001] 2007-12-03 11:44:10,798 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - setJobClientAndUserWithCups() 2007-12-03 11:44:10,799 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - sleeping a while (500) before requesting the server... 2007-12-03 11:44:11,301 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - trying to set user and client by requesting CUPS 2007-12-03 11:44:11,305 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - EsupCupsJob.getJob()... 2007-12-03 11:44:11,305 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - Cups.cupsGetJobs()... 2007-12-03 11:44:11,308 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - Cups.doRequest()... 2007-12-03 11:44:11,308 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - state = REQ_STATE_CREATE_HTTP 2007-12-03 11:44:11,312 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - state = REQ_STATE_WRITE_HTTP_HEADER 2007-12-03 11:44:11,313 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - state = REQ_STATE_WRITE_IPP_HEADER 2007-12-03 11:44:11,313 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - state = REQ_STATE_WRITE_IPP_ATTRS 2007-12-03 11:44:11,313 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - state = REQ_STATE_FINISH_IPP_ATTRS 2007-12-03 11:44:11,313 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - state = REQ_STATE_READ_RESPONSE 2007-12-03 11:44:11,314 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - status = HTTP_OK 2007-12-03 11:44:11,315 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - state = REQ_STATE_DONE 2007-12-03 11:44:11,317 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - found job #69753 from client 'me098142.etu.univ-rennes1.fr' for user '28002 182' 2007-12-03 11:44:11,317 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - printing job... 2007-12-03 11:44:11,317 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - treatJob() 2007-12-03 11:44:11,317 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - checkJob() 2007-12-03 11:44:11,317 INFO [esup-backend.printer-imp-113.job-69753.pid-23947] - checking job #69753... 2007-12-03 11:44:11,453 INFO [esup-backend.printer-imp-113.job-69753.pid-23947] - check result is: IDENT_ACCOUNT 2007-12-03 11:44:11,453 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - retrieving the counter of the printer before launching the job... 2007-12-03 11:44:11,453 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - getPrinterCounterBeforePrinting()... 2007-12-03 11:44:11,490 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - printer info: status=READY, counter=82726 2007-12-03 11:44:11,491 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - printer is ready 2007-12-03 11:44:11,491 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - storing the state of the queue... 2007-12-03 11:44:11,491 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - writeQueueState() 2007-12-03 11:44:11,491 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - trying to write queue state to [/var/tmp/esup-cupsbackend/imp-113-state.pro perties]... 2007-12-03 11:44:11,496 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - current queue state written to [/var/tmp/esup-cupsbackend/imp-113-state.pro perties] 2007-12-03 11:44:11,496 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - launchJobBackend() 2007-12-03 11:44:11,496 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - getLaunchCommandLineParts() 2007-12-03 11:44:11,496 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - backend command line args (9): 2007-12-03 11:44:11,497 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - 0 -> [/home/esup-cupsbackend/utils/launcher] 2007-12-03 11:44:11,497 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - 1 -> [/usr/lib/cups/backend/socket] 2007-12-03 11:44:11,497 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - 2 -> [socket://imp-113.etu.univ-rennes1.fr:9100] 2007-12-03 11:44:11,497 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - 3 -> [69753] 2007-12-03 11:44:11,497 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - 4 -> [28002182] 2007-12-03 11:44:11,497 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - 5 -> [gv_4753ddc9_1_a01examenjuin2007-3.ps.tmp] 2007-12-03 11:44:11,497 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - 6 -> [1] 2007-12-03 11:44:11,497 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - 7 -> [job-uuid=urn:uuid:cccfae45-0eb1-3f3c-7e93-001a80b84463] 2007-12-03 11:44:11,497 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - 8 -> [/var/spool/cups/d69753-001] 2007-12-03 11:44:11,497 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - launching the real backend... 2007-12-03 11:44:11,506 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - running streamGobbler stderr... 2007-12-03 11:44:11,507 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - streamGobbler stderr: waiting... 2007-12-03 11:44:11,507 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - data filename passed to the backend as a command line arg... 2007-12-03 11:44:11,510 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - running streamGobbler stdout... 2007-12-03 11:44:11,511 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - streamGobbler stdout: waiting... 2007-12-03 11:44:11,528 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - printer info: status=READY, counter=82726 2007-12-03 11:44:11,528 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - waiting for the end of the backend process... 2007-12-03 11:44:11,757 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - printer info: status=PRINTING, counter=82726 2007-12-03 11:44:11,757 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - status changed to PRINTING 2007-12-03 11:44:11,983 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - printer info: status=PRINTING, counter=82726 2007-12-03 11:44:12,008 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - streamGobbler stderr: reading... 2007-12-03 11:44:12,009 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - stderr: INFO: tentative de connexion à lâhôte imp-113.etu.univ-rennes1.fr s ur le port 9100 2007-12-03 11:44:12,009 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - stderr: STATE: +connecting-to-device 2007-12-03 11:44:12,009 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - stderr: STATE: -connecting-to-device 2007-12-03 11:44:12,009 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - stderr: INFO: connecté à imp-113.etu.univ-rennes1.fr... 2007-12-03 11:44:12,009 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - stderr: DEBUG: Connected to 148.60.98.11:9100 (IPv4)... 2007-12-03 11:44:12,009 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - stderr: PAGE: 1 1 2007-12-03 11:44:12,009 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - stderr: DEBUG: backendRunLoop(print_fd=3, device_fd=4, use_bc=0, side_cb=(n il)) 2007-12-03 11:44:12,010 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - stderr: DEBUG: Read 8192 bytes of print data... 2007-12-03 11:44:12,010 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - stderr: STATE: -media-empty-error 2007-12-03 11:44:12,010 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - stderr: STATE: -offline-error 2007-12-03 11:44:12,010 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - stderr: INFO: imprimante connectée. 2007-12-03 11:44:12,010 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - stderr: DEBUG: Wrote 8192 bytes of print data... 2007-12-03 11:44:12,010 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - stderr: DEBUG: Read 8192 bytes of print data... [...] 2007-12-03 11:44:12,011 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - stderr: INFO: fichier dâimpression envoyé, 56541 octets... 2007-12-03 11:44:12,011 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - streamGobbler stderr: waiting... 2007-12-03 11:44:12,206 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - printer info: status=PRINTING, counter=82726 [...] 2007-12-03 11:44:14,894 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - printer info: status=PRINTING, counter=82726 2007-12-03 11:44:15,023 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - streamGobbler stderr: reading... 2007-12-03 11:44:15,024 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - stderr: DEBUG: Received 10 bytes of back-channel data! 2007-12-03 11:44:15,024 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - streamGobbler stderr: waiting... 2007-12-03 11:44:15,117 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - printer info: status=PRINTING, counter=82726 [...] 2007-12-03 11:44:17,352 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - printer info: status=PRINTING, counter=82726 2007-12-03 11:44:17,534 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - streamGobbler stderr: reading... 2007-12-03 11:44:17,535 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - stderr: DEBUG: Received 1 bytes of back-channel data! 2007-12-03 11:44:17,535 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - streamGobbler stderr: waiting... 2007-12-03 11:44:17,573 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - printer info: status=PRINTING, counter=82726 2007-12-03 11:44:22,228 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - printer info: status=PRINTING, counter=82727 2007-12-03 11:44:22,431 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - backend exit value = 0 2007-12-03 11:44:22,431 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - waiting for the end of the treatment... 2007-12-03 11:44:22,431 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - waiting for the printer to start... 2007-12-03 11:44:22,433 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - starting a timer for 30 seconds... 2007-12-03 11:44:22,451 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - printer info: status=PRINTING, counter=82727 2007-12-03 11:44:22,451 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - waiting for the printer to finish... 2007-12-03 11:44:22,452 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - timer was interrupted! 2007-12-03 11:44:22,471 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - printer info: status=PRINTING, counter=82727 2007-12-03 11:44:22,471 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - printer is not ready (PRINTING), waiting... 2007-12-03 11:44:22,554 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - streamGobbler stderr: reading... 2007-12-03 11:44:22,555 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - stderr: INFO: fichier dâimpression envoyé, en attente de la fin de la tâche dâimpression... 2007-12-03 11:44:22,555 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - stderr: INFO: prêt pour lâimpression. 2007-12-03 11:44:22,555 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - streamGobbler stderr: waiting... 2007-12-03 11:44:27,492 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - printer info: status=PRINTING, counter=82728 2007-12-03 11:44:27,492 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - printer is not ready (PRINTING), waiting... 2007-12-03 11:44:32,514 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - printer info: status=READY, counter=82728 2007-12-03 11:44:32,514 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - status changed to READY 2007-12-03 11:44:32,514 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - printer is now ready, starting the timer (30 seconds). 2007-12-03 11:44:33,036 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - printer info: status=READY, counter=82728 2007-12-03 11:45:02,752 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - printer is ready with the same counter (82728) for more than 30 seconds, considering the the printer has finished. 2007-12-03 11:45:02,752 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - The printer has finished. 2007-12-03 11:45:02,752 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - logAcceptedJob() 2007-12-03 11:45:02,753 INFO [esup-backend.printer-imp-113.job-69753.pid-23947] - user [28002182] has printed job #69753 ([gv_4753ddc9_1_a01examenjuin2007-3.p s.tmp]) on queue [imp-113] from client [me098142.etu.univ-rennes1.fr] (2 pages) 2007-12-03 11:45:02,753 INFO [esup-backend.printer-imp-113.job-69753.pid-23947] - logging job #69753... 2007-12-03 11:45:02,753 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - ident=[true] 2007-12-03 11:45:02,753 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - impactCredits=[true] 2007-12-03 11:45:02,778 INFO [esup-backend.printer-imp-113.job-69753.pid-23947] - job #69753 has been accounted. 2007-12-03 11:45:02,778 DEBUG [esup-backend.printer-imp-113.job-69753.pid-23947] - deleting the state of the queue...