Rework LogFilter.level

[Levi-Lesches]

This is the cause of a pretty weird bug:

final filter = ProductionFilter();
final logger = Logger(filter: filter);

void main() {
  filter.level = Level.warning;
  logger.i("This is an info message and should not show");  // it shows
}

Took me a while to isolate the problem, but it is because logger is lazily evaluated:

class MyFilter extends LogFilter {
	Level _level = Level.info;
	@override Level get level => _level;	
	@override set level(Level? value) {
		print("Setting log level to $value");
		_level = value ?? Level.info;
	}

	@override	
	bool shouldLog(LogEvent event) => event.level.index >= level.index;
}

final filter = MyFilter();
final logger = Logger(filter: filter, printer: SimplePrinter())..toString();

void main() {
  filter.level = Level.warning;
  logger.i("This is an info message and should not show");  // it shows
}
 // Output: 
 // Setting level to warning
// Setting level to verbose
// [I] This is an info message and should not show

Turns out, when logger is accessed for the first time, its constructor sets filter.level = Logger.level, overriding any previous assignment. This should be removed so we can configure the log level of a global logger

[Bungeefan]

Hi, it is currently not intended to set the level of a filter manually, you should use the constructor parameter of the logger to set your initial level!
Just removing the assignment in the constructor would break the library and the default level behavior.
Because then no level would be set for the filter, and we cannot rely on the user to hopefully set a level.

However, if you have ideas for restructuring the relationship between Logger and its Filter, feel free to propose them!

[Levi-Lesches]

So how would I change the log level after the code has begun? Eg, I have a function that usually logs a lot, but I want to suppress it once, so I set the log level to warning, run the function, then reset it back to info.

However, if you have ideas for restructuring the relationship between Logger and its Filter, feel free to propose them!

Perhaps the default LogFilters should compare directly against Logger.level, instead of instance-level variables? I made a custom workaround that does that and it works pretty well:

class MyLogger {
  static Level level = Level.info;
}

class MyFilter extends LogFilter {
  @override
  bool shouldLog(LogEvent event) => event.level.index >= MyLogger.level.index;
}

From what I can tell in the code, LogFilter.level is hardly if ever used, because it's immediately overwritten to Logger.level and Logger._filter is private so you can't even set it at the instance level. There's essentially one global setting so it should be safe to use Logger.level directly.

[Bungeefan]

You should be able to change the level of your filter just fine after the logger has been created.

Perhaps the default LogFilters should compare directly against Logger.level, instead of instance-level variables? I made a custom workaround that does that and it works pretty well:

This only works because you statically referenced your single logger instance, however, this can't be applied to other filters, as already mentioned, filters don't know their loggers, and it should be possible to use multiple loggers without sharing the same level.

Logger._filter is private so you can't even set it at the instance level.

True, but you can save your filter reference and use that to modify it after the creation.
But I am with you, this isn't an elegant way.

[Levi-Lesches]

You should be able to change the level of your filter just fine after the logger has been created.
True, but you can save your filter reference and use that to modify it after the creation.

But due to this bug, I can't. I used to have a global variable final logFilter = ProductionFilter(); and then set logFilter.level, but because of this bug, simply calling logger.i overwrites whatever level I have already set (because the final variable is lazily evaluated, and the Logger constructor overwrites LogFilter.level):

logger/lib/src/logger.dart

Lines 88 to 105 in 84c1668

	/// Create a new instance of Logger.
	///
	/// You can provide a custom [printer], [filter] and [output]. Otherwise the
	/// defaults: [PrettyPrinter], [DevelopmentFilter] and [ConsoleOutput] will be
	/// used.
	Logger({
	LogFilter? filter,
	LogPrinter? printer,
	LogOutput? output,
	Level? level,
	}) : _filter = filter ?? defaultFilter(),
	_printer = printer ?? defaultPrinter(),
	_output = output ?? defaultOutput() {
	_filter.init();
	_filter.level = level ?? Logger.level;
	_printer.init();
	_output.init();
	}

Deleting _filter.level = level ?? Logger.level; seems to be the only way to prevent this bug.

This only works because you statically referenced your single logger instance, however, this can't be applied to other filters, as already mentioned, filters don't know their loggers, and it should be possible to use multiple loggers without sharing the same level.

Fully agree here, my use of Logger.level was just to work around this bug.

[Bungeefan]

The logger doesn't overwrite anything on your filter while logging, this is only set when creating the logger, hence, the constructor parameter.

Are you sure your logger field isn't static or late? AFAIK, Dart doesn't lazily initialize member fields.
However, as a possible workaround, you could access the logger field once before doing any actual code, to force its initialization and therefore the level assignment.

And as I said, I can't just remove the assignment, as this would currently break a lot of code.

[Levi-Lesches]

It's a final global variable, which also has the lazy behavior, unfortunately.

I definitely agree that it would be bad to break current code. I was thinking removing that line wouldn't if you made another change

Currently, ProductionFilter.shouldLog checks against level!.index, asserting that the nullable value has already been set to Logger.level. What if, you instead do level ?? Logger.level? That way, if the value has been externally overriden, it will keep it's value, and if not, will be treated with the same behavior as today.

[Bungeefan]

https://dart.dev/language/variables#default-value

Top-level and class variables are lazily initialized; the initialization code runs the first time the variable is used.

---

You are right, I didn't know that a global final field would be lazily initialized, bummer.
However, accessing it once directly after declaring it should fix your problem, at least for now.

Currently, ProductionFilter.shouldLog checks against level!.index, asserting that the nullable value has already been set to Logger.level. What if, you instead do level ?? Logger.level? That way, if the value has been externally overriden, it will keep it's value, and if not, will be treated with the same behavior as today.

This would work for this filter, but how about all the custom filters that people are using in their code and are currently relying on the logger constructor to set their level to a non-null value, the same way Production and DevelopmentFilter are relying on it? This would still break those filters.

I know you want an easy fix especially because it looks easy to fix, but in this case I can't easily change something without risking people's code breaking in a way that isn't obvious (for example, in opposite to a method signature change).

Currently, there is an issue that plans to rework the whole relationships, and we can probably use it to implement a better solution for this. (#5)

[Bungeefan]

However, we could probably change the field to a getter and in this getter check for Logger.level.
I'll check that as soon as I have some time.

[Bungeefan]

@Levi-Lesches Sorry for the long delay, I finally put my idea into code, can you please check if this works for you?
You can use the following in your pubspec.yaml to test it:

dependency_overrides:
  logger:
    git:
      url: https://github.com/SourceHorizon/logger

[Levi-Lesches]

Nice!

import "package:logger/logger.dart";

final logger = Logger(filter: ProductionFilter(), printer: SimplePrinter());

void main() {
  Logger.level = Level.warning;
  logger.i("This should not show");
  Logger.level = Level.info;
  logger.i("This will show");
}

Output:

[I]  This will show

[Bungeefan]

Great, thanks!
I am going to release a patch update soon.

Additionally, I would like to keep this issue open for the greater rework that I am planning, as the current state is still not great. 👍

[Bungeefan]

@Levi-Lesches 2.0.2 has been successfully published!

[shovelmn12]

I'd say level shuold be part of LogFilter and not a separate field.

Logger(filter: LogFilter(level: Level.warning));