poll_reporter ¶

Logging for loops that poll every half second, where a line per cycle would bury the journal.

The REST pollers in bin/<broker>/ and the combiners in bin/unified/ report each cycle's outcome - "Merged 0 of 0 order(s)", "Orders poll failed: ..." - and at two cycles a second that is about 170,000 lines a day per script, nearly all of them the same line. PollReporter logs a message when it differs from the last one it logged at that level, and otherwise repeats it once every interval seconds, so the journal shows every change and a steady heartbeat while nothing changes.

Classes:

Name	Description
`PollReporter`	Log a polling loop's outcomes when they change, and at most once every `interval` seconds while they do not.

PollReporter ¶

PollReporter(logger, interval=60)

Log a polling loop's outcomes when they change, and at most once every interval seconds while they do not.

logger is where the messages go.
interval is how often an unchanged message is repeated, in seconds.

Start with no message logged at any level, so the first message at each level is always logged.

Parameters:

Name	Type	Description	Default
`logger`	`Logger`	Where the messages go.	required
`interval`	`float`	How often an unchanged message is repeated, in seconds; 60 unless given.	`60`

Example programs

Quiet until something changesHeartbeat after the interval

examples/utilities/poll_reporter/PollReporter/example_1_quiet_until_something_changes.py

"""Reports ten polling cycles, logging only the cycles whose outcome differs from the last one logged.

The REST pollers and the unified combiners run a cycle twice a second. Logging every cycle's outcome would write about 170,000 nearly identical lines a day per script, so they report through a `PollReporter`, which logs a message only when it differs from the last message logged at that level, or when that message is at least `interval` seconds old.

This program feeds a reporter the outcomes of ten made-up order poll cycles. It uses the default one-minute interval, and the ten cycles take far less than a minute, so no unchanged message is repeated. The reporter's logger writes to the output through a handler that prints the level and message without a timestamp. Nothing is polled.

Notice that the three identical "Merged 0" cycles produce one line, that the error is logged as soon as it appears and again when its text changes, and that the INFO line after the errors is logged because it differs from the last INFO line, not because an error came between.

Run it from the project root:

    python examples/utilities/poll_reporter/PollReporter/example_1_quiet_until_something_changes.py
"""

import logging
import sys

from utilities.poll_reporter import (
    PollReporter,
)


class QuietUntilSomethingChangesExample:
    """Reports ten cycles through a reporter and prints what was logged.

    Attributes:
        reporter (PollReporter): The reporter being shown.
        outcomes (list): Each cycle's level name and message.
    """

    def __init__(self):
        """Builds a logger that prints to the output and a reporter over it.

        Returns:
            None: This method returns nothing.
        """
        logger = logging.getLogger('example.orders_poller')
        handler = logging.StreamHandler(sys.stdout)
        handler.setFormatter(logging.Formatter('  logged %(levelname)s: %(message)s'))
        logger.addHandler(handler)
        logger.setLevel(logging.INFO)
        self.reporter = PollReporter(logger)
        self.outcomes = [
            (
                'info',
                'Merged 0 of 0 order(s)',
            ),
            (
                'info',
                'Merged 0 of 0 order(s)',
            ),
            (
                'info',
                'Merged 0 of 0 order(s)',
            ),
            (
                'info',
                'Merged 2 of 2 order(s)',
            ),
            (
                'error',
                'Orders poll failed: 503 Service Unavailable',
            ),
            (
                'error',
                'Orders poll failed: 503 Service Unavailable',
            ),
            (
                'error',
                'Orders poll failed: read timed out',
            ),
            (
                'info',
                'Merged 0 of 2 order(s)',
            ),
            (
                'info',
                'Merged 0 of 2 order(s)',
            ),
            (
                'info',
                'Merged 0 of 2 order(s)',
            ),
        ]

    def run(self):
        """Reports each cycle.

        Returns:
            None: This method returns nothing.
        """
        print(f'Repeat interval: {self.reporter.interval} seconds')
        for cycle, outcome in enumerate(self.outcomes, start=1):
            level_name, message = outcome
            print(f'cycle {cycle}: {level_name} {message}')
            if level_name == 'info':
                self.reporter.info(message)
            else:
                self.reporter.error(message)


if __name__ == '__main__':
    QuietUntilSomethingChangesExample().run()

It prints:

Repeat interval: 60 seconds
cycle 1: info Merged 0 of 0 order(s)
  logged INFO: Merged 0 of 0 order(s)
cycle 2: info Merged 0 of 0 order(s)
cycle 3: info Merged 0 of 0 order(s)
cycle 4: info Merged 2 of 2 order(s)
  logged INFO: Merged 2 of 2 order(s)
cycle 5: error Orders poll failed: 503 Service Unavailable
  logged ERROR: Orders poll failed: 503 Service Unavailable
cycle 6: error Orders poll failed: 503 Service Unavailable
cycle 7: error Orders poll failed: read timed out
  logged ERROR: Orders poll failed: read timed out
cycle 8: info Merged 0 of 2 order(s)
  logged INFO: Merged 0 of 2 order(s)
cycle 9: info Merged 0 of 2 order(s)
cycle 10: info Merged 0 of 2 order(s)

examples/utilities/poll_reporter/PollReporter/example_2_heartbeat_after_the_interval.py

