root/MGET/Trunk/PythonPackage/src/GeoEco/Logging.py

# Logging.py - Implements the Logger class, which other classes in the GeoEco
# Python package use to report activity to the user.
#
# Copyright (C) 2007 Jason J. Roberts
#
# 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 (available in the file LICENSE.TXT)
# 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., 51 Franklin Street, Fifth Floor, Boston, MA  02110-1301, USA.

import datetime
import logging
import logging.config       # Do not remove this statement, even though it seems redundant after importing the logging module above. Removing it will break something.
import os
import sys
import time
import traceback
import types

from GeoEco.DynamicDocString import DynamicDocString
from GeoEco.Internationalization import _, UnicodeToUserPreferredEncoding, UserPreferredEncodingToUnicode


# Public classes exposed by this module

class Logger(object):
    __doc__ = DynamicDocString()

    _LogInfoAsDebug = False    
    _LogErrorsAsWarnings = False    

    @classmethod
    def GetLogInfoAsDebug(cls):
        return Logger._LogInfoAsDebug

    @classmethod
    def SetLogInfoAsDebug(cls, value):
        if not isinstance(value, types.BooleanType):
            RaiseException(TypeError(_(u'The value provided for the value parameter is an invalid type ("%(badType)s" in Python). Please provide a value having the Python type "bool".') % {u'badType' : type(value).__name__}))
        Logger._LogInfoAsDebug = value

    LogInfoAsDebug = property(GetLogInfoAsDebug, SetLogInfoAsDebug, doc=DynamicDocString())

    @classmethod
    def GetLogErrorsAsWarnings(cls):
        return Logger._LogErrorsAsWarnings

    @classmethod
    def SetLogErrorsAsWarnings(cls, value):
        if not isinstance(value, types.BooleanType):
            RaiseException(TypeError(_(u'The value provided for the value parameter is an invalid type ("%(badType)s" in Python). Please provide a value having the Python type "bool".') % {u'badType' : type(value).__name__}))
        Logger._LogErrorsAsWarnings = value

    LogErrorsAsWarnings = property(GetLogErrorsAsWarnings, SetLogErrorsAsWarnings, doc=DynamicDocString())
    
    @classmethod
    def Debug(cls, format, *args):
        try:
            logging.getLogger(u'GeoEco').debug(format.rstrip(), *args)
        except:
            pass

    @classmethod
    def Info(cls, format, *args):
        try:
            if cls.GetLogInfoAsDebug():
                logging.getLogger(u'GeoEco').debug(format.rstrip(), *args)
            else:
                logging.getLogger(u'GeoEco').info(format.rstrip(), *args)
        except:
            pass

    @classmethod
    def Warning(cls, format, *args):
        try:
            logging.getLogger(u'GeoEco').warning(format.rstrip(), *args)
        except:
            pass

    @classmethod
    def Error(cls, format, *args):
        try:
            if cls.GetLogErrorsAsWarnings():
                logging.getLogger(u'GeoEco').warning(format.rstrip(), *args)
            else:
                logging.getLogger(u'GeoEco').error(format.rstrip(), *args)
        except:
            pass

    @classmethod
    def RaiseException(cls, exception):
        try:
            raise exception
        except:
            if cls.GetLogErrorsAsWarnings():
                cls.LogExceptionAsWarning()
            else:
                cls.LogExceptionAsError()
            raise

    @classmethod
    def LogInfoAndSetInfoToDebug(cls, format, *args):
        cls.Info(format, *args)
        oldValue = cls.GetLogInfoAsDebug()
        cls.SetLogInfoAsDebug(True)
        return oldValue

    @classmethod
    def LogExceptionAsWarning(cls, format=None, *args):
        cls._LogExceptionAndMessage(logging.WARNING, format, *args)

    @classmethod
    def LogExceptionAsError(cls, format=None, *args):
        if cls.GetLogErrorsAsWarnings():
            cls._LogExceptionAndMessage(logging.WARNING, format, *args)
        else:
            cls._LogExceptionAndMessage(logging.ERROR, format, *args)

    _ExceptionTracebackID = None
    _ReportedSubsequentErrors = False
    
    @classmethod
    def _LogExceptionAndMessage(cls, level, format=None, *args):
        try:
            logger = logging.getLogger(u'GeoEco')

            # Log the exception, if it has not been done already.

            tb = sys.exc_info()[2]
            if tb is not None:
                try:

                    # Obtain the inner-most traceback object.
                    
                    while tb.tb_next is not None:
                        tb = tb.tb_next

                    # If we have not logged a traceback yet, or this is a
                    # different one than last time, log it.
                    
                    if cls._ExceptionTracebackID != id(tb):
                        cls._ExceptionTracebackID = id(tb)
                        cls._ReportedSubsequentErrors = False
                        logger.log(level, u'%s: %s', unicode(sys.exc_info()[0].__name__), unicode(sys.exc_info()[1]).rstrip())

                        # Log useful debugging information, starting with a stack
                        # trace. To log the stack trace, we could just call
                        # logger.debug(exc_info=True), but that function ultimately
                        # calls traceback.print_exception(), which only prints the
                        # stack frames from the exception back to the frame that
                        # handled the exception. It does NOT go all the way back up
                        # the stack. That is is not good enough for us, because we
                        # need to see how we got to the problem, all the way from
                        # the program entry point. So we have to use the
                        # traceback.extract_stack() function to get those outer
                        # frames.

                        logger.debug(_(u'---------- BEGINNING OF DEBUGGING INFORMATION ----------'))
                        logger.debug(_(u'Traceback (most recent call last):'))
                        stackTraceEntries = traceback.extract_stack(tb.tb_frame.f_back) + traceback.extract_tb(tb)
                        for entry in traceback.format_list(stackTraceEntries):
                            for line in entry.split('\n'):
                                if len(line) > 0:
                                    logger.debug(line.rstrip())
                        logger.debug(u'%s: %s', unicode(sys.exc_info()[0].__name__), unicode(sys.exc_info()[1]).rstrip())

                        # Log the local and global variables of the most recent
                        # GeoEco call, unless it is RaiseException.

                        frame = tb.tb_frame
                        try:
                            while frame is not None and (frame.f_code.co_filename.find('GeoEco') == -1 or frame.f_code.co_filename.find('AssimilatedModules') >= 0 or frame.f_code.co_filename.endswith('Logging.py') and frame.f_code.co_name == 'RaiseException' or frame.f_code.co_filename.endswith('R.py') and frame.f_code.co_name in ['__call__', '__getitem__', '__setitem__', '__delitem__', '__getattr__', '__setattr__', '__delattr__']):
                                frame = frame.f_back
                            if frame is None:
                                frame = tb.tb_frame
                            logger.debug(_(u'Local variables for stack frame: File "%(file)s", line %(line)i, in %(func)s:') % {u'file' : frame.f_code.co_filename, u'line' : frame.f_lineno, u'func' : frame.f_code.co_name})
                            keys = frame.f_locals.keys()
                            keys.sort()
                            for key in keys:
                                logger.debug(u'  %s = %s', unicode(key), repr(frame.f_locals[key]))

                            logger.debug(_(u'Global variables for stack frame: File "%(file)s", line %(line)i, in %(func)s:') % {u'file' : frame.f_code.co_filename, u'line' : frame.f_lineno, u'func' : frame.f_code.co_name})
                            keys = frame.f_globals.keys()
                            keys.sort()
                            for key in keys:
                                if key != '__builtins__':       # Don't bother dumping __builtins__
                                    logger.debug(u'  %s = %s', unicode(key), repr(frame.f_globals[key]))
                        finally:
                            del frame            # Avoid memory cycle by explicitly deleting frame object; see Python documentation for discussion of this problem.

                        # Log other useful info.                                

                        logger.debug(_(u'Enviornment variables:'))
                        keys =  os.environ.keys()
                        keys.sort()
                        for key in keys:
                            logger.debug(u'  %s = %s', unicode(key), repr(os.environ[key]))

                        logger.debug(_(u'Other variables:'))
                        import GeoEco
                        logger.debug(u'  GeoEco.__version__ = %s', repr(GeoEco.__version__))
                        logger.debug(u'  sys.argv = %s', repr(sys.argv))
                        logger.debug(u'  sys.version = %s', str(sys.version))
                        logger.debug(u'  sys.version_info = %s', repr(sys.version_info))
                        logger.debug(u'  sys.platform = %s', str(sys.platform))
                        if isinstance(sys.platform, basestring) and sys.platform.lower() == 'win32':
                            logger.debug(u'  sys.getwindowsversion() = %s', repr(sys.getwindowsversion()))
                        logger.debug(u'  os.getcwd() = %s', str(os.getcwd()))
                        logger.debug(u'  sys.path = %s', repr(sys.path))

                        keys =  sys.modules.keys()
                        keys.sort()
                        logger.debug(_(u'Loaded modules: ') + u', '.join(keys))

                        logger.debug(_(u'---------- END OF DEBUGGING INFORMATION ----------'))
                finally:
                    del tb          # Avoid memory cycle by explicitly deleting traceback object; see Python documentation for discussion of this problem.
            else:
                cls._ExceptionTracebackID = None

            # If the caller provided a message, log it.

            if format is not None:
                
                # If this is the first message to be logged after the exception,
                # first log a message indicating that the following messages are
                # consequences of the original exception.

                if cls._ExceptionTracebackID is not None and not cls._ReportedSubsequentErrors:
                    logger.log(level, _(u'The following consequences resulted from the original error:'))
                    cls._ReportedSubsequentErrors = True

                # Log the message.
                
                logger.log(level, format.rstrip(), *args)
            
        except:
            pass

    @classmethod
    def Initialize(cls, activateArcGISLogging=False, loggingConfigFile=None):
        cls.__doc__.Obj.ValidateMethodInvocation()

        # Hack: Set the _srcfile attribute in the logging module to
        # None, so that the module does not try to walk the stack when
        # emitting log messages. This stack walking screws up our
        # exception logging code when we're running in the Python 2.5
        # exception handler hosted in-process by ArcGIS 9.3.

        logging._srcfile = None

        # Hack: this module (GeoEco.Logging) defines a class _ArcGISLoggingHandler
        # which derives from logging.Handler. We want the user to be able to
        # reference this handler in a logging configuration file. But the logging.config
        # module offers no way to import this module into its namespace, which
        # prevents it from being able to instantiate our class. So we must manually
        # import ourself into the logging namespace (! not logging.config !).

        if not sys.modules[u'logging'].__dict__.has_key(u'GeoEco'):
            sys.modules[u'logging'].__dict__[u'GeoEco'] = sys.modules[u'GeoEco']
        if not sys.modules[u'logging'].__dict__.has_key(u'GeoEco.Logging'):
            sys.modules[u'logging'].__dict__[u'GeoEco.Logging'] = sys.modules[u'GeoEco.Logging']

        # If the caller provided a file, try to initialize the logging system
        # from it.

        callersFileWarning = None
        if loggingConfigFile is not None:
            callersFileWarning = cls._InitializeLoggingFromFile(loggingConfigFile)

        # If the caller did not provide a file, or the logging system could not
        # be initialized from it, try the user's default logging config file.

        userDefaultFile = None
        userDefaultFileWarning = None
        if loggingConfigFile is None or callersFileWarning is not None:
            if sys.platform.lower() == u'win32' and os.environ.has_key(u'APPDATA'):
                import codecs
                userDefaultFile = codecs.mbcs_decode(os.environ['APPDATA'])[0] + u'\\GeoEco\\Logging.ini'
            if userDefaultFile is not None:
                if os.path.isfile(userDefaultFile):
                    userDefaultFileWarning = cls._InitializeLoggingFromFile(userDefaultFile)
                else:
                    userDefaultFile = None

        # If if the caller's file or the user's default file did not work, try
        # the system default logging file.

        systemDefaultFile = os.path.join(os.path.dirname(sys.modules['GeoEco.Logging'].__file__), u'Configuration', u'Logging.ini')
        systemDefaultFileWarning = None
        if (loggingConfigFile is None or callersFileWarning is not None) and (userDefaultFile is None or userDefaultFileWarning is not None):
            systemDefaultFileWarning = cls._InitializeLoggingFromFile(systemDefaultFile)

        # If all of the above failed, initialize using a hard-coded
        # configuration.

        manualInitializationWarning = None        
        if (loggingConfigFile is None or callersFileWarning is not None) and (userDefaultFile is None or userDefaultFileWarning is not None) and systemDefaultFileWarning is not None:
            try:
                stdout_handler = logging.StreamHandler(strm=sys.stdout)
                stdout_handler.level = logging.INFO
                logging.getLogger(u'').addHandler(stdout_handler)
                logging.getLogger(u'').setLevel(logging.INFO)
            except Exception, e:
                manualInitializationWarning = _(u'Failed to initialize the logging system from hard-coded settings. One of the logging functions reported the error: %s: %s') % (e.__class__.__name__, unicode(e))

        # Log warning messages, if any, and a success message. We have to delay of
        # all this until now, because until this point, the logging system may not
        # have been initialized. If we were able to initialize it, we want any
        # warning messages to be logged using the best possible settings.

        if manualInitializationWarning is not None:
            if callersFileWarning is not None:
                print(callersFileWarning)
            if userDefaultFileWarning is not None:
                print(userDefaultFileWarning)
            print(systemDefaultFileWarning)
            print(manualInitializationWarning)
            print(_(u'The logging system could not be initialized. Log messages will not be reported.'))

        elif loggingConfigFile is not None and callersFileWarning is None:
            cls.Debug(_(u'Logging system initialized from config file "%s".'), loggingConfigFile)

        elif userDefaultFile is not None and userDefaultFileWarning is None:
            if callersFileWarning is not None:
                cls.Warning(callersFileWarning)
            cls.Debug(_(u'Logging system initialized from config file "%s".'), userDefaultFile)

        elif systemDefaultFileWarning is None:
            if callersFileWarning is not None:
                cls.Warning(callersFileWarning)
            if userDefaultFileWarning is not None:
                cls.Warning(userDefaultFileWarning)
            cls.Debug(_(u'Logging system initialized from config file "%s".'), systemDefaultFile)

        elif manualInitializationWarning is None:
            if callersFileWarning is not None:
                cls.Warning(callersFileWarning)
            if userDefaultFileWarning is not None:
                cls.Warning(userDefaultFileWarning)
            cls.Warning(systemDefaultFileWarning)
            cls.Info(_(u'Log messages will only be sent to the console output (stdout).'))

        # Active ArcGIS logging if requested.

        if activateArcGISLogging and (loggingConfigFile is not None and callersFileWarning is None or userDefaultFile is not None and userDefaultFileWarning is None or systemDefaultFileWarning is None):
            cls.ActivateArcGISLogging()

    @classmethod
    def ActivateArcGISLogging(cls):
        _ArcGISLoggingHandler.Activate()

    @classmethod
    def _InitializeLoggingFromFile(cls, loggingConfigFile=None):
        assert isinstance(loggingConfigFile, types.UnicodeType), u'loggingConfigFile must be a Unicode string'

        # Try to open the file for reading, so we know it is accessible.

        try:
            f = file(loggingConfigFile, u'r')
        except Exception, e:
            return(_(u'Failed to initialize logging from the config file "%(file)s". The file could not be opened. The operating system reported: %(error)s: %(msg)s') % {u'file': loggingConfigFile, u'error': e.__class__.__name__, u'msg': unicode(e)})
        try:
            f.close()
        except:
            pass

        # If that was successful, try to initialize logging.
        #
        # If the logging config file is improperly formatted, the logging
        # initialization function can fail in two ways. First, it may raise an
        # exception. In this case, catch it as usual and return a failure
        # message.
        #
        # In the second failure mode, it simply prints an exception trace to
        # stderr, but does not raise an exception or return a value indicating
        # failure. This would be ok, except that it can leave the logging system
        # in an inconsistent state: subsequent calls to logging functions such
        # as logging.debug() will fail. Again, these failed calls swallow
        # exceptions, just printing their traces to stderr.
        #
        # Because we don't want stderr to be spammed when logging fails to
        # initialize, we detect the failure in the logging configuration
        # function by capturing stderr, and return a failure message.

        cap = _StderrCapturer()
        cap.Start()
        try:
            try:
                # First handle a bug in logging.config.fileConfig that causes the
                # logging Handler class to raise an exception at shutdown. This bug
                # was reported in Aug 2006 and exists in Python 2.4.4 but is
                # supposedly fixed in Python 2.5.
                
                if globals().has_key(u'_TempHandler') and globals()[u'_TempHandler'] is not None:
                    logging.getLogger(u'GeoEco').removeHandler(globals()[u'_TempHandler'])
                    globals()[u'_TempHandler'].close()
                    del globals()[u'_TempHandler']

                # Now read the config file.
                
                logging.config.fileConfig(loggingConfigFile)
                
            except Exception, e:
                return _(u'Failed to initialize logging from the config file "%(file)s". Please verify that the contents of the config file are valid. Search the Python documentation for "logging configuration file format". In Python 2.4, the article is titled "6.29.10.2 Configuration file format". Python\'s log configuration file parser (logging.config.fileConfig) reported: %(error)s: %(msg)s') % {u'file': loggingConfigFile, u'error': e.__class__.__name__, u'msg': unicode(e)}
        finally:
            result = cap.Stop()

        if result is not None and len(result.strip()) > 0:
            result_lines = result.strip().split(u'\n')
            i = 1
            while i < len(result_lines) and (len(result_lines[i]) == 0 or result_lines[i][0] == u' '):
                i = i + 1
            message = u''
            for j in range(i, len(result_lines)):
                message = message + result_lines[j] + u'\n'
            message = message.strip()
            return _(u'Failed to initialize logging from the config file "%s". Please verify that the contents of the config file are valid. Search the Python documentation for "logging configuration file format". In Python 2.4, the article is titled "6.29.10.2 Configuration file format". Python\'s log configuration file parser (logging.config.fileConfig) reported the error: %s') % (loggingConfigFile, message)

        # Return successfully.

        return None


