Test hang in Y01

Test hang in Y01

[Vin Shelton]

Greetings -

With an up-to-date archive, I'm getting a hang in test Y01.  Here's
what I found:

; ZTST_verbose=2 make TESTNUM=Y01 check
if test -n "gcc"; then \
          cd .. && DESTDIR= \
          make MODDIR=`pwd`/Test/Modules install.modules > /dev/null; \
        fi
if ZTST_testlist="`for f in /opt/src/zsh-2009-01-09/Test/Y01*.ztst; \
           do echo $f; done`" \
         ZTST_srcdir="/opt/src/zsh-2009-01-09/Test" \
         ZTST_exe=../Src/zsh \
         ../Src/zsh +Z -f /opt/src/zsh-2009-01-09/Test/runtests.zsh; then \
         stat=0; \
        else \
         stat=1; \
        fi; \
        rm -rf Modules .zcompdump; \
        exit $stat
/opt/src/zsh-2009-01-09/Test/Y01completion.ztst: starting.
ZTST_getsect: read section name: prep
ZTST_getchunk: read code chunk:
  if ( zmodload -i zsh/zpty ) >/dev/null 2>&1; then
    . $ZTST_srcdir/comptest
    mkdir comp.tmp
    cd comp.tmp
    comptestinit -z $ZTST_testdir/../Src/zsh &&
    {
      mkdir dir1 &&
      mkdir dir2 &&
      touch file1 &&
      touch file2
    }
  else
    ZTST_unimplemented="the zsh/zpty module is not available"
  fi
ZTST_execchunk: status 0
ZTST_getchunk: read code chunk:

ZTST_getsect: read section name: test
ZTST_test: looking for new test
ZTST_test: examining line:

ZTST_test: examining line:
  comptest $': \t\t\t\t\t\t\t'
ZTST_getchunk: read code chunk:
  comptest $': \t\t\t\t\t\t\t'
ZTST_test: examining line:
>line: {: }{}
ZTST_getredir: read redir for '>':
line: {: }{}
DESCRIPTION:{file}
DI:{dir1}
DI:{dir2}
FI:{file1}
FI:{file2}
line: {: dir1/}{}
line: {: dir2/}{}
line: {: file1}{}
line: {: file2}{}
line: {: dir1/}{}
line: {: dir2/}{}
ZTST_test: examining line:

Running test: directories and files
ZTST_test: expecting status: 0
Input: /tmp/zsh.ztst.in.30417, output: /tmp/zsh.ztst.out.30417, error:
/tmp/zsh.ztst.terr.30417

The err file is empty.  The output file contains only:

line: {: }{}
DESCRIPTION:{file}
DI:{dir1}
DI:{dir2}
FI:{file1}
FI:{file2}
line: {: dir1/}{}
line: {: dir2/}{}
line: {: file1}{}
line: {: file2}{}
line: {: dir1/}{}
line: {: dir2/}{}

Let me know if you need any more information.

Regards,
  Vin

Re: Test hang in Y01

[Bart Schaefer]

On Jan 10, 10:44am, Vin Shelton wrote:
}
} With an up-to-date archive, I'm getting a hang in test Y01.  Here's
} what I found:
} 
} Running test: directories and files
} ZTST_test: expecting status: 0
} Input: /tmp/zsh.ztst.in.30417, output: /tmp/zsh.ztst.out.30417, error:
} /tmp/zsh.ztst.terr.30417
} 
} Let me know if you need any more information.

OS and hardware architecture?

This test passes OK for me (RHEL4 / i686).

Re: Test hang in Y01

[Vin Shelton]

On Sat, Jan 10, 2009 at 12:34 PM, Bart Schaefer
<schaefer@brasslantern.com> wrote:
> On Jan 10, 10:44am, Vin Shelton wrote:
> }
> } With an up-to-date archive, I'm getting a hang in test Y01.  Here's
> } what I found:
> }
> } Running test: directories and files
> } ZTST_test: expecting status: 0
> } Input: /tmp/zsh.ztst.in.30417, output: /tmp/zsh.ztst.out.30417, error:
> } /tmp/zsh.ztst.terr.30417
> }
> } Let me know if you need any more information.
>
> OS and hardware architecture?
>
> This test passes OK for me (RHEL4 / i686).
>
>

