From d74697aa9648b99fd999ad1812bd6014910df7ac Mon Sep 17 00:00:00 2001 From: Paul Hu Date: Wed, 12 Apr 2023 16:00:37 +0800 Subject: [PATCH 1/4] Record DiscoveryManager history logs for better debugging MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Log: 2023-04-17T15:05:28.428369 - Unregistering listener for serviceType:_nmt274981618._tcp.local 2023-04-17T15:05:28.228777 - [_nmt274981618._tcp.local-102] onServiceFound: ^Nsd.Test|Non-#AsCiI\Characters&\ufffe テスト 測試 2023-04-17T15:05:28.227786 - [_nmt274981618._tcp.local-102] onServiceNameDiscovered: ^Nsd.Test|Non-#AsCiI\Characters&\ufffe テスト 測試 2023-04-17T15:05:27.409364 - createServiceTypeClient for serviceType:_nmt274981618._tcp.local network:103 2023-04-17T15:05:27.409104 - createServiceTypeClient for serviceType:_nmt274981618._tcp.local network:102 2023-04-17T15:05:27.407701 - createServiceTypeClient for serviceType:_nmt274981618._tcp.local network:101 2023-04-17T15:05:27.398075 - Registering listener for serviceType: _nmt274981618._tcp.local Test: atest FrameworksNetTests android.net.cts.NsdManagerTest Bug: 275004614 Change-Id: Icaa1df2e7019e5cce1b4eca7edcb4a761b7b20cf --- .../mdns/MdnsDiscoveryManager.java | 23 +++++++------ .../mdns/MdnsServiceTypeClient.java | 32 +++++++++++++------ .../mdns/MdnsServiceTypeClientTests.java | 13 +++++--- 3 files changed, 44 insertions(+), 24 deletions(-) diff --git a/service-t/src/com/android/server/connectivity/mdns/MdnsDiscoveryManager.java b/service-t/src/com/android/server/connectivity/mdns/MdnsDiscoveryManager.java index fb8af8d121..491698d30c 100644 --- a/service-t/src/com/android/server/connectivity/mdns/MdnsDiscoveryManager.java +++ b/service-t/src/com/android/server/connectivity/mdns/MdnsDiscoveryManager.java @@ -23,16 +23,16 @@ import android.annotation.NonNull; import android.annotation.Nullable; import android.annotation.RequiresPermission; import android.net.Network; -import android.text.TextUtils; import android.util.ArrayMap; import android.util.Log; import android.util.Pair; import com.android.internal.annotations.GuardedBy; import com.android.internal.annotations.VisibleForTesting; -import com.android.server.connectivity.mdns.util.MdnsLogger; +import com.android.net.module.util.SharedLog; import java.io.IOException; +import java.io.PrintWriter; import java.util.ArrayList; import java.util.List; @@ -43,7 +43,7 @@ import java.util.List; public class MdnsDiscoveryManager implements MdnsSocketClientBase.Callback { private static final String TAG = MdnsDiscoveryManager.class.getSimpleName(); public static final boolean DBG = Log.isLoggable(TAG, Log.DEBUG); - private static final MdnsLogger LOGGER = new MdnsLogger("MdnsDiscoveryManager"); + private static final SharedLog LOGGER = new SharedLog(TAG); private final ExecutorProvider executorProvider; private final MdnsSocketClientBase socketClient; @@ -120,9 +120,7 @@ public class MdnsDiscoveryManager implements MdnsSocketClientBase.Callback { @NonNull String serviceType, @NonNull MdnsServiceBrowserListener listener, @NonNull MdnsSearchOptions searchOptions) { - LOGGER.log( - "Registering listener for subtypes: %s", - TextUtils.join(",", searchOptions.getSubtypes())); + LOGGER.i("Registering listener for serviceType: " + serviceType); if (perNetworkServiceTypeClients.isEmpty()) { // First listener. Starts the socket client. try { @@ -157,8 +155,7 @@ public class MdnsDiscoveryManager implements MdnsSocketClientBase.Callback { @RequiresPermission(permission.CHANGE_WIFI_MULTICAST_STATE) public synchronized void unregisterListener( @NonNull String serviceType, @NonNull MdnsServiceBrowserListener listener) { - LOGGER.log("Unregistering listener for service type: %s", serviceType); - if (DBG) Log.d(TAG, "Unregistering listener for serviceType:" + serviceType); + LOGGER.i("Unregistering listener for serviceType:" + serviceType); final List serviceTypeClients = perNetworkServiceTypeClients.getByServiceType(serviceType); if (serviceTypeClients.isEmpty()) { @@ -198,11 +195,19 @@ public class MdnsDiscoveryManager implements MdnsSocketClientBase.Callback { } } + /** Dump info to dumpsys */ + public void dump(PrintWriter pw) { + LOGGER.reverseDump(pw); + } + @VisibleForTesting MdnsServiceTypeClient createServiceTypeClient(@NonNull String serviceType, @Nullable Network network) { + LOGGER.log("createServiceTypeClient for serviceType:" + serviceType + + " network:" + network); return new MdnsServiceTypeClient( serviceType, socketClient, - executorProvider.newServiceTypeClientSchedulerExecutor(), network); + executorProvider.newServiceTypeClientSchedulerExecutor(), network, + LOGGER.forSubComponent(serviceType + "-" + network)); } } \ No newline at end of file diff --git a/service-t/src/com/android/server/connectivity/mdns/MdnsServiceTypeClient.java b/service-t/src/com/android/server/connectivity/mdns/MdnsServiceTypeClient.java index f87804bdcd..1d0772ad19 100644 --- a/service-t/src/com/android/server/connectivity/mdns/MdnsServiceTypeClient.java +++ b/service-t/src/com/android/server/connectivity/mdns/MdnsServiceTypeClient.java @@ -28,7 +28,7 @@ import android.util.Pair; import com.android.internal.annotations.GuardedBy; import com.android.internal.annotations.VisibleForTesting; -import com.android.server.connectivity.mdns.util.MdnsLogger; +import com.android.net.module.util.SharedLog; import java.net.Inet4Address; import java.net.Inet6Address; @@ -49,8 +49,6 @@ import java.util.concurrent.ScheduledExecutorService; public class MdnsServiceTypeClient { private static final int DEFAULT_MTU = 1500; - private static final MdnsLogger LOGGER = new MdnsLogger("MdnsServiceTypeClient"); - private final String serviceType; private final String[] serviceTypeLabels; @@ -58,6 +56,7 @@ public class MdnsServiceTypeClient { private final MdnsResponseDecoder responseDecoder; private final ScheduledExecutorService executor; @Nullable private final Network network; + @NonNull private final SharedLog sharedLog; private final Object lock = new Object(); private final ArrayMap listeners = new ArrayMap<>(); @@ -90,8 +89,10 @@ public class MdnsServiceTypeClient { @NonNull String serviceType, @NonNull MdnsSocketClientBase socketClient, @NonNull ScheduledExecutorService executor, - @Nullable Network network) { - this(serviceType, socketClient, executor, new MdnsResponseDecoder.Clock(), network); + @Nullable Network network, + @NonNull SharedLog sharedLog) { + this(serviceType, socketClient, executor, new MdnsResponseDecoder.Clock(), network, + sharedLog); } @VisibleForTesting @@ -100,7 +101,8 @@ public class MdnsServiceTypeClient { @NonNull MdnsSocketClientBase socketClient, @NonNull ScheduledExecutorService executor, @NonNull MdnsResponseDecoder.Clock clock, - @Nullable Network network) { + @Nullable Network network, + @NonNull SharedLog sharedLog) { this.serviceType = serviceType; this.socketClient = socketClient; this.executor = executor; @@ -108,6 +110,7 @@ public class MdnsServiceTypeClient { this.responseDecoder = new MdnsResponseDecoder(clock, serviceTypeLabels); this.clock = clock; this.network = network; + this.sharedLog = sharedLog; } private static MdnsServiceInfo buildMdnsServiceInfoFromResponse( @@ -253,20 +256,20 @@ public class MdnsServiceTypeClient { } private void onResponseModified(@NonNull MdnsResponse response) { + final String serviceInstanceName = response.getServiceInstanceName(); final MdnsResponse currentResponse = - instanceNameToResponse.get(response.getServiceInstanceName()); + instanceNameToResponse.get(serviceInstanceName); boolean newServiceFound = false; boolean serviceBecomesComplete = false; if (currentResponse == null) { newServiceFound = true; - String serviceInstanceName = response.getServiceInstanceName(); if (serviceInstanceName != null) { instanceNameToResponse.put(serviceInstanceName, response); } } else { boolean before = currentResponse.isComplete(); - instanceNameToResponse.put(response.getServiceInstanceName(), response); + instanceNameToResponse.put(serviceInstanceName, response); boolean after = response.isComplete(); serviceBecomesComplete = !before && after; } @@ -276,13 +279,16 @@ public class MdnsServiceTypeClient { for (int i = 0; i < listeners.size(); i++) { final MdnsServiceBrowserListener listener = listeners.keyAt(i); if (newServiceFound) { + sharedLog.log("onServiceNameDiscovered: " + serviceInstanceName); listener.onServiceNameDiscovered(serviceInfo); } if (response.isComplete()) { if (newServiceFound || serviceBecomesComplete) { + sharedLog.log("onServiceFound: " + serviceInstanceName); listener.onServiceFound(serviceInfo); } else { + sharedLog.log("onServiceUpdated: " + serviceInstanceName); listener.onServiceUpdated(serviceInfo); } } @@ -299,8 +305,10 @@ public class MdnsServiceTypeClient { final MdnsServiceInfo serviceInfo = buildMdnsServiceInfoFromResponse(response, serviceTypeLabels); if (response.isComplete()) { + sharedLog.log("onServiceRemoved: " + serviceInstanceName); listener.onServiceRemoved(serviceInfo); } + sharedLog.log("onServiceNameRemoved: " + serviceInstanceName); listener.onServiceNameRemoved(serviceInfo); } } @@ -475,7 +483,7 @@ public class MdnsServiceTypeClient { servicesToResolve) .call(); } catch (RuntimeException e) { - LOGGER.e(String.format("Failed to run EnqueueMdnsQueryCallable for subtype: %s", + sharedLog.e(String.format("Failed to run EnqueueMdnsQueryCallable for subtype: %s", TextUtils.join(",", config.subtypes)), e); result = null; } @@ -520,8 +528,12 @@ public class MdnsServiceTypeClient { buildMdnsServiceInfoFromResponse( existingResponse, serviceTypeLabels); if (existingResponse.isComplete()) { + sharedLog.log("TTL expired. onServiceRemoved: " + + serviceInstanceName); listener.onServiceRemoved(serviceInfo); } + sharedLog.log("TTL expired. onServiceNameRemoved: " + + serviceInstanceName); listener.onServiceNameRemoved(serviceInfo); } } diff --git a/tests/unit/java/com/android/server/connectivity/mdns/MdnsServiceTypeClientTests.java b/tests/unit/java/com/android/server/connectivity/mdns/MdnsServiceTypeClientTests.java index 5d58f5d360..98348b6683 100644 --- a/tests/unit/java/com/android/server/connectivity/mdns/MdnsServiceTypeClientTests.java +++ b/tests/unit/java/com/android/server/connectivity/mdns/MdnsServiceTypeClientTests.java @@ -41,6 +41,7 @@ import android.net.InetAddresses; import android.net.Network; import android.text.TextUtils; +import com.android.net.module.util.SharedLog; import com.android.server.connectivity.mdns.MdnsServiceInfo.TextEntry; import com.android.server.connectivity.mdns.MdnsServiceTypeClient.QueryTaskConfig; import com.android.testutils.DevSdkIgnoreRule; @@ -99,6 +100,8 @@ public class MdnsServiceTypeClientTests { private Network mockNetwork; @Mock private MdnsResponseDecoder.Clock mockDecoderClock; + @Mock + private SharedLog mockSharedLog; @Captor private ArgumentCaptor serviceInfoCaptor; @@ -166,7 +169,7 @@ public class MdnsServiceTypeClientTests { client = new MdnsServiceTypeClient(SERVICE_TYPE, mockSocketClient, currentThreadExecutor, - mockDecoderClock, mockNetwork) { + mockDecoderClock, mockNetwork, mockSharedLog) { @Override MdnsPacketWriter createMdnsPacketWriter() { return mockPacketWriter; @@ -701,7 +704,7 @@ public class MdnsServiceTypeClientTests { final String serviceInstanceName = "service-instance-1"; client = new MdnsServiceTypeClient(SERVICE_TYPE, mockSocketClient, currentThreadExecutor, - mockDecoderClock, mockNetwork) { + mockDecoderClock, mockNetwork, mockSharedLog) { @Override MdnsPacketWriter createMdnsPacketWriter() { return mockPacketWriter; @@ -740,7 +743,7 @@ public class MdnsServiceTypeClientTests { final String serviceInstanceName = "service-instance-1"; client = new MdnsServiceTypeClient(SERVICE_TYPE, mockSocketClient, currentThreadExecutor, - mockDecoderClock, mockNetwork) { + mockDecoderClock, mockNetwork, mockSharedLog) { @Override MdnsPacketWriter createMdnsPacketWriter() { return mockPacketWriter; @@ -773,7 +776,7 @@ public class MdnsServiceTypeClientTests { final String serviceInstanceName = "service-instance-1"; client = new MdnsServiceTypeClient(SERVICE_TYPE, mockSocketClient, currentThreadExecutor, - mockDecoderClock, mockNetwork) { + mockDecoderClock, mockNetwork, mockSharedLog) { @Override MdnsPacketWriter createMdnsPacketWriter() { return mockPacketWriter; @@ -898,7 +901,7 @@ public class MdnsServiceTypeClientTests { @Test public void testProcessResponse_Resolve() throws Exception { client = new MdnsServiceTypeClient( - SERVICE_TYPE, mockSocketClient, currentThreadExecutor, mockNetwork); + SERVICE_TYPE, mockSocketClient, currentThreadExecutor, mockNetwork, mockSharedLog); final String instanceName = "service-instance"; final String[] hostname = new String[] { "testhost "}; From b204ce59d9d1812f551a6d0e2b9baf583cfa9986 Mon Sep 17 00:00:00 2001 From: Paul Hu Date: Wed, 12 Apr 2023 16:35:44 +0800 Subject: [PATCH 2/4] Record SocketProvider history logs for better debugging Log: 2023-04-17T15:05:34.377599 - Stop monitoring sockets. 2023-04-17T15:05:34.377310 - Remove socket on net:101 after unrequestSocket 2023-04-17T15:05:28.330290 - Remove socket on net:103 2023-04-17T15:05:28.292106 - Remove socket on net:102 2023-04-17T15:05:26.441517 - Create socket on net:NetworkAsKey{ network=102 }, ifName:testtap0 2023-04-17T15:05:26.435649 - Create socket on net:NetworkAsKey{ network=103 }, ifName:testtap1 2023-04-17T15:05:26.416708 - Create socket on net:NetworkAsKey{ network=101 }, ifName:wlan0 2023-04-17T15:05:26.409005 - Start monitoring sockets. Test: atest FrameworksNetTests android.net.cts.NsdManagerTest Bug: 275004614 Change-Id: I46f806a8f9d171c114d22b426db43260e004cb9e --- .../connectivity/mdns/MdnsSocketProvider.java | 29 ++++++++++++------- 1 file changed, 18 insertions(+), 11 deletions(-) diff --git a/service-t/src/com/android/server/connectivity/mdns/MdnsSocketProvider.java b/service-t/src/com/android/server/connectivity/mdns/MdnsSocketProvider.java index 8017ee01e7..c45345a156 100644 --- a/service-t/src/com/android/server/connectivity/mdns/MdnsSocketProvider.java +++ b/service-t/src/com/android/server/connectivity/mdns/MdnsSocketProvider.java @@ -42,9 +42,9 @@ import com.android.internal.annotations.VisibleForTesting; import com.android.net.module.util.CollectionUtils; import com.android.net.module.util.LinkPropertiesUtils.CompareResult; import com.android.net.module.util.SharedLog; -import com.android.server.connectivity.mdns.util.MdnsLogger; import java.io.IOException; +import java.io.PrintWriter; import java.net.NetworkInterface; import java.net.SocketException; import java.util.ArrayList; @@ -66,7 +66,7 @@ public class MdnsSocketProvider { // But 1440 should generally be enough because of standard Ethernet. // Note: mdnsresponder mDNSEmbeddedAPI.h uses 8940 for Ethernet jumbo frames. private static final int READ_BUFFER_SIZE = 2048; - private static final MdnsLogger LOGGER = new MdnsLogger(TAG); + private static final SharedLog LOGGER = new SharedLog(TAG); private static final int IFACE_IDX_NOT_EXIST = -1; @NonNull private final Context mContext; @NonNull private final Looper mLooper; @@ -132,7 +132,7 @@ public class MdnsSocketProvider { } }; - mSocketNetlinkMonitor = mDependencies.createSocketNetlinkMonitor(mHandler, LOGGER.mLog, + mSocketNetlinkMonitor = mDependencies.createSocketNetlinkMonitor(mHandler, LOGGER, new NetLinkMessageProcessor()); } @@ -258,7 +258,7 @@ public class MdnsSocketProvider { Log.d(TAG, "Already monitoring sockets."); return; } - if (DBG) Log.d(TAG, "Start monitoring sockets."); + LOGGER.i("Start monitoring sockets."); mContext.getSystemService(ConnectivityManager.class).registerNetworkCallback( new NetworkRequest.Builder().clearCapabilities().build(), mNetworkCallback, mHandler); @@ -287,6 +287,7 @@ public class MdnsSocketProvider { // Only unregister the network callback if there is no socket request. if (mCallbacksToRequestedNetworks.isEmpty()) { + LOGGER.i("Stop monitoring sockets."); mContext.getSystemService(ConnectivityManager.class) .unregisterNetworkCallback(mNetworkCallback); @@ -312,7 +313,6 @@ public class MdnsSocketProvider { Log.d(TAG, "Monitoring sockets hasn't been started."); return; } - if (DBG) Log.d(TAG, "Try to stop monitoring sockets."); mRequestStop = true; maybeStopMonitoringSockets(); } @@ -431,10 +431,7 @@ public class MdnsSocketProvider { return; } - if (DBG) { - Log.d(TAG, "Create a socket on network:" + networkKey - + " with interfaceName:" + interfaceName); - } + LOGGER.log("Create socket on net:" + networkKey + ", ifName:" + interfaceName); final MdnsInterfaceSocket socket = mDependencies.createMdnsInterfaceSocket( networkInterface.getNetworkInterface(), MdnsConstants.MDNS_PORT, mLooper, mPacketReadBuffer); @@ -455,7 +452,7 @@ public class MdnsSocketProvider { notifySocketCreated(((NetworkAsKey) networkKey).mNetwork, socket, addresses); } } catch (IOException e) { - Log.e(TAG, "Create a socket failed with interface=" + interfaceName, e); + LOGGER.e("Create socket failed ifName:" + interfaceName, e); } } @@ -484,7 +481,7 @@ public class MdnsSocketProvider { // transports above in priority. return iface.supportsMulticast(); } catch (SocketException e) { - Log.e(TAG, "Error checking interface flags", e); + LOGGER.e("Error checking interface flags", e); return false; } } @@ -495,6 +492,7 @@ public class MdnsSocketProvider { socketInfo.mSocket.destroy(); notifyInterfaceDestroyed(network, socketInfo.mSocket); + LOGGER.log("Remove socket on net:" + network); } private void removeTetherInterfaceSocket(String interfaceName) { @@ -502,6 +500,7 @@ public class MdnsSocketProvider { if (socketInfo == null) return; socketInfo.mSocket.destroy(); notifyInterfaceDestroyed(null /* network */, socketInfo.mSocket); + LOGGER.log("Remove socket on ifName:" + interfaceName); } private void notifySocketCreated(Network network, MdnsInterfaceSocket socket, @@ -610,6 +609,7 @@ public class MdnsSocketProvider { info.mSocket.destroy(); // Still notify to unrequester for socket destroy. cb.onInterfaceDestroyed(network, info.mSocket); + LOGGER.log("Remove socket on net:" + network + " after unrequestSocket"); } // Remove all sockets for tethering interface because these sockets do not have associated @@ -620,6 +620,8 @@ public class MdnsSocketProvider { info.mSocket.destroy(); // Still notify to unrequester for socket destroy. cb.onInterfaceDestroyed(null /* network */, info.mSocket); + LOGGER.log("Remove socket on ifName:" + mTetherInterfaceSockets.keyAt(i) + + " after unrequestSocket"); } mTetherInterfaceSockets.clear(); @@ -627,6 +629,11 @@ public class MdnsSocketProvider { maybeStopMonitoringSockets(); } + /** Dump info to dumpsys */ + public void dump(PrintWriter pw) { + LOGGER.reverseDump(pw); + } + /*** Callbacks for listening socket changes */ public interface SocketCallback { /*** Notify the socket is created */ From 1571df639a8fd17098dc910b9371ad41311eeec9 Mon Sep 17 00:00:00 2001 From: Paul Hu Date: Wed, 12 Apr 2023 19:15:22 +0800 Subject: [PATCH 3/4] Record Advertiser history logs for better debugging MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Log: 2023-04-12T20:00:18.100961 - Removing service with ID 2 2023-04-12T20:00:17.173904 - [wlan0] Probing finished for service 2 2023-04-12T20:00:17.147089 - [testtap1] Probing finished for service 2 2023-04-12T20:00:17.074575 - [testtap0] Probing finished for service 2 2023-04-12T20:00:16.249636 - Adding service name: ^Nsd.Test|Non-#AsCiI\Characters&\ufffe テスト 測試, type: _nmt950580894._tcp, hostAddresses: , port: 12345, network: null, txtRecord: with ID 2 Test: atest FrameworksNetTests android.net.cts.NsdManagerTest Bug: 275004614 Change-Id: I22577615b0b2c212c0a4349a06ef3c75239a5651 --- .../connectivity/mdns/MdnsAdvertiser.java | 21 ++++++++-------- .../mdns/MdnsInterfaceAdvertiser.java | 24 ++++++++++--------- .../mdns/MdnsInterfaceAdvertiserTest.kt | 5 +++- 3 files changed, 28 insertions(+), 22 deletions(-) diff --git a/service-t/src/com/android/server/connectivity/mdns/MdnsAdvertiser.java b/service-t/src/com/android/server/connectivity/mdns/MdnsAdvertiser.java index ec3e997938..33fef9d692 100644 --- a/service-t/src/com/android/server/connectivity/mdns/MdnsAdvertiser.java +++ b/service-t/src/com/android/server/connectivity/mdns/MdnsAdvertiser.java @@ -28,7 +28,9 @@ import android.util.Log; import android.util.SparseArray; import com.android.internal.annotations.VisibleForTesting; +import com.android.net.module.util.SharedLog; +import java.io.PrintWriter; import java.util.List; import java.util.Map; import java.util.UUID; @@ -46,6 +48,7 @@ public class MdnsAdvertiser { // Top-level domain for link-local queries, as per RFC6762 3. private static final String LOCAL_TLD = "local"; + private static final SharedLog LOGGER = new SharedLog(TAG); private final Looper mLooper; private final AdvertiserCallback mCb; @@ -82,7 +85,7 @@ public class MdnsAdvertiser { // Note NetworkInterface is final and not mockable final String logTag = socket.getInterface().getName(); return new MdnsInterfaceAdvertiser(logTag, socket, initialAddresses, looper, - packetCreationBuffer, cb, deviceHostName); + packetCreationBuffer, cb, deviceHostName, LOGGER.forSubComponent(logTag)); } /** @@ -129,9 +132,7 @@ public class MdnsAdvertiser { @Override public void onServiceConflict(@NonNull MdnsInterfaceAdvertiser advertiser, int serviceId) { - if (DBG) { - Log.v(TAG, "Found conflict, restarted probing for service " + serviceId); - } + LOGGER.i("Found conflict, restarted probing for service " + serviceId); final Registration registration = mRegistrations.get(serviceId); if (registration == null) return; @@ -439,9 +440,7 @@ public class MdnsAdvertiser { return; } - if (DBG) { - Log.i(TAG, "Adding service " + service + " with ID " + id); - } + LOGGER.i("Adding service " + service + " with ID " + id); final Network network = service.getNetwork(); final Registration registration = new Registration(service); @@ -473,9 +472,7 @@ public class MdnsAdvertiser { public void removeService(int id) { checkThread(); if (!mRegistrations.contains(id)) return; - if (DBG) { - Log.i(TAG, "Removing service with ID " + id); - } + LOGGER.i("Removing service with ID " + id); for (int i = mAdvertiserRequests.size() - 1; i >= 0; i--) { final InterfaceAdvertiserRequest advertiser = mAdvertiserRequests.valueAt(i); advertiser.removeService(id); @@ -487,6 +484,10 @@ public class MdnsAdvertiser { } } + /** Dump info to dumpsys */ + public void dump(PrintWriter pw) { + LOGGER.reverseDump(pw); + } private static boolean any(@NonNull ArrayMap map, @NonNull BiPredicate predicate) { for (int i = 0; i < map.size(); i++) { diff --git a/service-t/src/com/android/server/connectivity/mdns/MdnsInterfaceAdvertiser.java b/service-t/src/com/android/server/connectivity/mdns/MdnsInterfaceAdvertiser.java index 79cddce0c8..9eaa580f46 100644 --- a/service-t/src/com/android/server/connectivity/mdns/MdnsInterfaceAdvertiser.java +++ b/service-t/src/com/android/server/connectivity/mdns/MdnsInterfaceAdvertiser.java @@ -26,6 +26,7 @@ import android.util.Log; import com.android.internal.annotations.VisibleForTesting; import com.android.net.module.util.HexDump; +import com.android.net.module.util.SharedLog; import com.android.server.connectivity.mdns.MdnsAnnouncer.BaseAnnouncementInfo; import com.android.server.connectivity.mdns.MdnsPacketRepeater.PacketRepeaterCallback; @@ -62,6 +63,9 @@ public class MdnsInterfaceAdvertiser implements MulticastPacketReader.PacketHand @NonNull private final MdnsReplySender mReplySender; + @NonNull + private final SharedLog mSharedLog; + /** * Callbacks called by {@link MdnsInterfaceAdvertiser} to report status updates. */ @@ -96,15 +100,13 @@ public class MdnsInterfaceAdvertiser implements MulticastPacketReader.PacketHand @Override public void onFinished(MdnsProber.ProbingInfo info) { final MdnsAnnouncer.AnnouncementInfo announcementInfo; - if (DBG) { - Log.v(mTag, "Probing finished for service " + info.getServiceId()); - } + mSharedLog.i("Probing finished for service " + info.getServiceId()); mCbHandler.post(() -> mCb.onRegisterServiceSucceeded( MdnsInterfaceAdvertiser.this, info.getServiceId())); try { announcementInfo = mRecordRepository.onProbingSucceeded(info); } catch (IOException e) { - Log.e(mTag, "Error building announcements", e); + mSharedLog.e("Error building announcements", e); return; } @@ -171,15 +173,16 @@ public class MdnsInterfaceAdvertiser implements MulticastPacketReader.PacketHand public MdnsInterfaceAdvertiser(@NonNull String logTag, @NonNull MdnsInterfaceSocket socket, @NonNull List initialAddresses, @NonNull Looper looper, @NonNull byte[] packetCreationBuffer, @NonNull Callback cb, - @NonNull String[] deviceHostName) { + @NonNull String[] deviceHostName, @NonNull SharedLog sharedLog) { this(logTag, socket, initialAddresses, looper, packetCreationBuffer, cb, - new Dependencies(), deviceHostName); + new Dependencies(), deviceHostName, sharedLog); } public MdnsInterfaceAdvertiser(@NonNull String logTag, @NonNull MdnsInterfaceSocket socket, @NonNull List initialAddresses, @NonNull Looper looper, @NonNull byte[] packetCreationBuffer, @NonNull Callback cb, - @NonNull Dependencies deps, @NonNull String[] deviceHostName) { + @NonNull Dependencies deps, @NonNull String[] deviceHostName, + @NonNull SharedLog sharedLog) { mTag = MdnsInterfaceAdvertiser.class.getSimpleName() + "/" + logTag; mRecordRepository = deps.makeRecordRepository(looper, deviceHostName); mRecordRepository.updateAddresses(initialAddresses); @@ -190,6 +193,7 @@ public class MdnsInterfaceAdvertiser implements MulticastPacketReader.PacketHand mAnnouncer = deps.makeMdnsAnnouncer(logTag, looper, mReplySender, mAnnouncingCallback); mProber = deps.makeMdnsProber(logTag, looper, mReplySender, mProbingCallback); + mSharedLog = sharedLog; } /** @@ -213,10 +217,8 @@ public class MdnsInterfaceAdvertiser implements MulticastPacketReader.PacketHand // Cancel announcements for the existing service. This only happens for exiting services // (so cancelling exiting announcements), as per RecordRepository.addService. if (replacedExitingService >= 0) { - if (DBG) { - Log.d(mTag, "Service " + replacedExitingService - + " getting re-added, cancelling exit announcements"); - } + mSharedLog.i("Service " + replacedExitingService + + " getting re-added, cancelling exit announcements"); mAnnouncer.stop(replacedExitingService); } mProber.startProbing(mRecordRepository.setServiceProbing(id)); diff --git a/tests/unit/java/com/android/server/connectivity/mdns/MdnsInterfaceAdvertiserTest.kt b/tests/unit/java/com/android/server/connectivity/mdns/MdnsInterfaceAdvertiserTest.kt index 0ca08350a8..9c0abfcf08 100644 --- a/tests/unit/java/com/android/server/connectivity/mdns/MdnsInterfaceAdvertiserTest.kt +++ b/tests/unit/java/com/android/server/connectivity/mdns/MdnsInterfaceAdvertiserTest.kt @@ -22,6 +22,7 @@ import android.net.nsd.NsdServiceInfo import android.os.Build import android.os.HandlerThread import com.android.net.module.util.HexDump +import com.android.net.module.util.SharedLog import com.android.server.connectivity.mdns.MdnsAnnouncer.AnnouncementInfo import com.android.server.connectivity.mdns.MdnsAnnouncer.BaseAnnouncementInfo import com.android.server.connectivity.mdns.MdnsAnnouncer.ExitAnnouncementInfo @@ -75,6 +76,7 @@ class MdnsInterfaceAdvertiserTest { private val replySender = mock(MdnsReplySender::class.java) private val announcer = mock(MdnsAnnouncer::class.java) private val prober = mock(MdnsProber::class.java) + private val sharedlog = mock(SharedLog::class.java) @Suppress("UNCHECKED_CAST") private val probeCbCaptor = ArgumentCaptor.forClass(PacketRepeaterCallback::class.java) as ArgumentCaptor> @@ -97,7 +99,8 @@ class MdnsInterfaceAdvertiserTest { TEST_BUFFER, cb, deps, - TEST_HOSTNAME + TEST_HOSTNAME, + sharedlog ) } From eaa99274bd21413d0d6b586a31fbaf0c959c735f Mon Sep 17 00:00:00 2001 From: Paul Hu Date: Thu, 13 Apr 2023 09:09:30 +0800 Subject: [PATCH 4/4] Put client logs into SharedLog and dump more logs MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - Put client logs into SharedLog and dump them to the bugreport - Adjust log format in bugreport. - Also dump DiscoveryManager, Advertiser and SocketProvider logs Before: NsdService: total records=9 rec[0]: time=04-12 14:54:31.742 processed=DefaultState org=EnabledState dest= what=REGISTER_CLIENT rec[1]: time=04-12 14:54:31.744 processed=EnabledState org=EnabledState dest= what=REGISTER_SERVICE rec[2]: time=04-12 14:54:32.649 processed=EnabledState org=EnabledState dest= what=DISCOVER_SERVICES curState=EnabledState After: NsdService: total records=9 rec[0]: time=04-17 15:05:26.408 processed=DefaultState org=EnabledState dest= what=REGISTER_CLIENT rec[1]: time=04-17 15:05:26.409 processed=EnabledState org=EnabledState dest= what=REGISTER_SERVICE rec[2]: time=04-17 15:05:27.409 processed=EnabledState org=EnabledState dest= what=DISCOVER_SERVICES rec[3]: time=04-17 15:05:28.236 processed=EnabledState org=EnabledState dest= what=MDNS_DISCOVERY_MANAGER_EVENT rec[4]: time=04-17 15:05:28.241 processed=EnabledState org=EnabledState dest= what=RESOLVE_SERVICE rec[5]: time=04-17 15:05:28.248 processed=EnabledState org=EnabledState dest= what=MDNS_DISCOVERY_MANAGER_EVENT rec[6]: time=04-17 15:05:28.255 processed=EnabledState org=EnabledState dest= what=UNREGISTER_SERVICE rec[7]: time=04-17 15:05:28.428 processed=DefaultState org=EnabledState dest= what=UNREGISTER_CLIENT curState=EnabledState 2023-04-17T15:05:28.428230 - [Client10082-1] Client unregistered. expungeAllRequests! 2023-04-17T15:05:28.241837 - [Client10082-1] Register a ResolutionListener 4 for service type:_nmt274981618._tcp.local 2023-04-17T15:05:27.409895 - [Client10082-1] Register a DiscoveryListener 3 for service type:_nmt274981618._tcp.local 2023-04-17T15:05:26.408015 - [Client10082-1] New client. useJavaBackend=true Advertiser: 2023-04-17T15:05:28.252545 - Removing service with ID 2 2023-04-17T15:05:27.213023 - [testtap0] Probing finished for service 2 2023-04-17T15:05:26.409607 - Adding service name: ^Nsd.Test|Non-#AsCiI\Characters&\ufffe テスト 測試, type: _nmt274981618._tcp, hostAddresses: , port: 12345, network: null, txtRecord: with ID 2 DiscoveryManager: 2023-04-17T15:05:28.428369 - Unregistering listener for serviceType:_nmt274981618._tcp.local 2023-04-17T15:05:28.247622 - Unregistering listener for serviceType:_nmt274981618._tcp.local 2023-04-17T15:05:28.241062 - Registering listener for serviceType: _nmt274981618._tcp.local 2023-04-17T15:05:28.228777 - [_nmt274981618._tcp.local-102] onServiceFound: ^Nsd.Test|Non-#AsCiI\Characters&\ufffe テスト 測試 2023-04-17T15:05:28.227786 - [_nmt274981618._tcp.local-102] onServiceNameDiscovered: ^Nsd.Test|Non-#AsCiI\Characters&\ufffe テスト 測試 2023-04-17T15:05:27.409104 - createServiceTypeClient for serviceType:_nmt274981618._tcp.local network:102 2023-04-17T15:05:27.398075 - Registering listener for serviceType: _nmt274981618._tcp.local SocketProvider: 2023-04-17T15:05:34.377599 - Stop monitoring sockets. 2023-04-17T15:05:28.292106 - Remove socket on net:102 2023-04-17T15:05:26.441517 - Create socket on net:NetworkAsKey{ network=102 }, ifName:testtap0 2023-04-17T15:05:26.409005 - Start monitoring sockets. Bug: 275004614 Test: atest FrameworksNetTests android.net.cts.NsdManagerTest Change-Id: I41743f47abe5ca75c2a33da674d24d3a7f997d93 --- .../src/com/android/server/NsdService.java | 81 +++++++++++++++---- 1 file changed, 67 insertions(+), 14 deletions(-) diff --git a/service-t/src/com/android/server/NsdService.java b/service-t/src/com/android/server/NsdService.java index c5104d8ef1..383ed2cf92 100644 --- a/service-t/src/com/android/server/NsdService.java +++ b/service-t/src/com/android/server/NsdService.java @@ -44,6 +44,7 @@ import android.net.nsd.INsdServiceConnector; import android.net.nsd.MDnsManager; import android.net.nsd.NsdManager; import android.net.nsd.NsdServiceInfo; +import android.os.Binder; import android.os.Handler; import android.os.HandlerThread; import android.os.IBinder; @@ -56,10 +57,12 @@ import android.util.Log; import android.util.SparseArray; import com.android.internal.annotations.VisibleForTesting; +import com.android.internal.util.IndentingPrintWriter; import com.android.internal.util.State; import com.android.internal.util.StateMachine; import com.android.net.module.util.DeviceConfigUtils; import com.android.net.module.util.PermissionUtils; +import com.android.net.module.util.SharedLog; import com.android.server.connectivity.mdns.ExecutorProvider; import com.android.server.connectivity.mdns.MdnsAdvertiser; import com.android.server.connectivity.mdns.MdnsDiscoveryManager; @@ -159,6 +162,7 @@ public class NsdService extends INsdManager.Stub { private final MdnsSocketProvider mMdnsSocketProvider; @NonNull private final MdnsAdvertiser mAdvertiser; + private final SharedLog mServiceLogs = new SharedLog(TAG); // WARNING : Accessing these values in any thread is not safe, it must only be changed in the // state machine thread. If change this outside state machine, it will need to introduce // synchronization. @@ -179,6 +183,8 @@ public class NsdService extends INsdManager.Stub { private int mUniqueId = 1; // The count of the connected legacy clients. private int mLegacyClientCount = 0; + // The number of client that ever connected. + private int mClientNumberId = 1; private static class MdnsListener implements MdnsServiceBrowserListener { protected final int mClientId; @@ -332,6 +338,7 @@ public class NsdService extends INsdManager.Stub { mMDnsManager.startDaemon(); mIsDaemonStarted = true; maybeScheduleStop(); + mServiceLogs.log("Start mdns_responder daemon"); } private void maybeStopDaemon() { @@ -342,6 +349,7 @@ public class NsdService extends INsdManager.Stub { mMDnsManager.unregisterEventListener(mMDnsEventCallback); mMDnsManager.stopDaemon(); mIsDaemonStarted = false; + mServiceLogs.log("Stop mdns_responder daemon"); } private boolean isAnyRequestActive() { @@ -401,7 +409,9 @@ public class NsdService extends INsdManager.Stub { final INsdManagerCallback cb = arg.callback; try { cb.asBinder().linkToDeath(arg.connector, 0); - cInfo = new ClientInfo(cb, arg.useJavaBackend); + final String tag = "Client" + arg.uid + "-" + mClientNumberId++; + cInfo = new ClientInfo(cb, arg.useJavaBackend, + mServiceLogs.forSubComponent(tag)); mClients.put(arg.connector, cInfo); } catch (RemoteException e) { Log.w(TAG, "Client " + clientId + " has already died"); @@ -628,6 +638,8 @@ public class NsdService extends INsdManager.Stub { listenServiceType, listener, options); storeDiscoveryManagerRequestMap(clientId, id, listener, clientInfo); clientInfo.onDiscoverServicesStarted(clientId, info); + clientInfo.log("Register a DiscoveryListener " + id + + " for service type:" + listenServiceType); } else { maybeStartDaemon(); if (discoverServices(id, info)) { @@ -669,6 +681,7 @@ public class NsdService extends INsdManager.Stub { if (request instanceof DiscoveryManagerRequest) { stopDiscoveryManagerRequest(request, clientId, id, clientInfo); clientInfo.onStopDiscoverySucceeded(clientId); + clientInfo.log("Unregister the DiscoveryListener " + id); } else { removeRequestMap(clientId, id, clientInfo); if (stopServiceDiscovery(id)) { @@ -804,6 +817,8 @@ public class NsdService extends INsdManager.Stub { mMdnsDiscoveryManager.registerListener( resolveServiceType, listener, options); storeDiscoveryManagerRequestMap(clientId, id, listener, clientInfo); + clientInfo.log("Register a ResolutionListener " + id + + " for service type:" + resolveServiceType); } else { if (clientInfo.mResolvedService != null) { clientInfo.onResolveServiceFailed( @@ -846,6 +861,7 @@ public class NsdService extends INsdManager.Stub { if (request instanceof DiscoveryManagerRequest) { stopDiscoveryManagerRequest(request, clientId, id, clientInfo); clientInfo.onStopResolutionSucceeded(clientId); + clientInfo.log("Unregister the ResolutionListener " + id); } else { removeRequestMap(clientId, id, clientInfo); if (stopResolveService(id)) { @@ -891,6 +907,8 @@ public class NsdService extends INsdManager.Stub { mMdnsDiscoveryManager.registerListener( resolveServiceType, listener, options); storeDiscoveryManagerRequestMap(clientId, id, listener, clientInfo); + clientInfo.log("Register a ServiceInfoListener " + id + + " for service type:" + resolveServiceType); break; } case NsdManager.UNREGISTER_SERVICE_CALLBACK: { @@ -914,6 +932,7 @@ public class NsdService extends INsdManager.Stub { if (request instanceof DiscoveryManagerRequest) { stopDiscoveryManagerRequest(request, clientId, id, clientInfo); clientInfo.onServiceInfoCallbackUnregistered(clientId); + clientInfo.log("Unregister the ServiceInfoListener " + id); } else { loge("Unregister failed with non-DiscoveryManagerRequest."); } @@ -1545,12 +1564,14 @@ public class NsdService extends INsdManager.Stub { @NonNull public final NsdServiceConnector connector; @NonNull public final INsdManagerCallback callback; public final boolean useJavaBackend; + public final int uid; ConnectorArgs(@NonNull NsdServiceConnector connector, @NonNull INsdManagerCallback callback, - boolean useJavaBackend) { + boolean useJavaBackend, int uid) { this.connector = connector; this.callback = callback; this.useJavaBackend = useJavaBackend; + this.uid = uid; } } @@ -1559,9 +1580,9 @@ public class NsdService extends INsdManager.Stub { mContext.enforceCallingOrSelfPermission(android.Manifest.permission.INTERNET, "NsdService"); if (DBG) Log.d(TAG, "New client connect. useJavaBackend=" + useJavaBackend); final INsdServiceConnector connector = new NsdServiceConnector(); - mNsdStateMachine.sendMessage(mNsdStateMachine.obtainMessage( - NsdManager.REGISTER_CLIENT, - new ConnectorArgs((NsdServiceConnector) connector, cb, useJavaBackend))); + mNsdStateMachine.sendMessage(mNsdStateMachine.obtainMessage(NsdManager.REGISTER_CLIENT, + new ConnectorArgs((NsdServiceConnector) connector, cb, useJavaBackend, + Binder.getCallingUid()))); return connector; } @@ -1760,15 +1781,39 @@ public class NsdService extends INsdManager.Stub { } @Override - public void dump(FileDescriptor fd, PrintWriter pw, String[] args) { - if (!PermissionUtils.checkDumpPermission(mContext, TAG, pw)) return; - - for (ClientInfo client : mClients.values()) { - pw.println("Client Info"); - pw.println(client); - } + public void dump(FileDescriptor fd, PrintWriter writer, String[] args) { + if (!PermissionUtils.checkDumpPermission(mContext, TAG, writer)) return; + final IndentingPrintWriter pw = new IndentingPrintWriter(writer, " "); + // Dump state machine logs mNsdStateMachine.dump(fd, pw, args); + + // Dump service and clients logs + pw.println(); + pw.increaseIndent(); + mServiceLogs.reverseDump(pw); + pw.decreaseIndent(); + + // Dump advertiser related logs + pw.println(); + pw.println("Advertiser:"); + pw.increaseIndent(); + mAdvertiser.dump(pw); + pw.decreaseIndent(); + + // Dump discoverymanager related logs + pw.println(); + pw.println("DiscoveryManager:"); + pw.increaseIndent(); + mMdnsDiscoveryManager.dump(pw); + pw.decreaseIndent(); + + // Dump socketprovider related logs + pw.println(); + pw.println("SocketProvider:"); + pw.increaseIndent(); + mMdnsSocketProvider.dump(pw); + pw.decreaseIndent(); } private abstract static class ClientRequest { @@ -1819,11 +1864,14 @@ public class NsdService extends INsdManager.Stub { private boolean mIsPreSClient = false; // The flag of using java backend if the client's target SDK >= U private final boolean mUseJavaBackend; + // Store client logs + private final SharedLog mClientLogs; - private ClientInfo(INsdManagerCallback cb, boolean useJavaBackend) { + private ClientInfo(INsdManagerCallback cb, boolean useJavaBackend, SharedLog sharedLog) { mCb = cb; mUseJavaBackend = useJavaBackend; - if (DBG) Log.d(TAG, "New client"); + mClientLogs = sharedLog; + mClientLogs.log("New client. useJavaBackend=" + useJavaBackend); } @Override @@ -1861,6 +1909,7 @@ public class NsdService extends INsdManager.Stub { // Remove any pending requests from the global map when we get rid of a client, // and send cancellations to the daemon. private void expungeAllRequests() { + mClientLogs.log("Client unregistered. expungeAllRequests!"); // TODO: to keep handler responsive, do not clean all requests for that client at once. for (int i = 0; i < mClientRequests.size(); i++) { final int clientId = mClientRequests.keyAt(i); @@ -1915,6 +1964,10 @@ public class NsdService extends INsdManager.Stub { return -1; } + private void log(String message) { + mClientLogs.log(message); + } + void onDiscoverServicesStarted(int listenerKey, NsdServiceInfo info) { try { mCb.onDiscoverServicesStarted(listenerKey, info);