class ProgressReporter(object):    
    __doc__ = DynamicDocString()

    def __init__(self,
                 progressMessage1=_(u'Progress report: %(elapsed)s elapsed, %(opsCompleted)i operations completed, %(perOp)s per operation, %(opsRemaining)i remaining, estimated completion time: %(etc)s.'),
                 progressMessage2=_(u'Progress report: %(elapsed)s elapsed, %(opsCompleted)i operations completed, %(perOp)s per operation.'),
                 completionMessage=_(u'Processing complete: %(elapsed)s elapsed, %(opsCompleted)i operations completed, %(perOp)s per operation.'),
                 abortedMessage=_(u'Processing stopped before all operations were completed: %(elapsed)s elapsed, %(opsCompleted)i operations completed, %(perOp)s per operation, %(opsIncomplete)i operations not completed.'),
                 loggingChannel=u'GeoEco'):

        self.ProgressMessage1 = progressMessage1
        self.ProgressMessage2 = progressMessage2
        self.CompletionMessage = completionMessage
        self.AbortedMessage = abortedMessage
        self.LoggingChannel = loggingChannel
        self._TotalOperations = None
        self._OperationsCompleted = 0
        self._TimeStarted = None
        self._TimeCompleted = None
        self._ClockStarted = None
        self._ClockNextReportTime = None

    def _GetProgressMessage1(self):
        return self._ProgressMessage1

    def _SetProgressMessage1(self, value):
        assert isinstance(value, (types.NoneType, types.UnicodeType)), u'ProgressMessage1 must be a Unicode string, or None.'
        self._ProgressMessage1 = value
    
    ProgressMessage1 = property(_GetProgressMessage1, _SetProgressMessage1, doc=DynamicDocString())

    def _GetProgressMessage2(self):
        return self._ProgressMessage2

    def _SetProgressMessage2(self, value):
        assert isinstance(value, (types.NoneType, types.UnicodeType)), u'ProgressMessage2 must be a Unicode string, or None.'
        self._ProgressMessage2 = value
    
    ProgressMessage2 = property(_GetProgressMessage2, _SetProgressMessage2, doc=DynamicDocString())

    def _GetCompletionMessage(self):
        return self._CompletionMessage

    def _SetCompletionMessage(self, value):
        assert isinstance(value, (types.NoneType, types.UnicodeType)), u'CompletionMessage must be a Unicode string, or None.'
        self._CompletionMessage = value
    
    CompletionMessage = property(_GetCompletionMessage, _SetCompletionMessage, doc=DynamicDocString())

    def _GetAbortedMessage(self):
        return self._AbortedMessage

    def _SetAbortedMessage(self, value):
        assert isinstance(value, (types.NoneType, types.UnicodeType)), u'AbortedMessage must be a Unicode string, or None.'
        self._AbortedMessage = value
    
    AbortedMessage = property(_GetAbortedMessage, _SetAbortedMessage, doc=DynamicDocString())

    def _GetLoggingChannel(self):
        return self._LoggingChannel

    def _SetLoggingChannel(self, value):
        assert isinstance(value, (types.NoneType, types.UnicodeType)), u'LoggingChannel must be a Unicode string, or None.'
        self._LoggingChannel = value
    
    LoggingChannel = property(_GetLoggingChannel, _SetLoggingChannel, doc=DynamicDocString())

    def _GetTotalOperations(self):
        return self._TotalOperations

    def _SetTotalOperations(self, value):
        assert value is None or (isinstance(value, types.IntType) and value >= 0), u'totalOperations must be a non-negative integer, or None'
        self._TotalOperations = value
        if self._TotalOperations is not None and self.HasStarted and self._OperationsCompleted >= self._TotalOperations:
            self.Stop()
    
    TotalOperations = property(_GetTotalOperations, _SetTotalOperations, doc=DynamicDocString())

    def _GetOperationsCompleted(self):
        return self._OperationsCompleted
    
    OperationsCompleted = property(_GetOperationsCompleted, doc=DynamicDocString())

    def _GetTimeStarted(self):
        return self._TimeStarted
    
    TimeStarted = property(_GetTimeStarted, doc=DynamicDocString())

    def _GetTimeCompleted(self):
        return self._TimeCompleted
    
    TimeCompleted = property(_GetTimeCompleted, doc=DynamicDocString())

    def _GetHasStarted(self):
        return self._TimeStarted is not None
    
    HasStarted = property(_GetHasStarted, doc=DynamicDocString())

    def _GetHasCompleted(self):
        return self._TimeCompleted is not None
    
    HasCompleted = property(_GetHasCompleted, doc=DynamicDocString())

    def _GetTimeElapsed(self):
        if self._TimeStarted is None:
            return None
        if self._TimeCompleted is None:
            return datetime.timedelta(seconds = time.clock() - self._ClockStarted)
        return self._TimeCompleted - self._TimeStarted

    TimeElapsed = property(_GetTimeElapsed, doc=DynamicDocString())

    def Start(self, totalOperations=None):
        assert not self.HasStarted, u'This ProgressReporter was already started and cannot be started a second time'
        
        self.TotalOperations = totalOperations
        self._OperationsCompleted = 0
        self._TimeStarted = datetime.datetime.now()
        self._ClockStarted = time.clock()
        self._ClockNextReportTime = self._ClockStarted + 60.0

        if totalOperations == 0:
            self.Stop()

    def ReportProgress(self, operationsCompleted=1):
        assert self.HasStarted, u'This ProgressReporter has not been started'
        assert operationsCompleted >= 1, u'operationsCompelted must be greater than or equal to 1'
        
        self._OperationsCompleted += operationsCompleted
        
        if self._TotalOperations is not None and self._OperationsCompleted >= self._TotalOperations:
            self.Stop()
            return
        
        clockNow = time.clock()
        if clockNow >= self._ClockNextReportTime:
            timeElapsed = self.TimeElapsed
            timePerOp = timeElapsed / self._OperationsCompleted

            if self._TotalOperations is not None:
                if self._ProgressMessage1 is not None:
                    now = datetime.datetime.now()
                    timeOfCompletion = now + timePerOp * (self._TotalOperations - self._OperationsCompleted)
                    if now.day == timeOfCompletion.day:
                        etc = unicode(timeOfCompletion.strftime('%X'))
                    else:
                        etc = unicode(timeOfCompletion.strftime('%c'))
                    self._Log(self._FormatProgressMessage1(timeElapsed, self._OperationsCompleted, timePerOp, self._TotalOperations - self._OperationsCompleted, etc))

            elif self._ProgressMessage2 is not None:
                self._Log(self._FormatProgressMessage2(timeElapsed, self._OperationsCompleted, timePerOp))

            self._ClockNextReportTime = clockNow + 300.0

    def Stop(self):
        assert self.HasStarted, u'This ProgressReporter has not been started'
        if self.HasCompleted:
            return
        
        self._TimeCompleted = datetime.datetime.now()
        timeElapsed = self.TimeElapsed
        if self._OperationsCompleted > 0:
            timePerOp = timeElapsed / self._OperationsCompleted
        else:
            timePerOp = datetime.timedelta()
        if self._TotalOperations is None or self._OperationsCompleted >= self._TotalOperations:
            if self._CompletionMessage is not None:
                self._Log(self._FormatCompletionMessage(timeElapsed, self._OperationsCompleted, timePerOp))
        elif self._AbortedMessage is not None:
            self._Log(self._FormatAbortedMessage(timeElapsed, self._OperationsCompleted, timePerOp, self._TotalOperations - self._OperationsCompleted))

    def _Log(self, message):
        try:
            if self._LoggingChannel == u'GeoEco':
                Logger.Info(message)
            else:
                logging.getLogger(self._LoggingChannel).info(message)
        except:
            pass

    # Private methods intended to be overridden by derived classes
    # that need to do custom formatting of the progress messages.

    def _FormatProgressMessage1(self, timeElapsed, opsCompleted, timePerOp, opsRemaining, estimatedTimeOfCompletionString):
        return self._ProgressMessage1 % {u'elapsed' : unicode(datetime.timedelta(days=timeElapsed.days, seconds=timeElapsed.seconds)), u'opsCompleted': opsCompleted, u'perOp': unicode(timePerOp), u'opsRemaining': opsRemaining, u'etc': estimatedTimeOfCompletionString}

    def _FormatProgressMessage2(self, timeElapsed, opsCompleted, timePerOp):
        return self._ProgressMessage2 % {u'elapsed' : unicode(datetime.timedelta(days=timeElapsed.days, seconds=timeElapsed.seconds)), u'opsCompleted': opsCompleted, u'perOp': unicode(timePerOp)}

    def _FormatCompletionMessage(self, timeElapsed, opsCompleted, timePerOp):
        return self._CompletionMessage % {u'elapsed' : unicode(datetime.timedelta(days=timeElapsed.days, seconds=timeElapsed.seconds)), u'opsCompleted': opsCompleted, u'perOp': unicode(timePerOp)}

    def _FormatAbortedMessage(self, timeElapsed, opsCompleted, timePerOp, opsIncomplete):
        return self._AbortedMessage % {u'elapsed' : unicode(datetime.timedelta(days=timeElapsed.days, seconds=timeElapsed.seconds)), u'opsCompleted': opsCompleted, u'perOp': unicode(timePerOp), u'opsIncomplete': opsIncomplete}


