Bug 12096 - dejagnu truncates output from spawned commands randomly, causing intermittant failed tests
Summary: dejagnu truncates output from spawned commands randomly, causing intermittant...
Status: RESOLVED WORKSFORME
Alias: None
Product: gcc
Classification: Unclassified
Component: testsuite (show other bugs)
Version: 3.3.1
: P2 normal
Target Milestone: ---
Assignee: Not yet assigned to anyone
URL:
Keywords: documentation
: 18961 21996 (view as bug list)
Depends on:
Blocks:
 
Reported: 2003-08-28 17:33 UTC by dank
Modified: 2017-01-11 20:38 UTC (History)
5 users (show)

See Also:
Host:
Target:
Build:
Known to work:
Known to fail:
Last reconfirmed: 2005-05-11 01:04:27


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description dank 2003-08-28 17:33:45 UTC
This is most likely a bug in expect, not in any part of gcc,
but it deserves mention here nonetheless. 
Tests which tend to be affected by this are those that generate
lots of output.  I've observed it cause the following most often:

FAIL: gcc.dg/cpp/tr-warn3.c 
FAIL: gcc.dg/format/c90-printf-1.c 
FAIL: gcc.dg/format/c99-printf-1.c
FAIL: gcc.dg/format/ext-1.c
FAIL: gcc.dg/format/ext-3.c 
FAIL: gcc.dg/format/ext-6.c 
FAIL: gcc.dg/noncompile/voidparam-1.c
FAIL: gcc.dg/typespec-1.c
FAIL: g++.law/visibility19.C

and the failures usually are marked with 'test for warnings'
or 'test for excess errors', e.g.

FAIL: gcc.dg/format/ext-3.c bad %^# (test for warnings, line 215)
FAIL: gcc.dg/format/ext-3.c (test for excess errors) 

See also
http://gcc.gnu.org/ml/gcc/2001-02/msg01313.html
http://gcc.gnu.org/ml/gcc/2002-09/msg00653.html
http://mail.gnu.org/archive/html/dejagnu/2003-07/msg00020.html

One workaround might be to install the latest expect, but 
I haven't tried that.
FWIW, on one system I'm seeing this on, 'expect -version' outputs
"expect version 5.32.2"
which is probably as old as the oldest report I cite above,
so updating expect might indeed help.
Comment 1 Andrew Pinski 2003-11-02 22:37:26 UTC
Since expact or dejagnu is not part GCC at all, closing.
Comment 2 Joseph S. Myers 2003-11-02 22:51:37 UTC
Subject: Re:  dejagnu truncates output from spawned commands
 randomly, causing intermittant failed tests

On Sun, 2 Nov 2003, pinskia at gcc dot gnu dot org wrote:

> Since expact or dejagnu is not part GCC at all, closing.

Do note that we try to document the prerequisites for
building/testing/modifying GCC, and our documentation with regard to
expect/dejagnu is seriously deficient (as no-one was sure of the required
versions):

   expect version ???

   tcl version ???

   dejagnu version ???
          Necessary to run the GCC testsuite.

