Working typescript refactor hangs: Timeout while waiting for response. Method: workspace/executeCommand

[vjohansen]

Thank you for the bug report

• I am using the latest version of lsp-mode related packages.
• I checked FAQ and Troubleshooting sections
• You may also try reproduce the issue using clean environment using the following command: M-x lsp-start-plain

Bug description

I just updated to lsp 9 and the latest typescript language server.

When I call "Extract to function in module scope" it hangs for about 10 seconds (which seems to be lsp-response-timeout) and shows

lsp-workspace-command-execute: ‘workspace/executeCommand’ with ‘_typescript.applyRefactoring’ failed.
(error "Timeout while waiting for response.  Method: workspace/executeCommand")```

Note that refactoring is **working**. The bug is that it hangs and shows an error.


### Steps to reproduce



In a test script run via _npx tsx test.ts_

function log_add() {
const a = 1;
const b = 2;
const sum = a + b;
console.log('sum', sum);
}

- mark the the tree lines with const at the beginning
- Run lsp-execute-code-action
- Select "Extract to function in module scope"
-  Type a 'add'  in the prompt "Rename newFunction to:"

Result:

lsp-workspace-command-execute: ‘workspace/executeCommand’ with ‘_typescript.applyRefactoring’ failed.
(error "Timeout while waiting for response.  Method: workspace/executeCommand")Invalid face referenc

If you wait 10 seconds in the prompt for a new name the error appears immediately

If a add a (message "DEBUG.. ") line at the top of the lsp-request function I see multiple requests

LSP :: Connected to [ts-ls:28236/starting c:/code/react/rproj4].
Prettier restart complete.
LSP :: ts-ls:28236 initialized successfully in folders: (c:/code/react/rproj4)
DEBUG lsp-request "textDocument/codeAction"
DEBUG lsp-request "workspace/executeCommand"
LSP :: Applying 2 edits to vproj4-vjtest.ts' ... Applying 2 edits to vproj4-vjtest.ts' ...done
DEBUG lsp-request "textDocument/prepareRename"
DEBUG lsp-request "textDocument/rename"
LSP :: Applying 2 edits to vproj4-vjtest.ts' ... Applying 2 edits to vproj4-vjtest.ts' ...done
lsp-workspace-command-execute: ‘workspace/executeCommand’ with ‘_typescript.applyRefactoring’ failed.
(error "Timeout while waiting for response. Method: workspace/executeCommand")Invalid face referenc

### Expected behavior

No error message since the refactor actually works




### Which Language Server did you use?






[-] c:/code/react/rproj4
 `-[-] ts-ls:38500
    |-[-] Buffers
    |  `-[+] vproj4-vjtest.ts
    `-[+] Capabilities



### OS

Windows

### Error callstack

