From a4f17bcbdf787852267a6f24d83ca2011f0decac Mon Sep 17 00:00:00 2001 From: Hugo Benichi Date: Mon, 21 Nov 2016 13:50:05 +0900 Subject: [PATCH 1/3] DO NOT MERGE Captive portal systel log improvements This patch improves system logging around captive portal detection to make inspection of bug reports sligthly easier: - NetworkMonitor now logs by default CMD_CAPTIVE_PORTAL_RECHECK and CMD_CAPTIVE_PORTAL_APP_FINISHED. Other system logs are kept off with a new VDBG boolean contant, - NetworkNotificationManager now prints the notification id at notification time. This allows to easily correlate show and clear. - errors in NetworkNotificationManager are logged as Throwable instead of through their implicit toString() method. Test: $ runtest frameworks-net Bug: 32198726 (cherry picked from commit 8b025bf108c729156b40159038befa0e6c5bebce) Change-Id: I7780c389a94c4b9fa226f53b02fe5960d1c08618 --- .../android/server/connectivity/NetworkMonitor.java | 11 ++++++----- .../connectivity/NetworkNotificationManager.java | 6 +++--- 2 files changed, 9 insertions(+), 8 deletions(-) diff --git a/services/core/java/com/android/server/connectivity/NetworkMonitor.java b/services/core/java/com/android/server/connectivity/NetworkMonitor.java index c73d1dd954375..aa66917e48fd3 100644 --- a/services/core/java/com/android/server/connectivity/NetworkMonitor.java +++ b/services/core/java/com/android/server/connectivity/NetworkMonitor.java @@ -80,7 +80,8 @@ import java.util.concurrent.TimeUnit; */ public class NetworkMonitor extends StateMachine { private static final String TAG = NetworkMonitor.class.getSimpleName(); - private static final boolean DBG = false; + private static final boolean DBG = true; + private static final boolean VDBG = false; // Default configuration values for captive portal detection probes. // TODO: append a random length parameter to the default HTTPS url. @@ -918,7 +919,7 @@ public class NetworkMonitor extends StateMachine { latencyBroadcast.putExtra(EXTRA_SSID, currentWifiInfo.getSSID()); latencyBroadcast.putExtra(EXTRA_BSSID, currentWifiInfo.getBSSID()); } else { - if (DBG) logw("network info is TYPE_WIFI but no ConnectionInfo found"); + if (VDBG) logw("network info is TYPE_WIFI but no ConnectionInfo found"); return; } break; @@ -931,8 +932,8 @@ public class NetworkMonitor extends StateMachine { if (cellInfo.isRegistered()) { numRegisteredCellInfo++; if (numRegisteredCellInfo > 1) { - log("more than one registered CellInfo. Can't " + - "tell which is active. Bailing."); + if (VDBG) logw("more than one registered CellInfo." + + " Can't tell which is active. Bailing."); return; } if (cellInfo instanceof CellInfoCdma) { @@ -948,7 +949,7 @@ public class NetworkMonitor extends StateMachine { CellIdentityWcdma cellId = ((CellInfoWcdma) cellInfo).getCellIdentity(); latencyBroadcast.putExtra(EXTRA_CELL_ID, cellId); } else { - if (DBG) logw("Registered cellinfo is unrecognized"); + if (VDBG) logw("Registered cellinfo is unrecognized"); return; } } diff --git a/services/core/java/com/android/server/connectivity/NetworkNotificationManager.java b/services/core/java/com/android/server/connectivity/NetworkNotificationManager.java index f7b01be48d887..c6bf4c5fcd6a4 100644 --- a/services/core/java/com/android/server/connectivity/NetworkNotificationManager.java +++ b/services/core/java/com/android/server/connectivity/NetworkNotificationManager.java @@ -114,7 +114,7 @@ public class NetworkNotificationManager { } if (DBG) { - Slog.d(TAG, "showNotification " + notifyType + Slog.d(TAG, "showNotification id=" + id + " " + notifyType + " transportType=" + getTransportName(transportType) + " extraInfo=" + extraInfo + " highPriority=" + highPriority); } @@ -187,7 +187,7 @@ public class NetworkNotificationManager { try { mNotificationManager.notifyAsUser(NOTIFICATION_ID, id, notification, UserHandle.ALL); } catch (NullPointerException npe) { - Slog.d(TAG, "setNotificationVisible: visible notificationManager npe=" + npe); + Slog.d(TAG, "setNotificationVisible: visible notificationManager error", npe); } } @@ -198,7 +198,7 @@ public class NetworkNotificationManager { try { mNotificationManager.cancelAsUser(NOTIFICATION_ID, id, UserHandle.ALL); } catch (NullPointerException npe) { - Slog.d(TAG, "setNotificationVisible: cancel notificationManager npe=" + npe); + Slog.d(TAG, "setNotificationVisible: cancel notificationManager error", npe); } } From dd22982e250d1758098a88f00e607a464928ae5a Mon Sep 17 00:00:00 2001 From: Hugo Benichi Date: Tue, 15 Nov 2016 23:23:24 +0900 Subject: [PATCH 2/3] DO NOT MERGE NetworkMonitor metrics: add first validation information This patch adds first validation information to: - ValidationProbeEvent, by extending the probe_type int field of to also include a bit indicating if the probe was part of a first validation attempt or not. - NetworkMonitorEvent, by defining new contants for the event_type field. Test: $ runtest frameworks-net + manually generating events and inspecting the output of $ adb shell dumpsys connmetrics list Bug: b/32198726 (cherry picked from commit 147aa6d53bc1e9f8a3632553abcf936023806e1d) Change-Id: I7ed954dee006f8804a5bf8940eec180714bddd07 --- .../android/net/metrics/NetworkEvent.java | 13 +++++ .../net/metrics/ValidationProbeEvent.java | 34 +++++++++---- .../server/connectivity/NetworkMonitor.java | 50 ++++++++++++++++++- 3 files changed, 85 insertions(+), 12 deletions(-) diff --git a/core/java/android/net/metrics/NetworkEvent.java b/core/java/android/net/metrics/NetworkEvent.java index 3b3fa6976fc98..06674950a044d 100644 --- a/core/java/android/net/metrics/NetworkEvent.java +++ b/core/java/android/net/metrics/NetworkEvent.java @@ -41,6 +41,15 @@ public final class NetworkEvent implements Parcelable { public static final int NETWORK_UNLINGER = 6; public static final int NETWORK_DISCONNECTED = 7; + /** {@hide} */ + public static final int NETWORK_FIRST_VALIDATION_SUCCESS = 8; + /** {@hide} */ + public static final int NETWORK_REVALIDATION_SUCCESS = 9; + /** {@hide} */ + public static final int NETWORK_FIRST_VALIDATION_PORTAL_FOUND = 10; + /** {@hide} */ + public static final int NETWORK_REVALIDATION_PORTAL_FOUND = 11; + /** {@hide} */ @IntDef(value = { NETWORK_CONNECTED, @@ -50,6 +59,10 @@ public final class NetworkEvent implements Parcelable { NETWORK_LINGER, NETWORK_UNLINGER, NETWORK_DISCONNECTED, + NETWORK_FIRST_VALIDATION_SUCCESS, + NETWORK_REVALIDATION_SUCCESS, + NETWORK_FIRST_VALIDATION_PORTAL_FOUND, + NETWORK_REVALIDATION_PORTAL_FOUND, }) @Retention(RetentionPolicy.SOURCE) public @interface EventType {} diff --git a/core/java/android/net/metrics/ValidationProbeEvent.java b/core/java/android/net/metrics/ValidationProbeEvent.java index 1a31b56f1ffb6..a724ec12ed324 100644 --- a/core/java/android/net/metrics/ValidationProbeEvent.java +++ b/core/java/android/net/metrics/ValidationProbeEvent.java @@ -44,10 +44,8 @@ public final class ValidationProbeEvent implements Parcelable { public static final int DNS_FAILURE = 0; public static final int DNS_SUCCESS = 1; - /** {@hide} */ - @IntDef(value = {PROBE_DNS, PROBE_HTTP, PROBE_HTTPS, PROBE_PAC}) - @Retention(RetentionPolicy.SOURCE) - public @interface ProbeType {} + private static final int FIRST_VALIDATION = 1 << 8; + private static final int REVALIDATION = 2 << 8; /** {@hide} */ @IntDef(value = {DNS_FAILURE, DNS_SUCCESS}) @@ -56,12 +54,17 @@ public final class ValidationProbeEvent implements Parcelable { public final int netId; public final long durationMs; - public final @ProbeType int probeType; + // probeType byte format (MSB to LSB): + // byte 0: unused + // byte 1: unused + // byte 2: 0 = UNKNOWN, 1 = FIRST_VALIDATION, 2 = REVALIDATION + // byte 3: PROBE_* constant + public final int probeType; public final @ReturnCode int returnCode; /** {@hide} */ public ValidationProbeEvent( - int netId, long durationMs, @ProbeType int probeType, @ReturnCode int returnCode) { + int netId, long durationMs, int probeType, @ReturnCode int returnCode) { this.netId = netId; this.durationMs = durationMs; this.probeType = probeType; @@ -99,9 +102,19 @@ public final class ValidationProbeEvent implements Parcelable { } }; + /** @hide */ + public static int makeProbeType(int probeType, boolean firstValidation) { + return (probeType & 0xff) | (firstValidation ? FIRST_VALIDATION : REVALIDATION); + } + /** @hide */ public static String getProbeName(int probeType) { - return Decoder.constants.get(probeType, "PROBE_???"); + return Decoder.constants.get(probeType & 0xff, "PROBE_???"); + } + + /** @hide */ + public static String getValidationStage(int probeType) { + return Decoder.constants.get(probeType & 0xff00, "UNKNOWN"); } public static void logEvent(int netId, long durationMs, int probeType, int returnCode) { @@ -109,12 +122,13 @@ public final class ValidationProbeEvent implements Parcelable { @Override public String toString() { - return String.format("ValidationProbeEvent(%d, %s:%d, %dms)", - netId, getProbeName(probeType), returnCode, durationMs); + return String.format("ValidationProbeEvent(%d, %s:%d %s, %dms)", netId, + getProbeName(probeType), returnCode, getValidationStage(probeType), durationMs); } final static class Decoder { static final SparseArray constants = MessageUtils.findMessageNames( - new Class[]{ValidationProbeEvent.class}, new String[]{"PROBE_"}); + new Class[]{ValidationProbeEvent.class}, + new String[]{"PROBE_", "FIRST_", "REVALIDATION"}); } } diff --git a/services/core/java/com/android/server/connectivity/NetworkMonitor.java b/services/core/java/com/android/server/connectivity/NetworkMonitor.java index aa66917e48fd3..209ea647922c0 100644 --- a/services/core/java/com/android/server/connectivity/NetworkMonitor.java +++ b/services/core/java/com/android/server/connectivity/NetworkMonitor.java @@ -97,6 +97,24 @@ public class NetworkMonitor extends StateMachine { private static final int SOCKET_TIMEOUT_MS = 10000; private static final int PROBE_TIMEOUT_MS = 3000; + static enum EvaluationResult { + VALIDATED(true), + CAPTIVE_PORTAL(false); + final boolean isValidated; + EvaluationResult(boolean isValidated) { + this.isValidated = isValidated; + } + } + + static enum ValidationStage { + FIRST_VALIDATION(true), + REVALIDATION(false); + final boolean isFirstValidation; + ValidationStage(boolean isFirstValidation) { + this.isFirstValidation = isFirstValidation; + } + } + public static final String ACTION_NETWORK_CONDITIONS_MEASURED = "android.net.conn.NETWORK_CONDITIONS_MEASURED"; public static final String EXTRA_CONNECTIVITY_TYPE = "extra_connectivity_type"; @@ -216,6 +234,8 @@ public class NetworkMonitor extends StateMachine { protected boolean mIsCaptivePortalCheckEnabled; private boolean mUseHttps; + // The total number of captive portal detection attempts for this NetworkMonitor instance. + private int mValidations = 0; // Set if the user explicitly selected "Do not use this network" in captive portal sign-in app. private boolean mUserDoesNotWant = false; @@ -290,6 +310,10 @@ public class NetworkMonitor extends StateMachine { return validationLogs.readOnlyLocalLog(); } + private ValidationStage validationStage() { + return 0 == mValidations ? ValidationStage.FIRST_VALIDATION : ValidationStage.REVALIDATION; + } + // DefaultState is the parent of all States. It exists only to handle CMD_* messages but // does not entail any real state (hence no enter() or exit() routines). private class DefaultState extends State { @@ -366,9 +390,11 @@ public class NetworkMonitor extends StateMachine { private class ValidatedState extends State { @Override public void enter() { - maybeLogEvaluationResult(NetworkEvent.NETWORK_VALIDATED); + maybeLogEvaluationResult( + networkEventType(validationStage(), EvaluationResult.VALIDATED)); mConnectivityServiceHandler.sendMessage(obtainMessage(EVENT_NETWORK_TESTED, NETWORK_TEST_RESULT_VALID, mNetworkAgentInfo.network.netId, null)); + mValidations++; } @Override @@ -584,7 +610,8 @@ public class NetworkMonitor extends StateMachine { @Override public void enter() { - maybeLogEvaluationResult(NetworkEvent.NETWORK_CAPTIVE_PORTAL_FOUND); + maybeLogEvaluationResult( + networkEventType(validationStage(), EvaluationResult.CAPTIVE_PORTAL)); // Don't annoy user with sign-in notifications. if (mDontDisplaySigninNotification) return; // Create a CustomIntentReceiver that sends us a @@ -604,6 +631,7 @@ public class NetworkMonitor extends StateMachine { // Retest for captive portal occasionally. sendMessageDelayed(CMD_CAPTIVE_PORTAL_RECHECK, 0 /* no UID */, CAPTIVE_PORTAL_REEVALUATE_DELAY_MS); + mValidations++; } @Override @@ -974,6 +1002,22 @@ public class NetworkMonitor extends StateMachine { mMetricsLog.log(new NetworkEvent(mNetId, evtype)); } + private int networkEventType(ValidationStage s, EvaluationResult r) { + if (s.isFirstValidation) { + if (r.isValidated) { + return NetworkEvent.NETWORK_FIRST_VALIDATION_SUCCESS; + } else { + return NetworkEvent.NETWORK_FIRST_VALIDATION_PORTAL_FOUND; + } + } else { + if (r.isValidated) { + return NetworkEvent.NETWORK_REVALIDATION_SUCCESS; + } else { + return NetworkEvent.NETWORK_REVALIDATION_PORTAL_FOUND; + } + } + } + private void maybeLogEvaluationResult(int evtype) { if (mEvaluationTimer.isRunning()) { mMetricsLog.log(new NetworkEvent(mNetId, evtype, mEvaluationTimer.stop())); @@ -982,6 +1026,8 @@ public class NetworkMonitor extends StateMachine { } private void logValidationProbe(long durationMs, int probeType, int probeResult) { + probeType = + ValidationProbeEvent.makeProbeType(probeType, validationStage().isFirstValidation); mMetricsLog.log(new ValidationProbeEvent(mNetId, durationMs, probeType, probeResult)); } } From eb5e9aa2cea166455f4f157cf550e44626ede204 Mon Sep 17 00:00:00 2001 From: Hugo Benichi Date: Wed, 16 Nov 2016 18:18:08 +0900 Subject: [PATCH 3/3] DO NOT MERGE NetworkMonitor: send one DNS probe per web probe This patch changes sligthly the two web probes mechanism for captive portal detection and network validation so that DNS resolution is always done for both probes. In general the target web servers of the two parallel HTTP and HTTPS probes are now different. This introduces a bias in the latency measurement of th HTTPS probe since this latency will also include DNS resolution in general. Test: manual verification + $ runtest frameworks-net Bug: 32198726 (cherry picked from commit ab61e7c324b24e46829495bc2597e42ea907c53d) Change-Id: Ic83c3f8f46d32269bca1b90ae192ef648d5df6c3 --- .../server/connectivity/NetworkMonitor.java | 96 ++++++++++--------- 1 file changed, 52 insertions(+), 44 deletions(-) diff --git a/services/core/java/com/android/server/connectivity/NetworkMonitor.java b/services/core/java/com/android/server/connectivity/NetworkMonitor.java index 209ea647922c0..5e98859141697 100644 --- a/services/core/java/com/android/server/connectivity/NetworkMonitor.java +++ b/services/core/java/com/android/server/connectivity/NetworkMonitor.java @@ -707,48 +707,13 @@ public class NetworkMonitor extends StateMachine { long startTime = SystemClock.elapsedRealtime(); - // Pre-resolve the captive portal server host so we can log it. - // Only do this if HttpURLConnection is about to, to avoid any potentially - // unnecessary resolution. - String hostToResolve = null; + final CaptivePortalProbeResult result; if (pacUrl != null) { - hostToResolve = pacUrl.getHost(); - } else if (proxyInfo != null) { - hostToResolve = proxyInfo.getHost(); - } else { - hostToResolve = httpUrl.getHost(); - } - - if (!TextUtils.isEmpty(hostToResolve)) { - String probeName = ValidationProbeEvent.getProbeName(ValidationProbeEvent.PROBE_DNS); - final Stopwatch dnsTimer = new Stopwatch().start(); - int dnsResult; - long dnsLatency; - try { - InetAddress[] addresses = mNetworkAgentInfo.network.getAllByName(hostToResolve); - dnsResult = ValidationProbeEvent.DNS_SUCCESS; - dnsLatency = dnsTimer.stop(); - final StringBuffer connectInfo = new StringBuffer(", " + hostToResolve + "="); - for (InetAddress address : addresses) { - connectInfo.append(address.getHostAddress()); - if (address != addresses[addresses.length-1]) connectInfo.append(","); - } - validationLog(probeName + " OK " + dnsLatency + "ms" + connectInfo); - } catch (UnknownHostException e) { - dnsResult = ValidationProbeEvent.DNS_FAILURE; - dnsLatency = dnsTimer.stop(); - validationLog(probeName + " FAIL " + dnsLatency + "ms, " + hostToResolve); - } - logValidationProbe(dnsLatency, ValidationProbeEvent.PROBE_DNS, dnsResult); - } - - CaptivePortalProbeResult result; - if (pacUrl != null) { - result = sendHttpProbe(pacUrl, ValidationProbeEvent.PROBE_PAC); + result = sendDnsAndHttpProbes(null, pacUrl, ValidationProbeEvent.PROBE_PAC); } else if (mUseHttps) { - result = sendParallelHttpProbes(httpsUrl, httpUrl, fallbackUrl); + result = sendParallelHttpProbes(proxyInfo, httpsUrl, httpUrl, fallbackUrl); } else { - result = sendHttpProbe(httpUrl, ValidationProbeEvent.PROBE_HTTP); + result = sendDnsAndHttpProbes(proxyInfo, httpUrl, ValidationProbeEvent.PROBE_HTTP); } long endTime = SystemClock.elapsedRealtime(); @@ -761,8 +726,50 @@ public class NetworkMonitor extends StateMachine { } /** - * Do a URL fetch on a known server to see if we get the data we expect. - * Returns HTTP response code. + * Do a DNS resolution and URL fetch on a known web server to see if we get the data we expect. + * @return a CaptivePortalProbeResult inferred from the HTTP response. + */ + private CaptivePortalProbeResult sendDnsAndHttpProbes(ProxyInfo proxy, URL url, int probeType) { + // Pre-resolve the captive portal server host so we can log it. + // Only do this if HttpURLConnection is about to, to avoid any potentially + // unnecessary resolution. + final String host = (proxy != null) ? proxy.getHost() : url.getHost(); + sendDnsProbe(host); + return sendHttpProbe(url, probeType); + } + + /** Do a DNS resolution of the given server. */ + private void sendDnsProbe(String host) { + if (TextUtils.isEmpty(host)) { + return; + } + + final String name = ValidationProbeEvent.getProbeName(ValidationProbeEvent.PROBE_DNS); + final Stopwatch watch = new Stopwatch().start(); + int result; + String connectInfo; + try { + InetAddress[] addresses = mNetworkAgentInfo.network.getAllByName(host); + result = ValidationProbeEvent.DNS_SUCCESS; + StringBuffer buffer = new StringBuffer(host).append("="); + for (InetAddress address : addresses) { + buffer.append(address.getHostAddress()); + if (address != addresses[addresses.length-1]) buffer.append(","); + } + connectInfo = buffer.toString(); + } catch (UnknownHostException e) { + result = ValidationProbeEvent.DNS_FAILURE; + connectInfo = host; + } + final long latency = watch.stop(); + String resultString = (ValidationProbeEvent.DNS_SUCCESS == result) ? "OK" : "FAIL"; + validationLog(String.format("%s %s %dms, %s", name, resultString, latency, connectInfo)); + logValidationProbe(latency, ValidationProbeEvent.PROBE_DNS, result); + } + + /** + * Do a URL fetch on a known web server to see if we get the data we expect. + * @return a CaptivePortalProbeResult inferred from the HTTP response. */ @VisibleForTesting protected CaptivePortalProbeResult sendHttpProbe(URL url, int probeType) { @@ -829,7 +836,7 @@ public class NetworkMonitor extends StateMachine { } private CaptivePortalProbeResult sendParallelHttpProbes( - URL httpsUrl, URL httpUrl, URL fallbackUrl) { + ProxyInfo proxy, URL httpsUrl, URL httpUrl, URL fallbackUrl) { // Number of probes to wait for. If a probe completes with a conclusive answer // it shortcuts the latch immediately by forcing the count to 0. final CountDownLatch latch = new CountDownLatch(2); @@ -849,9 +856,10 @@ public class NetworkMonitor extends StateMachine { @Override public void run() { if (mIsHttps) { - mResult = sendHttpProbe(httpsUrl, ValidationProbeEvent.PROBE_HTTPS); + mResult = + sendDnsAndHttpProbes(proxy, httpsUrl, ValidationProbeEvent.PROBE_HTTPS); } else { - mResult = sendHttpProbe(httpUrl, ValidationProbeEvent.PROBE_HTTP); + mResult = sendDnsAndHttpProbes(proxy, httpUrl, ValidationProbeEvent.PROBE_HTTP); } if ((mIsHttps && mResult.isSuccessful()) || (!mIsHttps && mResult.isPortal())) { // Stop waiting immediately if https succeeds or if http finds a portal.