New issue
Advanced search Search tips

Issue 746775 link

Starred by 1 user

Issue metadata

Status: Fixed
Owner:
Closed: Jul 2017
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Fuchsia
Pri: 1
Type: Bug

Blocking:
issue 738275
issue 741194



Sign in to add a comment

Process::WaitForExitOrTimeout mistakenly treats |timeout| as absolute, not now-relative.

Project Member Reported by w...@chromium.org, Jul 20 2017

Issue description

Running the command:

out/gnDebug/bin/run_base_unittests --gtest_filter=*TestTraceFlush*  --gtest_repeat=100

leads to the second repeat run of the test causing TestLauncher to start reporting failures once per second:

[00006.574] 03624.03664> Note: Google Test filter = TraceEventTestFixture.TestTraceFlush
[00006.577] 03624.03664> [==========] Running 1 test from 1 test case.
[00006.577] 03624.03664> [----------] Global test environment set-up.
[00006.579] 03624.03664> [----------] 1 test from TraceEventTestFixture
[00006.581] 03624.03664> [ RUN      ] TraceEventTestFixture.TestTraceFlush
[00019.771] 02542.02841> Still waiting for the following processes to finish:
[00019.772] 02542.02841> /system/base_unittests --gtest_filter=*TestTraceFlush* --gtest_flagfile=/tmp/.org.chromium.Chromium.aDnNKi/.org.chromium.Chromium.kMeMOg --single-process-tests --test-launcher-output=/tmp/.org.chromium.Chromium.jilond/test_r
[00019.772] 02542.02841> esults.xml --test-launcher-retry-limit=0 --test-launcher-timeout=90000
[00034.773] 02542.02841> Still waiting for the following processes to finish:
[00034.773] 02542.02841> /system/base_unittests --gtest_filter=*TestTraceFlush* --gtest_flagfile=/tmp/.org.chromium.Chromium.aDnNKi/.org.chromium.Chromium.kMeMOg --single-process-tests --test-launcher-output=/tmp/.org.chromium.Chromium.jilond/test_r
[00034.773] 02542.02841> esults.xml --test-launcher-retry-limit=0 --test-launcher-timeout=90000
[00049.774] 02542.02841> Still waiting for the following processes to finish:
[00049.775] 02542.02841> /system/base_unittests --gtest_filter=*TestTraceFlush* --gtest_flagfile=/tmp/.org.chromium.Chromium.aDnNKi/.org.chromium.Chromium.kMeMOg --single-process-tests --test-launcher-output=/tmp/.org.chromium.Chromium.jilond/test_r
[00049.775] 02542.02841> esults.xml --test-launcher-retry-limit=0 --test-launcher-timeout=90000
[00063.489] 03624.03664> [       OK ] TraceEventTestFixture.TestTraceFlush (56903 ms)
[00063.491] 03624.03664> [----------] 1 test from TraceEventTestFixture (56909 ms total)
[00063.491] 03624.03664> 
[00063.491] 03624.03664> [----------] Global test environment tear-down
[00063.493] 03624.03664> [==========] 1 test from 1 test case ran. (56918 ms total)
[00063.493] 03624.03664> [  PASSED  ] 1 test.
[00063.821] 02542.02841> [1/1] TraceEventTestFixture.TestTraceFlush (56903 ms)
[00063.822] 02542.02841> SUCCESS: all tests passed.
[00065.202] 18150.18177> Note: Google Test filter = TraceEventTestFixture.TestTraceFlush
[00065.204] 18150.18177> [==========] Running 1 test from 1 test case.
[00065.204] 18150.18177> [----------] Global test environment set-up.
[00065.205] 18150.18177> [----------] 1 test from TraceEventTestFixture
[00065.206] 18150.18177> [ RUN      ] TraceEventTestFixture.TestTraceFlush
[00078.821] 02542.02841> Still waiting for the following processes to finish:
[00078.822] 02542.02841> /system/base_unittests --gtest_filter=*TestTraceFlush* --gtest_flagfile=/tmp/.org.chromium.Chromium.aDnNKi/.org.chromium.Chromium.OcmEdL --single-process-tests --test-launcher-output=/tmp/.org.chromium.Chromium.jpCEFD/test_r
[00078.822] 02542.02841> esults.xml --test-launcher-retry-limit=0 --test-launcher-timeout=90000
[00090.133] 02542.02841> [1/1] TraceEventTestFixture.TestTraceFlush (TIMED OUT)
[00090.134] 02542.02841> 1 test timed out:
[00090.134] 02542.02841>     TraceEventTestFixture.TestTraceFlush (../../base/trace_event/trace_event_unittest.cc:1373)
[00090.433] 02542.02841> Failed to get out-of-band test success data, dumping full stdio below:
[00090.433] 02542.02841> 
[00090.433] 02542.02841> [1/1] TraceEventTestFixture.TestTraceFlush (UNKNOWN)
[00090.433] 02542.02841> 1 test had unknown result:
[00090.433] 02542.02841>     TraceEventTestFixture.TestTraceFlush (../../base/trace_event/trace_event_unittest.cc:1373)
[00090.739] 02542.02841> Failed to get out-of-band test success data, dumping full stdio below:
[00090.739] 02542.02841> 
[00090.739] 02542.02841> [1/1] TraceEventTestFixture.TestTraceFlush (UNKNOWN)
[00090.739] 02542.02841> 1 test had unknown result:
[00090.739] 02542.02841>     TraceEventTestFixture.TestTraceFlush (../../base/trace_event/trace_event_unittest.cc:1373)
[00091.045] 02542.02841> Failed to get out-of-band test success data, dumping full stdio below:
[00091.045] 02542.02841> 
[00091.045] 02542.02841> [1/1] TraceEventTestFixture.TestTraceFlush (UNKNOWN)
[00091.045] 02542.02841> 1 test had unknown result:
[00091.045] 02542.02841>     TraceEventTestFixture.TestTraceFlush (../../base/trace_event/trace_event_unittest.cc:1373)
[00091.051] 02037.02708> dlsvc: msg write error: -24: MX_ERR_PEER_CLOSED
[00091.359] 02542.02841> Failed to get out-of-band test success data, dumping full stdio below:
[00091.359] 02542.02841> 

 

