Issue with the reporting of failed tests

LTP Mason 3 participants 15 messages Apr 21, 2016 – Apr 26, 2016

lore

Share & tools

lore

Mason

author

2016-04-21 13:25 UTC #0 lore raw

Hello,

For a particular LTP run, I had 97 reported failures.

$ grep -c FAIL result-log.987
97

However, FAILCMDFILE contained 804 lines (with many duplicates).

$ wc -l result-failed.987
804 result-failed.987

$ sort result-failed.987 | uniq | wc -l
85

It seems some failures did not get recorded in FAILCMDFILE at all, or were recorded, but later overwritten:
aio01, aio02, cgroup, controllers, ext4*, fs_racer, Numa-testcases and some of the cron tests.

As discussed with metan on IRC, this has all the symptoms of a FILE buffer shared between parent and child process. I am now running LTP again with the following patch applied:

pan/ltp-pan.c +1 -0

index cee71aa3b587..44c026e88a47 100644
@@ -535,6 +535,7 @@ int main(int argc, char **argv)
                                break;
                        }
 
+                       fflush(failcmdfile);
                        cpid =
                            run_child(coll->ary[c], running + i, quiet_mode,
                                      &failcnt, fmt_print, logfile);

When the run finishes, I will be able to tell if the issue remains.

Regards.

Mason

author

2016-04-21 14:47 UTC #1 lore raw

Quoted 39 lines · Mason

Hello,
For a particular LTP run, I had 97 reported failures.
$ grep -c FAIL result-log.987
97
However, FAILCMDFILE contained 804 lines (with many duplicates).
$ wc -l result-failed.987
804 result-failed.987
$ sort result-failed.987 | uniq | wc -l
85
It seems some failures did not get recorded in FAILCMDFILE at all, or were recorded, but later overwritten:
aio01, aio02, cgroup, controllers, ext4*, fs_racer, Numa-testcases and some of the cron tests.
As discussed with metan on IRC, this has all the symptoms of a FILE buffer shared between parent and child process. I am now running LTP again with the following patch applied:
pan/ltp-pan.c +1 -0
index cee71aa3b587..44c026e88a47 100644
@@ -535,6 +535,7 @@ int main(int argc, char **argv)
                                break;
                        }
 
+                       fflush(failcmdfile);
                        cpid =
                            run_child(coll->ary[c], running + i, quiet_mode,
                                      &failcnt, fmt_print, logfile);

Quoted 1 line

When the run finishes, I will be able to tell if the issue remains.

Calling fflush does appear to solve the problem:

# grep -c FAIL result-log.5160
38

# wc -l result-failed.5160
38 result-failed.5160

Does this mean no one ever reads FAILCMDFILE?!

Regards.

Cyril Hrubis

2016-04-21 15:30 UTC #2 lore raw

Hi!

Quoted 9 lines

Calling fflush does appear to solve the problem:
# grep -c FAIL result-log.5160
38
# wc -l result-failed.5160
38 result-failed.5160
Does this mean no one ever reads FAILCMDFILE?!

Just to have complete image here. I've discussed this a bit more at #ltp irc channel and the reason why we do not see this bug often is that the exec() that is done by the child after pan forks must fail (for example since bash is missing) then the code proceeds to exit(errno) line which flushes the buffers on open files...

Signature · 2 lines

Cyril Hrubis
[email protected]

Mason

author

2016-04-21 15:42 UTC #3 lore raw

Quoted 9 lines · Cyril Hrubis

Hi!
Quoted 8 lines
Calling fflush does appear to solve the problem:
# grep -c FAIL result-log.5160
38
# wc -l result-failed.5160
38 result-failed.5160

Quoted 7 lines

Quoted 1 line
Does this mean no one ever reads FAILCMDFILE?!
Just to have complete image here. I've discussed this a bit more at #ltp irc channel and the reason why we do not see this bug often is that the exec() that is done by the child after pan forks must fail (for example since bash is missing) then the code proceeds to exit(errno) line which flushes the buffers on open files...

Note: in my latest LTP run, I disabled memory overcommit, and pan failed to launch several tests:

pan(5163): fork failed (tag proc01). errno:12 Cannot allocate memory pan(5163): fork failed (tag fs_racer). errno:12 Cannot allocate memory pan(5163): fork failed (tag quota_remount_test01). errno:12 Cannot allocate memory pan(5163): fork failed (tag isofs). errno:12 Cannot allocate memory pan(5163): fork failed (tag fs_perms01). errno:12 Cannot allocate memory [747 similar lines]

/tmp is a ramfs. Maybe something fills it up...

Regards.

Mason

author

2016-04-21 17:02 UTC #4 lore raw

Quoted 21 lines · Mason

Quoted 9 lines · Cyril Hrubis
Hi!
Quoted 8 lines
Calling fflush does appear to solve the problem:
# grep -c FAIL result-log.5160
38
# wc -l result-failed.5160
38 result-failed.5160
Quoted 7 lines
Quoted 1 line
Does this mean no one ever reads FAILCMDFILE?!
Just to have complete image here. I've discussed this a bit more at #ltp irc channel and the reason why we do not see this bug often is that the exec() that is done by the child after pan forks must fail (for example since bash is missing) then the code proceeds to exit(errno) line which flushes the buffers on open files...
Note: in my latest LTP run, I disabled memory overcommit, and pan failed to launch several tests:

Quoted 8 lines

pan(5163): fork failed (tag proc01). errno:12 Cannot allocate memory pan(5163): fork failed (tag fs_racer). errno:12 Cannot allocate memory pan(5163): fork failed (tag quota_remount_test01). errno:12 Cannot allocate memory pan(5163): fork failed (tag isofs). errno:12 Cannot allocate memory pan(5163): fork failed (tag fs_perms01). errno:12 Cannot allocate memory [747 similar lines]
/tmp is a ramfs. Maybe something fills it up...

With overcommit enabled, all tests complete, but some problems remain:

$ grep -c FAIL result-log.24583 
85

$ wc -l result-failed.24583
157 result-failed.24583

$ sort result-failed.24583 | uniq | wc -l
83

I'm confused as to what else is causing this...

Regards.

Mason

author

2016-04-21 18:59 UTC #5 lore raw

Quoted 36 lines · Mason

Quoted 21 lines · Mason
Quoted 9 lines · Cyril Hrubis
Hi!
Quoted 8 lines
Calling fflush does appear to solve the problem:
# grep -c FAIL result-log.5160
38
# wc -l result-failed.5160
38 result-failed.5160
Quoted 7 lines
Quoted 1 line
Does this mean no one ever reads FAILCMDFILE?!
Just to have complete image here. I've discussed this a bit more at #ltp irc channel and the reason why we do not see this bug often is that the exec() that is done by the child after pan forks must fail (for example since bash is missing) then the code proceeds to exit(errno) line which flushes the buffers on open files...
Note: in my latest LTP run, I disabled memory overcommit, and pan failed to launch several tests:
Quoted 8 lines
pan(5163): fork failed (tag proc01). errno:12 Cannot allocate memory pan(5163): fork failed (tag fs_racer). errno:12 Cannot allocate memory pan(5163): fork failed (tag quota_remount_test01). errno:12 Cannot allocate memory pan(5163): fork failed (tag isofs). errno:12 Cannot allocate memory pan(5163): fork failed (tag fs_perms01). errno:12 Cannot allocate memory [747 similar lines]
/tmp is a ramfs. Maybe something fills it up...
With overcommit enabled, all tests complete, but some problems remain:
$ grep -c FAIL result-log.24583 
85

Quoted 7 lines

$ wc -l result-failed.24583
157 result-failed.24583
$ sort result-failed.24583 | uniq | wc -l
83
I'm confused as to what else is causing this...

Maybe metan was right, and we must also flush tconfcmdfile? Will test next week.

Regards.

Mason

author

2016-04-22 13:29 UTC #6 lore raw

In reply to Mason

Quoted 36 lines · Mason

