Add `Logger.rebuild()` Method #189

Mr0grog · 2024-01-05T21:51:10Z

This resolves #187 by adding a new Logger.rebuild(includeChildren) method, which takes care of using the methodFactory to update all the logging methods according to the current level. If the includeChildren argument is set to true and the method is called on the root logger, it will recursively rebuild all the child loggers (it is false by default, but in some future v2, it should probably be changed to true).

The includeChildren argument is mainly useful for two cases:

When applying a plugin or modifying the logger’s methodFactory, it can be used to update previously existing child loggers, so you can divorce logger configuration code from logger declaration code. Ideally, plugin developers will call this from their plugin’s apply/register/whatever code. But a user could call it directly if a plugin developer does not.
When changing the level on the root logger and you want that new level to apply to already existing child loggers (that you haven’t called setLevel() on and that didn’t have persisted levels). This essentially lets you treat a logger’s “default” level as if it means “whatever my parent/root logger’s current level is.”

So in #187, the example problem code could be updated slightly to make everything work right:

// In `a-random-submodule.js`
import log from 'loglevel'

const logger = log.getLogger('DefaultUiAutomationWorker');

// In `index.js`
import aRandomSubmodule from 'a-random-submodule.js';
import log from 'loglevel';
import logPrefix from 'loglevel-plugin-prefix';

function main() {
    logPrefix.reg(log);
    logPrefix.apply(log, { template: '[%t] %l %n:' });
    log.enableAll();
    log.rebuild(true);  // Adding this line is the only change.

    // start rest of program here
}

main();

Other Notes

In the discussion on Why do I have to configure the log in every typescript file? #187, we talked about calling this rebuildLogger(). I named it rebuild() here because I thought that was just as clear and a bit more concise, but I’m happy to change it if you’d prefer.
I made a small note in the code that includeChildren should default to true in some future v2 of the library. As discussed in Why do I have to configure the log in every typescript file? #187, having setLevel() affect pre-existing child loggers is probably the right ideal, but might cause subtle breakage, so for now I just made rebuild() only affect the current level by default. Flipping the default in the future will also affect the behavior of setLevel() and setDefaultLevel() since they use rebuild() internally.

Another option here is to make the default true but having setLevel() and setDefaultLevel() call it with false (so log.rebuild() affects child loggers by default, but setLevel() and setDefaultLevel() do not). I think either way would probably be fine. 🤷
There are a few subtle side-effects here:
- The currentLevel private variable used to always be a valid level. It no longer is — you should always call logger.getLevel() to get the current level. (defaultLevel will always be set and valid; currentLevel will only be set if setLevel() was explicitly called or a persisted level was loaded.) This shouldn’t affect the public interface at all, and I’ve made sure all internal callsites do the right thing.
- setLevel() throws a TypeError instead of a string for invalid input. I don’t think this should really be an issue, and it arguably improves errors slightly (IMO throwing or rejecting with things that aren’t instances Error or a sub-type is problematic). But I can change it back if you prefer.

Mr0grog · 2024-01-05T22:03:07Z

Whoops, forgot to update docs and type definitions. I added two commits to do that.

I’m also noticing that it doesn’t look like Travis is in use any longer, or at least there are no CI checks showing up on this PR. Should we add a GitHub Actions workflow since Travis doesn’t really have a free-for-open-source plan anymore?

lib/loglevel.js

pimterry · 2024-01-10T16:22:50Z

lib/loglevel.js

