"The method 'isRequired' was called on null" on subsequent runs with daemon

[DanTup]

Using latest code (running spinning_square) I see crashes for any run that's not the first run. eg.:

• Run project (works)
• Close browser
• Run project (crashes)

If I clear the .dart_tool folder then it works again, once. Then fails on the next run.

GET /web/main.dart.js
Error thrown by handler.
NoSuchMethodError: The method 'isRequired' was called on null.
Receiver: null
Tried calling: isRequired(Instance of 'AssetId')
dart:core                                                        Object.noSuchMethod
FinalizedReader.unreadableReason
===== asynchronous gap ===========================
AssetHandler.handle
dart:async                                                       _completeOnAsyncReturn
package:build_runner/src/daemon/asset_server.dart                AssetServer.run.<fn>

I'm using 2.0.0 webdev and the latest code for spinning_square.

[jakemac53]

Ok, so part of the problem I think is that the daemon doesn't shut down until all vm service clients disconnect - we should be forcibly closing those connections.

[jakemac53]

Based on the stack trace it looks like we haven't ran a build yet, in that case the FinalizedAssetReader._optionalOutputsTracker is null (it doesn't get set until the first build).

[DanTup]

I think this is a new issue - I was just running my automated tests for web, and all but the first fail with this issue, but when I wrote them a few weeks ago I'm sure that wasn't the case.

I see #332 mentions this issue, so I'll do some testing with that code to see if it changes anything.

[DanTup]

The change above didn't fix the issue. The message from the title is gone, however it's still failing:

[1:47:27 PM]: PID: 38263
[1:47:29 PM]: <== [{"event":"daemon.connected","params":{"version":"0.4.2","pid":38336}}]
[1:47:29 PM]: <== [{"event":"daemon.log","params":{"log":"Connecting to the build daemon..."}}]
[1:47:30 PM]: <== [{"event":"daemon.log","params":{"log":"Generating build script..."}}]
[1:47:30 PM]: <== [{"event":"daemon.log","params":{"log":"Generating build script completed, took 350ms"}}]
[1:47:30 PM]: <== [{"event":"daemon.log","params":{"log":""}}]
[1:47:30 PM]: <== [{"event":"daemon.log","params":{"log":"Starting daemon..."}}]
[1:47:32 PM]: <== [{"event":"daemon.log","params":{"log":"BuildDefinition: Initializing inputs"}}]
[1:47:32 PM]: <== [{"event":"daemon.log","params":{"log":"BuildDefinition: Reading cached asset graph..."}}]
[1:47:32 PM]: <== [{"event":"daemon.log","params":{"log":"BuildDefinition: Reading cached asset graph completed, took 301ms"}}]
[1:47:32 PM]: <== [{"event":"daemon.log","params":{"log":""}}]
[1:47:32 PM]: <== [{"event":"daemon.log","params":{"log":"BuildDefinition: Checking for updates since last build..."}}]
[1:47:32 PM]: <== [{"event":"daemon.log","params":{"log":"BuildDefinition: Checking for updates since last build completed, took 828ms"}}]
[1:47:32 PM]: <== [{"event":"daemon.log","params":{"log":""}}]
[1:47:32 PM]: <== [{"event":"daemon.log","params":{"log":"build_runner: Setting up file watchers..."}}]
[1:47:32 PM]: <== [{"event":"daemon.log","params":{"log":"build_runner: Setting up file watchers completed, took 3ms"}}]
[1:47:32 PM]: <== [{"event":"daemon.log","params":{"log":""}}]
[1:47:32 PM]: <== [{"event":"daemon.log","params":{"log":"Registering build targets..."}}]
[1:47:32 PM]: <== [{"event":"daemon.log","params":{"log":"Starting initial build..."}}]
[1:47:32 PM]: <== [{"event":"daemon.log","params":{"log":"Serving DevTools at http://localhost:60170\n"}}]
[1:47:32 PM]: <== [{"event":"daemon.log","params":{"log":"Starting resource servers..."}}]
[1:47:32 PM]: <== [{"event":"daemon.log","params":{"log":"Serving `web` on http://localhost:60165\n"}}]
[1:47:32 PM]: <== [{"event":"daemon.log","params":{"log":"About to build [web]..."}}]
[1:47:32 PM]: <== [{"event":"daemon.log","params":{"log":"Build: Running build..."}}]
[1:47:33 PM]: <== [{"event":"daemon.log","params":{"log":"Build: Running build completed, took 300ms\n"}}]
[1:47:33 PM]: <== [{"event":"daemon.log","params":{"log":"Build: Caching finalized dependency graph..."}}]
[1:47:33 PM]: <== [{"event":"daemon.log","params":{"log":"Build: Caching finalized dependency graph completed, took 302ms\n"}}]
[1:47:33 PM]: <== [{"event":"daemon.log","params":{"log":"Build: Succeeded after 618ms with 0 outputs (0 actions)\n"}}]
[1:47:34 PM]: Unhandled exception:
[1:47:34 PM]: Bad state: No element
#0      Stream.firstWhere.<anonymous closure> (dart:async/stream.dart:1309:13)
#1      _RootZone.runGuarded (dart:async/zone.dart:1302:10)
#2      _BufferingStreamSubscription._sendDone.sendDone (dart:async/stream_impl.dart:389:13)
#3      _BufferingStreamSubscription._sendDone (dart:async/stream_impl.dart:399:15)
#4      _BufferingStreamSubscription._close (dart:async/stream_impl.dart:283:7)
#5      _SinkTransformerStreamSubscription._close (dart:async/stream_transformers.dart:96:11)
#6      _EventSinkWrapper.close (dart:async/stream_transformers.dart:23:11)
#7      _StringAdapterSink.close (dart:convert/string_conversion.dart:249:11)
#8      _LineSplitterSink.close (dart:convert/line_splitter.dart:134:11)
#9      _SinkTransformerStreamSubscription._handleDone (dart:async/stream_transformers.dart:141:24)
#10     _RootZone.runGuarded (dart:async/zone.dart:1302:10)
#11     _BufferingStreamSubscription._sendDone.sendDone (dart:async/stream_impl.dart:389:13)
#12     _BufferingStreamSubscription._sendDone (dart:async/stream_impl.dart:399:15)
#13     _BufferingStreamSubscription._close (dart:async/stream_impl.dart:283:7)
#14     _SinkTransformerStreamSubscription._close (dart:async/stream_transformers.dart:96:11)
#15     _EventSinkWrapper.close (dart:async/stream_transformers.dart:23:11)
#16     _StringAdapterSink.close (dart:convert/string_conversion.dart:249:11)
#17     _Utf8ConversionSink.close (dart:convert/string_conversion.dart:300:20)
#18     _ConverterStreamEventSink.close (dart:convert/chunked_conversion.dart:80:18)
#19     _SinkTransformerStreamSubscription._handleDone (dart:async/stream_transformers.dart:141:24)
#20     _RootZone.runGuarded (dart:async/zone.dart:1302:10)
#21     _BufferingStreamSubscription._sendDone.sendDone (dart:async/stream_impl.dart:389:13)
#22     _BufferingStreamSubscription._sendDone (dart:async/stream_impl.dart:399:15)
#23     _BufferingStreamSubscription._close (dart:async/stream_impl.dart:283:7)
#24     _SyncStreamController._sendDone (dart:async/stream_controller.dart:772:19)
#25     _StreamController._closeUnchecked (dart:async/stream_controller.dart:629:7)
#26     _StreamController.close (dart:async/stream_controller.dart:622:5)
#27     _Socket._onData (dart:io-patch/socket_patch.dart:1781:21)
#28     _RootZone.runUnaryGuarded (dart:async/zone.dart:1314:10)
#29     _BufferingStreamSubscription._sendData (dart:async/stream_impl.dart:336:11)
#30     _BufferingStreamSubscription._add (dart:async/stream_impl.dart:263:7)
#31     _SyncStreamController._sendData (dart:async/stream_controller.dart:764:19)
#32     _StreamController._add (dart:async/stream_controller.dart:640:7)
#33     _StreamController.add (dart:async/stream_controller.dart:586:5)
#34     new _RawSocket.<anonymous closure> (dart:io-patch/socket_patch.dart:1330:35)
#35     _NativeSocket.issueReadEvent.issue (dart:io-patch/socket_patch.dart:837:18)
#36     _microtaskLoop (dart:async/schedule_microtask.dart:41:21)
#37     _startMicrotaskLoop (dart:async/schedule_microtask.dart:50:5)
#38     _runPendingImmediateCallback (dart:isolate-patch/isolate_patch.dart:115:13)
#39     _RawReceivePortImpl._handleMessage (dart:isolate-patch/isolate_patch.dart:172:5)

