dart-lang / sdk

The Dart SDK, including the VM, JS and Wasm compilers, analysis, core libraries, and more.
https://dart.dev
BSD 3-Clause "New" or "Revised" License
10.21k stars 1.57k forks source link

Is there anything that can be done to make this stack trace more helpful? #37554

Open MichaelRFairhurst opened 5 years ago

MichaelRFairhurst commented 5 years ago

We're running into a p1/p0 issue on analyzer that has a stack trace which is almost 100% useless to us.

Exception
Dart analysis server, SDK version 2.3.3-dev.0.0, server version 1.27.1, FATAL error: Bad state: No element
#0      Stream.firstWhere. (dart:async/stream.dart:1327: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      _SyncBroadcastStreamController._sendDone. (dart:async/broadcast_stream_controller.dart:397:22)
#6      _BroadcastStreamController._forEachListener (dart:async/broadcast_stream_controller.dart:324:15)
#7      _SyncBroadcastStreamController._sendDone (dart:async/broadcast_stream_controller.dart:396:7)
#8      _BroadcastStreamController.close (dart:async/broadcast_stream_controller.dart:272:5)
#9      _AsBroadcastStreamController.close (dart:async/broadcast_stream_controller.dart:498:27)
#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     _ForwardingStream._handleDone (dart:async/stream_pipe.dart:106:10)
#15     _ForwardingStreamSubscription._handleDone (dart:async/stream_pipe.dart:172:13)
#16     _RootZone.runGuarded (dart:async/zone.dart:1302:10)
#17     _BufferingStreamSubscription._sendDone.sendDone (dart:async/stream_impl.dart:389:13)
#18     _BufferingStreamSubscription._sendDone (dart:async/stream_impl.dart:399:15)
#19     _BufferingStreamSubscription._close (dart:async/stream_impl.dart:283:7)
#20     _ForwardingStream._handleDone (dart:async/stream_pipe.dart:106:10)
#21     _ForwardingStreamSubscription._handleDone (dart:async/stream_pipe.dart:172:13)
#22     _RootZone.runGuarded (dart:async/zone.dart:1302:10)
#23     _BufferingStreamSubscription._sendDone.sendDone (dart:async/stream_impl.dart:389:13)
#24     _BufferingStreamSubscription._sendDone (dart:async/stream_impl.dart:399:15)
#25     _BufferingStreamSubscription._close (dart:async/stream_impl.dart:283:7)
#26     _SinkTransformerStreamSubscription._close (dart:async/stream_transformers.dart:96:11)
#27     _EventSinkWrapper.close (dart:async/stream_transformers.dart:23:11)
#28     _StringAdapterSink.close (dart:convert/string_conversion.dart:249:11)
#29     _LineSplitterSink.close (dart:convert/line_splitter.dart:134:11)
#30     _SinkTransformerStreamSubscription._handleDone (dart:async/stream_transformers.dart:141:24)
#31     _RootZone.runGuarded (dart:async/zone.dart:1302:10)
#32     _BufferingStreamSubscription._sendDone.sendDone (dart:async/stream_impl.dart:389:13)
#33     _BufferingStreamSubscription._sendDone (dart:async/stream_impl.dart:399:15)
#34     _BufferingStreamSubscription._close (dart:async/stream_impl.dart:283:7)
#35     _SinkTransformerStreamSubscription._close (dart:async/stream_transformers.dart:96:11)
#36     _EventSinkWrapper.close (dart:async/stream_transformers.dart:23:11)
#37     _StringAdapterSink.close (dart:convert/string_conversion.dart:249:11)
#38     _Utf8ConversionSink.close (dart:convert/string_conversion.dart:300:20)
#39     _ConverterStreamEventSink.close (dart:convert/chunked_conversion.dart:80:18)
#40     _SinkTransformerStreamSubscription._handleDone (dart:async/stream_transformers.dart:141:24)
#41     _RootZone.runGuarded (dart:async/zone.dart:1302:10)
#42     _BufferingStreamSubscription._sendDone.sendDone (dart:async/stream_impl.dart:389:13)
#43     _BufferingStreamSubscription._sendDone (dart:async/stream_impl.dart:399:15)
#44     _BufferingStreamSubscription._close (dart:async/stream_impl.dart:283:7)
#45     _SyncStreamController._sendDone (dart:async/stream_controller.dart:772:19)
#46     _StreamController._closeUnchecked (dart:async/stream_controller.dart:629:7)
#47     _StreamController.close (dart:async/stream_controller.dart:622:5)
#48     _Socket._onData (dart:io-patch/socket_patch.dart:1793:21)
#49     _RootZone.runUnaryGuarded (dart:async/zone.dart:1314:10)
#50     _BufferingStreamSubscription._sendData (dart:async/stream_impl.dart:336:11)
#51     _BufferingStreamSubscription._add (dart:async/stream_impl.dart:263:7)
#52     _SyncStreamController._sendData (dart:async/stream_controller.dart:764:19)
#53     _StreamController._add (dart:async/stream_controller.dart:640:7)
#54     _StreamController.add (dart:async/stream_controller.dart:586:5)
#55     new _RawSocket. (dart:io-patch/socket_patch.dart:1342:35)
#56     _NativeSocket.issueReadEvent.issue (dart:io-patch/socket_patch.dart:849:18)
#57     _microtaskLoop (dart:async/schedule_microtask.dart:41:21)
#58     _startMicrotaskLoop (dart:async/schedule_microtask.dart:50:5)
#59     _runPendingImmediateCallback (dart:isolate-patch/isolate_patch.dart:116:13)
#60     _RawReceivePortImpl._handleMessage (dart:isolate-patch/isolate_patch.dart:173:5)