ubuntu 8.4

uname -a reports:

Linux samwise 2.6.24-23-generic #1 SMP Thu Nov 27 18:44:42 UTC 2008
i686 GNU/Linux

Regards,
  Vin

Re: Test hang in Y01

[Peter Stephenson]

On Sat, 10 Jan 2009 10:44:49 -0500
"Vin Shelton" <acs@alumni.princeton.edu> wrote:
> With an up-to-date archive, I'm getting a hang in test Y01.

Haven't seen this with committed code, but I did get a hang in the
middle of changing it at one point.  Could you try "make clean" first?

-- 
Peter Stephenson <p.w.stephenson@ntlworld.com>
Web page now at http://homepage.ntlworld.com/p.w.stephenson/

Re: Test hang in Y01

[Vin Shelton]

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

I started from a clean checkout, so I doubt that will help, but I'll try
when I get home.
  Vin

On Jan 10, 2009 4:48 PM, "Peter Stephenson" <p.w.stephenson@ntlworld.com>
wrote:

On Sat, 10 Jan 2009 10:44:49 -0500 "Vin Shelton" <acs@alumni.princeton.edu>
wrote: > With an up-to-d...
Haven't seen this with committed code, but I did get a hang in the
middle of changing it at one point.  Could you try "make clean" first?

--
Peter Stephenson <p.w.stephenson@ntlworld.com>
Web page now at http://homepage.ntlworld.com/p.w.stephenson/