# Private classes and functions global to this module

class _ArcGISLoggingHandler(logging.Handler):

    def __init__(self, level=logging.NOTSET):
        logging.Handler.__init__(self, level)

    def emit(self, record):
        if self.__class__._Instance != self:
            self.__class__._Instance = self
        if not isinstance(record, logging.LogRecord):
            return
        try:
            if self.__class__._PreactivationQueue is not None:
                if len(self.__class__._PreactivationQueue) == 1000:
                    del self.__class__._PreactivationQueue[0]
                self.__class__._PreactivationQueue.append(record)
            else:
                self._Emit(record)
        except:
            pass

    def _Emit(self, record):
        try:
            from GeoEco.ArcGIS import GeoprocessorManager
            message = self.format(record)
            if GeoprocessorManager.GetGeoprocessorIsCOMObject():
                message = UserPreferredEncodingToUnicode(message)
            else:
                message = UnicodeToUserPreferredEncoding(message)
            if record.levelno >= logging.ERROR:
                GeoprocessorManager.GetGeoprocessor().AddError(message)
            elif record.levelno >= logging.WARNING:
                GeoprocessorManager.GetGeoprocessor().AddWarning(message)
            else:
                GeoprocessorManager.GetGeoprocessor().AddMessage(message)
        except:
            pass

    @classmethod
    def GetInstance(cls):
        return _ArcGISLoggingHandler._Instance

    @classmethod
    def Activate(cls):
        if cls._PreactivationQueue is not None:
            from GeoEco.ArcGIS import GeoprocessorManager
            if GeoprocessorManager.GetGeoprocessor() is None:
                GeoprocessorManager.InitializeGeoprocessor()
            if GeoprocessorManager.GetArcGISMajorVersion() == 9 and GeoprocessorManager.GetArcGISMinorVersion() == 3 and GeoprocessorManager.GetArcGISServicePack() == 0:       # Handle ArcGIS 9.3 bug NIM036130 - Print statements inside an in-proc script tool will lead to a "<type 'exceptions.IOError'>: [Errno 9] Bad file descriptor" error
                _GeoEcoStreamHandler.Deactivate()
            while len(cls._PreactivationQueue) > 0:
                record = cls._PreactivationQueue.pop(0)
                cls._Instance._Emit(record)
                del record
            cls._PreactivationQueue = None

    _Instance = None
    _PreactivationQueue = []


