root / pykota / trunk / bin / cupspykota @ 1923

#! /usr/bin/env python
# -*- coding: ISO-8859-15 -*-

# CUPSPyKota accounting backend
#
# PyKota - Print Quotas for CUPS and LPRng
#
# (c) 2003-2004 Jerome Alet <alet@librelogiciel.com>
# This program is free software; you can redistribute it and/or modify
# it under the terms of the GNU General Public License as published by
# the Free Software Foundation; either version 2 of the License, or
# (at your option) any later version.
#
# This program is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
# GNU General Public License for more details.
# 
# You should have received a copy of the GNU General Public License
# along with this program; if not, write to the Free Software
# Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307, USA.
#
# $Id$
#
# $Log$
# Revision 1.79  2004/11/15 22:01:34  jalet
# Improved banner handling.
# Fix for raw printing and banners.
#
# Revision 1.78  2004/11/15 19:59:34  jalet
# PyKota banners now basically work !
#
# Revision 1.77  2004/11/06 22:40:57  jalet
# Safer code
#
# Revision 1.76  2004/11/06 22:35:58  jalet
# Added a miniparser for IPP messages (RFC 2910). The job-originating-host-name
# retrieval is now fiable, unless the CUPS developpers change something...
#
# Revision 1.75  2004/11/01 15:45:25  jalet
# Added many debug messages.
# Added some code to prevent short writes.
#
# Revision 1.74  2004/10/13 20:51:27  jalet
# Made debugging levels be the same in cupspykota and lprngpykota.
# Now outputs more information in informational messages : user, printer, jobid
#
# Revision 1.73  2004/10/13 16:56:45  jalet
# Added a space to the pattern to differentiate jobs which id begins with
# the same digits, like jobs 87 and 879 for example : if printed by same
# user on same printer, but from a different host this could have broken
# the result. (In reality this couldn't happen because 879 would be the
# last line to match anyway because of job ordering, but we never know
# if the page_log file gets corrupt somewhat)
#
# Revision 1.72  2004/09/13 16:02:44  jalet
# Added fix for incorrect job's size when hardware accounting fails
#
# Revision 1.71  2004/09/06 17:05:06  jalet
# Fix for autodetection of SC_OPEN_MAX
#
# Revision 1.70  2004/07/26 09:20:27  jalet
# Unneeded module
#
# Revision 1.69  2004/07/22 22:41:47  jalet
# Hardware accounting for LPRng should be OK now. UNTESTED.
#
# Revision 1.68  2004/07/20 22:19:44  jalet
# Sanitized a bit + use of gettext
#
# Revision 1.67  2004/07/16 12:22:45  jalet
# LPRng support early version
#
# Revision 1.66  2004/07/01 19:56:25  jalet
# Better dispatching of error messages
#
# Revision 1.65  2004/06/22 09:31:17  jalet
# Always send some debug info to CUPS' back channel stream (stderr) as
# informationnal messages.
#
# Revision 1.64  2004/06/18 13:34:46  jalet
# Now all tracebacks include PyKota's version number
#
# Revision 1.63  2004/06/17 13:26:50  jalet
# Better exception handling code
#
# Revision 1.62  2004/06/16 20:56:34  jalet
# Smarter initialisation code
#
# Revision 1.61  2004/06/08 09:00:04  jalet
# Fixed problem when username was passed in uppercase from Samba and we
# tried to find correct line in CUPS page_log to extract the hostname.
#
# Revision 1.60  2004/06/03 23:14:08  jalet
# Now stores the job's size in bytes in the database.
# Preliminary work on payments storage : database schemas are OK now,
# but no code to store payments yet.
# Removed schema picture, not relevant anymore.
#
# Revision 1.59  2004/06/03 22:12:53  jalet
# Now denies empty jobs
#
# Revision 1.58  2004/06/03 21:50:33  jalet
# Improved error logging.
# crashrecipient directive added.
# Now exports the job's size in bytes too.
#
# Revision 1.57  2004/06/02 22:18:07  jalet
# I think the bug when cancelling jobs should be fixed right now
#
# Revision 1.56  2004/06/02 21:50:56  jalet
# Moved the sigterm capturing elsewhere
#
# Revision 1.55  2004/06/02 14:25:07  jalet
# Should correctly capture ALL errors now
#
# Revision 1.54  2004/05/26 16:44:48  jalet
# Now logs something when client hostname can't be extracted
#
# Revision 1.53  2004/05/26 14:49:35  jalet
# First try at saving the job-originating-hostname in the database
#
# Revision 1.52  2004/05/25 09:15:13  jalet
# accounter.py : old code deleted
# the rest : now exports PYKOTAPRECOMPUTEDJOBSIZE and PYKOTAPRECOMPUTEDJOBPRICE
#
# Revision 1.51  2004/05/25 08:31:16  jalet
# Heavy CPU usage seems to be fixed at least !
#
# Revision 1.50  2004/05/25 05:17:50  jalet
# Now precomputes the job's size only if current printer's enforcement
# is "STRICT"
#
# Revision 1.49  2004/05/24 22:45:48  jalet
# New 'enforcement' directive added
# Polling loop improvements
#
# Revision 1.48  2004/05/24 14:36:24  jalet
# Revert to old polling loop. Will need optimisations
#
# Revision 1.47  2004/05/24 11:59:46  jalet
# More robust (?) code
#
# Revision 1.46  2004/05/21 22:02:51  jalet
# Preliminary work on pre-accounting
#
# Revision 1.45  2004/05/19 07:15:32  jalet
# Could the 'misterious' bug in my loop be finally fixed ???
#
# Revision 1.44  2004/05/18 14:48:47  jalet
# Big code changes to completely remove the need for "requester" directives,
# jsut use "hardware(... your previous requester directive's content ...)"
#
# Revision 1.43  2004/05/17 11:46:05  jalet
# First try at cupspykota's main loop rewrite
#
# Revision 1.42  2004/05/10 11:22:28  jalet
# Typo
#
# Revision 1.41  2004/05/10 10:07:30  jalet
# Catches OSError while reading
#
# Revision 1.40  2004/05/10 09:29:48  jalet
# Should be more robust if we receive a SIGTERM during an I/O operation
#
# Revision 1.39  2004/05/07 14:44:53  jalet
# Fix for file handles unregistered twice from the polling object
#
# Revision 1.38  2004/04/09 22:24:46  jalet
# Began work on correct handling of child processes when jobs are cancelled by
# the user. Especially important when an external requester is running for a
# long time.
#
# Revision 1.37  2004/03/18 19:11:25  jalet
# Fix for raw jobs in cupspykota
#
# Revision 1.36  2004/03/18 14:03:18  jalet
# Added fsync() calls
#
# Revision 1.35  2004/03/16 12:05:01  jalet
# Small fix for new waitprinter.sh : when job was denied, would wait forever
# for printer being in printing mode.
#
# Revision 1.34  2004/03/15 10:47:56  jalet
# This time the traceback formatting should be correct !
#
# Revision 1.33  2004/03/05 12:46:07  jalet
# Improve tracebacks
#
# Revision 1.32  2004/03/05 12:31:35  jalet
# Now should output full traceback when crashing
#
# Revision 1.31  2004/03/01 14:35:56  jalet
# PYKOTAPHASE wasn't set soon enough at the start of the job
#
# Revision 1.30  2004/03/01 14:34:15  jalet
# PYKOTAPHASE wasn't set at the right time at the end of data transmission
# to underlying layer (real backend)
#
# Revision 1.29  2004/03/01 11:23:25  jalet
# Pre and Post hooks to external commands are available in the cupspykota
# backend. Forthe pykota filter they will be implemented real soon now.
#
# Revision 1.28  2004/02/26 14:18:07  jalet
# Should fix the remaining bugs wrt printers groups and users groups.
#
# Revision 1.27  2004/02/04 23:41:27  jalet
# Should fix the incorrect "backend died abnormally" problem.
#
# Revision 1.26  2004/01/30 16:35:03  jalet
# Fixes stupid software accounting bug in CUPS backend
#
# Revision 1.25  2004/01/16 17:51:46  jalet
# Fuck Fuck Fuck !!!
#
# Revision 1.24  2004/01/14 15:52:01  jalet
# Small fix for job cancelling code.
#
# Revision 1.23  2004/01/13 10:48:28  jalet
# Small streams polling loop modification.
#
# Revision 1.22  2004/01/12 22:43:40  jalet
# New formula to compute a job's price
#
# Revision 1.21  2004/01/12 18:17:36  jalet
# Denied jobs weren't stored into the history anymore, this is now fixed.
#
# Revision 1.20  2004/01/11 23:22:42  jalet
# Major code refactoring, it's way cleaner, and now allows automated addition
# of printers on first print.
#
# Revision 1.19  2004/01/08 14:10:32  jalet
# Copyright year changed.
#
# Revision 1.18  2004/01/07 16:16:32  jalet
# Better debugging information
#
# Revision 1.17  2003/12/27 16:49:25  uid67467
# Should be ok now.
#
# Revision 1.17  2003/12/06 08:54:29  jalet
# Code simplifications.
# Added many debugging messages.
#
# Revision 1.16  2003/11/26 20:43:29  jalet
# Inadvertantly introduced a bug, which is fixed.
#
# Revision 1.15  2003/11/26 19:17:35  jalet
# Printing on a printer not present in the Quota Storage now results
# in the job being stopped or cancelled depending on the system.
#
# Revision 1.14  2003/11/25 13:25:45  jalet
# Boolean problem with old Python, replaced with 0
#
# Revision 1.13  2003/11/23 19:01:35  jalet
# Job price added to history
#
# Revision 1.12  2003/11/21 14:28:43  jalet
# More complete job history.
#
# Revision 1.11  2003/11/19 23:19:35  jalet
# Code refactoring work.
# Explicit redirection to /dev/null has to be set in external policy now, just
# like in external mailto.
#
# Revision 1.10  2003/11/18 17:54:24  jalet
# SIGTERMs are now transmitted to original backends.
#
# Revision 1.9  2003/11/18 14:11:07  jalet
# Small fix for bizarre urls
#
# Revision 1.8  2003/11/15 14:26:44  jalet
# General improvements to the documentation.
# Email address changed in sample configuration file, because
# I receive low quota messages almost every day...
#
# Revision 1.7  2003/11/14 22:05:12  jalet
# New CUPS backend fully functionnal.
# Old CUPS configuration method is now officially deprecated.
#
# Revision 1.6  2003/11/14 20:13:11  jalet
# We exit the loop too soon.
#
# Revision 1.5  2003/11/14 18:31:27  jalet
# Not perfect, but seems to work with the poll() loop.
#
# Revision 1.4  2003/11/14 17:04:15  jalet
# More (untested) work on the CUPS backend.
#
# Revision 1.3  2003/11/12 23:27:44  jalet
# More work on new backend. This commit may be unstable.
#
# Revision 1.2  2003/11/12 09:33:34  jalet
# New CUPS backend supports device enumeration
#
# Revision 1.1  2003/11/08 16:05:31  jalet
# CUPS backend added for people to experiment.
#
#
#