Comment 1 by w...@chromium.org, Jul 20 2017

Status: Started (was: Assigned)
It appears that this is caused by the Process::WaitForExitOrTimeout() call passing the |timeout| to mx_object_wait_one(), rather than passing the desired deadline. The TestLauncher therefore ends up in a busy wait, continuously re-launching the sub-process, and immediately tearing it down again.

Comment 2 by w...@chromium.org, Jul 20 2017

Summary: Process::WaitForExitOrTimeout mistakenly treats |timeout| as absolute, not now-relative. (was: TestTraceFlush causes test-launcher misbehaviour if run repeatedly)
Project Member

Comment 3 by bugdroid1@chromium.org, Jul 20 2017

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/e1b867e61251a23b415c43a338956967eb17d1ce

commit e1b867e61251a23b415c43a338956967eb17d1ce
Author: Wez <wez@chromium.org>
Date: Thu Jul 20 21:11:53 2017

Fix WaitForExitOrTimeout to pass deadline to mx_object_wait_one().

Previously the |timeout| duration was being passed as the deadline,
leading to the wait operation timing out as soon as Fuchsia's total
up-time exceeded it. Any subsequent waits on process termination would
then timeout instantly.

This had the effect that any unit-test fixture that took longer than
the per-batch timeout (less the Fuchsia boot timer under the test-
runner) to complete would always fail, with UNKNOWN RESULT for tests
from all later batches.

Bug:  746775 , 738275
Change-Id: I89b6d03f58caffe602bbf37a921b3bd20c09cee2
Reviewed-on: https://chromium-review.googlesource.com/578699
Reviewed-by: Kevin Marshall <kmarshall@chromium.org>
Commit-Queue: Wez <wez@chromium.org>
Cr-Commit-Position: refs/heads/master@{#488406}
[modify] https://crrev.com/e1b867e61251a23b415c43a338956967eb17d1ce/base/process/process_fuchsia.cc

Comment 4 by w...@chromium.org, Jul 20 2017

Status: Fixed (was: Started)

Comment 5 by w...@chromium.org, Jul 22 2017

Cc: w...@chromium.org
 Issue 745855  has been merged into this issue.

Sign in to add a comment