feat(treesitter): improved logging (#23638)

- Add bindings to Treesitter ts_parser_set_logger and ts_parser_logger
- Add logfile with path STDPATH('log')/treesitter.c
- Rework existing LanguageTree loggin to use logfile
- Begin implementing log levels for vim.g.__ts_debug

runtime/lua/vim/fs.lua

@@ -73,10 +73,14 @@ function M.basename(file)
 end
 
 ---@private
-local function join_paths(...)
+---@param ... string
+---@return string
+function M._join_paths(...)
   return (table.concat({ ... }, '/'):gsub('//+', '/'))
 end
 
+local join_paths = M._join_paths
+
 ---@alias Iterator fun(): string?, string?
 
 --- Return an iterator over the files and directories located in {path}

runtime/lua/vim/treesitter/_meta.lua

@@ -45,6 +45,8 @@ function TSNode:_rawquery(query, captures, start, end_, opts) end
 ---@return fun(): string, any
 function TSNode:_rawquery(query, captures, start, end_, opts) end
 
+---@alias TSLoggerCallback fun(logtype: 'parse'|'lex', msg: string)
+
 ---@class TSParser
 ---@field parse fun(self: TSParser, tree: TSTree?, source: integer|string, include_bytes: boolean?): TSTree, integer[]
 ---@field reset fun(self: TSParser)
@@ -52,6 +54,8 @@ function TSNode:_rawquery(query, captures, start, end_, opts) end
 ---@field set_included_ranges fun(self: TSParser, ranges: Range6[])
 ---@field set_timeout fun(self: TSParser, timeout: integer)
 ---@field timeout fun(self: TSParser): integer
+---@field _set_logger fun(self: TSParser, lex: boolean, parse: boolean, cb: TSLoggerCallback)
+---@field _logger fun(self: TSParser): TSLoggerCallback
 
 ---@class TSTree
 ---@field root fun(self: TSTree): TSNode

runtime/lua/vim/treesitter/languagetree.lua

@@ -31,8 +31,17 @@
 --- shouldn't be done directly in the change callback anyway as they will be very frequent. Rather
 --- a plugin that does any kind of analysis on a tree should use a timer to throttle too frequent
 --- updates.
+---
+
+-- Debugging:
+--
+-- vim.g.__ts_debug levels:
+--    - 1. Messages from languagetree.lua
+--    - 2. Parse messages from treesitter
+--    - 2. Lex messages from treesitter
+--
+-- Log file can be found in stdpath('log')/treesitter.log
 
-local api = vim.api
 local query = require('vim.treesitter.query')
 local language = require('vim.treesitter.language')
 local Range = require('vim.treesitter._range')
@@ -75,6 +84,8 @@ local TSCallbackNames = {
 ---@field private _source (integer|string) Buffer or string to parse
 ---@field private _trees TSTree[] Reference to parsed tree (one for each language)
 ---@field private _valid boolean|table<integer,boolean> If the parsed tree is valid
+---@field private _logger? fun(logtype: string, msg: string)
+---@field private _logfile? file*
 local LanguageTree = {}
 
 ---@class LanguageTreeOpts
@@ -114,6 +125,10 @@ function LanguageTree.new(source, lang, opts)
     _callbacks_rec = {},
   }, LanguageTree)
 
+  if vim.g.__ts_debug and type(vim.g.__ts_debug) == 'number' then
+    self:_set_logger()
+  end
+
   for _, name in pairs(TSCallbackNames) do
     self._callbacks[name] = {}
     self._callbacks_rec[name] = {}
@@ -122,6 +137,33 @@ function LanguageTree.new(source, lang, opts)
   return self
 end
 
+function LanguageTree:_set_logger()
+  local source = self:source()
+  source = type(source) == 'string' and 'text' or tostring(source)
+
+  local lang = self:lang()
+
+  local logfilename = vim.fs._join_paths(vim.fn.stdpath('log'), 'treesitter.log')
+
+  local logfile, openerr = io.open(logfilename, 'a+')
+
+  if not logfile or openerr then
+    error(string.format('Could not open file (%s) for logging: %s', logfilename, openerr))
+    return
+  end
+
+  self._logfile = logfile
+
+  self._logger = function(logtype, msg)
+    self._logfile:write(string.format('%s:%s:(%s) %s\n', source, lang, logtype, msg))
+    self._logfile:flush()
+  end
+
+  local log_lex = vim.g.__ts_debug >= 3
+  local log_parse = vim.g.__ts_debug >= 2
+  self._parser:_set_logger(log_lex, log_parse, self._logger)
+end
+
 ---@private
 ---Measure execution time of a function
 ---@generic R1, R2, R3
@@ -139,7 +181,11 @@ end
 ---@private
 ---@vararg any
 function LanguageTree:_log(...)
-  if vim.g.__ts_debug == nil then
+  if not self._logger then
+    return
+  end
+
+  if not vim.g.__ts_debug or vim.g.__ts_debug < 1 then
     return
   end
 
@@ -150,19 +196,17 @@ function LanguageTree:_log(...)
 
   local info = debug.getinfo(2, 'nl')
   local nregions = #self:included_regions()