"""Shows the heartbeat: an unchanged message is logged again once the interval has passed, and each level keeps its own memory.

A `PollReporter` remembers the last message it logged at each level and when. An unchanged message is logged again once `interval` seconds have passed since it was last logged, so the journal shows the loop is still alive. Levels are tracked separately, so `log` with `logging.WARNING` does not reset what `info` remembers.

To keep the program short, the interval is 0.5 seconds and the program sleeps 0.6 seconds between two groups of cycles, instead of the pollers' 60 seconds. The logger writes to the output through a handler that prints the level and message without a timestamp. Nothing is polled.

Notice that the second group repeats "Positions unchanged" once, right after the pause, and then goes quiet again, and that the WARNING and INFO lines do not silence each other.

Run it from the project root:

    python examples/utilities/poll_reporter/PollReporter/example_2_heartbeat_after_the_interval.py
"""

import logging
import sys
import time

from utilities.poll_reporter import (
    PollReporter,
)


class HeartbeatAfterTheIntervalExample:
    """Reports two groups of cycles with a pause longer than the interval between them.

    Attributes:
        reporter (PollReporter): The reporter being shown.
    """

    def __init__(self):
        """Builds a logger that prints to the output and a reporter with a 0.5 second interval.

        Returns:
            None: This method returns nothing.
        """
        logger = logging.getLogger('example.positions_poller')
        handler = logging.StreamHandler(sys.stdout)
        handler.setFormatter(logging.Formatter('  logged %(levelname)s: %(message)s'))
        logger.addHandler(handler)
        logger.setLevel(logging.INFO)
        self.reporter = PollReporter(logger, interval=0.5)

    def one_group(self, label):
        """Reports three unchanged cycles with a warning between them.

        Args:
            label (str): The group's name, for the printout.

        Returns:
            None: This method returns nothing.
        """
        print(label)
        self.reporter.info('Positions unchanged')
        self.reporter.log(logging.WARNING, 'Dhan answered slowly')
        self.reporter.info('Positions unchanged')
        self.reporter.log(logging.WARNING, 'Dhan answered slowly')
        self.reporter.info('Positions unchanged')

    def run(self):
        """Reports two groups with a pause between them.

        Returns:
            None: This method returns nothing.
        """
        self.one_group('First group')
        time.sleep(0.6)
        self.one_group('Second group, after 0.6 seconds')
        levels = []
        for level in sorted(self.reporter.last):
            levels.append(logging.getLevelName(level))
        print(f'Levels remembered: {levels}')


if __name__ == '__main__':
    HeartbeatAfterTheIntervalExample().run()

It prints:

First group
  logged INFO: Positions unchanged
  logged WARNING: Dhan answered slowly
Second group, after 0.6 seconds
  logged INFO: Positions unchanged
  logged WARNING: Dhan answered slowly
Levels remembered: ['INFO', 'WARNING']

Methods:

Name	Description
`log`	Log `message` at `level` when it is not the message last logged at that level, or that one is `interval` old.
`info`	Log a cycle's outcome at INFO, when it changed or once an interval. `message` is the text.
`error`	Log a failed cycle at ERROR, when the failure changed or once an interval. `message` is the text.

Source code in utilities/poll_reporter.py

def __init__(self, logger, interval=60):
    """
    Start with no message logged at any level, so the first message at each level is always logged.

    Args:
        logger (logging.Logger): Where the messages go.
        interval (float): How often an unchanged message is repeated, in seconds; 60 unless given.
    """
    self.logger = logger
    self.interval = interval
    # The last message logged at each level, and when.
    self.last = {}

log ¶

log(level, message)

Log message at level when it is not the message last logged at that level, or that one is interval old.

level is a logging level, for example logging.INFO.
message is the text to log.

Example usage

From example_2_heartbeat_after_the_interval.py

self.reporter.log(logging.WARNING, 'Dhan answered slowly')

Source code in utilities/poll_reporter.py

def log(self, level, message):
    """
    Log `message` at `level` when it is not the message last logged at that level, or that one is `interval` old.

    - `level` is a `logging` level, for example `logging.INFO`.
    - `message` is the text to log.
    """
    now = time.monotonic()
    previous = self.last.get(level)
    if previous is None or previous[0] != message or now - previous[1] >= self.interval:
        self.logger.log(level, message)
        self.last[level] = (message, now)

info ¶

info(message)

Log a cycle's outcome at INFO, when it changed or once an interval. message is the text.

Example usage

From example_1_quiet_until_something_changes.py

self.reporter.info(message)

From example_2_heartbeat_after_the_interval.py

self.reporter.info('Positions unchanged')

Source code in utilities/poll_reporter.py

def info(self, message):
    """Log a cycle's outcome at INFO, when it changed or once an interval. `message` is the text."""
    self.log(logging.INFO, message)

error ¶

error(message)

Log a failed cycle at ERROR, when the failure changed or once an interval. message is the text.

Example usage

From example_1_quiet_until_something_changes.py

self.reporter.error(message)

Source code in utilities/poll_reporter.py

def error(self, message):
    """Log a failed cycle at ERROR, when the failure changed or once an interval. `message` is the text."""
    self.log(logging.ERROR, message)