GNU logs - #47795, boring messages

Message sent to bug-dejagnu@HIDDEN:

Subject: bug#47795: utils.test fails intermittently
Resent-From: Rainer Orth <ro@HIDDEN>
Original-Sender: "Debbugs-submit" <debbugs-submit-bounces <at> debbugs.gnu.org>
Resent-CC: bug-dejagnu@HIDDEN
Resent-Date: Thu, 15 Apr 2021 12:29:01 +0000
Resent-Message-ID: <handler.47795.B.161848969728684 <at> debbugs.gnu.org>
Resent-Sender: help-debbugs@HIDDEN
To: 47795 <at> debbugs.gnu.org
From: Rainer Orth <ro@HIDDEN>
Date: Thu, 15 Apr 2021 14:27:44 +0200
Message-ID: <yddk0p3hgvz.fsf@HIDDEN>
User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/27.1.90 (usg-unix-v)
MIME-Version: 1.0
Content-Type: text/plain
Received-SPF: none client-ip=129.70.160.84;
 envelope-from=ro@HIDDEN; helo=smtp.CeBiTec.Uni-Bielefeld.DE
X-Spam_score_int: -28
X-Spam_score: -2.9
X-Spam_bar: --
X-Spam_report: (-2.9 / 5.0 requ) BAYES_05=-0.5, DKIM_SIGNED=0.1,
 DKIM_VALID=-0.1, DKIM_VALID_AU=-0.1, RCVD_IN_DNSWL_MED=-2.3,
 RCVD_IN_MSPIKE_H2=-0.001, SPF_HELO_NONE=0.001,
 SPF_NONE=0.001 autolearn=ham autolearn_force=no
X-Spam_action: no action
X-Spam-Score: -2.3 (--)
X-BeenThere: debbugs-submit <at> debbugs.gnu.org
X-Mailman-Version: 2.1.18
Precedence: list
List-Id: <debbugs-submit.debbugs.gnu.org>
List-Unsubscribe: <https://debbugs.gnu.org/cgi-bin/mailman/options/debbugs-submit>, 
 <mailto:debbugs-submit-request <at> debbugs.gnu.org?subject=unsubscribe>
List-Archive: <https://debbugs.gnu.org/cgi-bin/mailman/private/debbugs-submit/>
List-Post: <mailto:debbugs-submit <at> debbugs.gnu.org>
List-Help: <mailto:debbugs-submit-request <at> debbugs.gnu.org?subject=help>
List-Subscribe: <https://debbugs.gnu.org/cgi-bin/mailman/listinfo/debbugs-submit>, 
 <mailto:debbugs-submit-request <at> debbugs.gnu.org?subject=subscribe>
Errors-To: debbugs-submit-bounces <at> debbugs.gnu.org
Sender: "Debbugs-submit" <debbugs-submit-bounces <at> debbugs.gnu.org>
X-Spam-Score: -3.3 (---)

I just noticed that one part of the runtest testsuite fails
intermittently on both Solaris 10 and 11 on the 1.6.3 branch.  It's easy
to miss because it only manifests itself in runtest.{sum,log} as

[...]
PASS: testsuite file creates new implied object directory
ERROR: /vol/src/gnu/dejagnu/dejagnu-1.6.3-branch/local/testsuite/runtest.libs/utils.test did not complete

and

                === runtest Summary ===
 
-# of expected passes           268
+# of expected passes           294

Unless you know how many passes to expect, you likely miss the problem.

Even when running runtest -v -v instead, neither the runtest output

@@ -157,8 +157,7 @@
 Processing test /vol/src/gnu/dejagnu/dejagnu-1.6.3-branch/local/testsuite/runtest.libs/testsuite_file.test
 Running /vol/src/gnu/dejagnu/dejagnu-1.6.3-branch/local/testsuite/runtest.libs/utils.test ...
 Processing test /vol/src/gnu/dejagnu/dejagnu-1.6.3-branch/local/testsuite/runtest.libs/utils.test
-WARNED: diff1.txt doesn't exist
-
+ERROR: /vol/src/gnu/dejagnu/dejagnu-1.6.3-branch/local/testsuite/runtest.libs/utils.test did not complete

