New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 664872 link

Starred by 1 user

Issue metadata

Status: Fixed
Owner:
Closed: May 2017
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Android
Pri: 3
Type: Bug



Sign in to add a comment

JavaCronetEngine is flaky in CronetUrlRequestTest#testThrowOrCancelInOnCanceled

Project Member Reported by xunji...@chromium.org, Nov 14 2016

Issue description

This test is flaky when running with JavaCronetEngine.

"CronetTestBase.java:143" indicates that this test failed when running with JavaCronetEngine.


https://build.chromium.org/p/chromium.android/builders/Android%20Cronet%20Lollipop%20Builder/builds/3962/steps/cronet_test_instrumentation_apk/logs/stdio

C  161.534s Main  [FAIL] org.chromium.net.CronetUrlRequestTest#testThrowOrCancelInOnCanceled:
C  161.534s Main  java.lang.Throwable: CronetTestBase#runTest failed.
C  161.534s Main  	at org.chromium.net.CronetTestBase.runTest(CronetTestBase.java:146)
C  161.535s Main  	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:191)
C  161.535s Main  	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:176)
C  161.535s Main  	at android.test.InstrumentationTestRunner.onStart(InstrumentationTestRunner.java:555)
C  161.535s Main  	at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1853)
C  161.535s Main  Caused by: junit.framework.AssertionFailedError: expected:<ON_CANCELED> but was:<ON_FAILED>
C  161.535s Main  	at org.chromium.net.CronetUrlRequestTest.testThrowOrCancelInOnCanceled(CronetUrlRequestTest.java:1787)
C  161.535s Main  	at org.chromium.net.CronetTestBase.runTest(CronetTestBase.java:143)
C  161.535s Main  	... 9 more
 

Comment 1 by clm@google.com, Nov 14 2016

What's the error it fails with?
logcat can be obtained from 
https://build.chromium.org/p/chromium.android/builders/Android%20Cronet%20Lollipop%20Builder/builds/3962/

Under "gsutil upload " step.

I am attaching it here.
logcat_dumps%2FAndroid Cronet Lollipop Builder%2F3962
16.2 MB Download

Comment 3 by clm@google.com, Nov 15 2016

Can we change the assert to include the exception that caused the request to enter the error state?
I will add some more logging.
Project Member

Comment 5 by bugdroid1@chromium.org, Nov 17 2016

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

commit 7acfe39937220b608b8dc8314c14f0e6604c8021
Author: kapishnikov <kapishnikov@chromium.org>
Date: Thu Nov 17 16:03:02 2016

Instrument CronetUrlRequestTest#testThrowOrCancelInOnCanceled flaky test

Also, add toString method to UrlRequestException.

BUG= 664872 

