[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
This commit is contained in:
Chalard Jean
2019-12-10 21:07:02 +09:00
parent d4a4a30aef
commit 373391b2cd
5 changed files with 124 additions and 63 deletions

View File

@@ -231,6 +231,7 @@ import java.util.Map;
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 @@ public class ConnectivityService extends IConnectivityManager.Stub
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 @@ public class ConnectivityService extends IConnectivityManager.Stub
}
}
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 @@ public class ConnectivityService extends IConnectivityManager.Stub
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 @@ public class ConnectivityService extends IConnectivityManager.Stub
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 @@ public class ConnectivityService extends IConnectivityManager.Stub
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 @@ public class ConnectivityService extends IConnectivityManager.Stub
// 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 @@ public class ConnectivityService extends IConnectivityManager.Stub
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 @@ public class ConnectivityService extends IConnectivityManager.Stub
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 @@ public class ConnectivityService extends IConnectivityManager.Stub
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 @@ public class ConnectivityService extends IConnectivityManager.Stub
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 @@ public class ConnectivityService extends IConnectivityManager.Stub
pw.increaseIndent();
for (NetworkAgentInfo nai : networksSortedById()) {
if (nai.avoidUnvalidated) {
pw.println(nai.name());
pw.println(nai.toShortString());
}
}
pw.decreaseIndent();
@@ -3934,7 +3927,7 @@ public class ConnectivityService extends IConnectivityManager.Stub
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 @@ public class ConnectivityService extends IConnectivityManager.Stub
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 @@ public class ConnectivityService extends IConnectivityManager.Stub
// 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 @@ public class ConnectivityService extends IConnectivityManager.Stub
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 @@ public class ConnectivityService extends IConnectivityManager.Stub
mNetwork = network;
mOldBackground = oldBackground;
}
public String toString() {
return "[" + NetworkAgentInfo.toShortString(mNetwork)
+ " oldBg=" + mOldBackground + "]";
}
}
static class RequestReassignment {
@@ -6540,6 +6538,12 @@ public class ConnectivityService extends IConnectivityManager.Stub
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 @@ public class ConnectivityService extends IConnectivityManager.Stub
}
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 @@ public class ConnectivityService extends IConnectivityManager.Stub
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 @@ public class ConnectivityService extends IConnectivityManager.Stub
@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 @@ public class ConnectivityService extends IConnectivityManager.Stub
}
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 @@ public class ConnectivityService extends IConnectivityManager.Stub
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 @@ public class ConnectivityService extends IConnectivityManager.Stub
notifyNetworkLosing(nai, now);
}
} else {
if (DBG) log("Reaping " + nai.name());
if (DBG) log("Reaping " + nai.toShortString());
teardownUnneededNetwork(nai);
}
}
@@ -6980,8 +7020,8 @@ public class ConnectivityService extends IConnectivityManager.Stub
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 @@ public class ConnectivityService extends IConnectivityManager.Stub
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 @@ public class ConnectivityService extends IConnectivityManager.Stub
}
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 @@ public class ConnectivityService extends IConnectivityManager.Stub
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);

View File

@@ -325,7 +325,7 @@ public class KeepaliveTracker {
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 @@ public class KeepaliveTracker {
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 class KeepaliveTracker {
}
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 @@ public class KeepaliveTracker {
}
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 @@ public class KeepaliveTracker {
} 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 @@ public class KeepaliveTracker {
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 @@ public class KeepaliveTracker {
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 @@ public class KeepaliveTracker {
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);

View File

@@ -200,8 +200,9 @@ public class LingerMonitor {
}
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 class LingerMonitor {
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 @@ public class LingerMonitor {
// 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;
}

View File

@@ -174,7 +174,7 @@ public class Nat464Xlat extends BaseNetworkObserver {
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;
}

View File

@@ -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 @@ public class NetworkAgentInfo implements Comparable<NetworkAgentInfo> {
// 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 @@ public class NetworkAgentInfo implements Comparable<NetworkAgentInfo> {
// 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 class NetworkAgentInfo implements Comparable<NetworkAgentInfo> {
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 class NetworkAgentInfo implements Comparable<NetworkAgentInfo> {
+ "}";
}
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 class NetworkAgentInfo implements Comparable<NetworkAgentInfo> {
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]";
}
}