Beispiel #1
0
 def _setup_timers(self):
     self.run_timer = Timer('Runtime')
     self.poll_timer = Timer('Poll')
     self.format_timer = Timer('Format')
     self.export_timer = Timer('Export')
     self.transaction_start_timer = Timer('Trans start')
     self.transaction_life_timer = Timer('Trans life')
Beispiel #2
0
 def _setup_timers(self):
     self.run_timer = Timer('Runtime')
     self.poll_timer = Timer('Poll')
     self.format_timer = Timer('Format')
     self.export_timer = Timer('Export')
     self.transaction_start_timer = Timer('Trans start')
     self.transaction_life_timer = Timer('Trans life')
Beispiel #3
0
class PushedSubscription(object):
    subscription_counter = Counter()
    def __init__(self, monitor, target, nodetable, period, retries, sid=None):
        self.subscription_number = self.subscription_counter.increment()
        self._setup_collaborators(monitor)
        self.node_table = nodetable
        self.target = target
        self.period = period
        self.retries = retries
        self.sid = sid
        self.running = Flag()
        self._setup = Flag()
        self._setup_counters()
        self._setup_timers()
        self._setup_trackers()
        super(PushedSubscription, self).__init__()
    def id(self):
        return self.sid
    def is_running(self):
        return self.running.isSet()
    def is_setup(self):
        return self._setup.isSet()
    def get_target(self):
        return self.target
    def start(self, skip = 0):
        assert not self.is_running()
        self._reset_timers()
        self._reset_counters()
        self._reset_trackers()
        if not self.is_setup():
            self.setup_subscription()
        self.running.set()
        self.run_timer.start()
        self.exports_skipped.decrement(skip)
        self.schedule_next_export(skip)
        return self.sid
    def stop(self):
        assert self.is_running()
        self.running.clear()
        self.run_timer.stop()
        try: 
            self.manager.destroy(self.sid)
        except: 
            msglog.exception(prefix="Handled")
    def reset_subscription(self):
        self._export_all_values = True
    def setup_subscription(self):
        assert not self.is_setup()
        try:
            self.sid = self.manager.create_polled(
                self.node_table, None, self.sid)
        except:
            msglog.exception()
        else:
            self._setup.set()
        assert self.is_setup()
        return self.sid
    def teardown_subscription(self):
        assert self.is_setup()
        try: 
            self.manager.destroy(self.sid)
        except: 
            msglog.exception(prefix="Handled")
        else:
            self._setup.clear()
        assert not self.is_setup()
        return self.sid
    def next_poll_time(self, skip = 0):
        offset = self.period + (skip * self.period)
        return ((int(time.time()) / self.period) * self.period) + offset
    def exports_possible(self):  
        runtime = self.export_time - self.first_export_time
        return (runtime / self.period)
    def prepare_to_export(self):
        exportstart = time.time()
        self.exports_started.increment()
        self.check_missed_exports(exportstart)
        transaction = self.active_transaction
        if transaction:
            if transaction.is_complete():
                if transaction.succeeded():
                    self.handle_export_success(transaction)
                else:
                    raise ETransactionException(transaction)
            elif transaction.is_expired():
                raise ETransactionTimeout(transaction)
            else:
                raise ETransactionInProgress(transaction)
        self._reset_timers()
        self.export_timer.start(exportstart)
    def get_export_data(self):
        messages = []
        self.poll_timer.start()
        if self._export_all_values:
            dblevel = 2
            messages.append('Polled all values')
            data = self.manager.poll_all(self.sid)
            self._export_all_values = False
        else:
            dblevel = 3
            messages.append('Polled COV values')
            data = self.manager.poll_changed(self.sid)
        self.poll_timer.stop()
        if self.debuglevel(dblevel):
            messages.append('%d values being returned' % len(data))
            self.debugout('%s\n' % '\n\t'.join(messages))
        return data
    def format_export_data(self, data):
        self.debugout('Formatting data.', 2)
        self.format_timer.start()
        data = self.formatter.format(data)
        self.format_timer.stop()
        self.debugout('Data formatted.', 2)
        return data
    def start_export_transaction(self, data):
        self.debugout('Creating export transaction', 2)

        self.active_transaction = self.transporter.transport(self.target, data, sid=self.sid)
        if(self.active_transaction == None):
            return
        self.transaction_start_timer.start()
        self.transaction_start_timer.stop()
        self.transaction_life_timer.start()
        self.active_transaction.set_timeout(self.period * 3)
        self.active_transaction.add_state_listener(self.notify_complete)
        if self.debuglevel(2):
            self.debugout('Export transaction created', 2)
            if self.debuglevel(4):
                self.debugout('Export transaction data: \n%r\n\n' % data)
        self.exports_processed.increment()
    def schedule_next_export(self, skip = 0):
        if not self.is_running():
            message = 'Not rescheduling because subscription stopped.'
            self.debugout(message, 1)
            return
        nextexport = self.next_poll_time(skip)
        if self.export_time is None:
            self.first_export_time = nextexport
        self.export_time = nextexport
        self.monitor.schedule_subscription(self, nextexport)
        self.exports_skipped.increment(skip)
        self.exports_scheduled.increment()
        return nextexport
    def handle_export_success(self, transaction):
        self.active_transaction = None
        self.export_successes.increment()
    def handle_export_timeout(self, error):
        """
            Transaction still pending and time exceeded export 
            period, which is also transport timeout value.
            No data has been sent to the server.
        """
        try:
            transaction = error.transaction
            errors = self.export_timeouts.pre_increment()
            message = 'Handling timed out export: %s' % transaction
            self.msglog(message, msglog.types.WARN)
            try: 
                transaction.handle_timeout()
            except:
                msglog.exception()
            self.record_failed_export(transaction, errors)
        finally:
            self.active_transaction = None
            self.schedule_next_export(1)
    def handle_export_pending(self, error):
        self.exports_deferred.increment()
        self.debugout('Previous export still pending.', 1)
        self.schedule_next_export(0)
    def handle_export_failure(self, error):
        """
            Transaction completed but returned error response 
            code.  Data was sent to the server and a response 
            was sent back, but the response code indicates that 
            the server failed to handle the request properly.
        """
        try:
            transaction = error.transaction
            failures = self.export_errors.pre_increment()
            if self.debuglevel(2):
                message = 'Handling errored out export: %r' % transaction
                self.msglog(message, msglog.types.WARN)
                self.record_failed_export(transaction, failures)
        finally:
            self.active_transaction = None
            self.schedule_next_export(1)
    def handle_export_exception(self, error, stage = None):
        """
            An uncaught exception was raised during export 
            process.  This indicates that one of the export 
            methods raised an exception.  The status may be 
            anything from uninitialized to the request having 
            been sent, and the response having been received.
            
            This method resets the subscription and reschedules 
            next export after skipping one period.
        """
        if not self.is_running():
            message = 'Ignoring exception because subscription stopped.'
            self.debugout(message, 1)
            return
        messages = ['Handling export exception']
        if isinstance(error, ETransactionInProgress):
            self.handle_export_pending(error)
        elif isinstance(error, ETransactionTimeout):
            self.handle_export_timeout(error)
        elif isinstance(error, ETransactionException):
            self.handle_export_failure(error)
        else:
            try:
                warning = msglog.types.WARN
                self.msglog('Handling uknown exception', warning)
                msglog.exception(prefix = 'handling')
                self.reset_subscription()
                self.msglog('Subscription reset', msglog.types.INFO)
                self.export_timer.stop()
                self.msglog('Export timer stopped', msglog.types.INFO)
                messages.append('Export timer stopped.')
                transaction = self.active_transaction
                if transaction:
                    try:
                        transaction.handle_error()
                    except:
                        self.msglog('Notify transaction failed.', warning)
                        msglog.exception(prefix = 'Handled')
                    else:
                        self.msglog(
                           'Transaction notified of failure', msglog.types.INFO)
            finally:
                self.active_transaction = None
                self.schedule_next_export(1)
                self.msglog('One export will be skipped', warning)
    def check_missed_exports(self, actual):
        scheduled = self.export_time
        exportdelta = actual - scheduled
        exportsmissed = int(exportdelta / self.period)
        if exportsmissed > 0:
            messages = ['Missed exports detected']
            messages.append('Scheduled export: %s' % time.ctime(scheduled))
            messages.append('Actual export: %s' % time.ctime(actual))
            messages.append('Configured period: %s' % self.period)
            messages.append('Delta between exports: %s' % exportdelta)
            messages.append('Periods missed: %s' % exportsmissed)
            self.msglog('%s\n' % '\n\t'.join(messages), msglog.types.WARN)
            self.exports_missed.increment(exportsmissed)
        return exportsmissed
    def record_successful_export(self, transaction, successes):
        messages = ['%s:' % self.toString()]
        runtime = self.export_time - self.first_export_time
        average = runtime / successes
        if self.debuglevel(2):
            message = 'Exports: %d, runtime: %0.1f sec'
            messages.append(message % (successes, runtime))
        if self.debuglevel(2):
            message = 'Period: %0.2f sec, effective: ~ %0.2f sec'
        else:
            message = '(%0.0f => ~%0.2f)'
        messages.append(message % (self.period, average))
        if self.debuglevel(2):
            messages.append(transaction.stats()[1:-1])
            messages.append(', '.join(self._timer_strings()))
            messages = ['\t\t- %s' % message for message in messages]
            messages.insert(0, 'Statistics of completed export:')
            message = '%s\n' % '\n'.join(messages)
        else:
            timeitems = [(timer.get_name().lower(), timer.get_lapse()) 
                         for timer in self._get_timers() 
                         if (timer.get_start() and timer.get_stop())]
            flighttime = transaction.get_flighttime()
            timeitems.append(('flight', flighttime))
            timestrs = ['(%s %0.2f)' % item for item in timeitems]
            messages.extend(timestrs)
            message = ' '.join(messages)
        self.debugout(message, 1)
    def record_failed_export(self, transaction, failures, outputdata = False):
        warning = msglog.types.WARN
        information = msglog.types.INFO
        self.msglog('Transaction failed: %r' % transaction, information)
        self.msglog('Failed request: %r' % transaction.request, information)
        if outputdata or self.debuglevel(2):
            message = 'Failed request data: \n%r\n'
            self.debugout(message % transaction.request.data)
        if transaction.is_complete():
            response = transaction.get_response()
            self.msglog('Failed response: %r.' % response, information)
            message = 'Failed response data: \n%r\n'
            self.debugout(message % response.read(), 0)
    def notify_complete(self, transaction):
        if transaction is self.active_transaction:
            self.transaction_life_timer.stop()
            self.export_timer.stop()
            if transaction.succeeded():
                successes = self.export_successes.value + 1
                if self.debuglevel(1):
                    self.monitor.enqueue_work(
                        self.record_successful_export, transaction, successes)
            else:
                failures = self.export_errors.value + 1
                self.monitor.enqueue_work(
                    self.record_failed_export, transaction, failures)
        else:
            messages = ['Completed transaction is not current']
            messages.append('Current: %r' % self.active_transaction)
            messages.append('Completed: %r' % transaction)
            self.msglog('\n\t- '.join(messages), msglog.types.WARN)
    def _setup_collaborators(self, monitor):
        self.monitor = monitor
        self.manager = monitor.get_subscription_manager()
        self.formatter = monitor.get_formatter()
        self.transporter = monitor.get_transporter()
    def _setup_counters(self):
        self.export_successes = Counter()
        self.export_timeouts = Counter()
        self.export_errors = Counter()
        self.exports_started = Counter()
        self.exports_processed = Counter()
        self.exports_deferred = Counter()
        self.export_transactions = Counter()
        self.exports_scheduled = Counter()
        self.export_exceptions = Counter()
        # Export scheduled following skip.
        self.exports_skipped = Counter()
        # Scheduled export called late.
        self.exports_missed = Counter()
    def _reset_counters(self):
        self.export_successes.reset()
        self.export_timeouts.reset()
        self.export_errors.reset()
        self.exports_started.reset()
        self.exports_processed.reset()
        self.exports_deferred.reset()
        self.export_transactions.reset()
        self.exports_scheduled.reset()
        self.export_exceptions.reset()
        self.exports_skipped.reset()
        self.exports_missed.reset()
    def _setup_timers(self):
        self.run_timer = Timer('Runtime')
        self.poll_timer = Timer('Poll')
        self.format_timer = Timer('Format')
        self.export_timer = Timer('Export')
        self.transaction_start_timer = Timer('Trans start')
        self.transaction_life_timer = Timer('Trans life')
    def _reset_timers(self):
        self.poll_timer.reset()
        self.format_timer.reset()
        self.export_timer.reset()
        self.transaction_start_timer.reset()
        self.transaction_life_timer.reset()
    def _setup_trackers(self):
        self.export_time = None
        self.first_export_time = None
        self.active_transaction = None
        self._export_all_values = False
    def _reset_trackers(self):
        self._setup_trackers()
    def _timer_string(self, prefix = '\t', sep = '\n'):
        timestrs = ['%s%s' % (prefix, timestr) 
                    for timstr in self._timer_strings()]
        return sep.join(timestrs)
    def _timer_strings(self):
        timers = self._get_timers()
        return map(str, timers)
    def _get_timers(self):
        return [self.export_timer, self.poll_timer, self.format_timer, 
                self.transaction_start_timer, self.transaction_life_timer]
    def debugout(self, dbmessage, dblevel = 1):
        if self.debuglevel(dblevel):
            self.msglog(dbmessage, msglog.types.DB)
    def debuglevel(self, level = 1):
        return level <= DEBUG
    def msglog(self, message, mtype = msglog.types.INFO, autoprefix = True):
        if autoprefix:
            message = '[%s] %s' % (self, message)
        msglog.log('broadway', mtype, message)
    def as_dictionary(self):
        configuration = {}
        configuration['monitor'] = self.monitor.url
        configuration['target'] = self.target
        configuration['nodes'] = self.node_table
        configuration['period'] = self.period
        configuration['retries'] = self.retries
        configuration['sid'] = self.sid
        return configuration
    def from_dictionary(klass, configuration):
        if not configuration.has_key('monitor'):
            msglog.log('broadway', msglog.types.WARN, 
                       'Creating monitor URL from formatter parent to '
                       'recreate subscription from %r' % configuration)
            formatter = rootspace.as_node(configuration['formatter'])
            configuration['monitor'] = formatter.parent.url
        monitor = rootspace.as_node(configuration['monitor'])
        target = configuration['target']
        nodes = configuration['nodes']
        period = configuration['period']
        retries = configuration['retries']
        sid = configuration['sid']
        return klass(monitor, target, nodes, period, retries, sid)
    from_dictionary = classmethod(from_dictionary)
    def __repr__(self):
        classname = self.__class__.__name__
        subscriptionnumber = self.subscription_number
        details = ['%s #%04d [%s]' % (classname, subscriptionnumber, self.sid)]
        counts = ['%dES' % self.exports_started.value]
        counts.append('%dEM' % self.exports_missed.value)
        counts.append('%dED' % self.exports_deferred.value)
        counts.append('%dEP' % self.exports_processed.value)
        counts.append('%dGD' % self.export_successes.value)
        counts.append('%dBD' % self.export_errors.value)
        counts.append('%dTO' % self.export_timeouts.value)
        counts.append('%dSK' % self.exports_skipped.value)
        details.append('(%s)' % '/'.join(counts))
        return '<%s>' % ' '.join(details)
    def toString(self):
        details = ['PS #%04d' % self.subscription_number]
        counts = ['%dES' % self.exports_started.value]
        counts.append('%dEM' % self.exports_missed.value)
        counts.append('%dED' % self.exports_deferred.value)
        counts.append('%dEP' % self.exports_processed.value)
        counts.append('%dGD' % self.export_successes.value)
        counts.append('%dBD' % self.export_errors.value)
        counts.append('%dTO' % self.export_timeouts.value)
        counts.append('%dSK' % self.exports_skipped.value)
        details.append('(%s)' % '/'.join(counts))
        return ' '.join(details)
    def __str__(self):
        classname = self.__class__.__name__
        return '%s #%d %r' % (classname, self.subscription_number, self.sid)
