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

Issue 751700 link

Starred by 1 user
Status: Fixed
Owner:
█ xunji...@chromium.org
Last visit > 30 days ago
Closed: Aug 2017
Components:
EstimatedDays: ----
NextAction: ----
OS: Android
Pri: 2
Type: Bug



Sign in to add a comment

BidirectionalStreamTest.testFlushData flakes

Project Member Reported by pauljensen@chromium.org, Aug 2 2017 
This test, when run in another testing environment seems to fail about 10% of the time.  I believe it's more or less the only flaking test left.

The failures always look the same:
After about 1m45s a java.util.concurrent.TimeoutException is thrown.
A thread dump at the time of timeout shows the test thread stuck here:

    java.lang.Object.wait(Native Method)
    android.os.ConditionVariable.block(ConditionVariable.java:97)
    org.chromium.net.TestBidirectionalStreamCallback.blockForDone(TestBidirectionalStreamCallback.java:141)
    org.chromium.net.BidirectionalStreamTest.testFlushData(BidirectionalStreamTest.java:383)
    java.lang.reflect.Method.invoke(Native Method)
    junit.framework.TestCase.runTest(TestCase.java:168)
    org.chromium.net.CronetTestBase.runTest(CronetTestBase.java:186)

The three netty threads look like they're waiting.

Logcat looks like this:

08-01 15:42:23.959  4847  4886 I TestRunner: run started: 1 tests
08-01 15:42:23.961  4847  4886 I TestRunner: started: testFlushData(org.chromium.net.BidirectionalStreamTest)
08-01 15:42:23.968  4847  4847 I MonitoringInstr: Activities that are still in CREATED to STOPPED: 0
08-01 15:42:24.050  4847  4852 I art     : Do partial code cache collection, code=28KB, data=24KB
08-01 15:42:24.050  4847  4852 I art     : After code cache collection, code=28KB, data=24KB
08-01 15:42:24.050  4847  4852 I art     : Increasing code cache capacity to 128KB
08-01 15:42:24.128  4847  4884 D NativeLibraryUtils: Install completed successfully. count=12 extracted=0
08-01 15:42:24.155  4847  4886 I cr_CronetLibraryLoader: Cronet version: 60.0.3112.78, arch: i686
08-01 15:42:24.161  4864  4864 D PhenotypeChimeraService: onCreate
08-01 15:42:24.211  4864  4912 D GetConfigurationSnapshotOperation: byFlagStorageType, addSet = Flag(Ulr__ble_enable_batch_scanner, false, 2, 0), Flag(Ulr__ble_enable_location_aware_scanner, true, 2, 0), Flag(Ulr__ble_nearby_max_duration_millis, 1440000, 1, 0), Flag(Ulr__enable_clearcut_testcodes, true, 2, 0), Flag(Ulr__enable_confirmed_home_placefencing, false, 2, 0), Flag(Ulr__enable_confirmed_work_placefencing, false, 2, 0), Flag(Ulr__enable_wifi_triggered_placefencing, false, 2, 0), Flag(Ulr__location_sample_default_millis, 120000, 1, 0), Flag(Ulr__moving_latency_millis, 600000, 1, 0), Flag(Ulr__placefencing_nearby_alert_radius, 0, 1, 0), Flag(Ulr__wifi_triggered_latency_millis, 180000, 1, 0)
08-01 15:42:24.211  4864  4912 D GetConfigurationSnapshotOperation: byFlagStorageType, deleteSet = 
08-01 15:42:24.269  4847  4887 D DropBoxEntryAddedChimeraService: User is not opted-in to Usage & Diagnostics or Lockbox.
08-01 15:42:24.609  4847  4926 I LoggingHandler: [id: 0x406f7329] REGISTERED
08-01 15:42:24.610  4847  4926 I LoggingHandler: [id: 0x406f7329] BIND: ::/:::8443
08-01 15:42:24.610  4847  4925 I cr_Http2TestServer: Netty HTTP/2 server started on https://127.0.0.1:8443
08-01 15:42:24.615  4847  4926 I LoggingHandler: [id: 0x406f7329, L:/:::8443] ACTIVE
08-01 15:42:24.620  4847  4926 I LoggingHandler: [id: 0x406f7329, L:/:::8443] RECEIVED: [id: 0xa165f4ea, L:/127.0.0.1:8443 - R:/127.0.0.1:49977]
08-01 15:42:24.684  4847  4927 I Http2TestHandler: 
08-01 15:42:24.684  4847  4927 I Http2TestHandler: ----------------OUTBOUND--------------------
08-01 15:42:24.684  4847  4927 I Http2TestHandler: [id: 0xa165f4ea, L:/127.0.0.1:8443 - R:/127.0.0.1:49977] SETTINGS: ack=false, settings={MAX_HEADER_LIST_SIZE=8192}
08-01 15:42:24.684  4847  4927 I Http2TestHandler: ------------------------------------
08-01 15:42:24.688  4847  4927 I Http2TestHandler: 
08-01 15:42:24.688  4847  4927 I Http2TestHandler: ----------------INBOUND--------------------
08-01 15:42:24.688  4847  4927 I Http2TestHandler: [id: 0xa165f4ea, L:/127.0.0.1:8443 - R:/127.0.0.1:49977] SETTINGS: ack=false, settings={HEADER_TABLE_SIZE=65536, MAX_CONCURRENT_STREAMS=1000, INITIAL_WINDOW_SIZE=6291456}
08-01 15:42:24.688  4847  4927 I Http2TestHandler: ------------------------------------
08-01 15:42:24.688  4847  4927 I Http2TestHandler: 
08-01 15:42:24.688  4847  4927 I Http2TestHandler: ----------------OUTBOUND--------------------
08-01 15:42:24.688  4847  4927 I Http2TestHandler: [id: 0xa165f4ea, L:/127.0.0.1:8443 - R:/127.0.0.1:49977] SETTINGS: ack=true
08-01 15:42:24.688  4847  4927 I Http2TestHandler: ------------------------------------
08-01 15:42:24.689  4847  4927 I Http2TestHandler: 
08-01 15:42:24.689  4847  4927 I Http2TestHandler: ----------------INBOUND--------------------
08-01 15:42:24.689  4847  4927 I Http2TestHandler: [id: 0xa165f4ea, L:/127.0.0.1:8443 - R:/127.0.0.1:49977] WINDOW_UPDATE: streamId=0, windowSizeIncrement=15663105
08-01 15:42:24.689  4847  4927 I Http2TestHandler: ------------------------------------
08-01 15:42:24.692  4847  4927 I Http2TestHandler: 
08-01 15:42:24.692  4847  4927 I Http2TestHandler: ----------------INBOUND--------------------
08-01 15:42:24.692  4847  4927 I Http2TestHandler: [id: 0xa165f4ea, L:/127.0.0.1:8443 - R:/127.0.0.1:49977] SETTINGS: ack=true
08-01 15:42:24.692  4847  4927 I Http2TestHandler: ------------------------------------
08-01 15:42:24.697  4847  4927 I Http2TestHandler: 
08-01 15:42:24.697  4847  4927 I Http2TestHandler: ----------------INBOUND--------------------
08-01 15:42:24.697  4847  4927 I Http2TestHandler: [id: 0xa165f4ea, L:/127.0.0.1:8443 - R:/127.0.0.1:49977] HEADERS: streamId=1, headers=DefaultHttp2Headers[:method: POST, :authority: 127.0.0.1:8443, :scheme: https, :path: /echostream, foo: bar, empty: , content-type: zebra, user-agent: com.google.android.gms/11648478 (Linux; U; Android 7.0; en_US; Nexus 6 (Android); Build/LRX09D; Cronet/60.0.3112.78)], streamDependency=0, weight=220, exclusive=true, padding=0, endStream=false
08-01 15:42:24.697  4847  4927 I Http2TestHandler: ------------------------------------
08-01 15:42:24.698  4847  4927 I Http2TestHandler: 
08-01 15:42:24.698  4847  4927 I Http2TestHandler: ----------------OUTBOUND--------------------
08-01 15:42:24.698  4847  4927 I Http2TestHandler: [id: 0xa165f4ea, L:/127.0.0.1:8443 - R:/127.0.0.1:49977] HEADERS: streamId=1, headers=DefaultHttp2Headers[:status: 200, echo-foo: bar, echo-empty: , echo-content-type: zebra, echo-user-agent: com.google.android.gms/11648478 (Linux; U; Android 7.0; en_US; Nexus 6 (Android); Build/LRX09D; Cronet/60.0.3112.78), echo-method: POST], streamDependency=0, weight=16, exclusive=false, padding=0, endStream=false
08-01 15:42:24.698  4847  4927 I Http2TestHandler: ------------------------------------
08-01 15:42:24.705  4847  4927 I Http2TestHandler: 
08-01 15:42:24.705  4847  4927 I Http2TestHandler: ----------------INBOUND--------------------
08-01 15:42:24.705  4847  4927 I Http2TestHandler: [id: 0xa165f4ea, L:/127.0.0.1:8443 - R:/127.0.0.1:49977] DATA: streamId=1, padding=0, endStream=false, length=3, bytes=313233
08-01 15:42:24.705  4847  4927 I Http2TestHandler: ------------------------------------
08-01 15:42:24.707  4847  4927 I Http2TestHandler: 
08-01 15:42:24.707  4847  4927 I Http2TestHandler: ----------------OUTBOUND--------------------
08-01 15:42:24.707  4847  4927 I Http2TestHandler: [id: 0xa165f4ea, L:/127.0.0.1:8443 - R:/127.0.0.1:49977] DATA: streamId=1, padding=0, endStream=false, length=3, bytes=313233
08-01 15:42:24.707  4847  4927 I Http2TestHandler: ------------------------------------
08-01 15:42:24.708  4847  4927 I Http2TestHandler: 
08-01 15:42:24.708  4847  4927 I Http2TestHandler: ----------------INBOUND--------------------
08-01 15:42:24.708  4847  4927 I Http2TestHandler: [id: 0xa165f4ea, L:/127.0.0.1:8443 - R:/127.0.0.1:49977] DATA: streamId=1, padding=0, endStream=false, length=2, bytes=3435
08-01 15:42:24.708  4847  4927 I Http2TestHandler: ------------------------------------
08-01 15:42:24.709  4847  4927 I Http2TestHandler: 
08-01 15:42:24.709  4847  4927 I Http2TestHandler: ----------------OUTBOUND--------------------
08-01 15:42:24.709  4847  4927 I Http2TestHandler: [id: 0xa165f4ea, L:/127.0.0.1:8443 - R:/127.0.0.1:49977] DATA: streamId=1, padding=0, endStream=false, length=2, bytes=3435
08-01 15:42:24.709  4847  4927 I Http2TestHandler: ------------------------------------
08-01 15:42:24.711  4847  4927 I Http2TestHandler: 
08-01 15:42:24.711  4847  4927 I Http2TestHandler: ----------------INBOUND--------------------
08-01 15:42:24.711  4847  4927 I Http2TestHandler: [id: 0xa165f4ea, L:/127.0.0.1:8443 - R:/127.0.0.1:49977] DATA: streamId=1, padding=0, endStream=true, length=1, bytes=36
08-01 15:42:24.711  4847  4927 I Http2TestHandler: ------------------------------------
08-01 15:42:24.712  4847  4927 I Http2TestHandler: 
08-01 15:42:24.712  4847  4927 I Http2TestHandler: ----------------OUTBOUND--------------------
08-01 15:42:24.712  4847  4927 I Http2TestHandler: [id: 0xa165f4ea, L:/127.0.0.1:8443 - R:/127.0.0.1:49977] DATA: streamId=1, padding=0, endStream=true, length=1, bytes=36
08-01 15:42:24.712  4847  4927 I Http2TestHandler: ------------------------------------
08-01 15:42:29.280  4864  4864 D PhenotypeChimeraService: onDestroy
08-01 15:43:03.859  4864  4864 E NetworkScheduler.SIR: GcmNetworkManager unavailable.