Review-Url: https://codereview.chromium.org/2506653003
Cr-Commit-Position: refs/heads/master@{#432884}

[modify] https://crrev.com/7acfe39937220b608b8dc8314c14f0e6604c8021/components/cronet/android/api/src/org/chromium/net/UrlRequestException.java
[modify] https://crrev.com/7acfe39937220b608b8dc8314c14f0e6604c8021/components/cronet/android/test/javatests/src/org/chromium/net/BidirectionalStreamTest.java
[modify] https://crrev.com/7acfe39937220b608b8dc8314c14f0e6604c8021/components/cronet/android/test/javatests/src/org/chromium/net/CronetTestBase.java
[modify] https://crrev.com/7acfe39937220b608b8dc8314c14f0e6604c8021/components/cronet/android/test/javatests/src/org/chromium/net/CronetUrlRequestContextTest.java
[modify] https://crrev.com/7acfe39937220b608b8dc8314c14f0e6604c8021/components/cronet/android/test/javatests/src/org/chromium/net/CronetUrlRequestTest.java
[modify] https://crrev.com/7acfe39937220b608b8dc8314c14f0e6604c8021/components/cronet/android/test/javatests/src/org/chromium/net/TestUrlRequestCallback.java
[modify] https://crrev.com/7acfe39937220b608b8dc8314c14f0e6604c8021/components/cronet/android/test/javatests/src/org/chromium/net/UploadDataProvidersTest.java

Example recent failure: https://uberchromegw.corp.google.com/i/chromium.android/builders/Android%20Cronet%20Marshmallow%2064bit%20Perf/builds/3958

I  240.523s run_tests_on_device(00bebe3061e6bdcf)  detected failure in org.chromium.net.CronetUrlRequestTest#testThrowOrCancelInOnCanceled. raw output:
I  240.523s run_tests_on_device(00bebe3061e6bdcf)    INSTRUMENTATION_STATUS: numtests=1
I  240.524s run_tests_on_device(00bebe3061e6bdcf)    INSTRUMENTATION_STATUS: stream=
I  240.524s run_tests_on_device(00bebe3061e6bdcf)    org.chromium.net.CronetUrlRequestTest:
I  240.524s run_tests_on_device(00bebe3061e6bdcf)    INSTRUMENTATION_STATUS: id=InstrumentationTestRunner
I  240.524s run_tests_on_device(00bebe3061e6bdcf)    INSTRUMENTATION_STATUS: test=testThrowOrCancelInOnCanceled
I  240.524s run_tests_on_device(00bebe3061e6bdcf)    INSTRUMENTATION_STATUS: class=org.chromium.net.CronetUrlRequestTest
I  240.524s run_tests_on_device(00bebe3061e6bdcf)    INSTRUMENTATION_STATUS: current=1
I  240.524s run_tests_on_device(00bebe3061e6bdcf)    INSTRUMENTATION_STATUS_CODE: 1
I  240.524s run_tests_on_device(00bebe3061e6bdcf)    INSTRUMENTATION_RESULT: shortMsg=java.lang.NullPointerException
I  240.524s run_tests_on_device(00bebe3061e6bdcf)    INSTRUMENTATION_RESULT: longMsg=java.lang.NullPointerException: Attempt to write to field 'com.android.okhttp.okio.Segment com.android.okhttp.okio.Segment.next' on a null object reference
I  240.524s run_tests_on_device(00bebe3061e6bdcf)    INSTRUMENTATION_CODE: 0
Status: Untriaged (was: Available)
Thanks twellington@ for finding a flaky run. 

I am marking this Untriaged so it is in Cronet triager's queue.
This flake was caused by a different reason. Here is the relevant stack trace:

6bdcf:  --------- beginning of crash
6bdcf:  12-14 17:03:48.644 15805 15830 E AndroidRuntime: FATAL EXCEPTION: JavaCronetEngine
6bdcf:  12-14 17:03:48.644 15805 15830 E AndroidRuntime: Process: org.chromium.net, PID: 15805
6bdcf:  12-14 17:03:48.644 15805 15830 E AndroidRuntime: java.lang.NullPointerException: Attempt to write to field 'com.android.okhttp.okio.Segment com.android.okhttp.okio.Segment.next' on a null object reference
6bdcf:  12-14 17:03:48.644 15805 15830 E AndroidRuntime: 	at com.android.okhttp.okio.Segment.pop(Segment.java:82)
6bdcf:  12-14 17:03:48.644 15805 15830 E AndroidRuntime: 	at com.android.okhttp.okio.Buffer.skip(Buffer.java:780)
6bdcf:  12-14 17:03:48.644 15805 15830 E AndroidRuntime: 	at com.android.okhttp.okio.Buffer.clear(Buffer.java:762)
6bdcf:  12-14 17:03:48.644 15805 15830 E AndroidRuntime: 	at com.android.okhttp.internal.Util.skipAll(Util.java:177)
6bdcf:  12-14 17:03:48.644 15805 15830 E AndroidRuntime: 	at com.android.okhttp.internal.Util.discard(Util.java:158)
6bdcf:  12-14 17:03:48.644 15805 15830 E AndroidRuntime: 	at com.android.okhttp.internal.http.HttpConnection$FixedLengthSource.close(HttpConnection.java:435)
6bdcf:  12-14 17:03:48.644 15805 15830 E AndroidRuntime: 	at com.android.okhttp.okio.RealBufferedSource.close(RealBufferedSource.java:374)
6bdcf:  12-14 17:03:48.644 15805 15830 E AndroidRuntime: 	at com.android.okhttp.okio.RealBufferedSource$1.close(RealBufferedSource.java:362)
6bdcf:  12-14 17:03:48.644 15805 15830 E AndroidRuntime: 	at org.chromium.net.impl.InputStreamChannel.close(InputStreamChannel.java:72)
6bdcf:  12-14 17:03:48.644 15805 15830 E AndroidRuntime: 	at org.chromium.net.impl.JavaUrlRequest$13.run(JavaUrlRequest.java:924)
6bdcf:  12-14 17:03:48.644 15805 15830 E AndroidRuntime: 	at org.chromium.net.impl.JavaUrlRequest$1$1.run(JavaUrlRequest.java:160)
6bdcf:  12-14 17:03:48.644 15805 15830 E AndroidRuntime: 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1113)
6bdcf:  12-14 17:03:48.644 15805 15830 E AndroidRuntime: 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:588)
6bdcf:  12-14 17:03:48.644 15805 15830 E AndroidRuntime: 	at org.chromium.net.impl.JavaCronetEngine$1$1.run(JavaCronetEngine.java:55)
6bdcf:  12-14 17:03:48.644 15805 15830 E AndroidRuntime: 	at java.lang.Thread.run(Thread.java:818)
6bdcf:  12-14 17:03:48.647   920 10283 W ActivityManager: Error in app org.chromium.net running instrumentation ComponentInfo{org.chromium.net.tests/android.test.InstrumentationTestRunner}:
6bdcf:  12-14 17:03:48.647   920 10283 W ActivityManager:   java.lang.NullPointerException
6bdcf:  12-14 17:03:48.647   920 10283 W ActivityManager:   java.lang.NullPointerException: Attempt to write to field 'com.android.okhttp.okio.Segment com.android.okhttp.okio.Segment.next' on a null object reference
6bdcf:  12-14 17:03:48.648 15797 15797 D AndroidRuntime: Shutting down VM