[-- Attachment #2: Type: text/html, Size: 963 bytes --]

Re: Test hang in Y01

[Geoff Wing]

On Saturday 2009-01-10 21:48 +0000, Peter Stephenson output:
:On Sat, 10 Jan 2009 10:44:49 -0500
:"Vin Shelton" <acs@alumni.princeton.edu> wrote:
:> With an up-to-date archive, I'm getting a hang in test Y01.
:Haven't seen this with committed code, but I did get a hang in the
:middle of changing it at one point.  Could you try "make clean" first?

Does it for me too.  My nightly build/test cron job first picked it up
12 hours ago so it only due to something in the last day or so.  It hangs
with continuous CPU use.

BTW, the ChangeLog line for 26272 has some stuff elided.

Regards,
Geoff

#0  0xbbafba77 in read () from /usr/lib/libc.so.12
#1  0xbbad0082 in bin_zpty (nam=0x80f96d0 "zpty", args=0xbfbe7784, ops=0xbfbe77f0, func=0) at zpty.c:573
#2  0x08057efe in execbuiltin (args=0x80f9688, bn=0xbbad1e20) at builtin.c:439
#3  0x08066be9 in execcmd (state=0xbfbea058, input=0, output=0, how=2, last1=2) at exec.c:3066
#4  0x0806776a in execpline2 (state=0xbfbea058, pcode=<value optimized out>, how=2, input=0, output=0, last1=0) at exec.c:1561
#5  0x08067b17 in execpline (state=0xbfbea058, slcode=<value optimized out>, how=2, last1=0) at exec.c:1347
#6  0x08068adb in execlist (state=0xbfbea058, dont_change_job=1, exiting=0) at exec.c:1184
#7  0x08068bb5 in execode (p=0x80d0de0, dont_change_job=1, exiting=0) at exec.c:975
#8  0x08068c69 in runshfunc (prog=0x80d0de0, wrap=0x0, name=dwarf2_read_address: Corrupted DWARF expression.) at exec.c:4423
#9  0x0806900a in doshfunc (shfunc=0x80d46f8, doshargs=0x80f94c8, noreturnval=0) at exec.c:4331
[...it's a long backtrace...]
#58 0x08068bb5 in execode (p=0x80e15b0, dont_change_job=0, exiting=0) at exec.c:975
#59 0x08078874 in loop (toplevel=1, justonce=0) at init.c:181
#60 0x080794e2 in zsh_main (argc=5, argv=0xbfbfe708) at init.c:1406
#61 0x08052217 in main (argc=Cannot access memory at address 0x7a28) at ./main.c:93

Re: Test hang in Y01

[Peter Stephenson]

On Sun, 11 Jan 2009 16:45:06 +1100
Geoff Wing <gcw@zsh.org> wrote:
> On Saturday 2009-01-10 21:48 +0000, Peter Stephenson output:
> :On Sat, 10 Jan 2009 10:44:49 -0500
> :"Vin Shelton" <acs@alumni.princeton.edu> wrote:
> :> With an up-to-date archive, I'm getting a hang in test Y01.
> :Haven't seen this with committed code, but I did get a hang in the
> :middle of changing it at one point.  Could you try "make clean" first?
> 
> Does it for me too.  My nightly build/test cron job first picked it up
> 12 hours ago so it only due to something in the last day or so.  It hangs
> with continuous CPU use.
> 
> #0  0xbbafba77 in read () from /usr/lib/libc.so.12
> #1  0xbbad0082 in bin_zpty (nam=0x80f96d0 "zpty", args=0xbfbe7784, ops=0xbfbe77f0, func=0) at zpty.c:573

There must be something screwy about the exit condition for the loop in
ptyread() such that read() is repeatedly being called but not returning
in such a way that the loop exits.  I did change this a few months ago,
noticed the condition was horrible, and tried to fix it up a bit without
being entirely sure what it was trying to do (you may have heard that
before...)

If "prog" is non-NULL at that point (which I can't see offhand), we are
more aggressive about continuing, but maybe need to trap some more
errors.  For example, if ret is -1 there may be (thinking about it,
almost certainly are) some values of errno where we need to exit the
loop.  Consequently it would probably be useful to find out what errno
was and if prog was non-NULL.

This is all guesswork.  I would put small amounts of money on this being
an existing race that's just shown up rather than a fundamentally new
bug that's just been introduced.

> BTW, the ChangeLog line for 26272 has some stuff elided.

Thanks, I've fixed this.

-- 
Peter Stephenson <p.w.stephenson@ntlworld.com>
Web page now at http://homepage.ntlworld.com/p.w.stephenson/

Re: Test hang in Y01

[Bart Schaefer]

On Jan 10,  1:34pm, Vin Shelton wrote:
}
} ubuntu 8.4
} 
} uname -a reports:
} 
} Linux samwise 2.6.24-23-generic #1 SMP Thu Nov 27 18:44:42 UTC 2008
} i686 GNU/Linux

I have exactly the same on my work laptop (well, except for the host
name :-).

On Jan 11,  4:45pm, Geoff Wing wrote:
} Subject: Re: Test hang in Y01
}
} Does it for me too.  My nightly build/test cron job first picked it up
} 12 hours ago so it only due to something in the last day or so.  It hangs
} with continuous CPU use.

Odd.  Having never built zsh on that laptop, before, I did a complete
fresh CVS checkout from sourceforge, preconfig, configure, make, and
make test.  Everything passed.

I haven't tried building from the tarball.  Could there be something
wrong with the configure script that a new preconfig pass fixes up?

Re: Test hang in Y01

[Vin Shelton]

On Sun, Jan 11, 2009 at 12:46 PM, Bart Schaefer
<schaefer@brasslantern.com> wrote:
> On Jan 10,  1:34pm, Vin Shelton wrote:
> }
> } ubuntu 8.4
> }
> } uname -a reports:
> }
> } Linux samwise 2.6.24-23-generic #1 SMP Thu Nov 27 18:44:42 UTC 2008
> } i686 GNU/Linux
>
> I have exactly the same on my work laptop (well, except for the host
> name :-).
>
> On Jan 11,  4:45pm, Geoff Wing wrote:
> } Subject: Re: Test hang in Y01
> }
> } Does it for me too.  My nightly build/test cron job first picked it up
> } 12 hours ago so it only due to something in the last day or so.  It hangs
> } with continuous CPU use.
>
> Odd.  Having never built zsh on that laptop, before, I did a complete
> fresh CVS checkout from sourceforge, preconfig, configure, make, and
> make test.  Everything passed.
>
> I haven't tried building from the tarball.  Could there be something
> wrong with the configure script that a new preconfig pass fixes up?

