Refactor and improve logging.

Test: as follows
    - build
    - flashed
    - booted
    - "runtest frameworks-net" passed
    - "dumpsys connectivity" shows new log output
Bug: 32163131
Bug: 36504926

Change-Id: I14d6da18660223f7cace156cb6594ee18928a7b0

diff --git a/services/core/java/com/android/server/connectivity/Tethering.java b/services/core/java/com/android/server/connectivity/Tethering.java
index 9edc35e..4dae364 100644 (file)
--- a/services/core/java/com/android/server/connectivity/Tethering.java
+++ b/services/core/java/com/android/server/connectivity/Tethering.java
@@ -62,6 +62,7 @@ import android.telephony.CarrierConfigManager;
 import android.telephony.TelephonyManager;
 import android.text.TextUtils;
 import android.util.ArrayMap;
+import android.util.LocalLog;
 import android.util.Log;
 import android.util.SparseArray;
 
@@ -144,6 +145,10 @@ public class Tethering extends BaseNetworkObserver implements IControlsTethering
         }
     }
 
+    private final static int MAX_LOG_RECORDS = 500;
+
+    private final LocalLog mLocalLog = new LocalLog(MAX_LOG_RECORDS);
+
     // used to synchronize public access to members
     private final Object mPublicSync;
     private final Context mContext;
@@ -174,6 +179,7 @@ public class Tethering extends BaseNetworkObserver implements IControlsTethering
     public Tethering(Context context, INetworkManagementService nmService,
             INetworkStatsService statsService, INetworkPolicyManager policyManager,
             Looper looper, MockableSystemProperties systemProperties) {
+        mLocalLog.log("CONSTRUCTED");
         mContext = context;
         mNMService = nmService;
         mStatsService = statsService;
@@ -963,7 +969,7 @@ public class Tethering extends BaseNetworkObserver implements IControlsTethering
         return ConnectivityManager.TETHER_ERROR_NO_ERROR;
     }
 
-    // TODO review API - maybe return ArrayList<String> here and below?
+    // TODO review API - figure out how to delete these entirely.
     public String[] getTetheredIfaces() {
         ArrayList<String> list = new ArrayList<String>();
         synchronized (mPublicSync) {
@@ -1106,19 +1112,19 @@ public class Tethering extends BaseNetworkObserver implements IControlsTethering
 
             //Add states
             mInitialState = new InitialState();
-            addState(mInitialState);
             mTetherModeAliveState = new TetherModeAliveState();
-            addState(mTetherModeAliveState);
-
             mSetIpForwardingEnabledErrorState = new SetIpForwardingEnabledErrorState();
-            addState(mSetIpForwardingEnabledErrorState);
             mSetIpForwardingDisabledErrorState = new SetIpForwardingDisabledErrorState();
-            addState(mSetIpForwardingDisabledErrorState);
             mStartTetheringErrorState = new StartTetheringErrorState();
-            addState(mStartTetheringErrorState);
             mStopTetheringErrorState = new StopTetheringErrorState();
-            addState(mStopTetheringErrorState);
             mSetDnsForwardersErrorState = new SetDnsForwardersErrorState();
+
+            addState(mInitialState);
+            addState(mTetherModeAliveState);
+            addState(mSetIpForwardingEnabledErrorState);
+            addState(mSetIpForwardingDisabledErrorState);
+            addState(mStartTetheringErrorState);
+            addState(mStopTetheringErrorState);
             addState(mSetDnsForwardersErrorState);
 
             mNotifyList = new ArrayList<>();
@@ -1126,6 +1132,29 @@ public class Tethering extends BaseNetworkObserver implements IControlsTethering
             setInitialState(mInitialState);
         }
 
+        class InitialState extends State {
+            @Override
+            public boolean processMessage(Message message) {
+                maybeLogMessage(this, message.what);
+                switch (message.what) {
+                    case EVENT_IFACE_SERVING_STATE_ACTIVE:
+                        TetherInterfaceStateMachine who = (TetherInterfaceStateMachine)message.obj;
+                        if (VDBG) Log.d(TAG, "Tether Mode requested by " + who);
+                        handleInterfaceServingStateActive(message.arg1, who);
+                        transitionTo(mTetherModeAliveState);
+                        break;
+                    case EVENT_IFACE_SERVING_STATE_INACTIVE:
+                        who = (TetherInterfaceStateMachine)message.obj;
+                        if (VDBG) Log.d(TAG, "Tether Mode unrequested by " + who);
+                        handleInterfaceServingStateInactive(who);
+                        break;
+                    default:
+                        return NOT_HANDLED;
+                }
+                return HANDLED;
+            }
+        }
+
         class TetherMasterUtilState extends State {
             @Override
             public boolean processMessage(Message m) {
@@ -1146,6 +1175,7 @@ public class Tethering extends BaseNetworkObserver implements IControlsTethering
                 try {
                     mNMService.setIpForwardingEnabled(true);
                 } catch (Exception e) {
+                    mLocalLog.log("ERROR " + e);
                     transitionTo(mSetIpForwardingEnabledErrorState);
                     return false;
                 }
@@ -1158,10 +1188,12 @@ public class Tethering extends BaseNetworkObserver implements IControlsTethering
                         mNMService.stopTethering();
                         mNMService.startTethering(cfg.dhcpRanges);
                     } catch (Exception ee) {
+                        mLocalLog.log("ERROR " + ee);
                         transitionTo(mStartTetheringErrorState);
                         return false;
                     }
                 }
+                mLocalLog.log("SET master tether settings: ON");
                 return true;
             }
 
