New doom-log macro for debug-time logging

doom-log won't interfere with the minibuffer if it's in use, and will
report the originating module.

Addresses #1215

core/autoload/packages.el

@@ -262,8 +262,7 @@ Used by `doom-packages-update'."
     ;; asynchronously.
     (let (futures)
       (dolist (pkg quelpa-pkgs)
-        (when doom-debug-mode
+        (doom-log "New thread for: %s" pkg)
-          (message "New thread for: %s" pkg))
         (push (async-start
                `(lambda ()
                   (let ((gc-cons-threshold ,doom-gc-cons-upper-limit)

core/core-lib.el

@@ -102,6 +102,22 @@ This is used by `associate!', `file-exists-p!' and `project-file-exists-p!'."
   (cl-check-type :test keyword)
   (substring (symbol-name keyword) 1))
 
+(defmacro doom-log (format-string &rest args)
+  "Log to *Messages* if `doom-debug-mode' is on.
+Does not interrupt the minibuffer if it is in use, but still logs to *Messages*.
+Accepts the same arguments as `message'."
+  (when doom-debug-mode
+    `(let ((inhibit-message (active-minibuffer-window)))
+       (message
+        ,(concat (propertize "DOOM " 'face 'font-lock-comment-face)
+                 format-string
+                 (when doom--current-module
+                   (propertize (format " [%s/%s]"
+                                       (doom-keyword-name (car doom--current-module))
+                                       (cdr doom--current-module))
+                               'face 'warning)))
+        ,@args))))
+
 (defun FILE! ()
   "Return the emacs lisp file this macro is called from."
   (cond ((bound-and-true-p byte-compile-current-file))

core/core-modules.el

@@ -250,8 +250,7 @@ non-nil, return paths of possible modules, activated or otherwise."
         (use-package-concat
          `((fset ',fn
                  (lambda (&rest _)
-                   (when doom-debug-mode
+                   (doom-log "Loading deferred package %s from %s" ',name ',fn)
-                     (message "Loading deferred package %s from %s" ',name ',fn))
                    (condition-case e (require ',name)
                      ((debug error)
                       (message "Failed to load deferred package %s: %s" ',name e)))

core/core.el

@@ -264,7 +264,7 @@ If you want to disable incremental loading altogether, either remove
 
 Set this to nil to disable incremental loading.")
 
-(defvar doom-incremental-idle-timer 1
+(defvar doom-incremental-idle-timer 1.5
   "How long (in idle seconds) in between incrementally loading packages.")
 
 (defun doom-load-packages-incrementally (packages &optional now)
@@ -280,17 +280,17 @@ intervals."
         (let* ((reqs (cl-delete-if #'featurep packages))
                (req (ignore-errors (pop reqs))))
           (when req
-            (when doom-debug-mode
+            (doom-log "Incrementally loading %s" req)
-              (message "Incrementally loading %s" req))
             (condition-case e
                 (require req nil t)
-              (error
+              ((error debug)
                (message "Failed to load '%s' package incrementally, because: %s"
                         req e)))
-            (when reqs
+            (if reqs
-              (run-with-idle-timer doom-incremental-idle-timer
+                (run-with-idle-timer doom-incremental-idle-timer
-                                   nil #'doom-load-packages-incrementally
+                                     nil #'doom-load-packages-incrementally
-                                   reqs t))))))))
+                                     reqs t)
+              (doom-log "Finished incremental loading"))))))))
 
 (defun doom|load-packages-incrementally ()
   "Begin incrementally loading packages in `doom-incremental-packages'.
@@ -314,8 +314,7 @@ If this is a daemon session, load them all immediately instead."
 issues easier.
 
 Meant to be used with `run-hook-wrapped'."
-  (when doom-debug-mode
+  (doom-log "Running doom hook: %s" hook)
-    (message "Running doom hook: %s" hook))
   (condition-case e
       (funcall hook)
     ((debug error)

modules/editor/format/autoload/settings.el

@@ -34,16 +34,14 @@
         (insert input)
         (condition-case e
             (progn
-              (when doom-debug-mode
+              (doom-log "formatter (commandp) %s" #',formatter)
-                (message "formatter (commandp) %s" #',formatter))
               (call-interactively #',formatter)
               (list nil ""))
           (error (list t (error-message-string e))))))))
 
 (defun +format--make-function (formatter &rest _)
   `(progn
-     (when doom-debug-mode
+     (doom-log "formatter (functionp) %s" #',formatter)
-       (message "formatter (functionp) %s" #',formatter))
      (format-all-buffer-thunk #',formatter)))
 
 (defun +format--make-shell-command (command ok-statuses error-regexp)
@@ -66,8 +64,7 @@
                           ((stringp this)
                            (push this subargs))))
                   (setq args (append subargs args)))))))
-     (when doom-debug-mode
+     (doom-log "formatter (arglist) %s" args)
-       (message "formatter (arglist) %s" args))
      (if ,(and (or ok-statuses error-regexp) t)
          (apply #'format-all-buffer-hard
                 ',ok-statuses ,error-regexp

modules/feature/evil/+everywhere.el

@@ -163,8 +163,7 @@ variable for an explanation of the defaults (in comments). See
 
 (defun +evil-collection-init (module)
   (unless (memq (or (car-safe module) module) +evil-collection-disabled-list)
-    (when doom-debug-mode
+    (doom-log "Initialized evil-collection-%s" (or (car-safe module) module))
-      (message "Loaded evil-collection-%s" (or (car-safe module) module)))
     (with-demoted-errors "evil-collection error: %s"
       (evil-collection-init (list module)))))
 

modules/feature/lookup/autoload/lookup.el

@@ -108,6 +108,7 @@ Otherwise, these properties are available to be set:
          (xref-backend-identifier-at-point (xref-find-backend)))))
 
 (defun +lookup--run-hooks (hook identifier origin &optional other-window)
+  (doom-log "Looking up '%s' with '%s'" identifier hook)
   (condition-case-unless-debug e
       (if (get hook '+lookup-async)
           (progn