From 6cac7b05b69427c2dc68573afe271827c0ad1cef Mon Sep 17 00:00:00 2001 From: Henrik Lissner Date: Sun, 11 Sep 2022 20:12:22 +0200 Subject: [PATCH] refactor(lib): tidy doom-log output This commit reduces the debug log noise, makes it easier to read/parse/search, and soft-introduces a convention for doom-log messages, where they are prefixed with a unique identifier loosely named after it's running context or calling function. I haven't enforced it everywhere doom-log is used yet, but this is a start. --- bin/doom | 8 ++----- lisp/cli/autoloads.el | 2 +- lisp/cli/env.el | 4 ++-- lisp/cli/packages.el | 16 +++++++------- lisp/doom-cli.el | 39 +++++++++++++++++----------------- lisp/doom-lib.el | 10 +++++---- lisp/doom-start.el | 6 +++--- lisp/lib/debug.el | 49 +++++++++++++++++++++++-------------------- 8 files changed, 68 insertions(+), 66 deletions(-) diff --git a/bin/doom b/bin/doom index c70586f53..920d092ba 100755 --- a/bin/doom +++ b/bin/doom @@ -201,8 +201,7 @@ SEE ALSO: (when pager (setq doom-cli-pager pager)) (when force? - (setf (doom-cli-context-suppress-prompts-p context) t) - (doom-log "User requested all prompts be suppressed")) + (setf (doom-cli-context-suppress-prompts-p context) t)) ;; For these settings to take full effect, the script must be restarted: (when (or debug? profile @@ -296,7 +295,6 @@ SEE ALSO: (defcli-group! :prefix (format "+%s" (cdr key)) (load! cli-file path t))))) - (doom-log "Loading $DOOMDIR/cli.el") (load! cli-file doom-user-dir t)) ;; Allow per-project Doom settings in .doom files. @@ -305,9 +303,7 @@ SEE ALSO: ((setq doomrc (getenv "DOOMRC")) (load! doomrc)) ((setq doomrc (locate-dominating-file default-directory ".doomrc")) - (load! ".doomrc" doomrc))) - (when doomrc - (doom-log "Loaded doomrc: %s" doomrc))))) + (load! ".doomrc" doomrc)))))) ;; diff --git a/lisp/cli/autoloads.el b/lisp/cli/autoloads.el index a1ce81003..7c62ba9e8 100644 --- a/lisp/cli/autoloads.el +++ b/lisp/cli/autoloads.el @@ -212,7 +212,7 @@ non-nil, treat FILES as pre-generated autoload files instead." (dolist (file files (nreverse (delq nil autoloads))) (when (and (not (seq-find (doom-rpartial #'string-match-p file) exclude)) (file-readable-p file)) - (doom-log "Scanning %s" file) + (doom-log "loaddefs:scan: %s" file) (setq file (file-truename file)) (with-temp-buffer (if literal diff --git a/lisp/cli/env.el b/lisp/cli/env.el index aaec49939..24bf79281 100644 --- a/lisp/cli/env.el +++ b/lisp/cli/env.el @@ -125,8 +125,8 @@ Why this over exec-path-from-shell? (pred (doom-rpartial #'string-match-p var))) (when (seq-find pred denylist) (if (seq-find pred allowlist) - (doom-log "Whitelisted %s" var) - (doom-log "Ignored %s" var) + (doom-log "cli:env: allow %s" var) + (doom-log "cli:env: deny %s" var) (throw 'skip t))) (insert (prin1-to-string env) "\n ")))) (insert ")")) diff --git a/lisp/cli/packages.el b/lisp/cli/packages.el index 02baa55b6..ef9dc8e22 100644 --- a/lisp/cli/packages.el +++ b/lisp/cli/packages.el @@ -184,7 +184,7 @@ list remains lean." ;; `no-byte-compile'. Rebuilding unnecessarily is expensive. (when (and (file-exists-p elc-file) (file-newer-than-file-p file elc-file)) - (doom-log "%s is newer than %s" file elc-file) + (doom-log "packages:elc: %s is newer than %s" file elc-file) t))) (defun doom-packages--eln-file-outdated-p (file) @@ -195,13 +195,15 @@ list remains lean." (error-file (doom-packages--eln-error-file eln-name))) (cond (eln-file (when (file-newer-than-file-p file eln-file) - (doom-log "%s is newer than %s" file eln-file) + (doom-log "packages:eln: %s is newer than %s" file eln-file) t)) ((file-exists-p error-file) (when (file-newer-than-file-p file error-file) - (doom-log "%s is newer than %s" file error-file) + (doom-log "packages:eln: %s is newer than %s" file error-file) t)) - ((always (doom-log "%s doesn't exist" eln-name))))))) + ((file-exists-p (byte-compile-dest-file file)) + (doom-log "packages:eln: cannot find %s" eln-name) + t))))) (defun doom-packages--native-compile-done-h (file) "Callback fired when an item has finished async compilation." @@ -210,13 +212,13 @@ list remains lean." (eln-file (doom-packages--eln-output-file eln-name)) (error-file (doom-packages--eln-error-file eln-name))) (if (file-exists-p eln-file) - (doom-log "Compiled %s" eln-file) + (doom-log "packages:nativecomp: Compiled %s" eln-file) (let ((error-dir (file-name-directory error-file))) (if (not (file-writable-p error-dir)) - (doom-log "Can't write %s" error-file) + (doom-log "packages:nativecomp: failed to write %s" error-file) (make-directory error-dir 'parents) (write-region "" nil error-file) - (doom-log "Wrote %s" error-file))))))) + (doom-log "packages:nativecomp: wrote %s" error-file))))))) (defun doom-packages--wait-for-native-compile-jobs () "Wait for all pending async native compilation jobs." diff --git a/lisp/doom-cli.el b/lisp/doom-cli.el index badd7a375..b59ed6280 100644 --- a/lisp/doom-cli.el +++ b/lisp/doom-cli.el @@ -61,9 +61,8 @@ (require 'seq) (require 'map) - ;; Use our own home-grown debugger so we can capture backtraces, make them - ;; more presentable, and write them to a file. Cleaner backtraces are better - ;; UX than the giant wall of text the default debugger throws up. + ;; Load and set up our debugger first, so backtraces can be made more + ;; presentable and logged to file. (doom-require 'doom-lib 'debug) (if init-file-debug (doom-debug-mode +1)) @@ -304,7 +303,7 @@ the return value of the executed CLI.") BINDINGS is an alist of (SYMBOL . VALUE) to bind lexically during CLI's execution. Can be generated from a `doom-cli-context' with `doom-cli--bindings'." - (doom-log "doom-cli-execute: %s %s" (doom-cli-key cli) bindings) + (doom-log "cli-execute: %s %s" (doom-cli-key cli) bindings) (funcall (doom-cli-fn cli) cli bindings)) (defun doom-cli-key (cli) @@ -728,7 +727,7 @@ executable context." (let* ((command (doom-cli-context-command context)) (cli (doom-cli-get command t)) (prefix (doom-cli-context-prefix context))) - (doom-log "doom-cli-context-execute: %s" + (doom-log "cli-context-execute: %s" (mapconcat #'doom-cli-command-string (delq nil (list (car (doom-cli-context-path context)) command)) " -> ")) @@ -789,7 +788,7 @@ executable context." (_ old-value)))))) (run-hook-with-args 'doom-cli-create-context-functions context) (delete-file file) - (doom-log "Restored context: %s" (doom-cli-context-pid context)))) + (doom-log "cli-context-restore: %s" (doom-cli-context-pid context)))) context) (defun doom-cli-context-parse (args context) @@ -804,7 +803,7 @@ executable context." (save-match-data (cond ((equal arg "--") - (doom-log "Found arg separator" arg) + (doom-log "cli-context-parse: found arg separator" arg) (setq arguments (cdr args) args nil)) @@ -817,7 +816,7 @@ executable context." ((and (stringp arg) (or (string-match "^\\(--\\w[a-z0-9-_]+\\)\\(?:=\\(.*\\)\\)?$" arg) (string-match "^\\(-[^-]\\)$" arg))) - (doom-log "Found switch: %s" arg) + (doom-log "cli-context-parse: found switch %S" arg) (catch :skip (let* ((fullflag (match-string 1 arg)) (normflag (if (string-prefix-p "--no-" fullflag) @@ -825,7 +824,7 @@ executable context." fullflag)) (option (or (doom-cli-context-find-option context normflag) (when (member fullflag '("-?" "--help" "--version")) - (doom-log "Found help switch: %s" arg) + (doom-log "cli-context-parse: found help switch %S" arg) (setf (doom-cli-context-meta-p context) fullflag) (throw :skip t)) (when rest? @@ -869,11 +868,11 @@ executable context." (cli (doom-cli-get command t)) (rcli (doom-cli-get command)) (key (doom-cli-key rcli))) - (doom-log "doom-cli-context-execute: found %s" command) + (doom-log "cli-context-parse: found %s" command) ;; Show warnings depending on CLI plists (when (doom-cli-alias cli) (dolist (pcli (doom-cli-path cli)) - (doom-log "doom-cli-context-execute: path=%s" (doom-cli-key pcli)) + (doom-log "cli-context-parse: path += %s" (doom-cli-key pcli)) (push (doom-cli-key pcli) (doom-cli-context-path context)))) ;; Collect &rest for this command (setf (doom-cli-context-command context) key @@ -896,7 +895,7 @@ executable context." t)) ((push arg arguments) - (doom-log "Found argument: %s" arg))))) + (doom-log "cli-context-parse: found arg %S" arg))))) (setf (alist-get t (doom-cli-context-arguments context)) (append (alist-get t (doom-cli-context-arguments context)) @@ -1110,7 +1109,7 @@ Will also output it to stdout if requested (CLI sets :benchmark to t) or the command takes >5s to run. If :benchmark is explicitly set to nil (or `doom-cli-benchmark-threshold' is nil), under no condition should a benchmark be shown." - (doom-log "%s (GCs: %d, elapsed: %.6fs)" + (doom-log "cli: %s (GCs: %d, elapsed: %.6fs)" (if (= doom-cli--exit-code 254) "Restarted" "Finished") gcs-done gc-elapsed) (when-let* ((init-time (doom-cli-context-init-time context)) @@ -1155,8 +1154,8 @@ If ERROR is provided, store the error in CONTEXT, in case a later CLI wants to read/use it (e.g. like a :help CLI)." (let ((oldcommand (doom-cli-context-command context))) (if oldcommand - (doom-log "doom-cli-call: %s -> %s" oldcommand args) - (doom-log "doom-cli-call: %s" oldcommand args)) + (doom-log "cli-call: %s -> %s" oldcommand args) + (doom-log "cli-call: %s" oldcommand args)) (when error (setf (doom-cli-context-error context) error)) (setf (doom-cli-context-command context) nil @@ -1195,7 +1194,7 @@ Emacs' batch library lacks an implementation of the exec system call." (shell-quote-argument (match-string 2 env))))))) (cl-incf (doom-cli-context-step context)) (with-file-modes #o600 - (doom-log "Writing context file: %s" context-file) + (doom-log "cli:restart: writing context to %s" context-file) (doom-file-write context-file (let ((newcontext (copy-doom-cli-context context)) (print-level nil) @@ -1211,7 +1210,7 @@ Emacs' batch library lacks an implementation of the exec system call." (convert-buffer doom-cli-context-stdout) (convert-buffer doom-cli-context-stderr)) newcontext)) - (doom-log "Writing post-script file: %s" script-file) + (doom-log "cli:restart: writing post-script to %s" script-file) (doom-file-write script-file `("#!/usr/bin/env sh\n" "trap _doomcleanup EXIT\n" @@ -1442,7 +1441,7 @@ ARGS are options passed to less. If DOOMPAGER is set, ARGS are ignored." "If CLI is autoloaded, load it, otherwise return it unchanged." (or (when-let* ((path (doom-cli-autoload cli)) (path (locate-file-internal path doom-cli-load-path load-suffixes))) - (doom-log "Autoloading %s" path) + (doom-log "cli-load: autoload %s" path) (let ((doom-cli--plist (doom-cli-plist cli))) (load! path)) (let* ((key (doom-cli-key cli)) @@ -1905,7 +1904,8 @@ errors to `doom-cli-error-file')." ;; Clone output to stdout/stderr buffers for logging. (standard-output (doom-rpartial #'doom-cli--output context)) (#'message (doom-partial #'doom-cli--redirect-output-a context))) - (doom-log "Starting!") + ;; Clone output to stdout/stderr buffers for logging. + (doom-log "run!: %s %s" prefix (combine-and-quote-strings args)) (add-hook 'kill-emacs-hook show-benchmark-fn 94) (add-hook 'kill-emacs-hook write-logs-fn 95) (when (doom-cli-context-pipe-p context :out t) @@ -1915,7 +1915,6 @@ errors to `doom-cli-error-file')." (while (if-let (in (ignore-errors (read-from-minibuffer ""))) (insert in "\n") (ignore-errors (delete-char -1)))))) - (doom-log "doom-cli-run: %s" command-line-args) (doom-cli--exit (condition-case e (let* ((args (cons (if (getenv "__DOOMDUMP") :dump prefix) args)) diff --git a/lisp/doom-lib.el b/lisp/doom-lib.el index dec43aa39..3776ad15e 100644 --- a/lisp/doom-lib.el +++ b/lisp/doom-lib.el @@ -13,9 +13,11 @@ debug mode is off." (let ((inhibit-message (not init-file-debug))) (message "%s" (propertize - (format (concat "* [%.06f] " ,output) - (float-time (time-subtract (current-time) before-init-time)) - ,@args) + ;; Byte compiler: don't complain about more args than %-sequences. + (with-no-warnings + (format (concat "* %.06f: " ,output) + (float-time (time-subtract (current-time) before-init-time)) + ,@args)) 'face 'font-lock-doc-face))))) @@ -115,7 +117,7 @@ at the values with which this function was called." "Load PATH and handle any Doom errors that arise from it. If NOERROR, don't throw an error if PATH doesn't exist." - (doom-log "Loading %S..." path) + (doom-log "load: %s %s" (abbreviate-file-name path) noerror) (condition-case-unless-debug e (load path noerror 'nomessage) ((doom-error file-missing) diff --git a/lisp/doom-start.el b/lisp/doom-start.el index 4afed7d41..8e9da44fe 100644 --- a/lisp/doom-start.el +++ b/lisp/doom-start.el @@ -106,14 +106,14 @@ intervals." (let ((req (pop packages)) idle-time) (if (featurep req) - (doom-log "[ILoader] Already loaded: %s (%d left)" req (length packages)) + (doom-log "start:iloader: Already loaded %s (%d left)" req (length packages)) (condition-case-unless-debug e (and (or (null (setq idle-time (current-idle-time))) (< (float-time idle-time) doom-incremental-first-idle-timer) (not (while-no-input - (doom-log "[ILoader] Loading: %s (%d left)" req (length packages)) + (doom-log "start:iloader: Loading %s (%d left)" req (length packages)) ;; If `default-directory' doesn't exist or is ;; unreadable, Emacs throws file errors. (let ((default-directory doom-emacs-dir) @@ -127,7 +127,7 @@ intervals." (message "Error: failed to incrementally load %S because: %s" req e) (setq packages nil))) (if (null packages) - (doom-log "[ILoader] Finished!") + (doom-log "start:iloader: Finished!") (run-at-time (if idle-time doom-incremental-idle-timer doom-incremental-first-idle-timer) diff --git a/lisp/lib/debug.el b/lisp/lib/debug.el index 23d5e744a..913cbcfbf 100644 --- a/lisp/lib/debug.el +++ b/lisp/lib/debug.el @@ -28,36 +28,37 @@ Each entry can be a variable symbol or a cons cell whose CAR is the variable symbol and CDR is the value to set it to when `doom-debug-mode' is activated.") -(defvar doom-debug--undefined-vars nil) +(defvar doom-debug--unbound-vars nil) (defun doom-debug--watch-vars-h (&rest _) - (when-let (bound-vars (cl-delete-if-not #'boundp doom-debug--undefined-vars)) - (doom-log "New variables available: %s" bound-vars) - (let ((message-log-max nil)) - (doom-debug-mode -1) - (doom-debug-mode +1)))) + (when-let (vars (copy-sequence doom-debug--unbound-vars)) + (setq doom-debug--unbound-vars nil) + (mapc #'doom-debug--set-var vars))) + +(defun doom-debug--set-var (spec) + (cond ((listp spec) + (pcase-let ((`(,var . ,val) spec)) + (if (boundp var) + (set-default + var (if (not doom-debug-mode) + (prog1 (get var 'initial-value) + (put var 'initial-value nil)) + (doom-log "debug:vars: %s = %S" var (default-toplevel-value var)) + (put var 'initial-value (default-toplevel-value var)) + val)) + (add-to-list 'doom-debug--unbound-vars spec)))) + ((boundp spec) + (doom-log "debug:vars: %s = %S" spec doom-debug-mode) + (set-default-toplevel-value spec doom-debug-mode)) + ((add-to-list 'doom-debug--unbound-vars (cons spec t))))) ;;;###autoload (define-minor-mode doom-debug-mode "Toggle `debug-on-error' and `init-file-debug' for verbose logging." - :init-value init-file-debug :global t (let ((enabled doom-debug-mode)) - (setq doom-debug--undefined-vars nil) - (dolist (var doom-debug-variables) - (cond ((listp var) - (pcase-let ((`(,var . ,val) var)) - (if (boundp var) - (set-default - var (if (not enabled) - (prog1 (get var 'initial-value) - (put var 'initial-value nil)) - (put var 'initial-value (default-toplevel-value var)) - val)) - (add-to-list 'doom-debug--undefined-vars var)))) - ((if (boundp var) - (set-default-toplevel-value var enabled) - (add-to-list 'doom-debug--undefined-vars var))))) + (doom-log "debug: enabled!") + (mapc #'doom-debug--set-var doom-debug-variables) (when (called-interactively-p 'any) (when (fboundp 'explain-pause-mode) (explain-pause-mode (if enabled +1 -1)))) @@ -65,7 +66,8 @@ symbol and CDR is the value to set it to when `doom-debug-mode' is activated.") ;; potentially define one of `doom-debug-variables'), in case some of them ;; aren't defined when `doom-debug-mode' is first loaded. (cond (enabled - (message "Debug mode enabled! (Run 'M-x view-echo-area-messages' to open the log buffer)") + (unless noninteractive + (message "Debug mode enabled! (Run 'M-x view-echo-area-messages' to open the log buffer)")) ;; Produce more helpful (and visible) error messages from errors ;; emitted from hooks (particularly mode hooks), that usually go ;; unnoticed otherwise. @@ -83,6 +85,7 @@ symbol and CDR is the value to set it to when `doom-debug-mode' is activated.") (advice-remove #'gcmh-idle-garbage-collect #'doom-debug-shut-up-a) (remove-variable-watcher 'doom-debug-variables #'doom-debug--watch-vars-h) (remove-hook 'after-load-functions #'doom-debug--watch-vars-h) + (doom-log "debug: disabled") (message "Debug mode disabled!"))))) (defun doom-debug-shut-up-a (fn &rest args)