Improve logging for visual voicemail.

Improved the logging in telephony VVM code.

Test: Manual testing of new log statements.
Flag: EXEMPT bugfix
Bug: 354090891
Change-Id: Ie05a830a7e137352761a1da93590976faae830e0
diff --git a/src/com/android/phone/vvm/CarrierVvmPackageInstalledReceiver.java b/src/com/android/phone/vvm/CarrierVvmPackageInstalledReceiver.java
index ec0d3f6..7ade1ab 100644
--- a/src/com/android/phone/vvm/CarrierVvmPackageInstalledReceiver.java
+++ b/src/com/android/phone/vvm/CarrierVvmPackageInstalledReceiver.java
@@ -80,24 +80,29 @@
                     .createForPhoneAccountHandle(phoneAccountHandle);
 
             if (pinnedTelephonyManager == null) {
-                VvmLog.e(TAG, "cannot create TelephonyManager from " + phoneAccountHandle);
+                VvmLog.e(TAG, "carrierVvmPkgAdded: cannot create TelephonyManager from "
+                        + phoneAccountHandle);
                 continue;
             }
 
             if (!getCarrierVvmPackages(telephonyManager).contains(packageName)) {
+                VvmLog.w(TAG, "carrierVvmPkgAdded: carrier vvm packages doesn't contain "
+                        + packageName);
                 continue;
             }
 
-            VvmLog.i(TAG, "Carrier VVM app " + packageName + " installed");
+            VvmLog.i(TAG, "carrierVvmPkgAdded: Carrier VVM app " + packageName + " installed");
 
             String vvmPackage = pinnedTelephonyManager.getVisualVoicemailPackageName();
             if (!TextUtils.equals(vvmPackage, systemDialer)) {
                 // Non system dialer do not need to prioritize carrier vvm app.
-                VvmLog.i(TAG, "non system dialer " + vvmPackage + " ignored");
+                VvmLog.i(TAG, "carrierVvmPkgAdded: non system dialer "
+                        + vvmPackage + " ignored");
                 continue;
             }
 
-            VvmLog.i(TAG, "sending broadcast to " + vvmPackage);
+            VvmLog.i(TAG, "carrierVvmPkgAdded: sending vvm package installed broadcast to "
+                    + vvmPackage);
             Intent broadcast = new Intent(ACTION_CARRIER_VVM_PACKAGE_INSTALLED);
             broadcast.putExtra(Intent.EXTRA_PACKAGE_NAME, packageName);
             broadcast.setPackage(vvmPackage);
diff --git a/src/com/android/phone/vvm/RemoteVvmTaskManager.java b/src/com/android/phone/vvm/RemoteVvmTaskManager.java
index daa5d67b..b7c3406 100644
--- a/src/com/android/phone/vvm/RemoteVvmTaskManager.java
+++ b/src/com/android/phone/vvm/RemoteVvmTaskManager.java
@@ -170,22 +170,23 @@
             }
             if (info.serviceInfo == null) {
                 VvmLog.w(TAG,
-                        "Component " + TelephonyUtils.getComponentInfo(info)
+                        "getRemotePackage: Component " + TelephonyUtils.getComponentInfo(info)
                             + " is not a service, ignoring");
                 continue;
             }
             if (!android.Manifest.permission.BIND_VISUAL_VOICEMAIL_SERVICE
                     .equals(info.serviceInfo.permission)) {
-                VvmLog.w(TAG, "package " + info.serviceInfo.packageName
+                VvmLog.w(TAG, "getRemotePackage: package " + info.serviceInfo.packageName
                         + " does not enforce BIND_VISUAL_VOICEMAIL_SERVICE, ignoring");
                 continue;
             }
             if (targetPackage != null && !TextUtils.equals(packageName, targetPackage)) {
-                VvmLog.w(TAG, "target package " + targetPackage
+                VvmLog.w(TAG, "getRemotePackage: target package " + targetPackage
                         + " is no longer the active VisualVoicemailService, ignoring");
                 continue;
             }
             ComponentInfo componentInfo = TelephonyUtils.getComponentInfo(info);
+            VvmLog.i(TAG, "getRemotePackage: found package " + targetPackage);
             return new ComponentName(componentInfo.packageName, componentInfo.name);
 
         }
@@ -206,6 +207,7 @@
             return null;
         }
         ComponentInfo componentInfo = TelephonyUtils.getComponentInfo(info.get(0));
