[#226] Add debug logs (#235)

Adds a way to properly diagnose performance issues like those reported
in https://github.com/radian-software/apheleia/issues/226.

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

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

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

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))

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
+                 (if (not (equal saved-buffer-hash (apheleia--buffer-hash)))
-                     (equal
+                     (apheleia--log
-                      saved-buffer-hash (apheleia--buffer-hash))
+                      '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
+                          (if (not (equal
-                              (equal
+                                    saved-buffer-hash
-                               saved-buffer-hash (apheleia--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