BUG: checkpoint scheduler messes with logging

[stephankramer]

Consider the following MFE:

from firedrake import *
from firedrake.adjoint import *
from checkpoint_schedules import SingleMemoryStorageSchedule

set_log_level(INFO)
continue_annotation()
tape = get_working_tape()
tape.enable_checkpointing(
    SingleMemoryStorageSchedule(),
    gc_timestep_frequency=1,
    gc_generation=2
)
trange = iter(range(10))
adj_timestepper = tape.timestepper(trange)

for i in adj_timestepper:
    info(f"Timestep {i}")

When run in serial, the info messages are duplicated:

firedrake:INFO Timestep 0
INFO:firedrake:Timestep 0
firedrake:INFO Timestep 1
INFO:firedrake:Timestep 1
firedrake:INFO Timestep 2
INFO:firedrake:Timestep 2
firedrake:INFO Timestep 3
INFO:firedrake:Timestep 3
firedrake:INFO Timestep 4
INFO:firedrake:Timestep 4
firedrake:INFO Timestep 5
INFO:firedrake:Timestep 5
firedrake:INFO Timestep 6
INFO:firedrake:Timestep 6
firedrake:INFO Timestep 7
INFO:firedrake:Timestep 7
firedrake:INFO Timestep 8
INFO:firedrake:Timestep 8
firedrake:INFO Timestep 9
INFO:firedrake:Timestep 9

whereas if you comment out the enable_checkpointing() line, it only prints the expected firedrake:INFO Timestep ... line. When run in serial this gets worse because it now also duplicates the additional lines (not prefixed with "firedrake:" for every process.

[jrmaddison]

It's caused by

https://github.com/dolfin-adjoint/pyadjoint/blob/40b8eeb84ae15f4ed97c067c288b7c91925f2592/pyadjoint/checkpointing.py#L219

which logs on the root logger. I think this should be fine, and I have no idea why this changes the behaviour of the Firedrake logger.

[jrmaddison]

The issue is that the root logger has no handlers. logging.info automatically sets up a basic handler with logging.basicConfig (https://docs.python.org/3/library/logging.html#logging.debug, https://docs.python.org/3/library/logging.html#logging.info) which then also logs output from all child loggers.