Quoted 21 lines · Mason
Quoted 9 lines · Cyril Hrubis
Hi!
Quoted 8 lines
Calling fflush does appear to solve the problem:
# grep -c FAIL result-log.5160
38
# wc -l result-failed.5160
38 result-failed.5160
Quoted 7 lines
Quoted 1 line
Does this mean no one ever reads FAILCMDFILE?!
Just to have complete image here. I've discussed this a bit more at #ltp irc channel and the reason why we do not see this bug often is that the exec() that is done by the child after pan forks must fail (for example since bash is missing) then the code proceeds to exit(errno) line which flushes the buffers on open files...
Note: in my latest LTP run, I disabled memory overcommit, and pan failed to launch several tests:
Quoted 8 lines
pan(5163): fork failed (tag proc01). errno:12 Cannot allocate memory pan(5163): fork failed (tag fs_racer). errno:12 Cannot allocate memory pan(5163): fork failed (tag quota_remount_test01). errno:12 Cannot allocate memory pan(5163): fork failed (tag isofs). errno:12 Cannot allocate memory pan(5163): fork failed (tag fs_perms01). errno:12 Cannot allocate memory [747 similar lines]
/tmp is a ramfs. Maybe something fills it up...
With overcommit enabled, all tests complete, but some problems remain:
$ grep -c FAIL result-log.24583 
85

Quoted 7 lines

$ wc -l result-failed.24583
157 result-failed.24583
$ sort result-failed.24583 | uniq | wc -l
83
I'm confused as to what else is causing this...

I am now testing yet another LTP run with the following patch applied.

pan/ltp-pan.c +3 -1

