Detect+trigger bugreport for abnormal connections

This is an effort investigate why certain connections take really long
to finish.

Users running user-debug builds will be shown an notification, which
they may tap on to file a bugreport.

Added DeviceConfig flags (that is disabled by default) which may be
configured on the server side to enable this feature for a select group
of users. Also added a flag to fine tune the threshold at which
bugreports get triggered.

Bug: 132648941
Test: Unit tests
Test: Tested turning on the bugreport trigger with "adb shell
device_config put wifi abnormal_connection_bugreport_enabled true"
Test: Ran "adb shell device_config put wifi abnormal_connection_duration_ms 30" and verified that bugreport is taken

Change-Id: Ic4ea7c1850677781838a645b989f81db858546f4
diff --git a/service/java/com/android/server/wifi/ClientModeImpl.java b/service/java/com/android/server/wifi/ClientModeImpl.java
index a18760c..292e902 100644
--- a/service/java/com/android/server/wifi/ClientModeImpl.java
+++ b/service/java/com/android/server/wifi/ClientModeImpl.java
@@ -959,6 +959,8 @@
                 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) {
@@ -4292,6 +4294,7 @@
                     }
 
                     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/DeviceConfigFacade.java b/service/java/com/android/server/wifi/DeviceConfigFacade.java
new file mode 100644
index 0000000..c64cd52
--- /dev/null
+++ b/service/java/com/android/server/wifi/DeviceConfigFacade.java
@@ -0,0 +1,57 @@
+/*
+ * Copyright (C) 2019 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package com.android.server.wifi;
+
+import android.provider.DeviceConfig;
+
+import java.util.concurrent.Executor;
+import java.util.concurrent.TimeUnit;
+
+/**
+ * This class allows getting all configurable flags from DeviceConfig.
+ */
+public class DeviceConfigFacade {
+    private static final int DEFAULT_ABNORMAL_CONNECTION_DURATION_MS =
+            (int) TimeUnit.SECONDS.toMillis(30);
+    private static final String NAMESPACE = "wifi";
+
+    /**
+     * Gets the feature flag for reporting abnormally long connections.
+     */
+    public boolean isAbnormalConnectionBugreportEnabled() {
+        return DeviceConfig.getBoolean(NAMESPACE, "abnormal_connection_bugreport_enabled", false);
+    }
+
+    /**
+     * Gets the threshold for classifying abnormally long connections.
+     */
+    public int getAbnormalConnectionDurationMs() {
+        return DeviceConfig.getInt(NAMESPACE, "abnormal_connection_duration_ms",
+                DEFAULT_ABNORMAL_CONNECTION_DURATION_MS);
+    }
+
+    /**
+     * Adds a listener that will be run on the specified executor.
+     * @param executor
+     * @param onPropertiesChangedListener
+     */
+    public void addOnPropertiesChangedListener(Executor executor,
+            DeviceConfig.OnPropertiesChangedListener onPropertiesChangedListener) {
+        DeviceConfig.addOnPropertiesChangedListener(NAMESPACE, executor,
+                onPropertiesChangedListener);
+    }
+}
diff --git a/service/java/com/android/server/wifi/WifiInjector.java b/service/java/com/android/server/wifi/WifiInjector.java
index f33c7cf..ade295c 100644
--- a/service/java/com/android/server/wifi/WifiInjector.java
+++ b/service/java/com/android/server/wifi/WifiInjector.java
@@ -82,6 +82,7 @@
 
     private final Context mContext;
     private final FrameworkFacade mFrameworkFacade = new FrameworkFacade();
+    private final DeviceConfigFacade mDeviceConfigFacade;
     private final HandlerThread mWifiServiceHandlerThread;
     private final HandlerThread mWifiCoreHandlerThread;
     private final HandlerThread mWifiP2pServiceHandlerThread;
@@ -168,6 +169,7 @@
         sWifiInjector = this;
 
         mContext = context;
+        mDeviceConfigFacade = new DeviceConfigFacade();
         mWifiScoreCard = new WifiScoreCard(mClock,
                 Secure.getString(mContext.getContentResolver(), Secure.ANDROID_ID));
         mSettingsStore = new WifiSettingsStore(mContext);