Comment 1 by xunji...@chromium.org, Aug 2 2017

Cc: -xunji...@chromium.org
Owner: xunji...@chromium.org
Status: Assigned (was: Available)
Thanks Paul. I will take a look.

Comment 2 by pauljensen@chromium.org, Aug 2 2017 

I should mention that in the other testing environment, the device runs very quickly.

For comparison, here's the logcat I see when I successfully run the test locally:

08-02 11:27:14.404 19689 19718 I LoggingHandler: [id: 0x9f886334] REGISTERED
08-02 11:27:14.405 19689 19718 I LoggingHandler: [id: 0x9f886334] BIND: ::/:::8443
08-02 11:27:14.405 19689 19717 I cr_X    : Netty HTTP/2 server started on https://127.0.0.1:8443
08-02 11:27:14.406 19689 19718 I LoggingHandler: [id: 0x9f886334, L:/:::8443] ACTIVE
08-02 11:27:14.408 19689 19718 I LoggingHandler: [id: 0x9f886334, L:/:::8443] RECEIVED: [id: 0x419d8afc, L:/127.0.0.1:8443 - R:/127.0.0.1:53744]
08-02 11:27:14.442 19689 19719 I org.chromium.net.W: 
08-02 11:27:14.442 19689 19719 I org.chromium.net.W: ----------------OUTBOUND--------------------
08-02 11:27:14.442 19689 19719 I org.chromium.net.W: [id: 0x419d8afc, L:/127.0.0.1:8443 - R:/127.0.0.1:53744] SETTINGS: ack=false, settings={MAX_HEADER_LIST_SIZE=8192}
08-02 11:27:14.442 19689 19719 I org.chromium.net.W: ------------------------------------
08-02 11:27:14.444 19689 19719 I org.chromium.net.W: 
08-02 11:27:14.444 19689 19719 I org.chromium.net.W: ----------------INBOUND--------------------
08-02 11:27:14.444 19689 19719 I org.chromium.net.W: [id: 0x419d8afc, L:/127.0.0.1:8443 - R:/127.0.0.1:53744] SETTINGS: ack=false, settings={HEADER_TABLE_SIZE=65536, MAX_CONCURRENT_STREAMS=1000, INITIAL_WINDOW_SIZE=6291456, MAX_HEADER_LIST_SIZE=262144}
08-02 11:27:14.444 19689 19719 I org.chromium.net.W: ------------------------------------
08-02 11:27:14.445 19689 19719 I org.chromium.net.W: 
08-02 11:27:14.445 19689 19719 I org.chromium.net.W: ----------------OUTBOUND--------------------
08-02 11:27:14.445 19689 19719 I org.chromium.net.W: [id: 0x419d8afc, L:/127.0.0.1:8443 - R:/127.0.0.1:53744] SETTINGS: ack=true
08-02 11:27:14.445 19689 19719 I org.chromium.net.W: ------------------------------------
08-02 11:27:14.445 19689 19719 I org.chromium.net.W: 
08-02 11:27:14.445 19689 19719 I org.chromium.net.W: ----------------INBOUND--------------------
08-02 11:27:14.445 19689 19719 I org.chromium.net.W: [id: 0x419d8afc, L:/127.0.0.1:8443 - R:/127.0.0.1:53744] WINDOW_UPDATE: streamId=0, windowSizeIncrement=15663105
08-02 11:27:14.445 19689 19719 I org.chromium.net.W: ------------------------------------
08-02 11:27:14.449 19689 19719 I org.chromium.net.W: 
08-02 11:27:14.449 19689 19719 I org.chromium.net.W: ----------------INBOUND--------------------
08-02 11:27:14.449 19689 19719 I org.chromium.net.W: [id: 0x419d8afc, L:/127.0.0.1:8443 - R:/127.0.0.1:53744] HEADERS: streamId=1, headers=DefaultHttp2Headers[:method: POST, :authority: 127.0.0.1:8443, :scheme: https, :path: /echostream, foo: bar, empty: , content-type: zebra, user-agent: org.chromium.net/1 (Linux; U; Android 7.0; en_US; Nexus 6 (Android); Build/LRX09D; Cronet/62.0.3175.0)], streamDependency=0, weight=220, exclusive=true, padding=0, endStream=false
08-02 11:27:14.449 19689 19719 I org.chromium.net.W: ------------------------------------
08-02 11:27:14.451 19689 19719 I org.chromium.net.W: 
08-02 11:27:14.451 19689 19719 I org.chromium.net.W: ----------------OUTBOUND--------------------
08-02 11:27:14.451 19689 19719 I org.chromium.net.W: [id: 0x419d8afc, L:/127.0.0.1:8443 - R:/127.0.0.1:53744] HEADERS: streamId=1, headers=DefaultHttp2Headers[:status: 200, echo-foo: bar, echo-empty: , echo-content-type: zebra, echo-user-agent: org.chromium.net/1 (Linux; U; Android 7.0; en_US; Nexus 6 (Android); Build/LRX09D; Cronet/62.0.3175.0), echo-method: POST], streamDependency=0, weight=16, exclusive=false, padding=0, endStream=false
08-02 11:27:14.451 19689 19719 I org.chromium.net.W: ------------------------------------
08-02 11:27:14.453 19689 19719 I org.chromium.net.W: 
08-02 11:27:14.453 19689 19719 I org.chromium.net.W: ----------------INBOUND--------------------
08-02 11:27:14.453 19689 19719 I org.chromium.net.W: [id: 0x419d8afc, L:/127.0.0.1:8443 - R:/127.0.0.1:53744] DATA: streamId=1, padding=0, endStream=false, length=3, bytes=313233
08-02 11:27:14.453 19689 19719 I org.chromium.net.W: ------------------------------------
08-02 11:27:14.454 19689 19719 I org.chromium.net.W: 
08-02 11:27:14.454 19689 19719 I org.chromium.net.W: ----------------INBOUND--------------------
08-02 11:27:14.454 19689 19719 I org.chromium.net.W: [id: 0x419d8afc, L:/127.0.0.1:8443 - R:/127.0.0.1:53744] DATA: streamId=1, padding=0, endStream=false, length=2, bytes=3435
08-02 11:27:14.454 19689 19719 I org.chromium.net.W: ------------------------------------
08-02 11:27:14.455 19689 19719 I org.chromium.net.W: 
08-02 11:27:14.455 19689 19719 I org.chromium.net.W: ----------------INBOUND--------------------
08-02 11:27:14.455 19689 19719 I org.chromium.net.W: [id: 0x419d8afc, L:/127.0.0.1:8443 - R:/127.0.0.1:53744] DATA: streamId=1, padding=0, endStream=true, length=1, bytes=36
08-02 11:27:14.455 19689 19719 I org.chromium.net.W: ------------------------------------
08-02 11:27:14.464 19689 19719 I org.chromium.net.W: 
08-02 11:27:14.464 19689 19719 I org.chromium.net.W: ----------------OUTBOUND--------------------
08-02 11:27:14.464 19689 19719 I org.chromium.net.W: [id: 0x419d8afc, L:/127.0.0.1:8443 - R:/127.0.0.1:53744] DATA: streamId=1, padding=0, endStream=true, length=6, bytes=313233343536
08-02 11:27:14.464 19689 19719 I org.chromium.net.W: ------------------------------------
08-02 11:27:14.477 19689 19720 I cr_CronetUrlRequestContext: destroyNativeStreamLocked org.chromium.net.impl.CronetBidirectionalStream@2967acb
08-02 11:27:14.478 19689 19719 I org.chromium.net.W: 
08-02 11:27:14.478 19689 19719 I org.chromium.net.W: ----------------INBOUND--------------------
08-02 11:27:14.478 19689 19719 I org.chromium.net.W: [id: 0x419d8afc, L:/127.0.0.1:8443 - R:/127.0.0.1:53744] SETTINGS: ack=true
08-02 11:27:14.478 19689 19719 I org.chromium.net.W: ------------------------------------
08-02 11:27:14.478 19689 19718 I LoggingHandler: [id: 0x9f886334, L:/:::8443] CLOSE
08-02 11:27:14.479 19689 19718 I LoggingHandler: [id: 0x9f886334, L:/:::8443] UNREGISTERED
08-02 11:27:14.479 19689 19717 I cr_X    : Stopped Http2TestServerRunnable!