It turns out that for me, the enabling factor is --enable-zsh-mem; if
I configure with that, I get the test hang.  Without that option, Y01
completes without a hitch.

Regards,
  Vin

Re: Test hang in Y01

[Geoff Wing]

On Sunday 2009-01-11 21:25 -0500, Vin Shelton output:
:It turns out that for me, the enabling factor is --enable-zsh-mem; if
:I configure with that, I get the test hang.  Without that option, Y01
:completes without a hitch.

Ah, same for me.  I was configuring with 
"--enable-zsh-debug
 --enable-zsh-mem --enable-zsh-mem-debug --enable-zsh-mem-warning
 --enable-zsh-secure-free --enable-zsh-hash-debug --with-tcsetpgrp
 --disable-multibyte"

Regards,
Geoff

Re: Test hang in Y01

[Peter Stephenson]

On Sun, 11 Jan 2009 21:25:15 -0500
"Vin Shelton" <acs@alumni.princeton.edu> wrote:
> It turns out that for me, the enabling factor is --enable-zsh-mem; if
> I configure with that, I get the test hang.  Without that option, Y01
> completes without a hitch.

It appeared to need both this and debugging active.  I think the underlying
failure is a crash in completion, which I can provoke very readily after
running compinit.  It would be great if someone else could do some prodding
to locate the memory error in question---I'm not going to be able to do
this at home as my home machine gave up on --enable-zsh-mem some time ago.

Unfortunately, my machine here (Fedora 8, reasonably up to date as far as
that goes) has stopped being able to read symbols from .so files and
instead issues meaningless complaints along the lines of

Missing separate debuginfo for /home/pws/src/zsh-debug/zsh/modules/zsh/zle.so
Try: yum --enablerepo='*-debuginfo' install /usr/lib/debug/.build-id/25/f01fa65e4c2fc031c9f53901f46e3f3b654c31

Clearly the message at least is Fedora-specific.  Anyone know what to do
about this?  (If switching to Debian or Ubuntu works I'm starting seriously
to consider it...)

The following patch merely makes the test symptoms more sensible.  I hope
this will allow someone to automate the search for the cause.

First, the infinite loop: the read in "zpty -r" was, as I expected, getting
an error, actually EIO.  However, it wasn't a race; the subshell had simply
gone away.  I think it makes no sense to continue the loop in ptyread()
unless the error is one of the ones we handle specially afterward, EAGAIN
and EWOULDBLOCK (possibly you can argue for EINTR, please do if you want).
Otherwise we should return at that point.

Second, "zpty -r" is designed and documented to return status 0 if it read
as far as it could and successfully input something, even if the pattern
it's been passed didn't match.  This seems a pretty odd piece of design
to me, but as it's apparently supposed to do that I've added a must match
flag, -m, and used that in the test system where we want to be quite sure
we've read what we're expecting.

Now the test fails, but more gracefully.

Index: Doc/Zsh/mod_zpty.yo
===================================================================
RCS file: /cvsroot/zsh/zsh/Doc/Zsh/mod_zpty.yo,v
retrieving revision 1.7
diff -u -r1.7 mod_zpty.yo
--- Doc/Zsh/mod_zpty.yo	25 Jan 2008 16:48:23 -0000	1.7
+++ Doc/Zsh/mod_zpty.yo	13 Jan 2009 11:44:24 -0000
@@ -38,7 +38,7 @@
 were typed, so beware when sending special tty driver characters such as
 word-erase, line-kill, and end-of-file.
 )