class _GeoEcoStreamHandler(logging.StreamHandler):

    def __init__(self, strm=None):
        logging.StreamHandler.__init__(self, strm)

    def emit(self, record):
        if not _GeoEcoStreamHandler._Deactivated:
            logging.StreamHandler.emit(self, record)

    @classmethod
    def Deactivate(cls):
        _GeoEcoStreamHandler._Deactivated = True

    _Deactivated = False


class _StderrCapturer(object):

    def __init__(self):
        self._Buffer = None
        self._OriginalStderr = None

    def Start(self):
        if self._OriginalStderr is None:
            self._Buffer = None
            self._OriginalStderr = sys.stderr
            sys.stderr = self

    def write(self, obj):
        if self._OriginalStderr is not None:
            if self._Buffer is None:
                self._Buffer = unicode(obj)
            else:
                self._Buffer = self._Buffer + unicode(obj)

    def Stop(self):
        if self._OriginalStderr is not None:
            sys.stderr = self._OriginalStderr
            self._OriginalStderr = None
            return self._Buffer
        else:
            return None


# Initialize, but do not activate, the ArcGIS logging handler. Until the handler
# is activated by an external caller (by calling GeoEco.Logging.ActivateArcGISLogging)
# the handler will just queue log messages in memory. Then, when it is
# activated, it will dump the queue to ArcGIS. This ensures that all log
# messages are reported to the ArcGIS UI when GeoEco is used from an Arc
# geoprocessing script, even those generated before the Activate call is made.

