Changeset 640 for tea4cups

Show
Ignore:
Timestamp:
06/11/05 19:00:35 (19 years ago)
Author:
stuge
Message:

Tees have been removed, the original backend is run with fd:s pointing
directly to the proper files rather than having to be read and written
by tea4cups, and a few small bug fixes and cleanups are also included.

Full list of changes:

* Remove the Popen4ForCUPS class
fork() and execve() directly in runOriginalBackend() instead.

* Added exception handling to logInfo()
When CUPS cancels a job before tea4cups is completely done stderr is
closed and writing to it would raise an IOError causing tea4cups to
abort without a chance to clean up.


* Rewrote most of runBranches() to remove tees and clean up a bit
Use retcode for consistency throughout program. Proper error
handling, falling through and doing the right thing whenever
something exits nonzero, removed the shared pipe and use stdin/stdout
instead. Make sure they aren't closed when all the pipes are closed.

* Changed stdioRedirSystem() to return actual exit code of command..
..instead of the encoded value returned by waitpid(), or -1 if the
command didn't exit with an exit code. (E.g. killed by a signal.)
Adjusted all places using the return value accordingly. Also fixed a
bug, if the execl() failed, the child would exit 1. Changed that to
-1 which has special meaning. (prehook cancels the job)

* Fixed indentation mistake and clean a condition in runCommand()
I use two spaces and had an incorrect indentation in the previous
patch. :) Now that tees are removed, == prehook is nicer than !=
posthook.

* Removed tee handling from runCommands() and some cleanup
This includes moving the call to runOriginalBackend() up one level
into runBranches(). Changed to os._exit() for forked hooks as
recommended by docs.python.org. sys.exit() is only supposed to be
used in the parent process. Finally, the child pid for forked hooks
is already known in the waitpid loop (in pid, from the pids dict) so
I removed the variable childpid.

* Removed unregisterFileNo() and formatFileEvents()
No longer used by runOriginalBackend() and not used anywhere else.

* Rewrote runOriginalBackend() per previous no-copy theory
Fork, open dataFile and dup2() if needed, execve original backend.
Log an error and exit -1 if execve() fails. Simplified reaping of the
original backend but it still has to keep track of SIGTERM and pass
it on if received during waitpid(). Log an error message with the
exit code of the original backend if nonzero.

Files:
1 modified

Legend:

