Treat Breakpoint logMessage as expression

[auchenberg]

Change LogPoints's logMessage to be evaluated as an expression and not a string, so LogPoints like LogPoint('products', products) can be set.

[weinand]

Thanks for the PR, but expression interpolation is a bit more tricky.

The log message is plain text (as in VS and VS for Mac), not an expression. Expressions are only interpolated within curly brackets.

node-debug's implementation will be in the next Insiders.

[auchenberg]

What's the syntax for interruptions @weinand? String literals?

The challenge is that we want to provide a better console.log, and developers will probably expect to be able to pass multiple arguments as in console.log('a', b, c, d)

[weinand]

syntax is identical to VS and VS for Mac:

{ Date.now() }: this is a log message showing the value of x: {x} and y: {y} or their sum: {x + y}

Inside curly braces the language of the underlying source can be used (and soon Intellisense).

[auchenberg]

I'm not sure this is a great experience for JavaScript developers. We shouldn't introduce a new custom syntax for LogPoints if the store telling and positioning is "a better console.log". JavaScript devs won't care about a VS or VS for Mac syntax, but how it feels in JavaScript.

If we think string interpolation is the way to go, we should at least use https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Template_literals

[weinand]

To support "a better console.log" story for all debuggers, we should not cling to the idiosyncrasies of JavaScript's console.log.

console.log by itself supports C-style %s substitutions and it is not very readable to correlate the %ss with the arguments passed at the end:

"%s: this is a log message showing the value of x: %s and y: %s or their sum: %s", Date.now(), x, y, x+y

Then there is the somewhat laborious way of "adding" strings:

Date.now() + ": this is a log message showing the value of x: " + x + "and y: " + y + "or their sum: " x+y

And last but not least the "Template literals":

`${Date.now()}: this is a log message showing the value of x: ${x} and y: ${y} or their sum: ${x+y}`

And here again the VS syntax (which differs from "Template literals" only by the dropped '$' and backticks):

{Date.now()}: this is a log message showing the value of x: {x} and y: {y} or their sum: {x+y}

For me it's pretty obvious what syntax is most appealing and readable and easy to type.

And it does not not make a lot of sense to drop VS compatibility by introducing a '$'.

In addition, I have to wear my multi-language-debugging hat. And with that hat on I prefer the somewhat unbiased VS syntax.

@auchenberg What is your concrete proposal?

[auchenberg]

My specific proposal is that we should enable language specific syntaxes for LogPoint messages, instead of introducing a VS/VSCode specific and language neutral for a new debugging feature.

We should follow the language specific standards for string interpolation, and the standards for how the usual logging helper mechanism works. We should meet developers there they are instead of giving them a new syntax to learn.

C#:
https://docs.microsoft.com/en-us/dotnet/csharp/language-reference/keywords/interpolated-strings

"Name = {name}, hours = {hours:hh}"

(I assume this is where the existing VS syntax is coming from)

Ruby:
http://ruby-for-beginners.rubymonstas.org/bonus/string_interpolation.html

"Hello, #{name}!"

Go:
https://golang.org/pkg/fmt/

"There are %v reasons to code!", num

JavaScript:

https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Template_literals

string text ${expression} string text

Keeping our LogPoint messages compatible with the used language can also enable us to convert LogPoints to persisted log message by injecting console.log or whatever used method at a later point.

[weinand]

You said:

We should meet developers where they are, instead of giving them a new syntax to learn.

But then you are proposing just another new syntax: your approach is basically a "crippled syntax" approach: remove the name of the language specific log function (the "context") and only keep the rest. Is this really preferable over VS's minimalistic approach?

e.g.

"There are %v reasons to code!", num

vs

There are {num} reasons to code!

For your approach it will be very difficult to provide Intellisense because for every language, VS code would need to know what syntactic construct the logMessage represents.
E.g. for "Go" it is not an expression but a function argument list. And for C# it is an interpolated string. And for JavaScript it is exactly what?

But this approach is not only difficult to support in VS Code but it is also problematic for devs that work with different languages. They always have to understand how the entered logMessage maps to the underlying implementation otherwise it will be difficult to understand what to enter in Go vs. JavaScript.

Your last argument:

Keeping our LogPoint messages compatible with the used language can also enable us to convert LogPoints to persisted log message by injecting console.log or whatever used method at a later point.

holds equally well (or even better) for the proposed VS syntax:

In the VS syntax it is well defined that the logMessage is text and that curly braces contain language specific expressions. Converting that into a different logging method at a later point is always possible. Doing the same with logMessages "Hello, #{name}!" or "There are %v reasons to code!", num is more difficult without knowing their context.

[weinand]

Let's get additional opinions from some of the DAP stakeholders:
@gregg-miskelly @andrewcrawley @richardstanton @DavidKarlas @changsi-an @roblourens

