bug#47320: Improve failure reporting in test/lisp/electrict-tests.el

bug#47320: Improve failure reporting in test/lisp/electrict-tests.el

[Alan Mackenzie]

Hello, Emacs.

When running make check, and a failure occurs in electric-tests.elc, the
resulting output in electric-tests.log is frustratingly cryptic.
Although one can fairly easily get back to the source code for the test
in electric-tests.el, it is difficult to reconstruct the snippet of text
on which the test was performed.  This is because the tests are
(necessarily) generated by fairly inscrutable macros.

This is a shame, since each generated test has its own exceptionally
clear generated doc-string.  An example of such a doc string is:

#########################################################################
Electricity test in a `c-mode' buffer.

Start with point at 7 in a 7-char-long buffer
like this one:

  |"foo \"|   (buffer start and end are denoted by `|')

Now call this:

#'electric-quote-local-mode

Ensure the following bindings:

'((electric-quote-replace-double . t)
  (electric-quote-comment . t)
  (electric-quote-string . t))

Now press the key for: "

The buffer's contents should become:

  |"foo \""|

, and point should be at 7.
#########################################################################

My proposal is that on a test failure, this generated doc-string should
be output along with the other failure stuff.  It doesn't actually add
all that much bulk to the .log file.

Here is patch which does this.  If there are no objections, I will
commit it in a day or two.



diff --git a/test/lisp/electric-tests.el b/test/lisp/electric-tests.el
index 62a42b7fe4..44b3d8b672 100644
--- a/test/lisp/electric-tests.el
+++ b/test/lisp/electric-tests.el
@@ -50,7 +50,8 @@ save-electric-modes
   `(call-with-saved-electric-modes #'(lambda () ,@body)))
 
 (defun electric-pair-test-for (fixture where char expected-string
-                                       expected-point mode bindings fixture-fn)
+                                       expected-point mode bindings
+                                       fixture-fn &optional doc-string)
   (with-temp-buffer
     (funcall mode)
     (insert fixture)
@@ -63,6 +64,14 @@ electric-pair-test-for
             (mapcar #'car bindings)
             (mapcar #'cdr bindings)
           (call-interactively (key-binding `[,last-command-event])))))