It looks like a concurrency issue.

Relevant okhttp source: https://android.googlesource.com/platform/external/okhttp/+/6d3859960e52daf10b48b4d0ce45b011fa27f3a7/okio/okio/src/main/java/okio/Segment.java
logcat_dumps%2FAndroid Cronet Marshmallow 64bit Perf%2F3958
4.7 MB View Download
Charles, do you have any ideas on this?  Are we careful to only access the OkHttp (system HttlURLConnection impl) stuff from just the executor's thread?
I spent some time trying to fix this.  Here are my ideas:
1. Break the CANCELLED state in JavaUrlRequest into CANCELLING and CANCELLED.  cancel() immediately transitions to CANCELLING, and if we're waiting on the user code (e.g. we're in AWAITING_READ or AWAITING_FOLLOW_REDIRECT) we can immediately transition to CANCELLED (via mState.compareAndSet(State.CANCELLING, State.CANCELLED)), otherwise if transitionState() fails because the state is currently CANCELLING, it can transition to CANCELLED and complete the cancelation (i.e. by calling onCancelled).  This got pretty tricky however because of the number of state transitions...
2. Charles had the idea of using a serializing executor.  If I'm not mistaken, currently the executor used by JavaUrlRequest is backed by a limitless pool of threads, which means theoretically if two tasks are posted to the executor, they may execute simultaneously.  We sequence the tasks with compareAndSets of mState.  That's why I thought adding the CANCELLING state was a good idea.  Anyhow, we could wrap the executor we're given in one that serializes tasks.
3. What about the really simply solution of just putting synchronized blocks around the three places that access the HttpURLConnection?  This has the effect of serializing them.

Comment 11 by clm@google.com, Jan 5 2017

Option 3 is certainly the easiest, but it's not just interactions with HttpUrlConnection we need to synchronize, we also need to guard interactions with the inputstream/outputstream we open from it. One advantage of using a SerializingExecutor vs the lock is that we get better thread utilization - holding a lock while calling read() could block other threads (admittedly, the ones in our unbounded pool) for a long time. 

SerializingExecutor doesn't have this problem because it'll queue rather than block, and as a bonus we get control over how the queue works - so we can do things like post our call to close() (triggered by cancellation) to the start of the queue, potentially avoiding work done by other operations.

Comment 12 by mef@chromium.org, Jan 10 2017

Owner: pauljensen@chromium.org
Status: Assigned (was: Untriaged)
Project Member

Comment 13 by bugdroid1@chromium.org, Jan 12 2017

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

commit 16325c0ba632bc13701728830fe14a873ef8ab53
Author: pauljensen <pauljensen@chromium.org>
Date: Thu Jan 12 18:52:56 2017

[Cronet] In JavaUrlRequest avoid thread-unsafe access to HttpURLConnection

Executor passed into JavaUrlRequest is backed by a thread-pool so it can
concurrently run tasks which can lead to crashes in underlying
HttpURLConnection.  Prevent this by serializing taskes passed to
underlying Executor.

BUG= 664872 
CQ_INCLUDE_TRYBOTS=master.tryserver.chromium.android:android_cronet_tester

Review-Url: https://codereview.chromium.org/2613393002
Cr-Commit-Position: refs/heads/master@{#443307}

[modify] https://crrev.com/16325c0ba632bc13701728830fe14a873ef8ab53/components/cronet/android/BUILD.gn
[modify] https://crrev.com/16325c0ba632bc13701728830fe14a873ef8ab53/components/cronet/android/java/src/org/chromium/net/impl/JavaUrlRequest.java

Status: Fixed (was: Assigned)

Sign in to add a comment