_TempHandler = None         # This is required to address in Python's logging.config.fileConfig function: it calls logging._handlers.clear() but does not also remove the handlers from logging._handlerList
try:
    if _ArcGISLoggingHandler.GetInstance() is None:         # I'm fairly sure this will always return None, since nobody can instantiate _ArcGISLoggingHandler without importing the module first, causing the code below to execute first.
        _TempHandler = _ArcGISLoggingHandler(logging.INFO)
        _logger = logging.getLogger(u'GeoEco')
        if _logger is not None:
            _logger.addHandler(_TempHandler)
        del _logger
except:
    pass


###############################################################################
# Metadata: module
###############################################################################

from GeoEco.Metadata import *
from GeoEco.Types import *

AddModuleMetadata(shortDescription=_(u'Implements the Logger class, which other GeoEco classes use to report activity to the user.'))

###############################################################################
# Metadata: Logger class
###############################################################################

AddClassMetadata(Logger,
    shortDescription=_(u'Provides methods for reporting messages to the user.'),
    isExposedAsCOMServer=True,
    comIID=u'{0DA39145-CDE6-48F2-AFD9-8EA6623A3121}',
    comCLSID=u'{EE5ED6B5-55E7-4D65-B627-EF062B8332C4}')

# Public properties

AddPropertyMetadata(Logger.LogInfoAsDebug,
    typeMetadata=BooleanTypeMetadata(),
    shortDescription=_(u'If True, informational messages will be logged as debug messages.'),
    longDescription=_(
u"""Informational messages describe major processing steps that may be
interesting to the user but do not require the user to take any
action. For example, a method that performs three major processing
tasks might report an informational message after each step is
finished.

Sometimes your method may repeatedly call another method to accomplish
some processing that you consider to be relatively unimportant. For
example, your method may copy a bunch of files, and you might want to
inform the user that you are performing the copying but do not want to
inform them about every file. In this situation, set this property to
True prior to entering the copy loop, and restore it to False when you
are done."""),
    isExposedToPythonCallers=True,
    isExposedByCOM=True)

AddPropertyMetadata(Logger.LogErrorsAsWarnings,
    typeMetadata=BooleanTypeMetadata(),
    shortDescription=_(u'If True, errors will be logged as warning messages.'),
    longDescription=_(
u"""Error messages describe failures that halt processing and require the user
to fix a problem and restart processing. ArcGIS highlights error messages in red
in its user interface, and fails geoprocessing if even one error is reported.

Sometimes you don't want to halt processing when an unimportant operation fails.
For example, you may not care that a temporary file could not be deleted. In
that situation, set this property to True prior to calling File.Delete to delete
the file. If the deletion fails, the errors that occur will be logged as
warnings rather than errors, and processing will not be halted. After
File.Delete returns, set this property back to False, so that subsequent errors
will be logged as errors."""),
    isExposedToPythonCallers=True,
    isExposedByCOM=True)

# Public method: Debug

AddMethodMetadata(Logger.Debug,
    shortDescription=_(u'Reports a debugging message to the user.'),
    longDescription=_(
u"""Like the C printf function or the Python % operator, this method generates a
message string by merging in the optional arguments into the format string.

Debugging messages describe processing details that are usually not interesting
unless the user is diagnosing a problem. The default configuration of the
logging system causes debugging messages to be discarded."""),
    isExposedToPythonCallers=True,
    isExposedByCOM=True)

AddArgumentMetadata(Logger.Debug, u'cls',
    typeMetadata=ClassOrClassInstanceTypeMetadata(cls=Logger),
    description=_(u'%s class or an instance of it.') % Logger.__name__)

AddArgumentMetadata(Logger.Debug, u'format',
    typeMetadata=UnicodeStringTypeMetadata(),
    description=_(
u"""A printf-style format string. While Unicode strings are encouraged, this
method will also accept an 8-bit string for this parameter. For a complete
specification of the format of this string, look up "% formatting" in the Python
documentation."""))

AddArgumentMetadata(Logger.Debug, u'args',
    typeMetadata=TupleTypeMetadata(elementType=AnyObjectTypeMetadata(canBeNone=True)),
    description=_(u'Values to insert into the format string.'))

# Public method: Info

AddMethodMetadata(Logger.Info,
    shortDescription=_(u'Reports an informational message to the user.'),
    longDescription=_(
u"""Like the C printf function or the Python % operator, this method generates a
message string by merging in the optional arguments into the format string.

Informational messages describe major processing steps that may be interesting to
the user but do not require the user to take any action. For example, a method
that performs three major processing tasks might report an informational message
after each step is finished. Do not report too many informational messages or
you may overwhelm the user. Report processing details as debug messages."""),
    isExposedToPythonCallers=True,
    isExposedByCOM=True)

AddArgumentMetadata(Logger.Info, u'cls',
    typeMetadata=ClassOrClassInstanceTypeMetadata(cls=Logger),
    description=Logger.Debug.__doc__.Obj.Arguments[0].Description)

AddArgumentMetadata(Logger.Info, u'format',
    typeMetadata=UnicodeStringTypeMetadata(),
    description=Logger.Debug.__doc__.Obj.Arguments[1].Description)

AddArgumentMetadata(Logger.Info, u'args',
    typeMetadata=TupleTypeMetadata(elementType=AnyObjectTypeMetadata(canBeNone=True)),
    description=Logger.Debug.__doc__.Obj.Arguments[2].Description)

# Public method: Warning

AddMethodMetadata(Logger.Warning,
    shortDescription=_(u'Reports a warning message to the user.'),
    longDescription=_(
u"""Like the C printf function or the Python % operator, this method generates a
message string by merging in the optional arguments into the format string.

Warning messages describe important events that should be brought to the user's
attention but do not necessarily indicate that processing will fail. To draw the
user's attention, ArcGIS highlights warning messages in green in its user
interface.

*Note to GeoEco developers:* Do not call this method to report exceptions caught
inside methods of GeoEco classes. Call LogExceptionAsWarning instead."""),
    isExposedToPythonCallers=True,
    isExposedByCOM=True)

AddArgumentMetadata(Logger.Warning, u'cls',
    typeMetadata=ClassOrClassInstanceTypeMetadata(cls=Logger),
    description=Logger.Debug.__doc__.Obj.Arguments[0].Description)

AddArgumentMetadata(Logger.Warning, u'format',
    typeMetadata=UnicodeStringTypeMetadata(),
    description=Logger.Debug.__doc__.Obj.Arguments[1].Description)

AddArgumentMetadata(Logger.Warning, u'args',
    typeMetadata=TupleTypeMetadata(elementType=AnyObjectTypeMetadata(canBeNone=True)),
    description=Logger.Debug.__doc__.Obj.Arguments[2].Description)

# Public method: Error