+        VvmLog.i(TAG, "getBroadcastPackage: found package " + componentInfo.packageName);
         return new ComponentName(componentInfo.packageName, componentInfo.name);
     }
 
@@ -234,7 +236,7 @@
         mTaskReferenceCount++;
 
         if (intent == null) {
-            VvmLog.i(TAG, "received intent is null");
+            VvmLog.i(TAG, "onStartCommand: received intent is null");
             checkReference();
             return START_NOT_STICKY;
         }
@@ -245,7 +247,8 @@
         ComponentName remotePackage = getRemotePackage(this, subId,
                 intent.getStringExtra(EXTRA_TARGET_PACKAGE));
         if (remotePackage == null) {
-            VvmLog.i(TAG, "No service to handle " + intent.getAction() + ", ignoring");
+            VvmLog.i(TAG, "onStartCommand: No service to handle "
+                    + intent.getAction() + ", ignoring");
             checkReference();
             return START_NOT_STICKY;
         }
@@ -309,6 +312,7 @@
 
         public void onServiceConnected(ComponentName className,
                 IBinder service) {
+            VvmLog.i(TAG, "onServiceConnected: " + className);
             mRemoteMessenger = new Messenger(service);
             mConnected = true;
             runQueue();
@@ -318,7 +322,8 @@
             mConnection = null;
             mConnected = false;
             mRemoteMessenger = null;
-            VvmLog.e(TAG, "Service disconnected, " + mTaskReferenceCount + " tasks dropped.");
+            VvmLog.e(TAG, "onServiceDisconnected: remoteService disconnected, "
+                    + mTaskReferenceCount + " tasks dropped.");
             mTaskReferenceCount = 0;
             checkReference();
         }
@@ -333,7 +338,7 @@
                 try {
                     mRemoteMessenger.send(message);
                 } catch (RemoteException e) {
-                    VvmLog.e(TAG, "Error sending message to remote service", e);
+                    VvmLog.e(TAG, "runQueue: Error sending message to remote service", e);
                 }
                 message = mTaskQueue.poll();
             }
@@ -351,7 +356,7 @@
              * a different repository so it can not be updated in sync with android SDK. It is also
              * hard to make a manifest service to work in the intermittent state.
              */
-            VvmLog.i(TAG, "sending broadcast " + what + " to " + remotePackage);
+            VvmLog.i(TAG, "send: sending broadcast " + what + " to " + remotePackage);
             Intent intent = new Intent(ACTION_VISUAL_VOICEMAIL_SERVICE_EVENT);
             intent.putExtras(extras);
             intent.putExtra(EXTRA_WHAT, what);
@@ -371,7 +376,7 @@
         if (!mConnection.isConnected()) {
             Intent intent = newBindIntent(this);
             intent.setComponent(remotePackage);
-            VvmLog.i(TAG, "Binding to " + intent.getComponent());
+            VvmLog.i(TAG, "send: Binding to " + intent.getComponent());
             bindServiceAsUser(intent, mConnection, Context.BIND_AUTO_CREATE, userHandle);
         }
     }
diff --git a/src/com/android/phone/vvm/VvmSimStateTracker.java b/src/com/android/phone/vvm/VvmSimStateTracker.java
index ab8329c..0362d02 100644
--- a/src/com/android/phone/vvm/VvmSimStateTracker.java
+++ b/src/com/android/phone/vvm/VvmSimStateTracker.java
@@ -116,12 +116,13 @@
 
         final String action = intent.getAction();
         if (action == null) {
-            VvmLog.w(TAG, "Null action for intent.");
+            VvmLog.w(TAG, "onReceive: Null action for intent.");
             return;
         }
         VvmLog.i(TAG, action);
         switch (action) {
             case Intent.ACTION_BOOT_COMPLETED:
+                VvmLog.i(TAG, "onReceive: ACTION_BOOT_COMPLETED");
                 onBootCompleted(context);
                 break;
             case TelephonyIntents.ACTION_SIM_STATE_CHANGED:
@@ -131,6 +132,7 @@
                     // which SIM is removed.
                     // ACTION_SIM_STATE_CHANGED only provides subId which cannot be converted to a
                     // PhoneAccountHandle when the SIM is absent.
+                    VvmLog.i(TAG, "onReceive: ACTION_SIM_STATE_CHANGED");
                     checkRemovedSim(context);
                 }
                 break;
