root / pykota / trunk / bin / cupspykota @ 1974

Revision 1974, 38.0 kB (checked in by jalet, 19 years ago)

Now logs as errors differences between computed and precomputed job's sizes

  • Property svn:eol-style set to native
  • Property svn:executable set to *
  • Property svn:keywords set to Author Date Id Revision
Line 
1#! /usr/bin/env python
2# -*- coding: ISO-8859-15 -*-
3
4# CUPSPyKota accounting backend
5#
6# PyKota - Print Quotas for CUPS and LPRng
7#
8# (c) 2003-2004 Jerome Alet <alet@librelogiciel.com>
9# This program is free software; you can redistribute it and/or modify
10# it under the terms of the GNU General Public License as published by
11# the Free Software Foundation; either version 2 of the License, or
12# (at your option) any later version.
13#
14# This program is distributed in the hope that it will be useful,
15# but WITHOUT ANY WARRANTY; without even the implied warranty of
16# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
17# GNU General Public License for more details.
18#
19# You should have received a copy of the GNU General Public License
20# along with this program; if not, write to the Free Software
21# Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307, USA.
22#
23# $Id$
24#
25# $Log$
26# Revision 1.81  2004/12/07 16:54:02  jalet
27# Now logs as errors differences between computed and precomputed job's sizes
28#
29# Revision 1.80  2004/11/15 22:12:46  jalet
30# Fix for the Fix !!!
31#
32# Revision 1.79  2004/11/15 22:01:34  jalet
33# Improved banner handling.
34# Fix for raw printing and banners.
35#
36# Revision 1.78  2004/11/15 19:59:34  jalet
37# PyKota banners now basically work !
38#
39# Revision 1.77  2004/11/06 22:40:57  jalet
40# Safer code
41#
42# Revision 1.76  2004/11/06 22:35:58  jalet
43# Added a miniparser for IPP messages (RFC 2910). The job-originating-host-name
44# retrieval is now fiable, unless the CUPS developpers change something...
45#
46# Revision 1.75  2004/11/01 15:45:25  jalet
47# Added many debug messages.
48# Added some code to prevent short writes.
49#
50# Revision 1.74  2004/10/13 20:51:27  jalet
51# Made debugging levels be the same in cupspykota and lprngpykota.
52# Now outputs more information in informational messages : user, printer, jobid
53#
54# Revision 1.73  2004/10/13 16:56:45  jalet
55# Added a space to the pattern to differentiate jobs which id begins with
56# the same digits, like jobs 87 and 879 for example : if printed by same
57# user on same printer, but from a different host this could have broken
58# the result. (In reality this couldn't happen because 879 would be the
59# last line to match anyway because of job ordering, but we never know
60# if the page_log file gets corrupt somewhat)
61#
62# Revision 1.72  2004/09/13 16:02:44  jalet
63# Added fix for incorrect job's size when hardware accounting fails
64#
65# Revision 1.71  2004/09/06 17:05:06  jalet
66# Fix for autodetection of SC_OPEN_MAX
67#
68# Revision 1.70  2004/07/26 09:20:27  jalet
69# Unneeded module
70#
71# Revision 1.69  2004/07/22 22:41:47  jalet
72# Hardware accounting for LPRng should be OK now. UNTESTED.
73#
74# Revision 1.68  2004/07/20 22:19:44  jalet
75# Sanitized a bit + use of gettext
76#
77# Revision 1.67  2004/07/16 12:22:45  jalet
78# LPRng support early version
79#
80# Revision 1.66  2004/07/01 19:56:25  jalet
81# Better dispatching of error messages
82#
83# Revision 1.65  2004/06/22 09:31:17  jalet
84# Always send some debug info to CUPS' back channel stream (stderr) as
85# informationnal messages.
86#
87# Revision 1.64  2004/06/18 13:34:46  jalet
88# Now all tracebacks include PyKota's version number
89#
90# Revision 1.63  2004/06/17 13:26:50  jalet
91# Better exception handling code
92#
93# Revision 1.62  2004/06/16 20:56:34  jalet
94# Smarter initialisation code
95#
96# Revision 1.61  2004/06/08 09:00:04  jalet
97# Fixed problem when username was passed in uppercase from Samba and we
98# tried to find correct line in CUPS page_log to extract the hostname.
99#
100# Revision 1.60  2004/06/03 23:14:08  jalet
101# Now stores the job's size in bytes in the database.
102# Preliminary work on payments storage : database schemas are OK now,
103# but no code to store payments yet.
104# Removed schema picture, not relevant anymore.
105#
106# Revision 1.59  2004/06/03 22:12:53  jalet
107# Now denies empty jobs
108#
109# Revision 1.58  2004/06/03 21:50:33  jalet
110# Improved error logging.
111# crashrecipient directive added.
112# Now exports the job's size in bytes too.
113#
114# Revision 1.57  2004/06/02 22:18:07  jalet
115# I think the bug when cancelling jobs should be fixed right now
116#
117# Revision 1.56  2004/06/02 21:50:56  jalet
118# Moved the sigterm capturing elsewhere
119#
120# Revision 1.55  2004/06/02 14:25:07  jalet
121# Should correctly capture ALL errors now
122#
123# Revision 1.54  2004/05/26 16:44:48  jalet
124# Now logs something when client hostname can't be extracted
125#
126# Revision 1.53  2004/05/26 14:49:35  jalet
127# First try at saving the job-originating-hostname in the database
128#
129# Revision 1.52  2004/05/25 09:15:13  jalet
130# accounter.py : old code deleted
131# the rest : now exports PYKOTAPRECOMPUTEDJOBSIZE and PYKOTAPRECOMPUTEDJOBPRICE
132#
133# Revision 1.51  2004/05/25 08:31:16  jalet
134# Heavy CPU usage seems to be fixed at least !
135#
136# Revision 1.50  2004/05/25 05:17:50  jalet
137# Now precomputes the job's size only if current printer's enforcement
138# is "STRICT"
139#
140# Revision 1.49  2004/05/24 22:45:48  jalet
141# New 'enforcement' directive added
142# Polling loop improvements
143#
144# Revision 1.48  2004/05/24 14:36:24  jalet
145# Revert to old polling loop. Will need optimisations
146#
147# Revision 1.47  2004/05/24 11:59:46  jalet
148# More robust (?) code
149#
150# Revision 1.46  2004/05/21 22:02:51  jalet
151# Preliminary work on pre-accounting
152#
153# Revision 1.45  2004/05/19 07:15:32  jalet
154# Could the 'misterious' bug in my loop be finally fixed ???
155#
156# Revision 1.44  2004/05/18 14:48:47  jalet
157# Big code changes to completely remove the need for "requester" directives,
158# jsut use "hardware(... your previous requester directive's content ...)"
159#
160# Revision 1.43  2004/05/17 11:46:05  jalet
161# First try at cupspykota's main loop rewrite
162#
163# Revision 1.42  2004/05/10 11:22:28  jalet
164# Typo
165#
166# Revision 1.41  2004/05/10 10:07:30  jalet
167# Catches OSError while reading
168#
169# Revision 1.40  2004/05/10 09:29:48  jalet
170# Should be more robust if we receive a SIGTERM during an I/O operation
171#
172# Revision 1.39  2004/05/07 14:44:53  jalet
173# Fix for file handles unregistered twice from the polling object
174#
175# Revision 1.38  2004/04/09 22:24:46  jalet
176# Began work on correct handling of child processes when jobs are cancelled by
177# the user. Especially important when an external requester is running for a
178# long time.
179#
180# Revision 1.37  2004/03/18 19:11:25  jalet
181# Fix for raw jobs in cupspykota
182#
183# Revision 1.36  2004/03/18 14:03:18  jalet
184# Added fsync() calls
185#
186# Revision 1.35  2004/03/16 12:05:01  jalet
187# Small fix for new waitprinter.sh : when job was denied, would wait forever
188# for printer being in printing mode.
189#
190# Revision 1.34  2004/03/15 10:47:56  jalet
191# This time the traceback formatting should be correct !
192#
193# Revision 1.33  2004/03/05 12:46:07  jalet
194# Improve tracebacks
195#
196# Revision 1.32  2004/03/05 12:31:35  jalet
197# Now should output full traceback when crashing
198#
199# Revision 1.31  2004/03/01 14:35:56  jalet
200# PYKOTAPHASE wasn't set soon enough at the start of the job
201#
202# Revision 1.30  2004/03/01 14:34:15  jalet
203# PYKOTAPHASE wasn't set at the right time at the end of data transmission
204# to underlying layer (real backend)
205#
206# Revision 1.29  2004/03/01 11:23:25  jalet
207# Pre and Post hooks to external commands are available in the cupspykota
208# backend. Forthe pykota filter they will be implemented real soon now.
209#
210# Revision 1.28  2004/02/26 14:18:07  jalet
211# Should fix the remaining bugs wrt printers groups and users groups.
212#
213# Revision 1.27  2004/02/04 23:41:27  jalet
214# Should fix the incorrect "backend died abnormally" problem.
215#
216# Revision 1.26  2004/01/30 16:35:03  jalet
217# Fixes stupid software accounting bug in CUPS backend
218#
219# Revision 1.25  2004/01/16 17:51:46  jalet
220# Fuck Fuck Fuck !!!
221#
222# Revision 1.24  2004/01/14 15:52:01  jalet
223# Small fix for job cancelling code.
224#
225# Revision 1.23  2004/01/13 10:48:28  jalet
226# Small streams polling loop modification.
227#
228# Revision 1.22  2004/01/12 22:43:40  jalet
229# New formula to compute a job's price
230#
231# Revision 1.21  2004/01/12 18:17:36  jalet
232# Denied jobs weren't stored into the history anymore, this is now fixed.
233#
234# Revision 1.20  2004/01/11 23:22:42  jalet
235# Major code refactoring, it's way cleaner, and now allows automated addition
236# of printers on first print.
237#
238# Revision 1.19  2004/01/08 14:10:32  jalet
239# Copyright year changed.
240#
241# Revision 1.18  2004/01/07 16:16:32  jalet
242# Better debugging information
243#
244# Revision 1.17  2003/12/27 16:49:25  uid67467
245# Should be ok now.
246#
247# Revision 1.17  2003/12/06 08:54:29  jalet
248# Code simplifications.
249# Added many debugging messages.
250#
251# Revision 1.16  2003/11/26 20:43:29  jalet
252# Inadvertantly introduced a bug, which is fixed.
253#
254# Revision 1.15  2003/11/26 19:17:35  jalet
255# Printing on a printer not present in the Quota Storage now results
256# in the job being stopped or cancelled depending on the system.
257#
258# Revision 1.14  2003/11/25 13:25:45  jalet
259# Boolean problem with old Python, replaced with 0
260#
261# Revision 1.13  2003/11/23 19:01:35  jalet
262# Job price added to history
263#
264# Revision 1.12  2003/11/21 14:28:43  jalet
265# More complete job history.
266#
267# Revision 1.11  2003/11/19 23:19:35  jalet
268# Code refactoring work.
269# Explicit redirection to /dev/null has to be set in external policy now, just
270# like in external mailto.
271#
272# Revision 1.10  2003/11/18 17:54:24  jalet
273# SIGTERMs are now transmitted to original backends.
274#
275# Revision 1.9  2003/11/18 14:11:07  jalet
276# Small fix for bizarre urls
277#
278# Revision 1.8  2003/11/15 14:26:44  jalet
279# General improvements to the documentation.
280# Email address changed in sample configuration file, because
281# I receive low quota messages almost every day...
282#
283# Revision 1.7  2003/11/14 22:05:12  jalet
284# New CUPS backend fully functionnal.
285# Old CUPS configuration method is now officially deprecated.
286#
287# Revision 1.6  2003/11/14 20:13:11  jalet
288# We exit the loop too soon.
289#
290# Revision 1.5  2003/11/14 18:31:27  jalet
291# Not perfect, but seems to work with the poll() loop.
292#
293# Revision 1.4  2003/11/14 17:04:15  jalet
294# More (untested) work on the CUPS backend.
295#
296# Revision 1.3  2003/11/12 23:27:44  jalet
297# More work on new backend. This commit may be unstable.
298#
299# Revision 1.2  2003/11/12 09:33:34  jalet
300# New CUPS backend supports device enumeration
301#
302# Revision 1.1  2003/11/08 16:05:31  jalet
303# CUPS backend added for people to experiment.
304#
305#
306#
307
308import sys
309import os
310import popen2
311import cStringIO
312import shlex
313import select
314import signal
315import time
316
317from pykota.tool import PyKotaFilterOrBackend, PyKotaToolError, crashed
318from pykota.config import PyKotaConfigError
319from pykota.storage import PyKotaStorageError
320from pykota.accounter import PyKotaAccounterError
321from pykota.ipp import IPPMessage, PyKotaIPPError
322   
323class PyKotaPopen4(popen2.Popen4) :
324    """Our own class to execute real backends.
325   
326       Their first argument is different from their path so using
327       native popen2.Popen3 would not be feasible.
328    """
329    def __init__(self, cmd, bufsize=-1, arg0=None) :
330        self.arg0 = arg0
331        popen2.Popen4.__init__(self, cmd, bufsize)
332       
333    def _run_child(self, cmd):
334        try :
335            MAXFD = os.sysconf("SC_OPEN_MAX")
336        except (AttributeError, ValueError) :   
337            MAXFD = 256
338        for i in range(3, MAXFD) : 
339            try:
340                os.close(i)
341            except OSError:
342                pass
343        try:
344            os.execvpe(cmd[0], [self.arg0 or cmd[0]] + cmd[1:], os.environ)
345        finally:
346            os._exit(1)
347   
348class PyKotaBackend(PyKotaFilterOrBackend) :       
349    """A class for the pykota backend."""
350    def acceptJob(self) :       
351        """Returns the appropriate exit code to tell CUPS all is OK."""
352        return 0
353           
354    def removeJob(self) :           
355        """Returns the appropriate exit code to let CUPS think all is OK.
356       
357           Returning 0 (success) prevents CUPS from stopping the print queue.
358        """   
359        return 0
360       
361    def getCupsConfigDirectives(self, directives=[]) :
362        """Retrieves some CUPS directives from its configuration file.
363       
364           Returns a mapping with lowercased directives as keys and
365           their setting as values.
366        """
367        dirvalues = {} 
368        cupsroot = os.environ.get("CUPS_SERVERROOT", "/etc/cups")
369        cupsdconf = os.path.join(cupsroot, "cupsd.conf")
370        try :
371            conffile = open(cupsdconf, "r")
372        except IOError :   
373            self.logdebug("Unable to open %s" % cupsdconf)
374        else :   
375            for line in conffile.readlines() :
376                linecopy = line.strip().lower()
377                for di in [d.lower() for d in directives] :
378                    if linecopy.startswith("%s " % di) :
379                        try :
380                            val = line.split()[1]
381                        except :   
382                            pass # ignore errors, we take the last value in any case.
383                        else :   
384                            dirvalues[di] = val
385            conffile.close()           
386        return dirvalues       
387           
388    def getJobOriginatingHostnameFromPageLog(self, cupsconfig, printername, username, jobid) :
389        """Retrieves the job-originating-hostname from the CUPS page_log file if possible."""
390        pagelogpath = cupsconfig.get("pagelog", "/var/log/cups/page_log")
391        self.logdebug("Trying to extract job-originating-host-name from %s" % pagelogpath)
392        try :
393            pagelog = open(pagelogpath, "r")
394        except IOError :   
395            self.logdebug("Unable to open %s" % pagelogpath)
396            return # no page log or can't read it, originating hostname unknown yet
397        else :   
398            # TODO : read backward so we could take first value seen
399            # TODO : here we read forward so we must take the last value seen
400            prefix = ("%s %s %s " % (printername, username, jobid)).lower()
401            matchingline = None
402            while 1 :
403                line = pagelog.readline()
404                if not line :
405                    break
406                else :
407                    line = line.strip()
408                    if line.lower().startswith(prefix) :   
409                        matchingline = line # no break, because we read forward
410            pagelog.close()       
411            if matchingline is None :
412                self.logdebug("No matching line found in %s" % pagelogpath)
413                return # correct line not found, job-originating-host-name unknown
414            else :   
415                return matchingline.split()[-1]
416               
417    def doWork(self, policy, printer, user, userpquota) :   
418        """Most of the work is done here."""
419        # Two different values possible for policy here :
420        # ALLOW means : Either printer, user or user print quota doesn't exist,
421        #               but the job should be allowed anyway.
422        # OK means : Both printer, user and user print quota exist, job should
423        #            be allowed if current user is allowed to print on this printer
424        if policy == "OK" :
425            # exports user information with initial values
426            self.exportUserInfo(userpquota)
427           
428            # tries to extract job-originating-host-name and other information
429            cupsdconf = self.getCupsConfigDirectives(["PageLog", "RequestRoot"])
430            requestroot = cupsdconf.get("requestroot", "/var/spool/cups")
431            if (len(self.jobid) < 5) and self.jobid.isdigit() :
432                ippmessagefile = "c%05i" % int(self.jobid)
433            else :   
434                ippmessagefile = "c%s" % self.jobid
435            ippmessagefile = os.path.join(requestroot, ippmessagefile)
436            ippmessage = {}
437            try :
438                ippdatafile = open(ippmessagefile)
439            except :   
440                self.printInfo("Unable to open IPP message file %s" % ippmessagefile, "warn")
441            else :   
442                self.logdebug("Parsing of IPP message file %s begins." % ippmessagefile)
443                try :
444                    ippmessage = IPPMessage(ippdatafile.read())
445                except PyKotaIPPError, msg :   
446                    self.printInfo("Error while parsing %s : %s" % (ippmessagefile, msg), "warn")
447                else :   
448                    self.logdebug("Parsing of IPP message file %s ends." % ippmessagefile)
449                ippdatafile.close()
450               
451            clienthost = ippmessage.get("job-originating-host-name") \
452                         or self.getJobOriginatingHostnameFromPageLog(cupsdconf, printer.Name, user.Name, self.jobid)
453            self.logdebug("Client Hostname : %s" % (clienthost or "Unknown"))   
454            os.environ["PYKOTAJOBORIGINATINGHOSTNAME"] = str(clienthost or "")
455           
456            # TODO : extract username (double check ?) and billing code too
457           
458            # enters first phase
459            os.environ["PYKOTAPHASE"] = "BEFORE"
460           
461            # do we want strict or laxist quota enforcement ?
462            if self.config.getPrinterEnforcement(printer.Name) == "STRICT" :
463                self.softwareJobSize = self.precomputeJobSize()
464                self.softwareJobPrice = userpquota.computeJobPrice(self.softwareJobSize)
465                self.logdebug("Precomputed job's size is %s pages, price is %s units" % (self.softwareJobSize, self.softwareJobPrice))
466            os.environ["PYKOTAPRECOMPUTEDJOBSIZE"] = str(self.softwareJobSize)
467            os.environ["PYKOTAPRECOMPUTEDJOBPRICE"] = str(self.softwareJobPrice)
468           
469            # if no data to pass to real backend, probably a filter
470            # higher in the chain failed because of a misconfiguration.
471            # we deny the job in this case (nothing to print anyway)
472            if not self.jobSizeBytes :
473                self.printMoreInfo(user, printer, _("Job contains no data. Printing is denied."), "warn")
474                action = "DENY"
475            else :   
476                # checks the user's quota
477                action = self.warnUserPQuota(userpquota)
478           
479            # exports some new environment variables
480            os.environ["PYKOTAACTION"] = action
481           
482            # launches the pre hook
483            self.prehook(userpquota)
484
485            # saves the size of banners which have to be accounted for
486            # this is needed in the case of software accounting
487            bannersize = 0
488           
489            # handle starting banner pages before accounting
490            accountbanner = self.config.getAccountBanner(printer.Name)
491            if accountbanner in ["ENDING", "NONE"] :
492                banner = self.startingBanner(printer.Name)
493                if banner :
494                    self.logdebug("Printing starting banner before accounting begins.")
495                    self.handleData(banner)
496 
497            self.printMoreInfo(user, printer, _("Job accounting begins."))
498            self.accounter.beginJob(printer)
499           
500            # handle starting banner pages during accounting
501            if accountbanner in ["STARTING", "BOTH"] :
502                banner = self.startingBanner(printer.Name)
503                if banner :
504                    self.logdebug("Printing starting banner during accounting.")
505                    self.handleData(banner)
506                    if self.accounter.isSoftware :
507                        bannersize += 1 # TODO : fix this by passing the banner's content through PDLAnalyzer
508        else :   
509            action = "ALLOW"
510            os.environ["PYKOTAACTION"] = action
511           
512        # pass the job's data to the real backend   
513        if action in ["ALLOW", "WARN"] :
514            if self.gotSigTerm :
515                retcode = self.removeJob()
516            else :   
517                retcode = self.handleData()       
518        else :       
519            retcode = self.removeJob()
520       
521        if policy == "OK" :       
522            # indicate phase change
523            os.environ["PYKOTAPHASE"] = "AFTER"
524           
525            # handle ending banner pages during accounting
526            if accountbanner in ["ENDING", "BOTH"] :
527                banner = self.endingBanner(printer.Name)
528                if banner :
529                    self.logdebug("Printing ending banner during accounting.")
530                    self.handleData(banner)
531                    if self.accounter.isSoftware :
532                        bannersize += 1 # TODO : fix this by passing the banner's content through PDLAnalyzer
533 
534            # stops accounting.
535            self.accounter.endJob(printer)
536            self.printMoreInfo(user, printer, _("Job accounting ends."))
537               
538            # retrieve the job size   
539            if action == "DENY" :
540                jobsize = 0
541                self.printMoreInfo(user, printer, _("Job size forced to 0 because printing is denied."))
542            else :   
543                jobsize = self.accounter.getJobSize(printer) 
544                if self.softwareJobSize and (jobsize != self.softwareJobSize) :
545                    self.printInfo(_("Beware : computed job size (%s) != precomputed job size (%s)") % (jobsize, self.softwareJobSize), "error")
546                jobsize += bannersize
547            self.printMoreInfo(user, printer, _("Job size : %i") % jobsize)
548           
549            # update the quota for the current user on this printer
550            self.printInfo(_("Updating user %s's quota on printer %s") % (user.Name, printer.Name))
551            jobprice = userpquota.increasePagesUsage(jobsize)
552           
553            # adds the current job to history   
554            printer.addJobToHistory(self.jobid, user, self.accounter.getLastPageCounter(), action, jobsize, jobprice, self.preserveinputfile, self.title, self.copies, self.options, clienthost, self.jobSizeBytes)
555            self.printMoreInfo(user, printer, _("Job added to history."))
556           
557            # exports some new environment variables
558            os.environ["PYKOTAJOBSIZE"] = str(jobsize)
559            os.environ["PYKOTAJOBPRICE"] = str(jobprice)
560           
561            # then re-export user information with new value
562            self.exportUserInfo(userpquota)
563           
564            # handle ending banner pages after accounting ends
565            if accountbanner in ["STARTING", "NONE"] :
566                banner = self.endingBanner(printer.Name)
567                if banner :
568                    self.logdebug("Printing ending banner after accounting ends.")
569                    self.handleData(banner)
570           
571            # Launches the post hook
572            self.posthook(userpquota)
573           
574        return retcode   
575               
576    def unregisterFileNo(self, pollobj, fileno) :               
577        """Removes a file handle from the polling object."""
578        try :
579            pollobj.unregister(fileno)
580        except KeyError :   
581            self.printInfo(_("File number %s unregistered twice from polling object, ignored.") % fileno, "warn")
582        except :   
583            self.logdebug("Error while unregistering file number %s from polling object." % fileno)
584        else :   
585            self.logdebug("File number %s unregistered from polling object." % fileno)
586           
587    def formatFileEvent(self, fd, mask) :       
588        """Formats file debug info."""
589        maskval = []
590        if mask & select.POLLIN :
591            maskval.append("POLLIN")
592        if mask & select.POLLOUT :
593            maskval.append("POLLOUT")
594        if mask & select.POLLPRI :
595            maskval.append("POLLPRI")
596        if mask & select.POLLERR :
597            maskval.append("POLLERR")
598        if mask & select.POLLHUP :
599            maskval.append("POLLHUP")
600        if mask & select.POLLNVAL :
601            maskval.append("POLLNVAL")
602        return "%s (%s)" % (fd, " | ".join(maskval))
603       
604    def handleData(self, filehandle=None) :
605        """Pass the job's data to the real backend."""
606        # Find the real backend pathname   
607        realbackend = os.path.join(os.path.split(sys.argv[0])[0], self.originalbackend)
608       
609        # And launch it
610        if filehandle is None :
611            arguments = sys.argv
612        else :   
613            # Here we absolutely WANT to remove any filename from the command line !
614            arguments = [ "Fake this because we are printing a banner" ] + sys.argv[1:6]
615        self.logdebug("Starting real backend %s with args %s" % (realbackend, " ".join(['"%s"' % a for a in ([os.environ["DEVICE_URI"]] + arguments[1:])])))
616        subprocess = PyKotaPopen4([realbackend] + arguments[1:], bufsize=0, arg0=os.environ["DEVICE_URI"])
617       
618        # Save file descriptors, we will need them later.
619        stderrfno = sys.stderr.fileno()
620        fromcfno = subprocess.fromchild.fileno()
621        tocfno = subprocess.tochild.fileno()
622       
623        # We will have to be careful when dealing with I/O
624        # So we use a poll object to know when to read or write
625        pollster = select.poll()
626        pollster.register(fromcfno, select.POLLIN | select.POLLPRI)
627        pollster.register(stderrfno, select.POLLOUT)
628        pollster.register(tocfno, select.POLLOUT)
629       
630        # Initialize our buffers
631        indata = ""
632        outdata = ""
633        endinput = endoutput = 0
634        inputclosed = outputclosed = 0
635        totaltochild = totalfromcups = 0
636        totalfromchild = totaltocups = 0
637       
638        if filehandle is None:
639            if self.preserveinputfile is None :
640               # this is not a real file, we read the job's data
641                # from our temporary file which is a copy of stdin
642                infno = self.jobdatastream.fileno()
643                self.jobdatastream.seek(0)
644                pollster.register(infno, select.POLLIN | select.POLLPRI)
645            else :   
646                # job's data is in a file, no need to pass the data
647                # to the real backend
648                self.logdebug("Job's data is in %s" % self.preserveinputfile)
649                infno = None
650                endinput = 1
651        else:
652            self.logdebug("Printing data passed from filehandle")
653            indata = filehandle.read()
654            infno = None
655            endinput = 1
656            filehandle.close()
657       
658        self.logdebug("Entering streams polling loop...")
659        MEGABYTE = 1024*1024
660        killed = 0
661        status = -1
662        while (status == -1) and (not killed) and not (inputclosed and outputclosed) :
663            # First check if original backend is still alive
664            status = subprocess.poll()
665           
666            # Now if we got SIGTERM, we have
667            # to kill -TERM the original backend
668            if self.gotSigTerm and not killed :
669                try :
670                    os.kill(subprocess.pid, signal.SIGTERM)
671                except OSError, msg : # ignore but logs if process was already killed.
672                    self.logdebug("Error while sending signal to pid %s : %s" % (subprocess.pid, msg))
673                else :   
674                    self.printInfo(_("SIGTERM was sent to real backend %s (pid: %s)") % (realbackend, subprocess.pid))
675                    killed = 1
676           
677            # In any case, deal with any remaining I/O
678            try :
679                availablefds = pollster.poll(5000)
680            except select.error, msg :   
681                self.logdebug("Interrupted poll : %s" % msg)
682                availablefds = []
683            if not availablefds :
684                self.logdebug("Nothing to do, sleeping a bit...")
685                time.sleep(0.01) # give some time to the system
686            else :
687                for (fd, mask) in availablefds :
688                    # self.logdebug(self.formatFileEvent(fd, mask))
689                    try :
690                        if mask & select.POLLOUT :
691                            # We can write
692                            if fd == tocfno :
693                                if indata :
694                                    try :
695                                        nbwritten = os.write(fd, indata)   
696                                    except (OSError, IOError), msg :   
697                                        self.logdebug("Error while writing to real backend's stdin %s : %s" % (fd, msg))
698                                    else :   
699                                        if len(indata) != nbwritten :
700                                            self.logdebug("Short write to real backend's input !")
701                                        totaltochild += nbwritten   
702                                        self.logdebug("%s bytes sent to real backend so far..." % totaltochild)
703                                        indata = indata[nbwritten:]
704                                else :       
705                                    self.logdebug("No data to send to real backend yet, sleeping a bit...")
706                                    time.sleep(0.01)
707                                   
708                                if endinput :   
709                                    self.unregisterFileNo(pollster, tocfno)       
710                                    self.logdebug("Closing real backend's stdin.")
711                                    os.close(tocfno)
712                                    inputclosed = 1
713                            elif fd == stderrfno :
714                                if outdata :
715                                    try :
716                                        nbwritten = os.write(fd, outdata)
717                                    except (OSError, IOError), msg :   
718                                        self.logdebug("Error while writing to CUPS back channel (stderr) %s : %s" % (fd, msg))
719                                    else :
720                                        if len(outdata) != nbwritten :
721                                            self.logdebug("Short write to stderr (CUPS) !")
722                                        totaltocups += nbwritten   
723                                        self.logdebug("%s bytes sent back to CUPS so far..." % totaltocups)
724                                        outdata = outdata[nbwritten:]
725                                else :       
726                                    # self.logdebug("No data to send back to CUPS yet, sleeping a bit...") # Uncommenting this fills your logs
727                                    time.sleep(0.01) # Give some time to the system, stderr is ALWAYS writeable it seems.
728                                   
729                                if endoutput :   
730                                    self.unregisterFileNo(pollster, stderrfno)       
731                                    outputclosed = 1
732                            else :   
733                                self.logdebug("Unexpected : %s - Sleeping a bit..." % self.formatFileEvent(fd, mask))
734                                time.sleep(0.01)
735                               
736                        if mask & (select.POLLIN | select.POLLPRI) :     
737                            # We have something to read
738                            try :
739                                data = os.read(fd, MEGABYTE)
740                            except (IOError, OSError), msg :   
741                                self.logdebug("Error while reading file %s : %s" % (fd, msg))
742                            else :
743                                if fd == infno :
744                                    if not data :    # If yes, then no more input data
745                                        self.unregisterFileNo(pollster, infno)
746                                        self.logdebug("Input data ends.")
747                                        endinput = 1 # this happens with real files.
748                                    else :   
749                                        indata += data
750                                        totalfromcups += len(data)
751                                        self.logdebug("%s bytes read from CUPS so far..." % totalfromcups)
752                                elif fd == fromcfno :
753                                    if not data :
754                                        self.logdebug("No back channel data to read from real backend yet, sleeping a bit...")
755                                        time.sleep(0.01)
756                                    else :
757                                        outdata += data
758                                        totalfromchild += len(data)
759                                        self.logdebug("%s bytes read from real backend so far..." % totalfromchild)
760                                else :   
761                                    self.logdebug("Unexpected : %s - Sleeping a bit..." % self.formatFileEvent(fd, mask))
762                                    time.sleep(0.01)
763                                   
764                        if mask & (select.POLLHUP | select.POLLERR) :
765                            # Treat POLLERR as an EOF.
766                            # Some standard I/O stream has no more datas
767                            self.unregisterFileNo(pollster, fd)
768                            if fd == infno :
769                                # Here we are in the case where the input file is stdin.
770                                # which has no more data to be read.
771                                self.logdebug("Input data ends.")
772                                endinput = 1
773                            elif fd == fromcfno :   
774                                # We are no more interested in this file descriptor       
775                                self.logdebug("Closing real backend's stdout+stderr.")
776                                os.close(fromcfno)
777                                endoutput = 1
778                            else :   
779                                self.logdebug("Unexpected : %s - Sleeping a bit..." % self.formatFileEvent(fd, mask))
780                                time.sleep(0.01)
781                               
782                        if mask & select.POLLNVAL :       
783                            self.logdebug("File %s was closed. Unregistering from polling object." % fd)
784                            self.unregisterFileNo(pollster, fd)
785                    except IOError, msg :           
786                        self.logdebug("Got an IOError : %s" % msg) # we got signalled during an I/O
787               
788        # We must close the real backend's input stream
789        if killed and not inputclosed :
790            self.logdebug("Forcing close of real backend's stdin.")
791            os.close(tocfno)
792       
793        self.logdebug("Exiting streams polling loop...")
794       
795        self.logdebug("input data's final length : %s" % len(indata))
796        self.logdebug("back-channel data's final length : %s" % len(outdata))
797       
798        self.logdebug("Total bytes read from CUPS (job's datas) : %s" % totalfromcups)
799        self.logdebug("Total bytes sent to real backend (job's datas) : %s" % totaltochild)
800       
801        self.logdebug("Total bytes read from real backend (back-channel datas) : %s" % totalfromchild)
802        self.logdebug("Total bytes sent back to CUPS (back-channel datas) : %s" % totaltocups)
803       
804        # Check exit code of original CUPS backend.   
805        if status == -1 :
806            # we exited the loop before the real backend exited
807            # now we have to wait for it to finish and get its status
808            self.logdebug("Waiting for real backend to exit...")
809            try :
810                status = subprocess.wait()
811            except OSError : # already dead   
812                status = 0
813        if os.WIFEXITED(status) :
814            retcode = os.WEXITSTATUS(status)
815        elif not killed :   
816            self.sendBackChannelData(_("CUPS backend %s died abnormally.") % realbackend, "error")
817            retcode = -1
818        else :   
819            retcode = self.removeJob()
820        return retcode   
821   
822if __name__ == "__main__" :   
823    # This is a CUPS backend, we should act and die like a CUPS backend
824    retcode = 0
825    if len(sys.argv) == 1 :
826        # we will execute each existing backend in device enumeration mode
827        # and generate their PyKota accounting counterpart
828        (directory, myname) = os.path.split(sys.argv[0])
829        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)] :
830            answer = os.popen(backend, "r")
831            try :
832                devices = [line.strip() for line in answer.readlines()]
833            except :   
834                devices = []
835            status = answer.close()
836            if status is None :
837                for d in devices :
838                    # each line is of the form : 'xxxx xxxx "xxxx xxx" "xxxx xxx"'
839                    # so we have to decompose it carefully
840                    fdevice = cStringIO.StringIO("%s" % d)
841                    tokenizer = shlex.shlex(fdevice)
842                    tokenizer.wordchars = tokenizer.wordchars + r".:,?!~/\_$*-+={}[]()#"
843                    arguments = []
844                    while 1 :
845                        token = tokenizer.get_token()
846                        if token :
847                            arguments.append(token)
848                        else :
849                            break
850                    fdevice.close()
851                    try :
852                        (devicetype, device, name, fullname) = arguments
853                    except ValueError :   
854                        pass    # ignore this 'bizarre' device
855                    else :   
856                        if name.startswith('"') and name.endswith('"') :
857                            name = name[1:-1]
858                        if fullname.startswith('"') and fullname.endswith('"') :
859                            fullname = fullname[1:-1]
860                        print '%s cupspykota:%s "PyKota+%s" "PyKota managed %s"' % (devicetype, device, name, fullname)
861        retcode = 0               
862    elif len(sys.argv) not in (6, 7) :   
863        sys.stderr.write("ERROR: %s job-id user title copies options [file]\n" % sys.argv[0])
864        retcode = 1
865    else :   
866        try :
867            try :
868                # Initializes the backend
869                kotabackend = PyKotaBackend()   
870            except SystemExit :   
871                retcode = -1
872            except :   
873                crashed("cupspykota backend initialization failed")
874                retcode = 1
875            else :   
876                retcode = kotabackend.mainWork()
877                kotabackend.storage.close()
878                kotabackend.closeJobDataStream()   
879        except :
880            try :
881                kotabackend.crashed("cupspykota backend failed")
882            except :   
883                crashed("cupspykota backend failed")
884            retcode = 1   
885       
886    sys.exit(retcode)   
Note: See TracBrowser for help on using the browser.