AddMethodMetadata(Logger.Error,
    shortDescription=_(u'Reports an error message to the user.'),
    longDescription=_(
u"""Like the C printf function or the Python % operator, this method generates a
message string by merging in the optional arguments into the format string.

Error messages describe failures that halt processing and require the user to
fix a problem and restart processing. ArcGIS highlights error messages in red in
its user interface, and fails geoprocessing if even one error is reported.
Because of this, do not report error messages unless the problem is serious
enough to stop processing. For problems that may or may not be of consequence to
the user, report warning messages.

If LogWarningsAsErrors has been set to True, the message will be reported as a
warning rather than an error.

*Note to GeoEco developers:* Do not call this method to report exceptions caught
inside methods of GeoEco classes. Call LogExceptionAsError instead."""),
    isExposedToPythonCallers=True,
    isExposedByCOM=True)

AddArgumentMetadata(Logger.Error, u'cls',
    typeMetadata=ClassOrClassInstanceTypeMetadata(cls=Logger),
    description=Logger.Debug.__doc__.Obj.Arguments[0].Description)

AddArgumentMetadata(Logger.Error, u'format',
    typeMetadata=UnicodeStringTypeMetadata(),
    description=Logger.Debug.__doc__.Obj.Arguments[1].Description)

AddArgumentMetadata(Logger.Error, u'args',
    typeMetadata=TupleTypeMetadata(elementType=AnyObjectTypeMetadata(canBeNone=True)),
    description=Logger.Debug.__doc__.Obj.Arguments[2].Description)

# Public method: LogInfoAndSetInfoToDebug

AddMethodMetadata(Logger.LogInfoAndSetInfoToDebug,
    shortDescription=_(u'Reports an informational message, sets the LogInfoAsDebug property to True, and returns its previous value.'),
    longDescription=_(
u"""This function is used to efficiently implement a common logging
scenario: a function wants to log one informational message announcing
the processing it is doing and report everything else as debug
messages, including informational messages reported by nested
functions. The Python pattern for implementing this scenario is::

    from GeoEco.Internationalization import _
    from GeoEco.Logging import Logger

    def MyFunc(...):
        oldLogInfoAsDebug = Logger.LogInfoAndSetInfoToDebug(_(u'Doing my processing...'))
        try:
            ...
        finally:
            Logger.SetLogInfoAsDebug(oldLogInfoAsDebug)
"""),
    isExposedToPythonCallers=True,
    isExposedByCOM=True)

CopyArgumentMetadata(Logger.Info, u'cls', Logger.LogInfoAndSetInfoToDebug, u'cls')
CopyArgumentMetadata(Logger.Info, u'format', Logger.LogInfoAndSetInfoToDebug, u'format')
CopyArgumentMetadata(Logger.Info, u'args', Logger.LogInfoAndSetInfoToDebug, u'args')

AddResultMetadata(Logger.LogInfoAndSetInfoToDebug, u'oldLogInfoAsDebug',
    typeMetadata=BooleanTypeMetadata(),
    description=_(u"""The old value of the LogInfoAsDebug property, prior to this method being invoked."""))

# Public method: RaiseException

AddMethodMetadata(Logger.RaiseException,
    shortDescription=_(u'Raises a Python exception and logs it as an error message and additional information as debug messages.'),
    longDescription=_(
u"""GeoEco classes should not raise exceptions by calling the Python raise
statement directly, but should call this method instead. This method will raise
the exception, log it as an error (or warning, if LogWarningsAsErrors has been
set to True), and also log a bunch of debugging information as debug messages."""))

AddArgumentMetadata(Logger.RaiseException, u'cls',
    typeMetadata=ClassOrClassInstanceTypeMetadata(cls=Logger),
    description=Logger.Debug.__doc__.Obj.Arguments[0].Description)

AddArgumentMetadata(Logger.RaiseException, u'exception',
    typeMetadata=ClassInstanceTypeMetadata(cls=Exception),
    description=_(u'The Python exception instance to raise.'))

# Public method: LogExceptionAsWarning

AddMethodMetadata(Logger.LogExceptionAsWarning,
    shortDescription=_(u'Logs a Python exception caught by a GeoEco class as a warning message and additional information as debug messages.'),
    longDescription=_(
u"""GeoEco classes should use LogExceptionAsWarning or LogExceptionAsError to
report exceptions caught by except clauses of try statements, like this::

    Logger.Debug(_(u'Copying file %s to %s.') % (sourceFile, destinationFile))
    try:
        shutil.copy2(sourceFile, destinationFile)
    except:
        Logger.LogExceptionAsError(_(u'Could not copy file %(source)s to %(dest)s.') % \\
                                   {u'source' :  sourceFile, u'dest' : destinationFile})
        raise

As shown, the except clause should re-raise the exception (if appropriate) using
a raise statement with no parameters. LogExceptionAsWarning and
LogExceptionAsError will log the exception and some debugging information,
including a stack trace. If the caller provides the optional format string, it
is logged as a "consequence" of the original error. For example the code above
produces the following output when the caller does not have permission to write
the destination file::

    DEBUG Copying file c:\\foo.txt to c:\\bar.txt.
    ERROR IOError: [Errno 13] Permission denied: u'c:\\\\bar.txt'
    DEBUG ---------- BEGINNING OF DEBUGGING INFORMATION ----------
    DEBUG Traceback (most recent call last):
    DEBUG   File "<stdin>", line 1, in ?
    DEBUG   File "<stdin>", line 2, in tryit
    DEBUG   File "C:\\Python24\\Lib\\site-packages\\GeoEco\\FileSystemUtils.py", line 47, in CopyFile
    DEBUG     shutil.copy2(sourceFile, destinationFile)
    DEBUG   File "C:\\Python24\\lib\\shutil.py", line 92, in copy2
    DEBUG     copyfile(src, dst)
    DEBUG   File "C:\\Python24\\lib\\shutil.py", line 48, in copyfile
    DEBUG     fdst = open(dst, 'wb')
    DEBUG IOError: [Errno 13] Permission denied: u'c:\\\\bar.txt'
    DEBUG End of traceback. Logging other useful debugging information...
    DEBUG sys.argv = ['']
    DEBUG sys.version = 2.4.4 (#71, Oct 18 2006, 08:34:43) [MSC v.1310 32 bit (Intel)]
    DEBUG sys.version_info = (2, 4, 4, 'final', 0)
    DEBUG sys.platform = win32
    DEBUG sys.getwindowsversion() = (5, 1, 2600, 2, 'Service Pack 2')
    DEBUG ...
    DEBUG ---------- END OF DEBUGGING INFORMATION ----------
    ERROR The following consequences resulted from the original error:
    ERROR Could not copy file c:\\foo.txt to c:\\bar.txt.

Unless the user has debugging messages turned on, they will only see the warning
and error messages in the log::

    ERROR IOError: [Errno 13] Permission denied: u'c:\\\\bar.txt'
    ERROR The following consequences resulted from the original error:
    ERROR Could not copy file c:\\foo.txt to c:\\bar2\\bar.txt.

Except clauses higher on the stack can also call LogExceptionAsWarning and
LogExceptionAsError. The methods keep track of whether the original exception
was logged and will not log it a second time. Instead they will just log the
optional format string, if provided, as a subsequent "consequence" of the
original exception. This allows nested methods to illustrate how the low-level
failure causes a problem in the high-level operation the user actually cares
about. For example, if the output file from a function cannot be copied from a
temporary location because a directory cannot be created, the log might look
like this::

    ERROR IOError: [Errno 13] Permission denied: u'c:\\\\output'
    ERROR The following consequences resulted from the original error:
    ERROR Could create directory c:\\output.
    ERROR Could not copy file c:\\processing\\results.txt to c:\\output\\results.txt.
    ERROR Could not copy the results to the output directory."""))

