improve logging of dynamicNode.

lua/luasnip/nodes/dynamicNode.lua

@@ -8,6 +8,8 @@ local FunctionNode = require("luasnip.nodes.functionNode").FunctionNode
 local SnippetNode = require("luasnip.nodes.snippet").SN
 local extend_decorator = require("luasnip.util.extend_decorator")
 local mark = require("luasnip.util.mark").mark
+local log = require("luasnip.util.log").new("dynamicNode")
+local describe = require("luasnip.util.log").describe
 
 local function D(pos, fn, args, opts)
 	opts = opts or {}
@@ -152,6 +154,11 @@ function DynamicNode:update()
 
 	if vim.deep_equal(self.last_args, str_args) then
 		-- no update, the args still match.
+		log.debug(
+			"skipping update of %s due to unchanged args (old: %s, new: %s)",
+			describe.node(self),
+			describe.inspect(self.last_args),
+			describe.inspect(str_args))
 		return
 	end
 
@@ -185,6 +192,7 @@ function DynamicNode:update()
 		self.snip:exit()
 		self.snip = nil
 
+		log.debug("content of %s before update: %s.", describe.node(self), describe.node_buftext(self))
 		-- focuses node.
 		self:set_text_raw({ "" })
 	else
@@ -246,6 +254,7 @@ function DynamicNode:update()
 	local from, to = self.mark:pos_begin_end_raw()
 	-- inserts nodes with extmarks false,false
 	tmp:put_initial(from)
+	log.debug("content of %s after update: %s.", describe.node(self), describe.node_buftext(self))
 	-- adjust gravity in left side of snippet, such that it matches the current
 	-- gravity of self.
 	tmp:subtree_set_pos_rgrav(to, -1, true)
@@ -434,6 +443,13 @@ function DynamicNode:update_restore()
 
 		tmp:update_restore()
 	else
+		log.debug(
+			"update_restore: rejecting stored data of %s (has snip: %s, snip is visible: %s, old args: %s, new args: %s)",
+			describe.node(self),
+			self.snip ~= nil,
+			self.snip and self.snip.visible,
+			describe.inspect(self.last_args),
+			describe.inspect(str_args))
 		self:update()
 	end
 end

lua/luasnip/nodes/node.lua

@@ -7,6 +7,8 @@ local key_indexer = require("luasnip.nodes.key_indexer")
 local types = require("luasnip.util.types")
 local opt_args = require("luasnip.nodes.optional_arg")
 local snippet_string = require("luasnip.nodes.util.snippet_string")
+local log = require("luasnip.util.log").new("node")
+local describe = require("luasnip.util.log").describe
 
 ---@class LuaSnip.Node
 ---@field key? any Key to identify the node with.
@@ -624,11 +626,14 @@ end
 -- self has to be visible/in the buffer.
 -- none of the node's ancestors may contain self.
 function Node:update_dependents(which)
+	log.debug("updating dependents of %s, selected %s", describe.node(self), describe.inspect(which, {newline =" ", indent = ""}))
 	-- false: don't set static
 	local dependents = node_util.collect_dependents(self, which, false)
 	for _, node in ipairs(dependents) do
 		if node.visible then
 			node:update_restore()
+		else
+			log.debug("skipping update of %s, it is not visible.", describe.node(node))
 		end
 	end
 end

lua/luasnip/util/log.lua

@@ -1,4 +1,5 @@
 local util = require("luasnip.util.util")
+local tbl = require("luasnip.util.table")
 
 -- older neovim-versions (even 0.7.2) do not have stdpath("log").
 local logpath_ok, logpath = pcall(vim.fn.stdpath, "log")
@@ -108,13 +109,84 @@ function M.set_loglevel(target_level)
 	end
 end
 
+local describe_key = {}
+
+local function mk_describe(f)
+	local wrapped_f = function(self)
+		return f(unpack(self.args))
+	end
+	return function(...)
+		return {
+			args = {...},
+			get = wrapped_f,
+			-- we want to be able to uniquely identify describe-objects, and the
+			-- simplest way (I think) is to set a unique key that is not known,
+			-- or even better, accessible by other modules.
+			[describe_key] = true
+		}
+	end
+end
+local function is_describe(t)
+	return type(t) == "table" and t[describe_key] ~= nil
+end
+
+M.describe = {
+	node_buftext = mk_describe(function(node)
+		local from, to = node:get_buf_position()
+		return vim.inspect(vim.api.nvim_buf_get_text(0, from[1], from[2], to[1], to[2], {}))
+	end),
+	node = mk_describe(function(node)
+		if not node.parent then
+			return ("snippet[trig: %s]"):format(node.trigger)
+		else
+			local snip_id = node.parent.snippet.trigger
+			-- render node readably.
+			local node_id = ""
+			if node.key then
+				node_id = "key: " .. node.key
+			elseif node.absolute_insert_position then
+				node_id = "insert_pos: " .. vim.inspect(node.absolute_insert_position)
+			else
+				node_id = "pos: " .. vim.inspect(node.absolute_position)
+			end
+			return ("node[%s, snippet: `%s`]"):format(node_id, snip_id)
+		end
+	end),
+	inspect = mk_describe(function(t, inspect_opts)
+		return vim.inspect(t, inspect_opts or {})
+	end),
+	traceback = mk_describe(function()
+		-- get position where log.debug is called with describe-object.
+		return debug.traceback("", 3)
+	end)
+}
+
+
+local function readable_format(msg, ...)
+	local args = tbl.pack(...)
+	for i, arg in ipairs(args) do
+		if is_describe(arg) then
+			args[i] = arg:get()
+		end
+	end
+	return msg:format(tbl.unpack(args))
+end
+
 function M.new(module_name)
 	local module_log = {}
 	for name, _ in pairs(log) do
 		module_log[name] = function(msg, ...)
 			-- don't immediately get the referenced function, we'd like to
 			-- allow changing the loglevel on-the-fly.
-			effective_log[name](module_name .. ": " .. msg:format(...))
+
+			-- also: make sure that whatever code called for logging does not
+			-- cause an error.
+			local ok, fmt_msg = pcall(readable_format, msg, ...)
+			if not ok then
+				effective_log.error(("log: error while formatting or writing message \"%s\": %s"):format(msg, fmt_msg))
+			end
+
+			effective_log[name](module_name .. ": " .. fmt_msg)
 		end
 	end
 	return module_log

lua/luasnip/util/table.lua

@@ -33,7 +33,13 @@ local function list_to_set(values)
 	return list
 end
 
+-- http://lua-users.org/wiki/VarargTheSecondClassCitizen
+local function pack2(...) return {n=select('#', ...), ...} end
+local function unpack2(t) return unpack(t, 1, t.n) end
+
 return {
 	list_to_set = list_to_set,
 	set_to_list = set_to_list,
+	pack = pack2,
+	unpack = unpack2
 }