nor runtest.log show much:

Running /vol/src/gnu/dejagnu/dejagnu-1.6.3-branch/local/testsuite/runtest.libs/utils.test ...
Processing test /vol/src/gnu/dejagnu/dejagnu-1.6.3-branch/local/testsuite/runtest.libs/utils.test

interp delete test_case
interp create test_case
interp create test_case
expect1.30> test_case eval {foreach { n v }}  [list [array get default_vars]] {{ set $n $v }}
test_case eval {foreach { n v }}  [list [array get default_vars]] {{ set $n $v }}
test_case^M^M
expect1.31> test_case eval source /vol/src/gnu/dejagnu/dejagnu-1.6.3-branch/local/testsuite/runtest.libs/utils.test
test_case eval source /vol/src/gnu/dejagnu/dejagnu-1.6.3-branch/local/testsuite/runtest.libs/utils.test
expect1.32> ERROR: /vol/src/gnu/dejagnu/dejagnu-1.6.3-branch/local/testsuite/runtest.libs/utils.test did not complete

The test does succeed when running

runtest --tool runtest

in a row about 2 out of 10 times.

I'm a bit at a loss how to investigate this further.

Message sent:

Content-Disposition: inline
Content-Transfer-Encoding: quoted-printable
MIME-Version: 1.0
X-Mailer: MIME-tools 5.505 (Entity 5.505)
Content-Type: text/plain; charset=utf-8
X-Loop: help-debbugs@HIDDEN
From: help-debbugs@HIDDEN (GNU bug Tracking System)
To: Rainer Orth <ro@HIDDEN>
Subject: bug#47795: Acknowledgement (utils.test fails intermittently)
Message-ID: <handler.47795.B.161848969728684.ack <at> debbugs.gnu.org>
References: <yddk0p3hgvz.fsf@HIDDEN>
X-Gnu-PR-Message: ack 47795
X-Gnu-PR-Package: dejagnu
Reply-To: 47795 <at> debbugs.gnu.org
Date: Thu, 15 Apr 2021 12:29:02 +0000

Thank you for filing a new bug report with debbugs.gnu.org.

This is an automatically generated reply to let you know your message
has been received.

Your message is being forwarded to the package maintainers and other
interested parties for their attention; they will reply in due course.

Your message has been sent to the package maintainer(s):
 bug-dejagnu@HIDDEN

If you wish to submit further information on this problem, please
send it to 47795 <at> debbugs.gnu.org.

Please do not send mail to help-debbugs@HIDDEN unless you wish
to report a problem with the Bug-tracking system.

--=20
47795: http://debbugs.gnu.org/cgi/bugreport.cgi?bug=3D47795
GNU Bug Tracking System
Contact help-debbugs@HIDDEN with problems

Message sent to bug-dejagnu@HIDDEN:

Subject: bug#47795: utils.test fails intermittently
Resent-From: Jacob Bachmeyer <jcb62281@HIDDEN>
Original-Sender: "Debbugs-submit" <debbugs-submit-bounces <at> debbugs.gnu.org>
Resent-CC: bug-dejagnu@HIDDEN
Resent-Date: Fri, 30 Apr 2021 03:17:01 +0000
Resent-Message-ID: <handler.47795.B47795.161975256823611 <at> debbugs.gnu.org>
Resent-Sender: help-debbugs@HIDDEN
To: Rainer Orth <ro@HIDDEN>
Cc: 47795 <at> debbugs.gnu.org
Reply-To: jcb62281@HIDDEN
Message-ID: <608B7669.1090604@HIDDEN>
Date: Thu, 29 Apr 2021 22:15:53 -0500
From: Jacob Bachmeyer <jcb62281@HIDDEN>
User-Agent: Mozilla/5.0 (X11; U; Linux x86_64; en-US;
 rv:1.8.1.22) Gecko/20090807 MultiZilla/1.8.3.4e SeaMonkey/1.1.17
 Mnenhy/0.7.6.0