@@ -1169,16 +1201,19 @@ public class Tethering extends BaseNetworkObserver implements IControlsTethering
                 try {
                     mNMService.stopTethering();
                 } catch (Exception e) {
+                    mLocalLog.log("ERROR " + e);
                     transitionTo(mStopTetheringErrorState);
                     return false;
                 }
                 try {
                     mNMService.setIpForwardingEnabled(false);
                 } catch (Exception e) {
+                    mLocalLog.log("ERROR " + e);
                     transitionTo(mSetIpForwardingDisabledErrorState);
                     return false;
                 }
                 transitionTo(mInitialState);
+                mLocalLog.log("SET master tether settings: OFF");
                 return true;
             }
 
@@ -1302,16 +1337,15 @@ public class Tethering extends BaseNetworkObserver implements IControlsTethering
                     // TODO: remove this invocation of NetworkUtils.makeStrings().
                     dnsServers = NetworkUtils.makeStrings(dnses);
                 }
-                if (VDBG) {
-                    Log.d(TAG, "Setting DNS forwarders: Network=" + network +
-                           ", dnsServers=" + Arrays.toString(dnsServers));
-                }
                 try {
                     mNMService.setDnsForwarders(network, dnsServers);
+                    mLocalLog.log(String.format(
+                            "SET DNS forwarders: network=%s dnsServers=[%s]",
+                            network, Arrays.toString(dnsServers)));
                 } catch (Exception e) {
                     // TODO: Investigate how this can fail and what exactly
                     // happens if/when such failures occur.
-                    Log.e(TAG, "Setting DNS forwarders failed!");
+                    mLocalLog.log("ERROR setting DNS forwarders failed, " + e);
                     transitionTo(mSetDnsForwardersErrorState);
                 }
             }
@@ -1376,39 +1410,18 @@ public class Tethering extends BaseNetworkObserver implements IControlsTethering
             }
         }
 