+    (when
+        (and doc-string
+             (not
+              (and
+               (equal (buffer-substring-no-properties (point-min) (point-max))
+                      expected-string)
+               (equal (point) expected-point))))
+      (message "\n%s\n" doc-string))
     (should (equal (buffer-substring-no-properties (point-min) (point-max))
                    expected-string))
     (should (equal (point)
@@ -109,14 +118,9 @@ electric-pair-test-for
            (fixture (format "%s%s%s" prefix fixture suffix))
            (expected-string (format "%s%s%s" prefix expected-string suffix))
            (expected-point (+ (length prefix) expected-point))
-           (pos (+ (length prefix) pos)))
-      `(ert-deftest ,(intern (format "electric-pair-%s-at-point-%s-in-%s%s"
-                                     name
-                                     (1+ pos)
-                                     mode
-                                     extra-desc))
-           ()
-         ,(format "Electricity test in a `%s' buffer.\n
+           (pos (+ (length prefix) pos))
+           (doc-string
+            (format "Electricity test in a `%s' buffer.\n
 Start with point at %d in a %d-char-long buffer
 like this one:
 
@@ -143,7 +147,14 @@ electric-pair-test-for
                   char
                   (if (string= fixture expected-string) "stay" "become")
                   (replace-regexp-in-string "\n" "\\\\n" expected-string)
-                  expected-point)
+                  expected-point)))
+      `(ert-deftest ,(intern (format "electric-pair-%s-at-point-%s-in-%s%s"
+                                     name
+                                     (1+ pos)
+                                     mode
+                                     extra-desc))
+           ()
+         ,doc-string
          (electric-pair-test-for ,fixture
                                  ,(1+ pos)
                                  ,char
@@ -151,7 +162,8 @@ electric-pair-test-for
                                  ,expected-point
                                  ',mode
                                  ,bindings
-                                 ,fixture-fn)))))
+                                 ,fixture-fn
+                                 ,doc-string)))))
 
 (cl-defmacro define-electric-pair-test
     (name fixture


-- 
Alan Mackenzie (Nuremberg, Germany).

bug#47320: Improve failure reporting in test/lisp/electrict-tests.el

[Michael Albinus]

Alan Mackenzie <acm@muc.de> writes:

> Hello, Emacs.

Hi Alan,

> My proposal is that on a test failure, this generated doc-string should
> be output along with the other failure stuff.  It doesn't actually add
> all that much bulk to the .log file.
>
> Here is patch which does this.  If there are no objections, I will
> commit it in a day or two.

There is the explainer functionality in ert, see

(info "(ert)Defining Explanation Functions")

I recommend to use it, for better readability of the test code. Examples
are in our test files.

Best regards, Michael.

bug#47320: Improve failure reporting in test/lisp/electrict-tests.el

[Alan Mackenzie]

Hello, Michael.

On Tue, Mar 23, 2021 at 09:53:04 +0100, Michael Albinus wrote:
> Alan Mackenzie <acm@muc.de> writes:

> > Hello, Emacs.

> Hi Alan,

> > My proposal is that on a test failure, this generated doc-string should
> > be output along with the other failure stuff.  It doesn't actually add
> > all that much bulk to the .log file.

> > Here is patch which does this.  If there are no objections, I will
> > commit it in a day or two.

> There is the explainer functionality in ert, see

> (info "(ert)Defining Explanation Functions")

That description is rather terse.  In fact it is incomplete - it does
not say when the explanation function gets called, nor does it say what
is done with any resulting explanation.

It looks like a explanation function needs to duplicate the test code of
the test being explained - it seems the function has no access to the
internal state of the test.

I only wish to print the extra information when there is a test failure.
Otherwise the information in electric-tests.log would be swamped by
pointless voluminous doc strings.

Or am I missing something?

> I recommend to use it, for better readability of the test code. Examples
> are in our test files.

Thanks!

> Best regards, Michael.

-- 
Alan Mackenzie (Nuremberg, Germany).

bug#47320: Improve failure reporting in test/lisp/electrict-tests.el

[Michael Albinus]

Alan Mackenzie <acm@muc.de> writes:

> Hello, Michael.

Hi Alan,

>> There is the explainer functionality in ert, see
>
>> (info "(ert)Defining Explanation Functions")
>
> That description is rather terse.  In fact it is incomplete - it does
> not say when the explanation function gets called, nor does it say what
> is done with any resulting explanation.

100% d'accord. The ert manual isn't as helpful as it should ...

> It looks like a explanation function needs to duplicate the test code of
> the test being explained - it seems the function has no access to the
> internal state of the test.

No, it has full access to the test via the ert machinery.

(ert-get-test SYMBOL) returns the test object which has been created via
(ert-deftest SYMBOL-NAME ...)

(ert-running-test) returns the test object of the test just running.

With that test object, you have different access functions, like
ert-test-name, ert-test-documentation, ert-test-most-recent-result; see
cl-defstruct ert-test. And there are also some other defstructs, which
give you convenience functions like ert-test-failed-p.

> I only wish to print the extra information when there is a test failure.
> Otherwise the information in electric-tests.log would be swamped by
> pointless voluminous doc strings.

The ert explainer writes only something for failed functions.

> Or am I missing something?

<shameless advertisement>I've spent hours and hours to understand these
ert functions. You might have a look on filenotify-tests.el or
tramp-tests.el, for example.</>

>> I recommend to use it, for better readability of the test code. Examples
>> are in our test files.
>
> Thanks!

If needed, I could help you in setting upt these explainers. But I must
confess, I have no idea about electrict-tests.el.

For the beginning, you might look on this:

--8<---------------cut here---------------start------------->8---
(defun test-function ()
  "The result."
  t)

(defun test-function-explainer ()
  "The explainer, a string."
  (format "%s: %s" (ert-test-name (ert-running-test)) (ert-test-documentation (ert-running-test))))

(ert-deftest first-test ()
  "Just the first test"
  (should (test-function)))

(ert-deftest second-test ()
  "Just the second test"
  (should-not (test-function)))

(put 'test-function 'ert-explainer
     'test-function-explainer)
--8<---------------cut here---------------end--------------->8---

If you run both tests, you get

--8<---------------cut here---------------start------------->8---
.F

. first-test
    Just the first test
    passed

F second-test
    Just the second test
    (ert-test-failed
     ((should-not
       (test-function))
      :form
      (test-function)
      :value t :explanation "second-test: Just the second test"))
--8<---------------cut here---------------end--------------->8---

Best regards, Michael.

bug#47320: Improve failure reporting in test/lisp/electrict-tests.el

[João Távora]

[-- Attachment #1: Type: text/plain, Size: 3384 bytes --]

As the author of electric-tests.el, I'm fine with either approach.
Michael's would seem more integrated, at a glance, not sure how hard it is
to switch to it. I'd have to see that patch. João

On Tue, Mar 23, 2021, 15:24 Michael Albinus <michael.albinus@gmx.de> wrote:

> Alan Mackenzie <acm@muc.de> writes:
>
> > Hello, Michael.
>
> Hi Alan,
>
> >> There is the explainer functionality in ert, see
> >
> >> (info "(ert)Defining Explanation Functions")
> >
> > That description is rather terse.  In fact it is incomplete - it does
> > not say when the explanation function gets called, nor does it say what
> > is done with any resulting explanation.
>
> 100% d'accord. The ert manual isn't as helpful as it should ...
>
> > It looks like a explanation function needs to duplicate the test code of
> > the test being explained - it seems the function has no access to the
> > internal state of the test.
>
> No, it has full access to the test via the ert machinery.
>
> (ert-get-test SYMBOL) returns the test object which has been created via
> (ert-deftest SYMBOL-NAME ...)
>
> (ert-running-test) returns the test object of the test just running.
>
> With that test object, you have different access functions, like
> ert-test-name, ert-test-documentation, ert-test-most-recent-result; see
> cl-defstruct ert-test. And there are also some other defstructs, which
> give you convenience functions like ert-test-failed-p.
>
> > I only wish to print the extra information when there is a test failure.
> > Otherwise the information in electric-tests.log would be swamped by
> > pointless voluminous doc strings.
>
> The ert explainer writes only something for failed functions.
>
> > Or am I missing something?
>
> <shameless advertisement>I've spent hours and hours to understand these
> ert functions. You might have a look on filenotify-tests.el or
> tramp-tests.el, for example.</>
>
> >> I recommend to use it, for better readability of the test code. Examples
> >> are in our test files.
> >
> > Thanks!
>
> If needed, I could help you in setting upt these explainers. But I must
> confess, I have no idea about electrict-tests.el.
>
> For the beginning, you might look on this:
>
> --8<---------------cut here---------------start------------->8---
> (defun test-function ()
>   "The result."
>   t)
>
> (defun test-function-explainer ()
>   "The explainer, a string."
>   (format "%s: %s" (ert-test-name (ert-running-test))
> (ert-test-documentation (ert-running-test))))
>
> (ert-deftest first-test ()
>   "Just the first test"
>   (should (test-function)))
>
> (ert-deftest second-test ()
>   "Just the second test"
>   (should-not (test-function)))
>
> (put 'test-function 'ert-explainer
>      'test-function-explainer)
> --8<---------------cut here---------------end--------------->8---
>
> If you run both tests, you get
>
> --8<---------------cut here---------------start------------->8---
> .F
>
> . first-test
>     Just the first test
>     passed
>
> F second-test
>     Just the second test
>     (ert-test-failed
>      ((should-not
>        (test-function))
>       :form
>       (test-function)
>       :value t :explanation "second-test: Just the second test"))
> --8<---------------cut here---------------end--------------->8---
>
> Best regards, Michael.
>

[-- Attachment #2: Type: text/html, Size: 4185 bytes --]

bug#47320: Improve failure reporting in test/lisp/electrict-tests.el

[Alan Mackenzie]

Hello, João,

Thanks for the positive reaction!

On Tue, Mar 23, 2021 at 15:59:03 +0000, João Távora wrote:
> As the author of electric-tests.el, I'm fine with either approach.
> Michael's would seem more integrated, at a glance, not sure how hard it is
> to switch to it. I'd have to see that patch. João

I'm having some difficulty getting my head around the "explanation"
functionality of ert, which leans me towards my initial plan.

Here's the patch (actually written quite a long time ago) I would like to
merge into electric-tests.el:



diff --git a/test/lisp/electric-tests.el b/test/lisp/electric-tests.el
index 62a42b7fe4..44b3d8b672 100644
--- a/test/lisp/electric-tests.el
+++ b/test/lisp/electric-tests.el
@@ -50,7 +50,8 @@ save-electric-modes
   `(call-with-saved-electric-modes #'(lambda () ,@body)))
 
 (defun electric-pair-test-for (fixture where char expected-string
-                                       expected-point mode bindings fixture-fn)
+                                       expected-point mode bindings
+                                       fixture-fn &optional doc-string)
   (with-temp-buffer
     (funcall mode)
     (insert fixture)
@@ -63,6 +64,14 @@ electric-pair-test-for
             (mapcar #'car bindings)
             (mapcar #'cdr bindings)
           (call-interactively (key-binding `[,last-command-event])))))
+    (when
+        (and doc-string
+             (not
+              (and
+               (equal (buffer-substring-no-properties (point-min) (point-max))
+                      expected-string)
+               (equal (point) expected-point))))
+      (message "\n%s\n" doc-string))
     (should (equal (buffer-substring-no-properties (point-min) (point-max))
                    expected-string))
     (should (equal (point)
@@ -109,14 +118,9 @@ electric-pair-test-for
            (fixture (format "%s%s%s" prefix fixture suffix))
            (expected-string (format "%s%s%s" prefix expected-string suffix))
            (expected-point (+ (length prefix) expected-point))
-           (pos (+ (length prefix) pos)))
-      `(ert-deftest ,(intern (format "electric-pair-%s-at-point-%s-in-%s%s"
-                                     name
-                                     (1+ pos)
-                                     mode
-                                     extra-desc))
-           ()
-         ,(format "Electricity test in a `%s' buffer.\n
+           (pos (+ (length prefix) pos))
+           (doc-string
+            (format "Electricity test in a `%s' buffer.\n
 Start with point at %d in a %d-char-long buffer
 like this one:
 
@@ -143,7 +147,14 @@ electric-pair-test-for
                   char
                   (if (string= fixture expected-string) "stay" "become")
                   (replace-regexp-in-string "\n" "\\\\n" expected-string)
-                  expected-point)
+                  expected-point)))
+      `(ert-deftest ,(intern (format "electric-pair-%s-at-point-%s-in-%s%s"
+                                     name
+                                     (1+ pos)
+                                     mode
+                                     extra-desc))
+           ()
+         ,doc-string
          (electric-pair-test-for ,fixture
                                  ,(1+ pos)
                                  ,char
@@ -151,7 +162,8 @@ electric-pair-test-for
                                  ,expected-point
                                  ',mode
                                  ,bindings
-                                 ,fixture-fn)))))
+                                 ,fixture-fn
+                                 ,doc-string)))))
 
 (cl-defmacro define-electric-pair-test
     (name fixture


-- 
Alan Mackenzie (Nuremberg, Germany).

bug#47320: Improve failure reporting in test/lisp/electrict-tests.el

[João Távora]

Hello Alan,

On Wed, Mar 24, 2021 at 1:46 PM Alan Mackenzie <acm@muc.de> wrote:

> Thanks for the positive reaction!

Speak nothing of it!

> I'm having some difficulty getting my head around the "explanation"
> functionality of ert, which leans me towards my initial plan.
>
> Here's the patch (actually written quite a long time ago) I would like to
> merge into electric-tests.el:

As far as I understand, this just stores the big explanation string in
a variable, and uses it both for putting into the `ert-deftest` 's docstring
as well as for logging with message(), right?  If so, it's fine to add.

Maybe you could leverage `ert-fail` instead of checking the test's
main assertion twice, once in should, and once when deciding
whether to log.

I'd say, just check it once and put both logging and `ert-fail` inside the if.

João

bug#47320: Improve failure reporting in test/lisp/electrict-tests.el

[Alan Mackenzie]

Hello again, João.

On Wed, Mar 24, 2021 at 14:02:58 +0000, João Távora wrote:
> On Wed, Mar 24, 2021 at 1:46 PM Alan Mackenzie <acm@muc.de> wrote:

> > I'm having some difficulty getting my head around the "explanation"
> > functionality of ert, which leans me towards my initial plan.

> > Here's the patch (actually written quite a long time ago) I would like to
> > merge into electric-tests.el:

> As far as I understand, this just stores the big explanation string in
> a variable, and uses it both for putting into the `ert-deftest` 's docstring
> as well as for logging with message(), right?  If so, it's fine to add.

> Maybe you could leverage `ert-fail` instead of checking the test's
> main assertion twice, once in should, and once when deciding
> whether to log.

In the end, I couldn't get that to work - the handler for the signal, in
outputting the doc string, replaced all the \n's with the octal
read-syntax, "\\12".  This left the text readable only with effort.

> I'd say, just check it once and put both logging and `ert-fail` inside the if.

I just committed the patch as it was.  Sorry.

> João

-- 
Alan Mackenzie (Nuremberg, Germany).

bug#47320: Improve failure reporting in test/lisp/electrict-tests.el

[João Távora]

[-- Attachment #1: Type: text/plain, Size: 3072 bytes --]

Hello Alan,

> I just committed the patch as it was.  Sorry.

I don't much see the point in asking for comments from people
and then proceeding to ignore the simplest request for adjustments
outright.
You did write "if there are no objections...". Well I had a small
objection. I get it that following Michael's idea, which is probably
better, takes a little bit more work, but a simple adjustment
to avoid code repetition could certainly be accommodated.

FWIW I've quickly tried with this version and it seems to work
fine:

(defun electric-pair-test-for (fixture where char expected-string
                                       expected-point mode bindings
                                       fixture-fn &optional doc-string)
  (with-temp-buffer
    (funcall mode)
    (insert fixture)
    (save-electric-modes
      (let ((last-command-event char)
            (transient-mark-mode 'lambda))
        (goto-char where)
        (funcall fixture-fn)
        (cl-progv
            (mapcar #'car bindings)
            (mapcar #'cdr bindings)
          (call-interactively (key-binding `[,last-command-event])))))
    (unless (equal (buffer-substring-no-properties (point-min) (point-max))
                   expected-string)
      (when doc-string (message "\n%s\n" doc-string))
      (ert-fail (format
                 "buffer contents don't match! (observed %s, expected %s)"
                 (buffer-string) expected-string)))
    (unless (equal (point) expected-point)
      (when doc-string (message "\n%s\n" doc-string))
      (ert-fail
       (format "point isn't where it was supposed to be! (observed %s,
expected %s)"
               (point) expected-point)))))




