From 147aa6d53bc1e9f8a3632553abcf936023806e1d Mon Sep 17 00:00:00 2001 From: Hugo Benichi Date: Tue, 15 Nov 2016 23:23:24 +0900 Subject: [PATCH 1/2] 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 Change-Id: If5687e310ddd18ed3096f8ecbdfc2ef866519234 --- ] | 12 +++++ .../android/net/metrics/NetworkEvent.java | 13 +++++ .../net/metrics/ValidationProbeEvent.java | 34 +++++++++---- .../server/connectivity/NetworkMonitor.java | 50 ++++++++++++++++++- 4 files changed, 97 insertions(+), 12 deletions(-) create mode 100644 ] diff --git a/] b/] new file mode 100644 index 0000000000000..5619151c7ee3e --- /dev/null +++ b/] @@ -0,0 +1,12 @@ +NetworkNotificationManager: logging improvements + +TODO: squash me +# Please enter the commit message for your changes. Lines starting +# with '#' will be ignored, and an empty message aborts the commit. +# On branch notification_tagging +# Your branch is ahead of 'goog/master' by 2 commits. +# (use "git push" to publish your local commits) +# +# Changes to be committed: +# modified: services/core/java/com/android/server/connectivity/NetworkNotificationManager.java +# 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 ab61e7c324b24e46829495bc2597e42ea907c53d Mon Sep 17 00:00:00 2001 From: Hugo Benichi Date: Wed, 16 Nov 2016 18:18:08 +0900 Subject: [PATCH 2/2] 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 Change-Id: I71ed6927f5d9cdab0d0236cc147fe1c5735a1245 --- .../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.