Jacob Bachmeyer <jcb62281@HIDDEN>
to control <at> debbugs.gnu.org.
Full text available.
Received: (at 47795) by debbugs.gnu.org; 30 Apr 2021 03:16:08 +0000
From debbugs-submit-bounces <at> debbugs.gnu.org Thu Apr 29 23:16:08 2021
Received: from localhost ([127.0.0.1]:57188 helo=debbugs.gnu.org)
by debbugs.gnu.org with esmtp (Exim 4.84_2)
(envelope-from <debbugs-submit-bounces <at> debbugs.gnu.org>)
id 1lcJdQ-00068l-1c
for submit <at> debbugs.gnu.org; Thu, 29 Apr 2021 23:16:08 -0400
Received: from mail-ot1-f48.google.com ([209.85.210.48]:45026)
by debbugs.gnu.org with esmtp (Exim 4.84_2)
(envelope-from <jcb62281@HIDDEN>) id 1lcJdK-000686-Or
for 47795 <at> debbugs.gnu.org; Thu, 29 Apr 2021 23:16:07 -0400
Received: by mail-ot1-f48.google.com with SMTP id
z25-20020a9d65d90000b02902a560806ca7so4592699oth.11
for <47795 <at> debbugs.gnu.org>; Thu, 29 Apr 2021 20:16:02 -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:cc:subject
:references:in-reply-to:content-transfer-encoding;
bh=dlkBPrI8c0yzRyzuLkpYjcxRSpu7VlrA1Xr7Zcoe0qM=;
b=o+lZKCRBEKJg9umzi3ih6k78cDC9AQPfMEXYXDRUL6dpmgOUV0u3cPOYLMzqHTjFp5
OuunpAbaoHKCnF5nvKthWECp83OnqVyC5j/t1e5eM38tvtcZEmqrIwo4pPfmxH3Rs73/
cw5r6g+Vay3Qu90MYo3C0sL+kYbmZbA/fwdJNYIbSDyMrjSi3AuXvko2dv9UzvrhOyuK
dJMRVZjBjQyo9WyRLR+EUkYX2c3s57xKPBkT01GxhfgA0BLg6KGozH0CEAyDvV3wxn+T
gdZNbnSDeV/I/FvlPXT592kxTGl2hVhdv6oqW7drQ3Rm00QcTx0sUlO9Npq57X5yjwwD
R8Eg==
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:cc:subject:references:in-reply-to
:content-transfer-encoding;
bh=dlkBPrI8c0yzRyzuLkpYjcxRSpu7VlrA1Xr7Zcoe0qM=;
b=Rvt2BA2GajUSQdWKte5xGRwImMgwSQzOjAaH7NDa5LwFAXwsU0wSnzTKpaqUT2QG66
4ZjRAiibjRGLI/1Byi280Fhw3GoE1tOUk6Vt37/GsaBRpgKmmp7xNgFYfRa9ltSd4fFs
O4E8CTC6QK+kuxp28kj0BpFEu4nh22Q4vMN5pn/XNaPiSrkF2Z9OxaKY6X/3sN7YQO5h
f9rzwYLthyPQnEo2v1tM6SDx/C1qb4DeeGg65kjxa+KUL2FA/X5bLgImaEPvZkk2QXcX
KLMh+guZCuX4fGmFB+pivfPxkoSONunrorBDHUX1/3rYYGAKd81fYISlrNhqyX+Xk0rH
375g==
X-Gm-Message-State: AOAM530i4dRUuEYiqbEU2SvHzjGrhtNc/B8eRqOdxCUQQqoAjEiJPS7Z
hhfBmwCLl3KcM5cVYZAjDdKnq7bGzow=
X-Google-Smtp-Source: ABdhPJwGWsKiR4qW/jZrz/mjiTYdeENbjly/k96bEfxf+UA0eIZdHKVAFImpZD5FY0D5vhI0LQrtjg==
X-Received: by 2002:a9d:7391:: with SMTP id j17mr1929143otk.82.1619752556947;
Thu, 29 Apr 2021 20:15:56 -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 j5sm401272otq.10.2021.04.29.20.15.53
(version=TLS1 cipher=ECDHE-RSA-AES128-SHA bits=128/128);
Thu, 29 Apr 2021 20:15:55 -0700 (PDT)
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
To: Rainer Orth <ro@HIDDEN>
Subject: Re: bug#47795: utils.test fails intermittently
References: <yddk0p3hgvz.fsf@HIDDEN>
In-Reply-To: <yddk0p3hgvz.fsf@HIDDEN>
Content-Type: text/plain; charset=UTF-8; format=flowed
Content-Transfer-Encoding: 7bit
X-Spam-Score: 0.5 (/)
X-Debbugs-Envelope-To: 47795
Cc: 47795 <at> debbugs.gnu.org
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 (/)
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
bug-dejagnu@HIDDEN:bug#47795; Package dejagnu.
Full text available.
Received: (at submit) by debbugs.gnu.org; 15 Apr 2021 12:28:17 +0000
From debbugs-submit-bounces <at> debbugs.gnu.org Thu Apr 15 08:28:17 2021
Received: from localhost ([127.0.0.1]:36649 helo=debbugs.gnu.org)
by debbugs.gnu.org with esmtp (Exim 4.84_2)
(envelope-from <debbugs-submit-bounces <at> debbugs.gnu.org>)
id 1lX16W-0007Sa-VR
for submit <at> debbugs.gnu.org; Thu, 15 Apr 2021 08:28:17 -0400
Received: from lists.gnu.org ([209.51.188.17]:60146)
by debbugs.gnu.org with esmtp (Exim 4.84_2)
(envelope-from <ro@HIDDEN>) id 1lX16V-0007ST-Gi
for submit <at> debbugs.gnu.org; Thu, 15 Apr 2021 08:28:16 -0400
Received: from eggs.gnu.org ([2001:470:142:3::10]:46674)
by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256)
(Exim 4.90_1) (envelope-from <ro@HIDDEN>)
id 1lX16U-00043Y-VE
for bug-dejagnu@HIDDEN; Thu, 15 Apr 2021 08:28:15 -0400
Received: from smtp.cebitec.uni-bielefeld.de ([129.70.160.84]:47090)
by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256)
(Exim 4.90_1) (envelope-from <ro@HIDDEN>)
id 1lX16B-0006SH-3B
for bug-dejagnu@HIDDEN; Thu, 15 Apr 2021 08:28:14 -0400
Received: from localhost (localhost [127.0.0.1])
by smtp.CeBiTec.Uni-Bielefeld.DE (Postfix) with ESMTP id 62F312262
for <bug-dejagnu@HIDDEN>; Thu, 15 Apr 2021 14:27:45 +0200 (CEST)
X-Virus-Scanned: amavisd-new at CeBiTec.Uni-Bielefeld.DE
Received: from smtp.CeBiTec.Uni-Bielefeld.DE ([127.0.0.1])
by localhost (smtp.cebitec.uni-bielefeld.de [127.0.0.1]) (amavisd-new,
port 10024) with ESMTP id GORZgi9_AvcU for <bug-dejagnu@HIDDEN>;
Thu, 15 Apr 2021 14:27:44 +0200 (CEST)
Received: from manam.CeBiTec.Uni-Bielefeld.DE (p50854142.dip0.t-ipconnect.de
[80.133.65.66])
by smtp.CeBiTec.Uni-Bielefeld.DE (Postfix) with ESMTPSA id D10C32261
for <bug-dejagnu@HIDDEN>; Thu, 15 Apr 2021 14:27:44 +0200 (CEST)
DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple;
d=CeBiTec.Uni-Bielefeld.DE; s=20200306; t=1618489664;
bh=8j1MV9aK9gVNv35GtNQaJQlCWqvjkS0dlkVwUN/J/dg=;
h=From:To:Subject:Date:From;
b=beHdqtoEPeqA7Z4fwnUfTvW7Y0uDqiajr3K4bZQQ1vHbj14Ys1CCgVJdX/Xpq80Ff
1D+jEiqfs3gfWRtn2hzL1sSWXnwMlp/EKmnKcYc5e/MD6wlDJwaOmDTtlFR+KEJLeC
FNivssC4LCC5wuLRQ1Hqi/bZjE6cUtZRAcNc5KlP5Ga3+l2gtDiHCwJJ2DYB5URJj2
VngoFhx2F6nrctVyQvxU3fVUmnogIRyzwIu4jdNqrxM6bRxxRmYmxEbQ9WeJ5hBdZo
W0KRI2SROCMSPyevHo5EzNKw/NLdFBAB4Fk8G72cgr3P9ZXk19ftif/rh/fR7bG2ZW
XdBGQvK/f45Fw==
From: Rainer Orth <ro@HIDDEN>
To: bug-dejagnu@HIDDEN
Subject: utils.test fails intermittently
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-Debbugs-Envelope-To: submit
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.
Rainer Orth <ro@HIDDEN>:bug-dejagnu@HIDDEN.
Full text available.bug-dejagnu@HIDDEN:bug#47795; Package dejagnu.
Full text available.
GNU bug tracking system
Copyright (C) 1999 Darren O. Benham,
1997 nCipher Corporation Ltd,
1994-97 Ian Jackson.