[NS B03] Add debug log showing the reassignment
dumpString for a reassignment looks like :
NetworkReassignment :
Rematched networks : [100 CELLULAR], [101 WIFI]
6 : 100 → 101
8 : null → 101
toString looks like :
NetReassign [4 : 100 → 101, 5 : null → 101]
If no changes, then it looks like
NetworkReassignment : no changes
Bug: 113554781
Test: Manual
Change-Id: If9eeadb7ee317dee2d91ca1feca3091ae39e9bae
diff --git a/services/core/java/com/android/server/ConnectivityService.java b/services/core/java/com/android/server/ConnectivityService.java
index ea6fe2b..d4d870f 100644
--- a/services/core/java/com/android/server/ConnectivityService.java
+++ b/services/core/java/com/android/server/ConnectivityService.java
@@ -231,6 +231,7 @@
import java.util.Objects;
import java.util.Set;
import java.util.SortedSet;
+import java.util.StringJoiner;
import java.util.TreeSet;
import java.util.concurrent.atomic.AtomicInteger;
@@ -727,9 +728,9 @@
private void maybeLogBroadcast(NetworkAgentInfo nai, DetailedState state, int type,
boolean isDefaultNetwork) {
if (DBG) {
- log("Sending " + state +
- " broadcast for type " + type + " " + nai.name() +
- " isDefaultNetwork=" + isDefaultNetwork);
+ log("Sending " + state
+ + " broadcast for type " + type + " " + nai.toShortString()
+ + " isDefaultNetwork=" + isDefaultNetwork);
}
}
@@ -809,14 +810,6 @@
}
}
- private String naiToString(NetworkAgentInfo nai) {
- String name = nai.name();
- String state = (nai.networkInfo != null) ?
- nai.networkInfo.getState() + "/" + nai.networkInfo.getDetailedState() :
- "???/???";
- return name + " " + state;
- }
-
public void dump(IndentingPrintWriter pw) {
pw.println("mLegacyTypeTracker:");
pw.increaseIndent();
@@ -831,7 +824,7 @@
for (int type = 0; type < mTypeLists.length; type++) {
if (mTypeLists[type] == null || mTypeLists[type].isEmpty()) continue;
for (NetworkAgentInfo nai : mTypeLists[type]) {
- pw.println(type + " " + naiToString(nai));
+ pw.println(type + " " + nai.toShortString());
}
}
}
@@ -2786,7 +2779,7 @@
nai.everCaptivePortalDetected |= visible;
if (nai.lastCaptivePortalDetected &&
Settings.Global.CAPTIVE_PORTAL_MODE_AVOID == getCaptivePortalMode()) {
- if (DBG) log("Avoiding captive portal network: " + nai.name());
+ if (DBG) log("Avoiding captive portal network: " + nai.toShortString());
nai.asyncChannel.sendMessage(
NetworkAgent.CMD_PREVENT_AUTOMATIC_RECONNECT);
teardownUnneededNetwork(nai);
@@ -2845,7 +2838,7 @@
final String logMsg = !TextUtils.isEmpty(redirectUrl)
? " with redirect to " + redirectUrl
: "";
- log(nai.name() + " validation " + (valid ? "passed" : "failed") + logMsg);
+ log(nai.toShortString() + " validation " + (valid ? "passed" : "failed") + logMsg);
}
if (valid != nai.lastValidated) {
if (wasDefault) {
@@ -3126,13 +3119,13 @@
// one lingered request, start lingering.
nai.updateLingerTimer();
if (nai.isLingering() && nai.numForegroundNetworkRequests() > 0) {
- if (DBG) log("Unlingering " + nai.name());
+ if (DBG) log("Unlingering " + nai.toShortString());
nai.unlinger();
logNetworkEvent(nai, NetworkEvent.NETWORK_UNLINGER);
} else if (unneeded(nai, UnneededFor.LINGER) && nai.getLingerExpiry() > 0) {
if (DBG) {
final int lingerTime = (int) (nai.getLingerExpiry() - now);
- log("Lingering " + nai.name() + " for " + lingerTime + "ms");
+ log("Lingering " + nai.toShortString() + " for " + lingerTime + "ms");
}
nai.linger();
logNetworkEvent(nai, NetworkEvent.NETWORK_LINGER);
@@ -3196,7 +3189,7 @@
private void disconnectAndDestroyNetwork(NetworkAgentInfo nai) {
ensureRunningOnConnectivityServiceThread();
if (DBG) {
- log(nai.name() + " got DISCONNECTED, was satisfying " + nai.numNetworkRequests());
+ log(nai.toShortString() + " disconnected, was satisfying " + nai.numNetworkRequests());
}
// Clear all notifications of this network.
mNotifier.clearNotification(nai.network.netId);
@@ -3254,7 +3247,7 @@
mDefaultNetworkNai = null;
updateDataActivityTracking(null /* newNetwork */, nai);
notifyLockdownVpn(nai);
- ensureNetworkTransitionWakelock(nai.name());
+ ensureNetworkTransitionWakelock(nai.toShortString());
}
mLegacyTypeTracker.remove(nai, wasDefault);
if (!nai.networkCapabilities.hasTransport(TRANSPORT_VPN)) {
@@ -3477,8 +3470,8 @@
boolean wasBackgroundNetwork = nai.isBackgroundNetwork();
nai.removeRequest(nri.request.requestId);
if (VDBG || DDBG) {
- log(" Removing from current network " + nai.name() +
- ", leaving " + nai.numNetworkRequests() + " requests.");
+ log(" Removing from current network " + nai.toShortString()
+ + ", leaving " + nai.numNetworkRequests() + " requests.");
}
// If there are still lingered requests on this network, don't tear it down,
// but resume lingering instead.
@@ -3487,7 +3480,7 @@
notifyNetworkLosing(nai, now);
}
if (unneeded(nai, UnneededFor.TEARDOWN)) {
- if (DBG) log("no live requests for " + nai.name() + "; disconnecting");
+ if (DBG) log("no live requests for " + nai.toShortString() + "; disconnecting");
teardownUnneededNetwork(nai);
} else {
wasKept = true;
@@ -3822,7 +3815,7 @@
pw.increaseIndent();
for (NetworkAgentInfo nai : networksSortedById()) {
if (nai.avoidUnvalidated) {
- pw.println(nai.name());
+ pw.println(nai.toShortString());
}
}
pw.decreaseIndent();
@@ -3934,7 +3927,7 @@
private void handleNetworkUnvalidated(NetworkAgentInfo nai) {
NetworkCapabilities nc = nai.networkCapabilities;
- if (DBG) log("handleNetworkUnvalidated " + nai.name() + " cap=" + nc);
+ if (DBG) log("handleNetworkUnvalidated " + nai.toShortString() + " cap=" + nc);
if (!nc.hasTransport(NetworkCapabilities.TRANSPORT_WIFI)) {
return;
@@ -5348,7 +5341,7 @@
detail = reason;
}
log(String.format("updateSignalStrengthThresholds: %s, sending %s to %s",
- detail, Arrays.toString(thresholdsArray.toArray()), nai.name()));
+ detail, Arrays.toString(thresholdsArray.toArray()), nai.toShortString()));
}
nai.asyncChannel.sendMessage(
@@ -6272,9 +6265,9 @@
// newLp is already a defensive copy.
newLp.ensureDirectlyConnectedRoutes();
if (VDBG || DDBG) {
- log("Update of LinkProperties for " + nai.name() +
- "; created=" + nai.created +
- "; everConnected=" + nai.everConnected);
+ log("Update of LinkProperties for " + nai.toShortString()
+ + "; created=" + nai.created
+ + "; everConnected=" + nai.everConnected);
}
updateLinkProperties(nai, newLp, new LinkProperties(nai.linkProperties));
}
@@ -6444,7 +6437,7 @@
loge("Unknown NetworkAgentInfo in handleLingerComplete");
return;
}
- if (DBG) log("handleLingerComplete for " + oldNetwork.name());
+ if (DBG) log("handleLingerComplete for " + oldNetwork.toShortString());
// If we get here it means that the last linger timeout for this network expired. So there
// must be no other active linger timers, and we must stop lingering.
@@ -6527,6 +6520,11 @@
mNetwork = network;
mOldBackground = oldBackground;
}
+
+ public String toString() {
+ return "[" + NetworkAgentInfo.toShortString(mNetwork)
+ + " oldBg=" + mOldBackground + "]";
+ }
}
static class RequestReassignment {
@@ -6540,6 +6538,12 @@
mOldNetwork = oldNetwork;
mNewNetwork = newNetwork;
}
+
+ public String toString() {
+ return mRequest.request.requestId + " : "
+ + (null != mOldNetwork ? mOldNetwork.network.netId : "null")
+ + " → " + (null != mNewNetwork ? mNewNetwork.network.netId : "null");
+ }
}
@NonNull private final Set<NetworkBgStatePair> mRematchedNetworks = new ArraySet<>();
@@ -6589,6 +6593,36 @@
}
return null;
}
+
+ public String toString() {
+ final StringJoiner sj = new StringJoiner(", " /* delimiter */,
+ "NetReassign [" /* prefix */, "]" /* suffix */);
+ if (mRematchedNetworks.isEmpty() && mReassignments.isEmpty()) {
+ return sj.add("no changes").toString();
+ }
+ for (final RequestReassignment rr : getRequestReassignments()) {
+ sj.add(rr.toString());
+ }
+ return sj.toString();
+ }
+
+ public String debugString() {
+ final StringBuilder sb = new StringBuilder();
+ sb.append("NetworkReassignment :");
+ if (mRematchedNetworks.isEmpty() && mReassignments.isEmpty()) {
+ return sb.append(" no changes").toString();
+ }
+ final StringJoiner sj = new StringJoiner(", " /* delimiter */,
+ "\n Rematched networks : " /* prefix */, "" /* suffix */);
+ for (final NetworkBgStatePair rr : mRematchedNetworks) {
+ sj.add(rr.mNetwork.toShortString());
+ }
+ sb.append(sj.toString());
+ for (final RequestReassignment rr : getRequestReassignments()) {
+ sb.append("\n ").append(rr);
+ }
+ return sb.append("\n").toString();
+ }
}
// TODO : remove this when it's useless
@@ -6661,7 +6695,7 @@
changes.addRematchedNetwork(new NetworkReassignment.NetworkBgStatePair(newNetwork,
newNetwork.isBackgroundNetwork()));
- if (VDBG || DDBG) log("rematching " + newNetwork.name());
+ if (VDBG || DDBG) log("rematching " + newNetwork.toShortString());
computeRequestReassignmentForNetwork(changes, newNetwork);
}
@@ -6671,10 +6705,10 @@
@Nullable final NetworkAgentInfo newSatisfier,
final long now) {
if (newSatisfier != null) {
- if (VDBG) log("rematch for " + newSatisfier.name());
+ if (VDBG) log("rematch for " + newSatisfier.toShortString());
if (previousSatisfier != null) {
if (VDBG || DDBG) {
- log(" accepting network in place of " + previousSatisfier.name());
+ log(" accepting network in place of " + previousSatisfier.toShortString());
}
previousSatisfier.removeRequest(nri.request.requestId);
previousSatisfier.lingerRequest(nri.request, now, mLingerDelayMs);
@@ -6683,11 +6717,12 @@
}
newSatisfier.unlingerRequest(nri.request);
if (!newSatisfier.addRequest(nri.request)) {
- Slog.wtf(TAG, "BUG: " + newSatisfier.name() + " already has " + nri.request);
+ Slog.wtf(TAG, "BUG: " + newSatisfier.toShortString() + " already has "
+ + nri.request);
}
} else {
if (DBG) {
- log("Network " + previousSatisfier.name() + " stopped satisfying"
+ log("Network " + previousSatisfier.toShortString() + " stopped satisfying"
+ " request " + nri.request.requestId);
}
previousSatisfier.removeRequest(nri.request.requestId);
@@ -6724,6 +6759,11 @@
final long now = SystemClock.elapsedRealtime();
final NetworkAgentInfo oldDefaultNetwork = getDefaultNetwork();
final NetworkReassignment changes = computeNetworkReassignment();
+ if (VDBG || DDBG) {
+ log(changes.debugString());
+ } else if (DBG) {
+ log(changes.toString()); // Shorter form, only one line of log
+ }
applyNetworkReassignment(changes, oldDefaultNetwork, now);
}
@@ -6832,7 +6872,7 @@
notifyNetworkLosing(nai, now);
}
} else {
- if (DBG) log("Reaping " + nai.name());
+ if (DBG) log("Reaping " + nai.toShortString());
teardownUnneededNetwork(nai);
}
}
@@ -6980,8 +7020,8 @@
notifyLockdownVpn(networkAgent);
if (DBG) {
- log(networkAgent.name() + " EVENT_NETWORK_INFO_CHANGED, going from " +
- oldInfo.getState() + " to " + state);
+ log(networkAgent.toShortString() + " EVENT_NETWORK_INFO_CHANGED, going from "
+ + oldInfo.getState() + " to " + state);
}
if (!networkAgent.created
@@ -6999,7 +7039,7 @@
networkAgent.everConnected = true;
if (networkAgent.linkProperties == null) {
- Slog.wtf(TAG, networkAgent.name() + " connected with null LinkProperties");
+ Slog.wtf(TAG, networkAgent.toShortString() + " connected with null LinkProperties");
}
// NetworkCapabilities need to be set before sending the private DNS config to
@@ -7059,7 +7099,7 @@
}
private void updateNetworkScore(NetworkAgentInfo nai, NetworkScore ns) {
- if (VDBG || DDBG) log("updateNetworkScore for " + nai.name() + " to " + ns);
+ if (VDBG || DDBG) log("updateNetworkScore for " + nai.toShortString() + " to " + ns);
nai.setNetworkScore(ns);
rematchAllNetworksAndRequests();
sendUpdatedScoreToFactories(nai);
@@ -7205,7 +7245,7 @@
protected void notifyNetworkCallbacks(NetworkAgentInfo networkAgent, int notifyType, int arg1) {
if (VDBG || DDBG) {
String notification = ConnectivityManager.getCallbackName(notifyType);
- log("notifyType " + notification + " for " + networkAgent.name());
+ log("notifyType " + notification + " for " + networkAgent.toShortString());
}
for (int i = 0; i < networkAgent.numNetworkRequests(); i++) {
NetworkRequest nr = networkAgent.requestAt(i);
diff --git a/services/core/java/com/android/server/connectivity/KeepaliveTracker.java b/services/core/java/com/android/server/connectivity/KeepaliveTracker.java
index af8a366..5059a48 100644
--- a/services/core/java/com/android/server/connectivity/KeepaliveTracker.java
+++ b/services/core/java/com/android/server/connectivity/KeepaliveTracker.java
@@ -325,7 +325,7 @@
mSlot = slot;
int error = isValid();
if (error == SUCCESS) {
- Log.d(TAG, "Starting keepalive " + mSlot + " on " + mNai.name());
+ Log.d(TAG, "Starting keepalive " + mSlot + " on " + mNai.toShortString());
switch (mType) {
case TYPE_NATT:
mNai.asyncChannel.sendMessage(
@@ -365,7 +365,8 @@
Log.e(TAG, "Cannot stop unowned keepalive " + mSlot + " on " + mNai.network);
}
}
- Log.d(TAG, "Stopping keepalive " + mSlot + " on " + mNai.name() + ": " + reason);
+ Log.d(TAG, "Stopping keepalive " + mSlot + " on " + mNai.toShortString()
+ + ": " + reason);
switch (mStartedState) {
case NOT_STARTED:
// Remove the reference of the keepalive that meet error before starting,
@@ -476,7 +477,7 @@
}
public void handleStopKeepalive(NetworkAgentInfo nai, int slot, int reason) {
- String networkName = (nai == null) ? "(null)" : nai.name();
+ final String networkName = NetworkAgentInfo.toShortString(nai);
HashMap <Integer, KeepaliveInfo> networkKeepalives = mKeepalives.get(nai);
if (networkKeepalives == null) {
Log.e(TAG, "Attempt to stop keepalive on nonexistent network " + networkName);
@@ -493,7 +494,7 @@
}
private void cleanupStoppedKeepalive(NetworkAgentInfo nai, int slot) {
- String networkName = (nai == null) ? "(null)" : nai.name();
+ final String networkName = NetworkAgentInfo.toShortString(nai);
HashMap<Integer, KeepaliveInfo> networkKeepalives = mKeepalives.get(nai);
if (networkKeepalives == null) {
Log.e(TAG, "Attempt to remove keepalive on nonexistent network " + networkName);
@@ -540,7 +541,7 @@
} catch(NullPointerException e) {}
if (ki == null) {
Log.e(TAG, "Event " + message.what + "," + slot + "," + reason
- + " for unknown keepalive " + slot + " on " + nai.name());
+ + " for unknown keepalive " + slot + " on " + nai.toShortString());
return;
}
@@ -562,7 +563,7 @@
if (KeepaliveInfo.STARTING == ki.mStartedState) {
if (SUCCESS == reason) {
// Keepalive successfully started.
- Log.d(TAG, "Started keepalive " + slot + " on " + nai.name());
+ Log.d(TAG, "Started keepalive " + slot + " on " + nai.toShortString());
ki.mStartedState = KeepaliveInfo.STARTED;
try {
ki.mCallback.onStarted(slot);
@@ -570,14 +571,14 @@
Log.w(TAG, "Discarded onStarted(" + slot + ") callback");
}
} else {
- Log.d(TAG, "Failed to start keepalive " + slot + " on " + nai.name()
+ Log.d(TAG, "Failed to start keepalive " + slot + " on " + nai.toShortString()
+ ": " + reason);
// The message indicated some error trying to start: do call handleStopKeepalive.
handleStopKeepalive(nai, slot, reason);
}
} else if (KeepaliveInfo.STOPPING == ki.mStartedState) {
// The message indicated result of stopping : clean up keepalive slots.
- Log.d(TAG, "Stopped keepalive " + slot + " on " + nai.name()
+ Log.d(TAG, "Stopped keepalive " + slot + " on " + nai.toShortString()
+ " stopped: " + reason);
ki.mStartedState = KeepaliveInfo.NOT_STARTED;
cleanupStoppedKeepalive(nai, slot);
@@ -733,7 +734,7 @@
pw.println("Socket keepalives:");
pw.increaseIndent();
for (NetworkAgentInfo nai : mKeepalives.keySet()) {
- pw.println(nai.name());
+ pw.println(nai.toShortString());
pw.increaseIndent();
for (int slot : mKeepalives.get(nai).keySet()) {
KeepaliveInfo ki = mKeepalives.get(nai).get(slot);
diff --git a/services/core/java/com/android/server/connectivity/LingerMonitor.java b/services/core/java/com/android/server/connectivity/LingerMonitor.java
index 7071510..04c000f 100644
--- a/services/core/java/com/android/server/connectivity/LingerMonitor.java
+++ b/services/core/java/com/android/server/connectivity/LingerMonitor.java
@@ -200,8 +200,9 @@
}
if (DBG) {
- Log.d(TAG, "Notifying switch from=" + fromNai.name() + " to=" + toNai.name() +
- " type=" + sNotifyTypeNames.get(notifyType, "unknown(" + notifyType + ")"));
+ Log.d(TAG, "Notifying switch from=" + fromNai.toShortString()
+ + " to=" + toNai.toShortString()
+ + " type=" + sNotifyTypeNames.get(notifyType, "unknown(" + notifyType + ")"));
}
mNotifications.put(fromNai.network.netId, toNai.network.netId);
@@ -222,10 +223,10 @@
public void noteLingerDefaultNetwork(@NonNull final NetworkAgentInfo fromNai,
@Nullable final NetworkAgentInfo toNai) {
if (VDBG) {
- Log.d(TAG, "noteLingerDefaultNetwork from=" + fromNai.name() +
- " everValidated=" + fromNai.everValidated +
- " lastValidated=" + fromNai.lastValidated +
- " to=" + toNai.name());
+ Log.d(TAG, "noteLingerDefaultNetwork from=" + fromNai.toShortString()
+ + " everValidated=" + fromNai.everValidated
+ + " lastValidated=" + fromNai.lastValidated
+ + " to=" + toNai.toShortString());
}
// If we are currently notifying the user because the device switched to fromNai, now that
@@ -270,7 +271,8 @@
// TODO: should we do this?
if (everNotified(fromNai)) {
if (VDBG) {
- Log.d(TAG, "Not notifying handover from " + fromNai.name() + ", already notified");
+ Log.d(TAG, "Not notifying handover from " + fromNai.toShortString()
+ + ", already notified");
}
return;
}
diff --git a/services/core/java/com/android/server/connectivity/Nat464Xlat.java b/services/core/java/com/android/server/connectivity/Nat464Xlat.java
index f636d67..82465f8 100644
--- a/services/core/java/com/android/server/connectivity/Nat464Xlat.java
+++ b/services/core/java/com/android/server/connectivity/Nat464Xlat.java
@@ -174,7 +174,7 @@
try {
mNMService.registerObserver(this);
} catch (RemoteException e) {
- Slog.e(TAG, "Can't register interface observer for clat on " + mNetwork.name());
+ Slog.e(TAG, "Can't register iface observer for clat on " + mNetwork.toShortString());
return;
}
diff --git a/services/core/java/com/android/server/connectivity/NetworkAgentInfo.java b/services/core/java/com/android/server/connectivity/NetworkAgentInfo.java
index d66aec5..d30a320 100644
--- a/services/core/java/com/android/server/connectivity/NetworkAgentInfo.java
+++ b/services/core/java/com/android/server/connectivity/NetworkAgentInfo.java
@@ -16,7 +16,10 @@
package com.android.server.connectivity;
+import static android.net.NetworkCapabilities.transportNamesOf;
+
import android.annotation.NonNull;
+import android.annotation.Nullable;
import android.content.Context;
import android.net.IDnsResolver;
import android.net.INetd;
@@ -372,7 +375,7 @@
// Should only happen if the requestId wraps. If that happens lots of other things will
// be broken as well.
Log.wtf(TAG, String.format("Duplicate requestId for %s and %s on %s",
- networkRequest, existing, name()));
+ networkRequest, existing, toShortString()));
updateRequestCounts(REMOVE, existing);
}
mNetworkRequests.put(networkRequest.requestId, networkRequest);
@@ -542,11 +545,11 @@
// Cannot happen. Once a request is lingering on a particular network, we cannot
// re-linger it unless that network becomes the best for that request again, in which
// case we should have unlingered it.
- Log.wtf(TAG, this.name() + ": request " + request.requestId + " already lingered");
+ Log.wtf(TAG, toShortString() + ": request " + request.requestId + " already lingered");
}
final long expiryMs = now + duration;
LingerTimer timer = new LingerTimer(request, expiryMs);
- if (VDBG) Log.d(TAG, "Adding LingerTimer " + timer + " to " + this.name());
+ if (VDBG) Log.d(TAG, "Adding LingerTimer " + timer + " to " + toShortString());
mLingerTimers.add(timer);
mLingerTimerForRequest.put(request.requestId, timer);
}
@@ -558,7 +561,7 @@
public boolean unlingerRequest(NetworkRequest request) {
LingerTimer timer = mLingerTimerForRequest.get(request.requestId);
if (timer != null) {
- if (VDBG) Log.d(TAG, "Removing LingerTimer " + timer + " from " + this.name());
+ if (VDBG) Log.d(TAG, "Removing LingerTimer " + timer + " from " + toShortString());
mLingerTimers.remove(timer);
mLingerTimerForRequest.remove(request.requestId);
return true;
@@ -645,9 +648,16 @@
+ "}";
}
- public String name() {
- return "NetworkAgentInfo [" + networkInfo.getTypeName() + " (" +
- networkInfo.getSubtypeName() + ") - " + Objects.toString(network) + "]";
+ /**
+ * Show a short string representing a Network.
+ *
+ * This is often not enough for debugging purposes for anything complex, but the full form
+ * is very long and hard to read, so this is useful when there isn't a lot of ambiguity.
+ * This represents the network with something like "[100 WIFI|VPN]" or "[108 MOBILE]".
+ */
+ public String toShortString() {
+ return "[" + network.netId + " "
+ + transportNamesOf(networkCapabilities.getTransportTypes()) + "]";
}
// Enables sorting in descending order of score.
@@ -655,4 +665,12 @@
public int compareTo(NetworkAgentInfo other) {
return other.getCurrentScore() - getCurrentScore();
}
+
+ /**
+ * Null-guarding version of NetworkAgentInfo#toShortString()
+ */
+ @NonNull
+ public static String toShortString(@Nullable final NetworkAgentInfo nai) {
+ return null != nai ? nai.toShortString() : "[null]";
+ }
}