Concurrency Issues with Multi-Isolate Logging to a Single File

[florianguyot]

Hi,

I am working with your logger package, using a multi-output setup: ConsoleOutput + AdvancedFileOutput. My application uses multiple long-lived isolates, each setting up a logger that points to the same file output to maintain the chronology of logs.

While this setup works fine for the ConsoleOutput, logs in the FileOutput are not always populated completely (or are partially written). This issue generally occurs when a heavy log is passed or when many log events are generated across multiple isolates.
If I log into different files, there is no data loss. It seems to be caused by concurrent calls. However, the solution of having multiple log files makes analysis difficult later on, as you need to switch between multiple files to reconstitute the event.

I understand the limitations of concurrency when sharing the same resource across isolates. I wanted to check if you have experience with a setup or architecture where multiple isolates write logs into a single file.

Thanks,

[Bungeefan]

Hi!
Unfortunately, no, I haven't tried to handle simultaneous IO in different isolates yet.

Is there data loss during normal operation or only on shutdown/when terminating the isolate?
Another potential workaround could be to pass your logs back to the main isolate and log it via a single logger instance your file.

EDIT: Sorry miss-pressed, didn't intend to close it.

[dooley-ch]

It's fundamentally flawed:

• The writer does not write to the file on each call, but caches it in memory and ONLY writes the file when the instance is destroyed!
• It ALL WAYS overwrites the current file! Either with the new content or with the old content + the new content
• And as the OP discovered there is not resource management

I'm new to Dart (but with 35 years coding experience) and I have been looking for a package that does logging correctly for some time now....

[Bungeefan]

Hi @dooley-ch, thanks for your feedback.

• The writer does not write to the file on each call, but caches it in memory and ONLY writes the file when the instance is destroyed!

  This is actually an intended feature and is only included in the AdvancedFileOutput, more information about this and other features in comparison to the normal FileOutput are documented in the class documentation: https://pub.dev/documentation/logger/latest/logger/AdvancedFileOutput-class.html

• It ALL WAYS overwrites the current file! Either with the new content or with the old content + the new content

  I am not sure why you think that this happens, I rechecked the implementation and couldn't verify your claim. The following method only ever writes the output lines of the current events (+ a new line character) from the buffer and then clears it:

  void _flushBuffer() {
    if (_sink == null) return; // Wait until _sink becomes available
    for (final event in _buffer) {
      _sink?.writeAll(event.lines, Platform.isWindows ? '\r\n' : '\n');
      _sink?.writeln();
    }
    _buffer.clear();
  }

  Please enlighten me, if you think I missed something :)

• And as the OP discovered there is not resource management

  I am also not sure what you expected to find in this class, it handles its buffer and opened files just fine. Yes, there is no specific handling in case of multiple isolates/concurrent file handling, however, this package never claimed to be compatible with such use-cases (ideas and PRs are welcome!).

---

Besides that, would you also need such a concurrency feature or are just searching for a logger with a working single file output?

[Bungeefan]

Sorry @florianguyot while writing the previous response, I noticed that I missed you mentioning AdvancedFileOutput in the first line, I have only read FileOutput.
And yes, as @dooley-ch said, the advanced output itself "caches" the output lines (as intended).
Have you tried using only FileOutput (not AdvancedFileOutput) instead?

Notice: The sinks would still not "flush" instantly, as this would require awaiting async code in between log calls.
However, since flush() just returns the _pendingWrites future, the flush should already be handled in the background (provided an empty event queue/microtask queue) without manual intervention.
And when having multiple sinks concurrently writing to the same file (even when correctly flushed), the file system flush could still be impacted/delayed by the operating system.

The only real way to fix it this, would be to share the same sink between all instances (like having one global logger and passing the log events back to the main isolate).

[florianguyot]

@Bungeefan, thank you for your answer and support. I did not send you a message earlier because I wanted to have a minimal reproducible snippet to demonstrate the behavior.

I have tried both FileOutput and AdvancedFileOutput, but the result is the same. If the logger becomes noisy in two different isolates or has a long message to write to the file, I often get a message that is partially written in the output file. I think this is due to accessing to the same resource through 2 different isolates.

The only real way to fix this would be to share the same sink between all instances (like having one global logger and passing the log events back to the main isolate).

I was thinking about that—having a either a logger event back to the main isolate or an "isolate logger" where all logs are redirected to ensure only instance manipulates the log file. However, this would require some work on my side, and I wanted to double-check if you have an alternative solution.

I am a bit overwhelmed right now to work on this, but if I have an example code to show this, I will respond to this thread.

In the meantime, if you want to clear your backlog by closing this issue, I am fine with it.

Thanks again for your support.

[dooley-ch]

To follow up on this:

The entire purpose of logging is to be able to figure out what went wrong when bad things happen....

The problem with physical files is just that - they are physical and resource management is key to ensure they will not get corrupt. This package is caching data and not cleaning up until it is destroyed. That means that if the scaffolding get's kicked out before hand, you end up with a useless log. For instance set a break point, edit the physical flag, let the app run it's course and you will not end up with a complete log.

If you are going to write to log files in a Dart app without using isolates, you are probably going to do something like this:

  @override
  Future<void> writeLog({required OutputRecord outputRecord}) async {
    final lock = Lock();

    await lock.synchronized(() async {
      var file = io.File(_fileName);

      for (var line in outputRecord.lines) {
        await file.writeAsString('$line$_endOfLine',
            mode: io.FileMode.append, flush: true);
      }
    });
  }

Just to ensure the data is written to the file. This is still not going to address out of sync messages, but I suspect given the way the message queue is handled in the Dart VM there is a low probability of this happening. An it would probably also need to be checked for reentry code.

Concerning Isolates, it is nothing more than an old technique we used 30+ years ago, before we had languages that kind of supported multi threading - just spinning off multiple instances and communicating over a pipe. Which makes the challenges of trying to do resource management greater as the only realistic way would be system mutexes. and as far as I can see they are not natively supported. And even if they were you'd be creating a system wide lock every time.

I suspect you could put an awful lot of time into and still not have a very stable solution. In such circumstances it would probably be better to writhe to a database, a message or a service API of some type.