GNU bug report logs - #42399
DejaGnu randomly truncates lines in runtest output

Previous Next

To add a comment to this bug, you must first unarchive it, by sending
a message to control AT debbugs.gnu.org, with unarchive 42399 in the body.
You can then email your comments to 42399 AT debbugs.gnu.org in the normal way.

Toggle the display of automated, internal messages from the tracker.

Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):

From: Alex Coplan <alex.coplan <at> arm.com>
To: bug-dejagnu <at> gnu.org
Cc: nd <at> arm.com
Subject: DejaGnu randomly truncates lines in runtest output
Date: Thu, 16 Jul 2020 15:30:46 +0100

Hello,

I've run into a DejaGnu bug while working on the GCC testsuite
(specifically the libgccjit testsuite). The issue is that runtest ends
up randomly truncating lines in the output.

To reproduce the issue, in a new directory, create a file bug.c with the
following contents:

  #include <dejagnu.h>

  int main(void)
  {
    for (int i = 0; i < 200; i++) {
      pass("This is a really long string and maybe it will be truncated because of the bug.");
    }
  }

Then, create a subdirectory bug.dg, containing a single file bug.exp
with the following contents:

  global text

  spawn "./a.out"

  set prefix "\[^\r\n\]*"
  expect {
    -re "^$prefix\tPASSED:${text}*" {
      regsub "\[\n\r\t\]*PASSED: $text\r\n" $expect_out(0,string) "" output
      set output [string range $output 8 end]
      pass "$output"
      exp_continue
    }
    -re "^$prefix\r\n" {
      exp_continue
    }
  }

Now compile bug.c, and verify the output is as expected:

$ gcc bug.c
$ ./a.out | uniq -c
    200         PASSED: This is a really long string and maybe it will be truncated because of the bug.

Now to reproduce the bug:

$ runtest --all 2>&1 | uniq -c

I see:

   1 WARNING: No tool specified
   1 Test run by alecop01 on Thu Jul 16 14:33:58 2020
   1 Native configuration is x86_64-pc-linux-gnu
   1 
   1 		===  tests ===
   1 
   1 Schedule of variations:
   1     unix
   1 
   1 Running target unix
   1 Using /usr/share/dejagnu/baseboards/unix.exp as board description file for target.
   1 Using /usr/share/dejagnu/config/unix.exp as generic interface file for target.
   1 WARNING: Couldn't find tool config file for unix, using default.
   1 Running ./bug.dg/bug.exp ...
  49 PASS:  This is a really long string and maybe it will be truncated because of the bug.
   1 PASS:  This is a really long string and mayb
  90 PASS:  This is a really long string and maybe it will be truncated because of the bug.
   1 PASS:  This is a really long string and mayb
  59 PASS:  This is a really long string and maybe it will be truncated because of the bug.
   1 
   1 		===  Summary ===
   1 
   1 # of expected passes		200

That is, some of the lines in the output have been truncated.

Running the last step multiple times, you should be able to see that the
truncation happens at different points in the output each time. This
nondeterministic behaviour makes it especially problematic since it is
now quite difficult to compare results across multiple test runs.

If it helps with reproducing the issue, I'm running Ubuntu 18.04 on
x86_64 and my software versions are as follows:

$ runtest --version
DejaGnu version	1.6.1
Expect version	5.45.4
Tcl version	8.6

Many thanks in advance for any assistance with this issue.

Best Regards,
Alex

Message #8 received at 42399 <at> debbugs.gnu.org (full text, mbox):

From: Jacob Bachmeyer <jcb62281 <at> gmail.com>
To: Alex Coplan <alex.coplan <at> arm.com>
Cc: 42399 <at> debbugs.gnu.org, nd <at> arm.com
Subject: Re: bug#42399: DejaGnu randomly truncates lines in runtest output
Date: Thu, 16 Jul 2020 21:40:21 -0500

Alex Coplan wrote:
> Then, create a subdirectory bug.dg, containing a single file bug.exp
> with the following contents:
>
>   global text
>
>   spawn "./a.out"
>
>   set prefix "\[^\r\n\]*"
>   expect {
>     -re "^$prefix\tPASSED:${text}*" {
>       regsub "\[\n\r\t\]*PASSED: $text\r\n" $expect_out(0,string) "" output
>       set output [string range $output 8 end]
>       pass "$output"
>       exp_continue
>     }
>     -re "^$prefix\r\n" {
>       exp_continue
>     }
>   }
>   