@@ -139,7 +141,7 @@
                         SubscriptionManager.INVALID_SUBSCRIPTION_ID);
 
                 if (!SubscriptionManager.isValidSubscriptionId(subId)) {
-                    VvmLog.i(TAG, "Received SIM change for invalid subscription id.");
+                    VvmLog.i(TAG, "onReceive: Received carrier config for invalid sub id.");
                     checkRemovedSim(context);
                     return;
                 }
@@ -149,10 +151,11 @@
 
                 if ("null".equals(phoneAccountHandle.getId())) {
                     VvmLog.e(TAG,
-                            "null phone account handle ID, possible modem crash."
+                            "onReceive: null phone account handle ID, possible modem crash."
                                     + " Ignoring carrier config changed event");
                     return;
                 }
+                VvmLog.i(TAG, "onReceive: ACTION_CARRIER_CONFIG_CHANGED; subId=" + subId);
                 onCarrierConfigChanged(context, phoneAccountHandle);
         }
     }
@@ -174,7 +177,7 @@
     }
 
     private void sendConnected(Context context, PhoneAccountHandle phoneAccountHandle) {
-        VvmLog.i(TAG, "Service connected on " + phoneAccountHandle);
+        VvmLog.i(TAG, "sendConnected: Service connected on " + phoneAccountHandle);
         RemoteVvmTaskManager.startCellServiceConnected(context, phoneAccountHandle);
     }
 
@@ -210,7 +213,7 @@
     }
 
     private void sendSimRemoved(Context context, PhoneAccountHandle phoneAccountHandle) {
-        VvmLog.i(TAG, "Sim removed on " + phoneAccountHandle);
+        VvmLog.i(TAG, "sendSimRemoved: Sim removed on " + phoneAccountHandle);
         RemoteVvmTaskManager.startSimRemoved(context, phoneAccountHandle);
     }
 
@@ -233,6 +236,8 @@
         }
         if (telephonyManager.getServiceState().getState()
                 == ServiceState.STATE_IN_SERVICE) {
+            VvmLog.i(TAG, "onCarrierConfigChanged: in service; send connected "
+                    + phoneAccountHandle);
             sendConnected(context, phoneAccountHandle);
             sListeners.put(phoneAccountHandle, null);
         } else {
@@ -243,6 +248,7 @@
     private void listenToAccount(Context context, PhoneAccountHandle phoneAccountHandle) {
         ServiceStateListener listener = new ServiceStateListener(context, phoneAccountHandle);
         listener.listen();
+        VvmLog.i(TAG, "listenToAccount: " + phoneAccountHandle);
         sListeners.put(phoneAccountHandle, listener);
     }
 
diff --git a/src/com/android/phone/vvm/VvmSmsReceiver.java b/src/com/android/phone/vvm/VvmSmsReceiver.java
index 8265e50..d4fa751 100644
--- a/src/com/android/phone/vvm/VvmSmsReceiver.java
+++ b/src/com/android/phone/vvm/VvmSmsReceiver.java
@@ -38,22 +38,22 @@
                 .getParcelable(VoicemailContract.EXTRA_VOICEMAIL_SMS);
         if (sms.getPhoneAccountHandle() == null) {
             // This should never happen
-            VvmLog.e(TAG, "Received message for null phone account");
+            VvmLog.e(TAG, "onReceive: Received message for null phone account");
             return;
         }
 
         int subId = PhoneAccountHandleConverter.toSubId(sms.getPhoneAccountHandle());
         if (!SubscriptionManager.isValidSubscriptionId(subId)) {
-            VvmLog.e(TAG, "Received message for invalid subId");
+            VvmLog.e(TAG, "onReceive: Received message for invalid subId");
             return;
         }
 
         String targetPackage = intent.getExtras().getString(VoicemailContract.EXTRA_TARGET_PACKAGE);
         if (RemoteVvmTaskManager.hasRemoteService(context, subId, targetPackage)) {
-            VvmLog.i(TAG, "Sending SMS received event to remote service");
+            VvmLog.i(TAG, "onReceive: Sending SMS received event to remote service");
             RemoteVvmTaskManager.startSmsReceived(context, sms, targetPackage);
         } else {
-            VvmLog.w(TAG, "No remote service to handle SMS received event");
+            VvmLog.w(TAG, "onReceive: No remote service to handle SMS received event");
         }
     }
 }