import sys
import os
import popen2
import cStringIO
import shlex
import select
import signal
import time

from pykota.tool import PyKotaFilterOrBackend, PyKotaToolError, crashed
from pykota.config import PyKotaConfigError
from pykota.storage import PyKotaStorageError
from pykota.accounter import PyKotaAccounterError
from pykota.ipp import IPPMessage, PyKotaIPPError
    
class PyKotaPopen4(popen2.Popen4) :
    """Our own class to execute real backends.
    
       Their first argument is different from their path so using
       native popen2.Popen3 would not be feasible.
    """
    def __init__(self, cmd, bufsize=-1, arg0=None) :
        self.arg0 = arg0
        popen2.Popen4.__init__(self, cmd, bufsize)
        
    def _run_child(self, cmd):
        try :
            MAXFD = os.sysconf("SC_OPEN_MAX")
        except (AttributeError, ValueError) :    
            MAXFD = 256
        for i in range(3, MAXFD) : 
            try:
                os.close(i)
            except OSError:
                pass
        try:
            os.execvpe(cmd[0], [self.arg0 or cmd[0]] + cmd[1:], os.environ)
        finally:
            os._exit(1)
    
class PyKotaBackend(PyKotaFilterOrBackend) :        
    """A class for the pykota backend."""
    def acceptJob(self) :        
        """Returns the appropriate exit code to tell CUPS all is OK."""
        return 0
            
    def removeJob(self) :            
        """Returns the appropriate exit code to let CUPS think all is OK.
        
           Returning 0 (success) prevents CUPS from stopping the print queue.
        """   
        return 0
        
    def getCupsConfigDirectives(self, directives=[]) :
        """Retrieves some CUPS directives from its configuration file.
        
           Returns a mapping with lowercased directives as keys and 
           their setting as values.
        """
        dirvalues = {} 
        cupsroot = os.environ.get("CUPS_SERVERROOT", "/etc/cups")
        cupsdconf = os.path.join(cupsroot, "cupsd.conf")
        try :
            conffile = open(cupsdconf, "r")
        except IOError :    
            self.logdebug("Unable to open %s" % cupsdconf)
        else :    
            for line in conffile.readlines() :
                linecopy = line.strip().lower()
                for di in [d.lower() for d in directives] :
                    if linecopy.startswith("%s " % di) :
                        try :
                            val = line.split()[1]
                        except :    
                            pass # ignore errors, we take the last value in any case.
                        else :    
                            dirvalues[di] = val
            conffile.close()            
        return dirvalues       
            
    def getJobOriginatingHostnameFromPageLog(self, cupsconfig, printername, username, jobid) :
        """Retrieves the job-originating-hostname from the CUPS page_log file if possible."""
        pagelogpath = cupsconfig.get("pagelog", "/var/log/cups/page_log")
        self.logdebug("Trying to extract job-originating-host-name from %s" % pagelogpath)
        try :
            pagelog = open(pagelogpath, "r")
        except IOError :    
            self.logdebug("Unable to open %s" % pagelogpath)
            return # no page log or can't read it, originating hostname unknown yet
        else :    
            # TODO : read backward so we could take first value seen
            # TODO : here we read forward so we must take the last value seen
            prefix = ("%s %s %s " % (printername, username, jobid)).lower()
            matchingline = None
            while 1 :
                line = pagelog.readline()
                if not line :
                    break
                else :
                    line = line.strip()
                    if line.lower().startswith(prefix) :    
                        matchingline = line # no break, because we read forward
            pagelog.close()        
            if matchingline is None :
                self.logdebug("No matching line found in %s" % pagelogpath)
                return # correct line not found, job-originating-host-name unknown
            else :    
                return matchingline.split()[-1]
                
    def doWork(self, policy, printer, user, userpquota) :    
        """Most of the work is done here."""
        # Two different values possible for policy here :
        # ALLOW means : Either printer, user or user print quota doesn't exist,
        #               but the job should be allowed anyway.
        # OK means : Both printer, user and user print quota exist, job should
        #            be allowed if current user is allowed to print on this printer
        if policy == "OK" :
            # exports user information with initial values
            self.exportUserInfo(userpquota)
            
            # tries to extract job-originating-host-name and other information
            cupsdconf = self.getCupsConfigDirectives(["PageLog", "RequestRoot"])
            requestroot = cupsdconf.get("requestroot", "/var/spool/cups")
            if (len(self.jobid) < 5) and self.jobid.isdigit() :
                ippmessagefile = "c%05i" % int(self.jobid)
            else :    
                ippmessagefile = "c%s" % self.jobid
            ippmessagefile = os.path.join(requestroot, ippmessagefile)
            ippmessage = {}
            try :
                ippdatafile = open(ippmessagefile)
            except :    
                self.printInfo("Unable to open IPP message file %s" % ippmessagefile, "warn")
            else :    
                self.logdebug("Parsing of IPP message file %s begins." % ippmessagefile)
                try :
                    ippmessage = IPPMessage(ippdatafile.read())
                except PyKotaIPPError, msg :    
                    self.printInfo("Error while parsing %s : %s" % (ippmessagefile, msg), "warn")
                else :    
                    self.logdebug("Parsing of IPP message file %s ends." % ippmessagefile)
                ippdatafile.close()
                
            clienthost = ippmessage.get("job-originating-host-name") \
                         or self.getJobOriginatingHostnameFromPageLog(cupsdconf, printer.Name, user.Name, self.jobid)
            self.logdebug("Client Hostname : %s" % (clienthost or "Unknown"))    
            os.environ["PYKOTAJOBORIGINATINGHOSTNAME"] = str(clienthost or "")
            
            # TODO : extract username (double check ?) and billing code too
            
            # enters first phase
            os.environ["PYKOTAPHASE"] = "BEFORE"
            
            # do we want strict or laxist quota enforcement ?
            if self.config.getPrinterEnforcement(printer.Name) == "STRICT" :
                self.softwareJobSize = self.precomputeJobSize()
                self.softwareJobPrice = userpquota.computeJobPrice(self.softwareJobSize)
                self.logdebug("Precomputed job's size is %s pages, price is %s units" % (self.softwareJobSize, self.softwareJobPrice))
            os.environ["PYKOTAPRECOMPUTEDJOBSIZE"] = str(self.softwareJobSize)
            os.environ["PYKOTAPRECOMPUTEDJOBPRICE"] = str(self.softwareJobPrice)
            
            # if no data to pass to real backend, probably a filter
            # higher in the chain failed because of a misconfiguration.
            # we deny the job in this case (nothing to print anyway)
            if not self.jobSizeBytes :
                self.printMoreInfo(user, printer, _("Job contains no data. Printing is denied."), "warn")
                action = "DENY"
            else :    
                # checks the user's quota
                action = self.warnUserPQuota(userpquota)
            
            # exports some new environment variables
            os.environ["PYKOTAACTION"] = action
            
            # launches the pre hook
            self.prehook(userpquota)

            # saves the size of banners which have to be accounted for
            # this is needed in the case of software accounting
            bannersize = 0
            
            # handle starting banner pages before accounting
            accountbanner = self.config.getAccountBanner(printer.Name)
            if accountbanner in ["ENDING", "NONE"] :
                banner = self.startingBanner(printer.Name)
                if banner :
                    self.logdebug("Printing starting banner before accounting begins.")
                    self.handleData(banner)
 
            self.printMoreInfo(user, printer, _("Job accounting begins."))
            self.accounter.beginJob(printer)
            
            # handle starting banner pages during accounting
            if accountbanner in ["STARTING", "BOTH"] :
                banner = self.startingBanner(printer.Name)
                if banner :
                    self.logdebug("Printing starting banner during accounting.")
                    self.handleData(banner)
                    if self.accounter.isSoftware :
                        bannersize += 1 # TODO : fix this by passing the banner's content through PDLAnalyzer
        else :    
            action = "ALLOW"
            os.environ["PYKOTAACTION"] = action
            
        # pass the job's data to the real backend    
        if action in ["ALLOW", "WARN"] :
            if self.gotSigTerm :
                retcode = self.removeJob()
            else :    
                retcode = self.handleData()        
        else :        
            retcode = self.removeJob()
        
        if policy == "OK" :        
            # indicate phase change
            os.environ["PYKOTAPHASE"] = "AFTER"
            
            # handle ending banner pages during accounting
            if accountbanner in ["ENDING", "BOTH"] :
                banner = self.endingBanner(printer.Name)
                if banner :
                    self.logdebug("Printing ending banner during accounting.")
                    self.handleData(banner)
                    if self.accounter.isSoftware :
                        bannersize += 1 # TODO : fix this by passing the banner's content through PDLAnalyzer
 
            # stops accounting. 
            self.accounter.endJob(printer)
            self.printMoreInfo(user, printer, _("Job accounting ends."))
                
            # retrieve the job size    
            if action == "DENY" :
                jobsize = 0
                self.printMoreInfo(user, printer, _("Job size forced to 0 because printing is denied."))
            else :    
                jobsize = self.accounter.getJobSize(printer) + bannersize
            self.printMoreInfo(user, printer, _("Job size : %i") % jobsize)
            
            # update the quota for the current user on this printer 
            self.printInfo(_("Updating user %s's quota on printer %s") % (user.Name, printer.Name))
            jobprice = userpquota.increasePagesUsage(jobsize)
            
            # adds the current job to history    
            printer.addJobToHistory(self.jobid, user, self.accounter.getLastPageCounter(), action, jobsize, jobprice, self.preserveinputfile, self.title, self.copies, self.options, clienthost, self.jobSizeBytes)
            self.printMoreInfo(user, printer, _("Job added to history."))
            
            # exports some new environment variables
            os.environ["PYKOTAJOBSIZE"] = str(jobsize)
            os.environ["PYKOTAJOBPRICE"] = str(jobprice)
            
            # then re-export user information with new value
            self.exportUserInfo(userpquota)
            
            # handle ending banner pages after accounting ends
            if accountbanner in ["STARTING", "NONE"] :
                banner = self.endingBanner(printer.Name)
                if banner :
                    self.logdebug("Printing ending banner after accounting ends.")
                    self.handleData(banner)
            
            # Launches the post hook
            self.posthook(userpquota)
            
        return retcode    
               
    def unregisterFileNo(self, pollobj, fileno) :                
        """Removes a file handle from the polling object."""
        try :
            pollobj.unregister(fileno)
        except KeyError :    
            self.printInfo(_("File number %s unregistered twice from polling object, ignored.") % fileno, "warn")
        except :    
            self.logdebug("Error while unregistering file number %s from polling object." % fileno)
        else :    
            self.logdebug("File number %s unregistered from polling object." % fileno)
            
    def formatFileEvent(self, fd, mask) :        
        """Formats file debug info."""
        maskval = []
        if mask & select.POLLIN :
            maskval.append("POLLIN")
        if mask & select.POLLOUT :
            maskval.append("POLLOUT")
        if mask & select.POLLPRI :
            maskval.append("POLLPRI")
        if mask & select.POLLERR :
            maskval.append("POLLERR")
        if mask & select.POLLHUP :
            maskval.append("POLLHUP")
        if mask & select.POLLNVAL :
            maskval.append("POLLNVAL")
        return "%s (%s)" % (fd, " | ".join(maskval))
        
    def handleData(self, filehandle=None) :
        """Pass the job's data to the real backend."""
        # Find the real backend pathname    
        realbackend = os.path.join(os.path.split(sys.argv[0])[0], self.originalbackend)
        
        # And launch it
        if filehandle is None :
            arguments = sys.argv
        else :    
            # Here we absolutely WANT to remove any filename from the command line !
            arguments = [ "Fake this because we are printing a banner" ] + sys.argv[1:6]
        self.logdebug("Starting real backend %s with args %s" % (realbackend, " ".join(['"%s"' % a for a in ([os.environ["DEVICE_URI"]] + arguments)])))
        subprocess = PyKotaPopen4([realbackend] + arguments, bufsize=0, arg0=os.environ["DEVICE_URI"])
        
        # Save file descriptors, we will need them later.
        stderrfno = sys.stderr.fileno()
        fromcfno = subprocess.fromchild.fileno()
        tocfno = subprocess.tochild.fileno()
        
        # We will have to be careful when dealing with I/O 
        # So we use a poll object to know when to read or write
        pollster = select.poll()
        pollster.register(fromcfno, select.POLLIN | select.POLLPRI)
        pollster.register(stderrfno, select.POLLOUT)
        pollster.register(tocfno, select.POLLOUT)
        
        # Initialize our buffers
        indata = ""
        outdata = ""
        endinput = endoutput = 0
        inputclosed = outputclosed = 0
        totaltochild = totalfromcups = 0
        totalfromchild = totaltocups = 0
        
        if filehandle is None:
            if self.preserveinputfile is None :
               # this is not a real file, we read the job's data
                # from our temporary file which is a copy of stdin 
                infno = self.jobdatastream.fileno()
                self.jobdatastream.seek(0)
                pollster.register(infno, select.POLLIN | select.POLLPRI)
            else :    
                # job's data is in a file, no need to pass the data
                # to the real backend
                self.logdebug("Job's data is in %s" % self.preserveinputfile)
                infno = None
                endinput = 1
        else:
            self.logdebug("Printing data passed from filehandle")
            indata = filehandle.read()
            infno = None
            endinput = 1
            filehandle.close()
        
        self.logdebug("Entering streams polling loop...")
        MEGABYTE = 1024*1024
        killed = 0
        status = -1
        while (status == -1) and (not killed) and not (inputclosed and outputclosed) :
            # First check if original backend is still alive
            status = subprocess.poll()
            
            # Now if we got SIGTERM, we have 
            # to kill -TERM the original backend
            if self.gotSigTerm and not killed :
                try :
                    os.kill(subprocess.pid, signal.SIGTERM)
                except OSError, msg : # ignore but logs if process was already killed.
                    self.logdebug("Error while sending signal to pid %s : %s" % (subprocess.pid, msg))
                else :    
                    self.printInfo(_("SIGTERM was sent to real backend %s (pid: %s)") % (realbackend, subprocess.pid))
                    killed = 1
            
            # In any case, deal with any remaining I/O
            try :
                availablefds = pollster.poll(5000)
            except select.error, msg :    
                self.logdebug("Interrupted poll : %s" % msg)
                availablefds = []
            if not availablefds :
                self.logdebug("Nothing to do, sleeping a bit...")
                time.sleep(0.01) # give some time to the system
            else :
                for (fd, mask) in availablefds :
                    # self.logdebug(self.formatFileEvent(fd, mask))
                    try :
                        if mask & select.POLLOUT :
                            # We can write
                            if fd == tocfno :
                                if indata :
                                    try :
                                        nbwritten = os.write(fd, indata)    
                                    except (OSError, IOError), msg :    
                                        self.logdebug("Error while writing to real backend's stdin %s : %s" % (fd, msg))
                                    else :    
                                        if len(indata) != nbwritten :
                                            self.logdebug("Short write to real backend's input !")
                                        totaltochild += nbwritten    
                                        self.logdebug("%s bytes sent to real backend so far..." % totaltochild)
                                        indata = indata[nbwritten:]
                                else :        
                                    self.logdebug("No data to send to real backend yet, sleeping a bit...")
                                    time.sleep(0.01)
                                    
                                if endinput :    
                                    self.unregisterFileNo(pollster, tocfno)        
                                    self.logdebug("Closing real backend's stdin.")
                                    os.close(tocfno)
                                    inputclosed = 1
                            elif fd == stderrfno :
                                if outdata :
                                    try :
                                        nbwritten = os.write(fd, outdata)
                                    except (OSError, IOError), msg :    
                                        self.logdebug("Error while writing to CUPS back channel (stderr) %s : %s" % (fd, msg))
                                    else :
                                        if len(outdata) != nbwritten :
                                            self.logdebug("Short write to stderr (CUPS) !")
                                        totaltocups += nbwritten    
                                        self.logdebug("%s bytes sent back to CUPS so far..." % totaltocups)
                                        outdata = outdata[nbwritten:]
                                else :        
                                    # self.logdebug("No data to send back to CUPS yet, sleeping a bit...") # Uncommenting this fills your logs
                                    time.sleep(0.01) # Give some time to the system, stderr is ALWAYS writeable it seems.
                                    
                                if endoutput :    
                                    self.unregisterFileNo(pollster, stderrfno)        
                                    outputclosed = 1
                            else :    
                                self.logdebug("Unexpected : %s - Sleeping a bit..." % self.formatFileEvent(fd, mask))
                                time.sleep(0.01)
                                
                        if mask & (select.POLLIN | select.POLLPRI) :     
                            # We have something to read
                            try :
                                data = os.read(fd, MEGABYTE)
                            except (IOError, OSError), msg :    
                                self.logdebug("Error while reading file %s : %s" % (fd, msg))
                            else :
                                if fd == infno :
                                    if not data :    # If yes, then no more input data
                                        self.unregisterFileNo(pollster, infno)
                                        self.logdebug("Input data ends.")
                                        endinput = 1 # this happens with real files.
                                    else :    
                                        indata += data
                                        totalfromcups += len(data)
                                        self.logdebug("%s bytes read from CUPS so far..." % totalfromcups)
                                elif fd == fromcfno :
                                    if not data :
                                        self.logdebug("No back channel data to read from real backend yet, sleeping a bit...")
                                        time.sleep(0.01)
                                    else :
                                        outdata += data
                                        totalfromchild += len(data)
                                        self.logdebug("%s bytes read from real backend so far..." % totalfromchild)
                                else :    
                                    self.logdebug("Unexpected : %s - Sleeping a bit..." % self.formatFileEvent(fd, mask))
                                    time.sleep(0.01)
                                    
                        if mask & (select.POLLHUP | select.POLLERR) :
                            # Treat POLLERR as an EOF.
                            # Some standard I/O stream has no more datas
                            self.unregisterFileNo(pollster, fd)
                            if fd == infno :
                                # Here we are in the case where the input file is stdin.
                                # which has no more data to be read.
                                self.logdebug("Input data ends.")
                                endinput = 1
                            elif fd == fromcfno :    
                                # We are no more interested in this file descriptor        
                                self.logdebug("Closing real backend's stdout+stderr.")
                                os.close(fromcfno)
                                endoutput = 1
                            else :    
                                self.logdebug("Unexpected : %s - Sleeping a bit..." % self.formatFileEvent(fd, mask))
                                time.sleep(0.01)
                                
                        if mask & select.POLLNVAL :        
                            self.logdebug("File %s was closed. Unregistering from polling object." % fd)
                            self.unregisterFileNo(pollster, fd)
                    except IOError, msg :            
                        self.logdebug("Got an IOError : %s" % msg) # we got signalled during an I/O
                
        # We must close the real backend's input stream
        if killed and not inputclosed :
            self.logdebug("Forcing close of real backend's stdin.")
            os.close(tocfno)
        
        self.logdebug("Exiting streams polling loop...")
        
        self.logdebug("input data's final length : %s" % len(indata))
        self.logdebug("back-channel data's final length : %s" % len(outdata))
        
        self.logdebug("Total bytes read from CUPS (job's datas) : %s" % totalfromcups)
        self.logdebug("Total bytes sent to real backend (job's datas) : %s" % totaltochild)
        
        self.logdebug("Total bytes read from real backend (back-channel datas) : %s" % totalfromchild)
        self.logdebug("Total bytes sent back to CUPS (back-channel datas) : %s" % totaltocups)
        
        # Check exit code of original CUPS backend.    
        if status == -1 :
            # we exited the loop before the real backend exited
            # now we have to wait for it to finish and get its status
            self.logdebug("Waiting for real backend to exit...")
            try :
                status = subprocess.wait()
            except OSError : # already dead    
                status = 0
        if os.WIFEXITED(status) :
            retcode = os.WEXITSTATUS(status)
        elif not killed :    
            self.sendBackChannelData(_("CUPS backend %s died abnormally.") % realbackend, "error")
            retcode = -1
        else :    
            retcode = self.removeJob()
        return retcode    
    