-item(tt(zpty) tt(-r) [ tt(-t) ] var(name) [ var(param) [ var(pattern) ] ])(
+item(tt(zpty) tt(-r) [ tt(-mt) ] var(name) [ var(param) [ var(pattern) ] ])(
 The tt(-r) option can be used to read the output of the command var(name).
 With only a var(name) argument, the output read is copied to the standard
 output.  Unless the pseudo-terminal is non-blocking, copying continues
@@ -54,10 +54,11 @@
 If a var(pattern) is given as well, output is read until the whole string
 read matches the var(pattern), even in the non-blocking case.  The return
 status is zero if the string read matches the pattern, or if the command
-has exited but at least one character could still be read.  As of this
-writing, a maximum of one megabyte of output can be consumed this way; if
-a full megabyte is read without matching the pattern, the return status is
-non-zero.
+has exited but at least one character could still be read.  If the option
+tt(-m) is present, the return status is zero only if the pattern matches.
+As of this writing, a maximum of one megabyte of output can be consumed
+this way; if a full megabyte is read without matching the pattern, the
+return status is non-zero.
 
 In all cases, the return status is non-zero if nothing could be read, and
 is tt(2) if this is because the command has finished.
Index: Src/Modules/zpty.c
===================================================================
RCS file: /cvsroot/zsh/zsh/Src/Modules/zpty.c,v
retrieving revision 1.40
diff -u -r1.40 zpty.c
--- Src/Modules/zpty.c	18 Nov 2008 10:14:35 -0000	1.40
+++ Src/Modules/zpty.c	13 Jan 2009 11:44:24 -0000
@@ -485,9 +485,9 @@
 }
 
 static int
-ptyread(char *nam, Ptycmd cmd, char **args, int noblock)
+ptyread(char *nam, Ptycmd cmd, char **args, int noblock, int mustmatch)
 {
-    int blen, used, seen = 0, ret = 0;
+    int blen, used, seen = 0, ret = 0, matchok = 0;
     char *buf;
     Patprog prog = NULL;
 
@@ -589,10 +589,24 @@
 	}
 	buf[used] = '\0';
 
-	if (!prog && (ret <= 0 || (*args && buf[used - 1] == '\n')))
-	    break;
+	if (!prog) {
+	    if (ret <= 0 || (*args && buf[used - 1] == '\n'))
+		break;
+	} else {
+	    if (ret < 0
+#ifdef EWOULDBLOCK
+		&& errno != EWOULDBLOCK
+#else
+#ifdef EAGAIN
+		&& errno != EAGAIN
+#endif
+#endif
+		)
+		break;
+	}
     } while (!(errflag || breaks || retflag || contflag) &&
-	     used < READ_MAX && !(prog && ret && pattry(prog, buf)));
+	     used < READ_MAX &&
+	     !(prog && ret && (matchok = pattry(prog, buf))));
 
     if (prog && ret < 0 &&
 #ifdef EWOULDBLOCK
@@ -613,7 +627,9 @@
     else if (used)
 	write(1, buf, used);
 
-    return (seen ? 0 : cmd->fin + 1);
+    if (seen && (!prog || matchok || !mustmatch))
+	return 0;
+    return cmd->fin + 1;
 }
 
 static int