-  local prefix =
-    string.format('%s:%d: [%s:%d] ', info.name, info.currentline, self:lang(), nregions)
+  local prefix = string.format('%s:%d: (#regions=%d) ', info.name, info.currentline, nregions)
 
-  api.nvim_out_write(prefix)
+  local msg = { prefix }
   for _, x in ipairs(args) do
     if type(x) == 'string' then
-      api.nvim_out_write(x)
+      msg[#msg + 1] = x
     else
-      api.nvim_out_write(vim.inspect(x, { newline = ' ', indent = '' }))
+      msg[#msg + 1] = vim.inspect(x, { newline = ' ', indent = '' })
     end
-    api.nvim_out_write(' ')
   end
-  api.nvim_out_write('\n')
+  self._logger('nvim', table.concat(msg, ' '))
 end
 
 --- Invalidates this parser and all its children
@@ -876,6 +920,11 @@ end
 function LanguageTree:_on_detach(...)
   self:invalidate(true)
   self:_do_callback('detach', ...)
+  if self._logfile then
+    self._logger('nvim', 'detaching')
+    self._logger = nil
+    self._logfile:close()
+  end
 end
 
 --- Registers callbacks for the |LanguageTree|.

src/nvim/lua/treesitter.c

@@ -20,6 +20,7 @@
 #include "nvim/api/private/helpers.h"
 #include "nvim/buffer_defs.h"
 #include "nvim/globals.h"
+#include "nvim/lua/executor.h"
 #include "nvim/lua/treesitter.h"
 #include "nvim/macros.h"
 #include "nvim/map.h"
@@ -43,6 +44,13 @@ typedef struct {
   int max_match_id;
 } TSLua_cursor;
 
+typedef struct {
+  LuaRef cb;
+  lua_State *lstate;
+  bool lex;
+  bool parse;
+} TSLuaLoggerOpts;
+
 #ifdef INCLUDE_GENERATED_DECLARATIONS
 # include "lua/treesitter.c.generated.h"
 #endif
@@ -56,6 +64,8 @@ static struct luaL_Reg parser_meta[] = {
   { "included_ranges", parser_get_ranges },
   { "set_timeout", parser_set_timeout },
   { "timeout", parser_get_timeout },
+  { "_set_logger", parser_set_logger },
+  { "_logger", parser_get_logger },
   { NULL, NULL }
 };
 
@@ -322,6 +332,12 @@ static int parser_gc(lua_State *L)
     return 0;
   }
 
+  TSLogger logger = ts_parser_logger(*p);
+  if (logger.log) {
+    TSLuaLoggerOpts *opts = (TSLuaLoggerOpts *)logger.payload;
+    xfree(opts);
+  }
+
   ts_parser_delete(*p);
   return 0;
 }
@@ -669,7 +685,80 @@ static int parser_get_timeout(lua_State *L)
   }
 
   lua_pushinteger(L, (long)ts_parser_timeout_micros(*p));
+  return 1;
+}
+
+static void logger_cb(void *payload, TSLogType logtype, const char *s)
+{
+  TSLuaLoggerOpts *opts = (TSLuaLoggerOpts *)payload;
+  if ((!opts->lex && logtype == TSLogTypeLex)
+      || (!opts->parse && logtype == TSLogTypeParse)) {
+    return;
+  }
+
+  lua_State *lstate = opts->lstate;
+
+  nlua_pushref(lstate, opts->cb);
+  lua_pushstring(lstate, logtype == TSLogTypeParse ? "parse" : "lex");
+  lua_pushstring(lstate, s);
+  if (lua_pcall(lstate, 2, 0, 0)) {
+    luaL_error(lstate, "Error executing treesitter logger callback");
+  }
+}
+
+static int parser_set_logger(lua_State *L)
+{
+  TSParser **p = parser_check(L, 1);
+  if (!p) {
     return 0;
+  }
+
+  if (!lua_isboolean(L, 2)) {
+    return luaL_argerror(L, 2, "boolean expected");
+  }
+
+  if (!lua_isboolean(L, 3)) {
+    return luaL_argerror(L, 3, "boolean expected");
+  }
+
+  if (!lua_isfunction(L, 4)) {
+    return luaL_argerror(L, 4, "function expected");
+  }
+
+  TSLuaLoggerOpts *opts = xmalloc(sizeof(TSLuaLoggerOpts));
+
+  *opts = (TSLuaLoggerOpts){
+    .lex = lua_toboolean(L, 2),
+    .parse = lua_toboolean(L, 3),
+    .cb = nlua_ref_global(L, 4),
+    .lstate = L
+  };
+
+  TSLogger logger = {
+    .payload = (void *)opts,
+    .log = logger_cb
+  };
+
+  ts_parser_set_logger(*p, logger);
+  return 0;
+}
+
+static int parser_get_logger(lua_State *L)
+{
+  TSParser **p = parser_check(L, 1);
+  if (!p) {
+    return 0;
+  }
+
+  TSLogger logger = ts_parser_logger(*p);
+  if (logger.log) {
+    TSLuaLoggerOpts *opts = (TSLuaLoggerOpts *)logger.payload;
+    nlua_pushref(L, opts->cb);
+  } else {
+    lua_pushnil(L);
+  }
+
+  return 1;
 }
 
 // Tree methods