MIME-Version: 1.0
References: <yddk0p3hgvz.fsf@HIDDEN>
In-Reply-To: <yddk0p3hgvz.fsf@HIDDEN>
Content-Type: text/plain; charset=UTF-8; format=flowed
Content-Transfer-Encoding: 7bit
Precedence: list
Errors-To: debbugs-submit-bounces <at> debbugs.gnu.org
Sender: "Debbugs-submit" <debbugs-submit-bounces <at> debbugs.gnu.org>

Rainer Orth wrote:
> I just noticed that one part of the runtest testsuite fails
> intermittently on both Solaris 10 and 11 on the 1.6.3 branch.  It's easy
> to miss because it only manifests itself in runtest.{sum,log} as
>
> [...]
> PASS: testsuite file creates new implied object directory
> ERROR: /vol/src/gnu/dejagnu/dejagnu-1.6.3-branch/local/testsuite/runtest.libs/utils.test did not complete
>
> and
>
>                 === runtest Summary ===
>  
> -# of expected passes           268
> +# of expected passes           294
>
> Unless you know how many passes to expect, you likely miss the problem.
>   

This is a long-standing issue with DejaGnu:  the framework does not know 
how many tests to expect, so missing tests just go, well, /missing/.

This is an architectural limitation in DejaGnu, so the closest to an 
actual solution while preserving backwards compatibility is to improve 
error handling to more reliably report that /something/ went wrong, even 
if we have no way to state how many tests were not run.  Optional "test 
manifest" features, allowing testsuites to provide the framework with a 
list of expected tests, are on my local TODO list, but I have not yet 
found a good way to generalize them to DejaGnu proper.  It is possible 
that some other code consequent to the test grouping features that will 
accompany the new XML output format in 1.7 will pave the way to a clean 
API for this, but I am not yet sure of that.

> Even when running runtest -v -v instead, neither the runtest output
>
> @@ -157,8 +157,7 @@
>  Processing test /vol/src/gnu/dejagnu/dejagnu-1.6.3-branch/local/testsuite/runtest.libs/testsuite_file.test
>  Running /vol/src/gnu/dejagnu/dejagnu-1.6.3-branch/local/testsuite/runtest.libs/utils.test ...
>  Processing test /vol/src/gnu/dejagnu/dejagnu-1.6.3-branch/local/testsuite/runtest.libs/utils.test
> -WARNED: diff1.txt doesn't exist
> -
> +ERROR: /vol/src/gnu/dejagnu/dejagnu-1.6.3-branch/local/testsuite/runtest.libs/utils.test did not complete
>
> nor runtest.log show much:
>
> Running /vol/src/gnu/dejagnu/dejagnu-1.6.3-branch/local/testsuite/runtest.libs/utils.test ...
> Processing test /vol/src/gnu/dejagnu/dejagnu-1.6.3-branch/local/testsuite/runtest.libs/utils.test
>
> interp delete test_case
> interp create test_case
> interp create test_case
> expect1.30> test_case eval {foreach { n v }}  [list [array get default_vars]] {{ set $n $v }}
> test_case eval {foreach { n v }}  [list [array get default_vars]] {{ set $n $v }}
> test_case^M^M
> expect1.31> test_case eval source /vol/src/gnu/dejagnu/dejagnu-1.6.3-branch/local/testsuite/runtest.libs/utils.test
> test_case eval source /vol/src/gnu/dejagnu/dejagnu-1.6.3-branch/local/testsuite/runtest.libs/utils.test
> expect1.32> ERROR: /vol/src/gnu/dejagnu/dejagnu-1.6.3-branch/local/testsuite/runtest.libs/utils.test did not complete
>
> The test does succeed when running
>
> runtest --tool runtest
>
> in a row about 2 out of 10 times.
>   

There is a possible clue here:  it appears that we may be losing 
synchronization:  the "interp create test_case" line should be emitted 
in response to an expect1.*> prompt which seems to be missing in your 
log, yet the preceding "interp delete test_case" is included.  Do I 
guess correctly that the line preceding that snippet was another "interp 
delete test_case"?  Particularly interesting in that your log seems to 
show "test_case" returned for the "test_case eval ... foreach ..." line, 
but that line should not produce a response -- the "test_case" response 
should be from the previous "interp create test_case" command.

