Subject: bug#25158: [PATCH] A better way for test code to access messages

From: Gemini Lasswell <[email-masked]>
Date: Sat, 10 Dec 2016 09:29:05 -0800

Here is a quote from Bug#24939's discussion, regarding the technique
used by autorevert-tests.el, filenotify-tests.el and the proposed
kmacro-tests.el to collect messages issued during part of a test by
temporarily narrowing *Messages*:

Eli Zaretskii <[email-masked]> writes:

> I don't like this implementation.  First, playing restriction games
> with *Messages* is inherently unsafe, because that buffer is treated
> specially by the code which puts messages there.  Second, this assumes
> *Messages* will have each message verbatim, which is false, because
> repeated messages aren't inserted.  And finally, some code can disable
> message logging or use some mechanism for displaying echo-area
> messages that bypasses *Messages*, in which case this macro will not
> catch the message.
>
> So I'd suggest instead to override or advice 'message', so you could
> get your hands on the messages more reliably.  It is possible we
> should have a more thorough infrastructure for collecting echo-area
> messages, which probably means parts of it should be implemented in C,
> but that's a separate project.
>

The attached patch adds a new macro called ert-with-message-capture to
ert-x.el which temporarily adds advice to 'message' to collect messages.
I've also modified autorevert-tests.el and filenotify-tests.el to use
the new macro. If or when the more thorough infrastructure is
implemented, that could replace the use of advice in this macro but the
tests which use it should not have to change.

Michael, in modifying autorevert-tests.el, at the start of
auto-revert-test02-auto-revert-deleted-file, *Messages* was narrowed,
and then narrowed again before the call to auto-revert--wait-for-revert,
so it looked safe to delete the first narrowing instead of replacing it
with ert-with-message-capture. Let me know if I've missed something
there.

>From da4bfb3adbb97841a3bf8bd80dfee7e6a474be32 Mon Sep 17 00:00:00 2001
From: gazally <[email-masked]>
Date: Wed, 30 Nov 2016 12:12:53 -0800
Subject: [PATCH] Add ert-with-message-capture

* lisp/emacs-lisp/ert-x.el (ert-with-message-capture): New function.

* test/lisp/autorevert-tests.el (auto-revert--wait-for-revert)
(auto-revert-test00-auto-revert-mode)
(auto-revert-test01-auto-revert-several-files)
(auto-revert-test02-auto-revert-deleted-file)
(auto-revert-test03-auto-revert-tail-mode)
(auto-revert-test04-auto-revert-mode-dired): Use it.

* test/lisp/filenotify-tests.el (file-notify-test03-autorevert): Use it.
---
 lisp/emacs-lisp/ert-x.el      |  24 ++++++
 test/lisp/autorevert-tests.el | 166 +++++++++++++++++++-----------------------
 test/lisp/filenotify-tests.el |  56 +++++++-------
 3 files changed, 125 insertions(+), 121 deletions(-)

diff --git a/lisp/emacs-lisp/ert-x.el b/lisp/emacs-lisp/ert-x.el
index 2a2418f..42899b3 100644
--- a/lisp/emacs-lisp/ert-x.el
+++ b/lisp/emacs-lisp/ert-x.el
@@ -285,6 +285,30 @@ ert-buffer-string-reindented
             (kill-buffer clone)))))))

