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

Issue 625188 link

Starred by 2 users

Issue metadata

Status: Fixed
Owner:
Closed: Jul 2016
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Android
Pri: 2
Type: Bug



Sign in to add a comment

Cronet tests failing on Android N

Project Member Reported by kapishnikov@chromium.org, Jul 1 2016

Issue description

The following four tests are passing on Android M but failing on Android N:

C  665.037s Main  ********************************************************************************
C  665.038s Main  Detailed Logs
C  665.038s Main  ********************************************************************************
C  665.039s Main  [FAIL] org.chromium.net.QuicTest#testQuicLoadUrl:
C  665.039s Main  java.lang.Throwable: CronetTestBase#runTest failed.
C  665.039s Main  	at org.chromium.net.CronetTestBase.runTest(CronetTestBase.java:147)
C  665.039s Main  	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:198)
C  665.039s Main  	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:183)
C  665.039s Main  	at android.test.InstrumentationTestRunner.onStart(InstrumentationTestRunner.java:560)
C  665.040s Main  	at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1932)
C  665.040s Main  Caused by: java.lang.NullPointerException: Attempt to invoke virtual method 'int org.chromium.net.UrlResponseInfo.getHttpStatusCode()' on a null object reference
C  665.040s Main  	at org.chromium.net.QuicTest.testQuicLoadUrl(QuicTest.java:116)
C  665.040s Main  	at org.chromium.net.CronetTestBase.runTest(CronetTestBase.java:137)
C  665.040s Main  	... 9 more
C  665.040s Main  
C  665.040s Main  [FAIL] org.chromium.net.QuicTest#testQuicLoadUrl_LegacyAPI:
C  665.040s Main  java.lang.Throwable: CronetTestBase#runTest failed.
C  665.041s Main  	at org.chromium.net.CronetTestBase.runTest(CronetTestBase.java:147)
C  665.041s Main  	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:198)
C  665.041s Main  	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:183)
C  665.041s Main  	at android.test.InstrumentationTestRunner.onStart(InstrumentationTestRunner.java:560)
C  665.041s Main  	at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1932)
C  665.041s Main  Caused by: junit.framework.AssertionFailedError: expected:<200> but was:<0>
C  665.041s Main  	at org.chromium.net.QuicTest.testQuicLoadUrl_LegacyAPI(QuicTest.java:91)
C  665.041s Main  	at org.chromium.net.CronetTestBase.runTest(CronetTestBase.java:137)
C  665.042s Main  	... 9 more
C  665.042s Main  
C  665.042s Main  [FAIL] org.chromium.net.QuicTest#testRealTimeNetworkQualityObservationsWithQuic:
C  665.042s Main  java.lang.Throwable: CronetTestBase#runTest failed.
C  665.042s Main  	at org.chromium.net.CronetTestBase.runTest(CronetTestBase.java:147)
C  665.042s Main  	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:198)
C  665.042s Main  	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:183)
C  665.042s Main  	at android.test.InstrumentationTestRunner.onStart(InstrumentationTestRunner.java:560)
C  665.042s Main  	at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1932)
C  665.042s Main  Caused by: java.lang.NullPointerException: Attempt to invoke virtual method 'int org.chromium.net.UrlResponseInfo.getHttpStatusCode()' on a null object reference
C  665.042s Main  	at org.chromium.net.QuicTest.testRealTimeNetworkQualityObservationsWithQuic(QuicTest.java:207)
C  665.042s Main  	at org.chromium.net.CronetTestBase.runTest(CronetTestBase.java:137)
C  665.042s Main  	... 9 more
C  665.042s Main  
C  665.043s Main  [FAIL] org.chromium.net.urlconnection.CronetHttpURLConnectionTest#testDoNotFollowRedirectsIfSchemesDontMatch:
C  665.043s Main  java.lang.Throwable: CronetTestBase#runTest failed.
C  665.043s Main  	at org.chromium.net.CronetTestBase.runTest(CronetTestBase.java:132)
C  665.043s Main  	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:198)
C  665.043s Main  	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:183)
C  665.043s Main  	at android.test.InstrumentationTestRunner.onStart(InstrumentationTestRunner.java:560)
C  665.043s Main  	at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1932)
C  665.043s Main  Caused by: junit.framework.ComparisonFailure: expected:<http[s://127.0.0.1:8000/success.txt]> but was:<http[://127.0.0.1:58881/redirect_invalid_scheme.html]>
C  665.043s Main  	at org.chromium.net.urlconnection.CronetHttpURLConnectionTest.testDoNotFollowRedirectsIfSchemesDontMatch(CronetHttpURLConnectionTest.java:1006)
C  665.043s Main  	at org.chromium.net.CronetTestBase.runTest(CronetTestBase.java:118)
C  665.043s Main  	... 9 more

 
Status: Available (was: Untriaged)
I took a quick look why the QUIC tests are failing. The reason why the tests are failing is that on Android N, the requests are unexpectedly return an error. As the result, |callback.mResponseInfo| remains null. The error codes: errorCode=7, nativeError=-102 (CONNECTION_REFUSED). Here is the comparison of debug logcats on 'N' vs 'M' running org.chromium.net.QuicTest#testQuicLoadUrl:

--- Android N ---
07-06 15:00:18.536 20652 20667 V chromium: [0706/150018:VERBOSE1:cronet_url_request_adapter.cc(54)] New chromium network request_adapter: https://test.example.com:6121/simple.txt
07-06 15:00:18.536 20652 20670 V chromium: [0706/150018:VERBOSE1:cronet_url_request_adapter.cc(286)] Starting chromium request: https://test.example.com:6121/simple.txt priority: MEDIUM
07-06 15:00:18.539 20652 20670 V chromium: [0706/150018:VERBOSE1:http_stream_factory_impl_job_controller.cc(508)] Selected alternative service (host: test.example.com port: 6121)
07-06 15:00:18.539 20652 20670 V chromium: [0706/150018:VERBOSE1:histogram.cc(377)] Histogram: Net.ProxyService.ResolveProxyTime has bad minimum: 0
07-06 15:00:18.540 20652 20676 V chromium: [0706/150018:VERBOSE1:simple_index_file.cc(535)] Simple Cache Index is being restored from disk.
07-06 15:00:18.541 20652 20670 V chromium: [0706/150018:VERBOSE1:spdy_session_key.cc(21)] SpdySessionKey(host=test.example.com:6121, proxy=direct://, privacy=0
07-06 15:00:18.541 20652 20670 V chromium: [0706/150018:VERBOSE1:histogram.cc(377)] Histogram: SimpleCache.Http.IndexNumEntriesOnWrite has bad minimum: 0
07-06 15:00:18.542 20652 20670 V chromium: [0706/150018:VERBOSE1:histogram.cc(377)] Histogram: SimpleCache.Http.IndexInitializationWaiters has bad minimum: 0
07-06 15:00:18.546 20652 20670 V chromium: [0706/150018:VERBOSE2:net_errors_posix.cc(19)] Error 111 << This is CONNECTION_REFUSED error code.
07-06 15:00:18.546 20652 20670 V chromium: [0706/150018:VERBOSE1:cronet_url_request_adapter.cc(375)] Error net::ERR_CONNECTION_REFUSED on chromium request: https://test.example.com:6121/simple.txt
------------------

--- Android M ---
07-06 15:03:43.260 15330 15343 V chromium: [0706/150343:VERBOSE1:cronet_url_request_adapter.cc(54)] New chromium network request_adapter: https://test.example.com:6121/simple.txt
07-06 15:03:43.260 15330 15346 V chromium: [0706/150343:VERBOSE1:cronet_url_request_adapter.cc(286)] Starting chromium request: https://test.example.com:6121/simple.txt priority: MEDIUM
07-06 15:03:43.264 15330 15352 V chromium: [0706/150343:VERBOSE1:simple_index_file.cc(535)] Simple Cache Index is being restored from disk.
07-06 15:03:43.264 15330 15346 V chromium: [0706/150343:VERBOSE1:http_stream_factory_impl_job_controller.cc(508)] Selected alternative service (host: test.example.com port: 6121)
07-06 15:03:43.264 15330 15346 V chromium: [0706/150343:VERBOSE1:histogram.cc(377)] Histogram: Net.ProxyService.ResolveProxyTime has bad minimum: 0
07-06 15:03:43.266 15330 15346 V chromium: [0706/150343:VERBOSE1:spdy_session_key.cc(21)] SpdySessionKey(host=test.example.com:6121, proxy=direct://, privacy=0
07-06 15:03:43.266 15330 15346 V chromium: [0706/150343:VERBOSE1:histogram.cc(377)] Histogram: SimpleCache.Http.IndexNumEntriesOnWrite has bad minimum: 0
07-06 15:03:43.267 15330 15346 V chromium: [0706/150343:VERBOSE1:histogram.cc(377)] Histogram: SimpleCache.Http.IndexInitializationWaiters has bad minimum: 0
07-06 15:03:43.270 15330 15346 V chromium: [0706/150343:VERBOSE1:quic_connection.cc(315)] Client: Created connection with connection_id: 6311824591647528009
-----------------
Thanks for looking at this, Andrei! I am not sure why we would receive ERR_CONNECTION_REFUSED on N. One thing we could try is to grab NetLog running on N, and see if the ERR_CONNECTION_REFUSED is coming from the TCP or QUIC, and add VLOGs to see why QUIC session isn't established. I can take a look later this week if you don't get to it.
Attached the netlog.
cronet1387395102json
35.5 KB View Download
One thing we could try is to add some VLOGs in AlternativeService
HttpStreamFactoryImpl::JobController::GetAlternativeServiceForInternal to see why it skipped QUIC. 
From quic_stream_factory.cc:
[0706/175209:INFO:quic_stream_factory.cc(1639)] ConfigureSocket result: -11 (NOT_IMPLEMENTED)

Cc: pauljensen@chromium.org lorenzo@google.com
Thanks to Helen & Misha for helping to identify the problem.

The QUIC tests are failing because udp_socket_posix.cc is trying to directly open "libnetd_client.so" system library using "dlopen". See the |BindToNetwork| method:
https://cs.chromium.org/chromium/src/net/udp/udp_socket_posix.cc?l=363

As the result, |setNetworkForSocket| is NULL and the |BindToNetwork| method returns ERR_NOT_IMPLEMENTED. This error is passed to |QuicStreamFactory::CreateSession| (see comment #6).


The loading of the system (non-NDK) libraries is prohibited starting from Android N. For more information see:
https://developer.android.com/preview/behavior-changes.html#ndk

This can be a serious problem since, with the current implementation, QUIC is going to be disabled on Android N devices.

Packaging "libnetd_client.so" together with the app is probably not an option since the library implementation may depend on a particular version of Android OS and hardware.

Is there any other way to bind the socket to particular network interface? CCing Paul & Lorenzo.

P.S. I checked that the failure to load the library is not related to the recent changes https://codereview.chromium.org/2104533002



Components: Internals>Network>QUIC
Paul is out of office for these two weeks. We could consider disabling QUIC connection migration on N until this issue is fixed. This can be done by adding a sdk version check in QuicStreamFactory::ConfigureSocket https://cs.chromium.org/chromium/src/net/quic/quic_stream_factory.cc?rcl=1467818171&l=1569 so that we call socket->Connect() instead of socket->ConnectUsing*Network() on N.

Comment 9 by jri@chromium.org, Jul 6 2016

Cc: jri@chromium.org

Comment 10 by jri@chromium.org, Jul 6 2016

There is already an sdk check on Android that verifies that the platform has the right APIs, and results in AreNetworkHandlesSupported() returning true only if the sdk is >= L. We could temporarily restrict it to >= L and < N. See: https://cs.chromium.org/chromium/src/net/base/network_change_notifier.cc?rcl=1467818171&l=639. (I don't know where the Android override is.)

It seems to me that these tests would also be failing for Chromium on Android N, so it'd be good to get this fixed. Does anyone know what a solution might look like?
I don't think restricting to < N in AreNetworkHandlesSupported() will solve the problem that Andrei is seeing. If AreNetworkHandlesSupported() returns false, I believe we will still end up with ERR_NOT_IMPLEMENTED when calling ConnectUsingDefaultNetwork below. I think it might be easier just to do (migrate_sessions_on_network_change_ && sdk_int < N) instead of (migrate_sessions_on_network_change_) for the if-conditional below.

  int rv;
  if (migrate_sessions_on_network_change_) {
    // If caller leaves network unspecified, use current default network.
    if (network == NetworkChangeNotifier::kInvalidNetworkHandle) {
      rv = socket->ConnectUsingDefaultNetwork(addr);
    } else {
      rv = socket->ConnectUsingNetwork(network, addr);
    }
  } else {
    rv = socket->Connect(addr);
  }

Comment 12 by jri@chromium.org, Jul 7 2016

AreNetworkHandlesSupported() is currently the mechanism we use to disable connection migration on platforms that don't have the requisite support. migrate_sessions_on_network_change_ is false if AreNetworkHandlesSupported() returns false. See: https://cs.chromium.org/chromium/src/net/quic/quic_stream_factory.cc?rcl=1467818171&l=683
The supported way to bind a socket to a network is the android_setsocknetwork NDK API:

https://android.googlesource.com/platform/frameworks/native/+/master/include/android/multinetwork.h

IIRC this was added in M. The header file has documentation on how to use it; feel free to get in touch with us if it's not sufficient.
Re 12: Jana, you are right. Thanks for pointing that out! I missed that part of code.
Cc: -pauljensen@chromium.org
Owner: pauljensen@chromium.org
Status: Started (was: Available)
Fix out for review: https://codereview.chromium.org/2160263002

With my fix all tests pass on Andrei's Nexus 9 running Android M.  On my Nexus 5X just one test fails, which I've tracked down and filed as  Issue 629591 .
Project Member

Comment 17 by bugdroid1@chromium.org, Jul 22 2016

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

commit 479143c5186dc2559f645cf25f9aebc006e0f3a2
Author: pauljensen <pauljensen@chromium.org>
Date: Fri Jul 22 12:35:09 2016

Use supported Android network handles in Android M and newer.

In Android N loading system libraries is banned so use the supported mechanism
for Android M and newer releases.  For Android L we still need to manually load
the system library.

BUG= 625188 

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

[modify] https://crrev.com/479143c5186dc2559f645cf25f9aebc006e0f3a2/chrome/android/java/src/org/chromium/chrome/browser/download/DownloadManagerService.java
[modify] https://crrev.com/479143c5186dc2559f645cf25f9aebc006e0f3a2/content/public/android/java/src/org/chromium/content/browser/BackgroundSyncNetworkObserver.java
[modify] https://crrev.com/479143c5186dc2559f645cf25f9aebc006e0f3a2/net/android/java/src/org/chromium/net/NetworkChangeNotifier.java
[modify] https://crrev.com/479143c5186dc2559f645cf25f9aebc006e0f3a2/net/android/java/src/org/chromium/net/NetworkChangeNotifierAutoDetect.java
[modify] https://crrev.com/479143c5186dc2559f645cf25f9aebc006e0f3a2/net/android/javatests/src/org/chromium/net/NetworkChangeNotifierTest.java
[modify] https://crrev.com/479143c5186dc2559f645cf25f9aebc006e0f3a2/net/android/network_change_notifier_delegate_android.cc
[modify] https://crrev.com/479143c5186dc2559f645cf25f9aebc006e0f3a2/net/android/network_change_notifier_delegate_android.h
[modify] https://crrev.com/479143c5186dc2559f645cf25f9aebc006e0f3a2/net/base/network_change_notifier.h
[modify] https://crrev.com/479143c5186dc2559f645cf25f9aebc006e0f3a2/net/udp/udp_socket_posix.cc
[modify] https://crrev.com/479143c5186dc2559f645cf25f9aebc006e0f3a2/net/udp/udp_socket_unittest.cc

Status: Fixed (was: Started)
Project Member

Comment 19 by bugdroid1@chromium.org, Aug 19 2016

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

commit eef27f6a445e0d16821f3ceebf73ca1a6d083698
Author: pauljensen <pauljensen@chromium.org>
Date: Fri Aug 19 14:06:46 2016

Make NetworkChangeNotifier NetworkHandles readable in NetLog on Android M

Due to  crbug.com/625188  fix NetworkHandles in the NetLog were unreadable,
fix them to be readable again.

R=xunjieli
BUG= 625188 

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

[modify] https://crrev.com/eef27f6a445e0d16821f3ceebf73ca1a6d083698/net/base/logging_network_change_observer.cc

Sign in to add a comment