AddArgumentMetadata(Logger.LogExceptionAsWarning, u'cls',
    typeMetadata=ClassOrClassInstanceTypeMetadata(cls=Logger),
    description=Logger.Debug.__doc__.Obj.Arguments[0].Description)

AddArgumentMetadata(Logger.LogExceptionAsWarning, u'format',
    typeMetadata=UnicodeStringTypeMetadata(canBeNone=True),
    description=Logger.Debug.__doc__.Obj.Arguments[1].Description)

AddArgumentMetadata(Logger.LogExceptionAsWarning, u'args',
    typeMetadata=TupleTypeMetadata(elementType=AnyObjectTypeMetadata(canBeNone=True)),
    description=Logger.Debug.__doc__.Obj.Arguments[2].Description)

# Public method: LogExceptionAsError

AddMethodMetadata(Logger.LogExceptionAsError,
    shortDescription=_(u'Logs a Python exception caught by a GeoEco class as an error message and additional information as debug messages.'),
    longDescription=Logger.LogExceptionAsWarning.__doc__.Obj.LongDescription)

AddArgumentMetadata(Logger.LogExceptionAsError, u'cls',
    typeMetadata=ClassOrClassInstanceTypeMetadata(cls=Logger),
    description=Logger.LogExceptionAsWarning.__doc__.Obj.Arguments[0].Description)

AddArgumentMetadata(Logger.LogExceptionAsError, u'format',
    typeMetadata=UnicodeStringTypeMetadata(canBeNone=True),
    description=Logger.LogExceptionAsWarning.__doc__.Obj.Arguments[1].Description)

AddArgumentMetadata(Logger.LogExceptionAsError, u'args',
    typeMetadata=TupleTypeMetadata(elementType=AnyObjectTypeMetadata(canBeNone=True)),
    description=Logger.LogExceptionAsWarning.__doc__.Obj.Arguments[2].Description)

# Public method: Initialize

AddMethodMetadata(Logger.Initialize,
    shortDescription=_(u'Initializes the logging system.'),
    isExposedToPythonCallers=True,
    isExposedByCOM=True)

AddArgumentMetadata(Logger.Initialize, u'cls',
    typeMetadata=ClassOrClassInstanceTypeMetadata(cls=Logger),
    description=Logger.Debug.__doc__.Obj.Arguments[0].Description)

AddArgumentMetadata(Logger.Initialize, u'activateArcGISLogging',
    typeMetadata=BooleanTypeMetadata(),
    description=_(
u"""If true, logging messages will be delivered to the ArcGIS geoprocessing
system and appear in the ArcGIS user interface. If false, they will be reported
to other logging destinations but will be queued in memory for ArcGIS until the
ActivateArcGISLogging method is called. To limit memory consumption in the event
that the method is never called, the queue retains only the most recent 1000
messages. If you are calling Initialize but not running as part of an ArcGIS
geoprocessing *do not* pass true for this parameter. Passing true will decrease
performance by initializing the ArcGIS geoprocessor when it might not be
necessary to do so. (The memory used by the queue is negligible.)"""))

AddArgumentMetadata(Logger.Initialize, u'loggingConfigFile',
    typeMetadata=FileTypeMetadata(canBeNone=True, mustExist=True),
    description=_(
u"""Path to the logging configuration file. If not provided, this
function attempts to load a configuration file from these two
locations:

* The file %APPDATA%\\\\GeoEco\\\\Logging.ini (e.g.
  C:\\\\Documents and Settings\\\\Jason\\\\Application Data\\\\GeoEco\\\\Logging.ini).
  This allows each user to configure their own default logging settings.

* The file Logging.ini in the Configuration subdirectory of the GeoEco
  Python package installation directory (e.g.
  C:\\\\Python24\\\\lib\\\\site-packages\\\\GeoEco\\\\Configuration\\\\Logging.ini).
  These settings will be used if the user does not specify their own
  Logging.ini file.

If neither is found (which would only occur if the GeoEco package
installation is corrupt), then all INFO, WARNING, and ERROR messages
will be logged to the console (i.e. the stdout stream)."""))

###############################################################################
# Metadata: ProgressReporter class
###############################################################################

AddClassMetadata(ProgressReporter,
    shortDescription=_(u'Provides a simple mechanism for long-running operations to report periodic progress to the user.'),
    longDescription=_(
u"""This class provides progress-reporting capability for two kinds of
long-running operations: those for which the total number of
sub-operations is known when the long-running operation is started,
and those for which the total number of sub-operations cannot be
determined. In both cases, this class periodically reports the elapsed
time, the number of completed sub-operations, and the average time per
sub-operation. If the number of sub-operations is known, this class
also reports the number of sub-operations remaining and the estimated
time of completion.

When the total number of sub-operations is known, use this class like
this::

    operations = [...]                          # List of operations to perform
    progressReporter = ProgressReporter()
    progressReporter.Start(len(operations))
    for op in operations:
        ...                                     # Do one operation
        progressReporter.ReportProgress()

When the total number of sub-operations is not known, use this class
like this::

    progressReporter = ProgressReporter()
    progressReporter.Start()
    while True:
        ...                                     # Do one operation or exit loop if done
        progressReporter.ReportProgress()
    progressReporter.Stop()

The ReportProgress method will report the first message after
one minute and an additional message every five minutes thereafter. A
message will also be reported when processing is complete, by
ReportProgress in the first scenario and Stop in the second scenario.
You can configure the format of the progress messages by setting the
ProgressMessage1, ProgressMessage2, and CompletionMessage properties.
All messages are reported at the Info logging level. You can configure
the logging channel that is used to report the messages by setting the
LoggingChannel property."""))

# Public properties

AddPropertyMetadata(ProgressReporter.ProgressMessage1,
    typeMetadata=UnicodeStringTypeMetadata(),
    shortDescription=_(u'printf-style format string for periodically reporting progress when the total number of sub-operations is known a priori.'),
    longDescription=_(
u"""Your string must include all five format specifiers, as is done in
this example::

    u'Progress report: %(elapsed)s elapsed, %(opsCompleted)i operations completed, %(perOp)s per operation, %(opsRemaining)i remaining, estimated completion time: %(etc)s.'
"""),
    isExposedToPythonCallers=True)

AddPropertyMetadata(ProgressReporter.ProgressMessage2,
    typeMetadata=UnicodeStringTypeMetadata(),
    shortDescription=_(u'printf-style format string for periodically reporting progress when the total number of sub-operations is not known a priori.'),
    longDescription=_(
u"""Your string must include all three format specifiers, as is done
in this example::

    u'Progress report: %(elapsed)s elapsed, %(opsCompleted)i operations completed, %(perOp)s per operation.'
"""),
    isExposedToPythonCallers=True)

AddPropertyMetadata(ProgressReporter.CompletionMessage,
    typeMetadata=UnicodeStringTypeMetadata(),
    shortDescription=_(u'printf-style format string for reporting that processing is complete.'),
    longDescription=_(
u"""Your string must include all three format specifiers, as is done
in this example::

    u'Processing complete: %(elapsed)s elapsed, %(opsCompleted)i operations completed, %(perOp)s per operation.'
"""),
    isExposedToPythonCallers=True)

AddPropertyMetadata(ProgressReporter.AbortedMessage,
    typeMetadata=UnicodeStringTypeMetadata(),
    shortDescription=_(u'printf-style format string for reporting that processing was stopped prematurely (i.e. that the Stop method was called before OperationsCompleted == TotalOperations).'),
    longDescription=_(
u"""Your string must include all four format specifiers, as is done in
this example::

    u'Processing stopped before all operations were completed: %(elapsed)s elapsed, %(opsCompleted)i operations completed, %(perOp)s per operation, %(opsIncomplete)i operations not completed.'
"""),
    isExposedToPythonCallers=True)

