Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[#226] Add debug logs #235

Merged
merged 1 commit into from
Oct 29, 2023
Merged

[#226] Add debug logs #235

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
13 changes: 12 additions & 1 deletion README.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
56 changes: 54 additions & 2 deletions apheleia-formatters.el
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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
Expand Down Expand Up @@ -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))
Expand Down Expand Up @@ -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
Expand All @@ -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)
Expand Down Expand Up @@ -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
Expand All @@ -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)
Expand All @@ -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
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down
49 changes: 49 additions & 0 deletions apheleia-log.el
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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.")
Expand Down Expand Up @@ -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
4 changes: 4 additions & 0 deletions apheleia-rcs.el
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,8 @@

;;; Code:

(require 'apheleia-log)

(require 'cl-lib)
(require 'subr-x)

Expand Down Expand Up @@ -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))
Expand Down
46 changes: 37 additions & 9 deletions apheleia.el
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -24,6 +24,7 @@
;;; Code:

(require 'apheleia-formatters)
(require 'apheleia-log)
(require 'apheleia-rcs)

(defgroup apheleia nil
Expand Down Expand Up @@ -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.
Expand All @@ -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
Expand All @@ -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
Expand Down