diff --git a/README.md b/README.md index 0f08877..4b420a5 100644 --- a/README.md +++ b/README.md @@ -262,6 +262,11 @@ require("sshfs").setup({ preferred_picker = "auto", -- one of: "auto", "snacks", "fzf-lua", "telescope", "mini" }, }, + debug = { + enabled = false, -- write SSH/SSHFS diagnostics to a log file + log_file = vim.fn.stdpath("log") .. "/sshfs.nvim.log", + max_size = 1048576, -- rotate to .1 past this size (0 disables) + }, lead_prefix = "m", -- change keymap prefix (default: m) keymaps = { mount = "mm", -- creates an ssh connection and mounts via sshfs @@ -296,6 +301,7 @@ require("sshfs").setup({ - `:SSHDisconnectAll` - Unmount all hosts - `:SSHConfig` - Edit SSH config files - `:SSHReload` - Reload SSH configuration +- `:SSHDebug [on|off]` - Toggle debug logging for the current Neovim session - `:SSHFiles` - Find files with auto-detected picker - `:SSHGrep [pattern]` - Search files with auto-detected tool - `:SSHLiveFind [pattern]` - Stream remote `find`/`fd` results over SSH (snacks/fzf-lua/telescope/mini) @@ -305,6 +311,8 @@ require("sshfs").setup({ - `:SSHCommand [cmd]` - Run custom command (e.g. `Oil`, `Telescope`) - `:SSHTerminal` - Open terminal session (reuses auth) +Debug logging records SSH authentication, ControlMaster, remote-home resolution, and SSHFS subprocess diagnostics. See [`docs/debug-logging.md`](docs/debug-logging.md) for details. + ## 🎹 Key Mapping Default keybindings under `m` (fully customizable): diff --git a/docs/debug-logging.md b/docs/debug-logging.md new file mode 100644 index 0000000..a5b6589 --- /dev/null +++ b/docs/debug-logging.md @@ -0,0 +1,30 @@ +# Debug logging + +Debug logging is disabled by default. Enable it in setup: + +```lua +require("sshfs").setup({ + debug = { + enabled = true, + log_file = vim.fn.stdpath("log") .. "/sshfs.nvim.log", + max_size = 1048576, + }, +}) +``` + +Once the log passes `max_size` bytes it is moved to `.1` and a fresh file is started, so only the last two generations are kept. Set `max_size = 0` to disable rotation and let the file grow. + +You can also change debug logging for the current Neovim session without changing configuration: + +```vim +:SSHDebug +:SSHDebug on +:SSHDebug off +``` + +With no argument, `:SSHDebug` toggles logging. The command reports the active log path. + +When enabled, sshfs.nvim records timestamped diagnostics for SSH authentication, ControlMaster setup/cleanup, remote home resolution, and SSHFS mount subprocesses, including exit codes, stdout, and stderr. No log file writes are performed while debug logging is disabled. + +> [!WARNING] +> Debug logs may contain hostnames, usernames, filesystem paths, SSH/SSHFS output, or authentication-related messages. Review logs before sharing them publicly. diff --git a/lua/sshfs/api.lua b/lua/sshfs/api.lua index 619c517..6eef33c 100644 --- a/lua/sshfs/api.lua +++ b/lua/sshfs/api.lua @@ -114,6 +114,31 @@ Api.reload = function() Session.reload() end +--- Toggle debug logging for the current Neovim session +--- @param mode string|nil Optional explicit mode: "on" or "off" +Api.debug = function(mode) + local Logger = require("sshfs.lib.logger") + local enabled + + if mode == nil or mode == "" then + enabled = Logger.toggle() + elseif mode == "on" then + Logger.enable() + enabled = true + elseif mode == "off" then + Logger.disable() + enabled = false + else + vim.notify("Usage: :SSHDebug [on|off]", vim.log.levels.ERROR) + return + end + + vim.notify( + string.format("sshfs.nvim debug logging %s: %s", enabled and "enabled" or "disabled", Logger.path()), + vim.log.levels.INFO + ) +end + --- Browse remote files using native file browser --- @param opts table|nil Picker options Api.find_files = function(opts) @@ -373,6 +398,16 @@ Api.setup = function() Api.reload() end, { desc = "Reload SSH configuration" }) + vim.api.nvim_create_user_command("SSHDebug", function(opts) + Api.debug(opts.args) + end, { + nargs = "?", + complete = function() + return { "on", "off" } + end, + desc = "Toggle sshfs.nvim debug logging", + }) + vim.api.nvim_create_user_command("SSHDisconnect", function() Api.unmount() end, { desc = "Disconnect from current SSH host" }) diff --git a/lua/sshfs/config.lua b/lua/sshfs/config.lua index 74f9b22..7debd64 100644 --- a/lua/sshfs/config.lua +++ b/lua/sshfs/config.lua @@ -82,6 +82,11 @@ local DEFAULT_CONFIG = { preferred_picker = "auto", -- "auto", "telescope", "fzf-lua", "snacks", "mini" }, }, + debug = { + enabled = false, -- Enable debug logging + log_file = vim.fn.stdpath("log") .. "/sshfs.nvim.log", -- Debug log destination + max_size = 1048576, -- Rotate the log to .1 once it passes this many bytes + }, keymaps = nil, -- Override individual keymaps (e.g., {mount = "mm", unmount = "mu"}) lead_prefix = "m", -- Prefix for default keymaps } diff --git a/lua/sshfs/init.lua b/lua/sshfs/init.lua index 6451a53..81fe934 100644 --- a/lua/sshfs/init.lua +++ b/lua/sshfs/init.lua @@ -10,6 +10,9 @@ function App.setup(user_opts) Config.setup(user_opts) local opts = Config.get() + local Logger = require("sshfs.lib.logger") + Logger.debug("sshfs.nvim initialized", { log_file = Logger.path() }) + -- Initialize other modules local MountPoint = require("sshfs.lib.mount_point") MountPoint.get_or_create() @@ -84,6 +87,7 @@ App.explore = Api.explore App.change_dir = Api.change_dir App.ssh_terminal = Api.ssh_terminal App.command = Api.command +App.debug = Api.debug App.test = Api.test return App diff --git a/lua/sshfs/lib/logger.lua b/lua/sshfs/lib/logger.lua new file mode 100644 index 0000000..e56752c --- /dev/null +++ b/lua/sshfs/lib/logger.lua @@ -0,0 +1,158 @@ +-- lua/sshfs/lib/logger.lua +-- Centralized debug logging for sshfs.nvim + +local Logger = {} +local runtime_enabled = nil +local last_write_error = nil + +local function get_config() + -- Logging can be reached before Config.setup() has run, so tolerate no config. + local ok, config = pcall(function() + return require("sshfs.config").get() + end) + if not ok or type(config) ~= "table" then return {} end + return config.debug or {} +end + +local NAMED_ESCAPES = { ["\r"] = "\\r", ["\n"] = "\\n", ["\t"] = "\\t" } + +local function escape_log_value(value) + -- Remote output reaches this file, so no control byte may survive to a terminal. + return ( + tostring(value):gsub("%c", function(char) + return NAMED_ESCAPES[char] or string.format("\\x%02x", char:byte()) + end) + ) +end + +local function ensure_parent_dir(path) + local parent = vim.fn.fnamemodify(path, ":h") + if parent ~= "" and vim.fn.isdirectory(parent) == 0 then + local result = vim.fn.mkdir(parent, "p", "0700") + if result == 0 and vim.fn.isdirectory(parent) == 0 then error("could not create log directory: " .. parent) end + end +end + +--- Move the log aside once it passes max_size, keeping a single previous generation +local function rotate_if_needed(path, max_size) + if not max_size or max_size <= 0 then return end + + local uv = vim.uv or vim.loop + local stat = uv.fs_stat(path) + if stat and stat.size >= max_size then uv.fs_rename(path, path .. ".1") end +end + +local function write_log_line(path, line) + local uv = vim.uv or vim.loop + local fd, open_err = uv.fs_open(path, "a", 384) + if not fd then error("could not open log file: " .. tostring(open_err)) end + + local chmod_ok, chmod_err = uv.fs_fchmod(fd, 384) + if not chmod_ok then + uv.fs_close(fd) + error("could not set log file permissions: " .. tostring(chmod_err)) + end + + local written, write_err = uv.fs_write(fd, line .. "\n", -1) + uv.fs_close(fd) + if not written then error("could not write log file: " .. tostring(write_err)) end +end + +local function serialize_context(context) + if not context then return "" end + if type(context) ~= "table" then return " " .. escape_log_value(context) end + + local parts = {} + for key, value in pairs(context) do + if value ~= nil then + local rendered = type(value) == "table" and vim.inspect(value) or tostring(value) + table.insert(parts, string.format("%s=%s", key, escape_log_value(rendered))) + end + end + table.sort(parts) + + return #parts > 0 and (" " .. table.concat(parts, " ")) or "" +end + +local function notify_write_failure(err) + local message = tostring(err) + if message == last_write_error then return end + last_write_error = message + + vim.schedule(function() + vim.notify("sshfs.nvim: failed to write debug log: " .. message, vim.log.levels.ERROR) + end) +end + +function Logger.is_enabled() + if runtime_enabled ~= nil then return runtime_enabled end + return get_config().enabled == true +end + +function Logger.set_enabled(enabled) + runtime_enabled = enabled == true +end + +function Logger.enable() + Logger.set_enabled(true) +end + +function Logger.disable() + Logger.set_enabled(false) +end + +function Logger.toggle() + Logger.set_enabled(not Logger.is_enabled()) + return Logger.is_enabled() +end + +function Logger.path() + local config = get_config() + return vim.fn.expand(config.log_file or (vim.fn.stdpath("log") .. "/sshfs.nvim.log")) +end + +function Logger.log(level, message, context) + if not Logger.is_enabled() then return end + + -- Callers pass a builder when the context costs something to assemble. + if type(context) == "function" then context = context() end + + local path = Logger.path() + local line = string.format( + "%s [%s] %s%s", + os.date("%Y-%m-%d %H:%M:%S"), + string.upper(level or "debug"), + escape_log_value(message), + serialize_context(context) + ) + + local ok, result = pcall(function() + ensure_parent_dir(path) + rotate_if_needed(path, get_config().max_size) + write_log_line(path, line) + end) + + if not ok then + notify_write_failure(result) + else + last_write_error = nil + end +end + +function Logger.debug(message, context) + Logger.log("debug", message, context) +end + +function Logger.info(message, context) + Logger.log("info", message, context) +end + +function Logger.warn(message, context) + Logger.log("warn", message, context) +end + +function Logger.error(message, context) + Logger.log("error", message, context) +end + +return Logger diff --git a/lua/sshfs/lib/ssh.lua b/lua/sshfs/lib/ssh.lua index cf9bd66..2c51063 100644 --- a/lua/sshfs/lib/ssh.lua +++ b/lua/sshfs/lib/ssh.lua @@ -2,6 +2,7 @@ -- SSH operations: terminal sessions, command execution, and connection utilities local Ssh = {} +local Logger = require("sshfs.lib.logger") --- Return the first non-empty process output after trimming whitespace. --- @param ... string|nil Process output values in priority order @@ -21,13 +22,19 @@ local function get_or_create_socket_dir() local Config = require("sshfs.config") local socket_dir = Config.get_socket_dir() - if vim.fn.isdirectory(socket_dir) == 1 then return socket_dir, nil end + if vim.fn.isdirectory(socket_dir) == 1 then + Logger.debug("SSH socket directory available", { socket_dir = socket_dir }) + return socket_dir, nil + end local ok, err = pcall(vim.fn.mkdir, socket_dir, "p", "0700") if ok then + Logger.debug("Created SSH socket directory", { socket_dir = socket_dir }) return socket_dir, nil else - return nil, "Failed to create socket directory: " .. socket_dir .. " (" .. tostring(err) .. ")" + local error_msg = "Failed to create socket directory: " .. socket_dir .. " (" .. tostring(err) .. ")" + Logger.error(error_msg) + return nil, error_msg end end @@ -76,6 +83,10 @@ local function normalize_host(host) return { name = host } end +local function host_label(host) + return normalize_host(host).name +end + local function append_host_options(cmd, host) host = normalize_host(host) if host.port then vim.list_extend(cmd, { "-p", tostring(host.port) }) end @@ -213,6 +224,7 @@ end ---@param remote_path string|nil Optional remote path to cd into function Ssh.open_terminal(host, remote_path) local ssh_cmd = Ssh.build_command(host, remote_path) + Logger.debug("Opening SSH terminal", { host = host_label(host), remote_path = remote_path }) vim.cmd("enew") vim.fn.jobstart(ssh_cmd, { term = true }) vim.cmd("startinsert") @@ -225,10 +237,20 @@ end ---@param callback function Callback(home_path: string|nil, error: string|nil) function Ssh.get_remote_home(host, callback) local cmd = Ssh.build_home_command(host) + Logger.debug("Resolving remote home", function() + return { host = host_label(host), command = table.concat(cmd, " ") } + end) -- Execute asynchronously vim.system(cmd, { text = true }, function(obj) vim.schedule(function() + Logger.debug("Remote home command completed", { + host = host_label(host), + exit_code = obj.code, + stdout = vim.trim(obj.stdout or ""), + stderr = vim.trim(obj.stderr or ""), + }) + if obj.code == 0 then local home_path = vim.trim(obj.stdout or "") if home_path ~= "" and home_path:sub(1, 1) == "/" then @@ -250,7 +272,16 @@ end ---@return boolean True if cleanup command was sent successfully function Ssh.cleanup_control_master(host) -- Execute synchronously (must complete before nvim exit) - vim.fn.system(Ssh.build_control_command(host, "exit")) + local cmd = Ssh.build_control_command(host, "exit") + Logger.debug("Closing SSH ControlMaster", function() + return { host = host_label(host), command = table.concat(cmd, " ") } + end) + local output = vim.fn.system(cmd) + Logger.debug("SSH ControlMaster cleanup completed", { + host = host_label(host), + exit_code = vim.v.shell_error, + output = vim.trim(output or ""), + }) -- Ignore exit code - socket may already be closed/expired return true end @@ -271,10 +302,20 @@ function Ssh.try_batch_connect(host, callback) -- Build and execute the batch command asynchronously local cmd = Ssh.build_batch_command(host) + Logger.debug("Starting batch SSH authentication", function() + return { host = host_label(host), command = table.concat(cmd, " ") } + end) vim.system(cmd, { text = true }, function(obj) vim.schedule(function() local success = obj.code == 0 local error_msg = success and nil or (first_nonempty_output(obj.stderr, obj.stdout) or "Unknown error") + Logger.debug("Batch SSH authentication completed", { + host = host_label(host), + success = success, + exit_code = obj.code, + stdout = vim.trim(obj.stdout or ""), + stderr = vim.trim(obj.stderr or ""), + }) callback(success, obj.code, error_msg) end) end) @@ -289,6 +330,7 @@ function Ssh.open_auth_terminal(host, callback) -- Ensure socket directory exists before attempting connection local socket_dir, err = get_or_create_socket_dir() if not socket_dir then + Logger.error("Unable to start interactive SSH authentication", { host = host_label(host), error = err }) vim.notify("sshfs.nvim: " .. err, vim.log.levels.ERROR) vim.schedule(function() callback(false, 1) @@ -301,8 +343,18 @@ function Ssh.open_auth_terminal(host, callback) local cmd = Ssh.build_auth_command(host_obj) -- Open authentication terminal window + Logger.debug("Opening interactive SSH authentication", function() + return { host = host_label(host), command = table.concat(cmd, " ") } + end) local Terminal = require("sshfs.ui.terminal") - Terminal.open_auth_floating(cmd, host_obj.name, callback) + Terminal.open_auth_floating(cmd, host_obj.name, function(success, exit_code) + Logger.debug("Interactive SSH authentication completed", { + host = host_label(host), + success = success, + exit_code = exit_code, + }) + callback(success, exit_code) + end) end return Ssh diff --git a/lua/sshfs/lib/sshfs.lua b/lua/sshfs/lib/sshfs.lua index 104d648..e3548c4 100644 --- a/lua/sshfs/lib/sshfs.lua +++ b/lua/sshfs/lib/sshfs.lua @@ -2,6 +2,8 @@ -- SSHFS wrapper with authentication workflows local Sshfs = {} +local Logger = require("sshfs.lib.logger") + local sshfs_major_version local sshfs_version_warning_shown = false @@ -142,9 +144,27 @@ end local function mount_with_path(host, mount_point, remote_path_suffix, callback) local cmd = Sshfs.build_mount_command(host, mount_point, remote_path_suffix) + Logger.debug("Starting SSHFS mount", { + host = host.name, + user = host.user, + remote_path = remote_path_suffix, + mount_point = mount_point, + command = table.concat(cmd, " "), + }) + -- Execute mount command asynchronously vim.system(cmd, { text = true }, function(obj) vim.schedule(function() + local stdout = vim.trim(obj.stdout or "") + local stderr = vim.trim(obj.stderr or "") + Logger.debug("SSHFS mount completed", { + host = host.name, + mount_point = mount_point, + exit_code = obj.code, + stdout = stdout, + stderr = stderr, + }) + if obj.code == 0 then callback({ success = true, @@ -152,12 +172,17 @@ local function mount_with_path(host, mount_point, remote_path_suffix, callback) resolved_path = remote_path_suffix, }) else - local stderr = vim.trim(obj.stderr or "") - local stdout = vim.trim(obj.stdout or "") local error_output = stderr ~= "" and stderr or stdout local message = string.format("Mount failed (exit code: %d)", obj.code) if error_output ~= "" then message = message .. ": " .. error_output end + Logger.error("SSHFS mount failed", { + host = host.name, + mount_point = mount_point, + exit_code = obj.code, + error = error_output ~= "" and error_output or "Unknown error", + }) + callback({ success = false, stage = "mount", @@ -188,9 +213,19 @@ local function mount_via_socket(host, mount_point, remote_path_suffix, callback) if actual_home then -- Replace ~ with the actual home path and mount local resolved_path = remote_path_suffix:gsub("^~", actual_home) + Logger.debug("Resolved remote home path", { + host = host.name, + requested_path = remote_path_suffix, + resolved_path = resolved_path, + }) mount_with_path(host, mount_point, resolved_path, callback) else -- Fall back to letting SSHFS try to handle it (may fail for symlinks) + Logger.warn("Could not resolve remote home path", { + host = host.name, + requested_path = remote_path_suffix, + error = error or "unknown error", + }) vim.notify( "Could not resolve home directory, attempting mount anyway: " .. (error or "unknown error"), vim.log.levels.WARN @@ -211,11 +246,19 @@ end --- @param callback function Callback function(result: table) - result has fields: success, message, resolved_path function Sshfs.authenticate_and_mount(host, mount_point, remote_path_suffix, callback) local Ssh = require("sshfs.lib.ssh") + Logger.debug("Starting SSH authentication and mount", { + host = host.name, + user = host.user, + port = host.port, + remote_path = remote_path_suffix, + mount_point = mount_point, + }) vim.notify("Connecting to " .. host.name .. "...", vim.log.levels.INFO) -- Try batch connection (non-interactive) Ssh.try_batch_connect(host, function(success, exit_code, error) if success then + Logger.debug("Batch authentication succeeded; mounting via socket", { host = host.name }) mount_via_socket(host, mount_point, remote_path_suffix, callback) return end @@ -236,12 +279,25 @@ function Sshfs.authenticate_and_mount(host, mount_point, remote_path_suffix, cal end -- Batch failed, try interactive terminal + Logger.debug("Batch authentication failed; falling back to interactive authentication", { + host = host.name, + exit_code = exit_code, + error = error, + }) + Ssh.open_auth_terminal(host, function(term_success, term_exit_code) if term_success then + Logger.debug("Interactive authentication succeeded; mounting via socket", { host = host.name }) mount_via_socket(host, mount_point, remote_path_suffix, callback) return end + Logger.error("SSH authentication failed", { + host = host.name, + batch_exit_code = exit_code, + exit_code = term_exit_code, + }) + local message = string.format( "SSH authentication failed for %s (batch exit code: %d, interactive exit code: %d)", host.name, diff --git a/tests/debug_instrumentation_spec.lua b/tests/debug_instrumentation_spec.lua new file mode 100644 index 0000000..6438c88 --- /dev/null +++ b/tests/debug_instrumentation_spec.lua @@ -0,0 +1,114 @@ +-- tests/debug_instrumentation_spec.lua +-- What debug logging actually records for a connection attempt +-- +-- Issue #9 was hard to diagnose because subprocess details were discarded. +-- These cover that the details survive when logging is on, and that nothing is +-- recorded when it is off. + +--- Run a connection attempt with logging configured, returning the log lines +--- @param opts table {enabled, batch_success, mount_code, mount_stderr} +--- @return table lines +local function connect_and_read_log(opts) + stub.reload() + local log_path = vim.fn.tempname() .. "/sshfs.nvim.log" + require("sshfs.config").setup({ debug = { enabled = opts.enabled, log_file = log_path } }) + + package.loaded["sshfs.lib.ssh"] = { + try_batch_connect = function(_, callback) + callback(opts.batch_success or false, opts.batch_success and 0 or 255, "Permission denied (publickey).") + end, + open_auth_terminal = function(_, callback) + callback(false, 1) + end, + build_command_string = function() + return "ssh" + end, + } + + stub.notifications() + stub.set("schedule", function(fn) + fn() + end) + stub.set("system", function(_, _, callback) + local result = { code = opts.mount_code or 0, stdout = "", stderr = opts.mount_stderr or "" } + if callback then callback(result) end + return { + wait = function() + return result + end, + } + end) + + require("sshfs.lib.sshfs").authenticate_and_mount( + { name = "example.com", user = "deploy" }, + "/home/tester/mnt/example", + "/srv/app", + function() end + ) + stub.restore_all() + + local lines = vim.fn.filereadable(log_path) == 1 and vim.fn.readfile(log_path) or {} + vim.fn.delete(vim.fn.fnamemodify(log_path, ":h"), "rf") + return lines +end + +--- Find the first log line containing a substring +local function line_with(lines, needle) + for _, line in ipairs(lines) do + if line:find(needle, 1, true) then return line end + end + return nil +end + +describe("connection diagnostics with logging enabled", function() + it("records the mount attempt with its host and target", function() + local lines = connect_and_read_log({ enabled = true, batch_success = true }) + local line = line_with(lines, "Starting SSHFS mount") + + expect.truthy(line, "the mount attempt must be recorded") + expect.contains(line, "host=example.com") + expect.contains(line, "mount_point=/home/tester/mnt/example") + end) + + it("records the exit code and stderr of a failed mount", function() + local lines = connect_and_read_log({ + enabled = true, + batch_success = true, + mount_code = 1, + mount_stderr = "read: Connection reset by peer", + }) + local line = line_with(lines, "SSHFS mount failed") + + expect.truthy(line) + expect.contains(line, "exit_code=1") + expect.contains(line, "Connection reset by peer") + end) + + it("records the fallback from batch to interactive authentication", function() + local lines = connect_and_read_log({ enabled = true, batch_success = false }) + + expect.truthy(line_with(lines, "falling back to interactive authentication")) + expect.truthy(line_with(lines, "Permission denied"), "the SSH reason must be preserved") + end) + + it("records an authentication failure", function() + local lines = connect_and_read_log({ enabled = true, batch_success = false }) + local line = line_with(lines, "SSH authentication failed") + + expect.truthy(line) + expect.contains(line, "[ERROR]") + end) +end) + +describe("connection diagnostics with logging disabled", function() + it("records nothing at all", function() + local lines = connect_and_read_log({ + enabled = false, + batch_success = true, + mount_code = 1, + mount_stderr = "read: Connection reset by peer", + }) + + expect.eq(lines, {}, "normal usage must not write a log file") + end) +end) diff --git a/tests/logger_spec.lua b/tests/logger_spec.lua new file mode 100644 index 0000000..80a1cd2 --- /dev/null +++ b/tests/logger_spec.lua @@ -0,0 +1,336 @@ +-- tests/logger_spec.lua +-- Opt-in debug logging: gating, formatting, and runtime toggling + +--- Load the logger against a temporary log file +--- @param debug_config table|nil Value for the `debug` configuration table +--- @return table Logger, string log_path +local function load_logger(debug_config) + stub.reload() + local log_path = vim.fn.tempname() .. "/sshfs.nvim.log" + if debug_config then debug_config.log_file = debug_config.log_file or log_path end + require("sshfs.config").setup({ debug = debug_config }) + return require("sshfs.lib.logger"), log_path +end + +--- Read a log file, returning an empty list when it was never created +local function read_log(path) + if vim.fn.filereadable(path) == 0 then return {} end + return vim.fn.readfile(path) +end + +local function cleanup(path) + vim.fn.delete(vim.fn.fnamemodify(path, ":h"), "rf") +end + +describe("debug logging gate", function() + it("writes nothing at all while disabled", function() + local Logger, log_path = load_logger({ enabled = false }) + + Logger.debug("a message") + Logger.error("another message") + + expect.eq(vim.fn.filereadable(log_path), 0, "a disabled logger must not even create the file") + cleanup(log_path) + end) + + it("writes when enabled through configuration", function() + local Logger, log_path = load_logger({ enabled = true }) + + Logger.debug("a message") + + expect.eq(#read_log(log_path), 1) + cleanup(log_path) + end) + + it("is disabled by default", function() + stub.reload() + require("sshfs.config").setup({}) + + expect.falsy(require("sshfs.lib.logger").is_enabled()) + end) + + it("does not raise when used before setup has run", function() + stub.reload() + local Logger = require("sshfs.lib.logger") + + expect.no_error(function() + Logger.is_enabled() + end, "configuration may not exist yet") + expect.no_error(function() + Logger.path() + end) + end) +end) + +describe("runtime toggling", function() + it("enables logging without rewriting configuration", function() + local Logger, log_path = load_logger({ enabled = false }) + + expect.truthy(Logger.toggle()) + Logger.debug("now recorded") + + expect.eq(#read_log(log_path), 1) + expect.falsy(require("sshfs.config").get().debug.enabled, "user configuration stays untouched") + cleanup(log_path) + end) + + it("disables logging that configuration had enabled", function() + local Logger, log_path = load_logger({ enabled = true }) + + Logger.disable() + Logger.debug("not recorded") + + expect.eq(read_log(log_path), {}) + cleanup(log_path) + end) + + it("toggles back and forth", function() + local Logger, log_path = load_logger({ enabled = false }) + + expect.truthy(Logger.toggle()) + expect.falsy(Logger.toggle()) + expect.truthy(Logger.toggle()) + cleanup(log_path) + end) + + it("reports the active log path", function() + local Logger, log_path = load_logger({ enabled = true }) + expect.eq(Logger.path(), log_path) + cleanup(log_path) + end) +end) + +describe("log formatting", function() + it("records a timestamp, level, and message", function() + local Logger, log_path = load_logger({ enabled = true }) + + Logger.warn("something happened") + local line = read_log(log_path)[1] + + expect.truthy(line:match("^%d%d%d%d%-%d%d%-%d%d %d%d:%d%d:%d%d %[WARN%] something happened$"), line) + cleanup(log_path) + end) + + it("renders context in a stable order", function() + local Logger, log_path = load_logger({ enabled = true }) + + Logger.debug("mount", { host = "example.com", exit_code = 1, mount_point = "/mnt/x" }) + local line = read_log(log_path)[1] + + expect.contains(line, "exit_code=1 host=example.com mount_point=/mnt/x") + cleanup(log_path) + end) + + it("keeps multi-line subprocess output on one line", function() + local Logger, log_path = load_logger({ enabled = true }) + + Logger.error("mount failed", { stderr = "first line\nsecond line\twith a tab" }) + local log = read_log(log_path) + + expect.eq(#log, 1, "an embedded newline must not split the record") + expect.contains(log[1], "stderr=first line\\nsecond line\\twith a tab") + cleanup(log_path) + end) + + it("appends rather than truncating", function() + local Logger, log_path = load_logger({ enabled = true }) + + Logger.debug("first") + Logger.debug("second") + + expect.eq(#read_log(log_path), 2) + cleanup(log_path) + end) + + it("creates the log directory when it does not exist", function() + local Logger, log_path = load_logger({ enabled = true }) + + Logger.debug("first") + + expect.eq(vim.fn.isdirectory(vim.fn.fnamemodify(log_path, ":h")), 1) + cleanup(log_path) + end) + + it("writes the log file readable only by its owner", function() + local Logger, log_path = load_logger({ enabled = true }) + + Logger.debug("sensitive output") + local mode = vim.fn.getfperm(log_path) + + expect.eq(mode, "rw-------", "logs can contain hostnames and SSH output") + cleanup(log_path) + end) +end) + +describe("log write failures", function() + it("reports a write failure once rather than on every call", function() + local Logger = load_logger({ enabled = true, log_file = "/proc/definitely-not-writable/sshfs.log" }) + local notifications = stub.notifications() + -- The failure notice is scheduled onto the event loop; run it inline. + stub.set("schedule", function(fn) + fn() + end) + + Logger.debug("first") + Logger.debug("second") + Logger.debug("third") + stub.restore_all() + + expect.eq(#notifications, 1, "a broken log path must not spam the user") + expect.contains(notifications[1].message, "failed to write debug log") + end) + + it("does not raise out of the caller", function() + local Logger = load_logger({ enabled = true, log_file = "/proc/definitely-not-writable/sshfs.log" }) + stub.notifications() + stub.set("schedule", function(fn) + fn() + end) + + expect.no_error(function() + Logger.debug("a message") + end, "logging is diagnostic and must never break the operation it describes") + stub.restore_all() + end) +end) + +describe(":SSHDebug", function() + local function run_debug(mode) + stub.reload() + local log_path = vim.fn.tempname() .. "/sshfs.nvim.log" + require("sshfs.config").setup({ debug = { enabled = false, log_file = log_path } }) + local notifications = stub.notifications() + + require("sshfs.api").debug(mode) + local enabled = require("sshfs.lib.logger").is_enabled() + stub.restore_all() + cleanup(log_path) + + return enabled, notifications + end + + it("toggles when given no argument", function() + local enabled, notifications = run_debug(nil) + + expect.truthy(enabled) + expect.contains(notifications[1].message, "enabled") + end) + + it("treats an empty argument as a toggle", function() + expect.truthy(run_debug("")) + end) + + it("enables explicitly with on", function() + local enabled, notifications = run_debug("on") + + expect.truthy(enabled) + expect.contains(notifications[1].message, "enabled") + end) + + it("disables explicitly with off", function() + local enabled, notifications = run_debug("off") + + expect.falsy(enabled) + expect.contains(notifications[1].message, "disabled") + end) + + it("reports the log path so the user can find it", function() + local _, notifications = run_debug("on") + expect.contains(notifications[1].message, "sshfs.nvim.log") + end) + + it("rejects an unknown argument without changing state", function() + local enabled, notifications = run_debug("maybe") + + expect.falsy(enabled) + expect.contains(notifications[1].message, "Usage: :SSHDebug [on|off]") + expect.eq(notifications[1].level, vim.log.levels.ERROR) + end) +end) + +describe("control byte escaping", function() + it("escapes an ANSI escape sequence from remote output", function() + local Logger, log_path = load_logger({ enabled = true }) + + Logger.debug("remote said", { stderr = "\27[2Jcleared\7" }) + local line = read_log(log_path)[1] + cleanup(log_path) + + expect.truthy(line, "the line must be written") + expect.is_nil(line:find("\27", 1, true), "no raw escape byte may reach the log") + expect.is_nil(line:find("\7", 1, true), "no raw bell byte may reach the log") + expect.contains(line, "\\x1b[2Jcleared\\x07") + end) + + it("keeps the readable names for the common whitespace bytes", function() + local Logger, log_path = load_logger({ enabled = true }) + + Logger.debug("whitespace", { value = "a\r\nb\tc" }) + local line = read_log(log_path)[1] + cleanup(log_path) + + expect.contains(line, "a\\r\\nb\\tc") + end) +end) + +describe("log rotation", function() + it("moves the log aside once it passes max_size", function() + local Logger, log_path = load_logger({ enabled = true, max_size = 200 }) + + for index = 1, 40 do + Logger.debug("filling the log", { index = index }) + end + local rotated = log_path .. ".1" + local current_lines = #read_log(log_path) + local rotated_lines = #read_log(rotated) + cleanup(log_path) + + expect.truthy(rotated_lines > 0, "the previous generation must be kept") + expect.truthy(current_lines > 0, "logging must continue after a rotation") + expect.truthy(current_lines < 40, "the current log must not still hold every line") + end) + + it("never rotates when max_size is unset", function() + local Logger, log_path = load_logger({ enabled = true }) + + for index = 1, 20 do + Logger.debug("filling the log", { index = index }) + end + local current_lines = #read_log(log_path) + local rotated_exists = vim.fn.filereadable(log_path .. ".1") + cleanup(log_path) + + expect.eq(current_lines, 20) + expect.eq(rotated_exists, 0) + end) +end) + +describe("lazy context", function() + it("skips the builder entirely while disabled", function() + local Logger, log_path = load_logger({ enabled = false }) + + local built = 0 + Logger.debug("expensive", function() + built = built + 1 + return { value = "assembled" } + end) + cleanup(log_path) + + expect.eq(built, 0, "a disabled logger must not pay for its context") + end) + + it("calls the builder and logs its table while enabled", function() + local Logger, log_path = load_logger({ enabled = true }) + + local built = 0 + Logger.debug("expensive", function() + built = built + 1 + return { value = "assembled" } + end) + local line = read_log(log_path)[1] + cleanup(log_path) + + expect.eq(built, 1) + expect.contains(line, "value=assembled") + end) +end)