AddPropertyMetadata(ProgressReporter.LoggingChannel,
    typeMetadata=UnicodeStringTypeMetadata(),
    shortDescription=_(u'Logging channel that progress messages should be reported to.'),
    longDescription=_(
u"""Please see the documentation for the Python logging module formore
information about logging channels. All progress messages are reported
at the Info logging level. You can configure the message filtering and
destinations by editing the GeoEco Logging.ini file."""),
    isExposedToPythonCallers=True)

AddPropertyMetadata(ProgressReporter.TotalOperations,
    typeMetadata=IntegerTypeMetadata(canBeNone=True),
    shortDescription=_(u'Total number of sub-operations in this long-running operation, or None if the number of sub-operations is not known a priori.'),
    longDescription=_(u'This property is initialized by the Start method.'),
    isExposedToPythonCallers=True)

AddPropertyMetadata(ProgressReporter.OperationsCompleted,
    typeMetadata=IntegerTypeMetadata(),
    shortDescription=_(u'Total number of sub-operations that have been completed so far.'),
    longDescription=_(u'This property is updated when ReportProgress is called.'),
    isExposedToPythonCallers=True)

AddPropertyMetadata(ProgressReporter.TimeStarted,
    typeMetadata=ClassInstanceTypeMetadata(cls=datetime.datetime, canBeNone=True),
    shortDescription=_(u'The time processing was started.'),
    longDescription=_(
u"""This property is set to the current system time when Start is
called, using the datetime.datetime.now method."""),
    isExposedToPythonCallers=True)

AddPropertyMetadata(ProgressReporter.TimeCompleted,
    typeMetadata=ClassInstanceTypeMetadata(cls=datetime.datetime, canBeNone=True),
    shortDescription=_(u'The time processing was completed.'),
    longDescription=_(
u"""This property is set to the current system time when
ReportProgress is called for the last sub-operation (when the total
number of sub-operations is known a priori) or when Stop is called
(when the the total number of sub-operations is not known a priori),
using the datetime.datetime.now method."""),
    isExposedToPythonCallers=True)

AddPropertyMetadata(ProgressReporter.HasStarted,
    typeMetadata=BooleanTypeMetadata(),
    shortDescription=_(u'True if processing has started (i.e. if Start was called).'),
    isExposedToPythonCallers=True)

AddPropertyMetadata(ProgressReporter.HasCompleted,
    typeMetadata=BooleanTypeMetadata(),
    shortDescription=_(u'True if processing has completed (i.e. the last operation was reported to ReportProgress or Stop was called).'),
    isExposedToPythonCallers=True)

AddPropertyMetadata(ProgressReporter.TimeElapsed,
    typeMetadata=ClassInstanceTypeMetadata(cls=datetime.timedelta, canBeNone=True),
    shortDescription=_(u'The time elapsed since processing was started, or None if processing has not started yet.'),
    longDescription=_(
u"""Processing starts when Start is called and stops when
ReportProgress is called for the last sub-operation (when the total
number of sub-operations is known a priori) or when Stop is called
(when the the total number of sub-operations is not known a priori).
After processing has stopped, this property will consistently return
the total time required for processing (it will not keep increasing as
additional time passes)."""),
    isExposedToPythonCallers=True)

# Constructor

AddMethodMetadata(ProgressReporter.__init__,
    shortDescription=_(u'Constructs a new %s instance.') % ProgressReporter.__name__,
    isExposedToPythonCallers=True)

AddArgumentMetadata(ProgressReporter.__init__, u'self',
    typeMetadata=ClassInstanceTypeMetadata(cls=ProgressReporter),
    description=_(u'%s instance.') % ProgressReporter.__name__)

AddArgumentMetadata(ProgressReporter.__init__, u'progressMessage1',
    typeMetadata=ProgressReporter.ProgressMessage1.__doc__.Obj.Type,
    description=ProgressReporter.ProgressMessage1.__doc__.Obj.ShortDescription + u'\n\n' + ProgressReporter.ProgressMessage1.__doc__.Obj.LongDescription)

AddArgumentMetadata(ProgressReporter.__init__, u'progressMessage2',
    typeMetadata=ProgressReporter.ProgressMessage2.__doc__.Obj.Type,
    description=ProgressReporter.ProgressMessage2.__doc__.Obj.ShortDescription + u'\n\n' + ProgressReporter.ProgressMessage2.__doc__.Obj.LongDescription)

AddArgumentMetadata(ProgressReporter.__init__, u'completionMessage',
    typeMetadata=ProgressReporter.CompletionMessage.__doc__.Obj.Type,
    description=ProgressReporter.CompletionMessage.__doc__.Obj.ShortDescription + u'\n\n' + ProgressReporter.CompletionMessage.__doc__.Obj.LongDescription)

AddArgumentMetadata(ProgressReporter.__init__, u'abortedMessage',
    typeMetadata=ProgressReporter.AbortedMessage.__doc__.Obj.Type,
    description=ProgressReporter.AbortedMessage.__doc__.Obj.ShortDescription + u'\n\n' + ProgressReporter.AbortedMessage.__doc__.Obj.LongDescription)

AddArgumentMetadata(ProgressReporter.__init__, u'loggingChannel',
    typeMetadata=ProgressReporter.LoggingChannel.__doc__.Obj.Type,
    description=ProgressReporter.LoggingChannel.__doc__.Obj.ShortDescription + u'\n\n' + ProgressReporter.LoggingChannel.__doc__.Obj.LongDescription)

AddResultMetadata(ProgressReporter.__init__, u'progressReporter',
    typeMetadata=ClassInstanceTypeMetadata(cls=ProgressReporter),
    description=_(u'New %s instance.') % ProgressReporter.__name__)

# Public method: Start

AddMethodMetadata(ProgressReporter.Start,
    shortDescription=_(u'Signals the ProgressReporter that processing has started.'),
    isExposedToPythonCallers=True)

CopyArgumentMetadata(ProgressReporter.__init__, u'self', ProgressReporter.Start, u'self')

AddArgumentMetadata(ProgressReporter.Start, u'totalOperations',
    typeMetadata=IntegerTypeMetadata(canBeNone=True, minValue=1),
    description=_(u'Total number of sub-operations that will be performed, or None if the number of sub-operations is not known.'))

# Public method: ReportProgress

AddMethodMetadata(ProgressReporter.ReportProgress,
    shortDescription=_(u'Signals the ProgressReporter that another one or more sub-operations just completed.'),
    longDescription=_(
u"""This method will periodically report progress messages as
described in the class-level documentation. You must call Start before
calling this method."""),
    isExposedToPythonCallers=True)

CopyArgumentMetadata(ProgressReporter.__init__, u'self', ProgressReporter.ReportProgress, u'self')

AddArgumentMetadata(ProgressReporter.ReportProgress, u'operationsCompleted',
    typeMetadata=IntegerTypeMetadata(minValue=1),
    description=_(
u"""Total number of sub-operations that just completed, typically 1.
You should provide the number of sub-operations that have completed
since you last called this method. Do not pass in a cumulative total."""))

# Public method: Stop

AddMethodMetadata(ProgressReporter.Stop,
    shortDescription=_(u'Signals the ProgressReporter that processing is complete.'),
    longDescription=_(
u"""This method will report a completion message as described in the
class-level documentation. You must call Start before calling this
method. If provided a value for totalOperations when you called Start,
and the number of completed operations has not reached this total,
Stop will report AbortedMessage."""),
    isExposedToPythonCallers=True)

CopyArgumentMetadata(ProgressReporter.__init__, u'self', ProgressReporter.Stop, u'self')


###############################################################################
# Names exported by this module
###############################################################################

__all__ = ['Logger']