Unmodified
Added
Removed

  • tea4cups/trunk/tea4cups

    r639 r640  
    5858    pass  
    5959     
    60 class Popen4ForCUPS(popen2.Popen4) : 
    61     """Our own class to execute real backends. 
    62      
    63        Their first argument is different from their path so using 
    64        native popen2.Popen3 would not be feasible. 
    65     """ 
    66     def __init__(self, cmd, bufsize=-1, arg0=None) : 
    67         self.arg0 = arg0 
    68         popen2.Popen4.__init__(self, cmd, bufsize) 
    69          
    70     def _run_child(self, cmd): 
    71         try : 
    72             MAXFD = os.sysconf("SC_OPEN_MAX") 
    73         except (AttributeError, ValueError) :     
    74             MAXFD = 256 
    75         for i in range(3, MAXFD) :  
    76             try: 
    77                 os.close(i) 
    78             except OSError: 
    79                 pass 
    80         try: 
    81             os.execvpe(cmd[0], [self.arg0 or cmd[0]] + cmd[1:], os.environ) 
    82         finally: 
    83             os._exit(1) 
    84      
    8560# Some IPP constants     
    8661OPERATION_ATTRIBUTES_TAG = 0x01 
    … …  
    283258    def logInfo(self, message, level="info") :         
    284259        """Logs a message to CUPS' error_log file.""" 
    285         sys.stderr.write("%s: %s v%s (PID %i) : %s\n" % (level.upper(), self.MyName, version, os.getpid(), message)) 
    286         sys.stderr.flush() 
     260        try : 
     261            sys.stderr.write("%s: %s v%s (PID %i) : %s\n" % (level.upper(), self.MyName, version, os.getpid(), message)) 
     262            sys.stderr.flush() 
     263        except IOError : 
     264            pass 
    287265         
    288266    def logDebug(self, message) :     
    … …  
    290268        if self.debug : 
    291269            self.logInfo(message, level="debug") 
    292          
     270             
    293271    def isTrue(self, option) :         
    294272        """Returns 1 if option is set to true, else 0.""" 
    … …  
    574552         
    575553    def runBranches(self) :          
    576         """Launches each hook or tee defined for the current print queue.""" 
    577         exitcode = 0 
     554        """Launches each hook defined for the current print queue.""" 
    578555        self.isCancelled = 0    # did a prehook cancel the print job ? 
    579556        self.gotSigTerm = 0 
    580557        signal.signal(signal.SIGTERM, self.sigtermHandler) 
    581558        serialize = self.isTrue(self.getPrintQueueOption(self.PrinterName, "serialize", ignore=1)) 
    582         self.pipes = { 0: os.pipe() } 
    583         for branchtype in ["prehook", "tee", "posthook"] : 
    584             if branchtype == "posthook" : 
    585                 os.close(self.pipes[0][1]) 
    586             branches = self.enumBranches(self.PrinterName, branchtype) 
    587             for b in branches : 
    588                 bname = b.split("_", 1)[1] 
    589                 if branchtype != "posthook" and bname not in self.pipes : 
    590                     self.pipes[bname] = os.pipe() 
    591                 else : 
    592                     if bname in self.pipes : 
    593                         os.close(self.pipes[bname][1]) 
    594             status = self.runCommands(branchtype, branches, serialize) 
    595             if status : 
    596                 if branchtype != "posthook" : 
    597                     exitcode = status 
    598                 else :     
    599                     # we just ignore error in posthooks 
     559        self.pipes = { 0: (0,1) } 
     560        branches = self.enumBranches(self.PrinterName, "prehook") 
     561        for b in branches : 
     562            self.pipes[b.split("_", 1)[1]] = os.pipe() 
     563        retcode = self.runCommands("prehook", branches, serialize) 
     564        for p in self.pipes.items()[1:] : 
     565            os.close(p[1][1]) 
     566        if not self.isCancelled and not self.gotSigTerm : 
     567            if self.RealBackend : 
     568                retcode = self.runOriginalBackend() 
     569            if not self.gotSigTerm : 
     570                os.environ["TEASTATUS"] = str(retcode) 
     571                branches = self.enumBranches(self.PrinterName, "posthook") 
     572                if self.runCommands("posthook", branches, serialize) : 
    600573                    self.logInfo("An error occured during the execution of posthooks.", "warn") 
    601             if (branchtype == "prehook") and self.isCancelled : 
    602                 break # We don't want to execute tees or posthooks in this case 
     574        for p in self.pipes.items()[1:] : 
     575            os.close(p[1][0]) 
    603576        signal.signal(signal.SIGTERM, signal.SIG_IGN) 
    604         for p in self.pipes : 
    605             os.close(self.pipes[p][0]) 
    606             try : 
    607                 os.close(self.pipes[p][1]) 
    608             except OSError : 
    609                 pass 
    610         if not exitcode : 
     577        if not retcode : 
    611578            self.logInfo("OK") 
    612579        else :     
    613580            self.logInfo("An error occured, please check CUPS' error_log file.") 
    614         return exitcode 
     581        return retcode 
    615582         
    616583    def stdioRedirSystem(self, cmd, stdin=0, stdout=1) : 
    … …  
    627594            try : 
    628595                os.execl("/bin/sh", "sh", "-c", cmd) 
    629             except OSError , msg : 
     596            except OSError, msg : 
    630597                self.logDebug("execl() failed: %s" % msg) 
    631             os._exit(1) 
    632         return os.waitpid(pid, 0)[1] 
     598            os._exit(-1) 
     599        status = os.waitpid(pid, 0)[1] 
     600        if os.WIFEXITED(status) : 
     601            return os.WEXITSTATUS(status) 
     602        return -1 
    633603         
    634604    def runCommand(self, branch, command) : 
    … …  
    638608        btype, bname = branch.split("_", 1) 
    639609        if bname not in self.pipes : 
    640           bname = 0 
    641         if btype != "posthook" : 
     610            bname = 0 
     611        if btype == "prehook" : 
    642612            return self.stdioRedirSystem(command, 0, self.pipes[bname][1]) 
    643613        else : 
    … …  
    653623        if serialize : 
    654624            self.logDebug("Begin serialized %ss" % btypetitle) 
    655             if (btype == "tee") and self.RealBackend : 
    656                 self.logDebug("Launching original backend %s for printer %s" % (self.RealBackend, self.PrinterName)) 
    657                 retcode = self.runOriginalBackend() 
    658                 if os.WIFEXITED(retcode) : 
    659                     retcode = os.WEXITSTATUS(retcode) 
    660                 os.environ["TEASTATUS"] = str(retcode) 
    661                 exitcode = retcode 
    662625            for branch in branchlist : 
    663                 command = branches[branch] 
    664626                if self.gotSigTerm : 
    665627                    break 
    666                 retcode = self.runCommand(branch, command) 
     628                retcode = self.runCommand(branch, branches[branch]) 
    667629                self.logDebug("Exit code for %s %s on printer %s is %s" % (btype, branch, self.PrinterName, retcode)) 
    668                 if os.WIFEXITED(retcode) : 
    669                     retcode = os.WEXITSTATUS(retcode) 
    670630                if retcode :     
    671631                    if (btype == "prehook") and (retcode == 255) : # -1 
    … …  
    679639            self.logDebug("Begin forked %ss" % btypetitle) 
    680640            pids = {} 
    681             if (btype == "tee") and self.RealBackend : 
    682                 branches["Original backend"] = None     # Fakes a tee to launch one more child 
    683                 branchlist = ["Original backend"] + branchlist 
    684641            for branch in branchlist : 
    685                 command = branches[branch] 
    686642                if self.gotSigTerm : 
    687643                    break 
    … …  
    690646                    pids[branch] = pid 
    691647                else :     
    692                     if branch == "Original backend" : 
    693                         self.logDebug("Launching original backend %s for printer %s" % (self.RealBackend, self.PrinterName)) 
    694                         sys.exit(self.runOriginalBackend()) 
    695                     else : 
    696                         retcode = self.runCommand(branch, command) 
    697                         if os.WIFEXITED(retcode) : 
    698                             retcode = os.WEXITSTATUS(retcode) 
    699                         else :     
    700                             retcode = -1 
    701                         sys.exit(retcode) 
     648                    os._exit(self.runCommand(branch, branches[branch])) 
    702649            for (branch, pid) in pids.items() : 
    703                 (childpid, retcode) = os.waitpid(pid, 0) 
    704                 self.logDebug("Exit code for %s %s (PID %s) on printer %s is %s" % (btype, branch, childpid, self.PrinterName, retcode)) 
     650                retcode = os.waitpid(pid, 0)[1] 
    705651                if os.WIFEXITED(retcode) : 
    706652                    retcode = os.WEXITSTATUS(retcode) 
     653                else : 
     654                    retcode = -1 
     655                self.logDebug("Exit code for %s %s (PID %s) on printer %s is %s" % (btype, branch, pid, self.PrinterName, retcode)) 
    707656                if retcode :     
    708657                    if (btype == "prehook") and (retcode == 255) : # -1 
    … …  
    710659                        self.isCancelled = 1 
    711660                    else :     
    712                         self.logInfo("%s %s (PID %s) on printer %s didn't exit successfully." % (btypetitle, branch, childpid, self.PrinterName), "error") 
     661                        self.logInfo("%s %s (PID %s) on printer %s didn't exit successfully." % (btypetitle, branch, pid, self.PrinterName), "error") 
    713662                        exitcode = 1 
    714                 if branch == "Original backend" :     
    715                     os.environ["TEASTATUS"] = str(retcode) 
    716663            self.logDebug("End forked %ss" % btypetitle) 
    717664        return exitcode 
    718          
    719     def unregisterFileNo(self, pollobj, fileno) :                 
    720         """Removes a file handle from the polling object.""" 
    721         try : 
    722             pollobj.unregister(fileno) 
    723         except KeyError :     
    724             self.logInfo("File number %s unregistered twice from polling object, ignored." % fileno, "warn") 
    725         except :     
    726             self.logDebug("Error while unregistering file number %s from polling object." % fileno) 
    727         else :     
    728             self.logDebug("File number %s unregistered from polling object." % fileno) 
    729              
    730     def formatFileEvent(self, fd, mask) :         
    731         """Formats file debug info.""" 
    732         maskval = [] 
    733         if mask & select.POLLIN : 
    734             maskval.append("POLLIN") 
    735         if mask & select.POLLOUT : 
    736             maskval.append("POLLOUT") 
    737         if mask & select.POLLPRI : 
    738             maskval.append("POLLPRI") 
    739         if mask & select.POLLERR : 
    740             maskval.append("POLLERR") 
    741         if mask & select.POLLHUP : 
    742             maskval.append("POLLHUP") 
    743         if mask & select.POLLNVAL : 
    744             maskval.append("POLLNVAL") 
    745         return "%s (%s)" % (fd, " | ".join(maskval)) 
    746665         
    747666    def runOriginalBackend(self) :     
    748667        """Launches the original backend.""" 
    749668        originalbackend = os.path.join(os.path.split(sys.argv[0])[0], self.RealBackend) 
    750         arguments = sys.argv 
    751         self.logDebug("Starting original backend %s with args %s" % (originalbackend, " ".join(['"%s"' % a for a in ([os.environ["DEVICE_URI"]] + arguments[1:])]))) 
    752         subprocess = Popen4ForCUPS([originalbackend] + arguments[1:], bufsize=0, arg0=os.environ["DEVICE_URI"]) 
    753          
    754         # Save file descriptors, we will need them later. 
    755         stderrfno = sys.stderr.fileno() 
    756         fromcfno = subprocess.fromchild.fileno() 
    757         tocfno = subprocess.tochild.fileno() 
    758          
    759         # We will have to be careful when dealing with I/O  
    760         # So we use a poll object to know when to read or write 
    761         pollster = select.poll() 
    762         pollster.register(fromcfno, select.POLLIN | select.POLLPRI) 
    763         pollster.register(stderrfno, select.POLLOUT) 
    764         pollster.register(tocfno, select.POLLOUT) 
    765          
    766         # Initialize our buffers 
    767         indata = "" 
    768         outdata = "" 
    769         endinput = endoutput = 0 
    770         inputclosed = outputclosed = 0 
    771         totaltochild = totalfromcups = 0 
    772         totalfromchild = totaltocups = 0 
    773          
    774         if self.InputFile is None : 
    775            # this is not a real file, we read the job's data 
    776             # from our temporary file which is a copy of stdin  
    777             inf = open(self.DataFile, "rb") 
    778             infno = inf.fileno() 
    779             pollster.register(infno, select.POLLIN | select.POLLPRI) 
    780         else :     
    781             # job's data is in a file, no need to pass the data 
    782             # to the original backend 
    783             self.logDebug("Job's data is in %s" % self.InputFile) 
    784             infno = None 
    785             endinput = 1 
    786          
    787         self.logDebug("Entering streams polling loop...") 
    788         MEGABYTE = 1024*1024 
     669        arguments = [os.environ["DEVICE_URI"]] + sys.argv[1:] 
     670        self.logDebug("Starting original backend %s with args %s" % (originalbackend, " ".join(['"%s"' % a for a in arguments]))) 
     671 
     672        pid = os.fork() 
     673        if pid == 0 : 
     674            if self.InputFile is None : 
     675                f=open(self.dataFile, "rb") 
     676                os.dup2(f.fileno(), 0) 
     677                f.close() 
     678            try : 
     679                os.execve(originalbackend,arguments,os.environ) 
     680            except OSError, msg : 
     681                self.logDebug("execve() failed: %s" % msg) 
     682            os._exit(-1) 
    789683        killed = 0 
    790684        status = -1 
    791         while (status == -1) and (not killed) and not (inputclosed and outputclosed) : 
    792             # First check if original backend is still alive 
    793             status = subprocess.poll() 
    794              
    795             # Now if we got SIGTERM, we have  
    796             # to kill -TERM the original backend 
    797             if self.gotSigTerm and not killed : 
    798                 try : 
    799                     os.kill(subprocess.pid, signal.SIGTERM) 
    800                 except OSError, msg : # ignore but logs if process was already killed. 
    801                     self.logDebug("Error while sending signal to pid %s : %s" % (subprocess.pid, msg)) 
    802                 else :     
    803                     self.logInfo(_("SIGTERM was sent to original backend %s (PID %s)") % (originalbackend, subprocess.pid)) 
     685        while status == -1 : 
     686            try : 
     687                status = os.waitpid(pid, 0)[1] 
     688            except OSError, (err, msg) : 
     689                if err == 4 and self.gotSigTerm : 
     690                    os.kill(pid, signal.SIGTERM) 
    804691                    killed = 1 
    805              
    806             # In any case, deal with any remaining I/O 
    807             try : 
    808                 availablefds = pollster.poll(5000) 
    809             except select.error, msg :     
    810                 self.logDebug("Interrupted poll : %s" % msg) 
    811                 availablefds = [] 
    812             if not availablefds : 
    813                 self.logDebug("Nothing to do, sleeping a bit...") 
    814                 time.sleep(0.01) # give some time to the system 
    815             else : 
    816                 for (fd, mask) in availablefds : 
    817                     try : 
    818                         if mask & select.POLLOUT : 
    819                             # We can write 
    820                             if fd == tocfno : 
    821                                 if indata : 
    822                                     try : 
    823                                         nbwritten = os.write(fd, indata)     
    824                                     except (OSError, IOError), msg :     
    825                                         self.logDebug("Error while writing to original backend's stdin %s : %s" % (fd, msg)) 
    826                                     else :     
    827                                         if len(indata) != nbwritten : 
    828                                             self.logDebug("Short write to original backend's input !") 
    829                                         totaltochild += nbwritten     
    830                                         self.logDebug("%s bytes sent to original backend so far..." % totaltochild) 
    831                                         indata = indata[nbwritten:] 
    832                                 else :         
    833                                     self.logDebug("No data to send to original backend yet, sleeping a bit...") 
    834                                     time.sleep(0.01) 
    835                                      
    836                                 if endinput :     
    837                                     self.unregisterFileNo(pollster, tocfno)         
    838                                     self.logDebug("Closing original backend's stdin.") 
    839                                     os.close(tocfno) 
    840                                     inputclosed = 1 
    841                             elif fd == stderrfno : 
    842                                 if outdata : 
    843                                     try : 
    844                                         nbwritten = os.write(fd, outdata) 
    845                                     except (OSError, IOError), msg :     
    846                                         self.logDebug("Error while writing to CUPS back channel (stderr) %s : %s" % (fd, msg)) 
    847                                     else : 
    848                                         if len(outdata) != nbwritten : 
    849                                             self.logDebug("Short write to stderr (CUPS) !") 
    850                                         totaltocups += nbwritten     
    851                                         self.logDebug("%s bytes sent back to CUPS so far..." % totaltocups) 
    852                                         outdata = outdata[nbwritten:] 
    853                                 else :         
    854                                     # self.logDebug("No data to send back to CUPS yet, sleeping a bit...") # Uncommenting this fills your logs 
    855                                     time.sleep(0.01) # Give some time to the system, stderr is ALWAYS writeable it seems. 
    856                                      
    857                                 if endoutput :     
    858                                     self.unregisterFileNo(pollster, stderrfno)         
    859                                     outputclosed = 1 
    860                             else :     
    861                                 self.logDebug("Unexpected : %s - Sleeping a bit..." % self.formatFileEvent(fd, mask)) 
    862                                 time.sleep(0.01) 
    863                                  
    864                         if mask & (select.POLLIN | select.POLLPRI) :      
    865                             # We have something to read 
    866                             try : 
    867                                 data = os.read(fd, MEGABYTE) 
    868                             except (IOError, OSError), msg :     
    869                                 self.logDebug("Error while reading file %s : %s" % (fd, msg)) 
    870                             else : 
    871                                 if fd == infno : 
    872                                     if not data :    # If yes, then no more input data 
    873                                         self.unregisterFileNo(pollster, infno) 
    874                                         self.logDebug("Input data ends.") 
    875                                         endinput = 1 # this happens with real files. 
    876                                     else :     
    877                                         indata += data 
    878                                         totalfromcups += len(data) 
    879                                         self.logDebug("%s bytes read from CUPS so far..." % totalfromcups) 
    880                                 elif fd == fromcfno : 
    881                                     if not data : 
    882                                         self.logDebug("No back channel data to read from original backend yet, sleeping a bit...") 
    883                                         time.sleep(0.01) 
    884                                     else : 
    885                                         outdata += data 
    886                                         totalfromchild += len(data) 
    887                                         self.logDebug("%s bytes read from original backend so far..." % totalfromchild) 
    888                                 else :     
    889                                     self.logDebug("Unexpected : %s - Sleeping a bit..." % self.formatFileEvent(fd, mask)) 
    890                                     time.sleep(0.01) 
    891                                      
    892                         if mask & (select.POLLHUP | select.POLLERR) : 
    893                             # Treat POLLERR as an EOF. 
    894                             # Some standard I/O stream has no more datas 
    895                             self.unregisterFileNo(pollster, fd) 
    896                             if fd == infno : 
    897                                 # Here we are in the case where the input file is stdin. 
    898                                 # which has no more data to be read. 
    899                                 self.logDebug("Input data ends.") 
    900                                 endinput = 1 
    901                             elif fd == fromcfno :     
    902                                 # We are no more interested in this file descriptor         
    903                                 self.logDebug("Closing original backend's stdout+stderr.") 
    904                                 os.close(fromcfno) 
    905                                 endoutput = 1 
    906                             else :     
    907                                 self.logDebug("Unexpected : %s - Sleeping a bit..." % self.formatFileEvent(fd, mask)) 
    908                                 time.sleep(0.01) 
    909                                  
    910                         if mask & select.POLLNVAL :         
    911                             self.logDebug("File %s was closed. Unregistering from polling object." % fd) 
    912                             self.unregisterFileNo(pollster, fd) 
    913                     except IOError, msg :             
    914                         self.logDebug("Got an IOError : %s" % msg) # we got signalled during an I/O 
    915                  
    916         # We must close the original backend's input stream 
    917         if killed and not inputclosed : 
    918             self.logDebug("Forcing close of original backend's stdin.") 
    919             os.close(tocfno) 
    920          
    921         self.logDebug("Exiting streams polling loop...") 
    922          
    923         self.logDebug("input data's final length : %s" % len(indata)) 
    924         self.logDebug("back-channel data's final length : %s" % len(outdata)) 
    925          
    926         self.logDebug("Total bytes read from CUPS (job's datas) : %s" % totalfromcups) 
    927         self.logDebug("Total bytes sent to original backend (job's datas) : %s" % totaltochild) 
    928          
    929         self.logDebug("Total bytes read from original backend (back-channel datas) : %s" % totalfromchild) 
    930         self.logDebug("Total bytes sent back to CUPS (back-channel datas) : %s" % totaltocups) 
    931          
    932         # Check exit code of original CUPS backend.     
    933         if status == -1 : 
    934             # we exited the loop before the original backend exited 
    935             # now we have to wait for it to finish and get its status 
    936             self.logDebug("Waiting for original backend to exit...") 
    937             try : 
    938                 status = subprocess.wait() 
    939             except OSError : # already dead : TODO : detect when abnormal 
    940                 status = 0 
    941692        if os.WIFEXITED(status) : 
    942             return os.WEXITSTATUS(status) 
     693            status = os.WEXITSTATUS(status) 
     694            if status : 
     695              self.logInfo("CUPS backend %s returned %d." % (originalbackend, status), "error") 
     696            return status 
    943697        elif not killed :     
    944698            self.logInfo("CUPS backend %s died abnormally." % originalbackend, "error")