Flickering tests

Flickering tests

[Andrea Corallo]

Hello,

lately I see some flickering tests in the testsuite.

I see these tests failing irregularly on emacs-30 master and igc:

dbus-test06-register-property-emits-signal
dbus-test05-register-signal-with-nils
dbus-test06-property-types
dbus-test03-peer-interface
secrets-test03-items

Am I the only one?

  Andrea

Re: Flickering tests

[Andrea Corallo]

Andrea Corallo <acorallo@gnu.org> writes:

> Hello,
>
> lately I see some flickering tests in the testsuite.
>
> I see these tests failing irregularly on emacs-30 master and igc:
>
> dbus-test06-register-property-emits-signal
> dbus-test05-register-signal-with-nils
> dbus-test06-property-types
> dbus-test03-peer-interface
> secrets-test03-items

Forgot to add to the list these two:

threads-condvar-wait
track-changes-tests--random

Re: Flickering tests

[Michael Albinus]

Andrea Corallo <acorallo@gnu.org> writes:

> Hello,

Hi Andrea,

> lately I see some flickering tests in the testsuite.
>
> I see these tests failing irregularly on emacs-30 master and igc:
>
> dbus-test06-register-property-emits-signal
> dbus-test05-register-signal-with-nils
> dbus-test06-property-types
> dbus-test03-peer-interface
> secrets-test03-items
>
> Am I the only one?

I don't see it here.

Could you pls show the error messages of the failed tests?

>   Andrea

Best regards, Michael.

Re: Flickering tests

[Andrea Corallo]

Michael Albinus <Michael.Albinus@gmx.de> writes:

> Andrea Corallo <acorallo@gnu.org> writes:
>
>> Hello,
>
> Hi Andrea,
>
>> lately I see some flickering tests in the testsuite.
>>
>> I see these tests failing irregularly on emacs-30 master and igc:
>>
>> dbus-test06-register-property-emits-signal
>> dbus-test05-register-signal-with-nils
>> dbus-test06-property-types
>> dbus-test03-peer-interface
>> secrets-test03-items
>>
>> Am I the only one?
>
> I don't see it here.
>
> Could you pls show the error messages of the failed tests?
>
>>   Andrea
>
> Best regards, Michael.

Hi Michael,

this what I saw on a recent master for
dbus-test05-register-signal-with-nils and
dbus-test05-register-signal-with-nils:

Test dbus-test05-register-signal-with-nils backtrace:
  signal(ert-test-failed (((should (equal dbus--test-signal-received '
  ert-fail(((should (equal dbus--test-signal-received '("foo"))) :form
  #f(compiled-function () #<bytecode 0xfe2dc592f6eb0e>)()
  #f(compiled-function () #<bytecode 0x19b37652292aff8f>)()
  handler-bind-1(#f(compiled-function () #<bytecode 0x19b37652292aff8f
  ert--run-test-internal(#s(ert--test-execution-info :test #s(ert-test
  ert-run-test(#s(ert-test :name dbus-test05-register-signal-with-nils
  ert-run-or-rerun-test(#s(ert--stats :selector ... :tests ... :test-m
  ert-run-tests((not (or (tag :expensive-test) (tag :unstable))) #f(co
  ert-run-tests-batch((not (or (tag :expensive-test) (tag :unstable)))
  ert-run-tests-batch-and-exit((not (or (tag :expensive-test) (tag :un
  eval((ert-run-tests-batch-and-exit '(not (or (tag :expensive-test) (
  command-line-1(("-L" ":." "-l" "ert" "--eval" "(setq treesit-extra-l
  command-line()
  normal-top-level()
Test dbus-test05-register-signal-with-nils condition:
    (ert-test-failed
     ((should (equal dbus--test-signal-received '("foo"))) :form
      (equal
       ((":1.171874" "/org/gtk/vfs/mount/1" "foo.tar.gz"
         "archive:host=file%253A%252F%252F%252Fhome%252Fandcor03%252Femacs-ci%252Femacs-ci-repo1%252Ftest%252Flisp%252Fnet%252Ftramp-archive-resources%252Ffoo.tar.gz"
         ""
         ". GThemedIcon drive-removable-media drive-removable drive drive-removable-media-symbolic drive-removable-symbolic drive-symbolic"
         ". GThemedIcon drive-removable-media-symbolic drive-removable-symbolic drive-symbolic drive-removable-media drive-removable drive"
         "" t ... ...))
       ("foo"))
      :value nil :explanation
      (list-elt 0
                (different-types
                 (":1.171874" "/org/gtk/vfs/mount/1" "foo.tar.gz"
                  "archive:host=file%253A%252F%252F%252Fhome%252Fandcor03%252Femacs-ci%252Femacs-ci-repo1%252Ftest%252Flisp%252Fnet%252Ftramp-archive-resources%252Ffoo.tar.gz"
                  ""
                  ". GThemedIcon drive-removable-media drive-removable drive drive-removable-media-symbolic drive-removable-symbolic drive-symbolic"
                  ". GThemedIcon drive-removable-media-symbolic drive-removable-symbolic drive-symbolic drive-removable-media drive-removable drive"
                  "" t ... ...)
                 "foo"))))
   FAILED  12/17  dbus-test05-register-signal-with-nils (0.112019 sec) at lisp/net/dbus-tests.el:795

Test dbus-test06-register-property-emits-signal backtrace:
  signal(ert-test-failed (((should (equal dbus--test-signal-received `
  ert-fail(((should (equal dbus--test-signal-received `(,dbus--test-in
  #f(compiled-function () #<bytecode -0xdd8901871824899>)()
  #f(compiled-function () #<bytecode 0x19b37652292aff8f>)()
  handler-bind-1(#f(compiled-function () #<bytecode 0x19b37652292aff8f
  ert--run-test-internal(#s(ert--test-execution-info :test #s(ert-test
  ert-run-test(#s(ert-test :name dbus-test06-register-property-emits-s
  ert-run-or-rerun-test(#s(ert--stats :selector ... :tests ... :test-m
  ert-run-tests((not (or (tag :expensive-test) (tag :unstable))) #f(co
  ert-run-tests-batch((not (or (tag :expensive-test) (tag :unstable)))
  ert-run-tests-batch-and-exit((not (or (tag :expensive-test) (tag :un
  eval((ert-run-tests-batch-and-exit '(not (or (tag :expensive-test) (
  command-line-1(("-L" ":." "-l" "ert" "--eval" "(setq treesit-extra-l
  command-line()
  normal-top-level()
Test dbus-test06-register-property-emits-signal condition:
    (ert-test-failed
     ((should (equal dbus--test-signal-received `...)) :form
      (equal ("org.gnu.Emacs.TestDBus")
             ("org.gnu.Emacs.TestDBus.Interface" (...) nil))
      :value nil :explanation
      (proper-lists-of-different-length 1 3 ("org.gnu.Emacs.TestDBus")
                                        ("org.gnu.Emacs.TestDBus.Interface"
                                         (...) nil)
                                        first-mismatch-at 0)))
   FAILED  15/17  dbus-test06-register-property-emits-signal (0.008444 sec) at lisp/net/dbus-tests.el:1163

  Andrea

Re: Flickering tests

[john muhl]

Andrea Corallo <acorallo@gnu.org> writes:

> Andrea Corallo <acorallo@gnu.org> writes:
>
>> Hello,
>>
>> lately I see some flickering tests in the testsuite.
>>
>> I see these tests failing irregularly on emacs-30 master and igc:
>>
>> dbus-test06-register-property-emits-signal
>> dbus-test05-register-signal-with-nils
>> dbus-test06-property-types
>> dbus-test03-peer-interface
>> secrets-test03-items
>
> Forgot to add to the list these two:
>
> threads-condvar-wait

I haven’t seen any of the above failing.

> track-changes-tests--random

This one has always been flaky on my test machines.

I also see intermittent failures for:

  src/process-tests
  lisp/eshell/esh-cmd-tests
  lisp/eshell/esh-proc-tests
  lisp/eshell/esh-var-tests
  lisp/gnus/mml-sec-tests
  lisp/net/network-stream-tests
  lisp/progmodes/eglot-tests

I assumed these were due to the machines the being underpowered
but can dig up the logs if someone wants to have a look at them.

Re: Flickering tests

[Andrea Corallo]

john muhl <jm@pub.pink> writes:

> Andrea Corallo <acorallo@gnu.org> writes:
>
>> Andrea Corallo <acorallo@gnu.org> writes:
>>
>>> Hello,
>>>
>>> lately I see some flickering tests in the testsuite.
>>>
>>> I see these tests failing irregularly on emacs-30 master and igc:
>>>
>>> dbus-test06-register-property-emits-signal
>>> dbus-test05-register-signal-with-nils
>>> dbus-test06-property-types
>>> dbus-test03-peer-interface
>>> secrets-test03-items
>>
>> Forgot to add to the list these two:
>>
>> threads-condvar-wait
>
> I haven’t seen any of the above failing.
>
>> track-changes-tests--random
>
> This one has always been flaky on my test machines.
>
> I also see intermittent failures for:
>
>   src/process-tests
>   lisp/eshell/esh-cmd-tests
>   lisp/eshell/esh-proc-tests
>   lisp/eshell/esh-var-tests
>   lisp/gnus/mml-sec-tests
>   lisp/net/network-stream-tests
>   lisp/progmodes/eglot-tests
>
> I assumed these were due to the machines the being underpowered

Mmmh, ideally tests should not be sensitive to the computational power
of the machine.

> but can dig up the logs if someone wants to have a look at them.

I think we should put an effort in reaching a stable a clean testsuite,
should we have separate bugs for each test where we do the
investigation/fix?

Re: Flickering tests

[Andrea Corallo]

Andrea Corallo <acorallo@gnu.org> writes:

> Michael Albinus <Michael.Albinus@gmx.de> writes:
>
>> Andrea Corallo <acorallo@gnu.org> writes:
>>
>>> Hello,
>>
>> Hi Andrea,
>>
>>> lately I see some flickering tests in the testsuite.
>>>
>>> I see these tests failing irregularly on emacs-30 master and igc:
>>>
>>> dbus-test06-register-property-emits-signal
>>> dbus-test05-register-signal-with-nils
>>> dbus-test06-property-types
>>> dbus-test03-peer-interface
>>> secrets-test03-items
>>>
>>> Am I the only one?
>>
>> I don't see it here.
>>
>> Could you pls show the error messages of the failed tests?
>>
>>>   Andrea
>>
>> Best regards, Michael.
>
> Hi Michael,
>
> this what I saw on a recent master for
> dbus-test05-register-signal-with-nils and
> dbus-test05-register-signal-with-nils:
>
> Test dbus-test05-register-signal-with-nils backtrace:
>   signal(ert-test-failed (((should (equal dbus--test-signal-received '
>   ert-fail(((should (equal dbus--test-signal-received '("foo"))) :form
>   #f(compiled-function () #<bytecode 0xfe2dc592f6eb0e>)()
>   #f(compiled-function () #<bytecode 0x19b37652292aff8f>)()
>   handler-bind-1(#f(compiled-function () #<bytecode 0x19b37652292aff8f
>   ert--run-test-internal(#s(ert--test-execution-info :test #s(ert-test
>   ert-run-test(#s(ert-test :name dbus-test05-register-signal-with-nils
>   ert-run-or-rerun-test(#s(ert--stats :selector ... :tests ... :test-m
>   ert-run-tests((not (or (tag :expensive-test) (tag :unstable))) #f(co
>   ert-run-tests-batch((not (or (tag :expensive-test) (tag :unstable)))
>   ert-run-tests-batch-and-exit((not (or (tag :expensive-test) (tag :un
>   eval((ert-run-tests-batch-and-exit '(not (or (tag :expensive-test) (
>   command-line-1(("-L" ":." "-l" "ert" "--eval" "(setq treesit-extra-l
>   command-line()
>   normal-top-level()
> Test dbus-test05-register-signal-with-nils condition:
>     (ert-test-failed
>      ((should (equal dbus--test-signal-received '("foo"))) :form
>       (equal
>        ((":1.171874" "/org/gtk/vfs/mount/1" "foo.tar.gz"
>          "archive:host=file%253A%252F%252F%252Fhome%252Fandcor03%252Femacs-ci%252Femacs-ci-repo1%252Ftest%252Flisp%252Fnet%252Ftramp-archive-resources%252Ffoo.tar.gz"
>          ""
>          ". GThemedIcon drive-removable-media drive-removable drive drive-removable-media-symbolic drive-removable-symbolic drive-symbolic"
>          ". GThemedIcon drive-removable-media-symbolic drive-removable-symbolic drive-symbolic drive-removable-media drive-removable drive"
>          "" t ... ...))
>        ("foo"))
>       :value nil :explanation
>       (list-elt 0
>                 (different-types
>                  (":1.171874" "/org/gtk/vfs/mount/1" "foo.tar.gz"
>                   "archive:host=file%253A%252F%252F%252Fhome%252Fandcor03%252Femacs-ci%252Femacs-ci-repo1%252Ftest%252Flisp%252Fnet%252Ftramp-archive-resources%252Ffoo.tar.gz"
>                   ""
>                   ". GThemedIcon drive-removable-media drive-removable drive drive-removable-media-symbolic drive-removable-symbolic drive-symbolic"
>                   ". GThemedIcon drive-removable-media-symbolic drive-removable-symbolic drive-symbolic drive-removable-media drive-removable drive"
>                   "" t ... ...)
>                  "foo"))))
>    FAILED  12/17  dbus-test05-register-signal-with-nils (0.112019 sec) at lisp/net/dbus-tests.el:795
>
> Test dbus-test06-register-property-emits-signal backtrace:
>   signal(ert-test-failed (((should (equal dbus--test-signal-received `
>   ert-fail(((should (equal dbus--test-signal-received `(,dbus--test-in
>   #f(compiled-function () #<bytecode -0xdd8901871824899>)()
>   #f(compiled-function () #<bytecode 0x19b37652292aff8f>)()
>   handler-bind-1(#f(compiled-function () #<bytecode 0x19b37652292aff8f
>   ert--run-test-internal(#s(ert--test-execution-info :test #s(ert-test
>   ert-run-test(#s(ert-test :name dbus-test06-register-property-emits-s
>   ert-run-or-rerun-test(#s(ert--stats :selector ... :tests ... :test-m
>   ert-run-tests((not (or (tag :expensive-test) (tag :unstable))) #f(co
>   ert-run-tests-batch((not (or (tag :expensive-test) (tag :unstable)))
>   ert-run-tests-batch-and-exit((not (or (tag :expensive-test) (tag :un
>   eval((ert-run-tests-batch-and-exit '(not (or (tag :expensive-test) (
>   command-line-1(("-L" ":." "-l" "ert" "--eval" "(setq treesit-extra-l
>   command-line()
>   normal-top-level()
> Test dbus-test06-register-property-emits-signal condition:
>     (ert-test-failed
>      ((should (equal dbus--test-signal-received `...)) :form
>       (equal ("org.gnu.Emacs.TestDBus")
>              ("org.gnu.Emacs.TestDBus.Interface" (...) nil))
>       :value nil :explanation
>       (proper-lists-of-different-length 1 3 ("org.gnu.Emacs.TestDBus")
>                                         ("org.gnu.Emacs.TestDBus.Interface"
>                                          (...) nil)
>                                         first-mismatch-at 0)))
>    FAILED  15/17  dbus-test06-register-property-emits-signal (0.008444 sec) at lisp/net/dbus-tests.el:1163
>
>   Andrea

Mmhh, I've the impression this happen on my system only when it's under
heavy load.  I've 64 cores and if I "make check -j64" I've say 50%
probability to hit these, but if I run only:

./src/emacs -batch -l ert -l ./test/lisp/net/dbus-tests.el -f ert-run-tests-batch-and-exit

they all pass.  Perhaps some timeout need to be adjusted?

  Andrea

Re: Flickering tests

[Michael Albinus]

Andrea Corallo <acorallo@gnu.org> writes:

Hi Andrea,

> Mmhh, I've the impression this happen on my system only when it's under
> heavy load.  I've 64 cores and if I "make check -j64" I've say 50%
> probability to hit these, but if I run only:
>
> ./src/emacs -batch -l ert -l ./test/lisp/net/dbus-tests.el -f ert-run-tests-batch-and-exit
>
> they all pass.  Perhaps some timeout need to be adjusted?

It's not the a I believe. D-Bus tests are sending events to the D-Buson
OS level, and receiving events which will be interpreted. They are not
written such a way that all tests can run in parallel.

If you invoke "make check -j64", it could happen that some D-Bus tests
run in parallel, and returning events do arrive in another Emacs
instance but the one which has send the evnt. This might be even more
problematic, because recently (on Sunday, commit
4e22ef870c4b650f29c4441ac51b6a2ac506ea57) a test which registers for
wildcard events has been added. This test resides in my local Emacs git
for 3 months w/o problems; I've simply waited until the FSF papers of
the author, Robert Church, were on file.

What could we do? Could we exclude dbus-tests.el from running as
simultaneous job?

Or could we simply skip D-Bus tests, if we detect that the tests run via
simultaneous make jobs? How to check, on Lisp level?

We always have the option to mark this test as :unstable, so we could
stabilize the Emacs 30 release this way. But it would be a pity.

Btw, could you check whether the D-Bus tests flickery goes away if we
tag dbus-test05-register-signal-with-nils as :unstable?

> Andrea

Best regards, Michael.

Re: Flickering tests

[Andrea Corallo]

Michael Albinus <Michael.Albinus@gmx.de> writes:

> Andrea Corallo <acorallo@gnu.org> writes:
>
> Hi Andrea,
>
>> Mmhh, I've the impression this happen on my system only when it's under
>> heavy load.  I've 64 cores and if I "make check -j64" I've say 50%
>> probability to hit these, but if I run only:
>>
>> ./src/emacs -batch -l ert -l ./test/lisp/net/dbus-tests.el -f ert-run-tests-batch-and-exit
>>
>> they all pass.  Perhaps some timeout need to be adjusted?
>
> It's not the a I believe. D-Bus tests are sending events to the D-Buson
> OS level, and receiving events which will be interpreted. They are not
> written such a way that all tests can run in parallel.
>
> If you invoke "make check -j64", it could happen that some D-Bus tests
> run in parallel, and returning events do arrive in another Emacs
> instance but the one which has send the evnt. This might be even more
> problematic, because recently (on Sunday, commit
> 4e22ef870c4b650f29c4441ac51b6a2ac506ea57) a test which registers for
> wildcard events has been added. This test resides in my local Emacs git
> for 3 months w/o problems; I've simply waited until the FSF papers of
> the author, Robert Church, were on file.
>
> What could we do? Could we exclude dbus-tests.el from running as
> simultaneous job?

Mmmh not sure is possible but also desirable, we want to be able to run
as many tests as possible even with -jN.

> Or could we simply skip D-Bus tests, if we detect that the tests run via
> simultaneous make jobs? How to check, on Lisp level?

Perhaps using some lock file as mutex for the generation of D-Bus
messages from different test files?

> We always have the option to mark this test as :unstable, so we could
> stabilize the Emacs 30 release this way. But it would be a pity.
>
> Btw, could you check whether the D-Bus tests flickery goes away if we
> tag dbus-test05-register-signal-with-nils as :unstable?

From the bunch of test I did seems this is solving, I'll mark it as
:unstable for now till a better solution is found.

Thanks

  Andrea

Re: Flickering tests

[Stefan Kangas]

Andrea Corallo <acorallo@gnu.org> writes:

> I think we should put an effort in reaching a stable a clean testsuite,

Agreed, that's an important goal.

> should we have separate bugs for each test where we do the
> investigation/fix?

Yes please.

Re: Flickering tests

[john muhl]

Stefan Kangas <stefankangas@gmail.com> writes:

> Andrea Corallo <acorallo@gnu.org> writes:
>
>> I think we should put an effort in reaching a stable a clean testsuite,
>
> Agreed, that's an important goal.
>
>> should we have separate bugs for each test where we do the
>> investigation/fix?
>
> Yes please.

Will do. Let’s start with bug#71942.

Re: Flickering tests

[Michael Albinus]

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

Andrea Corallo <acorallo@gnu.org> writes:

Hi Andrea,

> Mmmh not sure is possible but also desirable, we want to be able to run
> as many tests as possible even with -jN.

Last days, I've digged further into this. I still couldn't provoke the
error (my machine has only 8 processing units). However, ...

>> Btw, could you check whether the D-Bus tests flickery goes away if we
>> tag dbus-test05-register-signal-with-nils as :unstable?
>
> From the bunch of test I did seems this is solving, I'll mark it as
> :unstable for now till a better solution is found.

... I've found suspicious code in this test. Usually, all tests work
deterministic. A method call or a signal is raised, and the returned
message from D-Bus is analyzed. But in this test, a signal handler with
a wildcard filter is registered. That means, *any* signal from D-Bus is
catched, also signals which aren't relevant for this test. The more
pressure you give on the system ("make -j96"), the more likely it is.

So I have modified the signal handler to handle only signals we're
interested in. See the appended patch. Could you, pls, check whether it
helps? I guess we need it only in the master branch, because the problem
appears only in dbus-test.el. dbusbind.c and dbus.el are OK.

> Thanks
>
>   Andrea

Best regards, Michael.


[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: Type: text/x-patch, Size: 2851 bytes --]

diff --git a/test/lisp/net/dbus-tests.el b/test/lisp/net/dbus-tests.el
index b3337132fb6..0e0996b373e 100644
--- a/test/lisp/net/dbus-tests.el
+++ b/test/lisp/net/dbus-tests.el
@@ -25,7 +25,7 @@
 (require 'ert-x)
 (require 'dbus)

-(defvar dbus-debug nil)
+(defvar dbus-debug)
 (declare-function dbus-get-unique-name "dbusbind.c" (bus))

 (defconst dbus--test-enabled-session-bus
@@ -732,12 +732,28 @@ dbus-test04-call-method-timeout
     ;; Cleanup.
     (dbus-unregister-service :session dbus--test-service)))

+(defvar dbus--test-event-expected nil
+  "The expected event in `dbus--test-signal-handler'.")
+
 (defvar dbus--test-signal-received nil
   "Received signal value in `dbus--test-signal-handler'.")

 (defun dbus--test-signal-handler (&rest args)
   "Signal handler for `dbus-test*-signal' and `dbus-test08-register-monitor'."
-  (setq dbus--test-signal-received args))
+  (ignore-error dbus-error
+    (let ((last-input-event last-input-event))
+      (when (or (null dbus--test-event-expected)
+                (and (equal (dbus-event-bus-name last-input-event)
+                            (dbus-event-bus-name dbus--test-event-expected))
+                     (equal (dbus-event-message-type last-input-event)
+                            (dbus-event-message-type dbus--test-event-expected))
+                     (equal (dbus-event-service-name last-input-event)
+                            (dbus-event-service-name dbus--test-event-expected))
+                     (equal (dbus-event-path-name last-input-event)
+                            (dbus-event-path-name dbus--test-event-expected))
+                     (equal (dbus-event-member-name last-input-event)
+                            (dbus-event-member-name dbus--test-event-expected))))
+        (setq dbus--test-signal-received args)))))

 (defun dbus--test-timeout-handler (&rest _ignore)
   "Timeout handler, reporting a failed test."
@@ -804,6 +820,14 @@ dbus-test05-register-signal-with-nils
             (handler #'dbus--test-signal-handler)
             registered)

+        ;; Filter received signals in signal handler.
+        (setq dbus--test-event-expected
+              `(dbus-event :session ,dbus-message-type-signal
+                0 ;; Serial number doesn't matter.
+	        ,(dbus-get-unique-name :session)
+                nil ;; Destination doesn't matter.
+	        ,dbus--test-path ,dbus--test-interface "Member" ,handler))
+
         ;; Register signal handler.
         (should
          (equal
@@ -842,6 +866,7 @@ dbus-test05-register-signal-with-nils
         (should-not (dbus-unregister-object registered)))

     ;; Cleanup.
+    (setq dbus--test-event-expected nil)
     (dbus-unregister-service :session dbus--test-service)))

 (ert-deftest dbus-test06-register-property ()