While we're trying to get inventive in diagnosing what could be causing this, the thought occurred to me, could the stack trace be improved in theory?

I know there was a lot of work done around async/await recently to improve stack traces. That was super useful, and I think there are more cases like that where it could be a really high impact if we could somehow improve stack traces more.

I know that this is a hard problem. Is there a clever solution?

MichaelRFairhurst commented 5 years ago

Thanks @sjindel-google for the title change :)

I was not trying to be negative as much as frank & funny but tone does not come across in titles and I much prefer your title to mine :)

MichaelRFairhurst commented 5 years ago

(perhaps partly influenced by my recent usage of "suck-less tools")

rmacnak-google commented 5 years ago

--causal-async-stack is the flag the gives better traces when using async await. But that is on by default, and unfortunately it looks like this error happens in a place this is using streams directly, so I don't think it will help here. To debug this, I suggest running the analyzer with the VM set to pause on exceptions, then navigate to the stream object in the top frame that is experiencing the state error, then use the "inbound references" tool to see where else in the program that stream is referenced to hopeful to find the stream's producer and consumer. The top frame should also contain the closure doing the stream filtering as a local variable, and hopefully that closure is code in the analyzer instead of some internal wrapper.

lrhn commented 5 years ago

With the available information (which is everything shown in the stack trace), you cannot add more, so let's see what we can take away.

I tried removing all references to private functions and methods, but not private classes (because that would be everything):

Exception
Dart analysis server, SDK version 2.3.3-dev.0.0, server version 1.27.1, FATAL error: Bad state: No element
#0      Stream.firstWhere. (dart:async/stream.dart:1327:13)
#1      _RootZone.runGuarded (dart:async/zone.dart:1302:10)
#8      _BroadcastStreamController.close (dart:async/broadcast_stream_controller.dart:272:5)
#9      _AsBroadcastStreamController.close (dart:async/broadcast_stream_controller.dart:498:27)
#10     _RootZone.runGuarded (dart:async/zone.dart:1302:10)
#16     _RootZone.runGuarded (dart:async/zone.dart:1302:10)
#22     _RootZone.runGuarded (dart:async/zone.dart:1302:10)
#27     _EventSinkWrapper.close (dart:async/stream_transformers.dart:23:11)
#28     _StringAdapterSink.close (dart:convert/string_conversion.dart:249:11)
#29     _LineSplitterSink.close (dart:convert/line_splitter.dart:134:11)
#31     _RootZone.runGuarded (dart:async/zone.dart:1302:10)
#36     _EventSinkWrapper.close (dart:async/stream_transformers.dart:23:11)
#37     _StringAdapterSink.close (dart:convert/string_conversion.dart:249:11)
#38     _Utf8ConversionSink.close (dart:convert/string_conversion.dart:300:20)
#39     _ConverterStreamEventSink.close (dart:convert/chunked_conversion.dart:80:18)
#41     _RootZone.runGuarded (dart:async/zone.dart:1302:10)
#47     _StreamController.close (dart:async/stream_controller.dart:622:5)
#49     _RootZone.runUnaryGuarded (dart:async/zone.dart:1314:10)
#54     _StreamController.add (dart:async/stream_controller.dart:586:5)
#55     new _RawSocket. (dart:io-patch/socket_patch.dart:1342:35)
#56     _NativeSocket.issueReadEvent.issue (dart:io-patch/socket_patch.dart:849:18)

From that, it's relatively clear that there is a lot of close calls and then the first method on a stream fails with "no element". That makes sense.

The interesting point is #54 where adding an event turns into a close call. You can't easily debug that because I removed step #48 (dart:io-patch/socket_patch.dart:1793:21) which is code handling a raw socket closing.

The stack trace here is fairly standard for I/O code receiving input: Everything for a large number of steps is system code, then the value is passed to the user.

Removing some parts made the stack trace more readable, but not more debuggable because I removed an important step.

That suggests, to me, that you should have a way to collapse/expand/filter stack traces, rather than relying on one format to do everything. That, again, requires tool support, it's not something you can do on the command line.

Maybe the VM could detect terminal capabilities, and use color to dim out some lines?

devoncarew commented 4 years ago

I don't know what the right solution here is, but one possibility is to put a command in dartdev to post-process stack traces to improve readability / understandability.