Given that in fact an expect version with a special patch (HJ had one,
appended) may be needed, we really ought to try to do any necessary
testing and document the requirement (especially if the latest version
from expect.nist.gov doesn't work without being patched).

-- 
Joseph S. Myers
jsm@polyomino.org.uk

--- expect5.31/exp_chan.c.read	Fri Nov 16 00:14:15 2001
+++ expect5.31/exp_chan.c	Fri Nov 16 00:14:15 2001
@@ -519,6 +519,7 @@ expCreateChannel(interp,fdin,fdout,pid)
     esPtr->buffer = Tcl_NewStringObj("",0);
     Tcl_IncrRefCount(esPtr->buffer);
     esPtr->umsize = exp_default_match_max;
+    esPtr->umsize_changed = exp_default_match_max_changed;
     /* this will reallocate object with an appropriate sized buffer */
     expAdjust(esPtr);
 
--- expect5.31/exp_command.h.read	Fri Nov 16 00:14:15 2001
+++ expect5.31/exp_command.h	Fri Nov 16 00:14:15 2001
@@ -25,6 +25,7 @@ would appreciate credit if this program 
 EXTERN char *		exp_get_var _ANSI_ARGS_((Tcl_Interp *,char *));
 
 EXTERN int exp_default_match_max;
+EXTERN int exp_default_match_max_changed;
 EXTERN int exp_default_parity;
 EXTERN int exp_default_rm_nulls;
 
@@ -97,6 +98,7 @@ typedef struct ExpState {
     int msize;	        /* # of bytes that buffer can hold (max) */
     int umsize;	        /* # of bytes (min) that is guaranteed to match */
 			/* this comes from match_max command */
+    int umsize_changed;	/* is umsize changed by user?  */
     int printed;	/* # of bytes written to stdout (if logging on) */
                         /* but not actually returned via a match yet */
     int echoed;	        /* additional # of bytes (beyond "printed" above) */
--- expect5.31/expect.c.read	Fri Nov 16 00:14:15 2001
+++ expect5.31/expect.c	Fri Nov 16 11:09:59 2001
@@ -41,8 +41,17 @@ would appreciate credit if this program 
 #include "tcldbg.h"
 #endif
 
+/* The initial length is 2000. We increment it by 2000. The maximum
+   is 8MB (0x800000).  */
+#define EXP_MATCH_MAX		2000
+#define EXP_MATCH_INC		2000
+#define EXP_MATCH_STEP_LIMIT	0x700000
+#define EXP_MATCH_LIMIT		0x800000
+#define EXP_MATCH_LIMIT_QUOTE	"0x800000"
+
 /* initial length of strings that we can guarantee patterns can match */
-int exp_default_match_max =	2000;
+int exp_default_match_max =	EXP_MATCH_MAX;
+int exp_default_match_max_changed = 0;
 #define INIT_EXPECT_TIMEOUT_LIT	"10"	/* seconds */
 #define INIT_EXPECT_TIMEOUT	10	/* seconds */
 int exp_default_parity =	TRUE;
@@ -1557,6 +1566,76 @@ expNullStrip(obj,offsetBytes)
     Tcl_SetObjLength(obj,offsetBytes + (dest - src2));
 }
 
+/* returns # of bytes until we see a newline at the end or EOF.  */
+/*ARGSUSED*/
+static int
+expReadNewLine(interp,esPtr,save_flags) /* INTL */
+Tcl_Interp *interp;
+ExpState *esPtr;
+int save_flags;
+{
+    int size;
+    int exp_size;
+    int full_size;
+    int count;
+    char *str;
+
+    count = 0;
+    for (;;) {
+	exp_size = expSizeGet(esPtr);
+
+	/* When we reach the limit, we will only read one char at a
+	   time.  */
+	if (esPtr->umsize >= EXP_MATCH_STEP_LIMIT)
+	    size = TCL_UTF_MAX;
+	else
+	    size = exp_size;
+
+	if (exp_size + TCL_UTF_MAX >= esPtr->msize) {
+	    if (esPtr->umsize >= EXP_MATCH_LIMIT) {
+		expDiagLogU("WARNING: interact buffer is full. probably your program\r\n");
+		expDiagLogU("is not interactive or has a very long output line. The\r\n");
+		expDiagLogU("current limit is " EXP_MATCH_LIMIT_QUOTE ".\r\n");
+		expDiagLogU("Dumping first half of buffer in order to continue\r\n");
+		expDiagLogU("Recommend you enlarge the buffer.\r\n");
+		exp_buffer_shuffle(interp,esPtr,save_flags,EXPECT_OUT,"expect");
+		return count;
+	    }
+	    else {
+		esPtr->umsize += EXP_MATCH_INC;
+		expAdjust(esPtr);
+	    }
+	}
+
+	full_size = esPtr->msize - (size / TCL_UTF_MAX);
+	size = Tcl_ReadChars(esPtr->channel,
+			esPtr->buffer,
+			full_size,
+			1 /* append */);
+	if (size > 0) {
+	    count += size;
+	    /* We try again if there are more to read and we haven't
+	       seen a newline at the end. */
+	    if (size == full_size) {
+		str = Tcl_GetStringFromObj(esPtr->buffer, &size);
+		if (str[size - 1] != '\n')
+		    continue;
+	    }
+	}
+	else {
+	    /* It is even trickier. We got an error from read. We have
+	       to recover from it. Let's make sure the size of
+	       buffer is correct. It can be corrupted. */
+	    str = Tcl_GetString(esPtr->buffer);
+	    Tcl_SetObjLength(esPtr->buffer, strlen(str));
+	}
+
+	break;
+    }
+
+    return count;
+}
+
 /* returns # of bytes read or (non-positive) error of form EXP_XXX */
 /* returns 0 for end of file */
 /* If timeout is non-zero, set an alarm before doing the read, else assume */
@@ -1571,6 +1650,8 @@ int save_flags;
 {
     int cc = EXP_TIMEOUT;
     int size = expSizeGet(esPtr);
+    int full_size;
+    int count;
 
     if (size + TCL_UTF_MAX >= esPtr->msize) 
 	exp_buffer_shuffle(interp,esPtr,save_flags,EXPECT_OUT,"expect");
@@ -1587,11 +1668,43 @@ int save_flags;
     }
 #endif
 
-    
+    /* FIXME: If we ask less than what is available in the tcl buffer
+       when tcl has seen EOF, we will throw away the remaining data
+       since the next read will get EOF. Since expect is line-oriented,
+       we exand our buffer to get EOF or the next newline at the end of
+       the input buffer. I don't know if it is the right fix.  H.J. */
+    count = 0;
+    full_size = esPtr->msize - (size / TCL_UTF_MAX);
     cc = Tcl_ReadChars(esPtr->channel,
-	    esPtr->buffer,
-	    esPtr->msize - (size / TCL_UTF_MAX),
-	    1 /* append */);
+		esPtr->buffer,
+		full_size,
+		1 /* append */);
+    if (cc > 0) {
+	count += cc;
+	/* It gets very tricky. There are more to read. We will expand
+	   our buffer and get EOF or a newline at the end unless the
+	   buffer length has been changed.  */
+	if (cc == full_size) {
+	    char *str;
+	    str = Tcl_GetStringFromObj(esPtr->buffer, &size);
+	    if (str[size - 1] != '\n') {
+		if (esPtr->umsize_changed) {
+		    char buf[20];	/* big enough for 64bit int in hex.  */
+		    snprintf(buf,sizeof(buf),"0x%x", esPtr->umsize);
+		    expDiagLogU("WARNING: interact buffer is not large enough to hold\r\n");
+		    expDiagLogU("all output. probably your program is not interactive or\r\n");
+		    expDiagLogU("has a very long output line. The current limit is ");
+		    expDiagLogU(buf);
+		    expDiagLogU(".\r\n");
+		}
+		else {
+		    cc = expReadNewLine(interp,esPtr,save_flags);
+		    if (cc > 0)
+			count += cc;
+		}
+	    }
+	}
+    }
     i_read_errno = errno;
 
 #ifdef SIMPLE_EVENT
