Some unhandled exceptions sent to LSP client via `showMessage` usages are not written to the instrumentation log with stack traces

[FMorschel]

Today, I stumbled upon a Null check operator used on a null value message, and after some talk with @DanTup, he asked me to open this issue to track this work.

[DanTup]

{"jsonrpc":"2.0","method":"window/showMessage","params":{"message":"Socket error: Null check operator used on a null value","type":1}}

[DanTup]

The only code I can find that I think would produce an error in this format ("Socket error: {exception text}") is here:

sdk/pkg/analysis_server/lib/src/lsp/lsp_analysis_server.dart

Lines 993 to 995 in ef30b3c

	void socketError(Object error, StackTrace? stackTrace) {
	// Don't send to instrumentation service; not an internal error.
	sendServerErrorNotification('Socket error', error, stackTrace);

The code is commented suggesting this is related to the socket (for example the stdout stream closes), but that's clearly not the case here. The method is used in two places:

• in handleMessage which uses runZonedGuarded and passes it as a callback (the body of the method has a try/catch around it)
• the other is a call to channel.listen which at a glance doesn't execute a lot of code that could throw

My only theory right now is that some code that was executed within runZonedGuarded threw, but it as unawaited async code, and therefore triggered the zones error handler. In that case, I disagree that not logging it to the instrumentation log is the right thing to do.

I think probably the runZonedGuarded call should not take socketError but another similar method which logs. I'll see if I can repro the issue by just forcing an unawaited async exception and if so, ensure this change would get the stack trace in the instrumentation log.

[DanTup]

Yep, this repro'd:

1764069645365:Res:{"jsonrpc"::"2.0","method"::"window/showMessage","params"::{"message"::"Socket error:: Bad state:: This is an unawaited async exception","type"::1}}

And with the change:

1764069793915:Ex:Bad state:: This is an unawaited async exception:#0      LspAnalysisServer.handleMessage.<anonymous closure>.<anonymous closure> (package::analysis_server/src/lsp/lsp_analysis_server.dart::486::20)
#1      _rootRunUnary (dart::async/zone_root.dart::48::47)
#2      _CustomZone.runUnary (dart::async/zone.dart::733::19)
#3      Future._propagateToListeners.handleValueCallback (dart::async/future_impl.dart::948::45)
#4      Future._propagateToListeners (dart::async/future_impl.dart::977::13)
#5      Future._complete (dart::async/future_impl.dart::711::7)
#6      new Future.delayed.<anonymous closure> (dart::async/future.dart::436::16)
#7      _rootRun (dart::async/zone_root.dart::27::47)
#8      _CustomZone.run (dart::async/zone.dart::726::19)
#9      _CustomZone.runGuarded (dart::async/zone.dart::625::7)
#10     _CustomZone.bindCallbackGuarded.<anonymous closure> (dart::async/zone.dart::666::23)
#11     _rootRun (dart::async/zone_root.dart::35::13)
#12     _CustomZone.run (dart::async/zone.dart::726::19)
#13     _CustomZone.bindCallback.<anonymous closure> (dart::async/zone.dart::649::23)
#14     Timer._createTimer.<anonymous closure> (dart::async-patch/timer_patch.dart::18::15)
#15     _Timer._runTimers (dart::isolate-patch/timer_impl.dart::423::19)
#16     _Timer._handleMessage (dart::isolate-patch/timer_impl.dart::454::5)
#17     _RawReceivePort._handleMessage (dart::isolate-patch/isolate_patch.dart::193::12)

1764069793920:Res:{"jsonrpc"::"2.0","method"::"window/showMessage","params"::{"message"::"Unhandled handler error:: Bad state:: This is an unawaited async exception","type"::1}}

[DanTup]

I've opened https://dart-review.googlesource.com/c/sdk/+/464381 to fix the issue with the exception not being recorded.

It doesn't solve whatever the error was that you triggered, but with this change if you ever hit it again, you will be able to get the full exception details from the instrumentation log.