Merge "Add additional logging to improve debugability of VcnManagementService"

core/java/android/net/vcn/VcnNetworkPolicyResult.java

@@ -87,6 +87,16 @@ public final class VcnNetworkPolicyResult implements Parcelable {
                 && mNetworkCapabilities.equals(that.mNetworkCapabilities);
     }
 
+    @Override
+    public String toString() {
+        return "VcnNetworkPolicyResult { "
+                + "mIsTeardownRequested = "
+                + mIsTearDownRequested
+                + ", mNetworkCapabilities"
+                + mNetworkCapabilities
+                + " }";
+    }
+
     /** {@inheritDoc} */
     @Override
     public int describeContents() {

core/java/android/net/vcn/VcnUnderlyingNetworkPolicy.java

@@ -85,6 +85,11 @@ public final class VcnUnderlyingNetworkPolicy implements Parcelable {
         return mVcnNetworkPolicyResult.equals(that.mVcnNetworkPolicyResult);
     }
 
+    @Override
+    public String toString() {
+        return mVcnNetworkPolicyResult.toString();
+    }
+
     /** {@inheritDoc} */
     @Override
     public int describeContents() {

services/core/java/com/android/server/VcnManagementService.java

@@ -434,6 +434,7 @@ public class VcnManagementService extends IVcnManagementService.Stub {
             synchronized (mLock) {
                 final TelephonySubscriptionSnapshot oldSnapshot = mLastSnapshot;
                 mLastSnapshot = snapshot;
+                Slog.d(TAG, "new snapshot: " + mLastSnapshot);
 
                 // Start any VCN instances as necessary
                 for (Entry<ParcelUuid, VcnConfig> entry : mConfigs.entrySet()) {
@@ -536,7 +537,7 @@ public class VcnManagementService extends IVcnManagementService.Stub {
 
     @GuardedBy("mLock")
     private void startVcnLocked(@NonNull ParcelUuid subscriptionGroup, @NonNull VcnConfig config) {
-        Slog.v(TAG, "Starting VCN config for subGrp: " + subscriptionGroup);
+        Slog.d(TAG, "Starting VCN config for subGrp: " + subscriptionGroup);
 
         // TODO(b/176939047): Support multiple VCNs active at the same time, or limit to one active
         //                    VCN.
@@ -558,7 +559,7 @@ public class VcnManagementService extends IVcnManagementService.Stub {
     @GuardedBy("mLock")
     private void startOrUpdateVcnLocked(
             @NonNull ParcelUuid subscriptionGroup, @NonNull VcnConfig config) {
-        Slog.v(TAG, "Starting or updating VCN config for subGrp: " + subscriptionGroup);
+        Slog.d(TAG, "Starting or updating VCN config for subGrp: " + subscriptionGroup);
 
         if (mVcns.containsKey(subscriptionGroup)) {
             final Vcn vcn = mVcns.get(subscriptionGroup);
@@ -584,7 +585,7 @@ public class VcnManagementService extends IVcnManagementService.Stub {
         if (!config.getProvisioningPackageName().equals(opPkgName)) {
             throw new IllegalArgumentException("Mismatched caller and VcnConfig creator");
         }
-        Slog.v(TAG, "VCN config updated for subGrp: " + subscriptionGroup);
+        Slog.d(TAG, "VCN config updated for subGrp: " + subscriptionGroup);
 
         mContext.getSystemService(AppOpsManager.class)
                 .checkPackage(mDeps.getBinderCallingUid(), config.getProvisioningPackageName());
@@ -609,7 +610,7 @@ public class VcnManagementService extends IVcnManagementService.Stub {
     public void clearVcnConfig(@NonNull ParcelUuid subscriptionGroup, @NonNull String opPkgName) {
         requireNonNull(subscriptionGroup, "subscriptionGroup was null");
         requireNonNull(opPkgName, "opPkgName was null");
-        Slog.v(TAG, "VCN config cleared for subGrp: " + subscriptionGroup);
+        Slog.d(TAG, "VCN config cleared for subGrp: " + subscriptionGroup);
 
         mContext.getSystemService(AppOpsManager.class)
                 .checkPackage(mDeps.getBinderCallingUid(), opPkgName);
@@ -845,8 +846,14 @@ public class VcnManagementService extends IVcnManagementService.Stub {
             }
 
             final NetworkCapabilities result = ncBuilder.build();
-            return new VcnUnderlyingNetworkPolicy(
+            final VcnUnderlyingNetworkPolicy policy = new VcnUnderlyingNetworkPolicy(
                     mTrackingNetworkCallback.requiresRestartForCarrierWifi(result), result);
+
+            if (VDBG) {
+                Slog.d(TAG, "getUnderlyingNetworkPolicy() called for caps: " + networkCapabilities
+                        + "; and lp: " + linkProperties + "; result = " + policy);
+            }
+            return policy;
         });
     }
 

services/core/java/com/android/server/vcn/Vcn.java

@@ -311,7 +311,9 @@ public class Vcn extends Handler {
 
     private void handleConfigUpdated(@NonNull VcnConfig config) {
         // TODO: Add a dump function in VcnConfig that omits PII. Until then, use hashCode()
-        Slog.v(getLogTag(), "Config updated: config = " + config.hashCode());
+        Slog.d(
+                getLogTag(),
+                "Config updated: old = " + mConfig.hashCode() + "; new = " + config.hashCode());
 
         mConfig = config;
 
@@ -340,6 +342,7 @@ public class Vcn extends Handler {
     }
 
     private void handleTeardown() {
+        Slog.d(getLogTag(), "Tearing down");
         mVcnContext.getVcnNetworkProvider().unregisterListener(mRequestListener);
 
         for (VcnGatewayConnection gatewayConnection : mVcnGatewayConnections.values()) {
@@ -350,6 +353,7 @@ public class Vcn extends Handler {
     }
 
     private void handleSafeModeStatusChanged() {
+        Slog.d(getLogTag(), "VcnGatewayConnection safe mode status changed");
         boolean hasSafeModeGatewayConnection = false;
 
         // If any VcnGatewayConnection is in safe mode, mark the entire VCN as being in safe mode
@@ -365,21 +369,24 @@ public class Vcn extends Handler {
                 hasSafeModeGatewayConnection ? VCN_STATUS_CODE_SAFE_MODE : VCN_STATUS_CODE_ACTIVE;
         if (oldStatus != mCurrentStatus) {
             mVcnCallback.onSafeModeStatusChanged(hasSafeModeGatewayConnection);
+            Slog.d(
+                    getLogTag(),
+                    "Safe mode "
+                            + (mCurrentStatus == VCN_STATUS_CODE_SAFE_MODE ? "entered" : "exited"));
         }
     }
 
     private void handleNetworkRequested(@NonNull NetworkRequest request) {
-        Slog.v(getLogTag(), "Received request " + request);
+        if (VDBG) {
+            Slog.v(getLogTag(), "Received request " + request);
+        }
 
         // If preexisting VcnGatewayConnection(s) satisfy request, return
         for (VcnGatewayConnectionConfig gatewayConnectionConfig : mVcnGatewayConnections.keySet()) {
             if (isRequestSatisfiedByGatewayConnectionConfig(request, gatewayConnectionConfig)) {
-                if (VDBG) {
+                Slog.d(
-                    Slog.v(
+                        getLogTag(),
-                            getLogTag(),
+                        "Request already satisfied by existing VcnGatewayConnection: " + request);
-                            "Request already satisfied by existing VcnGatewayConnection: "
-                                    + request);
-                }
                 return;
             }
         }
@@ -389,7 +396,7 @@ public class Vcn extends Handler {
         for (VcnGatewayConnectionConfig gatewayConnectionConfig :
                 mConfig.getGatewayConnectionConfigs()) {
             if (isRequestSatisfiedByGatewayConnectionConfig(request, gatewayConnectionConfig)) {
-                Slog.v(getLogTag(), "Bringing up new VcnGatewayConnection for request " + request);
+                Slog.d(getLogTag(), "Bringing up new VcnGatewayConnection for request " + request);
 
                 if (getExposedCapabilitiesForMobileDataState(gatewayConnectionConfig).isEmpty()) {
                     // Skip; this network does not provide any services if mobile data is disabled.
@@ -414,8 +421,14 @@ public class Vcn extends Handler {
                                 new VcnGatewayStatusCallbackImpl(gatewayConnectionConfig),
                                 mIsMobileDataEnabled);
                 mVcnGatewayConnections.put(gatewayConnectionConfig, vcnGatewayConnection);
+
+                return;
             }
         }
+
+        if (VDBG) {
+            Slog.v(getLogTag(), "Request could not be fulfilled by VCN: " + request);
+        }
     }
 
     private Set<Integer> getExposedCapabilitiesForMobileDataState(
@@ -432,7 +445,7 @@ public class Vcn extends Handler {
     }
 
     private void handleGatewayConnectionQuit(VcnGatewayConnectionConfig config) {
-        Slog.v(getLogTag(), "VcnGatewayConnection quit: " + config);
+        Slog.d(getLogTag(), "VcnGatewayConnection quit: " + config);
         mVcnGatewayConnections.remove(config);
 
         // Trigger a re-evaluation of all NetworkRequests (to make sure any that can be satisfied
@@ -479,6 +492,8 @@ public class Vcn extends Handler {
 
             // Trigger re-evaluation of all requests; mobile data state impacts supported caps.
             mVcnContext.getVcnNetworkProvider().resendAllRequests(mRequestListener);
+
+            Slog.d(getLogTag(), "Mobile data " + (mIsMobileDataEnabled ? "enabled" : "disabled"));
         }
     }
 
@@ -521,6 +536,7 @@ public class Vcn extends Handler {
         pw.increaseIndent();
 
         pw.println("mCurrentStatus: " + mCurrentStatus);
+        pw.println("mIsMobileDataEnabled: " + mIsMobileDataEnabled);
 
         pw.println("mVcnGatewayConnections:");
         for (VcnGatewayConnection gw : mVcnGatewayConnections.values()) {

services/core/java/com/android/server/vcn/VcnGatewayConnection.java

@@ -701,6 +701,7 @@ public class VcnGatewayConnection extends StateMachine {
      * <p>Once torn down, this VcnTunnel CANNOT be started again.
      */
     public void teardownAsynchronously() {
+        Slog.d(TAG, "Triggering async teardown");
         sendDisconnectRequestedAndAcquireWakelock(
                 DISCONNECT_REASON_TEARDOWN, true /* shouldQuit */);
 
@@ -710,6 +711,8 @@ public class VcnGatewayConnection extends StateMachine {
 
     @Override
     protected void onQuitting() {
+        Slog.d(TAG, "Quitting VcnGatewayConnection");
+
         // No need to call setInterfaceDown(); the IpSecInterface is being fully torn down.
         if (mTunnelIface != null) {
             mTunnelIface.close();
@@ -750,6 +753,11 @@ public class VcnGatewayConnection extends StateMachine {
             // TODO(b/180132994): explore safely removing this Thread check
             mVcnContext.ensureRunningOnLooperThread();
 
+            Slog.d(
+                    TAG,
+                    "Selected underlying network changed: "
+                            + (underlying == null ? null : underlying.network));
+
             // TODO(b/179091925): Move the delayed-message handling to BaseState
 
             // If underlying is null, all underlying networks have been lost. Disconnect VCN after a
@@ -774,6 +782,10 @@ public class VcnGatewayConnection extends StateMachine {
 
         if (!mIsQuitting) {
             mWakeLock.acquire();
+
+            if (VDBG) {
+                Slog.v(TAG, "Wakelock acquired: " + mWakeLock);
+            }
         }
     }
 
@@ -781,6 +793,10 @@ public class VcnGatewayConnection extends StateMachine {
         mVcnContext.ensureRunningOnLooperThread();
 
         mWakeLock.release();
+
+        if (VDBG) {
+            Slog.v(TAG, "Wakelock released: " + mWakeLock);
+        }
     }
 
     /**
@@ -935,10 +951,17 @@ public class VcnGatewayConnection extends StateMachine {
     }
 
     private void setTeardownTimeoutAlarm() {
+        if (VDBG) {
+            Slog.v(TAG, "Setting teardown timeout alarm; mCurrentToken: " + mCurrentToken);
+        }
+
         // Safe to assign this alarm because it is either 1) already null, or 2) already fired. In
         // either case, there is nothing to cancel.
         if (mTeardownTimeoutAlarm != null) {
-            Slog.wtf(TAG, "mTeardownTimeoutAlarm should be null before being set");
+            Slog.wtf(
+                    TAG,
+                    "mTeardownTimeoutAlarm should be null before being set; mCurrentToken: "
+                            + mCurrentToken);
         }
 
         final Message delayedMessage = obtainMessage(EVENT_TEARDOWN_TIMEOUT_EXPIRED, mCurrentToken);
@@ -950,6 +973,10 @@ public class VcnGatewayConnection extends StateMachine {
     }
 
     private void cancelTeardownTimeoutAlarm() {
+        if (VDBG) {
+            Slog.v(TAG, "Cancelling teardown timeout alarm; mCurrentToken: " + mCurrentToken);
+        }
+
         if (mTeardownTimeoutAlarm != null) {
             mTeardownTimeoutAlarm.cancel();
             mTeardownTimeoutAlarm = null;
@@ -960,6 +987,13 @@ public class VcnGatewayConnection extends StateMachine {
     }
 
     private void setDisconnectRequestAlarm() {
+        if (VDBG) {
+            Slog.v(
+                    TAG,
+                    "Setting alarm to disconnect due to underlying network loss; mCurrentToken: "
+                            + mCurrentToken);
+        }
+
         // Only schedule a NEW alarm if none is already set.
         if (mDisconnectRequestAlarm != null) {
             return;
@@ -980,6 +1014,13 @@ public class VcnGatewayConnection extends StateMachine {
     }
 
     private void cancelDisconnectRequestAlarm() {
+        if (VDBG) {
+            Slog.v(
+                    TAG,
+                    "Cancelling alarm to disconnect due to underlying network loss; mCurrentToken: "
+                            + mCurrentToken);
+        }
+
         if (mDisconnectRequestAlarm != null) {
             mDisconnectRequestAlarm.cancel();
             mDisconnectRequestAlarm = null;
@@ -993,10 +1034,17 @@ public class VcnGatewayConnection extends StateMachine {
     }
 
     private void setRetryTimeoutAlarm(long delay) {
+        if (VDBG) {
+            Slog.v(TAG, "Setting retry alarm; mCurrentToken: " + mCurrentToken);
+        }
+
         // Safe to assign this alarm because it is either 1) already null, or 2) already fired. In
         // either case, there is nothing to cancel.
         if (mRetryTimeoutAlarm != null) {
-            Slog.wtf(TAG, "mRetryTimeoutAlarm should be null before being set");
+            Slog.wtf(
+                    TAG,
+                    "mRetryTimeoutAlarm should be null before being set; mCurrentToken: "
+                            + mCurrentToken);
         }
 
         final Message delayedMessage = obtainMessage(EVENT_RETRY_TIMEOUT_EXPIRED, mCurrentToken);
@@ -1004,6 +1052,10 @@ public class VcnGatewayConnection extends StateMachine {
     }
 
     private void cancelRetryTimeoutAlarm() {
+        if (VDBG) {
+            Slog.v(TAG, "Cancel retry alarm; mCurrentToken: " + mCurrentToken);
+        }
+
         if (mRetryTimeoutAlarm != null) {
             mRetryTimeoutAlarm.cancel();
             mRetryTimeoutAlarm = null;
@@ -1014,6 +1066,10 @@ public class VcnGatewayConnection extends StateMachine {
 
     @VisibleForTesting(visibility = Visibility.PRIVATE)
     void setSafeModeAlarm() {
+        if (VDBG) {
+            Slog.v(TAG, "Setting safe mode alarm; mCurrentToken: " + mCurrentToken);
+        }
+
         // Only schedule a NEW alarm if none is already set.
         if (mSafeModeTimeoutAlarm != null) {
             return;
@@ -1028,6 +1084,10 @@ public class VcnGatewayConnection extends StateMachine {
     }
 
     private void cancelSafeModeAlarm() {
+        if (VDBG) {
+            Slog.v(TAG, "Cancel safe mode alarm; mCurrentToken: " + mCurrentToken);
+        }
+
         if (mSafeModeTimeoutAlarm != null) {
             mSafeModeTimeoutAlarm.cancel();
             mSafeModeTimeoutAlarm = null;
@@ -1092,6 +1152,15 @@ public class VcnGatewayConnection extends StateMachine {
                             + exception.getMessage();
         }
 
+        Slog.d(
+                TAG,
+                "Encountered error; code="
+                        + errorCode
+                        + ", exceptionClass="
+                        + exceptionClass
+                        + ", exceptionMessage="
+                        + exceptionMessage);
+
         mGatewayStatusCallback.onGatewayConnectionError(
                 mConnectionConfig.getGatewayConnectionName(),
                 errorCode,
@@ -1234,7 +1303,7 @@ public class VcnGatewayConnection extends StateMachine {
         protected void handleDisconnectRequested(EventDisconnectRequestedInfo info) {
             // TODO(b/180526152): notify VcnStatusCallback for Network loss
 
-            Slog.v(TAG, "Tearing down. Cause: " + info.reason);
+            Slog.d(TAG, "Tearing down. Cause: " + info.reason);
             mIsQuitting = info.shouldQuit;
 
             teardownNetwork();
@@ -1250,6 +1319,7 @@ public class VcnGatewayConnection extends StateMachine {
 
         protected void handleSafeModeTimeoutExceeded() {
             mSafeModeTimeoutAlarm = null;
+            Slog.d(TAG, "Entering safe mode after timeout exceeded");
 
             // Connectivity for this GatewayConnection is broken; tear down the Network.
             teardownNetwork();
@@ -1722,6 +1792,8 @@ public class VcnGatewayConnection extends StateMachine {
         }
 
         private void handleMigrationCompleted(EventMigrationCompletedInfo migrationCompletedInfo) {
+            Slog.v(TAG, "Migration completed: " + mUnderlying.network);
+
             applyTransform(
                     mCurrentToken,
                     mTunnelIface,
@@ -1744,6 +1816,8 @@ public class VcnGatewayConnection extends StateMachine {
             mUnderlying = ((EventUnderlyingNetworkChangedInfo) msg.obj).newUnderlying;
 
             if (mUnderlying == null) {
+                Slog.v(TAG, "Underlying network lost");
+
                 // Ignored for now; a new network may be coming up. If none does, the delayed
                 // NETWORK_LOST disconnect will be fired, and tear down the session + network.
                 return;