diff --git a/README.md b/README.md index 8ac6e5ca..1abaf2af 100644 --- a/README.md +++ b/README.md @@ -221,7 +221,18 @@ Apheleia exposes some hooks for advanced customization: one of these returns non-nil then `apheleia-mode` is not enabled in the buffer. -## Known issues +## Troubleshooting + +Try running your formatter outside of Emacs to verify it works there. +Check what command-line options it is configured with in +`apheleia-formatters`. + +To debug internal bugs, race conditions, or performance issues, try +setting `apheleia-log-debug-info` to non-nil and check the contents of +`*apheleia-debug-log*`. It will have detailed trace information about +most operations performed by Apheleia. + +### Known issues * `process aphelieia-whatever no longer connected to pipe; closed it`: This happens on older Emacs versions when formatting a buffer with diff --git a/apheleia-formatters.el b/apheleia-formatters.el index 5e64ae9a..84aa5167 100644 --- a/apheleia-formatters.el +++ b/apheleia-formatters.el @@ -366,7 +366,10 @@ saying whether the process was interrupted before completion. REMOTE if supplied will be passed as the FILE-HANDLER argument to `make-process'. -See `make-process' for a description of the NAME and NOQUERY arguments." +See `make-process' for a description of the NAME and NOQUERY +arguments." + (apheleia--log + 'process "Using make-process to create process %s with %S" name command) (let ((proc (make-process :name name @@ -385,6 +388,9 @@ See `make-process' for a description of the NAME and NOQUERY arguments." (process-get proc :interrupted))))))) (set-process-sentinel (get-buffer-process stderr) #'ignore) (when stdin + (apheleia--log + 'process + "Sending %d bytes to stdin of process %s" (buffer-size stdin) name) (set-process-coding-system proc nil @@ -429,6 +435,9 @@ NO-QUERY, and CONNECTION-TYPE." nil) ;; argv[1:] (cdr command)))) + (apheleia--log + 'process "Sending stderr for process %s to tempfile %s" + name stderr-file) (unwind-protect (let ((exit-status (cl-letf* ((message (symbol-function #'message)) @@ -461,17 +470,32 @@ NO-QUERY, and CONNECTION-TYPE." (with-current-buffer stdin (apheleia--write-region-silently nil nil remote-stdin)) - + (apheleia--log + 'process + "Using process-file to create process %s with %S" + name (list shell "-c" shell-command)) (process-file shell nil (nth 2 args) nil "-c" shell-command)) (delete-file remote-stdin)))) (stdin + (apheleia--log + 'process + "Using call-process-region to create process %s with %S" + name command) (with-current-buffer stdin (apply #'call-process-region (point-min) (point-max) args))) (run-on-remote + (apheleia--log + 'process + "Using process-file to create process %s with %S" + name command) (apply #'process-file args)) (t + (apheleia--log + 'process + "Using process-file to create process %s with %S" + name command) (apply #'call-process args)))))) ;; Save stderr from STDERR-FILE back into the STDERR buffer. (with-current-buffer stderr @@ -496,7 +520,14 @@ not. EXIT-STATUS is a function which is called with the exit status of the command; it should return non-nil to indicate that the command succeeded. If EXIT-STATUS is omitted, then the command succeeds provided that its exit status is 0." + (apheleia--log + 'process "Trying to execute formatter process %s with %S" + (apheleia-formatter--name ctx) + `(,(apheleia-formatter--arg1 ctx) + ,@(apheleia-formatter--argv ctx))) (when (process-live-p apheleia--current-process) + (apheleia--log + 'process "Interrupting an existing process %S" apheleia--current-process) (message "Interrupting %s" apheleia--current-process) (process-put apheleia--current-process :interrupted t) (interrupt-process apheleia--current-process) @@ -527,6 +558,14 @@ command succeeds provided that its exit status is 0." :noquery t :callback (lambda (proc-exit-status proc-interrupted) + (apheleia--log + 'process + "Process %s exited with status %S%s" + name + proc-exit-status + (if proc-interrupted + " (interrupted)" + " (not interrupted)")) (setf (apheleia-formatter--exit-status ctx) proc-exit-status) (let ((exit-ok (and @@ -548,6 +587,9 @@ command succeeds provided that its exit status is 0." (with-current-buffer stderr (string-trim (buffer-string))))) (when (apheleia-formatter--name ctx) + (apheleia--log + 'hook + "Invoking apheleia-formatter-exited-hook") (run-hook-with-args 'apheleia-formatter-exited-hook :formatter (apheleia-formatter--name ctx) @@ -556,6 +598,10 @@ command succeeds provided that its exit status is 0." (unwind-protect (if exit-ok (when callback + (apheleia--log + 'process + (concat "Invoking process callback due " + "to successful exit status")) (funcall callback stdout)) (message (concat @@ -640,6 +686,9 @@ Once finished, invoke CALLBACK with a buffer containing the patch as its sole argument. See `apheleia--run-formatters' for a description of REMOTE." + (apheleia--log + 'rcs "Creating RCS patch between buffers with %d and %d bytes" + (buffer-size old-buffer) (buffer-size new-buffer)) ;; Make sure at least one of the two buffers is saved to a file. The ;; other one we can feed on stdin. (let ((old-fname @@ -972,6 +1021,9 @@ formatter in COMMANDS. This should not be supplied by the caller and instead is supplied by this command when invoked recursively. The stdout of the previous formatter becomes the stdin of the next formatter." + (apheleia--log + 'run-formatter + "Running formatters %S on buffer %S" formatters buffer) (let ((command (alist-get (car formatters) apheleia-formatters))) (funcall (cond diff --git a/apheleia-log.el b/apheleia-log.el index 4fe8d3d2..0617a271 100644 --- a/apheleia-log.el +++ b/apheleia-log.el @@ -25,6 +25,19 @@ if it is successful." :type 'boolean :group 'apheleia) +(defcustom apheleia-debug-info-buffer "*apheleia-debug-log*" + "Name of logging buffer when `apheleia-log-debug-info' is non-nil." + :type 'string + :group 'apheleia) + +(defcustom apheleia-log-debug-info nil + "Non-nil means to log debugging info to `apheleia-debug-info-buffer'. +This may be useful in understanding what commands Apheleia is +running, in what order, and at what times, or for filing a bug +report." + :type 'boolean + :group 'apheleia) + (defvar apheleia--last-error-marker nil "Marker for the last error message for any formatter. This points into a log buffer.") @@ -100,6 +113,42 @@ STDERR-STRING is the stderr output of the formatter." (min (point-max) orig-point))) (goto-char (point-max)))))) +;; Cribbed this from myself in straight.el +(defun apheleia--log (category message &rest args) + "Log diagnostic message to `apheleia-debug-info-buffer'. +If `apheleia-log-debug-info' is nil, this does nothing. CATEGORY +is a symbol that can help in filtering the resulting log output. +MESSAGE and ARGS are interpreted as in `message', except that any +of ARGS can also be a function of no arguments which will be +invoked to get the real value. This is helpful because the +function won't be evaluated if logging is disabled. Only lambda +functions are accepted, to avoid symbols being interpreted as +callables by accident." + (when apheleia-log-debug-info + (with-current-buffer (get-buffer-create apheleia-debug-info-buffer) + (unless (derived-mode-p 'special-mode) (special-mode)) + (save-excursion + (goto-char (point-max)) + (let ((inhibit-read-only t) + (body nil)) + (condition-case err + (let ((args (mapcar + (lambda (arg) + (if (and (listp arg) + (functionp arg)) + (funcall arg) + arg)) + args))) + (setq body (apply #'format message args))) + (error (setq body (format "Got error formatting log line %S: %s" + message + (error-message-string err))))) + (insert + (format + "%s <%S>: %s\n" + (format-time-string "%Y-%m-%d %H:%M:%S.%3N" (current-time)) + category body))))))) + (provide 'apheleia-log) ;;; apheleia-log.el ends here diff --git a/apheleia-rcs.el b/apheleia-rcs.el index 4b5b87d0..e2df650b 100644 --- a/apheleia-rcs.el +++ b/apheleia-rcs.el @@ -7,6 +7,8 @@ ;;; Code: +(require 'apheleia-log) + (require 'cl-lib) (require 'subr-x) @@ -113,6 +115,8 @@ point correctly." "Apply RCS patch. CONTENT-BUFFER contains the text to be patched, and PATCH-BUFFER contains the patch." + (apheleia--log + 'rcs "Applying RCS patch from %S to %S" patch-buffer content-buffer) (let ((commands nil) (point-list nil) (window-line-list nil)) diff --git a/apheleia.el b/apheleia.el index 9b5885ec..029f490a 100644 --- a/apheleia.el +++ b/apheleia.el @@ -24,6 +24,7 @@ ;;; Code: (require 'apheleia-formatters) +(require 'apheleia-log) (require 'apheleia-rcs) (defgroup apheleia nil @@ -81,6 +82,11 @@ changes), CALLBACK, if provided, is invoked with no arguments." (if current-prefix-arg 'prompt 'interactive))))) + (apheleia--log + 'format-buffer + "Invoking apheleia-format-buffer on %S with formatter %S" + (current-buffer) + formatter) (let ((formatters (apheleia--ensure-list formatter))) ;; Check for this error ahead of time so we don't have to deal ;; with it anywhere in the internal machinery of Apheleia. @@ -92,7 +98,12 @@ changes), CALLBACK, if provided, is invoked with no arguments." ;; Fail silently if disallowed, since we don't want to throw an ;; error on `post-command-hook'. We already took care of throwing ;; `user-error' on interactive usage above. - (unless (apheleia--disallowed-p) + (if-let ((err (apheleia--disallowed-p))) + (apheleia--log + 'format-buffer + "Aborting in %S due to apheleia--disallowed-p: %s" + (buffer-name (current-buffer)) + err) ;; It's important to store the saved buffer hash in a lexical ;; variable rather than a dynamic (global) one, else multiple ;; concurrent invocations of `apheleia-format-buffer' can @@ -110,23 +121,40 @@ changes), CALLBACK, if provided, is invoked with no arguments." cur-buffer remote (lambda (formatted-buffer) - (when (buffer-live-p cur-buffer) + (if (not (buffer-live-p cur-buffer)) + (apheleia--log + 'format-buffer + "Aborting in %S because buffer has died" + (buffer-name cur-buffer)) (with-current-buffer cur-buffer ;; Short-circuit. - (when - (equal - saved-buffer-hash (apheleia--buffer-hash)) + (if (not (equal saved-buffer-hash (apheleia--buffer-hash))) + (apheleia--log + 'format-buffer + "Aborting in %S because contents have changed" + (buffer-name cur-buffer)) (apheleia--create-rcs-patch cur-buffer formatted-buffer remote (lambda (patch-buffer) (when (buffer-live-p cur-buffer) (with-current-buffer cur-buffer - (when - (equal - saved-buffer-hash (apheleia--buffer-hash)) + (if (not (equal + saved-buffer-hash + (apheleia--buffer-hash))) + (apheleia--log + 'format-buffer + "Aborting in %S because contents have changed" + (buffer-name cur-buffer)) (apheleia--apply-rcs-patch (current-buffer) patch-buffer) - (when callback + (if (not callback) + (apheleia--log + 'format-buffer + (concat + "Skipping callback because " + "none was provided")) + (apheleia--log + 'format-buffer "Invoking callback") (funcall callback))))))))))))))))) (defcustom apheleia-post-format-hook nil