In fact, examining process_test in testsuite/runtest.libs/libs.exp which 
drives these tests, the error that you are seeing is exactly what is 
produced when an Expect prompt arrives when the driver is expecting to 
see test results.  Losing synchronization could cause this, although 
that check was added to detect the case where the slave interpreter 
aborts due to a Tcl error in the inner test script.

Assuming the "lost sync" hypothesis, when the failure occurs, the 
previous command is still "in-flight" somewhere... and the "1.32" prompt 
is when the "test_case eval source ..." command is given in my logs... 
but your logs show it being issued at the "1.31" prompt... is an 
"expect1./N/>" prompt duplicated somewhere earlier in the log?

It is also possible that an earlier "expect" (command in process_test) 
is timing out while waiting for an "expect*>" prompt from the child 
Expect.  My development box is relatively lightly loaded; what are the 
typical load averages on the system where the problem occurs?

The code in testsuite/runtest.libs/libs.exp is mostly my doing at this 
point, and is probably some of the earlier Expect code that I have 
written.  If there is a bug in there that only affects heavily-loaded 
systems, it is probably my then-inexperience showing.  :-)

> I'm a bit at a loss how to investigate this further.

I have only now found a possible explanation, after sitting on this for 
about two weeks.

-- Jacob

Message received at control <at> debbugs.gnu.org:

Received: (at control) by debbugs.gnu.org; 4 May 2021 04:18:34 +0000
From debbugs-submit-bounces <at> debbugs.gnu.org Tue May 04 00:18:34 2021
Received: from localhost ([127.0.0.1]:50566 helo=debbugs.gnu.org)
	by debbugs.gnu.org with esmtp (Exim 4.84_2)
	(envelope-from <debbugs-submit-bounces <at> debbugs.gnu.org>)
	id 1ldmW2-0001Ys-HK
	for submit <at> debbugs.gnu.org; Tue, 04 May 2021 00:18:34 -0400
Received: from mail-oi1-f180.google.com ([209.85.167.180]:36776)
 by debbugs.gnu.org with esmtp (Exim 4.84_2)
 (envelope-from <jcb62281@HIDDEN>) id 1ldmW1-0001Yg-8Q
 for control <at> debbugs.gnu.org; Tue, 04 May 2021 00:18:33 -0400
Received: by mail-oi1-f180.google.com with SMTP id i26so7586993oii.3
 for <control <at> debbugs.gnu.org>; Mon, 03 May 2021 21:18:33 -0700 (PDT)
DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025;
 h=message-id:date:from:reply-to:user-agent:mime-version:to:subject
 :content-transfer-encoding;
 bh=ua5LNtAaglHGgP+w6/8QMz2RVgwrzDoQZOdPaqZ6IkE=;
 b=AjLYbXaUDjmYRj13x0dvpU0tOtZoPY7JRdFdLlwMgtFYLzK/+GRxKt0mzpSsCSicI2
 i2uyj2VpgtULEuvudqEq3lgD+K6DGPKDFREcD11y5vu7HAFY1qNjsiOiiKvaOCqy6jDQ
 B16KP6bBtxSHJ0DKBdSj+vGQ5c/WtMCWJjX5bnYeQgpFsARWjyxlAaciWzXQrV0J4ClA
 oc/zVyttLJAyEakCxvtRfwkwpj7F0J/ikAiXEABrZ9Z1KXYFognaIIbB1ovDeJpSZlE4
 zBRkzPgRTNh+QI+YHg8w99Lyzf5Y+bUGVCJie2VO3DqFjSOuEUVUKhFyU3ocR+1kZQIw
 11Wg==