```emacs-lisp
Debugger entered--Lisp error: (error "Timeout while waiting for response.  Method: works...")
  error("Timeout while waiting for response.  Method: %s" "workspace/executeCommand")
  lsp-request("workspace/executeCommand" (:command "_typescript.applyRefactoring" :arguments [#<hash-table equal 7/7 0x83170d14e9>]))
  lsp-workspace-command-execute("_typescript.applyRefactoring" [#<hash-table equal 7/7 0x83170d14e9>])
  lsp-send-execute-command("_typescript.applyRefactoring" [#<hash-table equal 7/7 0x83170d14e9>])
  lsp--execute-command(#<hash-table equal 3/3 0x83179eb2dd>)
  lsp--execute-code-action(#<hash-table equal 3/3 0x83179ebe81>)
  lsp-execute-code-action(#<hash-table equal 3/3 0x83179ebe81>)
  funcall-interactively(lsp-execute-code-action #<hash-table equal 3/3 0x83179ebe81>)
  call-interactively(lsp-execute-code-action)
  (lambda nil (interactive) (call-interactively 'lsp-execute-code-action))()
  funcall-interactively((lambda nil (interactive) (call-interactively 'lsp-execute-code-action)))
  command-execute((lambda nil (interactive) (call-interactively 'lsp-execute-code-action)))



[Trace - 11:45:21 ] Received response 'textDocument/codeAction - (8)' in 69ms.
Result: [
  {
    "title": "Extract to inner function in function 'log_add'",
    "kind": "refactor",
    "command": {
      "title": "Extract to inner function in function 'log_add'",
      "command": "_typescript.applyRefactoring",
      "arguments": [
        {
          "file": "c:\\code\\react\\rproj4\\scripts\\vproj4-vjtest.ts",
          "startLine": 348,
          "startOffset": 1,
          "endLine": 351,
          "endOffset": 1,
          "refactor": "Extract Symbol",
          "action": "function_scope_0"
        }
      ]
    }
  },
  {
    "title": "Extract to function in module scope",
    "kind": "refactor",
    "command": {
      "title": "Extract to function in module scope",
      "command": "_typescript.applyRefactoring",
      "arguments": [
        {
          "file": "c:\\code\\react\\rproj4\\scripts\\vproj4-vjtest.ts",
          "startLine": 348,
          "startOffset": 1,
          "endLine": 351,
          "endOffset": 1,
          "refactor": "Extract Symbol",
          "action": "function_scope_1"
        }
      ]
    }
  }
]


[Trace - 11:45:21 ] Received response 'textDocument/codeAction - (9)' in 27ms.
Result: [
  {
    "title": "Extract to inner function in function 'log_add'",
    "kind": "refactor",
    "command": {
      "title": "Extract to inner function in function 'log_add'",
      "command": "_typescript.applyRefactoring",
      "arguments": [
        {
          "file": "c:\\code\\react\\rproj4\\scripts\\vproj4-vjtest.ts",
          "startLine": 348,
          "startOffset": 1,
          "endLine": 351,
          "endOffset": 1,
          "refactor": "Extract Symbol",
          "action": "function_scope_0"
        }
      ]
    }
  },
  {
    "title": "Extract to function in module scope",
    "kind": "refactor",
    "command": {
      "title": "Extract to function in module scope",
      "command": "_typescript.applyRefactoring",
      "arguments": [
        {
          "file": "c:\\code\\react\\rproj4\\scripts\\vproj4-vjtest.ts",
          "startLine": 348,
          "startOffset": 1,
          "endLine": 351,
          "endOffset": 1,
          "refactor": "Extract Symbol",
          "action": "function_scope_1"
        }
      ]
    }
  }
]


[Trace - 11:45:21 ] Received request 'window/workDoneProgress/create - (1).
Params: {
  "token": "58090bc5-30f9-463f-8c6c-6ffd9d5b3e9d"
}


[Trace - 11:45:21 ] Sending response 'window/workDoneProgress/create - (1)'. Processing request took 0ms
Params: {
  "jsonrpc": "2.0",
  "id": 1,
  "result": null
}


[Trace - 11:45:21 ] Received notification '$/progress'.
Params: {
  "token": "58090bc5-30f9-463f-8c6c-6ffd9d5b3e9d",
  "value": {
    "kind": "begin",
    "title": "Initializing JS/TS language features…"
  }
}


[Trace - 11:45:21 ] Received notification 'textDocument/publishDiagnostics'.
Params: 


[Trace - 11:45:22 ] Received notification '$/progress'.
Params: {
  "token": "58090bc5-30f9-463f-8c6c-6ffd9d5b3e9d",
  "value": {
    "kind": "end"
  }
}


[Trace - 11:45:22 ] Received notification 'textDocument/publishDiagnostics'.
Params: 


[Trace - 11:45:23 ] Sending request 'workspace/executeCommand - (10)'.
Params: {
  "command": "_typescript.applyRefactoring",
  "arguments": [
    {
      "file": "c:\\code\\react\\rproj4\\scripts\\vproj4-vjtest.ts",
      "startLine": 348,
      "startOffset": 1,
      "endLine": 351,
      "endOffset": 1,
      "refactor": "Extract Symbol",
      "action": "function_scope_0"
    }
  ]
}


[Trace - 11:45:23 ] Sending notification 'textDocument/didChange'.
Params: {
  "textDocument": {
    "uri": "file:///c%3A/code/react/rproj4/scripts/vproj4-vjtest.ts",
    "version": 1
  },
  "contentChanges": [
    {
      "range": {
        "start": {
          "line": 351,
          "character": 0
        },
        "end": {
          "line": 351,
          "character": 0
        }
      },
      "rangeLength": 0,
      "text": "\n    function newFunction() {\n        const a = 1;\n        const b = 2;\n        const sum = a + b;\n        return sum;\n    }\n"
    }
  ]
}


[Trace - 11:45:23 ] Sending notification 'textDocument/didChange'.
Params: {
  "textDocument": {
    "uri": "file:///c%3A/code/react/rproj4/scripts/vproj4-vjtest.ts",
    "version": 2
  },
  "contentChanges": [
    {
      "range": {
        "start": {
          "line": 347,
          "character": 2
        },
        "end": {
          "line": 349,
          "character": 20
        }
      },
      "rangeLength": 48,
      "text": "const sum = newFunction();"
    }
  ]
}


[Trace - 11:45:23 ] Received request 'workspace/applyEdit - (2).
Params: {
  "edit": {
    "changes": {
      "file:///c%3A/code/react/rproj4/scripts/vproj4-vjtest.ts": [
        {
          "range": {
            "start": {
              "line": 351,
              "character": 0
            },
            "end": {
              "line": 351,
              "character": 0
            }
          },
          "newText": "\n    function newFunction() {\n        const a = 1;\n        const b = 2;\n        const sum = a + b;\n        return sum;\n    }\n"
        },
        {
          "range": {
            "start": {
              "line": 347,
              "character": 2
            },
            "end": {
              "line": 349,
              "character": 20
            }
          },
          "newText": "const sum = newFunction();"
        }
      ]
    }
  }
}


[Trace - 11:45:23 ] Sending response 'workspace/applyEdit - (2)'. Processing request took 6ms
Params: {
  "jsonrpc": "2.0",
  "id": 2,
  "result": {
    "applied": true
  }
}


[Trace - 11:45:23 ] Sending notification '$/cancelRequest'.
Params: {
  "id": 10
}


[Trace - 11:45:23 ] Sending request 'textDocument/prepareRename - (11)'.
Params: {
  "textDocument": {
    "uri": "file:///c%3A/code/react/rproj4/scripts/vproj4-vjtest.ts"
  },
  "position": {
    "line": 347,
    "character": 14
  }
}


[Trace - 11:45:23 ] Received response 'textDocument/prepareRename - (11)' in 17ms.
Result: {
  "start": {
    "line": 347,
    "character": 14
  },
  "end": {
    "line": 347,
    "character": 25
  }
}


[Trace - 11:45:24 ] Received notification 'textDocument/publishDiagnostics'.
Params: 


[Trace - 11:45:24 ] Received notification 'textDocument/publishDiagnostics'.
Params: 


[Trace - 11:45:24 ] Received notification 'textDocument/publishDiagnostics'.
Params: 


[Trace - 11:45:25 ] Sending request 'textDocument/rename - (12)'.
Params: {
  "textDocument": {
    "uri": "file:///c%3A/code/react/rproj4/scripts/vproj4-vjtest.ts"
  },
  "position": {
    "line": 347,
    "character": 14
  },
  "newName": "newFunction2"
}


[Trace - 11:45:25 ] Received response 'textDocument/rename - (12)' in 3ms.
Result: {
  "changes": {
    "file:///c%3A/code/react/rproj4/scripts/vproj4-vjtest.ts": [
      {
        "newText": "newFunction2",
        "range": {
          "start": {
            "line": 347,
            "character": 14
          },
          "end": {
            "line": 347,
            "character": 25
          }
        }
      },
      {
        "newText": "newFunction2",
        "range": {
          "start": {
            "line": 350,
            "character": 13
          },
          "end": {
            "line": 350,
            "character": 24
          }
        }
      }
    ]
  }
}


[Trace - 11:45:25 ] Sending notification 'textDocument/didChange'.
Params: {
  "textDocument": {
    "uri": "file:///c%3A/code/react/rproj4/scripts/vproj4-vjtest.ts",
    "version": 3
  },
  "contentChanges": [
    {
      "range": {
        "start": {
          "line": 350,
          "character": 13
        },
        "end": {
          "line": 350,
          "character": 24
        }
      },
      "rangeLength": 11,
      "text": "newFunction2"
    }
  ]
}


[Trace - 11:45:25 ] Sending notification 'textDocument/didChange'.
Params: {
  "textDocument": {
    "uri": "file:///c%3A/code/react/rproj4/scripts/vproj4-vjtest.ts",
    "version": 4
  },
  "contentChanges": [
    {
      "range": {
        "start": {
          "line": 347,
          "character": 14
        },
        "end": {
          "line": 347,
          "character": 25
        }
      },
      "rangeLength": 11,
      "text": "newFunction2"
    }
  ]
}


[Trace - 11:45:25 ] Received request '_typescript.rename - (3).
Params: {
  "textDocument": {
    "uri": "file:///c%3A/code/react/rproj4/scripts/vproj4-vjtest.ts"
  },
  "position": {
    "line": 347,
    "character": 14
  }
}


[Trace - 11:45:25 ] Sending response '_typescript.rename - (3)'. Processing request took 1516ms
Params: {
  "jsonrpc": "2.0",
  "id": 3,
  "result": null
}


[Trace - 11:45:25 ] Received response 'nil - (10)' in 0ms.
Result: null


[Trace - 11:45:25 ] Received notification 'textDocument/publishDiagnostics'.
Params: 


[Trace - 11:45:57 ] Sending request 'textDocument/hover - (13)'.
Params: {
  "textDocument": {
    "uri": "file:///c%3A/code/react/rproj4/scripts/vproj4-vjtest.ts"
  },
  "position": {
    "line": 347,
    "character": 14
  }
}


[Trace - 11:45:57 ] Sending request 'textDocument/codeAction - (14)'.
Params: {
  "textDocument": {
    "uri": "file:///c%3A/code/react/rproj4/scripts/vproj4-vjtest.ts"
  },
  "range": {
    "start": {
      "line": 347,
      "character": 0
    },
    "end": {
      "line": 347,
      "character": 14
    }
  },
  "context": {
    "diagnostics": []
  }
}


[Trace - 11:45:57 ] Sending request 'textDocument/documentHighlight - (15)'.
Params: {
  "textDocument": {
    "uri": "file:///c%3A/code/react/rproj4/scripts/vproj4-vjtest.ts"
  },
  "position": {
    "line": 347,
    "character": 14
  }
}


[Trace - 11:45:57 ] Received response 'textDocument/hover - (13)' in 19ms.
Result: {
  "contents": {
    "kind": "markdown",
    "value": "\n\n(local function) newFunction2(): number\n\n"
  },
  "range": {
    "start": {
      "line": 347,
      "character": 14
    },
    "end": {
      "line": 347,
      "character": 26
    }
  }
}


[Trace - 11:45:57 ] Received response 'textDocument/documentHighlight - (15)' in 60ms.
Result: [
  {
    "kind": 2,
    "range": {
      "start": {
        "line": 347,
        "character": 14
      },
      "end": {
        "line": 347,
        "character": 26
      }
    }
  },
  {
    "kind": 2,
    "range": {
      "start": {
        "line": 350,
        "character": 13
      },
      "end": {
        "line": 350,
        "character": 25
      }
    }
  }
]


[Trace - 11:45:57 ] Received response 'textDocument/codeAction - (14)' in 63ms.
Result: []

Anything else?

No response