+(defmacro ert-with-message-capture (var &rest body)
+  "Execute BODY while collecting anything written with `message' in VAR.
+
+Capture all messages produced by `message' when it is called from
+Lisp, and concatenate them separated by newlines into one string.
+
+This is useful for separating the issuance of messages by the
+code under test from the behavior of the *Messages* buffer."
+  (declare (debug (symbolp body))
+           (indent 1))
+  (let ((g-advice (cl-gensym)))
+    `(let* ((,var "")
+            (,g-advice (lambda (func &rest args)
+                         (if (or (null args) (equal (car args) ""))
+                             (apply func args)
+                           (let ((msg (apply #'format-message args)))
+                             (setq ,var (concat ,var msg "\n"))
+                             (funcall func "%s" msg))))))
+       (advice-add 'message :around ,g-advice)
+       (unwind-protect
+           (progn ,@body)
+         (advice-remove 'message ,g-advice)))))
+
+
 (provide 'ert-x)
 
 ;;; ert-x.el ends here
diff --git a/test/lisp/autorevert-tests.el b/test/lisp/autorevert-tests.el
index 2f951c0..4dbeec5 100644
--- a/test/lisp/autorevert-tests.el
+++ b/test/lisp/autorevert-tests.el
@@ -24,24 +24,29 @@
 ;;; Code:
 
 (require 'ert)
+(require 'ert-x)
 (require 'autorevert)
 (setq auto-revert-notify-exclude-dir-regexp "nothing-to-be-excluded"
       auto-revert-stop-on-user-input nil)
 
 (defconst auto-revert--timeout 10
-  "Time to wait until a message appears in the *Messages* buffer.")
+  "Time to wait for a message.")
+
+(defvar auto-revert--messages nil
+  "Used to collect messages issued during a section of a test.")
 
 (defun auto-revert--wait-for-revert (buffer)
-  "Wait until the *Messages* buffer reports reversion of BUFFER."
+  "Wait until a message reports reversion of BUFFER.
+This expects `auto-revert--messages' to be bound by
+`ert-with-message-capture' before calling."
   (with-timeout (auto-revert--timeout nil)
-    (with-current-buffer "*Messages*"
-      (while
-          (null (string-match
-                 (format-message "Reverting buffer `%s'." (buffer-name buffer))
-                 (buffer-string)))
-	(if (with-current-buffer buffer auto-revert-use-notify)
-	    (read-event nil nil 0.1)
-	  (sleep-for 0.1))))))
+    (while
+        (null (string-match
+               (format-message "Reverting buffer `%s'." (buffer-name buffer))
+               auto-revert--messages))
+      (if (with-current-buffer buffer auto-revert-use-notify)
+          (read-event nil nil 0.1)
+        (sleep-for 0.1)))))
 
 (ert-deftest auto-revert-test00-auto-revert-mode ()
   "Check autorevert for a file."
@@ -51,41 +56,38 @@ auto-revert--wait-for-revert
         buf)
     (unwind-protect
 	(progn
-          (with-current-buffer (get-buffer-create "*Messages*")
-            (narrow-to-region (point-max) (point-max)))
-	  (write-region "any text" nil tmpfile nil 'no-message)
+          (write-region "any text" nil tmpfile nil 'no-message)
 	  (setq buf (find-file-noselect tmpfile))
-	  (with-current-buffer buf
-	    (should (string-equal (buffer-string) "any text"))
-            ;; `buffer-stale--default-function' checks for
-            ;; `verify-visited-file-modtime'.  We must ensure that it
-            ;; returns nil.
-            (sleep-for 1)
-	    (auto-revert-mode 1)
-	    (should auto-revert-mode)
+          (with-current-buffer buf
+            (ert-with-message-capture auto-revert--messages
+              (should (string-equal (buffer-string) "any text"))
+              ;; `buffer-stale--default-function' checks for
+              ;; `verify-visited-file-modtime'.  We must ensure that it
+              ;; returns nil.
+              (sleep-for 1)
+              (auto-revert-mode 1)
+              (should auto-revert-mode)
 
-	    ;; Modify file.  We wait for a second, in order to have
-	    ;; another timestamp.
-	    (sleep-for 1)
-            (write-region "another text" nil tmpfile nil 'no-message)
+              ;; Modify file.  We wait for a second, in order to have
+              ;; another timestamp.
+              (sleep-for 1)
+              (write-region "another text" nil tmpfile nil 'no-message)
 
-	    ;; Check, that the buffer has been reverted.
-            (auto-revert--wait-for-revert buf)
+              ;; Check, that the buffer has been reverted.
+              (auto-revert--wait-for-revert buf))
             (should (string-match "another text" (buffer-string)))
 
             ;; When the buffer is modified, it shall not be reverted.
-            (with-current-buffer (get-buffer-create "*Messages*")
-              (narrow-to-region (point-max) (point-max)))
-            (set-buffer-modified-p t)
-	    (sleep-for 1)
-            (write-region "any text" nil tmpfile nil 'no-message)
+            (ert-with-message-capture auto-revert--messages
+              (set-buffer-modified-p t)
+              (sleep-for 1)
+              (write-region "any text" nil tmpfile nil 'no-message)
 
-	    ;; Check, that the buffer hasn't been reverted.
-            (auto-revert--wait-for-revert buf)
+              ;; Check, that the buffer hasn't been reverted.
+              (auto-revert--wait-for-revert buf))
             (should-not (string-match "any text" (buffer-string)))))
 
       ;; Exit.
-      (with-current-buffer "*Messages*" (widen))
       (ignore-errors
         (with-current-buffer buf (set-buffer-modified-p nil))
         (kill-buffer buf))
@@ -106,13 +108,11 @@ auto-revert--wait-for-revert
           (make-temp-file (expand-file-name "auto-revert-test" tmpdir1)))
          buf1 buf2)
     (unwind-protect
-	(progn
-          (with-current-buffer (get-buffer-create "*Messages*")
-            (narrow-to-region (point-max) (point-max)))
-	  (write-region "any text" nil tmpfile1 nil 'no-message)
-	  (setq buf1 (find-file-noselect tmpfile1))
-	  (write-region "any text" nil tmpfile2 nil 'no-message)
-	  (setq buf2 (find-file-noselect tmpfile2))
+        (ert-with-message-capture auto-revert--messages
+          (write-region "any text" nil tmpfile1 nil 'no-message)
+          (setq buf1 (find-file-noselect tmpfile1))
+          (write-region "any text" nil tmpfile2 nil 'no-message)
+          (setq buf2 (find-file-noselect tmpfile2))
 
           (dolist (buf (list buf1 buf2))
             (with-current-buffer buf
@@ -148,7 +148,6 @@ auto-revert--wait-for-revert
               (should (string-match "another text" (buffer-string))))))
 
       ;; Exit.
-      (with-current-buffer "*Messages*" (widen))
       (ignore-errors
         (dolist (buf (list buf1 buf2))
           (with-current-buffer buf (set-buffer-modified-p nil))
@@ -165,8 +164,6 @@ auto-revert--wait-for-revert
         buf)
     (unwind-protect
 	(progn
-          (with-current-buffer (get-buffer-create "*Messages*")
-            (narrow-to-region (point-max) (point-max)))
           (write-region "any text" nil tmpfile nil 'no-message)
 	  (setq buf (find-file-noselect tmpfile))
 	  (with-current-buffer buf
@@ -184,42 +181,36 @@ auto-revert--wait-for-revert
              'before-revert-hook
              (lambda () (delete-file buffer-file-name))
              nil t)
-            (with-current-buffer (get-buffer-create "*Messages*")
-              (narrow-to-region (point-max) (point-max)))
-	    (sleep-for 1)
-            (write-region "another text" nil tmpfile nil 'no-message)
 
-	    ;; Check, that the buffer hasn't been reverted.  File
-	    ;; notification should be disabled, falling back to
-	    ;; polling.
-            (auto-revert--wait-for-revert buf)
+            (ert-with-message-capture auto-revert--messages
+              (sleep-for 1)
+              (write-region "another text" nil tmpfile nil 'no-message)
+              (auto-revert--wait-for-revert buf))
+            ;; Check, that the buffer hasn't been reverted.  File
+            ;; notification should be disabled, falling back to
+            ;; polling.
             (should (string-match "any text" (buffer-string)))
             (should-not auto-revert-use-notify)
 
             ;; Once the file has been recreated, the buffer shall be
             ;; reverted.
             (kill-local-variable 'before-revert-hook)
-            (with-current-buffer (get-buffer-create "*Messages*")
-              (narrow-to-region (point-max) (point-max)))
-	    (sleep-for 1)
-            (write-region "another text" nil tmpfile nil 'no-message)
-
-	    ;; Check, that the buffer has been reverted.
-            (auto-revert--wait-for-revert buf)
+            (ert-with-message-capture auto-revert--messages
+              (sleep-for 1)
+              (write-region "another text" nil tmpfile nil 'no-message)
+              (auto-revert--wait-for-revert buf))
+            ;; Check, that the buffer has been reverted.
             (should (string-match "another text" (buffer-string)))
 
             ;; An empty file shall still be reverted.
-            (with-current-buffer (get-buffer-create "*Messages*")
-              (narrow-to-region (point-max) (point-max)))
-	    (sleep-for 1)
-            (write-region "" nil tmpfile nil 'no-message)
-
-	    ;; Check, that the buffer has been reverted.
-            (auto-revert--wait-for-revert buf)
+            (ert-with-message-capture auto-revert--messages
+              (sleep-for 1)
+              (write-region "" nil tmpfile nil 'no-message)
+              (auto-revert--wait-for-revert buf))
+            ;; Check, that the buffer has been reverted.
             (should (string-equal "" (buffer-string)))))
 
       ;; Exit.
-      (with-current-buffer "*Messages*" (widen))
       (ignore-errors
         (with-current-buffer buf (set-buffer-modified-p nil))
         (kill-buffer buf))
@@ -232,9 +223,7 @@ auto-revert--wait-for-revert
   (let ((tmpfile (make-temp-file "auto-revert-test"))
         buf)
     (unwind-protect
-	(progn
-          (with-current-buffer (get-buffer-create "*Messages*")
-            (narrow-to-region (point-max) (point-max)))
+        (ert-with-message-capture auto-revert--messages
           (write-region "any text" nil tmpfile nil 'no-message)
 	  (setq buf (find-file-noselect tmpfile))
 	  (with-current-buffer buf
@@ -259,7 +248,6 @@ auto-revert--wait-for-revert
              (string-match "modified text\nanother text" (buffer-string)))))
 
       ;; Exit.
-      (with-current-buffer "*Messages*" (widen))
       (ignore-errors (kill-buffer buf))
       (ignore-errors (delete-file tmpfile)))))
 
@@ -283,33 +271,29 @@ auto-revert--wait-for-revert
 	    (should
              (string-match name (substring-no-properties (buffer-string))))
 
-	    ;; Delete file.  We wait for a second, in order to have
-	    ;; another timestamp.
-            (with-current-buffer (get-buffer-create "*Messages*")
-              (narrow-to-region (point-max) (point-max)))
-	    (sleep-for 1)
-            (delete-file tmpfile)
-
-	    ;; Check, that the buffer has been reverted.
-            (auto-revert--wait-for-revert buf)
+            (ert-with-message-capture auto-revert--messages
+              ;; Delete file.  We wait for a second, in order to have
+              ;; another timestamp.
+              (sleep-for 1)
+              (delete-file tmpfile)
+              (auto-revert--wait-for-revert buf))
+            ;; Check, that the buffer has been reverted.
             (should-not
              (string-match name (substring-no-properties (buffer-string))))
 
-            ;; Make dired buffer modified.  Check, that the buffer has
-            ;; been still reverted.
-            (with-current-buffer (get-buffer-create "*Messages*")
-              (narrow-to-region (point-max) (point-max)))
-            (set-buffer-modified-p t)
-	    (sleep-for 1)
-            (write-region "any text" nil tmpfile nil 'no-message)
+            (ert-with-message-capture auto-revert--messages
+              ;; Make dired buffer modified.  Check, that the buffer has
+              ;; been still reverted.
+              (set-buffer-modified-p t)
+              (sleep-for 1)
+              (write-region "any text" nil tmpfile nil 'no-message)
 
-	    ;; Check, that the buffer has been reverted.
-            (auto-revert--wait-for-revert buf)
+              (auto-revert--wait-for-revert buf))
+            ;; Check, that the buffer has been reverted.
             (should
              (string-match name (substring-no-properties (buffer-string))))))
 
       ;; Exit.
-      (with-current-buffer "*Messages*" (widen))
       (ignore-errors
         (with-current-buffer buf (set-buffer-modified-p nil))
         (kill-buffer buf))
diff --git a/test/lisp/filenotify-tests.el b/test/lisp/filenotify-tests.el
index 0e6e58e..07a88ed 100644
--- a/test/lisp/filenotify-tests.el
+++ b/test/lisp/filenotify-tests.el
@@ -36,6 +36,7 @@
 ;;; Code:
 
 (require 'ert)
+(require 'ert-x)
 (require 'filenotify)
 (require 'tramp)
 
@@ -640,21 +641,19 @@ file-notify--test-with-events
 	    (should auto-revert-notify-watch-descriptor)
 
 	    ;; Modify file.  We wait for a second, in order to have
-	    ;; another timestamp.
-            (with-current-buffer (get-buffer-create "*Messages*")
-              (narrow-to-region (point-max) (point-max)))
-	    (sleep-for 1)
-            (write-region
-             "another text" nil file-notify--test-tmpfile nil 'no-message)
-
-	    ;; Check, that the buffer has been reverted.
-	    (with-current-buffer (get-buffer-create "*Messages*")
-	      (file-notify--wait-for-events
-	       timeout
-	       (string-match
+            ;; another timestamp.
+            (ert-with-message-capture captured-messages
+              (sleep-for 1)
+              (write-region
+               "another text" nil file-notify--test-tmpfile nil 'no-message)
+
+              ;; Check, that the buffer has been reverted.
+              (file-notify--wait-for-events
+               timeout
+               (string-match
                 (format-message "Reverting buffer `%s'." (buffer-name buf))
-                (buffer-string))))
-	    (should (string-match "another text" (buffer-string)))
+                captured-messages))
+              (should (string-match "another text" (buffer-string))))
 
             ;; Stop file notification.  Autorevert shall still work via polling.
 	    (file-notify-rm-watch auto-revert-notify-watch-descriptor)
@@ -665,27 +664,24 @@ file-notify--test-with-events
 
 	    ;; Modify file.  We wait for two seconds, in order to
 	    ;; have another timestamp.  One second seems to be too
-	    ;; short.
-	    (with-current-buffer (get-buffer-create "*Messages*")
-	      (narrow-to-region (point-max) (point-max)))
-	    (sleep-for 2)
-	    (write-region
-	     "foo bla" nil file-notify--test-tmpfile nil 'no-message)
-
-	    ;; Check, that the buffer has been reverted.
-	    (with-current-buffer (get-buffer-create "*Messages*")
-	      (file-notify--wait-for-events
-	       timeout
-	       (string-match
-		(format-message "Reverting buffer `%s'." (buffer-name buf))
-		(buffer-string))))
-	    (should (string-match "foo bla" (buffer-string))))
+            ;; short.
+            (ert-with-message-capture captured-messages
+              (sleep-for 2)
+              (write-region
+               "foo bla" nil file-notify--test-tmpfile nil 'no-message)
+
+              ;; Check, that the buffer has been reverted.
+              (file-notify--wait-for-events
+               timeout
+               (string-match
+                (format-message "Reverting buffer `%s'." (buffer-name buf))
+                captured-messages))
+              (should (string-match "foo bla" (buffer-string)))))
 
           ;; The environment shall be cleaned up.
           (file-notify--test-cleanup-p))
 
       ;; Cleanup.
-      (with-current-buffer "*Messages*" (widen))
       (ignore-errors (kill-buffer buf))
       (file-notify--test-cleanup))))
 
-- 
2.10.1