Description
Logger does not report correct event origin time when executing in a zone created by fake_async due to LogEvent.time defaulting to DateTime.now().
This is technically not a bug since it's fake_async that requires all code that uses DateTime.now() to use clock.now() instead to work properly and allow overriding the current notion of time. See fake_async README.
This issue can be mitigated if all Logger.log and its level counterpart invocations are supplied with time: clock.now() in consumer code, but for large code bases this would take too much time for its limited value. Given that clock is a Dart-team package that should not introduce breaking changes neither for VM nor web environments, it seems it's a change that can be done quickly without any drawbacks.
Steps to reproduce
Implement a simple printer that adds formatted event origin time to a log message, then log inside of a fake_async callback with some time elapsed:
import 'package:intl/intl.dart';
import 'package:logger/logger.dart';
import 'package:clock/clock.dart';
import 'package:fake_async/fake_async.dart';
class TimedLogPrinter extends LogPrinter {
TimedLogPrinter();
@override
List<String> log(LogEvent event) {
final formattedTime = DateFormat('HH:mm:ss.SSS').format(event.time);
return ['$formattedTime | ${event.message}'];
}
}
void main() {
final logger = Logger(printer: TimedLogPrinter());
logger.d('1');
logger.d('2');
fakeAsync((fake) {
String now() => DateFormat('HH:mm:ss.SSS').format(clock.now());
logger.d('3, clock.now(): ${now()}');
fake.elapse(const Duration(seconds: 5));
logger.d('4, clock.now(): ${now()}');
});
logger.d('5');
logger.d('6');
}Resulting output is added underneath. You can see that formatted event time and clock.now() report different time (as expected), which is still bad for tests that rely on fake_async to control time passage.
23:01:45.901 | 1
23:01:45.909 | 2
23:01:45.913 | 3, clock.now(): 23:01:45.909
23:01:45.914 | 4, clock.now(): 23:01:50.909
23:01:45.914 | 5
23:01:45.914 | 6
Description
Loggerdoes not report correct event origin time when executing in a zone created byfake_asyncdue toLogEvent.timedefaulting toDateTime.now().This is technically not a bug since it's
fake_asyncthat requires all code that usesDateTime.now()to useclock.now()instead to work properly and allow overriding the current notion of time. See fake_async README.This issue can be mitigated if all
Logger.logand its level counterpart invocations are supplied withtime: clock.now()in consumer code, but for large code bases this would take too much time for its limited value. Given thatclockis a Dart-team package that should not introduce breaking changes neither for VM nor web environments, it seems it's a change that can be done quickly without any drawbacks.Steps to reproduce
Implement a simple printer that adds formatted event origin time to a log message, then log inside of a
fake_asynccallback with some time elapsed:Resulting output is added underneath. You can see that formatted event time and
clock.now()report different time (as expected), which is still bad for tests that rely onfake_asyncto control time passage.