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.
This commit is contained in:
Henrik Lissner 2022-09-11 20:12:22 +02:00
parent 0c43c769ef
commit 6cac7b05b6
No known key found for this signature in database
GPG key ID: B60957CA074D39A3
8 changed files with 68 additions and 66 deletions

View file

@ -201,8 +201,7 @@ SEE ALSO:
(when pager (when pager
(setq doom-cli-pager pager)) (setq doom-cli-pager pager))
(when force? (when force?
(setf (doom-cli-context-suppress-prompts-p context) t) (setf (doom-cli-context-suppress-prompts-p context) t))
(doom-log "User requested all prompts be suppressed"))
;; For these settings to take full effect, the script must be restarted: ;; For these settings to take full effect, the script must be restarted:
(when (or debug? (when (or debug?
profile profile
@ -296,7 +295,6 @@ SEE ALSO:
(defcli-group! :prefix (format "+%s" (cdr key)) (defcli-group! :prefix (format "+%s" (cdr key))
(load! cli-file path t))))) (load! cli-file path t)))))
(doom-log "Loading $DOOMDIR/cli.el")
(load! cli-file doom-user-dir t)) (load! cli-file doom-user-dir t))
;; Allow per-project Doom settings in .doom files. ;; Allow per-project Doom settings in .doom files.
@ -305,9 +303,7 @@ SEE ALSO:
((setq doomrc (getenv "DOOMRC")) ((setq doomrc (getenv "DOOMRC"))
(load! doomrc)) (load! doomrc))
((setq doomrc (locate-dominating-file default-directory ".doomrc")) ((setq doomrc (locate-dominating-file default-directory ".doomrc"))
(load! ".doomrc" doomrc))) (load! ".doomrc" doomrc))))))
(when doomrc
(doom-log "Loaded doomrc: %s" doomrc)))))
;; ;;

View file

