Add cache functionality to Logger

[lucas-flexcompute]

The cache can be used to suppress multiple messages from a context manager within that context or globally, for the whole python process. Here's a preview of how it works:

import tidy3d as td
from tidy3d import log

td.config.logging_level = "DEBUG"

print("Expected: info")
log.info("info message")

print("\nExpected: info, warning suppressed")
with log.cached() as cached_log:
    cached_log.info("info message")
    cached_log.warning("warning message")

print("\nExpected: warning, debug + 3 info suppressed")
with log.cached() as cached_log:
    cached_log.warning("warning message")
    cached_log.info("info message")
    cached_log.info("info message")
    cached_log.debug("debug message")
    cached_log.info("info message")

print("\nExpected: info + warning")
with log.cached(use_static_cache=True) as cached_log:
    cached_log.info("info message")
    cached_log.warning("warning message")

print("\nExpected: debug")
with log.cached(use_static_cache=True) as cached_log:
    cached_log.info("info message")
    cached_log.debug("debug message")
    cached_log.warning("warning message")

print("\nExpected: info")
log.info("info message")

Output:

Expected: info
[12:04:26] INFO: info message                             cached_log.py:7

Expected: info, warning suppressed
           INFO: info message                            cached_log.py:11
           INFO: Suppressed 1 WARNING message.                  log.py:83

Expected: warning, debug + 3 info suppressed
           WARNING: warning message                      cached_log.py:16
           INFO: Suppressed 3 INFO, 1 DEBUG messages.           log.py:83

Expected: info + warning
           INFO: info message                            cached_log.py:24
           WARNING: warning message                      cached_log.py:25

Expected: info
           INFO: info message                            cached_log.py:28

Expected: debug
           DEBUG: debug message                          cached_log.py:33

Expected: info
           INFO: info message                            cached_log.py:37

[tylerflex]

Looks good, this will give us some nice flexibility in how we display and package our validations. I just had a few higher level questions so I can understand a bit better

1. Does the caching happen based on the message string itself? because in our simulation.py code, for example, our warning message will contain information like the index into structures, which means that the message could be different each iteration. I think it would therefore not work as expected with this change? For example, we might want a way to display only the first warning within a context and then suppress the rest (but not necessarily cache the result). Right now, we've just been breaking out of the loop manually, which works.
2. I'm having trouble understanding the use_static_cache option. Is the point that if this is False, the caching happens at the global level (ie any logging gets cached and retained throughout the session) but if use_static_cache=True, the caching only happens within the context of the context manager? Maybe the "static" nomenclature is what's confusing me.

[tylerflex]

after looking at the example again, I think I'm still a bit confused, could you explain a bit what is going on here? For example, in the first few example is it just displaying the first log but then suppressing the rest? In the use_static_cache, it seems like similar behavior but just not printing an INFO message about suppression. Where does caching come in? For example, does the first info() call at the top level have any affect on the output?

[lucas-flexcompute]

The idea is the following: caching (either version) only takes place within managed context, both for storing entries and querying the contents of the cache. So the first info message in the example should have no effect anywhere else, nor any messages outside cached contexts (the last info message, for example). We could repeat this info messages everywhere and the outputs cached should remain the same. That's because we don't want to have a global state having effects throughout the code base.

The default (non-static) cache works only within a single context. It only allows a single log entry to be emitted, whatever level or message. All other entries after the first are accumulated (by level) so that a summary can be emitted after the context finishes (that was something Xin said might be valuable). The idea here is to substitute those early exits in warning loops you mentioned. In this case, the user will see the 1st warning as before and the total number of warnings emitted. So, for example, is a simulation validation generates 10 warnings about structures, the user sees the first and a message saying another 9 warnings were suppressed. That way they know how many issues have been found. The way I implemented, each validator has their own context, so the user will receive 1 message from each validator warning.

The static cache issues only messages that have not been issued before and is global to all cached contexts. The use here is to warn the user, for example, that we have now a remote mode solver on the first use of the local one, but never again. That will also be useful for any deprecation warnings we want to issue, so the user is not bombarded by recurring warnings.

Caching by message contents happens only for the static case, where messages should probably be constant. If not, the best way to ensure caching with dynamic strings, is to use the log system to do the composition: log.warning("Issue number %d", some_int) instead of log.warning(f"issue number {some_int}"), because the caching is done before the composition. For non-static caching, we catch all, do there's no real caching, it's more of an accumulator.

[tylerflex]