-              self.setLevel(level, false);
+          defaultLevel = normalizeLevel(level);
+          if (currentLevel == null) {
+            self.rebuild();


I'm not clear why the defaultlevel logic everywhere needs to change to implement this, can you clarify that? It seems without changing this, rebuild should be able to just call setDefaultLevel on children and they would update as expected already.

Hmmm, I’m not totally sure what you are getting at here, can you clarify a bit? (What do you mean by “the defaulLevel logic everywhere?”)

The problem I encountered going into this is that, under the hood, setDefaultLevel() calls setLevel(), and currentLevel is whatever level the logger is at. BUT that means you can’t tell the difference between a case where the logger is taking its level from its parent vs. a case where a user has explicitly set the logger’s level. There were three solutions that I could think of for that:

Have currentLevel be the explicitly set level (or null/undefined if not set delegating to the parent’s level) and have defaultLevel represent the parent’s level (since we don’t have a reference to the parent). This is what I did because it seemed most straightforward to me, logic-wise.

Have a new private variable named hasExplicitLevel or similar that indicates whether currentLevel comes from a user’s call to setLevel() (if true) vs. if it came from the parent logger (if false).

Have a logger keep a reference to its parent and drop the defaultLevel private variable. This has an issue where getLevel() might return something that doesn’t match the actual current behavior (if a parent’s level has changed but this logger has not been rebuilt).

(That said, I suspect most of the above is probably clear to you, and I’m missing what you’re getting at.)

I think this should also applies to setDefaultLevel though.

Reading the code, I think the current model implemented there is that 'something persisted' means that the value was overridden (and so shouldn't be changed) and anything else means that the value is a default value which should change when the default level changes.

We shouldn't change that existing logic for default levels (whether or not it's a good design, it's a breaking change that would unexpectedly change what's logged by people's applications).

I think the same logic should simply apply for the new rebuild API: if the pre-existing setDefaultLevel logic would modify the level, then rebuilding should modify the level.

In a future version we could re-evaulate this, and in that case I think there's a good argument for explicitly tracking whether the level was set manually or not, but for now I think we have to stick with the existing behaviour.

Reading the code, I think the current model implemented there is that 'something persisted' means that the value was overridden (and so shouldn't be changed) and anything else means that the value is a default value which should change when the default level changes.

I guess I’d argue that leaning on persistence is already problematic, since it doesn’t work in environments that have no persistence mechanism (e.g. Node, Bun, an iframe with a lot of sandboxing options turned on, etc.). It means this happens, which sure feels like a bug to me:

var child = log.getLogger("test"); child.getLevel(); // 3 (WARN) child.setLevel("TRACE"); child.getLevel(); // 0 (TRACE), good! child.setDefaultLevel("DEBUG"); child.getLevel(); // 1 (DEBUG), seems bad!

Or more saliently, once there’s a rebuild() method:

log.getLevel(); // 3 (WARN) var child = log.getLogger("test"); child.getLevel(); // 3 (WARN), it inherited, good. child.setLevel("TRACE"); child.getLevel(); // 0 (TRACE), good! log.rebuild(); child.getLevel(); // 3 (WARN), seems bad that rebuilding changes the // child's level after you've explicitly set it.

I suppose this is, very subtly, breaking; the question is whether the current behavior is a bug (my view, and hence why it is OK to “fix” as a byproduct of this) or is just what it is. I think most people’s mental model here is what I’m doing in this change and so wouldn’t be surprised by it.

There is also a test that models the above scenario:

loglevel/test/multiple-logger-test.js

Lines 175 to 182 in 4539639

it("should not change a child's explicitly set level even if un-persisted", function(log) {

log.setLevel("TRACE");

var newLogger = log.getLogger("newLogger");

newLogger.setLevel("DEBUG", false);

log.rebuild(true);

expect(newLogger).toBeAtLevel("DEBUG");

});

I feel like it is clear to me that that test should always succeed (and therefore needs this change, or one of the similar things I enumerated above).

Ugh, looked back at the discussion when I originally added setDefaultLevel(), and I am definitely wrong. “Default’ was probably a confusing name choice (my fault!) and I was over-focused on the browser context at the time. Anyway, I had lost track of the fact that setDefaultLevel() was originally intended to be a way to say “set the level unless you’ve loaded saved configuration info from somewhere,” not “set the level if one hasn’t been explicitly set otherwise” (which is how I was thinking of it when I wrote this PR). The idea was that setDefaultLevel() was for built-in config in your app, and setLevel() was only for runtime reconfiguration by users (e.g. a dev setting it in their console, some preference a user might adjust, a CLI flag).

Obviously I need to re-do this. setDefaultLevel() might not have been well designed (my fault!), but it is working as designed and is far too well baked to change, as you noted.

I think the same logic should simply apply for the new rebuild API: if the pre-existing setDefaultLevel logic would modify the level, then rebuilding should modify the level.

I don’t think this is quite right, though. With the right definition for setDefaultLevel() (above), it seems like it obviously qualifies as explicitly setting the logger’s level just as much as setLevel() does. Using either one means the logger’s level shouldn’t be influenced by its parent anymore.

That is:

log.setLevel("WARN"); var child1 = log.getLogger("child1"); child1.setLevel("ERROR"); child1.getLevel(); // ERROR var child2 = log.getLogger("child2"); child2.setDefaultLevel("ERROR"); child2.getLevel(); // Let's assume ERROR and something was not previously saved var child3 = log.getLogger("child3"); child3.getLevel(): // Let's assume it WARN because nothing was previously saved log.methodFactory = function() { ... } log.setLevel("TRACE"); log.rebuild(); // So the levels should now be: // log = TRACE (we just set it) // child1 = ERROR (was set with setLevel) // child2 = ERROR (was set with setDefaultLevel) // child3 = TRACE (was never set, so inherits the change from the parent)

Having rebuild() call setDefaultLevel() on child loggers would make child2 be at TRACE instead, and that’s where I don’t think it quite matches what setDefaultLevel() was designed to do. @pimterry what do you think about this?

This also makes it a bit ambiguous what resetLevel() should do. As coded today, calling it on the children would change child1 to TRACE and child2 would remain at ERROR. I think that’s probably fine — it resets from the persisted level to the logger’s expected level — but I can imagine people expecting it clears any level info on the logger in favor of inheriting from the parent instead.

Hmm, this is a good & complicated question. I've spent a few days twiddling at it, and I'm really not sure what's best to be honest! I can think of arguments for quite a few different behaviours here, and it's very hard to classify which is 'right' objectively.

The output you suggest is reasonable though, and we can do it with minimum impact to any other logic, so let's go that way. I can see how the default behaviour is currently odd and muddies the water, but I think there is a use case for directly controlling top-level and child default levels, and that would be hard to do independently otherwise if the parent levels could override default levels as I was proposing.

To model this, I think in effect we have three states. Either the level is set explicitly (=persisted, in our current model) or it's set as a default level, or it's an unset inherited level.

In that model, a parent set(Default)Level overrides any other level, and should be inherited by all children who are inheriting the current level when rebuilt (and potentially later this should happen automatically). Calling either setLevel or setDefaultLevel on the child should move them from 'inherited' to one of the other two states, so that future parent changes & rebuilds never affect them.

We could track that model by adding just a single extra private boolean to track this 'unset' state, similar to your hasExplicitLevel suggestion. If false, rebuild would override the level. It'd be set to true by setLevel, by setDefaultLevel, and by loading from a persisted level. resetLevel is tricky yes, but I agree that to match the current design it shouldn't unset it - effectively meaning that rebuild only ever affects loggers that have never ever been configured (which seems fine for what we're doing right here).

That would match your expected results above. It also requires nearly no changes to any other existing functionality, so we can mostly put getLevel & setDefaultLevel back as they were. The current set methods just need to add logic to set their flag to true when called.

What do you think?

That makes sense and sounds good to me. I’ll get to work on that.

OK, this should be solved. I kept getting myself twisted up in the logic with the boolean, so I wound up refactoring this as 3 private variables. LMK know if you find this too confusing and I will refactor some more, but it felt much easier to comprehend for me:

inheritedLevel is a cache of parent logger's level (or WARN for the root logger). This is always set to something valid.

defaultLevel is the default level that has been set for this logger. It may be null (unset).

userLevel is the level that has been set for this logger via persistence or via setLevel(). It may be null (unset).

The current/effective level of the logger is userLevel OR defaultLevel OR inheritedLevel.

This seemed like a more straightforward model of what’s going on, and the conceptual order of precedence is relatively obvious. There's no boolean or other state that is modifying how the levels behave based on what methods have been called in what contexts (resetLevel() was causing me subtle problems, although after the above renaming, I am pretty sure I could switch back to having the boolean and get it right this time).

The other thing worth noting here is that I opted to have child loggers reach up to their parent to get the parent’s level, where I previously had the parent updating the children’s levels. Based on the discussion here, we would have had to add a special public method for the parent to call, which seemed bad. So I flipped it around.

(Side note: since we only have one level of children right now, the children can just grab the parent level from defaultLogger. In some hypothetical future with a deep hierarchy of loggers, each logger will need to hold a reference to its parent.)

pimterry · 2024-01-10T16:29:32Z

Thanks for this! Definitely looks like the right direction. I think there's some tweaks to make but we're on the right road and I agree it'd be nice to fix this up 👍

Mr0grog · 2024-01-10T17:36:23Z

I’m also noticing that it doesn’t look like Travis is in use any longer, or at least there are no CI checks showing up on this PR. Should we add a GitHub Actions workflow since Travis doesn’t really have a free-for-open-source plan anymore?

@pimterry Just a quick re-up on the above question. Since #190 landed, I think this should be pretty easy to do (and I am happy to do the work; just let me know).

pimterry · 2024-01-11T13:20:24Z

I’m also noticing that it doesn’t look like Travis is in use any longer, or at least there are no CI checks showing up on this PR. Should we add a GitHub Actions workflow since Travis doesn’t really have a free-for-open-source plan anymore?

@pimterry Just a quick re-up on the above question. Since #190 landed, I think this should be pretty easy to do (and I am happy to do the work; just let me know).

Sorry I missed that - yes, Travis is indeed dead, I'd be extremely happy to move to GitHub Actions if you want to set that up.

This implements a new `Logger.rebuild(includeChildren)` method that does the actual work of replacing logging methods on a logger and, optionally, on child loggers. The goal is to make adding plugins (or otherwise changing the method factory) easier by giving users a way to update any child loggers that have already been declared, solving the need for careful declaration ordering as described in pimterry#187. In the ideal case, plugin developers will call this method automatically when their plugin is attached to a logger so users don't have to worry about it at all.

Fixes pimterry#187.

I rebased this work on top of pimterry#190, which means the tests now run in Jasmine 2.x, which treats error strings differently from error objects in `expect(...).toThrow(...)`, so this needed some updating.

This moves the non-recursive logic into a private method and makes the public `logger.rebuild()` method always recursive, per PR review.

See discussion in pimterry#189 (comment)

This changes the internal implementation to have three "level" variables, since I kept getting myself twisted up in knots with the idea of using a boolean. This made the logic much clearer for me: - `inheritedLevel` is the last known level from the logger's parent (or WARN for the root logger). This is always set to something valid. - `defaultLevel` is the default level that has been set for this logger. - `userLevel` is the level that has been set for this logger via persistence or via `setLevel()`. (This is similar to what was `currentLevel`, but not quite the same.) The effective level of the logger is just `userLevel OR defaultLevel OR inheritedLevel`.

Keeping these separate was unnecessarily confusing.

Mr0grog · 2024-01-23T00:06:14Z

Alright, this should be ready for another review (and maybe to land). See my replies to the previous review comments for an update on the architecture here: #189 (comment)

I added more comments, which pumps up the un-minified size a bit:

File	Before	After	Change
`loglevel.js`	9.41 KB	11.04 KB	+17.3%
`loglevel.min.js`	3.08 KB	3.26 KB	+5.9%

pimterry · 2024-01-25T18:01:08Z

Thanks, I agree that 3 variable model looks cleaner, and I'm happy this pulls together the rebuild logic without changing the existing code too significantly.

Thanks for all your hard work to make this and the other PRs happen. It's really tidied up the project and should be a great fix to help others who might be affected by #187 and similar confusion. Great stuff 👍. I'll do some last testing & checks locally and then publish a new release with these changes included soon.

Mr0grog · 2024-01-26T00:03:51Z

Awesome! 🙌

I’ll finish up with a commit that updates the contributing instructions as mentioned in #191 (comment).

This was referenced Jan 5, 2024

Why do I have to configure the log in every typescript file? #187

Closed

Update dev deps to make tests work on MacOS and resolve Critical arbitrary code execution/command injection vulnerabilities #190

Merged

pimterry requested changes Jan 10, 2024

View reviewed changes

Mr0grog force-pushed the 187-make-loggers-rebuildable branch from 8881ce9 to 4539639 Compare January 10, 2024 18:20

Mr0grog changed the title ~~Add Logger.rebuild(includeChildren) Method~~ Add Logger.rebuild() Method Jan 11, 2024

Mr0grog mentioned this pull request Jan 16, 2024

Cleanup/modernization of developer test/build tooling #191

Closed

Mr0grog added 11 commits January 22, 2024 17:52

Handle subtle issue with un-persisted levels

72f6f00

Add documentation

198a197

Fixes pimterry#187.

Also update type definitions

5eb5e5c

Update setLevel() error tests for Jasmine 2

192d445

I rebased this work on top of pimterry#190, which means the tests now run in Jasmine 2.x, which treats error strings differently from error objects in `expect(...).toThrow(...)`, so this needed some updating.

Make logger.rebuild() always recursive

7cd2f4c

This moves the non-recursive logic into a private method and makes the public `logger.rebuild()` method always recursive, per PR review.

Reset documentation around setDefaultLevel()

0bfa11a

Update tests around rebuild + setDefaultLevel

43d3164

See discussion in pimterry#189 (comment)

Add tests for resetLevel() on child loggers

1159a9d

Update docs and typings

9a6ae7c

Mr0grog force-pushed the 187-make-loggers-rebuildable branch from 4539639 to 4cd061f Compare January 22, 2024 23:23

Mr0grog added 2 commits January 22, 2024 23:38

Merge replaceLoggingMethods() and rebuildLoggingMethods()

4f15c59

Keeping these separate was unnecessarily confusing.

Remove rendundant initialization code

67e968b

pimterry approved these changes Jan 25, 2024

View reviewed changes

pimterry merged commit bd9eca0 into pimterry:master Jan 25, 2024
7 checks passed

Mr0grog deleted the 187-make-loggers-rebuildable branch January 25, 2024 23:53

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add `Logger.rebuild()` Method #189

Add `Logger.rebuild()` Method #189

Mr0grog commented Jan 5, 2024 •

edited

Mr0grog commented Jan 5, 2024

pimterry Jan 10, 2024

Mr0grog Jan 10, 2024

pimterry Jan 11, 2024

Mr0grog Jan 12, 2024 •

edited

Mr0grog Jan 12, 2024

Mr0grog Jan 15, 2024 •

edited

pimterry Jan 21, 2024

Mr0grog Jan 21, 2024

Mr0grog Jan 22, 2024

pimterry commented Jan 10, 2024

Mr0grog commented Jan 10, 2024 •

edited

pimterry commented Jan 11, 2024

Mr0grog commented Jan 23, 2024

pimterry commented Jan 25, 2024

Mr0grog commented Jan 26, 2024

	it("should not change a child's explicitly set level even if un-persisted", function(log) {
	log.setLevel("TRACE");
	var newLogger = log.getLogger("newLogger");
	newLogger.setLevel("DEBUG", false);

	log.rebuild(true);
	expect(newLogger).toBeAtLevel("DEBUG");
	});

Add Logger.rebuild() Method #189

Add Logger.rebuild() Method #189

Conversation

Mr0grog commented Jan 5, 2024 • edited

Other Notes

Mr0grog commented Jan 5, 2024

pimterry Jan 10, 2024

Choose a reason for hiding this comment

Mr0grog Jan 10, 2024

Choose a reason for hiding this comment

pimterry Jan 11, 2024

Choose a reason for hiding this comment

Mr0grog Jan 12, 2024 • edited

Choose a reason for hiding this comment

Mr0grog Jan 12, 2024

Choose a reason for hiding this comment

Mr0grog Jan 15, 2024 • edited

Choose a reason for hiding this comment

pimterry Jan 21, 2024

Choose a reason for hiding this comment

Mr0grog Jan 21, 2024

Choose a reason for hiding this comment

Mr0grog Jan 22, 2024

Choose a reason for hiding this comment

pimterry commented Jan 10, 2024

Mr0grog commented Jan 10, 2024 • edited

pimterry commented Jan 11, 2024

Mr0grog commented Jan 23, 2024

pimterry commented Jan 25, 2024

Mr0grog commented Jan 26, 2024

Add `Logger.rebuild()` Method #189

Add `Logger.rebuild()` Method #189

Mr0grog commented Jan 5, 2024 •

edited

Mr0grog Jan 12, 2024 •

edited

Mr0grog Jan 15, 2024 •

edited

Mr0grog commented Jan 10, 2024 •

edited