AdvancedFileOutput causes StateError

[sap1tz]

Hi,

I've recently started integrating the AdvancedFileOutput into a project. While testing, I noticed that it sometimes throws a StateError. This occurs more or less at random. However, I think I've traced it down to a race condition where the buffer is flushed while the log file is being rotated, or vice versa.

Bad state: StreamSink is bound to a stream
#0      _StreamSinkImpl._controller (dart:io/io_sink.dart:238:7)
#1      _StreamSinkImpl.add (dart:io/io_sink.dart:155:5)
#2      _IOSinkImpl.write (dart:io/io_sink.dart:296:5)
#3      _IOSinkImpl.writeAll (dart:io/io_sink.dart:307:7)
#4      AdvancedFileOutput._flushBuffer (package:logger/src/outputs/advanced_file_output.dart:183:14)
#5      AdvancedFileOutput.output (package:logger/src/outputs/advanced_file_output.dart:176:7)
#6      MultiOutput.output (package:logger/src/outputs/multi_output.dart:34:9)
#7      Logger.log (package:logger/src/logger.dart:196:19)
#8      Logger.i (package:logger/src/logger.dart:109:5)

I created an example that reproduces the issue quite regularly:

import 'package:logger/logger.dart';

void main(List<String> arguments) async {
  final logger = Logger(
    printer: PrettyPrinter(),
    output: MultiOutput([
      AdvancedFileOutput(
        path: "output",
        maxBufferSize: 100,
        maxRotatedFilesCount: 5,
        fileUpdateDuration: Duration(seconds: 1),
      ),
    ]),
  );

  await logger.init;

  while (true) {
    await Future.delayed(Duration(milliseconds: 100));
    for (int i = 0; i < 10000; i++) {
      logger.i("Just another info");
    }
  }

  await logger.close();
}

If my assumption is correct, rewriting _closeSink() like this could resolve the issue. It worked in my tests, at least.

Future<void> _closeSink() async {
  if (fileFooter != null) {
    _sink?.writeln(fileFooter);
  }

  final sink = _sink;
  _sink = null;

  await sink?.flush();
  await sink?.close();
}

I would be happy to hear any thoughts on this 😊

[Bungeefan]

Hi, thanks for bringing this to my attention!

I was able to reproduce the error and successfully applied your fix.
I even researched if there are better ways to handle such cases, but this seems to be the simplest, most effective solution to prevent such a race (at least for now), thanks!

The fix has been released in v2.6.1 (now on pub.dev).

[shaopx]

In fact, I can still use the above test code to trigger write exceptions. Although it's no longer a state-related issue, on some Windows machines with poor disk performance, it's quite easy to encounter file locking problems. Specifically, the flush operation that writes to the file can conflict with the file renaming operation, resulting in failure.

[Bungeefan]

Hi @shaopx, can you please provide the exception you are getting and how you can reliably reproduce them?
I don't really have a Windows machine with poor disk performance available.