Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Inconsistent Behaviour in use of custom_log #629

Closed
tbhallett opened this issue Jun 15, 2022 · 10 comments · Fixed by #1157
Closed

Inconsistent Behaviour in use of custom_log #629

tbhallett opened this issue Jun 15, 2022 · 10 comments · Fixed by #1157
Assignees
Labels
bug Something isn't working framework

Comments

@tbhallett
Copy link
Collaborator

tbhallett commented Jun 15, 2022

When using the argument custom_log when initialising a simulation, behaviour is not as expected when there is more than logger defined within a module. The behaviour is as expected when using the method sim.configure_logging() after the models have been registered.

As a consequence, all runs that ask for tlo.methods.demography (which is most) also go tlo.methods.demography.detail (which they don't want and is very heavy).

The issue is demonstrated in the tests added in #628

  • This test passes
def test_can_turn_off_the_detailed_logger_when_using_custom_log_after_registering(seed, tmpdir):
    """Check that the simulation can be set-up to get only the usual demography logger and not the detailed logger,
    when the custom_log information is given after the models are registered."""

    log_config = {
        'filename': 'temp',
        'directory': tmpdir,
        'custom_levels': {
            "*": logging.WARNING,
            'tlo.methods.demography.detail': logging.WARNING,  # <-- Explicitly turning off the detailed logger
            'tlo.methods.demography': logging.INFO,  # <-- Turning on the normal logger
        }
    }

    rfp = Path(os.path.dirname(__file__)) / '../resources'

    sim = Simulation(start_date=Date(2010, 1, 1), seed=seed)
    sim.register(demography.Demography(resourcefilepath=rfp))
    sim.configure_logging(**log_config)
    sim.make_initial_population(n=100)
    sim.simulate(end_date=sim.start_date)

    # Cause one death to occur
    sim.modules['Demography'].do_death(
        individual_id=0,
        originating_module=sim.modules['Demography'],
        cause='Other'
    )

    log = parse_log_file(sim.log_filepath)

    # Check the usual `tlo.methods.demography' log is created and that check persons have died (which would be when the
    # detailed logger would be used).
    assert 'tlo.methods.demography' in log.keys()
    assert 1 == len(log['tlo.methods.demography']['death'])

    # Check that the detailed logger is not created.
    assert 'tlo.methods.demography.detail' not in log.keys()
  • BUT This test fails
def test_can_turn_off_the_detailed_logger_when_using_custom_log_when_registering(seed, tmpdir):
    """Check that the simulation can be set-up to get only the usual demography logger and not the detailed logger,
    when providing the config_log information when the simulation is initialised."""

    log_config = {
        'filename': 'temp',
        'directory': tmpdir,
        'custom_levels': {
            "*": logging.WARNING,
            'tlo.methods.demography.detail': logging.WARNING,  # <-- Explicitly turning off the detailed logger
            'tlo.methods.demography': logging.INFO,  # <-- Turning on the normal logger
        }
    }

    rfp = Path(os.path.dirname(__file__)) / '../resources'

    sim = Simulation(start_date=Date(2010, 1, 1), seed=seed, log_config=log_config)

    sim.register(demography.Demography(resourcefilepath=rfp))
    sim.make_initial_population(n=100)
    sim.simulate(end_date=sim.start_date)

    # Cause one death to occur
    sim.modules['Demography'].do_death(
        individual_id=0,
        originating_module=sim.modules['Demography'],
        cause='Other'
    )

    log = parse_log_file(sim.log_filepath)

    # Check the usual `tlo.methods.demography' log is created and that check persons have died (which would be when the
    # detailed logger would be used).
    assert 'tlo.methods.demography' in log.keys()
    assert 1 == len(log['tlo.methods.demography']['death'])

    # Check that the detailed logger is not created.
    assert 'tlo.methods.demography.detail' not in log.keys()
@tamuri
Copy link
Collaborator

tamuri commented Nov 28, 2022

Thanks, Tim. Think I've found the cause of this problem. As you demonstrate, there are two ways to configure logging levels for the modules: either passing the log_config argument when initialising a Simulation or by explicitly calling configure_logging.

Unfortunately, the [internal] logic is not consistent. When passing the log_config argument, we apply a level for each module as it's registered. tlo.methods.demography is the registered module, so we lookup the custom level and set it. tlo.methods.demography.details is not a registered module, so the custom level is ignored. However, when calling configure_logging we loop over the custom_level key and apply each level without checking whether it's a registered module.

I'll fix this to make it consistent. I think it's safe to apply all the levels in custom_levels without checking for existence of a corresponding module.

@tamuri tamuri added bug Something isn't working framework labels Jul 26, 2023
@tamuri tamuri closed this as completed Aug 9, 2023
@tamuri tamuri moved this from To do to Done in Issue management Oct 12, 2023
@tamuri tamuri reopened this Oct 13, 2023
Issue management automation moved this from Done to Issues Oct 13, 2023
@tamuri tamuri moved this from Issues to To do in Issue management Oct 13, 2023
@mnjowe
Copy link
Collaborator

mnjowe commented Apr 16, 2024

@tamuri, @tbhallett . Is this issue resolved? I can see it was closed as completed, then re-opened, moved to done and then moved back to to do. Are there any issues still standing?

@tbhallett
Copy link
Collaborator Author

tbhallett commented Apr 16, 2024 via email

@mnjowe
Copy link
Collaborator

mnjowe commented Apr 25, 2024

Hi @tbhallett . I think this issue was resolved. Have run the two scenarios above and they are all passing. Have also run another issue #840 linked to this issue and its behaving just as expected. I was just thinking though if it can be good to make private self.configure_logging() so that we can have one way of configuring simulation logs as suggested here #1064?

@tbhallett
Copy link
Collaborator Author

Agreed -- please propose that change in a PR for @tamuri 's review

@tbhallett
Copy link
Collaborator Author

tbhallett commented Apr 25, 2024

@mnjowe --- could I also suggest that that test (test_can_turn_off_the_detailed_logger_when_using_custom_log_when_registering) sketched out above are brought into our tests formally, e..g in test_logging_end_to_end.py.... That way we guard against regression and the intended behaviour is clear to everyone.

@mnjowe
Copy link
Collaborator

mnjowe commented Apr 25, 2024

That's a good suggestion @tbhallett. I agree

@tbhallett
Copy link
Collaborator Author

Thanks @mnjowe. Please raise a PR for this when you get the chance and we'll get this ticked off! 👍

@mnjowe
Copy link
Collaborator

mnjowe commented Apr 29, 2024

Hi @tbhallett. I can see this issue in linked to PR #1157. Should I continue with that PR or I should still open a new PR? PR #1157 is still open

@tbhallett
Copy link
Collaborator Author

Either would be fine. As this PR has the key stuff already, it would be pretty easy to use it, so maybe do that!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working framework
Projects
Development

Successfully merging a pull request may close this issue.

3 participants