The bug is actually in bug.exp:  you have an expect pattern that does 
not require a newline at the end of its match.  Most of the time, 
DejaGnu runs often enough that there is only one line in the buffer, so 
this happens to work, but if the program under test produces output very 
quickly (as C unit test executables tend to do) the block read into 
DejaGnu may not end on a line boundary.  If the patterns require a 
terminating newline, there is no issue, since the patterns can then only 
match whole lines and Expect will read more input if needed.

There are plans to document the DejaGnu native unit testing protocol and 
to refactor reading test results into a separate API call from running 
the program under test to provide better support for other unit testing 
protocols like Perl's TAP, but the host_execute procedure currently 
exhibits this bug in master.

However, we are close to a 1.6.3 release and changing host_execute could 
have far-reaching effects.  The bad patterns in host_execute go back to 
the earliest revisions in the repository, and I hesitate to that 
procedure at this time, so this may have to be a known bug in the 1.6.3 
release, in which case it will be added to the planned fixes list for 1.6.4.

To Rob Savoye:  should we delay the 1.6.3 release to change the patterns 
in host_execute?  I think that I can adapt the needed patterns from the 
DejaGnu testsuite.

> Running the last step multiple times, you should be able to see that the
> truncation happens at different points in the output each time. This
> nondeterministic behaviour makes it especially problematic since it is
> now quite difficult to compare results across multiple test runs.
>   

Yes, the truncations are a result of the whims of the system scheduler.

There are two parts to this issue:  (1) the documentation needs to warn 
of this caveat and explain that patterns must not match prefixes of 
their intended input, and (2) DejaGnu's own host_execute procedure needs 
to heed that warning.  Any similar code in the GCC testsuite also needs 
to handle this issue.


-- Jacob

Message #11 received at 42399 <at> debbugs.gnu.org (full text, mbox):

From: Andreas Schwab <schwab <at> linux-m68k.org>
To: Alex Coplan <alex.coplan <at> arm.com>
Cc: 42399 <at> debbugs.gnu.org, nd <at> arm.com
Subject: Re: bug#42399: DejaGnu randomly truncates lines in runtest output
Date: Fri, 17 Jul 2020 10:39:45 +0200

On Jul 16 2020, Alex Coplan wrote:

> Then, create a subdirectory bug.dg, containing a single file bug.exp
> with the following contents:
>
>   global text
>
>   spawn "./a.out"
>
>   set prefix "\[^\r\n\]*"
>   expect {
>     -re "^$prefix\tPASSED:${text}*" {

Are you sure you want to repeatedly match the last character in ${text}?

Andreas.

-- 
Andreas Schwab, schwab <at> linux-m68k.org
GPG Key fingerprint = 7578 EB47 D4E5 4D69 2510  2552 DF73 E780 A9DA AEC1
"And now for something completely different."

Message #14 received at 42399 <at> debbugs.gnu.org (full text, mbox):

From: Jacob Bachmeyer <jcb62281 <at> gmail.com>
To: Andreas Schwab <schwab <at> linux-m68k.org>
Cc: 42399 <at> debbugs.gnu.org, nd <at> arm.com, Alex Coplan <alex.coplan <at> arm.com>
Subject: Re: bug#42399: DejaGnu randomly truncates lines in runtest output
Date: Fri, 17 Jul 2020 18:19:07 -0500

Andreas Schwab wrote:
> On Jul 16 2020, Alex Coplan wrote:
>   
>> Then, create a subdirectory bug.dg, containing a single file bug.exp
>> with the following contents:
>>
>>   global text
>>
>>   spawn "./a.out"
>>
>>   set prefix "\[^\r\n\]*"
>>   expect {
>>     -re "^$prefix\tPASSED:${text}*" {
>>     
>
> Are you sure you want to repeatedly match the last character in ${text}?
>   

That is what host_execute currently does in DejaGnu, since at least 2001 
to now.  The ${text} pattern fragment in lib/dejagnu.exp is a character 
class; I am considering replacing its use in host_execute and changing 
the {${text}*} in those patterns to {[^\n]+\n} which should fix this 
bug, but could have far-reaching effects on testsuites, which makes me 
somewhat reluctant to do so this close to a release.

This bug will be fixed in 1.6.4, but whether it will be fixed or a known 
bug in 1.6.3 is not yet determined.


-- Jacob

Message #17 received at 42399 <at> debbugs.gnu.org (full text, mbox):

From: Alex Coplan <Alex.Coplan <at> arm.com>
To: "jcb62281 <at> gmail.com" <jcb62281 <at> gmail.com>, Andreas Schwab
 <schwab <at> linux-m68k.org>
Cc: "42399 <at> debbugs.gnu.org" <42399 <at> debbugs.gnu.org>, nd <nd <at> arm.com>
Subject: RE: bug#42399: DejaGnu randomly truncates lines in runtest output
Date: Mon, 20 Jul 2020 07:34:09 +0000

Hi both,

> -----Original Message-----
> From: Jacob Bachmeyer <jcb62281 <at> gmail.com>
> Sent: 18 July 2020 00:19
> To: Andreas Schwab <schwab <at> linux-m68k.org>
> Cc: Alex Coplan <Alex.Coplan <at> arm.com>; 42399 <at> debbugs.gnu.org; nd <nd <at> arm.com>
> Subject: Re: bug#42399: DejaGnu randomly truncates lines in runtest output
> 
> Andreas Schwab wrote:
> > On Jul 16 2020, Alex Coplan wrote:
> >
> >> Then, create a subdirectory bug.dg, containing a single file bug.exp
> >> with the following contents:
> >>
> >>   global text
> >>
> >>   spawn "./a.out"
> >>
> >>   set prefix "\[^\r\n\]*"
> >>   expect {
> >>     -re "^$prefix\tPASSED:${text}*" {
> >>
> >
> > Are you sure you want to repeatedly match the last character in ${text}?
> >
> 
> That is what host_execute currently does in DejaGnu, since at least 2001
> to now.

Yes, for context, bug.exp is reduced from the "fixed_host_execute"
function in the libgccjit testsuite [0].

> The ${text} pattern fragment in lib/dejagnu.exp is a character
> class; I am considering replacing its use in host_execute and changing
> the {${text}*} in those patterns to {[^\n]+\n} which should fix this
> bug, but could have far-reaching effects on testsuites, which makes me
> somewhat reluctant to do so this close to a release.

This change to the pattern appears to fix the issue for me, thanks!
After some further testing I will submit a patch for the
fixed_host_execute function in the GCC testsuite.

> 
> This bug will be fixed in 1.6.4, but whether it will be fixed or a known
> bug in 1.6.3 is not yet determined.
> 
> 
> -- Jacob

Thanks,
Alex

[0] : https://gcc.gnu.org/git/?p=gcc.git;a=blob;f=gcc/testsuite/jit.dg/jit.exp;h=2f54681713b86c44069da88efd769e01f7c7bae4;hb=HEAD#l117

Message #24 received at 42399-done <at> debbugs.gnu.org (full text, mbox):

From: Jacob Bachmeyer <jcb62281 <at> gmail.com>
To: Alex Coplan <Alex.Coplan <at> arm.com>
Cc: 42399-done <at> debbugs.gnu.org, nd <nd <at> arm.com>,
 Andreas Schwab <schwab <at> linux-m68k.org>
Subject: Re: bug#42399: DejaGnu randomly truncates lines in runtest output
Date: Wed, 12 Aug 2020 21:51:58 -0500

Alex Coplan wrote:
>> -----Original Message-----
>> From: Jacob Bachmeyer <jcb62281 <at> gmail.com>
>> Sent: 18 July 2020 00:19
>> To: Andreas Schwab <schwab <at> linux-m68k.org>
>> Cc: Alex Coplan <Alex.Coplan <at> arm.com>; 42399 <at> debbugs.gnu.org; nd <nd <at> arm.com>
>> Subject: Re: bug#42399: DejaGnu randomly truncates lines in runtest output
>>
>> [...]
>> This bug will be fixed in 1.6.4, but whether it will be fixed or a known
>> bug in 1.6.3 is not yet determined.

The code fix landed on master at commit 
1e4010a4d2a8b63c3215dd7492eba38f056bb6e3, while the last of the 
associated fixes for the manual was commit 
aa173cea24b94d3f714f07bbbfda85740e8e77db just now.  With these commits, 
this bug should be fixed and is now closed, but please do not hesitate 
to reopen the bug (after verifying that you are actually using DejaGnu's 
host_execute procedure and not an out-of-tree fork thereof) if the issue 
somehow persists.


-- Jacob

Previous Next

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