For context: in this milestone we are introducing "logPoint" support by adding a string-valued logMessage attribute to Breakpoints in the Debug Adapter Protocol (see microsoft/vscode-debugadapter-node#162).

Now the question is: what is the semantics (and syntax) for logMessage. We have basically two proposals:

• use the VS/VS for Mac approach: a text with interpolated language specific expressions within curly braces (see Treat Breakpoint logMessage as expression #174 (comment))
• a new approach: just use the arguments that are passed to the underlying logging mechanism (see Treat Breakpoint logMessage as expression #174 (comment)).

[auchenberg]

@weinand

No, I'm not proposing to introduce a new syntax as JavaScript developers already are using Template Literals and multiple arguments withconsole.log. That's what they today use, and we are the ones introducing them to a new LogPoints` concept. If we go with a "minimal VS syntax" we are introducing them to a new syntax that isn't found in the JavaScript language, which I would expect many JS devs to find weird.

I don't consider existing users of VS/VS for Mac as the target audience for LogPoints in VS Code, and the VS syntax seem to be a result of them shipping LogPoints for C# first.

[gregg-miskelly]

For C# I would imagine we would want to use the existing VS syntax, since most C# developers are familiar with Visual Studio.

There are a few problems that get harder (but certainly not impossible) if one tries to use a different tracing syntax for each language:

1. Debuggers can often do things that don't exist in the language, and you want some way of making those show up. As an example, in the VS trace point syntax, you can use $CALLSTACK to have the tracepoint print the call stack.
2. Because of the previous point, it would be more difficult to provide IntelliSense if every language has their own syntax. In VS, the tracepoint IntelliSense can easy understand if it is dealing with natural text, a debugger pseudo-register, or an expression and switch back and forth between which IntelliSense to provide.
3. It can be harder to provide developers information on what they are allowed to type into that box

The only other problem I can think of with using a language-specific syntax is that in some languages (ex: C++, sounds like Go as well) the language specific syntax is definitely harder to use than the language neutral syntax. Though clearly in these cases one could just choose the language neutral syntax instead.

[roblourens]

If we use the common syntax with braces indicating expressions, would the protocol be changed so that this is enforced on vscode's end? Because otherwise we're just debating how node-debug should handle it, and there's no guarantee that any other debug adapter would make the same decision. And you can't really provide intellisense for it without an agreement between the language service and debug adapter on the syntax.

[andrewcrawley]

In my opinion, the main advantage of doing it the "VS way" is that it can be implemented entirely at the UI layer. VS doesn't expose anything about tracepoints to the debugger - it treats them as normal breakpoints. When a breakpoint is hit, VS recognizes that it has a tracepoint string associated with it, splits out everything between curly-brackets, asks the debugger to evaluate those strings, inserts the results back into the original string, prints it, and tells the debugger to resume execution.

A solution like this will "just work" for any debugger, without requiring any work on the debugger side.

[roblourens]

I think we allow the debug adapter to implement it because the Node adapter can have the runtime handle everything, much faster than making round trips. Especially important for attaching to production apps, which is a main use case.

We could actually have it both ways - implement it on the client for all types, unless the adapter opts in to handling it for itself.

[weinand]

@auchenberg I said that your approach introduces "new syntax" because it is not very common that a text box expects a specific argument list format (without the corresponding function) instead of a plain vanilla expression or a statement. How should a dev know that for JavaScript we are supporting only template-syntax but not the "classic" console.log format with embedded "%s".

@roblourens the DAP spec says for the logMessage attribute:

/** If this attribute exists and is non-empty, the backend must not 'break' (stop) but log the message instead. Expressions within {} are interpolated. */

As usual there is nothing node.js specific about this. So this syntax applies to all DAs that opt into this via the corresponding capability.

VS Code will enforce the syntax, but it will stop at the curly braces.
What's inside curly brackets, VS Code will leave it alone.

But we are already working on supporting language specific Intellisense within the braces. The language is determined by the underlying editor of the logPoint. Within a curly brace we assume expression syntax, the same that we will support for watch expressions or Breakpoint "conditions".

If we would have to support language specific argument lists, we would have to know the declaration of the underlying log-function. But the underlying log-function is DA specific so it will be difficult for VS Code to get this information (especially if the debug extension is not active).

@andrewcrawley your comment is basically what we are doing in VS Code and what motivated us to use that approach.

[auchenberg]

For the past hours I've been demoing LogPoints here at TechFest, and there's a few good learnings. I think this screenshot from a demo is a good summary of challenges for the current string interpolation based approach:

The user here entered a log expression to be evaluated, and was first of all surprised by the the {} syntax for evaluating expressions, but once explained it make sense, but was still weird: "Why can't I just use JS or multiple arguments?". The next question was then "how do I see nicely formatted objects like console.log"?

At the moment you can't with LogPoints as we don't provide any "magic" for the users, which console.log does. This doesn't seem to meet their expectations: "how is this a better console.log, if I have to do this manually??"

We can sure find a way to do object serialization, but my take is that we'll eventually end up implementing the the console apis in the Node DA to get parity

Based on this I still think we have to meet node developers they where are with console.log and we should treat LogPoints for Node as pure console.logs. For autocompletion my expectation would be to have the same Intellisense experience as if I were one a new line in the editor and had typed console.log(.

When the Edge DevTools team implemented Log/TracePoints they ended up reaching the same conclusion by offloading to console.log, and we shouldn't ignore this. It's our reference implementation we can learn from.

The value prop for LogPoints is that they are a quick and easy way to inject log messages into your application code, and we have to be at least in parity with the existing methods on the logging functionality side, and for the experience we have to significant better then the typical flow (in Node) by injecting a log, saving the file, and restarting the process

@weinand @roblourens

[roblourens]

Formatting objects nicely is definitely critical. I think that passing the objects as arguments to console.log is the only way to do that. Without breaking at the logpoints, the DA will never have a chance to evaluate the arguments itself.

[roblourens]

The DA can format the stuff that goes to the debug console however it wants to, but it can't change what goes to stdout in the terminal after it sets up the console.log conditional BP

[roblourens]

And I think it's a separate discussion from which syntax to use. Passing multiple arguments to console.log enforces a space between each one so it could add extra spaces in some cases, with the {} syntax.

[auchenberg]

@weinand Please see comments.

[weinand]

Instead of using the string value of interpolated expressions, we could easily use the object value instead. This may result in "nicely formatted objects", but please keep in mind the following shortcomings:

• an "object log" in the debug console does not actually record different states of an object. If an object is logged multiple times during program execution, all objects in the log share the same (its last) value. This is not the case when logging values.
• "nicely formatted objects" only exist if the DA is active. After its termination the objects are "dead" and only those can be viewed and expanded that were expanded when the DA was still alive.
• VS Code does not support more than on object in a line. So an "a: {a} b: {b} c: {c}" results in:

  a: >a
  b: >b
  c: >c
  

[auchenberg]

@weinand @roblourens I'm wondering if we could follow the best practice from MDN that recommends doing a console.log(JSON.parse(JSON.stringify(obj))) at logging time to generate a snapshot of the object?

https://developer.mozilla.org/en-US/docs/Web/API/Console/log#Logging_objects

I think splitting expressions onto multiple lines would be a great starting point.

[auchenberg]

If we end up doing our own object serialization, would we end-up duplicating console.log functionality? Handling circular references, etc?

[roblourens]

JSON.parse is lossy for things that can't go into JSON like classes, or functions, or NaN. And it doesn't handle circular references, we would need to write our own code for that. It could be slow on large objects.

[auchenberg]

So what could be a solution here?

Breakdown expressions and forward to console.log as arguments?

Product: {product} -> console.log('Product:', product)?

Product.constructor.getProduct for {product.id}, result: {product} ->
console.log('Product.constructor.getProduct for :', product.id, "result:", product)?

Use formatting options for expressions:

Chrome/Node supports print-if style formatting. Se https://developers.google.com/web/tools/chrome-devtools/console/console-reference#format-specifiers and https://nodejs.org/api/util.html#util_util_format_format_args

Product: {product} -> console.log('Product %o', product)?

Product.constructor.getProduct for {product.id}, result: {product} ->
console.log('Product.constructor.getProduct for %o, result: %o, product.id, product)?

https://developers.google.com/web/tools/chrome-devtools/console/console-write

[weinand]

Yes, using JSON.stringify(obj) was my thinking too.

The current approach is to delegate to console.log(...) and I suggest that we continue to do this as long as possible. So JSON.parse(JSON.stringify(obj)) would be the (somewhat laborious) approach to use.

On the other hand: since we control both sides of the pipe, we could easily use just JSON.stringify(obj) and parse the resulting string representation directly into the VS Code "Debug Console" tree (instead of doing the serialization/deserialization multiple times).

Another issue we should address is the unhelpful source location shown in the debug console. Currently all log output shows "VM123" as the source link because all console.logs are evaluated in an unnamed script (which we name by using the script id). Instead we could feed the Log Point's source location into the Output event's source attribute. One way to do this would be to tunnel the location as an additional argument through the console.log call.

[auchenberg]

@weinand @roblourens How do we best move forward? Open a new issue, so we can add it to the backlog?

I didn't know the log messages would show up with a VMsource. We should see if can get that fixed in the next iteration.

[weinand]

Please create new issues in VS Code for:

• the VM source issue,
• the "log expandable objects" issue.

I've already tried console.log('%o', o) and console.log('%O', o) but without success. I only get the string "Object" in the output.

Breaking the logMessage into individual arguments for console.log is simple, but it looks ugly in the VS Code debug console because there can only be one tree per line, and no additional text on that line.

So for this logMessage:

Name: {name} Father: {fatherObject} Mother: {motherObject}

you would get something like the following ('>' means expandable tree):

Name: "John" Father:
> father
Mother:
> mother

We need to explore more options (including improving the debug console). But for this we'll have to wait until for @isidorn to return from vacation.

[roblourens]

%o isn't supported yet, but easily can be: https://github.com/Microsoft/vscode-chrome-debug-core/blob/master/src/chrome/consoleHelper.ts#L112

[auchenberg]

Issues opened. Closing.