From b8ca3d6d8ee1b1a66d0c8dac88e2cebce43722ac Mon Sep 17 00:00:00 2001 From: Jim Porter Date: Tue, 29 Aug 2023 17:11:42 -0700 Subject: [PATCH 2/2] Add debug instrumentation for Eshell process management * lisp/eshell/esh-util.el (eshell-debug-command): Add 'process' type. * lisp/eshell/esh-proc.el (eshell-gather-process-output) (eshell-interactive-process-filter, eshell-insertion-filter) (eshell-sentinel): Call 'eshell-debug-command'. * test/lisp/eshell/eshell-tests-helpers.el (with-temp-eshell): Add 'process' to 'eshell-debug'command' (eshell-get-debug-logs): New function... (eshell-match-command-output, eshell-command-result-equal): ... use it. --- lisp/eshell/esh-proc.el | 17 ++++++++++++- lisp/eshell/esh-util.el | 3 ++- test/lisp/eshell/eshell-tests-helpers.el | 31 ++++++++++++++++++------ 3 files changed, 41 insertions(+), 10 deletions(-) diff --git a/lisp/eshell/esh-proc.el b/lisp/eshell/esh-proc.el index 9c4036004ff..87719c019cb 100644 --- a/lisp/eshell/esh-proc.el +++ b/lisp/eshell/esh-proc.el @@ -332,6 +332,8 @@ eshell-gather-process-output :connection-type conn-type :stderr stderr-proc :file-handler t))) + (eshell-debug-command + 'process (format-message "started external process `%s'" proc)) (eshell-record-process-object proc) (eshell-record-process-properties proc) (run-hook-with-args 'eshell-exec-hook proc) @@ -410,6 +412,9 @@ eshell-interactive-process-filter "Send the output from PROCESS (STRING) to the interactive display. This is done after all necessary filtering has been done." (when string + (eshell-debug-command + 'process (format-message "received output from process `%s'\n\n%s" + process string)) (eshell--mark-as-output 0 (length string) string) (require 'esh-mode) (declare-function eshell-interactive-filter "esh-mode" (buffer string)) @@ -436,6 +441,9 @@ eshell-insertion-filter (data (process-get proc :eshell-pending))) (process-put proc :eshell-pending nil) (process-put proc :eshell-busy t) + (eshell-debug-command + 'process (format-message "received output from process `%s'\n\n%s" + proc string)) (unwind-protect (condition-case nil (eshell-output-object data index handles) @@ -460,6 +468,9 @@ eshell-insertion-filter (defun eshell-sentinel (proc string) "Generic sentinel for command processes. Reports only signals. PROC is the process that's exiting. STRING is the exit message." + (eshell-debug-command + 'process (format-message "sentinel for external process `%s': %S" + proc string)) (when (buffer-live-p (process-buffer proc)) (with-current-buffer (process-buffer proc) (unwind-protect @@ -492,7 +503,11 @@ eshell-sentinel status (when status (list 'quote (= status 0))) handles) - (eshell-kill-process-function proc string))))) + (eshell-kill-process-function proc string) + (eshell-debug-command + 'process + (format-message + "finished external process `%s'" proc)))))) (funcall finish-io)))) (when-let ((entry (assq proc eshell-process-list))) (eshell-remove-process-entry entry)))))) diff --git a/lisp/eshell/esh-util.el b/lisp/eshell/esh-util.el index 3a318056445..5f7ac82ae57 100644 --- a/lisp/eshell/esh-util.el +++ b/lisp/eshell/esh-util.el @@ -109,7 +109,8 @@ eshell-debug-command If nil, don't debug commands at all." :version "30.1" - :type '(set (const :tag "Form manipulation" form))) + :type '(set (const :tag "Form manipulation" form) + (const :tag "Process operations" process))) ;;; Internal Variables: diff --git a/test/lisp/eshell/eshell-tests-helpers.el b/test/lisp/eshell/eshell-tests-helpers.el index 2c913d71cb4..e300f3d657a 100644 --- a/test/lisp/eshell/eshell-tests-helpers.el +++ b/test/lisp/eshell/eshell-tests-helpers.el @@ -54,6 +54,12 @@ with-temp-eshell (let* (;; We want no history file, so prevent Eshell from falling ;; back on $HISTFILE. (process-environment (cons "HISTFILE" process-environment)) + ;; Enable process debug instrumentation. We may be able + ;; to remove this eventually once we're confident that + ;; all the process bugs have been worked out. (At that + ;; point, we can just enable this selectively when + ;; needed.) + (eshell-debug-command (cons 'process eshell-debug-command)) (eshell-history-file-name nil) (eshell-last-dir-ring-file-name nil) (eshell-buffer (eshell t))) @@ -96,6 +102,13 @@ eshell-wait-for-subprocess (lambda () (not (if all eshell-process-list (eshell-interactive-process-p)))))) +(defun eshell-get-debug-logs () + "Get debug command logs for displaying on test failures." + (when (get-buffer eshell-debug-command-buffer) + (let ((separator (make-string 40 ?-))) + (with-current-buffer eshell-debug-command-buffer + (string-replace "\f" separator (buffer-string)))))) + (defun eshell-insert-command (command &optional func) "Insert a COMMAND at the end of the buffer. After inserting, call FUNC. If FUNC is nil, instead call @@ -135,10 +148,11 @@ eshell-match-command-output If IGNORE-ERRORS is non-nil, ignore any errors signaled when inserting the command." - (let ((debug-on-error (and (not ignore-errors) debug-on-error))) - (eshell-insert-command command func)) - (eshell-wait-for-subprocess) - (should (eshell-match-output regexp))) + (ert-info (#'eshell-get-debug-logs :prefix "Command logs: ") + (let ((debug-on-error (and (not ignore-errors) debug-on-error))) + (eshell-insert-command command func)) + (eshell-wait-for-subprocess) + (should (eshell-match-output regexp)))) (defvar eshell-history-file-name) @@ -164,10 +178,11 @@ eshell-command-result--equal-explainer (defun eshell-command-result-equal (command result) "Execute COMMAND non-interactively and compare it to RESULT." - (should (eshell-command-result--equal - command - (eshell-test-command-result command) - result))) + (ert-info (#'eshell-get-debug-logs :prefix "Command logs: ") + (should (eshell-command-result--equal + command + (eshell-test-command-result command) + result)))) (provide 'eshell-tests-helpers) -- 2.25.1