@@ -1612,7 +1725,7 @@ int save_flags;
 	}
     }
 #endif
-    return cc;	
+    return count > 0 ? count : cc;
 }
 
 /*
@@ -2667,8 +2780,14 @@ char **argv;
 	return(TCL_ERROR);
     }
 
-    if (Default) exp_default_match_max = size;
-    else esPtr->umsize = size;
+    if (Default) {
+	exp_default_match_max = size;
+	exp_default_match_max_changed = 1;
+    }
+    else {
+	esPtr->umsize = size;
+	esPtr->umsize_changed = 1;
+    }
 
     return(TCL_OK);
 }
Comment 3 dank 2003-11-03 00:35:57 UTC
Uh, dejagnu is included as part of the gcc tarball,
and is used to run the gcc regresssion tests. 
The copy shipped with gcc seems to have a bug in it.
Ergo it seems a bit cavalier to deny there's a problem.
There is at the very least a doc problem, as the
previous comment indicates.

jsm, thanks for posting that expect patch!  I'll
try updating my expect and applying that patch
to see if it helps.
Comment 4 Andrew Pinski 2003-11-03 01:51:03 UTC
dejagnu is in what tar ball, it is included with gdb, yes but not gcc.
Comment 5 Andrew Pinski 2003-11-03 02:35:38 UTC
GCC does not come with dejagnu, you must be thinking of GDB.
Comment 6 Dara Hazeghi 2003-11-05 00:39:54 UTC
I don't think this should be closed until we know _why_ dejagnu is failing. Daniel, can you check if 
the patch works? If so, a note in the install documentation is probably in order...
Comment 7 Dara Hazeghi 2004-01-17 23:57:04 UTC
Dan, any news on whether this still occurs, and if so why...?
Comment 8 Mark Post 2004-01-24 06:08:19 UTC
I was experiencing this exact problem, so I applied the proposed patch to expect
5.38, and re-ran the "make check" command.  The supposed failures I was seeing
all went away as a result.  I informed the expect maintainers of this problem
record so they could see the proposed patch that does seem to fix the problem:
https://sourceforge.net/tracker/index.php?func=detail&aid=883485&group_id=13179&atid=113179

Mark Post
Comment 9 dank 2004-01-27 17:09:44 UTC
The patch seems to do the trick.  It's required even if you're using
the latest expect.  I hope it gets integrated into the expect mainline.

Not sure what the next step is here, but I'll mark this as FIXED
to indicate that anyone who runs into this can get around it
by building an expect with the patch.  I'll also include this
in the crosstool patch repository at http://kegel.com/crosstool
Comment 10 Joseph S. Myers 2004-01-27 17:19:04 UTC
Subject: Re:  dejagnu truncates output from spawned commands
 randomly, causing intermittant failed tests

On Tue, 27 Jan 2004, dank at kegel dot com wrote:

> Not sure what the next step is here, but I'll mark this as FIXED

I don't think we should consider it fixed without proper documentation of
the required expect version in install.texi.

Comment 11 Dara Hazeghi 2004-01-27 17:36:27 UTC
Agreed. I'll make a patch this weekend if nobody else gets to it...
Comment 12 Chris Jefferson 2005-02-08 13:24:15 UTC
*** Bug 18961 has been marked as a duplicate of this bug. ***
Comment 13 Haren Visavadia 2005-06-10 15:35:33 UTC
*** Bug 21996 has been marked as a duplicate of this bug. ***
Comment 14 duncan_roe@acslink.net.au 2006-06-25 05:31:45 UTC
This problem is still displayed at gcc-4.1.1 using expect 5.43 and tcl 8.4.13. The patch above requires that one uses patch's --ignore-whitespace option because tab/space information is no longer present. See bug 28137.
Comment 15 Martin Sebor 2017-01-11 20:38:00 UTC
I haven't seen this problem although I have reported intermittent test failures in parallel builds in bug 77684.  Since the recommended DejaGnu, Expect, and Tcl versions are documented on the GCC Prerequisites page (https://gcc.gnu.org/install/prerequisites.html) and since there has been no progress or activity on this bug in a decade I'll close it as Works For Some.  If it persists or if the documentation is still inaccurate or insufficient please either reopen this bug or open a new one and attach the relevant output and version information or explain how the documentation should change.