-        class InitialState extends State {
-            @Override
-            public boolean processMessage(Message message) {
-                maybeLogMessage(this, message.what);
-                boolean retValue = true;
-                switch (message.what) {
-                    case EVENT_IFACE_SERVING_STATE_ACTIVE:
-                        TetherInterfaceStateMachine who = (TetherInterfaceStateMachine)message.obj;
-                        if (VDBG) Log.d(TAG, "Tether Mode requested by " + who);
-                        handleInterfaceServingStateActive(message.arg1, who);
-                        transitionTo(mTetherModeAliveState);
-                        break;
-                    case EVENT_IFACE_SERVING_STATE_INACTIVE:
-                        who = (TetherInterfaceStateMachine)message.obj;
-                        if (VDBG) Log.d(TAG, "Tether Mode unrequested by " + who);
-                        handleInterfaceServingStateInactive(who);
-                        break;
-                    default:
-                        retValue = false;
-                        break;
-                }
-                return retValue;
-            }
-        }
-
         class TetherModeAliveState extends TetherMasterUtilState {
             boolean mUpstreamWanted = false;
             boolean mTryCell = true;
 
             @Override
             public void enter() {
-                // TODO: examine if we should check the return value.
-                turnOnMasterTetherSettings(); // may transition us out
+                // If turning on master tether settings fails, we have already
+                // transitioned to an error state; exit early.
+                if (!turnOnMasterTetherSettings()) {
+                    return;
+                }
+
                 mSimChange.startListening();
                 mUpstreamNetworkMonitor.start();
                 mOffloadController.start();
@@ -1461,14 +1474,16 @@ public class Tethering extends BaseNetworkObserver implements IControlsTethering
                         handleInterfaceServingStateInactive(who);
 
                         if (mNotifyList.isEmpty()) {
-                            turnOffMasterTetherSettings(); // transitions appropriately
-                        } else {
-                            if (DBG) {
-                                Log.d(TAG, "TetherModeAlive still has " + mNotifyList.size() +
-                                        " live requests:");
-                                for (TetherInterfaceStateMachine o : mNotifyList) {
-                                    Log.d(TAG, "  " + o);
-                                }
+                            // transitions appropriately
+                            turnOffMasterTetherSettings();
+                            break;
+                        }
+
+                        if (DBG) {
+                            Log.d(TAG, "TetherModeAlive still has " + mNotifyList.size() +
+                                    " live requests:");
+                            for (TetherInterfaceStateMachine o : mNotifyList) {
+                                Log.d(TAG, "  " + o);
                             }
                         }
                         // If there has been a change and an upstream is no
@@ -1688,6 +1703,12 @@ public class Tethering extends BaseNetworkObserver implements IControlsTethering
             pw.println("Upstream wanted: " + upstreamWanted());
             pw.decreaseIndent();
         }
+
+        pw.println("Log:");
+        pw.increaseIndent();
+        mLocalLog.readOnlyLocalLog().dump(fd, pw, args);
+        pw.decreaseIndent();
+
         pw.decreaseIndent();
     }
 
@@ -1704,10 +1725,8 @@ public class Tethering extends BaseNetworkObserver implements IControlsTethering
             }
         }
 
-        if (DBG) {
-            Log.d(TAG, "iface " + iface + " notified that it was in state " + state +
-                    " with error " + error);
-        }
+        mLocalLog.log(String.format("OBSERVED iface=%s state=%s error=%s",
+                iface, state, error));
 
         try {
             // Notify that we're tethering (or not) this interface.

diff --git a/tests/net/java/com/android/server/connectivity/TetheringTest.java b/tests/net/java/com/android/server/connectivity/TetheringTest.java
index 7a1c239..3172c6e 100644 (file)
--- a/tests/net/java/com/android/server/connectivity/TetheringTest.java
+++ b/tests/net/java/com/android/server/connectivity/TetheringTest.java
@@ -18,12 +18,13 @@ package com.android.server.connectivity;
 
 import static org.junit.Assert.assertEquals;
 import static org.junit.Assert.assertTrue;
-import static org.mockito.Mockito.any;
 import static org.mockito.Matchers.anyBoolean;
 import static org.mockito.Matchers.anyInt;
 import static org.mockito.Matchers.anyString;
 import static org.mockito.Matchers.eq;
+import static org.mockito.Mockito.any;
 import static org.mockito.Mockito.atLeastOnce;
+import static org.mockito.Mockito.doThrow;
 import static org.mockito.Mockito.times;
 import static org.mockito.Mockito.verify;
 import static org.mockito.Mockito.verifyNoMoreInteractions;
@@ -47,6 +48,7 @@ import android.net.wifi.WifiManager;
 import android.os.Handler;
 import android.os.INetworkManagementService;
 import android.os.PersistableBundle;
+import android.os.RemoteException;
 import android.os.test.TestLooper;
 import android.os.UserHandle;
 import android.support.test.filters.SmallTest;
@@ -352,6 +354,56 @@ public class TetheringTest {
                 mTethering.getLastTetherError(mTestIfname));
     }
 
