[WIP] Wrap all RPC methods with exception logging

[jakebailey]

Adding this PR to get some feedback (do not merge). Leading into #246.

Right now, any exceptions thrown while handing an RPC method bubble back up to the RPC. They're encoded as a standard JSON RPC error message, which the editor does print. However, the RPC library we use only gives Exception.Message directly, instead supplying the stack trace in the RPC error's data member, which VS Code does not print. This leads to not-so-helpful errors like #23 which only show the message text and nothing else.

My first attempt subclassed JsonRpc to override the methods that invoke the different handlers, but sending logs/telemetry is also RPC that calls those methods, which means that reporting anything led to infinite recursion, so I threw that away.

Instead, I've written a function LogOnException which each function with attribute JsonRpcMethod calls manually. Exceptions are captured, sent back over RPC as an error, then rethrown as to not change the overall code flow. I have not included actual telemetry calls until I figure out the right schema for the object to send, and what information to omit.

Example before, if I just throw an exception from LineFormatter:

[Error - 1:06:46 PM] Request textDocument/onTypeFormatting failed.
  Message: this is a test
  Code: -32000 
[object Object]

And what this code shows:

[Error - 1:06:46 PM] System.Exception: this is a test
   at Microsoft.Python.LanguageServer.Implementation.LineFormatter.FormatLine(Int32 line) in C:\Users\jabaile\python-language-server\src\LanguageServer\Impl\Implementation\LineFormatter.cs:line 102
   at Microsoft.Python.LanguageServer.Implementation.Server.DocumentOnTypeFormatting(DocumentOnTypeFormattingParams params, CancellationToken cancellationToken) in C:\Users\jabaile\python-language-server\src\LanguageServer\Impl\Implementation\Server.OnTypeFormatting.cs:line 52
   at Microsoft.Python.LanguageServer.Implementation.LanguageServer.<>c__DisplayClass54_0.<<DocumentOnTypeFormatting>b__0>d.MoveNext() in C:\Users\jabaile\python-language-server\src\LanguageServer\Impl\LanguageServer.cs:line 371
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Python.LanguageServer.Implementation.LanguageServer.LogOnException[TResult](Func`1 func) in C:\Users\jabaile\python-language-server\src\LanguageServer\Impl\LanguageServer.cs:line 458
[Error - 1:06:46 PM] Request textDocument/onTypeFormatting failed.
  Message: this is a test
  Code: -32000 
[object Object]

Any thoughts on this?

[jakebailey]

I know that my main complaint about it is how invasive it feels. This call has to go everywhere. If this were Python, I'd probably use a decorator to wrap the functions, but that's not exactly possible in C# unless you have something like PostSharp.

[AlexanderSher]

Why JsonRpc.TraceSource doesn't work?

[jakebailey]

Why JsonRpc.TraceSource doesn't work?

We have StreamJsonRpc version 1.4.121. TraceSource is new as of a month ago, and is only released in 2.0.79-alpha (which is why I didn't find it when I was looking at what VS was saying about the type).

[jakebailey]

Related issue on their tracker: microsoft/vs-streamjsonrpc#115

I'm sure we could use this for both logging/telemetry, but we'd only get it by upgrading our version of the library to that alpha release (and I don't know anything about its stability or when they'd plan to release a non-alpha version).

[MikhailArkhipov]

We should try sending telemetry via ITelemetryServce. We can craft test event and check how it shows up in the app insights

[jakebailey]

Yes, I know. Above I stated that I specifically didn't put it in this WIP because I hadn't looked into the right schema for the telemetry events (Since ITelemetryService seems to just accept object).

[AArnott]

The 2.0 version of the library has no known stability issues, but the API may change before we release a stable 2.0 package, which is why the latest release is still a -prerelease.

Instead, I've written a function LogOnException which each function with attribute JsonRpcMethod calls manually. Exceptions are captured, sent back over RPC as an error, then rethrown as to not change the overall code flow. I have not included actual telemetry calls until I figure out the right schema for the object to send, and what information to omit.

If the goal is to improve the exception message shown in the client, I don't know why you're transmitting an error and still throwing from your method. That would lead to JsonRpc sending its own error response as well, and the client would receive two error messages.

Yes the tracing that is new in 2.0 can help you with telemetry, but if your goal is to better control the error responses to invocations so that a particular client will display what you want, 2.0 has a new feature that helps with that: you can intercept any message going either direction, so you can massage the error message however you'd like. You can also throw a special exception that gives you the ability to add whatever extra data you'd like, and control the error code, etc.

[AArnott]

One other thing (and this feature exists in the 1.x versions) is you can add a IsFatalException handler which gets a peek at every exception thrown from an RPC invocation. You can return false from this method, after logging whatever you want.

All of these approaches I've mentioned do not require you to change each individual serer method.

[AlexanderSher]

Thanks @AArnott , overriding IsFatalException sounds like a good option.

[jakebailey]

If the goal is to improve the exception message shown in the client, I don't know why you're transmitting an error and still throwing from your method. That would lead to JsonRpc sending its own error response as well, and the client would receive two error messages.

Yes, I'd like to avoid sending the error twice. The trouble is that VS Code gets the RPC error just fine, and is able to print Message (see my comparison in the description). But it doesn't seem to ever do anything with that Data, which from reading the StreamJsonRpc source code is typically set to be a CommonErrorData object. The stack trace is being kept there, but the editor doesn't do anything with it.

[jakebailey]

I should clarify that I'm assuming that Data makes it back to the editor and it's the editor that's not doing anything with it. [object Object] to me says VS Code is just calling toString() on that RPC error data member and showing that.

[AArnott]

How would sending an extra error message achieve the right experience in VS Code? Won't it still display an error message when the RPC error result comes back, with just the message?

And yes, the Data object is relayed back to the RPC client.

[MikhailArkhipov]

We should NOT be sending all exceptions. Cancellation exception does not make sense since it happens normally. We also throwing InvalidOperation when symbol cannot be renamed. Editor simply shows the message in the exception.

[AArnott]

@MikhailArkhipov: OperationCanceledException is swallowed by JsonRpc and a special error message with a reserved cancellation error code is sent to the client to indicate that the response was not completed due to their request to cancel it.

We should be sending all exceptions.

I don't hear anyone disagreeing with that. My question was how sending the error response back to the client twice fixes anything.

[jakebailey]

How would sending an extra error message achieve the right experience in VS Code? Won't it still display an error message when the RPC error result comes back, with just the message?

It doesn't achieve the right experience. Like I said, I don't really want to send the error twice. This is just a WIP idea to try to get the stack trace back to VS Code so that it displays it.

I'm also assuming that not rethrowing the error is a bad idea in this specific implementation, since otherwise the code needs to make a decision about what to actually send back.

[AArnott]

I'm also assuming that not rethrowing the error is a bad idea in this specific implementation, since otherwise the code needs to make a decision about what to actually send back.

I agree: not re-throwing would be problematic for multiple reasons.

While the existing 2.0 functionality will allow you to massage the message, adding a general message interceptor feels a bit heavy-handed. I'm going to look to see if we can make an easier way for hand-crafting the error message so you can include whatever you want.

[jakebailey]

Yeah, part of me is going "I wish VS Code were printing data a bit smarter", but I can't exactly blame them for not doing more than a simple toString() (or some implicit conversion). I'll take a quick look to see if I can find where that output is happening to know for sure.

Regardless, if we want to have telemetry and not just better logging, then we'd probably want a bit extra on top of JsonRpc. If you find an easier way to manage it, that'd be awesome. 🙂

[jakebailey]

This is the bit that's actually doing the printing of that error in languageserver-client:

https://github.com/Microsoft/vscode-languageserver-node/blob/9c26d2b58a441698a8e7790ce46c667dc4e2e199/client/src/client.ts#L2621-L2629

	public error(message: string, data?: any): void {
		this.outputChannel.appendLine(`[Error - ${(new Date().toLocaleTimeString())}] ${message}`);
		if (data) {
			this.outputChannel.appendLine(this.data2String(data));
		}
		if (this._clientOptions.revealOutputChannelOn <= RevealOutputChannelOn.Error) {
			this.outputChannel.show(true);
		}
	}

Where data2String is:

https://github.com/Microsoft/vscode-languageserver-node/blob/9c26d2b58a441698a8e7790ce46c667dc4e2e199/client/src/client.ts#L2584-L2599

	private data2String(data: any): string {
		if (data instanceof ResponseError) {
			const responseError = data as ResponseError<any>;
			return `  Message: ${responseError.message}\n  Code: ${responseError.code} ${responseError.data ? '\n' + responseError.data.toString() : ''}`
		}
		if (data instanceof Error) {
			if (Is.string(data.stack)) {
				return data.stack;
			}
			return (data as Error).message;
		}
		if (Is.string(data)) {
			return data;
		}
		return data.toString();
	}

So it's correctly detecting that it's a ResponseError, but then just calls data.toString(), which will just give back [object Object].

[MikhailArkhipov]

@AArnott - the intent is two-fold

1. Let user see callstack in the output log and submit it along with the bug
2. Be able to send crashes with callstacks to telemetry

The above does not apply to all exceptions. Currently we can throw InvalidOperationException to tell editor that say, rename cannot be performed. Although we can probably derive different one for that purpose, such as CannotRenameException: LanguageServerException: Exception and filter it out.

[AArnott]

Be able to send crashes with callstacks to telemetry

Do you really mean crashes? Won't Watson take care of that already, if you have your process name registered for collection? Or do you mean to send telemetry regarding exceptions from RPC methods? I notice that our new TraceSource doesn't emit an event when an RPC method throws an exception, and we can certainly improve that.

If you wanted to stick with 1.x, and didn't mind wrapping each server method with your delegate wrapper, then when you catch exceptions with your wrapper, you can throw a new exception (retaining the inner exception) with a Message that you want to show.

[MikhailArkhipov]

@AArnott - Watson on Linux? Also, some exception do not necessarily cause crash - including null refs. In VS Code output window it looks like textEditor/completion request failed - null reference exception

[AArnott]

I didn't know what platform you were on. But I don't know how anything you do in-proc can send telemetry on crashes, since by definition when you crash, you're not running any more.

[jakebailey]

Unless I'm mistaken, I'm not sure that actual crashes are in scope for tracking with an RPC library. Exceptions are, for sure.

If we want to try to track true crashes on Linux/macOS, I think that'll have to be done some other way separate from this discussion. (The extension already is able to detect when a crash occurs.)

EDIT: not sure. Oof. Bad typo.

[AArnott]

I'm sure that actual crashes are in scope for tracking with an RPC library. Exceptions are, for sure.

Catchable exceptions thrown from RPC methods do not turn into crashes because JsonRpc catches them so it can report them to the client. But first, JsonRpc.IsFatalException gets to look at the exception and decide whether the exception is worth terminating the connection. Returning true will terminate the connection, but will not crash the process. One user of the library decided to call Environment.FailFast in their IsFatalException override so that it will crash (and get Watson to collect evidence of the failure). I don't endorse that, but share it as a possibility for you. But as you're on Linux, maybe not crashing, but filing telemetry from IsFatalException and returning a bool value is more useful to you anyway.

[jakebailey]

You quoted my unedited comment. I typo'd in the worst possible way and ended up saying the exact opposite of what I intended. 🙁

[jakebailey]

Just to be clear, I don't think we should be tackling actual process crashes in the scope of improving the messages and telemetry that is being sent over RPC. That's likely better handled in the extension code, perhaps by overriding handleConnectionClosed in LanguageClient.

Looking at microsoft/vs-streamjsonrpc#187 seems like it'd be very useful, as we could override CreateErrorDetails to switch Data to a human-readable string in lieu of vscode-languageserver doing something better than just data.toString(). Thanks for taking the time to look into this, @AArnott!

[MikhailArkhipov]

@jakebailey - yes, we should. There is little dependency on the extension as the LS can be used in other applications. We should not be assuming extension functionality beyond that it launches the process.
Related: microsoft/vscode-python#2940

[jakebailey]

But as Andrew's said, if the process really, truly crashes, then there's no RPC stream anymore nor a process to report the crash. Outside of Windows, we have no way of knowing that has happened other than by having the thing that starts/communicates with LS do something, or a user bug report. vscode-python does the logging bit already, since it uses vscode-languageserver-client, which is the thing that implements the behavior of "restart 5 times then give up".

[jakebailey]

s/Aaron/Andrew. Not my day...

[AArnott]

The fixes I've made to streamjsonrpc based on this discussion will be available on nuget.org in v2.0.94-beta in a few minutes.

[jakebailey]

Alright, so the latest StreamJsonRpc build works, and you can see what a PR to switch to it looks like here: master...jakebailey:streamjsonrpc

However, due to microsoft/vs-streamjsonrpc#195, it might be a little bit annoying to upgrade because with NuGet's behavior on code analyzers our project would inherit all of StreamJsonRpc's analyzers (which causes a large number of warnings to show in our code, specifically to do with style we don't adhere to). Switching to the newer StreamJsonRpc to get access to the error API would be a better solution, but this PR works too.

Any thoughts on just merging this so that we have something in the way of printing stack traces, even if it means doubling up messages, then remove this in the future with a better method?

Another method would be for me to open a bug with the node-languageserver-client devs to see if they can print something prettier for that data element instead of calling toString blindly, but that would involve them changing it, releasing it, and the extension upgrading their library version, and also releasing, whereas this PR or even the StreamJsonRpc method would have instant gratification.

[AlexanderSher]

annoying to upgrade because with NuGet's behavior on code analyzers our project would inherit all of StreamJsonRpc's analyzers

We can disable those analyzers.

[jakebailey]

I haven't yet found a way to do so, other than to explicitly suppress each individual code that the introduced analyzer emits (which I then don't know how to make apply to everything at once). But, I'm not extremely experienced with dealing with C# analyzers. If you know of a way, that'd be great to see.

[AArnott]

Do it within Solution Explorer:

Tip: only disable one analyzer at first. Then you can bulk-select the rest and disable them all at once. VS has a bug where if you don't yet have a ruleset file and you bulk-select and disable rules, VS malfunctions badly.

[jakebailey]

Aha, yes, that works. I might see if any of the warnings being shown are of use before disabling them all, though. (The one about naming is definitely getting disabled.)

[jakebailey]

Eh, I'll just disable them all. Picking and choosing is out of scope of "show stack traces".

[jakebailey]

Closed in favor of #303.