Bug fixing

There are no breaking changes or new features.

Bugfixes

• expose the rest of the logging functions associated with a level (debug, warning, etc..).
• add stdout/stderr filter so that logs lower than WARNING go to stdout instead of stderr.
• fix PickleHandler trying to write in files it finds in log_dir by adding a timestamp.
• fix MaxMetric constructor args.
• fix import exception handling for TensorBoard.

Other

• change the stream output formatter.

Cache step values, saner logging levels

Breaking changes

There are no breaking changes.

New features

We now support a form of caching events traced at every step through the rlog.ValueMetric.
You can now configure it like this:

    ...
    rlog.ValueMetric("mse_err", metargs=["err"]),
    ...

and in your hot loop do:

    train_log.put(err=err)
    if logging_time:
        rlog.trace(step=policy.steps, **rlog.summary())

Improvements

The logging levels are now:

Level	Numeric value
CRITICAL	50
ERROR	40
WARNING	30
INFO	20
TRACE	15
DEBUG	10
NOTSET	0

• RLog is now configured with TRACE as before but
• the StreamHandler writing to the console and FileHandler writing to the the text file are configured as INFO in order to avoid dumping the data buffered by rlog.ValueMetric
• the structured handlers such as PickleHandler and TensorboardHandler are configured to TRACE levels and are logging this data to disk.

11:52:53 [ INFO]: RLog initialized.

With RLog you can start logging right away, no need to fiddle with settings.

import rlog

rlog.init("dqn")
rlog.info("Logging application level stuff.")

will output

11:52:53 [  dqn][   INFO]: Logging application level stuff.

This will not write to disk though. If we pass a folder path to rlog.init()
a rlog will write to a log.log, to a <logger_name>.pkl and optionaly to
a tensorboard event file.

rlog.init("dqn", path="./sota_results/", tensorboard=True)
rlog.info("Logging application level stuff.")

We can also create a new logger that will inherit the settings of the root one.

train_log = rlog.getLogger("dqn.train")
train_log.info("Starting training... ")

RLog provides a new logging.TRACE level and a new RLogger.trace() method
that allows logging structured info like this:

train_log.trace(step=1, loss=-0.23, target_val=2.38)
train_log.trace(step=2, loss=-0.21, target_val=1.87)
...
train_log.trace(step=5, loss=-0.18, target_val=1.33)

Although it probably not a good idea to trace every step all the time. For
experiments running for millions of steps we have another mechanism that
accumulates values at every step and summarizes them, logging only these
summaries.

Each Metric accepts a name and some metargs that tells it which arguments
received by the put call bellow to accumulate and summarize.

train_log.addMetrics([
    rlog.SumMetric("ep_cnt", resetable=False, metargs=["done"]),
    rlog.AvgMetric("R_per_ep", metargs=["reward", "done"]),
    rlog.AvgMetric("R_per_step", metargs=["reward", 1]),
    rlog.AvgMetric("rw_per_ep", metargs=["clip(reward)", "done"]),
    rlog.FPSMetric("learning_fps", metargs=["frame_no"]),
])

And somehwere in your training loop you can do:

for step in range(1, training_steps):

    # simply trace all the values you passed as `metargs` above.
    # the logger will know how to dispatch each argument.
    train_log.put(reward=reward, done=done, frame_no=32)

    if step % 250 == 0:
        # this is the call that dumps everything to the logger.
        train_log.trace(step=step, **train_log.summarize())
        # and here we reset the metrics so that we the statistics
        # are not a running average but are windowed.
        train_log.reset()

And ofcourse we can configure a different logger for evaluating the
agent we are training:

eval_log = rlog.getLogger("dqn.eval")
eval_log.info("Starting evaluation... ")