index cee71aa3b587..ceaa56c5a21d 100644
@@ -949,6 +949,8 @@ run_child(struct coll_entry *colle, struct tag_pgrp *active, int quiet_mode,
                if (!quiet_mode)
                        write_test_start(active);
 
+       fflush(NULL); /* flush all open output streams before forking */
+
        if ((cpid = fork()) == -1) {
                fprintf(stderr,
                        "pan(%s): fork failed (tag %s).  errno:%d  %s\n",

@@ -1042,7 +1044,7 @@ run_child(struct coll_entry *colle, struct tag_pgrp *active, int quiet_mode,
                }
                WRITE_OR_DIE(errpipe[1], &errlen, sizeof(errlen));
                WRITE_OR_DIE(errpipe[1], errbuf, errlen);
-               exit(errno);
+               _exit(errno); /* terminate "immediately" */
        }
 
        /* parent */

Mason

author

2016-04-25 08:04 UTC #7 lore raw

Quoted 40 lines · Mason

Quoted 39 lines · Mason
Quoted 21 lines · Mason
Quoted 9 lines · Cyril Hrubis
Hi!
Quoted 8 lines
Calling fflush does appear to solve the problem:
# grep -c FAIL result-log.5160
38
# wc -l result-failed.5160
38 result-failed.5160
Quoted 7 lines
Quoted 1 line
Does this mean no one ever reads FAILCMDFILE?!
Just to have complete image here. I've discussed this a bit more at #ltp irc channel and the reason why we do not see this bug often is that the exec() that is done by the child after pan forks must fail (for example since bash is missing) then the code proceeds to exit(errno) line which flushes the buffers on open files...
Note: in my latest LTP run, I disabled memory overcommit, and pan failed to launch several tests:
Quoted 8 lines
pan(5163): fork failed (tag proc01). errno:12 Cannot allocate memory pan(5163): fork failed (tag fs_racer). errno:12 Cannot allocate memory pan(5163): fork failed (tag quota_remount_test01). errno:12 Cannot allocate memory pan(5163): fork failed (tag isofs). errno:12 Cannot allocate memory pan(5163): fork failed (tag fs_perms01). errno:12 Cannot allocate memory [747 similar lines]
/tmp is a ramfs. Maybe something fills it up...
With overcommit enabled, all tests complete, but some problems remain:
$ grep -c FAIL result-log.24583 
85
$ wc -l result-failed.24583
157 result-failed.24583

Quoted 6 lines

Quoted 4 lines
$ sort result-failed.24583 | uniq | wc -l
83
I'm confused as to what else is causing this...
I am now testing yet another LTP run with the following patch applied.

There still is an inconsistency between result-log and result-failed.

$ grep -c FAIL result-log.30032
119

$ wc -l result-failed.30032
319 result-failed.30032

$ sort result-failed.30032 | uniq | wc -l
117

Either I didn't use the modified ltp-pan binary, or the change has no effect. (I will print something to stderr to make sure.)

Regards.

Mason

author

2016-04-25 11:40 UTC #8 lore raw

Quoted 53 lines · Mason

Quoted 40 lines · Mason
Quoted 39 lines · Mason
Quoted 21 lines · Mason
Quoted 9 lines · Cyril Hrubis
Hi!
Quoted 8 lines
Calling fflush does appear to solve the problem:
# grep -c FAIL result-log.5160
38
# wc -l result-failed.5160
38 result-failed.5160
Quoted 7 lines
Quoted 1 line
Does this mean no one ever reads FAILCMDFILE?!
Just to have complete image here. I've discussed this a bit more at #ltp irc channel and the reason why we do not see this bug often is that the exec() that is done by the child after pan forks must fail (for example since bash is missing) then the code proceeds to exit(errno) line which flushes the buffers on open files...
Note: in my latest LTP run, I disabled memory overcommit, and pan failed to launch several tests:
Quoted 8 lines
pan(5163): fork failed (tag proc01). errno:12 Cannot allocate memory pan(5163): fork failed (tag fs_racer). errno:12 Cannot allocate memory pan(5163): fork failed (tag quota_remount_test01). errno:12 Cannot allocate memory pan(5163): fork failed (tag isofs). errno:12 Cannot allocate memory pan(5163): fork failed (tag fs_perms01). errno:12 Cannot allocate memory [747 similar lines]
/tmp is a ramfs. Maybe something fills it up...
With overcommit enabled, all tests complete, but some problems remain:
$ grep -c FAIL result-log.24583 
85
$ wc -l result-failed.24583
157 result-failed.24583
Quoted 6 lines
Quoted 4 lines
$ sort result-failed.24583 | uniq | wc -l
83
I'm confused as to what else is causing this...
I am now testing yet another LTP run with the following patch applied.
There still is an inconsistency between result-log and result-failed.
$ grep -c FAIL result-log.30032
119

Quoted 8 lines

$ wc -l result-failed.30032
319 result-failed.30032
$ sort result-failed.30032 | uniq | wc -l
117
Either I didn't use the modified ltp-pan binary, or the change has no effect. (I will print something to stderr to make sure.)

I do see an improvement now: no more duplicates. However, it seems 2 tests are missing from result-failed: aio01, aio02.

$ grep -c FAIL result-log.1125
27

$ wc -l result-failed.1125
25 result-failed.1125

Regards.

Mason

author

2016-04-25 12:46 UTC #9 lore raw

Quoted 57 lines · Mason

Quoted 56 lines · Mason
Quoted 40 lines · Mason
Quoted 39 lines · Mason
Quoted 21 lines · Mason
Quoted 9 lines · Cyril Hrubis
Hi!
Quoted 8 lines
Calling fflush does appear to solve the problem:
# grep -c FAIL result-log.5160
38
# wc -l result-failed.5160
38 result-failed.5160
Quoted 7 lines
Quoted 1 line
Does this mean no one ever reads FAILCMDFILE?!
Just to have complete image here. I've discussed this a bit more at #ltp irc channel and the reason why we do not see this bug often is that the exec() that is done by the child after pan forks must fail (for example since bash is missing) then the code proceeds to exit(errno) line which flushes the buffers on open files...
Note: in my latest LTP run, I disabled memory overcommit, and pan failed to launch several tests:
Quoted 8 lines
pan(5163): fork failed (tag proc01). errno:12 Cannot allocate memory pan(5163): fork failed (tag fs_racer). errno:12 Cannot allocate memory pan(5163): fork failed (tag quota_remount_test01). errno:12 Cannot allocate memory pan(5163): fork failed (tag isofs). errno:12 Cannot allocate memory pan(5163): fork failed (tag fs_perms01). errno:12 Cannot allocate memory [747 similar lines]
/tmp is a ramfs. Maybe something fills it up...
With overcommit enabled, all tests complete, but some problems remain:
$ grep -c FAIL result-log.24583 
85
$ wc -l result-failed.24583
157 result-failed.24583
Quoted 6 lines
Quoted 4 lines
$ sort result-failed.24583 | uniq | wc -l
83
I'm confused as to what else is causing this...
I am now testing yet another LTP run with the following patch applied.
There still is an inconsistency between result-log and result-failed.
$ grep -c FAIL result-log.30032
119
$ wc -l result-failed.30032
319 result-failed.30032

Quoted 8 lines

Quoted 5 lines
$ sort result-failed.30032 | uniq | wc -l
117
Either I didn't use the modified ltp-pan binary, or the change has no effect. (I will print something to stderr to make sure.)
I do see an improvement now: no more duplicates. However, it seems 2 tests are missing from result-failed: aio01, aio02.

These two tests are not being built.
FILTER_OUT_DIRS := $(if $(AIO_LIBS),,aio ltp-aiodio)

so pan fails to launch them, obviously.
pan(1130): execvp of 'aio01' (tag aio01) failed. errno:2 No such file or directory pan(1130): execvp of 'aio_tio' (tag aio02) failed. errno:2 No such file or directory

I don't think these should be considered failures?

Regards.

Cyril Hrubis

2016-04-25 13:31 UTC #10 lore raw

Hi!

Quoted 8 lines

These two tests are not being built.
FILTER_OUT_DIRS := $(if $(AIO_LIBS),,aio ltp-aiodio)
so pan fails to launch them, obviously.
pan(1130): execvp of 'aio01' (tag aio01) failed. errno:2 No such file or directory pan(1130): execvp of 'aio_tio' (tag aio02) failed. errno:2 No such file or directory
I don't think these should be considered failures?

I guess that we should report TCONF if test binary was missing instead. I can try to prototype a patch for this, but I would preffer doing that after release.

Signature · 2 lines

Cyril Hrubis
[email protected]

Mason

author

2016-04-25 14:24 UTC #11 lore raw

Quoted 8 lines · Cyril Hrubis

Hi!
Quoted 7 lines
These two tests are not being built.
FILTER_OUT_DIRS := $(if $(AIO_LIBS),,aio ltp-aiodio)
so pan fails to launch them, obviously.
pan(1130): execvp of 'aio01' (tag aio01) failed. errno:2 No such file or directory pan(1130): execvp of 'aio_tio' (tag aio02) failed. errno:2 No such file or directory

Quoted 5 lines

Quoted 1 line
I don't think these should be considered failures?
I guess that we should report TCONF if test binary was missing instead. I can try to prototype a patch for this, but I would prefer doing that after release.

OK.

Similar issue with fanotify.

Some tests are correctly marked TCONF, but some FAIL because of TWARN.

fanotify01    1  TCONF  :  fanotify01.c:348: fanotify is not configured in this kernel.
fanotify01    2  TCONF  :  fanotify01.c:348: Remaining cases not appropriate for configuration
fanotify01    0  TWARN  :  fanotify01.c:359: close(-1) failed

fanotify02    1  TCONF  :  fanotify02.c:237: fanotify is not configured in this kernel.
fanotify02    2  TCONF  :  fanotify02.c:237: Remaining cases not appropriate for configuration
fanotify02    0  TWARN  :  fanotify02.c:248: close(-1) failed

fanotify04    1  TCONF  :  fanotify04.c:280: fanotify is not configured in this kernel.
fanotify04    2  TCONF  :  fanotify04.c:280: Remaining cases not appropriate for configuration
fanotify04    0  TWARN  :  fanotify04.c:291: close(-1) failed

Also the mq_* tests FAIL instead of TCONF.

mq_notify01    0  TINFO  :  (case00) START
mq_notify01    1  TFAIL  :  mq_notify01.c:206: mq_open failed: TEST_ERRNO=ENOSYS(38): Function not implemented

As do several netns_* tests.

netns_breakns_ns_exec_ipv6_netlink 1 TINFO : ns_create 0 TINFO : ltp_clone_quick: errno=EINVAL(22): Invalid argument
netns_breakns_ns_exec_ipv6_netlink 1 TBROK : unable to create a new network namespace

Regards.

Cyril Hrubis

2016-04-25 14:46 UTC #12 lore raw

Hi!

Quoted 8 lines

Similar issue with fanotify.

Some tests are correctly marked TCONF, but some FAIL because of TWARN.

fanotify01    1  TCONF  :  fanotify01.c:348: fanotify is not configured in this kernel.
fanotify01    2  TCONF  :  fanotify01.c:348: Remaining cases not appropriate for configuration
fanotify01    0  TWARN  :  fanotify01.c:359: close(-1) failed

Quoted 7 lines

fanotify02    1  TCONF  :  fanotify02.c:237: fanotify is not configured in this kernel.
fanotify02    2  TCONF  :  fanotify02.c:237: Remaining cases not appropriate for configuration
fanotify02    0  TWARN  :  fanotify02.c:248: close(-1) failed

fanotify04    1  TCONF  :  fanotify04.c:280: fanotify is not configured in this kernel.
fanotify04    2  TCONF  :  fanotify04.c:280: Remaining cases not appropriate for configuration
fanotify04    0  TWARN  :  fanotify04.c:291: close(-1) failed

These should have been fixed in:

commit 2d8cac4caeb21ae8e5426b7c839bd5ff3896bd37

Author: Cyril Hrubis <[email protected]>
Date:   Tue Mar 15 12:52:41 2016 +0100

syscalls/fanotify: Fix clenaups

Not to call close(-1) in cleanup when the test exits with TCONF.

Quoted 4 lines

Also the mq_* tests FAIL instead of TCONF.

mq_notify01    0  TINFO  :  (case00) START
mq_notify01    1  TFAIL  :  mq_notify01.c:206: mq_open failed: TEST_ERRNO=ENOSYS(38): Function not implemented

Looks like nobody has run the tests with CONFIG_POSIX_MQUEUE missing from .config, this should be easy to fix.

Quoted 4 lines

As do several netns_* tests.
netns_breakns_ns_exec_ipv6_netlink 1 TINFO : ns_create 0 TINFO : ltp_clone_quick: errno=EINVAL(22): Invalid argument
netns_breakns_ns_exec_ipv6_netlink 1 TBROK : unable to create a new network namespace

These should be fixed as well.

Signature · 2 lines

Cyril Hrubis
[email protected]

Sebastian Frias

2016-04-26 09:51 UTC #13 lore raw

[LTP] getrusage04 on ARM fails sometimes

Hi,

We are wondering if other people have issues with getrusage04 LTP test. We see it failing sometimes on our ARM platform.
It seems to happen most often when CONFIG_HZ=300 than when CONFIG_HZ=100.

When the test was introduced (https://sourceforge.net/p/ltp/mailman/message/27853271/) it did not support the "-m" parameter, which is meant to broaden the "acceptance" interval. The "-m" parameter was added by people from ST (fd875256d6f99102e3940c4dfc6b0a8a27f4d62c), so presumably working on embedded (probably ARM) systems. Some people are increasing that interval (https://ez.analog.com/docs/DOC-9111).

Also, according to the commit history, the test is disabled on QEMU, Xen and other environments.

Questions:
1) Does anybody else using ARM has issues with this test? Or is it just us?
2) Do you suggest that we increase the "-m" parameter?
3) Do you know of another test that could be used to double check that getrusage04 failure is a false positive?

Thanks, regards,

Sebastian

Cyril Hrubis

2016-04-25 13:04 UTC #14 lore raw

In reply to Mason

Hi!

Quoted 2 lines

I do see an improvement now: no more duplicates. However, it seems 2 tests are missing from result-failed: aio01, aio02.

I've tested that fflush(NULL) is enough to fix this and pushed patch with just that. Thanks.

Signature · 2 lines

Cyril Hrubis
[email protected]