X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed;
 d=1e100.net; s=20161025;
 h=x-gm-message-state:message-id:date:from:reply-to:user-agent
 :mime-version:to:subject:content-transfer-encoding;
 bh=ua5LNtAaglHGgP+w6/8QMz2RVgwrzDoQZOdPaqZ6IkE=;
 b=QTDfnlfOw+j4WtnBJVDTOfgEoJDs5uXlV8sSPoZWGr1mLJ6gJzDn+4lpsTwR59zF7Q
 AAIA3y82PiZ0E9o8jZkwAzIzKUU2PqDo2y24m44wnwq/0I1sKaQ0jnd4os8J1r+5Swz8
 a5FHCplLh7sSby4eA74aYlr53rTSk4LKWzGJy18oEI8dfDQxOArLfDJknVVVRgqzqhKP
 pUCg2TLak7jpK/8FGYDrbOZPfr/zyJycp9Q6oJ2D8WDcNLffjPLw1C6xktxQroPFb61d
 NdmoURi0myrRaawjSISPNiQh8mA14w3XAi3j5s6hV20Vla5R4DDJE5bhjciEibwilbYe
 smJw==
X-Gm-Message-State: AOAM532oS3OqbknGOoDkQJjw+6sRKl5YrZVv9YdrRrHQZQ9gO9LhLaXx
 +nw2UBjar31RZr9WPNM2IURDi00ETHE=
X-Google-Smtp-Source: ABdhPJzuwBKRLK6RubtIwyvkS4kTz6Y4ANm8FXt88Vetlf+UpYWRSzr80w9FTzPKGsxvcY3yJz0ZvA==
X-Received: by 2002:aca:6088:: with SMTP id u130mr1498213oib.51.1620101907682; 
 Mon, 03 May 2021 21:18:27 -0700 (PDT)
Received: from [192.168.2.42] (adsl-70-133-144-190.dsl.ablntx.sbcglobal.net.
 [70.133.144.190])
 by smtp.gmail.com with ESMTPSA id v28sm481054ood.27.2021.05.03.21.18.27
 for <control <at> debbugs.gnu.org>
 (version=TLS1 cipher=ECDHE-RSA-AES128-SHA bits=128/128);
 Mon, 03 May 2021 21:18:27 -0700 (PDT)
Message-ID: <6090CB12.1060900@HIDDEN>
Date: Mon, 03 May 2021 23:18:26 -0500
From: Jacob Bachmeyer <jcb62281@HIDDEN>
User-Agent: Mozilla/5.0 (X11; U; Linux x86_64; en-US;
 rv:1.8.1.22) Gecko/20090807 MultiZilla/1.8.3.4e SeaMonkey/1.1.17
 Mnenhy/0.7.6.0
MIME-Version: 1.0
To: GNU bug tracker automated control server <control <at> debbugs.gnu.org>
Subject: bug administrivia 2021-05-03
Content-Type: text/plain; charset=ISO-8859-1; format=flowed
Content-Transfer-Encoding: 7bit
X-Spam-Score: 0.5 (/)
X-Debbugs-Envelope-To: control
X-BeenThere: debbugs-submit <at> debbugs.gnu.org
X-Mailman-Version: 2.1.18
Precedence: list
List-Id: <debbugs-submit.debbugs.gnu.org>
List-Unsubscribe: <https://debbugs.gnu.org/cgi-bin/mailman/options/debbugs-submit>, 
 <mailto:debbugs-submit-request <at> debbugs.gnu.org?subject=unsubscribe>
List-Archive: <https://debbugs.gnu.org/cgi-bin/mailman/private/debbugs-submit/>
List-Post: <mailto:debbugs-submit <at> debbugs.gnu.org>
List-Help: <mailto:debbugs-submit-request <at> debbugs.gnu.org?subject=help>
List-Subscribe: <https://debbugs.gnu.org/cgi-bin/mailman/listinfo/debbugs-submit>, 
 <mailto:debbugs-submit-request <at> debbugs.gnu.org?subject=subscribe>
Reply-To: jcb62281@HIDDEN
Errors-To: debbugs-submit-bounces <at> debbugs.gnu.org
Sender: "Debbugs-submit" <debbugs-submit-bounces <at> debbugs.gnu.org>
X-Spam-Score: -0.5 (/)

package dejagnu

owner 47795 !
owner 48155 !

# It is enough to block the release until fixed.
severity 48155 serious

thanks

Last modified: Tue, 4 May 2021 04:30:01 UTC

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997 nCipher Corporation Ltd, 1994-97 Ian Jackson.