[PATCH] Ignore random output from Asan tests in dg-cmp-results

[PATCH] Ignore random output from Asan tests in dg-cmp-results

[Yuri Gribov]

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

Hi,

Currently dg-cmp-results fails to compare fails in Asan tests because
their output includes failing process id:
NA->FAIL: c-c++-common/asan/bitfield-1.c   -O0  output pattern test,
is ==18161==ERROR
FAIL->NA: c-c++-common/asan/bitfield-1.c   -O0  output pattern test,
is ==26667==ERROR

This patch fixes this. I also did some fairly standard refactoring to
improve stability and get rid of code dup.

Ok for trunk?

-Y

[-- Attachment #2: dg-cmp-results-asan-fix-1.patch --]
[-- Type: application/octet-stream, Size: 2428 bytes --]

2017-07-09  Yury Gribov  <tetra2005@gmail.com>

contrib/
        * dg-cmp-results.sh: Ignore random output from Asan tests.

diff -rupN gcc/contrib/dg-cmp-results.sh gcc-compare-checks/contrib/dg-cmp-results.sh
--- gcc/contrib/dg-cmp-results.sh	2017-07-09 07:41:13.000000000 +0200
+++ gcc-compare-checks/contrib/dg-cmp-results.sh	2017-07-09 18:58:52.000000000 +0200
@@ -1,5 +1,5 @@
-#!/bin/bash
-# Copyright (C) 2006, 2008 Free Software Foundation
+#!/bin/bash -eu
+# Copyright (C) 2006, 2008, 2017 Free Software Foundation
 #
 # Analyze changes in GCC DejaGNU test logs for binutils, gcc, gdb, etc.
 # Original version written in 2005 by James Lemke <jwlemke@wasabisystems.com>.
@@ -89,25 +89,29 @@ sed $E -e '/^[[:space:]]+===/,$d' $OFILE
 echo "Newer log file: $NFILE"
 sed $E -e '/^[[:space:]]+===/,$d' $NFILE
 
-# Create a temporary file from the old file's interesting section.
-sed $E -e "/$header/,/^[[:space:]]+===.*Summary ===/!d" \
-  -e '/^[A-Z]+:/!d' \
-  -e '/^(WARNING|ERROR):/d' \
-  -e 's/\r$//' \
-  -e 's/^/O:/' \
-  $OFILE |
-  sort -s -t : -k 3b - \
-  >/tmp/o$$-$OBASE
-
-# Create a temporary file from the new file's interesting section.
-sed $E -e "/$header/,/^[[:space:]]+===.*Summary ===/!d" \
-  -e '/^[A-Z]+:/!d' \
-  -e '/^(WARNING|ERROR):/d' \
-  -e 's/\r$//' \
-  -e 's/^/N:/' \
-  $NFILE |
-  sort -s -t : -k 3b - \
-  >/tmp/n$$-$NBASE
+O=/tmp/o$$-$OBASE
+N=/tmp/n$$-$NBASE
+
+trap "rm -f compare-$$.awk /tmp/o$$-$OBASE /tmp/n$$-$NBASE" EXIT
+
+# Create a temporary file from file's interesting section.
+get_interesting_lines() {
+  sed $E -e "/$header/,/^[[:space:]]+===.*Summary ===/!d" \
+      -e '/^[A-Z]+:/!d' \
+      -e '/^(WARNING|ERROR):/d' \
+      -e 's/\r$//' \
+      -e 's/^/'$1':/' \
+      | sort -s -t : -k 3b -
+}
+
+# Preprocess lines to avoid spurious differences
+canonize_lines() {
+  # For now just strip pid numbers from Asan messages
+  sed $E -e 's/(\/asan\/.* is ==)[0-9]+==/\1PID==/'
+}
+
+get_interesting_lines O < $OFILE | canonize_lines > $O
+get_interesting_lines N < $NFILE | canonize_lines > $N
 
 # Merge the two files, then compare adjacent lines.
 # Comparison is complicated by tests that may be run multiple times.
@@ -202,8 +206,3 @@ END {
 EOF
 sort -m -s -t : -k 3b /tmp/o$$-$OBASE /tmp/n$$-$NBASE |
  awk -v verbose=$verbose -f compare-$$.awk /dev/stdin
-
-# Delete the temporary files.
-rm -f compare-$$.awk /tmp/o$$-$OBASE /tmp/n$$-$NBASE
-
-exit 0

Re: [PATCH] Ignore random output from Asan tests in dg-cmp-results

[Thomas Preudhomme]

Hi Yuri,

On 09/07/17 20:06, Yuri Gribov wrote:
> Hi,
> 
> Currently dg-cmp-results fails to compare fails in Asan tests because
> their output includes failing process id:
> NA->FAIL: c-c++-common/asan/bitfield-1.c   -O0  output pattern test,
> is ==18161==ERROR
> FAIL->NA: c-c++-common/asan/bitfield-1.c   -O0  output pattern test,
> is ==26667==ERROR
> 
> This patch fixes this. I also did some fairly standard refactoring to
> improve stability and get rid of code dup.

I'm not familiar with asan but why not fix asan tests to not print the pid instead?

Best regards,

Thomas

Re: [PATCH] Ignore random output from Asan tests in dg-cmp-results

[Yuri Gribov]

On Mon, Jul 10, 2017 at 10:32 AM, Thomas Preudhomme
<thomas.preudhomme@foss.arm.com> wrote:
> Hi Yuri,
>
> On 09/07/17 20:06, Yuri Gribov wrote:
>>
>> Hi,
>>
>> Currently dg-cmp-results fails to compare fails in Asan tests because
>> their output includes failing process id:
>> NA->FAIL: c-c++-common/asan/bitfield-1.c   -O0  output pattern test,
>> is ==18161==ERROR
>> FAIL->NA: c-c++-common/asan/bitfield-1.c   -O0  output pattern test,
>> is ==26667==ERROR
>>
>> This patch fixes this. I also did some fairly standard refactoring to
>> improve stability and get rid of code dup.
>
>
> I'm not familiar with asan but why not fix asan tests to not print the pid
> instead?

The error message is printed by Asan runtime, not by tests themselves.
Asan maintainers are typically unwilling to change output format of
their messages as there may already be users who rely on it (e.g.
using specific regexes in their scripts, etc.).

Note that I'd very much rather fix the test (as I do in another patch
here: https://gcc.gnu.org/ml/gcc-patches/2017-07/msg00422.html).

-Y

Re: [PATCH] Ignore random output from Asan tests in dg-cmp-results

[Thomas Preudhomme]

[adding Mike Stump who approved my last patch to dg-cmp-results]

Hi Yuri,

On 09/07/17 20:06, Yuri Gribov wrote:
> Hi,
> 
> Currently dg-cmp-results fails to compare fails in Asan tests because
> their output includes failing process id:
> NA->FAIL: c-c++-common/asan/bitfield-1.c   -O0  output pattern test,
> is ==18161==ERROR
> FAIL->NA: c-c++-common/asan/bitfield-1.c   -O0  output pattern test,
> is ==26667==ERROR
> 
> This patch fixes this. I also did some fairly standard refactoring to
> improve stability and get rid of code dup.

While I welcome the hardening of dg-cmp-results you made, I think this would be 
better split out in a separate patch. Note though that I'm not maintainer so 
feel free to ignore me.

Other comments inline.

> 
> Ok for trunk?
> 
> -Y
> 
> 
> dg-cmp-results-asan-fix-1.patch
> 
> 
> 2017-07-09  Yury Gribov<tetra2005@gmail.com>
> 
> contrib/
>          * dg-cmp-results.sh: Ignore random output from Asan tests.
> 
> diff -rupN gcc/contrib/dg-cmp-results.sh gcc-compare-checks/contrib/dg-cmp-results.sh
> --- gcc/contrib/dg-cmp-results.sh	2017-07-09 07:41:13.000000000 +0200
> +++ gcc-compare-checks/contrib/dg-cmp-results.sh	2017-07-09 18:58:52.000000000 +0200
> @@ -1,5 +1,5 @@
> -#!/bin/bash
> -# Copyright (C) 2006, 2008 Free Software Foundation
> +#!/bin/bash -eu
> +# Copyright (C) 2006, 2008, 2017 Free Software Foundation
>   #
>   # Analyze changes in GCC DejaGNU test logs for binutils, gcc, gdb, etc.
>   # Original version written in 2005 by James Lemke<jwlemke@wasabisystems.com>.
> @@ -89,25 +89,29 @@ sed $E -e '/^[[:space:]]+===/,$d' $OFILE
>   echo "Newer log file: $NFILE"
>   sed $E -e '/^[[:space:]]+===/,$d' $NFILE
>   
> -# Create a temporary file from the old file's interesting section.
> -sed $E -e "/$header/,/^[[:space:]]+===.*Summary ===/!d" \
> -  -e '/^[A-Z]+:/!d' \
> -  -e '/^(WARNING|ERROR):/d' \
> -  -e 's/\r$//' \
> -  -e 's/^/O:/' \
> -  $OFILE |
> -  sort -s -t : -k 3b - \
> -  >/tmp/o$$-$OBASE
> -
> -# Create a temporary file from the new file's interesting section.
> -sed $E -e "/$header/,/^[[:space:]]+===.*Summary ===/!d" \
> -  -e '/^[A-Z]+:/!d' \
> -  -e '/^(WARNING|ERROR):/d' \
> -  -e 's/\r$//' \
> -  -e 's/^/N:/' \
> -  $NFILE |
> -  sort -s -t : -k 3b - \
> -  >/tmp/n$$-$NBASE
> +O=/tmp/o$$-$OBASE
> +N=/tmp/n$$-$NBASE
> +
> +trap "rm -f compare-$$.awk /tmp/o$$-$OBASE /tmp/n$$-$NBASE" EXIT

Why not use $O and $N here?

> +
> +# Create a temporary file from file's interesting section.
> +get_interesting_lines() {
> +  sed $E -e "/$header/,/^[[:space:]]+===.*Summary ===/!d" \
> +      -e '/^[A-Z]+:/!d' \
> +      -e '/^(WARNING|ERROR):/d' \
> +      -e 's/\r$//' \
> +      -e 's/^/'$1':/' \
> +      | sort -s -t : -k 3b -
> +}
> +
> +# Preprocess lines to avoid spurious differences
> +canonize_lines() {
> +  # For now just strip pid numbers from Asan messages
> +  sed $E -e 's/(\/asan\/.* is ==)[0-9]+==/\1PID==/'
> +}

I'd suggest to use @ as a separator for sed which will allow you to avoid the 
escaping of '/', ie. sed $E -e 's@(/asan/.* is ==)[0-9]+==@\1PID==@'

> +
> +get_interesting_lines O < $OFILE | canonize_lines > $O
> +get_interesting_lines N < $NFILE | canonize_lines > $N
>   
>   # Merge the two files, then compare adjacent lines.
>   # Comparison is complicated by tests that may be run multiple times.
> @@ -202,8 +206,3 @@ END {
>   EOF
>   sort -m -s -t : -k 3b /tmp/o$$-$OBASE /tmp/n$$-$NBASE |
>    awk -v verbose=$verbose -f compare-$$.awk /dev/stdin
> -
> -# Delete the temporary files.
> -rm -f compare-$$.awk /tmp/o$$-$OBASE /tmp/n$$-$NBASE
> -
> -exit 0

LGTM otherwise, but as I said this is not an approval to commit.

Best regards,

Thomas

Re: [PATCH] Ignore random output from Asan tests in dg-cmp-results

[Yuri Gribov]

On Mon, Jul 10, 2017 at 1:13 PM, Thomas Preudhomme
<thomas.preudhomme@foss.arm.com> wrote:
> [adding Mike Stump who approved my last patch to dg-cmp-results]
>
> Hi Yuri,
>
> On 09/07/17 20:06, Yuri Gribov wrote:
>>
>> Hi,
>>
>> Currently dg-cmp-results fails to compare fails in Asan tests because
>> their output includes failing process id:
>> NA->FAIL: c-c++-common/asan/bitfield-1.c   -O0  output pattern test,
>> is ==18161==ERROR
>> FAIL->NA: c-c++-common/asan/bitfield-1.c   -O0  output pattern test,
>> is ==26667==ERROR
>>
>> This patch fixes this. I also did some fairly standard refactoring to
>> improve stability and get rid of code dup.
>
>
> While I welcome the hardening of dg-cmp-results you made, I think this would
> be better split out in a separate patch. Note though that I'm not maintainer
> so feel free to ignore me.
>
> Other comments inline.
>
>>
>> Ok for trunk?
>>
>> -Y
>>
>>
>> dg-cmp-results-asan-fix-1.patch
>>
>>
>> 2017-07-09  Yury Gribov<tetra2005@gmail.com>
>>
>> contrib/
>>          * dg-cmp-results.sh: Ignore random output from Asan tests.
>>
>> diff -rupN gcc/contrib/dg-cmp-results.sh
>> gcc-compare-checks/contrib/dg-cmp-results.sh
>> --- gcc/contrib/dg-cmp-results.sh       2017-07-09 07:41:13.000000000
>> +0200
>> +++ gcc-compare-checks/contrib/dg-cmp-results.sh        2017-07-09
>> 18:58:52.000000000 +0200
>> @@ -1,5 +1,5 @@
>> -#!/bin/bash
>> -# Copyright (C) 2006, 2008 Free Software Foundation
>> +#!/bin/bash -eu
>> +# Copyright (C) 2006, 2008, 2017 Free Software Foundation
>>   #
>>   # Analyze changes in GCC DejaGNU test logs for binutils, gcc, gdb, etc.
>>   # Original version written in 2005 by James
>> Lemke<jwlemke@wasabisystems.com>.
>> @@ -89,25 +89,29 @@ sed $E -e '/^[[:space:]]+===/,$d' $OFILE
>>   echo "Newer log file: $NFILE"
>>   sed $E -e '/^[[:space:]]+===/,$d' $NFILE
>>   -# Create a temporary file from the old file's interesting section.
>> -sed $E -e "/$header/,/^[[:space:]]+===.*Summary ===/!d" \
>> -  -e '/^[A-Z]+:/!d' \
>> -  -e '/^(WARNING|ERROR):/d' \
>> -  -e 's/\r$//' \
>> -  -e 's/^/O:/' \
>> -  $OFILE |
>> -  sort -s -t : -k 3b - \
>> -  >/tmp/o$$-$OBASE
>> -
>> -# Create a temporary file from the new file's interesting section.
>> -sed $E -e "/$header/,/^[[:space:]]+===.*Summary ===/!d" \
>> -  -e '/^[A-Z]+:/!d' \
>> -  -e '/^(WARNING|ERROR):/d' \
>> -  -e 's/\r$//' \
>> -  -e 's/^/N:/' \
>> -  $NFILE |
>> -  sort -s -t : -k 3b - \
>> -  >/tmp/n$$-$NBASE
>> +O=/tmp/o$$-$OBASE
>> +N=/tmp/n$$-$NBASE
>> +
>> +trap "rm -f compare-$$.awk /tmp/o$$-$OBASE /tmp/n$$-$NBASE" EXIT
>
> Why not use $O and $N here?

Ah, will do.

>> +
>> +# Create a temporary file from file's interesting section.
>> +get_interesting_lines() {
>> +  sed $E -e "/$header/,/^[[:space:]]+===.*Summary ===/!d" \
>> +      -e '/^[A-Z]+:/!d' \
>> +      -e '/^(WARNING|ERROR):/d' \
>> +      -e 's/\r$//' \
>> +      -e 's/^/'$1':/' \
>> +      | sort -s -t : -k 3b -
>> +}
>> +
>> +# Preprocess lines to avoid spurious differences
>> +canonize_lines() {
>> +  # For now just strip pid numbers from Asan messages
>> +  sed $E -e 's/(\/asan\/.* is ==)[0-9]+==/\1PID==/'
>> +}
>
>
> I'd suggest to use @ as a separator for sed which will allow you to avoid
> the escaping of '/', ie. sed $E -e 's@(/asan/.* is ==)[0-9]+==@\1PID==@'

Right.

>> +
>> +get_interesting_lines O < $OFILE | canonize_lines > $O
>> +get_interesting_lines N < $NFILE | canonize_lines > $N
>>     # Merge the two files, then compare adjacent lines.
>>   # Comparison is complicated by tests that may be run multiple times.
>> @@ -202,8 +206,3 @@ END {
>>   EOF
>>   sort -m -s -t : -k 3b /tmp/o$$-$OBASE /tmp/n$$-$NBASE |
>>    awk -v verbose=$verbose -f compare-$$.awk /dev/stdin
>> -
>> -# Delete the temporary files.
>> -rm -f compare-$$.awk /tmp/o$$-$OBASE /tmp/n$$-$NBASE
>> -
>> -exit 0
>
>
> LGTM otherwise, but as I said this is not an approval to commit.
>
> Best regards,
>
> Thomas

Re: [PATCH] Ignore random output from Asan tests in dg-cmp-results

[Mike Stump]

On Jul 9, 2017, at 12:06 PM, Yuri Gribov <tetra2005@gmail.com> wrote:
> 
> Currently dg-cmp-results fails to compare fails in Asan tests because
> their output includes failing process id:
> NA->FAIL: c-c++-common/asan/bitfield-1.c   -O0  output pattern test,
> is ==18161==ERROR
> FAIL->NA: c-c++-common/asan/bitfield-1.c   -O0  output pattern test,
> is ==26667==ERROR
> 
> This patch fixes this. I also did some fairly standard refactoring to
> improve stability and get rid of code dup.
> 
> Ok for trunk?

I'd rather have this sorted out upstream of the compare utility.

Re: [PATCH] Ignore random output from Asan tests in dg-cmp-results

[Mike Stump]

On Jul 10, 2017, at 2:44 AM, Yuri Gribov <tetra2005@gmail.com> wrote:
> 
> On Mon, Jul 10, 2017 at 10:32 AM, Thomas Preudhomme
> <thomas.preudhomme@foss.arm.com> wrote:
>> Hi Yuri,
>> 
>> On 09/07/17 20:06, Yuri Gribov wrote:
>>> 
>>> Hi,
>>> 
>>> Currently dg-cmp-results fails to compare fails in Asan tests because
>>> their output includes failing process id:
>>> NA->FAIL: c-c++-common/asan/bitfield-1.c   -O0  output pattern test,
>>> is ==18161==ERROR
>>> FAIL->NA: c-c++-common/asan/bitfield-1.c   -O0  output pattern test,
>>> is ==26667==ERROR
>>> 
>>> This patch fixes this. I also did some fairly standard refactoring to
>>> improve stability and get rid of code dup.
>> 
>> 
>> I'm not familiar with asan but why not fix asan tests to not print the pid
>> instead?
> 
> The error message is printed by Asan runtime, not by tests themselves.
> Asan maintainers are typically unwilling to change output format of
> their messages as there may already be users who rely on it (e.g.
> using specific regexes in their scripts, etc.).

They don't have to change it.  There is a driver for asan tests in lib/asan-dg.exp that I believe has the code in it that causes this, and where the fix likely would be.

Indeed, in trunk, I see:

  fail "$testname output pattern test"

so, this looks like a local change in your tree.  Where does do the failing tests come from?  Change the failure line to fail "is_this_it", and see if the output is then deterministic; if so, you've identified the line.  Next, show us what is in your tree for that line; and we can tell you how it is wrong.

In this case, it feels like:

r205799 | rsandifo | 2013-12-09 00:04:57 -0800 (Mon, 09 Dec 2013) | 4 lines

gcc/testsuite/
        * lib/asan-dg.exp (asan-gtest): Remove expected output from the
        pass/fail line and add it to the log instead.


fixes the issue, but, for that to be the case, you'd have to have some really old unmaintained branch, or a bad copy of the file were the updates weren't also taken.  I've checked the results list, and certainly:

  https://gcc.gnu.org/ml/gcc-testresults/2017-07/msg00858.html

has the bad line, so  clearly something causes it.  [ searching ]

jit.exp has:

            fail "${executable-name} output pattern test, is ${output}, should match $texttmp"

bad, bad, bad line.  Try fixing this to just be:

            fail "${executable-name} output pattern test"

Not sure why fixes from 2013 never made it into that file.  If so, also update the pass line.

But, this raises the next interesting question.  Is this is jit test?  If not, jit is supposed to _undo_ all of it's changes to the environment.  I think it is leaking this routine into future unrelated test cases?  The jit people would have to chime in.  In the full log, if you run with -v, do you see:

  jit-run-executable:

just above the test case?  If so, and this isn't a jit test case, will confirm leakage.  If you run just the single .exp file this comes from, you can also tell if this is just leakage.  By running the single .exp file, (not jit.exp), if the output is then stable, then it is jit.exp likely leaking.

When I run with -j35, I don't see the ", " version of the test case name:

testsuite/gcc18/gcc.log:PASS: gcc.dg/pr67786.c output pattern test

in a check-gcc, but others do see the ", " version of the same test case:

FAIL: gcc.dg/pr67786.c output pattern test, is , should match 15

from https://gcc.gnu.org/ml/gcc-testresults/2017-07/msg00858.html.  One can run one in isolation like this:

$ make RUNTESTFLAGS='dg.exp=pr67786.c' check-gcc

$ grep 'output pattern' testsuite/gcc/gcc.log
PASS: gcc.dg/pr67786.c output pattern test

Someone with such a system will have to drill down into why.  Bill Seurer seems able to reliably see the problem as well, so you're not alone.  He is running dejagnu 1.5, I'm running 1.5.3, not sure if it is dejagnu related.  What version are you running?  You could try 1.5.3 and see if that fixes it.

My builds are without jit enabled.  Are you building with jit on?  What do you see for pr67786 in the full testsuite run?  When you run as above?

Re: [PATCH] Ignore random output from Asan tests in dg-cmp-results

[Mike Stump]

On Jul 10, 2017, at 2:21 PM, Mike Stump <mikestump@comcast.net> wrote:
> 
> Someone with such a system will have to drill down into why. 

Found it, fixed in dejagnu 1.5.3, just use a newer dejagnu, 1.5.3 or later should be fine.

Apparently, I should have just checked it _first_.  I didn't expect the fix to lie there.

Re: [PATCH] Ignore random output from Asan tests in dg-cmp-results

[Yuri Gribov]

On Mon, Jul 10, 2017 at 10:52 PM, Mike Stump <mikestump@comcast.net> wrote:
> On Jul 10, 2017, at 2:21 PM, Mike Stump <mikestump@comcast.net> wrote:
>>
>> Someone with such a system will have to drill down into why.
>
> Found it, fixed in dejagnu 1.5.3, just use a newer dejagnu, 1.5.3 or later should be fine.
>
> Apparently, I should have just checked it _first_.  I didn't expect the fix to lie there.

Thanks, Mike,

I didn't realize that the core issue is in Dejagnu. I believe Richard
fixed it in https://git.linaro.org/toolchain/dejagnu.git/commit/?h=dejagnu-1.5.3-release&id=a78bb783097d8a32dbaa0fe4f3a0d20297e5da15
, at the same time he fixed asan-gtest in GCC.

-Y