@ -212,7 +212,7 @@ non-nil, treat FILES as pre-generated autoload files instead."
(dolist (file files (nreverse (delq nil autoloads))) (dolist (file files (nreverse (delq nil autoloads)))
(when (and (not (seq-find (doom-rpartial #'string-match-p file) exclude)) (when (and (not (seq-find (doom-rpartial #'string-match-p file) exclude))
(file-readable-p file)) (file-readable-p file))
(doom-log "Scanning %s" file) (doom-log "loaddefs:scan: %s" file)
(setq file (file-truename file)) (setq file (file-truename file))
(with-temp-buffer (with-temp-buffer
(if literal (if literal

View file

@ -125,8 +125,8 @@ Why this over exec-path-from-shell?
(pred (doom-rpartial #'string-match-p var))) (pred (doom-rpartial #'string-match-p var)))
(when (seq-find pred denylist) (when (seq-find pred denylist)
(if (seq-find pred allowlist) (if (seq-find pred allowlist)
(doom-log "Whitelisted %s" var) (doom-log "cli:env: allow %s" var)
(doom-log "Ignored %s" var) (doom-log "cli:env: deny %s" var)
(throw 'skip t))) (throw 'skip t)))
(insert (prin1-to-string env) "\n ")))) (insert (prin1-to-string env) "\n "))))
(insert ")")) (insert ")"))

View file

@ -184,7 +184,7 @@ list remains lean."
;; `no-byte-compile'. Rebuilding unnecessarily is expensive. ;; `no-byte-compile'. Rebuilding unnecessarily is expensive.
(when (and (file-exists-p elc-file) (when (and (file-exists-p elc-file)
(file-newer-than-file-p file 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))) t)))
(defun doom-packages--eln-file-outdated-p (file) (defun doom-packages--eln-file-outdated-p (file)
@ -195,13 +195,15 @@ list remains lean."
(error-file (doom-packages--eln-error-file eln-name))) (error-file (doom-packages--eln-error-file eln-name)))
(cond (eln-file (cond (eln-file
(when (file-newer-than-file-p file 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)) t))
((file-exists-p error-file) ((file-exists-p error-file)
(when (file-newer-than-file-p file 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)) 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) (defun doom-packages--native-compile-done-h (file)
"Callback fired when an item has finished async compilation." "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)) (eln-file (doom-packages--eln-output-file eln-name))
(error-file (doom-packages--eln-error-file eln-name))) (error-file (doom-packages--eln-error-file eln-name)))
(if (file-exists-p eln-file) (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))) (let ((error-dir (file-name-directory error-file)))
(if (not (file-writable-p error-dir)) (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) (make-directory error-dir 'parents)
(write-region "" nil error-file) (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 () (defun doom-packages--wait-for-native-compile-jobs ()
"Wait for all pending async native compilation jobs." "Wait for all pending async native compilation jobs."

View file

@ -61,9 +61,8 @@
(require 'seq) (require 'seq)
(require 'map) (require 'map)
;; Use our own home-grown debugger so we can capture backtraces, make them ;; Load and set up our debugger first, so backtraces can be made more
;; more presentable, and write them to a file. Cleaner backtraces are better ;; presentable and logged to file.
;; UX than the giant wall of text the default debugger throws up.
(doom-require 'doom-lib 'debug) (doom-require 'doom-lib 'debug)
(if init-file-debug (doom-debug-mode +1)) (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 BINDINGS is an alist of (SYMBOL . VALUE) to bind lexically during CLI's
execution. Can be generated from a `doom-cli-context' with execution. Can be generated from a `doom-cli-context' with
`doom-cli--bindings'." `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)) (funcall (doom-cli-fn cli) cli bindings))
(defun doom-cli-key (cli) (defun doom-cli-key (cli)
@ -728,7 +727,7 @@ executable context."
(let* ((command (doom-cli-context-command context)) (let* ((command (doom-cli-context-command context))
(cli (doom-cli-get command t)) (cli (doom-cli-get command t))
(prefix (doom-cli-context-prefix context))) (prefix (doom-cli-context-prefix context)))
(doom-log "doom-cli-context-execute: %s" (doom-log "cli-context-execute: %s"
(mapconcat #'doom-cli-command-string (mapconcat #'doom-cli-command-string
(delq nil (list (car (doom-cli-context-path context)) command)) (delq nil (list (car (doom-cli-context-path context)) command))
" -> ")) " -> "))
@ -789,7 +788,7 @@ executable context."
(_ old-value)))))) (_ old-value))))))
(run-hook-with-args 'doom-cli-create-context-functions context) (run-hook-with-args 'doom-cli-create-context-functions context)
(delete-file file) (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) context)
(defun doom-cli-context-parse (args context) (defun doom-cli-context-parse (args context)
@ -804,7 +803,7 @@ executable context."
(save-match-data (save-match-data
(cond (cond
((equal arg "--") ((equal arg "--")
(doom-log "Found arg separator" arg) (doom-log "cli-context-parse: found arg separator" arg)
(setq arguments (cdr args) (setq arguments (cdr args)
args nil)) args nil))
@ -817,7 +816,7 @@ executable context."
((and (stringp arg) ((and (stringp arg)
(or (string-match "^\\(--\\w[a-z0-9-_]+\\)\\(?:=\\(.*\\)\\)?$" arg) (or (string-match "^\\(--\\w[a-z0-9-_]+\\)\\(?:=\\(.*\\)\\)?$" arg)
(string-match "^\\(-[^-]\\)$" arg))) (string-match "^\\(-[^-]\\)$" arg)))
(doom-log "Found switch: %s" arg) (doom-log "cli-context-parse: found switch %S" arg)
(catch :skip (catch :skip
(let* ((fullflag (match-string 1 arg)) (let* ((fullflag (match-string 1 arg))
(normflag (if (string-prefix-p "--no-" fullflag) (normflag (if (string-prefix-p "--no-" fullflag)
@ -825,7 +824,7 @@ executable context."
fullflag)) fullflag))
(option (or (doom-cli-context-find-option context normflag) (option (or (doom-cli-context-find-option context normflag)
(when (member fullflag '("-?" "--help" "--version")) (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) (setf (doom-cli-context-meta-p context) fullflag)
(throw :skip t)) (throw :skip t))
(when rest? (when rest?
@ -869,11 +868,11 @@ executable context."
(cli (doom-cli-get command t)) (cli (doom-cli-get command t))
(rcli (doom-cli-get command)) (rcli (doom-cli-get command))
(key (doom-cli-key rcli))) (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 ;; Show warnings depending on CLI plists
(when (doom-cli-alias cli) (when (doom-cli-alias cli)
(dolist (pcli (doom-cli-path 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)))) (push (doom-cli-key pcli) (doom-cli-context-path context))))
;; Collect &rest for this command ;; Collect &rest for this command
(setf (doom-cli-context-command context) key (setf (doom-cli-context-command context) key
@ -896,7 +895,7 @@ executable context."
t)) t))
((push arg arguments) ((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)) (setf (alist-get t (doom-cli-context-arguments context))
(append (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 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 `doom-cli-benchmark-threshold' is nil), under no condition should a benchmark be
shown." shown."
(doom-log "%s (GCs: %d, elapsed: %.6fs)" (doom-log "cli: %s (GCs: %d, elapsed: %.6fs)"
(if (= doom-cli--exit-code 254) "Restarted" "Finished") (if (= doom-cli--exit-code 254) "Restarted" "Finished")
gcs-done gc-elapsed) gcs-done gc-elapsed)
(when-let* ((init-time (doom-cli-context-init-time context)) (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)." read/use it (e.g. like a :help CLI)."
(let ((oldcommand (doom-cli-context-command context))) (let ((oldcommand (doom-cli-context-command context)))
(if oldcommand (if oldcommand
(doom-log "doom-cli-call: %s -> %s" oldcommand args) (doom-log "cli-call: %s -> %s" oldcommand args)
(doom-log "doom-cli-call: %s" oldcommand args)) (doom-log "cli-call: %s" oldcommand args))
(when error (when error
(setf (doom-cli-context-error context) error)) (setf (doom-cli-context-error context) error))
(setf (doom-cli-context-command context) nil (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))))))) (shell-quote-argument (match-string 2 env)))))))
(cl-incf (doom-cli-context-step context)) (cl-incf (doom-cli-context-step context))
(with-file-modes #o600 (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 (doom-file-write
context-file (let ((newcontext (copy-doom-cli-context context)) context-file (let ((newcontext (copy-doom-cli-context context))
(print-level nil) (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-stdout)
(convert-buffer doom-cli-context-stderr)) (convert-buffer doom-cli-context-stderr))
newcontext)) newcontext))
(doom-log "Writing post-script file: %s" script-file) (doom-log "cli:restart: writing post-script to %s" script-file)
(doom-file-write (doom-file-write
script-file `("#!/usr/bin/env sh\n" script-file `("#!/usr/bin/env sh\n"
"trap _doomcleanup EXIT\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." "If CLI is autoloaded, load it, otherwise return it unchanged."
(or (when-let* ((path (doom-cli-autoload cli)) (or (when-let* ((path (doom-cli-autoload cli))
(path (locate-file-internal path doom-cli-load-path load-suffixes))) (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))) (let ((doom-cli--plist (doom-cli-plist cli)))
(load! path)) (load! path))
(let* ((key (doom-cli-key cli)) (let* ((key (doom-cli-key cli))
@ -1905,7 +1904,8 @@ errors to `doom-cli-error-file')."
;; Clone output to stdout/stderr buffers for logging. ;; Clone output to stdout/stderr buffers for logging.
(standard-output (doom-rpartial #'doom-cli--output context)) (standard-output (doom-rpartial #'doom-cli--output context))
(#'message (doom-partial #'doom-cli--redirect-output-a 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 show-benchmark-fn 94)
(add-hook 'kill-emacs-hook write-logs-fn 95) (add-hook 'kill-emacs-hook write-logs-fn 95)
(when (doom-cli-context-pipe-p context :out t) (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 ""))) (while (if-let (in (ignore-errors (read-from-minibuffer "")))
(insert in "\n") (insert in "\n")
(ignore-errors (delete-char -1)))))) (ignore-errors (delete-char -1))))))
(doom-log "doom-cli-run: %s" command-line-args)
(doom-cli--exit (doom-cli--exit
(condition-case e (condition-case e
(let* ((args (cons (if (getenv "__DOOMDUMP") :dump prefix) args)) (let* ((args (cons (if (getenv "__DOOMDUMP") :dump prefix) args))

View file

@ -13,9 +13,11 @@ debug mode is off."
(let ((inhibit-message (not init-file-debug))) (let ((inhibit-message (not init-file-debug)))
(message (message
"%s" (propertize "%s" (propertize
(format (concat "* [%.06f] " ,output) ;; Byte compiler: don't complain about more args than %-sequences.
(float-time (time-subtract (current-time) before-init-time)) (with-no-warnings
,@args) (format (concat "* %.06f: " ,output)
(float-time (time-subtract (current-time) before-init-time))
,@args))
'face 'font-lock-doc-face))))) '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. "Load PATH and handle any Doom errors that arise from it.
If NOERROR, don't throw an error if PATH doesn't exist." 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 (condition-case-unless-debug e
(load path noerror 'nomessage) (load path noerror 'nomessage)
((doom-error file-missing) ((doom-error file-missing)

View file

@ -106,14 +106,14 @@ intervals."
(let ((req (pop packages)) (let ((req (pop packages))
idle-time) idle-time)
(if (featurep req) (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 (condition-case-unless-debug e
(and (and
(or (null (setq idle-time (current-idle-time))) (or (null (setq idle-time (current-idle-time)))
(< (float-time idle-time) doom-incremental-first-idle-timer) (< (float-time idle-time) doom-incremental-first-idle-timer)
(not (not
(while-no-input (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 ;; If `default-directory' doesn't exist or is
;; unreadable, Emacs throws file errors. ;; unreadable, Emacs throws file errors.
(let ((default-directory doom-emacs-dir) (let ((default-directory doom-emacs-dir)
@ -127,7 +127,7 @@ intervals."
(message "Error: failed to incrementally load %S because: %s" req e) (message "Error: failed to incrementally load %S because: %s" req e)
(setq packages nil))) (setq packages nil)))
(if (null packages) (if (null packages)
(doom-log "[ILoader] Finished!") (doom-log "start:iloader: Finished!")
(run-at-time (if idle-time (run-at-time (if idle-time
doom-incremental-idle-timer doom-incremental-idle-timer
doom-incremental-first-idle-timer) doom-incremental-first-idle-timer)

View file

@ -28,36 +28,37 @@
Each entry can be a variable symbol or a cons cell whose CAR is the variable 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.") 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 _) (defun doom-debug--watch-vars-h (&rest _)
(when-let (bound-vars (cl-delete-if-not #'boundp doom-debug--undefined-vars)) (when-let (vars (copy-sequence doom-debug--unbound-vars))
(doom-log "New variables available: %s" bound-vars) (setq doom-debug--unbound-vars nil)
(let ((message-log-max nil)) (mapc #'doom-debug--set-var vars)))
(doom-debug-mode -1)
(doom-debug-mode +1)))) (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 ;;;###autoload
(define-minor-mode doom-debug-mode (define-minor-mode doom-debug-mode
"Toggle `debug-on-error' and `init-file-debug' for verbose logging." "Toggle `debug-on-error' and `init-file-debug' for verbose logging."
:init-value init-file-debug
:global t :global t
(let ((enabled doom-debug-mode)) (let ((enabled doom-debug-mode))
(setq doom-debug--undefined-vars nil) (doom-log "debug: enabled!")
(dolist (var doom-debug-variables) (mapc #'doom-debug--set-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)))))
(when (called-interactively-p 'any) (when (called-interactively-p 'any)
(when (fboundp 'explain-pause-mode) (when (fboundp 'explain-pause-mode)
(explain-pause-mode (if enabled +1 -1)))) (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 ;; potentially define one of `doom-debug-variables'), in case some of them
;; aren't defined when `doom-debug-mode' is first loaded. ;; aren't defined when `doom-debug-mode' is first loaded.
(cond (enabled (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 ;; Produce more helpful (and visible) error messages from errors
;; emitted from hooks (particularly mode hooks), that usually go ;; emitted from hooks (particularly mode hooks), that usually go
;; unnoticed otherwise. ;; 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) (advice-remove #'gcmh-idle-garbage-collect #'doom-debug-shut-up-a)
(remove-variable-watcher 'doom-debug-variables #'doom-debug--watch-vars-h) (remove-variable-watcher 'doom-debug-variables #'doom-debug--watch-vars-h)
(remove-hook 'after-load-functions #'doom-debug--watch-vars-h) (remove-hook 'after-load-functions #'doom-debug--watch-vars-h)
(doom-log "debug: disabled")
(message "Debug mode disabled!"))))) (message "Debug mode disabled!")))))
(defun doom-debug-shut-up-a (fn &rest args) (defun doom-debug-shut-up-a (fn &rest args)