On Wed, Mar 24, 2021 at 7:42 PM Alan Mackenzie <acm@muc.de> wrote:
>
> Hello again, João.
>
> On Wed, Mar 24, 2021 at 14:02:58 +0000, João Távora wrote:
> > On Wed, Mar 24, 2021 at 1:46 PM Alan Mackenzie <acm@muc.de> wrote:
>
> > > I'm having some difficulty getting my head around the "explanation"
> > > functionality of ert, which leans me towards my initial plan.
>
> > > Here's the patch (actually written quite a long time ago) I would
like to
> > > merge into electric-tests.el:
>
> > As far as I understand, this just stores the big explanation string in
> > a variable, and uses it both for putting into the `ert-deftest` 's
docstring
> > as well as for logging with message(), right?  If so, it's fine to add.
>
> > Maybe you could leverage `ert-fail` instead of checking the test's
> > main assertion twice, once in should, and once when deciding
> > whether to log.
>
> In the end, I couldn't get that to work - the handler for the signal, in
> outputting the doc string, replaced all the \n's with the octal
> read-syntax, "\\12".  This left the text readable only with effort.
>
> > I'd say, just check it once and put both logging and `ert-fail` inside
the if.
>
> I just committed the patch as it was.  Sorry.
>
> > João
>
> --
> Alan Mackenzie (Nuremberg, Germany).