if __name__ == "__main__" :    
    # This is a CUPS backend, we should act and die like a CUPS backend
    retcode = 0
    if len(sys.argv) == 1 :
        # we will execute each existing backend in device enumeration mode
        # and generate their PyKota accounting counterpart
        (directory, myname) = os.path.split(sys.argv[0])
        for backend in [os.path.join(directory, b) for b in os.listdir(directory) if os.path.isfile(os.path.join(directory, b)) and (b != myname)] :
            answer = os.popen(backend, "r")
            try :
                devices = [line.strip() for line in answer.readlines()]
            except :    
                devices = []
            status = answer.close()
            if status is None :
                for d in devices :
                    # each line is of the form : 'xxxx xxxx "xxxx xxx" "xxxx xxx"'
                    # so we have to decompose it carefully
                    fdevice = cStringIO.StringIO("%s" % d)
                    tokenizer = shlex.shlex(fdevice)
                    tokenizer.wordchars = tokenizer.wordchars + r".:,?!~/\_$*-+={}[]()#"
                    arguments = []
                    while 1 :
                        token = tokenizer.get_token()
                        if token :
                            arguments.append(token)
                        else :
                            break
                    fdevice.close()
                    try :
                        (devicetype, device, name, fullname) = arguments
                    except ValueError :    
                        pass    # ignore this 'bizarre' device
                    else :    
                        if name.startswith('"') and name.endswith('"') :
                            name = name[1:-1]
                        if fullname.startswith('"') and fullname.endswith('"') :
                            fullname = fullname[1:-1]
                        print '%s cupspykota:%s "PyKota+%s" "PyKota managed %s"' % (devicetype, device, name, fullname)
        retcode = 0                
    elif len(sys.argv) not in (6, 7) :    
        sys.stderr.write("ERROR: %s job-id user title copies options [file]\n" % sys.argv[0])
        retcode = 1
    else :    
        try :
            try :
                # Initializes the backend
                kotabackend = PyKotaBackend()    
            except SystemExit :    
                retcode = -1
            except :    
                crashed("cupspykota backend initialization failed")
                retcode = 1
            else :    
                retcode = kotabackend.mainWork()
                kotabackend.storage.close()
                kotabackend.closeJobDataStream()    
        except :
            try :
                kotabackend.crashed("cupspykota backend failed")
            except :    
                crashed("cupspykota backend failed")
            retcode = 1    
        
    sys.exit(retcode)