@@ -679,16 +695,19 @@
 bin_zpty(char *nam, char **args, Options ops, UNUSED(int func))
 {
     if ((OPT_ISSET(ops,'r') && OPT_ISSET(ops,'w')) ||
-	((OPT_ISSET(ops,'r') || OPT_ISSET(ops,'w')) && 
+	((OPT_ISSET(ops,'r') || OPT_ISSET(ops,'w')) &&
 	 (OPT_ISSET(ops,'d') || OPT_ISSET(ops,'e') ||
 	  OPT_ISSET(ops,'b') || OPT_ISSET(ops,'L'))) ||
-	(OPT_ISSET(ops,'w') && OPT_ISSET(ops,'t')) ||
+	(OPT_ISSET(ops,'w') && (OPT_ISSET(ops,'t') || OPT_ISSET(ops,'m'))) ||
 	(OPT_ISSET(ops,'n') && (OPT_ISSET(ops,'b') || OPT_ISSET(ops,'e') ||
 				OPT_ISSET(ops,'r') || OPT_ISSET(ops,'t') ||
-				OPT_ISSET(ops,'d') || OPT_ISSET(ops,'L'))) ||
+				OPT_ISSET(ops,'d') || OPT_ISSET(ops,'L') ||
+				OPT_ISSET(ops,'m'))) ||
 	(OPT_ISSET(ops,'d') && (OPT_ISSET(ops,'b') || OPT_ISSET(ops,'e') ||
-				OPT_ISSET(ops,'L') || OPT_ISSET(ops,'t'))) ||
-	(OPT_ISSET(ops,'L') && (OPT_ISSET(ops,'b') || OPT_ISSET(ops,'e')))) {
+				OPT_ISSET(ops,'L') || OPT_ISSET(ops,'t') ||
+				OPT_ISSET(ops,'m'))) ||
+	(OPT_ISSET(ops,'L') && (OPT_ISSET(ops,'b') || OPT_ISSET(ops,'e') ||
+				OPT_ISSET(ops,'m')))) {
 	zwarnnam(nam, "illegal option combination");
 	return 1;
     }
@@ -706,7 +725,8 @@
 	    return 2;
 
 	return (OPT_ISSET(ops,'r') ?
-		ptyread(nam, p, args + 1, OPT_ISSET(ops,'t')) :
+		ptyread(nam, p, args + 1, OPT_ISSET(ops,'t'),
+			OPT_ISSET(ops, 'm')) :
 		ptywrite(p, args + 1, OPT_ISSET(ops,'n')));
     } else if (OPT_ISSET(ops,'d')) {
 	Ptycmd p;
@@ -780,7 +800,7 @@
 
 
 static struct builtin bintab[] = {
-    BUILTIN("zpty", 0, bin_zpty, 0, -1, 0, "ebdrwLnt", NULL),
+    BUILTIN("zpty", 0, bin_zpty, 0, -1, 0, "ebdmrwLnt", NULL),
 };
 
 static struct features module_features = {
Index: Test/comptest
===================================================================
RCS file: /cvsroot/zsh/zsh/Test/comptest,v
retrieving revision 1.17
diff -u -r1.17 comptest
--- Test/comptest	12 Oct 2008 19:20:01 -0000	1.17
+++ Test/comptest	13 Jan 2009 11:44:24 -0000
@@ -80,7 +80,7 @@
 
   print -lr - "$@" > $tmp
   zpty -w zsh ". $tmp"
-  zpty -r zsh log_eval "*<PROMPT>*" || {
+  zpty -r -m zsh log_eval "*<PROMPT>*" || {
     print "prompt hasn't appeared."
     return 1
   }
@@ -90,7 +90,7 @@
 comptest () {
   input="$*"
   zpty -n -w zsh "$input"$'\C-Z'
-  zpty -r zsh log "*<WIDGET><finish>*<PROMPT>*" || {
+  zpty -r -m zsh log "*<WIDGET><finish>*<PROMPT>*" || {
     print "failed to invoke finish widget."
     return 1
   }


-- 
Peter Stephenson <pws@csr.com>                  Software Engineer
CSR PLC, Churchill House, Cambridge Business Park, Cowley Road
Cambridge, CB4 0WZ, UK                          Tel: +44 (0)1223 692070

Re: Test hang in Y01

[Peter Stephenson]

On Tue, 13 Jan 2009 12:00:11 +0000
Peter Stephenson <pws@csr.com> wrote:
> The following patch merely makes the test symptoms more sensible.  I hope
> this will allow someone to automate the search for the cause.

It was the patch in 26270 for accept-and-menu-complete: alas, as so often,
the memory status of variables in the completion system is somewhat
obscure.  I've backed this off.

Next time at least we might know a completion failure is a completion
failure.

-- 
Peter Stephenson <pws@csr.com>                  Software Engineer
CSR PLC, Churchill House, Cambridge Business Park, Cowley Road
Cambridge, CB4 0WZ, UK                          Tel: +44 (0)1223 692070