-- 
João Távora

[-- Attachment #2: Type: text/html, Size: 3780 bytes --]

bug#47320: Improve failure reporting in test/lisp/electrict-tests.el

[Alan Mackenzie]

Hello, Jaão.

On Wed, Mar 24, 2021 at 20:10:48 +0000, João Távora wrote:
> > I just committed the patch as it was.  Sorry.

> I don't much see the point in asking for comments from people
> and then proceeding to ignore the simplest request for adjustments
> outright.

The requests were only simple on the surface.  Even though the original
change took me around about an hour (it was at ~03-00 a.m. one sleepless
night in 2019), I've spent a large part of two days trying to use the
ert facilities without reading its source (they are essentially
undocumented).

I misunderstood your suggestion as suggesting outputting the doc-string
using ert-fail.  In the end I couldn't get that to work, as I said.

> You did write "if there are no objections...". Well I had a small
> objection. I get it that following Michael's idea, which is probably
> better, takes a little bit more work, but a simple adjustment
> to avoid code repetition could certainly be accommodated.

> FWIW I've quickly tried with this version and it seems to work
> fine:

> (defun electric-pair-test-for (fixture where char expected-string
>                                        expected-point mode bindings
>                                        fixture-fn &optional doc-string)
>   (with-temp-buffer
>     (funcall mode)
>     (insert fixture)
>     (save-electric-modes
>       (let ((last-command-event char)
>             (transient-mark-mode 'lambda))
>         (goto-char where)
>         (funcall fixture-fn)
>         (cl-progv
>             (mapcar #'car bindings)
>             (mapcar #'cdr bindings)
>           (call-interactively (key-binding `[,last-command-event])))))
>     (unless (equal (buffer-substring-no-properties (point-min) (point-max))
>                    expected-string)
>       (when doc-string (message "\n%s\n" doc-string))
>       (ert-fail (format
>                  "buffer contents don't match! (observed %s, expected %s)"
>                  (buffer-string) expected-string)))
>     (unless (equal (point) expected-point)
>       (when doc-string (message "\n%s\n" doc-string))
>       (ert-fail
>        (format "point isn't where it was supposed to be! (observed %s,
> expected %s)"
>                (point) expected-point)))))

OK, I see what you meant now.  This version, instead of duplicating the
test comparisons, duplicates the call to message.  I think it boils down
to ert (particularly its documentation) not being sufficiently advanced
to do what we'd both like.

But if you'd prefer your version, I'd be happy enough to commit it.  I
mainly just want finally to get the amendment off my hands and into
master.

[ .... ]

> -- 
> João Távora

-- 
Alan Mackenzie (Nuremberg, Germany).

bug#47320: Improve failure reporting in test/lisp/electrict-tests.el

[João Távora]

[-- Attachment #1: Type: text/plain, Size: 725 bytes --]

>
> >                (point) expected-point)))))
>
> OK, I see what you meant now.  This version, instead of duplicating the
> test comparisons, duplicates the call to message.  I


The difference being that it's a one-arg call to message that has no
branching, i.e. functional impact, so if that code gets out of sync,
at least the test results don't change.  Your version duplicates the
test assertion itself.

It's localized, and none of this is serious, I was just a bit peeved
that my simple suggestion was ignored.   The solution for this is to
have ert.el utilize ert-describe-test and output that when
the test fails.   As you may know, ert-describe-test has the output
you are looking for.

João

[-- Attachment #2: Type: text/html, Size: 1143 bytes --]