-    // TODO: Test that a request for hotspot mode doesn't interface with an
+    @Test
+    public void failureEnablingIpForwarding() throws Exception {
+        when(mConnectivityManager.isTetheringSupported()).thenReturn(true);
+        when(mWifiManager.startSoftAp(any(WifiConfiguration.class))).thenReturn(true);
+        doThrow(new RemoteException()).when(mNMService).setIpForwardingEnabled(true);
+
+        // Emulate pressing the WiFi tethering button.
+        mTethering.startTethering(ConnectivityManager.TETHERING_WIFI, null, false);
+        mLooper.dispatchAll();
+        verify(mWifiManager, times(1)).startSoftAp(null);
+        verifyNoMoreInteractions(mWifiManager);
+        verifyNoMoreInteractions(mConnectivityManager);
+        verifyNoMoreInteractions(mNMService);
+
+        // Emulate externally-visible WifiManager effects, causing the
+        // per-interface state machine to start up, and telling us that
+        // tethering mode is to be started.
+        mTethering.interfaceStatusChanged(mTestIfname, true);
+        sendWifiApStateChanged(WifiManager.WIFI_AP_STATE_ENABLED);
+        mLooper.dispatchAll();
+
+        // Activity caused by test_wlan0 becoming available.
+        verify(mNMService, times(1)).listInterfaces();
+        // We verify get/set called twice here: once for setup and once during
+        // teardown because all events happen over the course of the single
+        // dispatchAll() above.
+        verify(mNMService, times(2)).getInterfaceConfig(mTestIfname);
+        verify(mNMService, times(2))
+                .setInterfaceConfig(eq(mTestIfname), any(InterfaceConfiguration.class));
+        verify(mNMService, times(1)).tetherInterface(mTestIfname);
+        verify(mWifiManager).updateInterfaceIpState(
+                mTestIfname, WifiManager.IFACE_IP_MODE_TETHERED);
+        verify(mConnectivityManager, atLeastOnce()).isTetheringSupported();
+        verifyTetheringBroadcast(mTestIfname, ConnectivityManager.EXTRA_AVAILABLE_TETHER);
+        // This is called, but will throw.
+        verify(mNMService, times(1)).setIpForwardingEnabled(true);
+        // This never gets called because of the exception thrown above.
+        verify(mNMService, times(0)).startTethering(any(String[].class));
+        // When the master state machine transitions to an error state it tells
+        // downstream interfaces, which causes us to tell Wi-Fi about the error
+        // so it can take down AP mode.
+        verify(mNMService, times(1)).untetherInterface(mTestIfname);
+        verify(mWifiManager).updateInterfaceIpState(
+                mTestIfname, WifiManager.IFACE_IP_MODE_CONFIGURATION_ERROR);
+
+        verifyNoMoreInteractions(mWifiManager);
+        verifyNoMoreInteractions(mConnectivityManager);
+        verifyNoMoreInteractions(mNMService);
+    }
+
+    // TODO: Test that a request for hotspot mode doesn't interfere with an
     // already operating tethering mode interface.
 }