WifiNative: Logging improvements for iface mgmt

Moved some spammy logs to under verbose logging flag. Also, modified
existing logs to print out more info about the iface. Otherwise logs
always print "wlan0" or "wlan1" which may not be useful for debugging.

Bug: 76100913
Test: Unit tests
Test: Manually verified logging.
Test: Ran WifiManagerTest & WifiSoftApTest locally
Change-Id: Id4d5061220f49ebc62baf72554ef2968df51ce3c

1 files changed, 56 insertions, 32 deletions

diff --git a/service/java/com/android/server/wifi/WifiNative.java b/service/java/com/android/server/wifi/WifiNative.java
index b5d3bfc8b..b33d6b1c4 100644
--- a/service/java/com/android/server/wifi/WifiNative.java
+++ b/service/java/com/android/server/wifi/WifiNative.java
@@ -77,6 +77,7 @@ public class WifiNative {
     private final INetworkManagementService mNwManagementService;
     private final PropertyService mPropertyService;
     private final WifiMetrics mWifiMetrics;
+    private boolean mVerboseLoggingEnabled = false;
 
     // TODO(b/69426063): Remove interfaceName from constructor once WifiStateMachine switches over
     // to the new interface management methods.
@@ -97,9 +98,10 @@ public class WifiNative {
      * Enable verbose logging for all sub modules.
      */
     public void enableVerboseLogging(int verbose) {
-        mWificondControl.enableVerboseLogging(verbose > 0 ? true : false);
-        mSupplicantStaIfaceHal.enableVerboseLogging(verbose > 0);
-        mWifiVendorHal.enableVerboseLogging(verbose > 0);
+        mVerboseLoggingEnabled = verbose > 0 ? true : false;
+        mWificondControl.enableVerboseLogging(mVerboseLoggingEnabled);
+        mSupplicantStaIfaceHal.enableVerboseLogging(mVerboseLoggingEnabled);
+        mWifiVendorHal.enableVerboseLogging(mVerboseLoggingEnabled);
     }
 
     /********************************************************
@@ -134,6 +136,20 @@ public class WifiNative {
             this.id = id;
             this.type = type;
         }
+
+        @Override
+        public String toString() {
+            StringBuffer sb = new StringBuffer();
+            sb.append("Iface:")
+                .append("{")
+                .append("Name=").append(name)
+                .append(",")
+                .append("Id=").append(id)
+                .append(",")
+                .append("Type=").append(type == IFACE_TYPE_STA ? "STA" : "AP")
+                .append("}");
+            return sb.toString();
+        }
     }
 
     /**
@@ -376,13 +392,13 @@ public class WifiNative {
     private void onClientInterfaceDestroyed(@NonNull Iface iface) {
         synchronized (mLock) {
             if (!unregisterNetworkObserver(iface.networkObserver)) {
-                Log.e(TAG, "Failed to unregister network observer for iface=" + iface.name);
+                Log.e(TAG, "Failed to unregister network observer on " + iface);
             }
             if (!mSupplicantStaIfaceHal.teardownIface(iface.name)) {
-                Log.e(TAG, "Failed to teardown iface in supplicant=" + iface.name);
+                Log.e(TAG, "Failed to teardown iface in supplicant on " + iface);
             }
             if (!mWificondControl.tearDownClientInterface(iface.name)) {
-                Log.e(TAG, "Failed to teardown iface in wificond=" + iface.name);
+                Log.e(TAG, "Failed to teardown iface in wificond on " + iface);
             }
             stopSupplicantIfNecessary();
             stopHalAndWificondIfNecessary();
@@ -393,20 +409,20 @@ public class WifiNative {
     private void onSoftApInterfaceDestroyed(@NonNull Iface iface) {
         synchronized (mLock) {
             if (!unregisterNetworkObserver(iface.networkObserver)) {
-                Log.e(TAG, "Failed to unregister network observer for iface=" + iface.name);
+                Log.e(TAG, "Failed to unregister network observer on " + iface);
             }
             if (!mHostapdHal.removeAccessPoint(iface.name)) {
-                Log.e(TAG, "Failed to remove access point on iface=" + iface.name);
+                Log.e(TAG, "Failed to remove access point on " + iface);
             }
             if (!mHostapdHal.deregisterDeathHandler()) {
                 Log.e(TAG, "Failed to deregister supplicant death handler");
             }
             // TODO(b/71513606): Move this to a global operation.
             if (!mWificondControl.stopHostapd(iface.name)) {
-                Log.e(TAG, "Failed to stop hostapd on iface=" + iface.name);
+                Log.e(TAG, "Failed to stop hostapd on " + iface);
             }
             if (!mWificondControl.tearDownSoftApInterface(iface.name)) {
-                Log.e(TAG, "Failed to teardown iface in wificond=" + iface.name);
+                Log.e(TAG, "Failed to teardown iface in wificond on " + iface);
             }
             stopHalAndWificondIfNecessary();
         }
@@ -442,12 +458,14 @@ public class WifiNative {
             synchronized (mLock) {
                 final Iface iface = mIfaceMgr.removeIface(mInterfaceId);
                 if (iface == null) {
-                    Log.e(TAG, "Received iface destroyed notification on an invalid iface="
-                            + ifaceName);
+                    if (mVerboseLoggingEnabled) {
+                        Log.v(TAG, "Received iface destroyed notification on an invalid iface="
+                                + ifaceName);
+                    }
                     return;
                 }
                 onInterfaceDestroyed(iface);
-                Log.i(TAG, "Successfully torn down iface=" + ifaceName);
+                Log.i(TAG, "Successfully torn down " + iface);
             }
         }
     }
@@ -528,10 +546,13 @@ public class WifiNative {
         synchronized (mLock) {
             // Mask multiple notifications with the same state.
             if (isUp == iface.isUp) {
-                Log.d(TAG, "Interface status unchanged from " + isUp + ", Ignoring...");
+                if (mVerboseLoggingEnabled) {
+                    Log.v(TAG, "Interface status unchanged on " + iface + " from " + isUp
+                            + ", Ignoring...");
+                }
                 return;
             }
-            Log.i(TAG, "Interface link state changed=" + iface.name + ", isUp=" + isUp);
+            Log.i(TAG, "Interface link state changed on " + iface + ", isUp=" + isUp);
             if (isUp) {
                 iface.externalListener.onUp(iface.name);
             } else {
@@ -557,14 +578,18 @@ public class WifiNative {
             synchronized (mLock) {
                 final Iface ifaceWithId = mIfaceMgr.getIface(mInterfaceId);
                 if (ifaceWithId == null) {
-                    Log.e(TAG, "Received iface up/down notification on an invalid iface="
-                            + mInterfaceId);
+                    if (mVerboseLoggingEnabled) {
+                        Log.v(TAG, "Received iface up/down notification on an invalid iface="
+                                + mInterfaceId);
+                    }
                     return;
                 }
                 final Iface ifaceWithName = mIfaceMgr.getIface(ifaceName);
                 if (ifaceWithName == null || ifaceWithName != ifaceWithId) {
-                    Log.e(TAG, "Received iface up/down notification on an invalid iface="
-                            + ifaceName);
+                    if (mVerboseLoggingEnabled) {
+                        Log.v(TAG, "Received iface up/down notification on an invalid iface="
+                                + ifaceName);
+                    }
                     return;
                 }
                 onInterfaceStateChanged(ifaceWithName, isUp);
@@ -579,7 +604,7 @@ public class WifiNative {
         Iface existingIface = mIfaceMgr.removeExistingIface(newIface.id);
         if (existingIface != null) {
             onInterfaceDestroyed(existingIface);
-            Log.i(TAG, "Successfully torn down iface=" + existingIface.name);
+            Log.i(TAG, "Successfully torn down " + existingIface);
         }
         // Return the interface name directly from the system property.
         return mPropertyService.getString("wifi.interface", "wlan0");
@@ -625,7 +650,7 @@ public class WifiNative {
     private boolean handleIfaceRemovalWhenVendorHalNotSupported(@NonNull Iface iface) {
         mIfaceMgr.removeIface(iface.id);
         onInterfaceDestroyed(iface);
-        Log.i(TAG, "Successfully torn down iface=" + iface.name);
+        Log.i(TAG, "Successfully torn down " + iface);
         return true;
     }
 
@@ -782,26 +807,26 @@ public class WifiNative {
             iface.externalListener = interfaceCallback;
             iface.name = createStaIface(iface, lowPrioritySta);
             if (TextUtils.isEmpty(iface.name)) {
-                Log.e(TAG, "Failed to create iface in vendor HAL");
+                Log.e(TAG, "Failed to create STA iface in vendor HAL");
                 mIfaceMgr.removeIface(iface.id);
                 mWifiMetrics.incrementNumWifiOnFailureDueToHal();
                 return null;
             }
             if (mWificondControl.setupInterfaceForClientMode(iface.name) == null) {
-                Log.e(TAG, "Failed to setup iface in wificond=" + iface.name);
+                Log.e(TAG, "Failed to setup iface in wificond on " + iface);
                 teardownInterface(iface.name);
                 mWifiMetrics.incrementNumWifiOnFailureDueToWificond();
                 return null;
             }
             if (!mSupplicantStaIfaceHal.setupIface(iface.name)) {
-                Log.e(TAG, "Failed to setup iface in supplicant=" + iface.name);
+                Log.e(TAG, "Failed to setup iface in supplicant on " + iface);
                 teardownInterface(iface.name);
                 mWifiMetrics.incrementNumWifiOnFailureDueToSupplicant();
                 return null;
             }
             iface.networkObserver = new NetworkObserverInternal(iface.id);
             if (!registerNetworkObserver(iface.networkObserver)) {
-                Log.e(TAG, "Failed to register network observer for iface=" + iface.name);
+                Log.e(TAG, "Failed to register network observer on " + iface);
                 teardownInterface(iface.name);
                 return null;
             }
@@ -809,7 +834,7 @@ public class WifiNative {
             // update the interface state before we exit.
             onInterfaceStateChanged(iface, isInterfaceUp(iface.name));
             initializeNwParamsForClientInterface(iface.name);
-            Log.i(TAG, "Successfully setup iface=" + iface.name);
+            Log.i(TAG, "Successfully setup " + iface);
             return iface.name;
         }
     }
@@ -838,14 +863,14 @@ public class WifiNative {
             iface.externalListener = interfaceCallback;
             iface.name = createApIface(iface);
             if (TextUtils.isEmpty(iface.name)) {
-                Log.e(TAG, "Failed to create iface in vendor HAL");
+                Log.e(TAG, "Failed to create AP iface in vendor HAL");
                 mIfaceMgr.removeIface(iface.id);
                 // TODO(b/68716726): Separate SoftAp metrics
                 mWifiMetrics.incrementNumWifiOnFailureDueToHal();
                 return null;
             }
             if (mWificondControl.setupInterfaceForSoftApMode(iface.name) == null) {
-                Log.e(TAG, "Failed to setup iface in wificond=" + iface.name);
+                Log.e(TAG, "Failed to setup iface in wificond on " + iface);
                 teardownInterface(iface.name);
                 // TODO(b/68716726): Separate SoftAp metrics
                 mWifiMetrics.incrementNumWifiOnFailureDueToWificond();
@@ -853,14 +878,14 @@ public class WifiNative {
             }
             iface.networkObserver = new NetworkObserverInternal(iface.id);
             if (!registerNetworkObserver(iface.networkObserver)) {
-                Log.e(TAG, "Failed to register network observer for iface=" + iface.name);
+                Log.e(TAG, "Failed to register network observer on " + iface);
                 teardownInterface(iface.name);
                 return null;
             }
             // Just to avoid any race conditions with interface state change callbacks,
             // update the interface state before we exit.
             onInterfaceStateChanged(iface, isInterfaceUp(iface.name));
-            Log.i(TAG, "Successfully setup iface=" + iface.name);
+            Log.i(TAG, "Successfully setup " + iface);
             return iface.name;
         }
     }
@@ -937,7 +962,7 @@ public class WifiNative {
                 Iface iface = mIfaceMgr.getIface(ifaceIdIter.next());
                 ifaceIdIter.remove();
                 onInterfaceDestroyed(iface);
-                Log.i(TAG, "Successfully torn down iface=" + iface.name);
+                Log.i(TAG, "Successfully torn down " + iface);
             }
             Log.i(TAG, "Successfully torn down all ifaces");
         }
@@ -2656,7 +2681,6 @@ public class WifiNative {
      * @param ifaceName Name of the interface.
      */
     public boolean configureRoaming(@NonNull String ifaceName, RoamingConfig config) {
-        Log.d(TAG, "configureRoaming ");
         return mWifiVendorHal.configureRoaming(ifaceName, config);
     }