Comment 3 by mef@chromium.org, Aug 2 2017 

Thanks Helen! 

Couple of things I've noticed in these logs:

1. In timeout case inbound and outbound frames are interleaved, but in good case outbound frame is sent after all inbound are received.
2. In good case there is inbound settings frame with ack=true at the end.

Comment 4 by xunji...@chromium.org, Aug 2 2017 

I don't think the interleaving of incoming and outgoing frames matter, but I could be wrong.

how easy is it to add some debugging statements and run it in this testing environment? I would like to see if the order of Callbacks and if onSucceeded() is invoked or not.

Comment 5 by pauljensen@chromium.org, Aug 2 2017 

Adding debug statements and running in this testing environment is not easy but it is doable.  If you provide me a CL to patch in, it might take me an hour to get results; probably a lot less if the CL involves only changing Test Java code.
Project Member

Comment 6 by bugdroid1@chromium.org, Aug 4 2017 

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

commit e2d97b2a87a9199d925cf4d6751a7bb90a1ac607
Author: Helen Li <xunjieli@chromium.org>
Date: Fri Aug 04 13:56:34 2017

[cronet] Deflake BidirectionalStreamTest#testFlushData

This CL gets rid of the dependency on setAutoAdvance(false), which
might have disabled the reading of data.

If reading of data is paused during the time mAutoAdvance = false,
when we set mAutoAdvance to true, startNextRead() won't be called
automatically. If we don't startNextRead(), Callback#onSucceeded()
will not be called.

