Re: acloca20 test intermittent failure

[Ralf Wildenhues]

[ http://lists.gnu.org/archive/html/bug-automake/2006-10/msg00026.html ]
[ http://lists.gnu.org/archive/html/bug-automake/2006-10/msg00036.html ]

Yeah, it's ancient... :-/

* Greg Schafer wrote on Tue, Oct 24, 2006 at 11:51:35PM CEST:
> On Tue, Oct 24, 2006 at 06:04:30PM +0200, Stepan Kasal wrote:
> 
> > I think I have found the bug now.
> 
> ...
> 
> > The fix is obvious: `autom4te' should always create the output file,
> > if --force was given.  Patch attached.
> > I committed it to the Autoconf CVS.
> > 
> > Greg, if you are willing to test the fix, then please build and
> > install CVS Autoconf or apply the patch to autoconf-2.60 and build
> > and install it.  Then apply Ralf's patch to acloca20.test (--force).
> > Then the test should pass.
> 
> Indeed it does! No failures at all now :-)

I have applied the patch from
.

Cheers,
Ralf

Re: acloca20 test intermittent failure

[Greg Schafer]

On Tue, Oct 24, 2006 at 06:04:30PM +0200, Stepan Kasal wrote:

> I think I have found the bug now.

...

> The fix is obvious: `autom4te' should always create the output file,
> if --force was given.  Patch attached.
> I committed it to the Autoconf CVS.
> 
> Greg, if you are willing to test the fix, then please build and
> install CVS Autoconf or apply the patch to autoconf-2.60 and build
> and install it.  Then apply Ralf's patch to acloca20.test (--force).
> Then the test should pass.

Indeed it does! No failures at all now :-)

Ralf's (first) patch is definitely required though..

Many thanks to both of you for figuring this one out.

Regards
Greg

Re: acloca20 test intermittent failure

[Stepan Kasal]

Hello Greg and Ralf,

I think I have found the bug now.

There were two suspects: aclocal and autoconf.

First, I tried to find out whether aclocal does its work correctly by
that unfortunate grep (should have been `grep acinclude aclocal.m4').

But then Greg posted the diff, and I had an idea: perhaps autoconf
does not refresh `configure', even though --force was given.

And indeed, this was the problem!

autoconf passes --force to autom4te.  autom4te then obediently
invalidates the cached output and runs m4 to create an updated one
and stores it to the cache.
But then it notices that the output file has the same time stamp as
the just computed output, and refrains from re-creating it.

The fix is obvious: `autom4te' should always create the output file,
if --force was given.  Patch attached.
I committed it to the Autoconf CVS.

Greg, if you are willing to test the fix, then please build and
install CVS Autoconf or apply the patch to autoconf-2.60 and build
and install it.  Then apply Ralf's patch to acloca20.test (--force).
Then the test should pass.

Have a nice day,
Stepan

---
Two side notes:

1) Ralf's patch decreased the failure rate, because there was more
work to do.  The bug hit only if the m4 run was finished in the same
second in which the old configure was created.

2)
On Tue, Oct 24, 2006 at 02:29:01PM +0200, Ralf Wildenhues wrote:
> Since we fixed autoconf/lib/autom4te.cfg in Autoconf 2.60, now when we
> call $ACLOCAL, the traces that were created by the $AUTOCONF before are
> sufficient; [...]

I think that this is not true.  aclocal uses language
`Autoconf-without-aclocal-m4', while autoconf uses language
`Autoconf'.  The languages use different lists of input files (the
former language does not include aclocal.m4), thus their caching
always stays disjoint.
2006-10-24  Stepan Kasal  <[EMAIL PROTECTED]>

* bin/autom4te.in: With --force, always refresh the output
file.  Problem reported by Greg Schafer <[EMAIL PROTECTED]>.

Index: bin/autom4te.in
===
RCS file: /cvsroot/autoconf/autoconf/bin/autom4te.in,v
retrieving revision 1.102
diff -u -r1.102 autom4te.in
--- bin/autom4te.in 16 Oct 2006 20:58:44 -  1.102
+++ bin/autom4te.in 24 Oct 2006 15:54:41 -
@@ -987,7 +987,7 @@
 # We now know whether we can trust the Request object.  Say it.
 verb "the trace request object is:\n" . $req->marshall;
 
-# We need to run M4 if (i) the users wants it (--force), (ii) $REQ is
+# We need to run M4 if (i) the user wants it (--force), (ii) $REQ is
 # invalid.
 handle_m4 ($req, keys %{$req->macro})
   if $force || ! $req->valid;
@@ -1026,10 +1026,10 @@
   }
 else
   {
-# Actual M4 expansion, only if $output is too old. STDOUT is
-# pretty old.
+# Actual M4 expansion, if the user wants it, or if $output is old
+# (STDOUT is pretty old).
 handle_output ($req, $output)
-  if mtime ($output) < mtime ($ocache . $req->id);
+  if $force || mtime ($output) < mtime ($ocache . $req->id);
   }
 
 # If we ran up to here, the cache is valid.

Re: acloca20 test intermittent failure

[Ralf Wildenhues]

* quoting myself:
> Since we fixed autoconf/lib/autom4te.cfg in Autoconf 2.60

The reasoning was wrong, the patch should still be right.
First, autoconf/lib/autom4te.in (sic) was fixed only after 2.60,
but second it was broken only for automake, not for aclocal.

So.  There you have it.  Now, 

> Does this make the failures go away?

Cheers,
Ralf

Re: acloca20 test intermittent failure

[Ralf Wildenhues]

Since we fixed autoconf/lib/autom4te.cfg in Autoconf 2.60, now when we
call $ACLOCAL, the traces that were created by the $AUTOCONF before are
sufficient; and since they appear with the same time stamp as all known
input files to aclocal.m4, they are used by autom4te.  So we have to
tell the autom4te invoked by aclocal that it has to do work.

The following $AUTOCONF should not need --force: it will know by way of
the updated autom4te/output.x file.

Does this make the failures go away?

Cheers,
Ralf

* tests/acloca20.test: Use `autom4te --force' with aclocal,
to force update on fast machines where the previous autoconf
invocation happened within the same second.
Report by Greg Schafer.

Index: tests/acloca20.test
===
RCS file: /cvs/automake/automake/tests/acloca20.test,v
retrieving revision 1.1
diff -u -r1.1 acloca20.test
--- tests/acloca20.test 19 Mar 2006 05:09:11 -  1.1
+++ tests/acloca20.test 24 Oct 2006 12:24:46 -
@@ -51,7 +51,7 @@
 sed 's/dnl //' configure.int
 mv -f configure.int configure.in
 
-$ACLOCAL
+AUTOM4TE="${AUTOM4TE-autom4te} --force" $ACLOCAL
 $AUTOCONF
 ./configure | grep 'right foo'
 grep 'wrong foo' foo.m4

Re: acloca20 test intermittent failure

[Greg Schafer]

On Tue, Oct 24, 2006 at 02:29:01PM +0200, Ralf Wildenhues wrote:
> Since we fixed autoconf/lib/autom4te.cfg in Autoconf 2.60, now when we
> call $ACLOCAL, the traces that were created by the $AUTOCONF before are
> sufficient; and since they appear with the same time stamp as all known
> input files to aclocal.m4, they are used by autom4te.  So we have to
> tell the autom4te invoked by aclocal that it has to do work.
> 
> The following $AUTOCONF should not need --force: it will know by way of
> the updated autom4te/output.x file.
> 
> Does this make the failures go away?

Still no dice I'm afraid :-(  Failure still happens intermittently..

Regards
Greg

Re: acloca20 test intermittent failure

[Greg Schafer]

On Tue, Oct 24, 2006 at 12:30:45PM +0200, Stepan Kasal wrote:
> I stared at the code for a while but I wasn't find other potential
> cause of the problem.  I would like to understand the cause of the
> problem, and thus I'd be grateful if you could perform some experiments
> to help us to find it.
> 
> When the failure appears even though Ralf's patch was applied, does
> the test fail at the same command (grep 'right foo') ?

Yes (AFAICT).

> If yes, then it seems that either aclocal or autoconf is failing.
> To find out which one, could you please try to reproduce the failure
> with the patch below?
> Does the failure appear at
>   grep 'ight foo' aclocal.m4
> or at
>   grep 'right foo'
> ?

I'm not sure whether your patch is correct because with it applied, it fails
100% of the time at
grep 'ight foo' aclocal.m4
I think you really meant acinclude.m4 instead of aclocal.m4 ?

Anyhow, if we ignore your patch for the time being, I think the following
diff of "testSubDir" between success and failure runs will make it clearer
where the failure is:


$ diff -ur testSubDir.good testSubDir
diff -ur testSubDir.good/config.log testSubDir/config.log
--- testSubDir.good/config.log  2006-10-24 21:39:47.0 +1000
+++ testSubDir/config.log   2006-10-24 21:50:55.0 +1000
@@ -48,7 +48,7 @@
 | test "$NLS" = N && { test "${enable_nls+set}" = set || enable_nls=no; }
 configure:1602: checking whether ln -s works
 configure:1606: result: yes
-configure:1746: creating ./config.status
+configure:1745: creating ./config.status
 
 ## -- ##
 ## Running config.status. ##
diff -ur testSubDir.good/configure testSubDir/configure
--- testSubDir.good/configure   2006-10-24 21:39:47.0 +1000
+++ testSubDir/configure2006-10-24 21:50:54.0 +1000
@@ -1610,7 +1610,6 @@
 echo "${ECHO_T}no, using $LN_S" >&6; }
 fi
 
-echo right foo
 ac_config_files="$ac_config_files doit"
 
 cat >confcache <<\_ACEOF


Regards
Greg

Re: acloca20 test intermittent failure

[Stepan Kasal]

Hello,

On Fri, Oct 20, 2006 at 07:45:44AM +1000, Greg Schafer wrote:
> On Thu, Oct 19, 2006 at 08:51:11AM +0200, Ralf Wildenhues wrote:
> > Out of curiosity: how fast is this machine, how many and what kind of
> > CPUs does it have?
> 
> Reasonably fast. 1 x AMD Athlon64 X2 4200+ (dual core).

well, my quick attempt to reproduce this on my oldish machine did not
work.

> The patch helps a little because the failures seem to happen less often but
> unfortunately they do still occur :-(

I stared at the code for a while but I wasn't find other potential
cause of the problem.  I would like to understand the cause of the
problem, and thus I'd be grateful if you could perform some experiments
to help us to find it.

When the failure appears even though Ralf's patch was applied, does
the test fail at the same command (grep 'right foo') ?

If yes, then it seems that either aclocal or autoconf is failing.
To find out which one, could you please try to reproduce the failure
with the patch below?
Does the failure appear at
grep 'ight foo' aclocal.m4
or at
grep 'right foo'
?

Thanks,
Stepan Kasal

Index: tests/acloca20.test
===
RCS file: /cvs/automake/automake/tests/acloca20.test,v
retrieving revision 1.1
diff -u -r1.1 acloca20.test
--- tests/acloca20.test 19 Mar 2006 05:09:11 -  1.1
+++ tests/acloca20.test 24 Oct 2006 10:27:48 -
@@ -52,6 +52,7 @@
 mv -f configure.int configure.in
 
 $ACLOCAL
-$AUTOCONF
+grep 'ight foo' aclocal.m4
+$AUTOCONF --force
 ./configure | grep 'right foo'
 grep 'wrong foo' foo.m4

Re: acloca20 test intermittent failure

[Ralf Wildenhues]

Hello Greg,

Thanks for the report.

* Greg Schafer wrote on Wed, Oct 18, 2006 at 09:37:26AM CEST:
> 
> I'm testing automake-1.10 on i686-pc-linux-gnu and seeing an intermittent
> failure of acloca20.test. It fails for me roughly 1 in 4 attempts, but then
> other times it will pass 10 times in a row. Here's the verbose output when
> it fails:

Out of curiosity: how fast is this machine, how many and what kind of
CPUs does it have?

> $ make check TESTS=acloca20.test VERBOSE=x
[...]
> + autoconf
> + ./configure
> + grep 'right foo'
> FAIL: acloca20.test

Could you please show the time stamps when the failure happens.  Like
this (in the tests subdirectory of the build tree):

$ while make check VERBOSE=x TESTS=acloca20.test; do :; done
$ ls -lart --time-style=full-iso testSubDir testSubDir/autom4te.cache

My assumption is that the second run of autoconf happens within the same
second as the first; if that is true, then the patch below should fix
this.  Could you try it?

Thanks,
Ralf

* tests/acloca20.test: Use `--force' with the second $AUTOCONF,
to force update on fast machines where both autoconf invocations
happen within the same second.
Report by Greg Schafer.

Index: tests/acloca20.test
===
RCS file: /cvs/automake/automake/tests/acloca20.test,v
retrieving revision 1.1
diff -u -r1.1 acloca20.test
--- tests/acloca20.test 19 Mar 2006 05:09:11 -  1.1
+++ tests/acloca20.test 19 Oct 2006 06:47:40 -
@@ -52,6 +52,6 @@
 mv -f configure.int configure.in
 
 $ACLOCAL
-$AUTOCONF
+$AUTOCONF --force
 ./configure | grep 'right foo'
 grep 'wrong foo' foo.m4

Re: acloca20 test intermittent failure

[Greg Schafer]

On Thu, Oct 19, 2006 at 08:51:11AM +0200, Ralf Wildenhues wrote:

> Out of curiosity: how fast is this machine, how many and what kind of
> CPUs does it have?

Reasonably fast. 1 x AMD Athlon64 X2 4200+ (dual core).

> Could you please show the time stamps when the failure happens.  Like
> this (in the tests subdirectory of the build tree):
> 
> $ while make check VERBOSE=x TESTS=acloca20.test; do :; done
> $ ls -lart --time-style=full-iso testSubDir testSubDir/autom4te.cache

$ ls -lart --time-style=full-iso testSubDir testSubDir/autom4te.cache
testSubDir/autom4te.cache:
total 292
-rw-r--r-- 1 pkgmgr pkgmgr 10126 2006-10-20 07:27:36.0 +1000 traces.2
-rw-r--r-- 1 pkgmgr pkgmgr 10072 2006-10-20 07:27:36.0 +1000 traces.1
-rw-r--r-- 1 pkgmgr pkgmgr 10072 2006-10-20 07:27:36.0 +1000 traces.0
-rw-r--r-- 1 pkgmgr pkgmgr 17323 2006-10-20 07:27:36.0 +1000 requests
-rw-r--r-- 1 pkgmgr pkgmgr 73015 2006-10-20 07:27:36.0 +1000 output.2
-rw-r--r-- 1 pkgmgr pkgmgr 73015 2006-10-20 07:27:36.0 +1000 output.1
-rw-r--r-- 1 pkgmgr pkgmgr 73000 2006-10-20 07:27:36.0 +1000 output.0
drwxr-xr-x 2 pkgmgr pkgmgr  4096 2006-10-20 07:27:36.0 +1000 .
drwxr-xr-x 3 pkgmgr pkgmgr  4096 2006-10-20 07:27:37.0 +1000 ..

testSubDir:
total 196
-rwxr-xr-x 1 pkgmgr pkgmgr 11135 2006-10-20 07:27:35.0 +1000 missing
-rwxr-xr-x 1 pkgmgr pkgmgr 13184 2006-10-20 07:27:35.0 +1000 install-sh
-rw-r--r-- 1 pkgmgr pkgmgr35 2006-10-20 07:27:35.0 +1000 foo.m4
-rw-r--r-- 1 pkgmgr pkgmgr25 2006-10-20 07:27:35.0 +1000 doit.in
-rwxr-xr-x 1 pkgmgr pkgmgr 17574 2006-10-20 07:27:35.0 +1000 depcomp
drwxr-xr-x 3 pkgmgr pkgmgr 16384 2006-10-20 07:27:35.0 +1000 ..
-rw-r--r-- 1 pkgmgr pkgmgr95 2006-10-20 07:27:36.0 +1000 
configure.in
-rwxr-xr-x 1 pkgmgr pkgmgr 72674 2006-10-20 07:27:36.0 +1000 configure
drwxr-xr-x 2 pkgmgr pkgmgr  4096 2006-10-20 07:27:36.0 +1000 
autom4te.cache
-rw-r--r-- 1 pkgmgr pkgmgr   612 2006-10-20 07:27:36.0 +1000 aclocal.m4
-rw-r--r-- 1 pkgmgr pkgmgr35 2006-10-20 07:27:36.0 +1000 
acinclude.m4
-rwxr-xr-x 1 pkgmgr pkgmgr24 2006-10-20 07:27:37.0 +1000 doit
-rwxr-xr-x 1 pkgmgr pkgmgr 20197 2006-10-20 07:27:37.0 +1000 
config.status
-rw-r--r-- 1 pkgmgr pkgmgr  3340 2006-10-20 07:27:37.0 +1000 config.log
drwxr-xr-x 3 pkgmgr pkgmgr  4096 2006-10-20 07:27:37.0 +1000 .

> My assumption is that the second run of autoconf happens within the same
> second as the first; if that is true, then the patch below should fix
> this.  Could you try it?

The patch helps a little because the failures seem to happen less often but
unfortunately they do still occur :-(

Regards
Greg