@@ -605,8 +607,9 @@
                 mWifiCoreHandlerThread.getLooper(), mFrameworkFacade, mClock, mWifiMetrics,
                 mWifiConfigManager, mWifiConfigStore, clientModeImpl,
                 new ConnectToNetworkNotificationBuilder(mContext, mFrameworkFacade));
-        mWifiLastResortWatchdog = new WifiLastResortWatchdog(this, mClock,
-                mWifiMetrics, clientModeImpl, clientModeImpl.getHandler().getLooper());
+        mWifiLastResortWatchdog = new WifiLastResortWatchdog(this, mContext, mClock,
+                mWifiMetrics, clientModeImpl, clientModeImpl.getHandler().getLooper(),
+                mDeviceConfigFacade);
         return new WifiConnectivityManager(mContext, getScoringParams(),
                 clientModeImpl, this,
                 mWifiConfigManager, clientModeImpl.getWifiInfo(),
diff --git a/service/java/com/android/server/wifi/WifiLastResortWatchdog.java b/service/java/com/android/server/wifi/WifiLastResortWatchdog.java
index 6889b50..e8a0688 100644
--- a/service/java/com/android/server/wifi/WifiLastResortWatchdog.java
+++ b/service/java/com/android/server/wifi/WifiLastResortWatchdog.java
@@ -16,10 +16,12 @@
 
 package com.android.server.wifi;
 
+import android.content.Context;
 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;
@@ -75,6 +77,10 @@
     @VisibleForTesting
     public static final long LAST_TRIGGER_TIMEOUT_MILLIS = 2 * 3600 * 1000; // 2 hours
 
+    private int mAbnormalConnectionDurationMs;
+    private boolean mAbnormalConnectionBugreportEnabled;
+
+
     /**
      * Cached WifiConfigurations of available networks seen within MAX_BSSID_AGE scan results
      * Key:BSSID, Value:Counters of failure types
@@ -102,22 +108,95 @@
     private Looper mClientModeImplLooper;
     private double mBugReportProbability = PROB_TAKE_BUGREPORT_DEFAULT;
     private Clock mClock;
+    private Context mContext;
+    private DeviceConfigFacade mDeviceConfigFacade;
     // 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.
      */
     private final LocalLog mLocalLog = new LocalLog(100);
 
-    WifiLastResortWatchdog(WifiInjector wifiInjector, Clock clock, WifiMetrics wifiMetrics,
-            ClientModeImpl clientModeImpl, Looper clientModeImplLooper) {
+    WifiLastResortWatchdog(WifiInjector wifiInjector, Context context, Clock clock,
+            WifiMetrics wifiMetrics, ClientModeImpl clientModeImpl, Looper clientModeImplLooper,
+            DeviceConfigFacade deviceConfigFacade) {
         mWifiInjector = wifiInjector;
         mClock = clock;
         mWifiMetrics = wifiMetrics;
         mClientModeImpl = clientModeImpl;
         mClientModeImplLooper = clientModeImplLooper;
+        mContext = context;
+        mDeviceConfigFacade = deviceConfigFacade;
+        updateDeviceConfigFlags();
+        mHandler = new Handler(clientModeImplLooper) {
+            public void handleMessage(Message msg) {
+                processMessage(msg);
+            }
+        };
+
+        mDeviceConfigFacade.addOnPropertiesChangedListener(
+                command -> mHandler.post(command),
+                properties -> {
+                    updateDeviceConfigFlags();
+                });
+    }
+
+    private void updateDeviceConfigFlags() {
+        mAbnormalConnectionBugreportEnabled =
+                mDeviceConfigFacade.isAbnormalConnectionBugreportEnabled();
+        mAbnormalConnectionDurationMs =
+                mDeviceConfigFacade.getAbnormalConnectionDurationMs();
+        logv("updateDeviceConfigFlags: mAbnormalConnectionDurationMs = "
+                + mAbnormalConnectionDurationMs
+                + ", mAbnormalConnectionBugreportEnabled = "
+                + mAbnormalConnectionBugreportEnabled);
+    }
+
+    /**
+     * 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() {
+        mHandler.post(() -> {
+            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 (mAbnormalConnectionBugreportEnabled && mLastStartConnectTime > 0) {
+                    long durationMs = mClock.getElapsedSinceBootMillis() - mLastStartConnectTime;
+                    if (durationMs > mAbnormalConnectionDurationMs) {
+                        final String bugTitle = "Wi-Fi Bugreport: Abnormal connection time";
+                        final String bugDetail = "Expected connection to take less than "
+                                + mAbnormalConnectionDurationMs + " milliseconds. "
+                                + "Actually took " + durationMs + " milliseconds.";
+                        logv("Triggering bug report for abnormal connection time.");
+                        mWifiInjector.getClientModeImplHandler().post(() -> {
+                            mClientModeImpl.takeBugReport(bugTitle, bugDetail);
+                        });
+                    }
+                }
+                // Should reset last connection time after each connection regardless if bugreport
+                // is enabled or not.
+                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 9ae3826..7c55228 100644
--- a/tests/wifitests/src/com/android/server/wifi/WifiLastResortWatchdogTest.java
+++ b/tests/wifitests/src/com/android/server/wifi/WifiLastResortWatchdogTest.java
@@ -21,16 +21,20 @@
 import static org.mockito.Mockito.*;
 import static org.mockito.MockitoAnnotations.*;
 
+import android.content.Context;
 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.provider.DeviceConfig.OnPropertiesChangedListener;
 import android.util.Pair;
 
 import androidx.test.filters.SmallTest;
 
 import org.junit.Before;
 import org.junit.Test;
+import org.mockito.ArgumentCaptor;
 import org.mockito.Mock;
 
 import java.util.ArrayList;
@@ -42,6 +46,8 @@
  */
 @SmallTest
 public class WifiLastResortWatchdogTest {
+    final ArgumentCaptor<OnPropertiesChangedListener> mOnPropertiesChangedListenerCaptor =
+            ArgumentCaptor.forClass(OnPropertiesChangedListener.class);
     WifiLastResortWatchdog mLastResortWatchdog;
     @Mock WifiInjector mWifiInjector;
     @Mock WifiMetrics mWifiMetrics;
@@ -49,6 +55,8 @@
     @Mock ClientModeImpl mClientModeImpl;
     @Mock Clock mClock;
     @Mock WifiInfo mWifiInfo;
+    @Mock Context mContext;
+    @Mock DeviceConfigFacade mDeviceConfigFacade;
 
     private String[] mSsids = {"\"test1\"", "\"test2\"", "\"test3\"", "\"test4\""};
     private String[] mBssids = {"6c:f3:7f:ae:8c:f3", "6c:f3:7f:ae:8c:f4", "de:ad:ba:b1:e5:55",
@@ -61,17 +69,24 @@
     private boolean[] mHasEverConnected = {false, false, false, false};
     private TestLooper mLooper;
     private static final String TEST_NETWORK_SSID = "\"test_ssid\"";
+    private static final int DEFAULT_ABNORMAL_CONNECTION_DURATION_MS = 30000;
 
     @Before
     public void setUp() throws Exception {
         initMocks(this);
         mLooper = new TestLooper();
         when(mWifiInjector.getSelfRecovery()).thenReturn(mSelfRecovery);
-        mLastResortWatchdog = new WifiLastResortWatchdog(mWifiInjector, mClock, mWifiMetrics,
-                mClientModeImpl, mLooper.getLooper());
+        when(mDeviceConfigFacade.isAbnormalConnectionBugreportEnabled()).thenReturn(true);
+        when(mDeviceConfigFacade.getAbnormalConnectionDurationMs()).thenReturn(
+                        DEFAULT_ABNORMAL_CONNECTION_DURATION_MS);
+        mLastResortWatchdog = new WifiLastResortWatchdog(mWifiInjector, mContext, mClock,
+                mWifiMetrics, mClientModeImpl, mLooper.getLooper(), mDeviceConfigFacade);
         mLastResortWatchdog.setBugReportProbability(1);
         when(mClientModeImpl.getWifiInfo()).thenReturn(mWifiInfo);
         when(mWifiInfo.getSSID()).thenReturn(TEST_NETWORK_SSID);
+        when(mWifiInjector.getClientModeImplHandler()).thenReturn(mLastResortWatchdog.getHandler());
+        verify(mDeviceConfigFacade).addOnPropertiesChangedListener(any(),
+                mOnPropertiesChangedListenerCaptor.capture());
     }
 
     private List<Pair<ScanDetail, WifiConfiguration>> createFilteredQnsCandidates(String[] ssids,
@@ -2152,4 +2167,91 @@
         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
+        // DEFAULT_ABNORMAL_CONNECTION_DURATION_MS
+        when(mClock.getElapsedSinceBootMillis()).thenReturn(1L);
+        mLastResortWatchdog.noteStartConnectTime();
+        mLooper.dispatchAll();
+        when(mClock.getElapsedSinceBootMillis()).thenReturn(
+                (long) DEFAULT_ABNORMAL_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();
+        mLooper.dispatchAll();
+        when(mClock.getElapsedSinceBootMillis()).thenReturn(
+                2L * DEFAULT_ABNORMAL_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(
+                4L * DEFAULT_ABNORMAL_CONNECTION_DURATION_MS);
+        handler.sendMessage(
+                handler.obtainMessage(WifiMonitor.NETWORK_CONNECTION_EVENT, 0, 0, null));
+        mLooper.dispatchAll();
+        verify(mClientModeImpl).takeBugReport(anyString(), anyString());
+    }
+
+    /**
+     * Changes |mAbnormalConnectionDurationMs| to a new value, and then verify that a bugreport is
+     * taken for a connection that takes longer than the new threshold.
+     * @throws Exception
+     */
+    @Test
+    public void testGServicesSetDuration() throws Exception {
+        final int testDurationMs = 10 * 1000; // 10 seconds
+        // changes the abnormal connection duration to |testDurationMs|.
+        when(mDeviceConfigFacade.getAbnormalConnectionDurationMs()).thenReturn(testDurationMs);
+        mOnPropertiesChangedListenerCaptor.getValue().onPropertiesChanged(null);
+
+        // verifies that bugreport is taken for connections that take longer than |testDurationMs|.
+        when(mClock.getElapsedSinceBootMillis()).thenReturn(1L);
+        mLastResortWatchdog.noteStartConnectTime();
+        mLooper.dispatchAll();
+        when(mClock.getElapsedSinceBootMillis()).thenReturn((long) testDurationMs + 2);
+        Handler handler = mLastResortWatchdog.getHandler();
+        handler.sendMessage(
+                handler.obtainMessage(WifiMonitor.NETWORK_CONNECTION_EVENT, 0, 0, null));
+        mLooper.dispatchAll();
+        verify(mClientModeImpl).takeBugReport(anyString(), anyString());
+    }
+
+    /**
+     * Verifies that bugreports are not triggered even when conditions are met after the
+     * |mAbnormalConnectionBugreportEnabled| flag is changed to false.
+     * @throws Exception
+     */
+    @Test
+    public void testGServicesFlagDisable() throws Exception {
+        // changes |mAbnormalConnectionBugreportEnabled| to false.
+        when(mDeviceConfigFacade.isAbnormalConnectionBugreportEnabled()).thenReturn(false);
+        mOnPropertiesChangedListenerCaptor.getValue().onPropertiesChanged(null);
+
+        // verifies that bugreports are not taken.
+        when(mClock.getElapsedSinceBootMillis()).thenReturn(1L);
+        mLastResortWatchdog.noteStartConnectTime();
+        mLooper.dispatchAll();
+        when(mClock.getElapsedSinceBootMillis()).thenReturn(
+                (long) DEFAULT_ABNORMAL_CONNECTION_DURATION_MS + 2);
+        Handler handler = mLastResortWatchdog.getHandler();
+        handler.sendMessage(
+                handler.obtainMessage(WifiMonitor.NETWORK_CONNECTION_EVENT, 0, 0, null));
+        mLooper.dispatchAll();
+        verify(mClientModeImpl, never()).takeBugReport(anyString(), anyString());
+    }
 }