Bug:  751700 
Cq-Include-Trybots: master.tryserver.chromium.android:android_cronet_tester
Change-Id: I47fa37fb5d71c4ec0fcda5d6fd2ff762c08505d5
Reviewed-on: https://chromium-review.googlesource.com/598992
Reviewed-by: Paul Jensen <pauljensen@chromium.org>
Commit-Queue: Helen Li <xunjieli@chromium.org>
Cr-Commit-Position: refs/heads/master@{#492015}
[modify] https://crrev.com/e2d97b2a87a9199d925cf4d6751a7bb90a1ac607/components/cronet/android/test/javatests/src/org/chromium/net/BidirectionalStreamTest.java

Comment 7 by xunji...@chromium.org, Aug 4 2017

Status: Fixed (was: Assigned)
I think this should be fixed.

Comment 8 by pauljensen@chromium.org, Aug 4 2017 

Can we merge this back too?  If you want me to, feel free to assign to me.

Comment 9 by xunji...@chromium.org, Aug 4 2017

Labels: Merge-Request-61
Requesting merge into M61. This is a test change.  Thank you.
Project Member

Comment 10 by sheriffbot@chromium.org, Aug 4 2017

Labels: -Merge-Request-61 Merge-Review-61 Hotlist-Merge-Review
This bug requires manual review: M61 has already been promoted to the beta branch, so this requires manual review
Please contact the milestone owner if you have questions.
Owners: amineer@(Android), cmasso@(iOS), ketakid@(ChromeOS), govind@(Desktop)

For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot

Comment 11 by xunji...@chromium.org, Aug 4 2017

Labels: -Hotlist-Merge-Review -Merge-Review-61
Removing the bug the request per go/chrome-merges guideline.
Paul has disabled the test in the other test environment.
►

Sign in to add a comment