Beispiel #4
0
class PushedSubscription(object):
    subscription_counter = Counter()

    def __init__(self, monitor, target, nodetable, period, retries, sid=None):
        self.subscription_number = self.subscription_counter.increment()
        self._setup_collaborators(monitor)
        self.node_table = nodetable
        self.target = target
        self.period = period
        self.retries = retries
        self.sid = sid
        self.running = Flag()
        self._setup = Flag()
        self._setup_counters()
        self._setup_timers()
        self._setup_trackers()
        super(PushedSubscription, self).__init__()

    def id(self):
        return self.sid

    def is_running(self):
        return self.running.isSet()

    def is_setup(self):
        return self._setup.isSet()

    def get_target(self):
        return self.target

    def start(self, skip=0):
        assert not self.is_running()
        self._reset_timers()
        self._reset_counters()
        self._reset_trackers()
        if not self.is_setup():
            self.setup_subscription()
        self.running.set()
        self.run_timer.start()
        self.exports_skipped.decrement(skip)
        self.schedule_next_export(skip)
        return self.sid

    def stop(self):
        assert self.is_running()
        self.running.clear()
        self.run_timer.stop()
        try:
            self.manager.destroy(self.sid)
        except:
            msglog.exception(prefix="Handled")

    def reset_subscription(self):
        self._export_all_values = True

    def setup_subscription(self):
        assert not self.is_setup()
        try:
            self.sid = self.manager.create_polled(self.node_table, None,
                                                  self.sid)
        except:
            msglog.exception()
        else:
            self._setup.set()
        assert self.is_setup()
        return self.sid

    def teardown_subscription(self):
        assert self.is_setup()
        try:
            self.manager.destroy(self.sid)
        except:
            msglog.exception(prefix="Handled")
        else:
            self._setup.clear()
        assert not self.is_setup()
        return self.sid

    def next_poll_time(self, skip=0):
        offset = self.period + (skip * self.period)
        return ((int(time.time()) / self.period) * self.period) + offset

    def exports_possible(self):
        runtime = self.export_time - self.first_export_time
        return (runtime / self.period)

    def prepare_to_export(self):
        exportstart = time.time()
        self.exports_started.increment()
        self.check_missed_exports(exportstart)
        transaction = self.active_transaction
        if transaction:
            if transaction.is_complete():
                if transaction.succeeded():
                    self.handle_export_success(transaction)
                else:
                    raise ETransactionException(transaction)
            elif transaction.is_expired():
                raise ETransactionTimeout(transaction)
            else:
                raise ETransactionInProgress(transaction)
        self._reset_timers()
        self.export_timer.start(exportstart)

    def get_export_data(self):
        messages = []
        self.poll_timer.start()
        if self._export_all_values:
            dblevel = 2
            messages.append('Polled all values')
            data = self.manager.poll_all(self.sid)
            self._export_all_values = False
        else:
            dblevel = 3
            messages.append('Polled COV values')
            data = self.manager.poll_changed(self.sid)
        self.poll_timer.stop()
        if self.debuglevel(dblevel):
            messages.append('%d values being returned' % len(data))
            self.debugout('%s\n' % '\n\t'.join(messages))
        return data

    def format_export_data(self, data):
        self.debugout('Formatting data.', 2)
        self.format_timer.start()
        data = self.formatter.format(data)
        self.format_timer.stop()
        self.debugout('Data formatted.', 2)
        return data

    def start_export_transaction(self, data):
        self.debugout('Creating export transaction', 2)

        self.active_transaction = self.transporter.transport(self.target,
                                                             data,
                                                             sid=self.sid)
        if (self.active_transaction == None):
            return
        self.transaction_start_timer.start()
        self.transaction_start_timer.stop()
        self.transaction_life_timer.start()
        self.active_transaction.set_timeout(self.period * 3)
        self.active_transaction.add_state_listener(self.notify_complete)
        if self.debuglevel(2):
            self.debugout('Export transaction created', 2)
            if self.debuglevel(4):
                self.debugout('Export transaction data: \n%r\n\n' % data)
        self.exports_processed.increment()

    def schedule_next_export(self, skip=0):
        if not self.is_running():
            message = 'Not rescheduling because subscription stopped.'
            self.debugout(message, 1)
            return
        nextexport = self.next_poll_time(skip)
        if self.export_time is None:
            self.first_export_time = nextexport
        self.export_time = nextexport
        self.monitor.schedule_subscription(self, nextexport)
        self.exports_skipped.increment(skip)
        self.exports_scheduled.increment()
        return nextexport

    def handle_export_success(self, transaction):
        self.active_transaction = None
        self.export_successes.increment()

    def handle_export_timeout(self, error):
        """
            Transaction still pending and time exceeded export 
            period, which is also transport timeout value.
            No data has been sent to the server.
        """
        try:
            transaction = error.transaction
            errors = self.export_timeouts.pre_increment()
            message = 'Handling timed out export: %s' % transaction
            self.msglog(message, msglog.types.WARN)
            try:
                transaction.handle_timeout()
            except:
                msglog.exception()
            self.record_failed_export(transaction, errors)
        finally:
            self.active_transaction = None
            self.schedule_next_export(1)

    def handle_export_pending(self, error):
        self.exports_deferred.increment()
        self.debugout('Previous export still pending.', 1)
        self.schedule_next_export(0)

    def handle_export_failure(self, error):
        """
            Transaction completed but returned error response 
            code.  Data was sent to the server and a response 
            was sent back, but the response code indicates that 
            the server failed to handle the request properly.
        """
        try:
            transaction = error.transaction
            failures = self.export_errors.pre_increment()
            if self.debuglevel(2):
                message = 'Handling errored out export: %r' % transaction
                self.msglog(message, msglog.types.WARN)
                self.record_failed_export(transaction, failures)
        finally:
            self.active_transaction = None
            self.schedule_next_export(1)

    def handle_export_exception(self, error, stage=None):
        """
            An uncaught exception was raised during export 
            process.  This indicates that one of the export 
            methods raised an exception.  The status may be 
            anything from uninitialized to the request having 
            been sent, and the response having been received.
            
            This method resets the subscription and reschedules 
            next export after skipping one period.
        """
        if not self.is_running():
            message = 'Ignoring exception because subscription stopped.'
            self.debugout(message, 1)
            return
        messages = ['Handling export exception']
        if isinstance(error, ETransactionInProgress):
            self.handle_export_pending(error)
        elif isinstance(error, ETransactionTimeout):
            self.handle_export_timeout(error)
        elif isinstance(error, ETransactionException):
            self.handle_export_failure(error)
        else:
            try:
                warning = msglog.types.WARN
                self.msglog('Handling uknown exception', warning)
                msglog.exception(prefix='handling')
                self.reset_subscription()
                self.msglog('Subscription reset', msglog.types.INFO)
                self.export_timer.stop()
                self.msglog('Export timer stopped', msglog.types.INFO)
                messages.append('Export timer stopped.')
                transaction = self.active_transaction
                if transaction:
                    try:
                        transaction.handle_error()
                    except:
                        self.msglog('Notify transaction failed.', warning)
                        msglog.exception(prefix='Handled')
                    else:
                        self.msglog('Transaction notified of failure',
                                    msglog.types.INFO)
            finally:
                self.active_transaction = None
                self.schedule_next_export(1)
                self.msglog('One export will be skipped', warning)

    def check_missed_exports(self, actual):
        scheduled = self.export_time
        exportdelta = actual - scheduled
        exportsmissed = int(exportdelta / self.period)
        if exportsmissed > 0:
            messages = ['Missed exports detected']
            messages.append('Scheduled export: %s' % time.ctime(scheduled))
            messages.append('Actual export: %s' % time.ctime(actual))
            messages.append('Configured period: %s' % self.period)
            messages.append('Delta between exports: %s' % exportdelta)
            messages.append('Periods missed: %s' % exportsmissed)
            self.msglog('%s\n' % '\n\t'.join(messages), msglog.types.WARN)
            self.exports_missed.increment(exportsmissed)
        return exportsmissed

    def record_successful_export(self, transaction, successes):
        messages = ['%s:' % self.toString()]
        runtime = self.export_time - self.first_export_time
        average = runtime / successes
        if self.debuglevel(2):
            message = 'Exports: %d, runtime: %0.1f sec'
            messages.append(message % (successes, runtime))
        if self.debuglevel(2):
            message = 'Period: %0.2f sec, effective: ~ %0.2f sec'
        else:
            message = '(%0.0f => ~%0.2f)'
        messages.append(message % (self.period, average))
        if self.debuglevel(2):
            messages.append(transaction.stats()[1:-1])
            messages.append(', '.join(self._timer_strings()))
            messages = ['\t\t- %s' % message for message in messages]
            messages.insert(0, 'Statistics of completed export:')
            message = '%s\n' % '\n'.join(messages)
        else:
            timeitems = [(timer.get_name().lower(), timer.get_lapse())
                         for timer in self._get_timers()
                         if (timer.get_start() and timer.get_stop())]
            flighttime = transaction.get_flighttime()
            timeitems.append(('flight', flighttime))
            timestrs = ['(%s %0.2f)' % item for item in timeitems]
            messages.extend(timestrs)
            message = ' '.join(messages)
        self.debugout(message, 1)

    def record_failed_export(self, transaction, failures, outputdata=False):
        warning = msglog.types.WARN
        information = msglog.types.INFO
        self.msglog('Transaction failed: %r' % transaction, information)
        self.msglog('Failed request: %r' % transaction.request, information)
        if outputdata or self.debuglevel(2):
            message = 'Failed request data: \n%r\n'
            self.debugout(message % transaction.request.data)
        if transaction.is_complete():
            response = transaction.get_response()
            self.msglog('Failed response: %r.' % response, information)
            message = 'Failed response data: \n%r\n'
            self.debugout(message % response.read(), 0)

    def notify_complete(self, transaction):
        if transaction is self.active_transaction:
            self.transaction_life_timer.stop()
            self.export_timer.stop()
            if transaction.succeeded():
                successes = self.export_successes.value + 1
                if self.debuglevel(1):
                    self.monitor.enqueue_work(self.record_successful_export,
                                              transaction, successes)
            else:
                failures = self.export_errors.value + 1
                self.monitor.enqueue_work(self.record_failed_export,
                                          transaction, failures)
        else:
            messages = ['Completed transaction is not current']
            messages.append('Current: %r' % self.active_transaction)
            messages.append('Completed: %r' % transaction)
            self.msglog('\n\t- '.join(messages), msglog.types.WARN)

    def _setup_collaborators(self, monitor):
        self.monitor = monitor
        self.manager = monitor.get_subscription_manager()
        self.formatter = monitor.get_formatter()
        self.transporter = monitor.get_transporter()

    def _setup_counters(self):
        self.export_successes = Counter()
        self.export_timeouts = Counter()
        self.export_errors = Counter()
        self.exports_started = Counter()
        self.exports_processed = Counter()
        self.exports_deferred = Counter()
        self.export_transactions = Counter()
        self.exports_scheduled = Counter()
        self.export_exceptions = Counter()
        # Export scheduled following skip.
        self.exports_skipped = Counter()
        # Scheduled export called late.
        self.exports_missed = Counter()

    def _reset_counters(self):
        self.export_successes.reset()
        self.export_timeouts.reset()
        self.export_errors.reset()
        self.exports_started.reset()
        self.exports_processed.reset()
        self.exports_deferred.reset()
        self.export_transactions.reset()
        self.exports_scheduled.reset()
        self.export_exceptions.reset()
        self.exports_skipped.reset()
        self.exports_missed.reset()

    def _setup_timers(self):
        self.run_timer = Timer('Runtime')
        self.poll_timer = Timer('Poll')
        self.format_timer = Timer('Format')
        self.export_timer = Timer('Export')
        self.transaction_start_timer = Timer('Trans start')
        self.transaction_life_timer = Timer('Trans life')

    def _reset_timers(self):
        self.poll_timer.reset()
        self.format_timer.reset()
        self.export_timer.reset()
        self.transaction_start_timer.reset()
        self.transaction_life_timer.reset()

    def _setup_trackers(self):
        self.export_time = None
        self.first_export_time = None
        self.active_transaction = None
        self._export_all_values = False

    def _reset_trackers(self):
        self._setup_trackers()

    def _timer_string(self, prefix='\t', sep='\n'):
        timestrs = [
            '%s%s' % (prefix, timestr) for timstr in self._timer_strings()
        ]
        return sep.join(timestrs)

    def _timer_strings(self):
        timers = self._get_timers()
        return map(str, timers)

    def _get_timers(self):
        return [
            self.export_timer, self.poll_timer, self.format_timer,
            self.transaction_start_timer, self.transaction_life_timer
        ]

    def debugout(self, dbmessage, dblevel=1):
        if self.debuglevel(dblevel):
            self.msglog(dbmessage, msglog.types.DB)

    def debuglevel(self, level=1):
        return level <= DEBUG

    def msglog(self, message, mtype=msglog.types.INFO, autoprefix=True):
        if autoprefix:
            message = '[%s] %s' % (self, message)
        msglog.log('broadway', mtype, message)

    def as_dictionary(self):
        configuration = {}
        configuration['monitor'] = self.monitor.url
        configuration['target'] = self.target
        configuration['nodes'] = self.node_table
        configuration['period'] = self.period
        configuration['retries'] = self.retries
        configuration['sid'] = self.sid
        return configuration

    def from_dictionary(klass, configuration):
        if not configuration.has_key('monitor'):
            msglog.log(
                'broadway', msglog.types.WARN,
                'Creating monitor URL from formatter parent to '
                'recreate subscription from %r' % configuration)
            formatter = rootspace.as_node(configuration['formatter'])
            configuration['monitor'] = formatter.parent.url
        monitor = rootspace.as_node(configuration['monitor'])
        target = configuration['target']
        nodes = configuration['nodes']
        period = configuration['period']
        retries = configuration['retries']
        sid = configuration['sid']
        return klass(monitor, target, nodes, period, retries, sid)

    from_dictionary = classmethod(from_dictionary)

    def __repr__(self):
        classname = self.__class__.__name__
        subscriptionnumber = self.subscription_number
        details = ['%s #%04d [%s]' % (classname, subscriptionnumber, self.sid)]
        counts = ['%dES' % self.exports_started.value]
        counts.append('%dEM' % self.exports_missed.value)
        counts.append('%dED' % self.exports_deferred.value)
        counts.append('%dEP' % self.exports_processed.value)
        counts.append('%dGD' % self.export_successes.value)
        counts.append('%dBD' % self.export_errors.value)
        counts.append('%dTO' % self.export_timeouts.value)
        counts.append('%dSK' % self.exports_skipped.value)
        details.append('(%s)' % '/'.join(counts))
        return '<%s>' % ' '.join(details)

    def toString(self):
        details = ['PS #%04d' % self.subscription_number]
        counts = ['%dES' % self.exports_started.value]
        counts.append('%dEM' % self.exports_missed.value)
        counts.append('%dED' % self.exports_deferred.value)
        counts.append('%dEP' % self.exports_processed.value)
        counts.append('%dGD' % self.export_successes.value)
        counts.append('%dBD' % self.export_errors.value)
        counts.append('%dTO' % self.export_timeouts.value)
        counts.append('%dSK' % self.exports_skipped.value)
        details.append('(%s)' % '/'.join(counts))
        return ' '.join(details)

    def __str__(self):
        classname = self.__class__.__name__
        return '%s #%d %r' % (classname, self.subscription_number, self.sid)