[DanTup]

@jakemac53 ok I did more digging and eventually found that the cause of the "browser not shutting down" but (which I think is related to this) is because in the debugger when we see app.stop come from the daemon, we run some code that eventually does:

if (!this.processExited && this.process && !this.process.killed)
	this.process.kill();

In this instance, this.process is a handle to the shell (we always spawn with a shell, because on Windows it's the only way to run pub.bat) and the kill() command sends SIGTERM by default.

So, I believe the issue is that during shutdown, if we send SIGTERM to the shell process, the daemon is not shutting down cleanly (but maybe immediately terminating). I wonder if this is default Dart behaviour, but we don't see it in Flutter because Flutter listens for that signal and handles it itself.

My understanding is that SIGTERM is a polite way of asking a process to shutdown, so I think maybe the daemon should handle it and still shutdown gracefully?

If I comment that line out, the browser closes as expected when I click the X in the tab, like it did when I launched it from the terminal - unfortunately skipping that code is tricky, since it's in a dispose() that may be called for other reasons (like failure cases) and I don't want to risk leaving processes around (something we're still not 100% reliably with). Of course, sending SIGTERM doesn't guarantee it'll terminate either, but it's better than nothing :-)

[jakemac53]

I think that @grouma saw this error yesterday as well - unfortunately its quite difficult to understand where it is coming from.

We could trap SIGTERM signals (build_runner does this).

[DanTup]

Yeah, I think it will fix #300 (comment) too. We're sending a SIGTERM to request a shutdown, but the VM is just terminating immediately because you don't have a handler. Having SIGTERM trigger (or wait for) a graceful shutdown I think is the correct fix :-)

[grouma]

I'll take a look at this today. We have similar logic in package:build_daemon as well to handle graceful shutdowns.

[grouma]

Found the root cause. This was a fun one. I made a change recently to not clean up the dataDir so that settings can be preserved between runs: https://github.com/dart-lang/webdev/pull/322/files

As a result of this, when starting Chrome a previous instance can be reused and we therefore never get the log message that Chrome DevTools is listening.

I have a few ideas on how to work around this. Worst case I'll revert the change.