Random Access Dart Failures

There was a new release of Dart yesterday. Everything broke.

I so desperately want to check to see if the new release contains something that I have been nearly aching for… but I have to fix those builds first.

The drone.io service continues to be outstanding. Every time there is a minor update to Dart, drone.io runs all of my builds. Normally this results in all of the builds continuing to pass or, on occasion, just one of the builds failing. After yesterday's update, all but one of my builds is failing:



I don't know why, but my first instinct is that the failures are all caused by some common technique that I inadvertently used in each of those. In fact, when I check the actual failures, I do find something common—an exception along the lines of:

Uncaught Error: FileException: An async operation is currently pending, path = test.db
Unhandled exception:
FileException: An async operation is currently pending, path = test.db
...

It does not take too long to track this error down a breaking commit in Dart itself with a very hard-to-argue-with description: “Only allow one async operation on RandomAccessFile at a time.” So it would seem that something in a common package of mine, dart dirty, is violating this rule.

After installing the latest and greatest version of Dart, I am able to reproduce the problem in my dart-dirty tests:

➜  dart-dirty git:(master) ✗ ./test/run.sh
unittest-suite-wait-for-done
Uncaught Error: FileException: An async operation is currently pending, path = test/test.db
Unhandled exception:
FileException: An async operation is currently pending, path = test/test.db
#0      _rootHandleUncaughtError.<anonymous closure> (dart:async/zone.dart:526)
#1      _asyncRunCallback (dart:async/event_loop.dart:18)
#2      _asyncRunCallback (dart:async/event_loop.dart:21)
#3      _createTimer.<anonymous closure> (dart:async-patch/timer_patch.dart:11)
#4      _Timer._createTimerHandler._handleTimeout (timer_impl.dart:151)
#5      _Timer._createTimerHandler._handleTimeout (timer_impl.dart:159)
#6      _Timer._createTimerHandler._handleTimeout (timer_impl.dart:159)
#7      _Timer._createTimerHandler.<anonymous closure> (timer_impl.dart:168)
#8      _ReceivePortImpl._handleMessage (dart:isolate-patch/isolate_patch.dart:113)

Wow. That stack trace is completely useless. It contains no mention of either my code or the package in Dart that is actually throwing that error. For now, it looks like I am back to print-stderr to try to track down where the exception is coming from. That is a bummer.

Actually, it's more than a bummer—even print-stderr fails me in this case. The error is thrown when an async operation is performed while another is already in motion. It does me no good to find the operation that is called to throw the error (it turns out to be a call to the close() method). I need to find the operation that is in motion when the close() method is invoked.

And for the life of me, I cannot think of a way to do this other than commenting out io-related methods. Using this “technique,” I am able to track the problem down the dart-dirty's flush() method:

  _flush() {
    _flushing = true;

    _queue.forEach((key) {
      String doc = JSON.stringify({'key': key, 'val': _docs[key]});
      // _io.writeString("$doc\n");
    });

    // _io.flush();
    _queue.clear();

    _flushing = false;
  }

If I comment out both operations on the RandomAccessFile variable _io, then my tests pass. Well, not quite pass since most of the tests depend on flush() to write data to the actual file, but at least the test failure message changes.

I hate to do this, but, to fix the errors, I change both the writeString() and flush() methods calls to their synchronous versions:

  _flush() {
    _flushing = true;

    _queue.forEach((key) {
      String doc = JSON.stringify({'key': key, 'val': _docs[key]});
      _io.writeStringSync("$doc\n");
    });

    _io.flushSync();
    _queue.clear();

    _flushing = false;
  }

I hate to make that change because it will impact performance. Before this change, I had Dart tell the OS to write newline-terminated strings and flush() the changes to the disk to persist data. If the write did not happen instantaneously, it was no big deal because the records were still persisted in memory. The flush() was a convenient, when-the-OS-has-time way to persist data to the file system without blocking. Now it blocks.

On the other hand, I have no performance tests currently written (it's a TODO in this project). And, if I am not testing it, then I cannot claim that it really, really is faster with the old asynchronous version of the code. What I can say is that the code is now working:

➜  dart-dirty git:(master) ✗ ./test/run.sh
unittest-suite-wait-for-done
PASS: new DBs creates a new DB
PASS: writing can write a record to the DB
PASS: reading can read a record from the DB
PASS: reading can read a record from the DB stored on the filesystem
PASS: removing can remove a record from the DB
PASS: removing can remove keys from the DB
PASS: removing can remove a record from the filesystem store
PASS: removing removes from the list of keys in the filesystem store
PASS: removing can delete the DB entirely from the filesystem

All 9 tests passed.
unittest-suite-success

dartanalyzer lib/dirty.dart
Analyzing lib/dirty.dart...
No issues found

And working code trumps fast code every single time.

With that fixed, I update dart-dirty's pubspec.yaml to depend on the latest and greatest version of the json package (so that it is mostly likely to work with recent Darts):

name: dirty
version: 0.1.2
description: Dart Dirty is a persistent, server-side HashMap - a dirt simple nosql DB.
author: Chris Strom <chris@eeecomputes.com>
homepage: https://github.com/eee-c/dart-dirty
dependencies:
  json: ">=0.8.1 <0.8.2"
dev_dependencies:
  unittest: any

I pub lish that to Dart Pub:

➜  dart-dirty git:(master) pub lish
Publishing "dirty" 0.1.2 to https://pub.dartlang.org:
|-- .gitignore
|-- LICENSE
|-- README.md
|-- lib
|   '-- dirty.dart
|-- pubspec.yaml
'-- test
    |-- dirty_test.dart
    |-- mk_perf_db.dart
    |-- perf.dart
    '-- run.sh

Looks great! Are you ready to upload your package (y/n)? y
Uploading........
dirty 0.1.2 uploaded successfully.

After going through similar step to update the dependencies in my other packages, I am back to mostly green on drone.io:



It would be all green if not for that pesky ICE Code Editor build. That build continues to fail because of something that has been missing from Dart for more than a month now. It has been slowly driving me mad. But maybe, just maybe… it is fixed now. And I'll try that tomorrow.


Day #899

‹prev | My Chain | next›