NREL-Sienna / InfrastructureSystems.jl

Utility package for Sienna's simulation infrastructure
https://nrel-sienna.github.io/InfrastructureSystems.jl/
BSD 3-Clause "New" or "Revised" License
38 stars 20 forks source link

Add time-based log event suppression #249

Closed daniel-thom closed 2 years ago

daniel-thom commented 3 years ago

This PR fixes https://github.com/NREL-SIIP/PowerSystems.jl/issues/775.

Use case:

@warn "Noisy log message" maxlog = 10 _suppression_period = 5

We take over maxlog if _suppression_period is set. At most, 10 instances of this message will get logged every 5 seconds. If _suppression_period is not set, the standard Julia behavior for maxlog applies: at most 10 log messages will occur for the entire Julia process.

codecov[bot] commented 3 years ago

Codecov Report

Merging #249 (146c416) into master (1efddc8) will increase coverage by 0.27%. The diff coverage is 100.00%.

:exclamation: Current head 146c416 differs from pull request most recent head 3c8c3a6. Consider uploading reports for the commit 3c8c3a6 to get more accurate results Impacted file tree graph

@@            Coverage Diff             @@
##           master     #249      +/-   ##
==========================================
+ Coverage   76.42%   76.70%   +0.27%     
==========================================
  Files          43       43              
  Lines        3165     3202      +37     
==========================================
+ Hits         2419     2456      +37     
  Misses        746      746              
Flag Coverage Δ
unittests 76.70% <100.00%> (+0.27%) :arrow_up:

Flags with carried forward coverage won't be shown. Click here to find out more.

Impacted Files Coverage Δ
src/utils/logging.jl 92.00% <100.00%> (+2.21%) :arrow_up:
src/utils/lazy_dict_from_iterator.jl 96.15% <0.00%> (-0.15%) :arrow_down:
jd-lara commented 3 years ago

This PR fixes NREL-SIIP/PowerSystems.jl#775.

You may have different opinions on the behavior, so please comment as you see fit. I'm not opposed to making changes. I'll update the documentation after we reach consensus.

My original plan was to support this:

@warn "Noisy log message" maxlog = 50 suppression_timeout = 5s

After further consideration I decided that the standard maxlog is really kind of pointless because it applies for the duration of the Julia process. If you are running in a REPL you really want suppression to reset after some time. So, I decided on this:

@warn "Noisy log message" max_count = 50

There is a global suppression_period value of 5 seconds that applies to all events. You can customize that for one event like this:

@warn "Noisy log message" max_count = 50 suppression_period = 5s

Update: There is a bit more complexity. If you create a logger with InfrastructureSystems.configure_logging, all of the above applies. Many users of PowerSystems won't do that. They will start Julia and implicitly use the default console logger. In that case the code in this PR that intercepts max_count and suppression_period won't run. The user will see something like this (note max_count):

┌ Warning: Rate 175.0 MW for C5 is larger than the max expected in the range of (min = 47.0, max = 52.0).
│   max_count = 50
└ @ PowerSystems ~/sandboxes/PowerSystems.jl/src/utils/IO/branchdata_checks.jl:148

If we completely took over maxlog in our logger and never defined a custom suppression_period, the user would see different behavior between the default Julia logger and our logger, but no "weird" parameters like max_count would show up.

We could assume safely that users mostly will limit the use to the default and only change this in some cases. In my experience, if a user wants a specific logger behavior then they control it witj kwargs into the functions.