fix(formatting/#2196): Fix buffer de-sync when applying formatting ed…

…its (#3233)

__Issue:__ When running format providers, like `prettier` or `rescript`, after multiple iterations, there could start to be duplicated or corrupted text.

__Defect:__ Some of the edits provided by the format provider, once they round-trip through our vim layer, weren't being applied back correctly in the extension host buffer updates (the `ModelContentChange` that we send to the extension host layer) - this would cause the buffer state to be de-sync'd - meaning that the view of the buffer text was different in the extension host than in the editor. The editor was correct, but the buffer text on the extension host side would have extra lines or extra concatenation, and when the next format was triggered, the formatting edits for the desync'd buffer would be applied, causing the issues in #2196

Currently, the way we send buffer updates is always linewise - and therefore a newline must always be included at the end. In the particular case of a formatting edit consolidating lines (deleting empty spaces), we wouldn't be adding that trailing newline - and this was the root cause of the desync.

While investigating, I found another case with undo - creating multiple lines, and then undoing them, triggers a similar bug.

__Fix:__ Simplify the way we decide to append a newline to correct these issues. Add a test case exercising the undo condition (once we have `$tryApplyEdit`, it'd be great to have that API exercised in a text synchronization case as well).

In addition, add some extra tooling in our `oni-dev-extension` to support troubleshooting these issues - when running with `oni2 -f --silent --debug-exthost` and running the `Developer: Show buffer updates` command, the extension host's view of the buffer will be shown in the console after each update.

__Next steps:__
- There's still a lot of room for improvement in the way we handle buffer updates - streamlining individual edits, and batched related updates into a single update call.

Fixes #2196 and the remainder of #2820

CHANGES_CURRENT.md

@@ -36,6 +36,7 @@
 - #3226 - Keybindings: Fix issue opening keybindings.json from the command palette
 - #3227 - Configuration: Allow string numbers as font sizes
 - #3230 - Font: Treat "FiraCode-Regular.ttf" as default font
+- #3233 - Formatting: Fix buffer de-sync when applying formatting edits (fixes #2196, #2820)
 
 ### Performance
 

development_extensions/oni-dev-extension/extension.js

@@ -35,6 +35,21 @@ function activate(context) {
         }),
     )
 
+    cleanup(
+        vscode.commands.registerCommand("developer.oni.logBufferUpdates", () => {
+                vscode.window.showInformationMessage("Logging buffer updates!");
+                vscode.workspace.onDidChangeTextDocument((e) => {
+                    console.log({
+                        type: "workspace.onDidChangeTextDocument",
+                        filename: e.document.fileName,
+                        version: e.document.version,
+                        contentChanges: e.contentChanges,
+                        fullText: e.document.getText(),
+                    });
+                });
+        }),
+    )
+
     cleanup(
         vscode.commands.registerCommand("developer.oni.tryOpenDocument", () => {
             vscode.workspace.openTextDocument(vscode.Uri.file("package.json"))

development_extensions/oni-dev-extension/package.json

@@ -40,6 +40,10 @@
 				"command": "developer.oni.tryOpenDocument",
 				"title": "Onivim - Developer: Try Open Document (package.json)"
 			},
+			{
+				"command": "developer.oni.logBufferUpdates",
+				"title": "Onivim - Developer: Log Buffer Updates"
+			},
 			{
 				"command": "developer.oni.showWorkspaceRootPath",
 				"title": "Onivim - Developer: Show Workspace Root Path"

integration_test/ExtHostBufferUpdatesTest.re

@@ -87,11 +87,36 @@ runTest(~name="ExtHostBufferUpdates", ({input, dispatch, wait, key, _}) => {
   // Finally, modify a single line
   input("gg");
   input("Iabc");
+  key(EditorInput.Key.Escape);
 
   TS.validateTextIsSynchronized(
     ~expectedText=Some("abca|b|c|"),
     ~description="after inserting some text in an existing line",
     dispatch,
     wait,
   );
+
+  // Insert multiple lines, and then undo
+  // This was a case discovered while investigating #2196
+  input("gg");
+  input("O");
+  key(EditorInput.Key.Return);
+  key(EditorInput.Key.Return);
+  key(EditorInput.Key.Escape);
+
+  TS.validateTextIsSynchronized(
+    ~expectedText=Some("|||abca|b|c|"),
+    ~description="after inserting multiple lines",
+    dispatch,
+    wait,
+  );
+
+  // Undo the change - we also had bugs here!
+  input("u");
+  TS.validateTextIsSynchronized(
+    ~expectedText=Some("abca|b|c|"),
+    ~description="after inserting multiple lines",
+    dispatch,
+    wait,
+  );
 });

src/CLI/Oni_CLI.re

@@ -20,6 +20,7 @@ type t = {
   shouldLoadConfiguration: bool,
   shouldSyntaxHighlight: bool,
   attachToForeground: bool,
+  logExthost: bool,
   logLevel: option(Timber.Level.t),
   logFile: option(string),
   logFilter: option(string),
@@ -93,6 +94,7 @@ let parse = (~getenv: string => option(string), args) => {
   let attachToForeground = ref(false);
   let logLevel = ref(None);
   let isSilent = ref(false);
+  let logExthost = ref(false);
   let logFile = ref(None);
   let logFilter = ref(None);
   let logColorsEnabled = ref(None);
@@ -142,6 +144,7 @@ let parse = (~getenv: string => option(string), args) => {
       ("-v", setEffect(PrintVersion), ""),
       ("--nofork", Unit(setAttached), ""),
       ("--debug", Unit(() => logLevel := Some(Timber.Level.debug)), ""),
+      ("--debug-exthost", Unit(() => logExthost := true), ""),
       ("--trace", Unit(() => logLevel := Some(Timber.Level.trace)), ""),
       ("--quiet", Unit(() => logLevel := Some(Timber.Level.warn)), ""),
       (
@@ -290,6 +293,7 @@ let parse = (~getenv: string => option(string), args) => {
     shouldSyntaxHighlight: shouldSyntaxHighlight^,
     attachToForeground: attachToForeground^,
     logLevel: logLevel^,
+    logExthost: logExthost^,
     logFile: logFile^,
     logFilter: logFilter^,
     logColorsEnabled: logColorsEnabled^,

src/CLI/Oni_CLI.rei

@@ -10,6 +10,7 @@ type t = {
   shouldLoadConfiguration: bool,
   shouldSyntaxHighlight: bool,
   attachToForeground: bool,
+  logExthost: bool,
   logLevel: option(Timber.Level.t),
   logFile: option(string),
   logFilter: option(string),

src/Core/Buffer.re

@@ -337,3 +337,20 @@ let setFont = (font, buf) => {
 let getSaveTick = ({saveTick, _}) => saveTick;
 
 let incrementSaveTick = buffer => {...buffer, saveTick: buffer.saveTick + 1};
+
+let toDebugString = buf => {
+  let lines =
+    buf
+    |> getLines
+    |> Array.to_list
+    |> List.mapi((idx, str) =>
+         "Line  " ++ string_of_int(idx) ++ ": |" ++ str ++ "|"
+       )
+    |> String.concat("\n");
+  Printf.sprintf(
+    "Buffer %d (version %d):\n---\n%s\n---\n",
+    getId(buf),
+    getVersion(buf),
+    lines,
+  );
+};

src/Core/Buffer.rei

@@ -88,3 +88,5 @@ let setFont: (Font.t, t) => t;
 
 let getSaveTick: t => int;
 let incrementSaveTick: t => t;
+
+let toDebugString: t => string;

src/Core/BufferUpdate.re

@@ -20,3 +20,19 @@ let create =
   version,
   isFull,
 };
+
+let toDebugString = ({isFull, version, startLine, endLine, lines, _}) => {
+  let lineStr =
+    lines
+    |> Array.to_list
+    |> List.mapi((idx, str) => Printf.sprintf("Line %d: |%s|", idx, str))
+    |> String.concat("\n");
+  Printf.sprintf(
+    "Core.BufferUpdate - version %d (full: %b) - startLine: %d endLine:%d\nLines:\n---\n%s\n---\n\n",
+    version,
+    isFull,
+    startLine |> LineNumber.toZeroBased,
+    endLine |> LineNumber.toZeroBased,
+    lineStr,
+  );
+};

src/Core/BufferUpdate.rei

@@ -22,3 +22,5 @@ let create:
     unit
   ) =>
   t;
+
+let toDebugString: t => string;

src/Exthost/ModelContentChange.re

@@ -17,17 +17,16 @@ let create = (~rangeLength: int, ~range: CharacterRange.t, ~text: string, ()) =>
 };
 
 let joinLines = (separator: string, lines: list(string)) => {
-  String.concat(separator, lines);
+  let joined = String.concat(separator, lines);
+
+  if (lines != []) {
+    joined ++ separator;
+  } else {
+    joined;
+  };
 };
 
 let getRangeFromEdit = (bu: BufferUpdate.t) => {
-  let newLines = Array.length(bu.lines);
-  let isInsert =
-    EditorCoreTypes.(
-      newLines >= LineNumber.toZeroBased(bu.endLine)
-      - LineNumber.toZeroBased(bu.startLine)
-    );
-
   let startLine = EditorCoreTypes.LineNumber.toZeroBased(bu.startLine);
   let endLine =
     EditorCoreTypes.LineNumber.toZeroBased(bu.endLine) |> max(startLine);
@@ -48,7 +47,7 @@ let getRangeFromEdit = (bu: BufferUpdate.t) => {
       }
     );
 
-  (isInsert, range);
+  range;
 };
 
 let getRangeLengthFromEdit =
@@ -72,11 +71,9 @@ let getRangeLengthFromEdit =
 
 let ofBufferUpdate =
     (~previousBuffer, bu: Oni_Core.BufferUpdate.t, eol: Eol.t) => {
-  let (isInsert, range) = getRangeFromEdit(bu);
+  let range = getRangeFromEdit(bu);
   let text = joinLines(Eol.toString(eol), bu.lines |> Array.to_list);
   let rangeLength = getRangeLengthFromEdit(~previousBuffer, ~eol, bu);
 
-  let text = isInsert ? text ++ Eol.toString(eol) : text;
-
   {range: OneBasedRange.ofRange(range), text, rangeLength};
 };

src/Feature/Buffers/Feature_Buffers.re

@@ -384,6 +384,7 @@ let update = (~activeBufferId, ~config, msg: msg, model: model) => {
       } else {
         newBuffer;
       };
+
     let markerUpdate =
       MarkerUpdate.create(~update, ~original=oldBuffer, ~updated=buffer);
     (

src/Store/StoreThread.re

@@ -129,11 +129,14 @@ let start =
 
   let initialState = getState();
 
-  let attachStdio =
+  let attachExthostStdio =
     Oni_CLI.(
       {
         initialState.cli.attachToForeground
-        && Option.is_some(initialState.cli.logLevel);
+        && (
+          Option.is_some(initialState.cli.logLevel)
+          || initialState.cli.logExthost
+        );
       }
     );
 
@@ -144,7 +147,7 @@ let start =
   let (extHostClientResult, extHostStream) =
     ExtensionClient.create(
       ~initialWorkspace,
-      ~attachStdio,
+      ~attachStdio=attachExthostStdio,
       ~config=getState().config,
       ~extensions,
       ~setup,

src/bin_launcher/Oni2.re

@@ -34,6 +34,11 @@ let spec =
       " Stay attached to the foreground terminal.",
     ),
     ("--debug", passthrough, " Enable debug logging."),
+    (
+      "--debug-exthost",
+      passthrough,
+      " Pipe exthost output to stdout/stderr.",
+    ),
     ("--trace", passthrough, " Enable trace logging."),
     ("--quiet", passthrough, " Print only error log messages."),
     ("--silent", passthrough, " Do not print any logging."),

src/reason-libvim/BufferUpdate.re

@@ -14,9 +14,11 @@ let show = (v: t) => {
     v.endLine,
     v.version,
   )
-  ++ "----"
-  ++ Array.fold_left((s, prev) => prev ++ s ++ "\n", "", v.lines)
-  ++ "----";
+  ++ "---- "
+  ++ string_of_int(Array.length(v.lines))
+  ++ "\n"
+  ++ Array.fold_left((s, prev) => prev ++ "\n" ++ s, "", v.lines)
+  ++ "\n----";
 };
 
 let getAllLines = (buffer: Native.buffer) => {

test/Cli/CliTest.re

@@ -57,6 +57,11 @@ describe("CLI", ({describe, test, _}) => {
     })
   });
   describe("log level", ({test, _}) => {
+    test("--debug-exthost should set logExthost", ({expect, _}) => {
+      let (options, _eff) =
+        Oni_CLI.parse(~getenv=noenv, [|"Oni2_editor", "--debug-exthost"|]);
+      expect.equal(options.logExthost, true);
+    });
     test("--silent should still require a console", ({expect, _}) => {
       let (options, _eff) =
         Oni_CLI.parse(~getenv=noenv, [|"Oni2_editor", "-f", "--silent"|]);