From c6cb88c37c22daeeac819726cc91b6c452791a46 Mon Sep 17 00:00:00 2001 From: xshu Date: Tue, 21 May 2019 17:34:56 -0700 Subject: Trigger bugreport for abnormally long connections Bug: 132648941 Test: Unit tests Test: mannually tested with a smaller threshold to verify bugreport is triggering properly. Change-Id: I2f5f9c9c08874f6f356a081b0a2575dd3851c241 --- .../com/android/server/wifi/ClientModeImpl.java | 3 ++ .../server/wifi/WifiLastResortWatchdog.java | 48 ++++++++++++++++++++++ .../server/wifi/WifiLastResortWatchdogTest.java | 39 ++++++++++++++++++ 3 files changed, 90 insertions(+) diff --git a/service/java/com/android/server/wifi/ClientModeImpl.java b/service/java/com/android/server/wifi/ClientModeImpl.java index 4adf27ff0..008135051 100644 --- a/service/java/com/android/server/wifi/ClientModeImpl.java +++ b/service/java/com/android/server/wifi/ClientModeImpl.java @@ -955,6 +955,8 @@ public class ClientModeImpl extends StateMachine { mWifiMetrics.getHandler()); mWifiMonitor.registerHandler(mInterfaceName, CMD_TARGET_BSSID, mWifiMetrics.getHandler()); + mWifiMonitor.registerHandler(mInterfaceName, WifiMonitor.NETWORK_CONNECTION_EVENT, + mWifiInjector.getWifiLastResortWatchdog().getHandler()); } private void setMulticastFilter(boolean enabled) { @@ -4274,6 +4276,7 @@ public class ClientModeImpl extends StateMachine { mWifiInfo.setMacAddress(currentMacAddress); Log.i(TAG, "Connecting with " + currentMacAddress + " as the mac address"); if (mWifiNative.connectToNetwork(mInterfaceName, config)) { + mWifiInjector.getWifiLastResortWatchdog().noteStartConnectTime(); mWifiMetrics.logStaEvent(StaEvent.TYPE_CMD_START_CONNECT, config); mLastConnectAttemptTimestamp = mClock.getWallClockMillis(); mTargetWifiConfiguration = config; diff --git a/service/java/com/android/server/wifi/WifiLastResortWatchdog.java b/service/java/com/android/server/wifi/WifiLastResortWatchdog.java index 6889b5016..286e4ba47 100644 --- a/service/java/com/android/server/wifi/WifiLastResortWatchdog.java +++ b/service/java/com/android/server/wifi/WifiLastResortWatchdog.java @@ -20,6 +20,7 @@ import android.net.wifi.ScanResult; import android.net.wifi.WifiConfiguration; import android.os.Handler; import android.os.Looper; +import android.os.Message; import android.text.TextUtils; import android.util.LocalLog; import android.util.Log; @@ -74,6 +75,8 @@ public class WifiLastResortWatchdog { // Number of milliseconds to wait before re-enable Watchdog triger @VisibleForTesting public static final long LAST_TRIGGER_TIMEOUT_MILLIS = 2 * 3600 * 1000; // 2 hours + @VisibleForTesting + public static final int ABNORMAL_SUCCESSFUL_CONNECTION_DURATION_MS = 1000 * 30; // 30 seconds /** * Cached WifiConfigurations of available networks seen within MAX_BSSID_AGE scan results @@ -105,6 +108,8 @@ public class WifiLastResortWatchdog { // If any connection failure happened after watchdog triggering restart then assume watchdog // did not fix the problem private boolean mWatchdogFixedWifi = true; + private long mLastStartConnectTime = 0; + private Handler mHandler; /** * Local log used for debugging any WifiLastResortWatchdog issues. @@ -118,6 +123,49 @@ public class WifiLastResortWatchdog { mWifiMetrics = wifiMetrics; mClientModeImpl = clientModeImpl; mClientModeImplLooper = clientModeImplLooper; + mHandler = new Handler(clientModeImplLooper) { + public void handleMessage(Message msg) { + processMessage(msg); + } + }; + } + + /** + * Returns handler for L2 events from supplicant. + * @return Handler + */ + public Handler getHandler() { + return mHandler; + } + + /** + * Refreshes when the last CMD_START_CONNECT is triggered. + */ + public void noteStartConnectTime() { + mLastStartConnectTime = mClock.getElapsedSinceBootMillis(); + } + + private void processMessage(Message msg) { + switch (msg.what) { + case WifiMonitor.NETWORK_CONNECTION_EVENT: + // Trigger bugreport for successful connections that take abnormally long + if (mLastStartConnectTime > 0) { + long durationMs = mClock.getElapsedSinceBootMillis() - mLastStartConnectTime; + if (durationMs > ABNORMAL_SUCCESSFUL_CONNECTION_DURATION_MS) { + final String bugTitle = "Wi-Fi Bugreport: Abnormal connection time"; + final String bugDetail = "Expected connection to take less than " + + ABNORMAL_SUCCESSFUL_CONNECTION_DURATION_MS + " milliseconds. " + + "Actually took " + durationMs + " milliseconds."; + mWifiInjector.getClientModeImplHandler().post(() -> { + mClientModeImpl.takeBugReport(bugTitle, bugDetail); + }); + } + mLastStartConnectTime = 0; + } + break; + default: + return; + } } /** diff --git a/tests/wifitests/src/com/android/server/wifi/WifiLastResortWatchdogTest.java b/tests/wifitests/src/com/android/server/wifi/WifiLastResortWatchdogTest.java index 9ae382640..dab283539 100644 --- a/tests/wifitests/src/com/android/server/wifi/WifiLastResortWatchdogTest.java +++ b/tests/wifitests/src/com/android/server/wifi/WifiLastResortWatchdogTest.java @@ -24,6 +24,7 @@ import static org.mockito.MockitoAnnotations.*; import android.net.wifi.WifiConfiguration; import android.net.wifi.WifiInfo; import android.net.wifi.WifiSsid; +import android.os.Handler; import android.os.test.TestLooper; import android.util.Pair; @@ -72,6 +73,7 @@ public class WifiLastResortWatchdogTest { mLastResortWatchdog.setBugReportProbability(1); when(mClientModeImpl.getWifiInfo()).thenReturn(mWifiInfo); when(mWifiInfo.getSSID()).thenReturn(TEST_NETWORK_SSID); + when(mWifiInjector.getClientModeImplHandler()).thenReturn(mLastResortWatchdog.getHandler()); } private List> createFilteredQnsCandidates(String[] ssids, @@ -2152,4 +2154,41 @@ public class WifiLastResortWatchdogTest { verify(mWifiMetrics, times(1)).incrementNumLastResortWatchdogSuccesses(); } + /** + * Verifies that when a connection takes too long (time difference between + * StaEvent.TYPE_CMD_START_CONNECT and StaEvent.TYPE_NETWORK_CONNECTION_EVENT) a bugreport is + * taken. + */ + @Test + public void testAbnormalConnectionTimeTriggersBugreport() throws Exception { + // first verifies that bugreports are not taken when connection takes less than + // WifiLastResortWatchdog.ABNORMAL_SUCCESSFUL_CONNECTION_DURATION_MS + when(mClock.getElapsedSinceBootMillis()).thenReturn(1L); + mLastResortWatchdog.noteStartConnectTime(); + when(mClock.getElapsedSinceBootMillis()).thenReturn( + (long) WifiLastResortWatchdog.ABNORMAL_SUCCESSFUL_CONNECTION_DURATION_MS); + Handler handler = mLastResortWatchdog.getHandler(); + handler.sendMessage( + handler.obtainMessage(WifiMonitor.NETWORK_CONNECTION_EVENT, 0, 0, null)); + mLooper.dispatchAll(); + verify(mClientModeImpl, never()).takeBugReport(anyString(), anyString()); + + // Now verify that bugreport is taken + mLastResortWatchdog.noteStartConnectTime(); + when(mClock.getElapsedSinceBootMillis()).thenReturn( + (long) 2 * WifiLastResortWatchdog.ABNORMAL_SUCCESSFUL_CONNECTION_DURATION_MS + 1); + handler.sendMessage( + handler.obtainMessage(WifiMonitor.NETWORK_CONNECTION_EVENT, 0, 0, null)); + mLooper.dispatchAll(); + verify(mClientModeImpl).takeBugReport(anyString(), anyString()); + + // Verify additional connections (without more TYPE_CMD_START_CONNECT) don't trigger more + // bugreports. + when(mClock.getElapsedSinceBootMillis()).thenReturn( + (long) 4 * WifiLastResortWatchdog.ABNORMAL_SUCCESSFUL_CONNECTION_DURATION_MS); + handler.sendMessage( + handler.obtainMessage(WifiMonitor.NETWORK_CONNECTION_EVENT, 0, 0, null)); + mLooper.dispatchAll(); + verify(mClientModeImpl).takeBugReport(anyString(), anyString()); + } } -- cgit v1.2.3