Fix IndexError in override_log_formatter_context utility

[sphuber]

Fixes #4872

In the aiida.common.log.override_log_formatter_context utility
function, the formatting of all current AiiDA handlers is temporarily
changed for the duration of the yield, and then reset. The problem is
that the function assumed that the number of handlers would not change,
which is not necessarily the case. Additionally, it also relied on the
order of the handlers, which isn't guaranteed either.

The solution is to simply cache the handlers' formatters as a dictionary
and directly use those handler references to reset the cached formatter.
Note that we copy the handler.formatter return value because it may be
returned by reference and we want to keep the original formatter if it
is changed during the yield. Note also that it doesn't matter that the
AiiDA logger may have gained additional handlers during the yield, after
we recorded the cached formatters, but that is ok, because we didn't
temporarily change their formatter either.

[sphuber]

@chrisjsewell interested to hear why you chose for your original implementation even though you were aware of this potential problem, as evidenced by your note in the docstring.

[chrisjsewell]

Nope I wasn't aware at all of that problem! The function and doc string note were added by @CasperWA in: #3599

[sphuber]

Ah apologies, in my git loggage it looked like you had committed that. Well I will pass on the question to @CasperWA in that case 😅

[ramirezfranciscof]

I don't know if this was the reason, but one issue that comes to mind is that if the handlers change then what is the "definition" of setting them back? I'm not familiar enough with this design to make any confident assertion of conceptual problems, but some ideas:

1. What happens when you handler.setFormatter(formatter) if the handler was removed from AIIDA_LOGGER.handlers?
2. It would seem that if a handler that was not originally on AIIDA_LOGGER.handlers is later changed (is then added to AIIDA_LOGGER.handlers?), then it will not be reset. Is this consistent with what happens in 1?

From an ignorant perspective, it seems that we are leaving alone any handler that got "created" in the middle but we are re-creating any handler that was "eliminated" during the yield, which is not the consistency I would expect at least.

(EDIT: again, this is an impression I get but I don't know the details of the implementation. Thus, if they are more familiar with this class, I think it'll be better if either @chrisjsewell or @CasperWA approve this PR)

[codecov]

Codecov Report

Merging #4873 (c35f963) into develop (7295bb6) will increase coverage by 0.01%.
The diff coverage is 100.00%.

@@             Coverage Diff             @@
##           develop    #4873      +/-   ##
===========================================
+ Coverage    79.62%   79.62%   +0.01%     
===========================================
  Files          519      519              
  Lines        37110    37111       +1     
===========================================
+ Hits         29544    29545       +1     
  Misses        7566     7566              

Flag	Coverage Δ
django	74.36% <100.00%> (-<0.01%)	⬇️
sqlalchemy	73.27% <100.00%> (+0.01%)	⬆️

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

Impacted Files	Coverage Δ
aiida/common/log.py	78.27% <100.00%> (+0.32%)	⬆️

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 7295bb6...c35f963. Read the comment docs.

[sphuber]

From an ignorant perspective, it seems that we are leaving alone any handler that got "created" in the middle but we are re-creating any handler that was "eliminated" during the yield, which is not the consistency I would expect at least.

We are not recreating any handlers actually, we are just temporarily changing the formatters. You can consider the AIIDA_LOGGER as a container for handlers. If the logger removes the handler, doesn't mean that the handler object no longer exists, but it won't really be used any more. It also really doesn't matter any more in that sense because the changed format will never come back into play.

So the behavior after this fix is correct as far as I am concerned. We take existing handlers, temporarily change their behavior, and afterwards revert that. Whether they are still in use by the same logger or not after the yield is irrelevant.

[sphuber]

Anyway, whatever we do. This blocks the v1.6.2 release so we cannot let this linger around for too long

[CasperWA]

Let's never talk of this again - go go go














(I think it was an issue of lazyness, lost overview, and a rogue simultaneous rewriting of some logging logic (not by me, though) during the specific PR that led to this poor choice of mine - but I might definitely be wrong - thanks for fixing it, though! ❤️ ).

[CasperWA]

... although maybe there should be a test for this one? ... 😅

[ramirezfranciscof]

If the logger removes the handler, doesn't mean that the handler object no longer exists, but it won't really be used any more.

Thanks for the explanation! Can this still be consider as an "activation/deactivation" of the handler through the inclusion on that list? It might be weird if I deactivate some handler at some point and I activate it again and it has a different format?

[CasperWA]

If the logger removes the handler, doesn't mean that the handler object no longer exists, but it won't really be used any more.

Thanks for the explanation! Can this still be consider as an "activation/deactivation" of the handler through the inclusion on that list? It might be weird if I deactivate some handler at some point and I activate it again and it has a different format?

I'm not exactly sure what you mean here, but this should - as @sphuber also described - just change the formatting, temporarily for the provided loggers for the entirety of the decorated function, and then revert them to their original formatting afterwards.

The provided loggers here, being all the loggers present in the AIIDA_LOGGER container. Or more specifically, all the logging module log handlers that are set up and stored in the AIIDA_LOGGER container for logging different name spaces in their own (or shared) formatting, etc.

Edit: And just to be clear. Nothing is "activated/deactivated". The formatting, i.e., how the logs are written/displayed is the only thing that is temporarily changed. I believe this is implemented to make the stdout outputs during export/import look nice - and that's it :)

[ramirezfranciscof]

Edit: And just to be clear. Nothing is "activated/deactivated". The formatting, i.e., how the logs are written/displayed is the only thing that is temporarily changed. I believe this is implemented to make the stdout outputs during export/import look nice - and that's it :)

Mmm ok, then perhaps the problem is that I don't fully understand the purpose of the AIIDA_LOGGER container; or more specifically, why would it change size/content if that is not related to the activation/deactivation or creation/deletion of handlers.

[ramirezfranciscof]

Anyway, whatever we do. This blocks the v1.6.2 release so we cannot let this linger around for too long

I'll approve this so my questions to understand this feature are not mistaken for objections to moving forward. As I said, I would have preferred the final greenlight came from someone more familiar with the class, but from @CasperWA and @chrisjsewell comments I assume they are giving implicit approval and may not have done so explicitly not to cut the ongoing discussion. If you understand the same @sphuber , feel free to merge, the discussion can continue independently of this.

[ramirezfranciscof]

Classic xD

[sphuber]

preferred the final greenlight came from someone more familiar with the class

Like who? It was @CasperWA who wrote the function. Think it is fine to merge this as it fixes the immediate problem. Happy to explain this some other time, preferably face to face over zoom, because in writing takes too much time.

[ramirezfranciscof]

Like who? It was @CasperWA who wrote the function

I totally missed that he already had approved the PR.

Happy to explain this some other time, preferably face to face over zoom, because in writing takes too much time.

I'll probably try to bring it up in the maintainers meeting tomorrow at 11 to see if Chris can explain this to me, but would very much welcome you there if you have 15 mins.