Ok I see, this sounds great. So the use_static_cache=False sounds perfect for eg. Simulation.structures validators, whereas the use_static_cache=True sounds perfect for eg. deprecation warnings we want to only show up once in the session. The only comment I might have is that maybe it's a little difficult to understand that behavior based on log.cached and use_static_cache nomenclature. Do you think these names are clear enough? A naive idea for what I might call these based on what I understand is something like log.capture for the context manager and suppress_cached for the kwarg toggling whether to suppress messages that have been previously called. We could also consider making two separate context managers (perhaps inheriting from the same base) like log.consolidate and log.suppress_cached. Just some thoughts, but overall I think the behavior of each sound very useful!

[lucas-flexcompute]

Agreed! I also think that using 2 separate functions makes much more sense! I'll make the changes soon. I implemented the new log contexts to Simulation. Do you have any other classes where this would be useful?

[tylerflex]

in the adjoint.components.simulation there are some validators that could probably also use it. they're similar to the ones in the regular Simulation.

[dbochkov-flexcompute]

I decomposed the field mapping into first building a hash map of all fields in the model, that should improve performance quite a bit. It is also done piece by piece, instead of all at the end, as you mentioned. Please take a look at the current state of #895

I like the idea of shutting off this functionality on the python front-end. It could be a global config flag (td.config.capture_validation_logs that the GUI could set on initialization).

The logger is only printing this information at the moment. How do you see it interacting with the client services?

Also, feel free to push into the other branch, so that all changes are consolidated in a single place. (And move the discussion over there too?)

This sounds great, thank for merging these two functionalities, it seems to be working as expected. For using capturing, maybe we can do something like that:

log.capture(True)  # from now capturing is on
# do things
warning_list = log.get_warning_list()  # compiles list of warning with similar to pydantic format and clears accumulated warnings
log.capture(False)  # turn off capturing

I can take a stab at it and commit/PR

[lucas-flexcompute]

The way is works now is on BaseModel, similar to what you have before, with log.begin_capture() ... log.end_cature(). Instead of printing, the logger could keep the captured trace:

    self._log_trace = stack_item

def last_trace(self):
    trace = self._log_trace
    self._log_trace = None
    return trace

and the client service would just look at that log.last_log after the validation, so there's o need to keep turning it on and off (this already happens in BaseModel.__init__). After initialization, the client just fetches log.last_trace() as they do right now with flush()

[dbochkov-flexcompute]

by log.capture(True) I meant controlling the behavior of the logger, like setting td.config.capture_validation_logs. I don't have a preference whether it should be done through a global config flag of and internal log flag. I implemented compiling the warning list similar to pydantic formatting, so it could be easily processed on gui side. Let me know if this looks ok to you, I put temporarily an example here https://github.com/flexcompute/tidy3d/pull/895/files#diff-b7d557b5545af720994d67968c9c54cb91b8957a38d7c0cb00f87ed92f0168b0, feel free to modify/revert whatever way it makes sense

[lucas-flexcompute]

Ah, I see! Yes, looks great to me! The test is a good addition too!

[tylerflex]

Looks good from a high level, so is there a summary of the changes to the logger somewhere? I feel like it would be really useful to have some kind of basic developer's guide to the new logging features, this could even be written in the form of a test. Is the main change just that

with log as captured_log:

consolidates all the messages? and more generally that any logging within a Tidy3DBaseModel init gets captured?

What happened to the functionality for eg the mode solver where we wanted to log a warning only once per session? is that included in the caching or a separate

[lucas-flexcompute]

Yes, this context manager with log as captured_log: initiates the log consolidation (I'm going to change the variable from captured_log to consolidated_logger to make it clearer). In fact, it could be simply with log: as there's no need to rename it; it's more for the sake of clarity.

The global log suppression if done with the keyword argument log_once, added to all log methods. That's because these 2 functionalities are orthogonal, having both started from a context manager is weird. Plus, suppression is something that should be set on an individual message, not in a context, as it is the message that we want shown only once.

Capturing for the UI happens regardless of the other functions, so the UI is unaffected by them.

[tylerflex]

sounds great! I'll approve but maybe @dbochkov-flexcompute wants to do a final review? note, you'll probably need to rebase this against pre/2.3 as I merged develop into pre/2.3 to incorporate tox and other fixes

[dbochkov-flexcompute]

Everything looks good to me too, I just added a clean test for warning capturing functionality. I can go ahead and rebase to pre/2.3

[dbochkov-flexcompute]

No issues during rebasing. Do we want to squash some/all commits in here? it kinda got out of hands lol. Up to you, @lucas-flexcompute