AVRCP: increase log info density

AVRCP has a lot of log messages that have little to no info.
Particularly with carkits that poll for data all the time, this makes it hard
to debug anything.

Remove logs where there's no info, add info where it's available with the goal
of making every log message useful.

Remove variables that we don't use anymore.

Print Now Playing Queue data on the dumpsys and when we report it
back to the controller.

Test: connect to a carkit and grab a bugreport
Bug: 37707672
Bug: 36802046
Bug: 38264897
Change-Id: I4fcb5a1c625c2d212685b4df04a0ac42df3d7841
(cherry picked from commit e5384f02ec837a8f274ed59548cb6879849239f5)

diff --git a/jni/com_android_bluetooth_avrcp.cpp b/jni/com_android_bluetooth_avrcp.cpp
index 26af2ed..2a13ea7 100644 (file)
--- a/jni/com_android_bluetooth_avrcp.cpp
+++ b/jni/com_android_bluetooth_avrcp.cpp
@@ -59,7 +59,6 @@ static void cleanup_items(btrc_folder_items_t* p_items, int numItems);
 
 static void btavrcp_remote_features_callback(bt_bdaddr_t* bd_addr,
                                              btrc_remote_features_t features) {
-  ALOGI("%s", __func__);
   CallbackEnv sCallbackEnv(__func__);
   if (!sCallbackEnv.valid()) return;
 
@@ -83,7 +82,6 @@ static void btavrcp_remote_features_callback(bt_bdaddr_t* bd_addr,
 
 /** Callback for play status request */
 static void btavrcp_get_play_status_callback(bt_bdaddr_t* bd_addr) {
-  ALOGI("%s", __func__);
   CallbackEnv sCallbackEnv(__func__);
   if (!sCallbackEnv.valid()) return;
 
@@ -107,7 +105,6 @@ static void btavrcp_get_play_status_callback(bt_bdaddr_t* bd_addr) {
 static void btavrcp_get_element_attr_callback(uint8_t num_attr,
                                               btrc_media_attr_t* p_attrs,
                                               bt_bdaddr_t* bd_addr) {
-  ALOGI("%s", __func__);
   CallbackEnv sCallbackEnv(__func__);
   if (!sCallbackEnv.valid()) return;
 
@@ -164,7 +161,6 @@ static void btavrcp_register_notification_callback(btrc_event_id_t event_id,
 
 static void btavrcp_volume_change_callback(uint8_t volume, uint8_t ctype,
                                            bt_bdaddr_t* bd_addr) {
-  ALOGI("%s", __func__);
   CallbackEnv sCallbackEnv(__func__);
   if (!sCallbackEnv.valid()) return;
 
@@ -189,7 +185,6 @@ static void btavrcp_volume_change_callback(uint8_t volume, uint8_t ctype,
 
 static void btavrcp_passthrough_command_callback(int id, int pressed,
                                                  bt_bdaddr_t* bd_addr) {
-  ALOGI("%s", __func__);
   CallbackEnv sCallbackEnv(__func__);
   if (!sCallbackEnv.valid()) return;
 
@@ -213,7 +208,6 @@ static void btavrcp_passthrough_command_callback(int id, int pressed,
 
 static void btavrcp_set_addressed_player_callback(uint16_t player_id,
                                                   bt_bdaddr_t* bd_addr) {
-  ALOGI("%s", __func__);
   CallbackEnv sCallbackEnv(__func__);
   if (!sCallbackEnv.valid()) return;
 
@@ -237,7 +231,6 @@ static void btavrcp_set_addressed_player_callback(uint16_t player_id,
 
 static void btavrcp_set_browsed_player_callback(uint16_t player_id,
                                                 bt_bdaddr_t* bd_addr) {
-  ALOGI("%s", __func__);
   CallbackEnv sCallbackEnv(__func__);
   if (!sCallbackEnv.valid()) return;
   if (!mCallbacksObj) {
@@ -261,7 +254,6 @@ static void btavrcp_set_browsed_player_callback(uint16_t player_id,
 static void btavrcp_get_folder_items_callback(
     uint8_t scope, uint32_t start_item, uint32_t end_item, uint8_t num_attr,
     uint32_t* p_attr_ids, bt_bdaddr_t* bd_addr) {
-  ALOGI("%s", __func__);
   CallbackEnv sCallbackEnv(__func__);
   if (!sCallbackEnv.valid()) return;
 
@@ -302,7 +294,6 @@ static void btavrcp_get_folder_items_callback(
 
 static void btavrcp_change_path_callback(uint8_t direction, uint8_t* folder_uid,
                                          bt_bdaddr_t* bd_addr) {
-  ALOGI("%s", __func__);
   CallbackEnv sCallbackEnv(__func__);
   if (!sCallbackEnv.valid()) return;
 
@@ -338,7 +329,6 @@ static void btavrcp_get_item_attr_callback(uint8_t scope, uint8_t* uid,
                                            uint8_t num_attr,
                                            btrc_media_attr_t* p_attrs,
                                            bt_bdaddr_t* bd_addr) {
-  ALOGI("%s", __func__);
   CallbackEnv sCallbackEnv(__func__);
   if (!sCallbackEnv.valid()) return;
 
@@ -391,7 +381,7 @@ static void btavrcp_play_item_callback(uint8_t scope, uint16_t uid_counter,
   ScopedLocalRef<jbyteArray> attrs(sCallbackEnv.get(),
                                    sCallbackEnv->NewByteArray(BTRC_UID_SIZE));
   if (!attrs.get()) {
-    ALOGE("%s:Fail to new jByteArray attrs for play_item command", __func__);
+    ALOGE("%s: Fail to new jByteArray attrs for play_item command", __func__);
     return;
   }
 

diff --git a/src/com/android/bluetooth/avrcp/AddressedMediaPlayer.java b/src/com/android/bluetooth/avrcp/AddressedMediaPlayer.java
index 2dfb778..ee305b6 100644 (file)
--- a/src/com/android/bluetooth/avrcp/AddressedMediaPlayer.java
+++ b/src/com/android/bluetooth/avrcp/AddressedMediaPlayer.java
@@ -27,6 +27,7 @@ import android.media.MediaMetadata;
 import android.os.Bundle;
 import android.util.Log;
 
+import com.android.bluetooth.btservice.ProfileService;
 import com.android.bluetooth.Utils;
 
 import java.nio.ByteBuffer;
@@ -260,14 +261,8 @@ public class AddressedMediaPlayer {
     boolean sendTrackChangeWithId(boolean requesting, @Nullable MediaController mediaController) {
         if (DEBUG)
             Log.d(TAG, "sendTrackChangeWithId (" + requesting + "): controller " + mediaController);
-        byte[] track;
-        long qid = MediaSession.QueueItem.UNKNOWN_ID;
-        if (mediaController != null) {
-            PlaybackState state = mediaController.getPlaybackState();
-            /* for any item associated with NowPlaying, uid is queueId */
-            if (state != null) qid = state.getActiveQueueItemId();
-        }
-        track = ByteBuffer.allocate(AvrcpConstants.UID_SIZE).putLong(qid).array();
+        long qid = getActiveQueueItemId(mediaController);
+        byte[] track = ByteBuffer.allocate(AvrcpConstants.UID_SIZE).putLong(qid).array();
         if (DEBUG) Log.d(TAG, "trackChangedRsp: 0x" + Utils.byteArrayToString(track));
         int trackChangedNT = AvrcpConstants.NOTIFICATION_TYPE_CHANGED;
         if (requesting) trackChangedNT = AvrcpConstants.NOTIFICATION_TYPE_INTERIM;
@@ -413,12 +408,9 @@ public class AddressedMediaPlayer {
         try {
             MediaDescription desc = item.getDescription();
             Bundle extras = desc.getExtras();
-            if (mediaController != null) {
-                PlaybackState state = mediaController.getPlaybackState();
-                if (state != null && (item.getQueueId() == state.getActiveQueueItemId())) {
-                    if (DEBUG) Log.d(TAG, "getAttrValue: item is active, filling extra data");
-                    extras = fillBundle(mediaController.getMetadata(), extras);
-                }
+            if (item.getQueueId() == getActiveQueueItemId(mediaController)) {
+                if (DEBUG) Log.d(TAG, "getAttrValue: item is active, filling extra data");
+                extras = fillBundle(mediaController.getMetadata(), extras);
             }
             if (DEBUG) Log.d(TAG, "getAttrValue: item " + item + " : " + desc);
             switch (attr) {
@@ -530,4 +522,24 @@ public class AddressedMediaPlayer {
             return;
         }
     }
+
+    private long getActiveQueueItemId(@Nullable MediaController controller) {
+        if (controller == null) return MediaSession.QueueItem.UNKNOWN_ID;
+        PlaybackState state = controller.getPlaybackState();
+        if (state == null) return MediaSession.QueueItem.UNKNOWN_ID;
+        return state.getActiveQueueItemId();
+    }
+
+    public void dump(StringBuilder sb, @Nullable MediaController mediaController) {
+        ProfileService.println(sb, "AddressedPlayer info:");
+        ProfileService.println(sb, "mLastTrackIdSent: " + mLastTrackIdSent);
+        ProfileService.println(sb, "mNowPlayingList: " + mNowPlayingList);
+        List<MediaSession.QueueItem> queue = getNowPlayingList(mediaController);
+        ProfileService.println(sb, "Current Queue: " + queue.size() + " elements");
+        long currentQueueId = getActiveQueueItemId(mediaController);
+        for (MediaSession.QueueItem item : queue) {
+            long itemId = item.getQueueId();
+            ProfileService.println(sb, (itemId == currentQueueId ? "*" : " ") + item.toString());
+        }
+    }
 }

diff --git a/src/com/android/bluetooth/avrcp/Avrcp.java b/src/com/android/bluetooth/avrcp/Avrcp.java
index df529b2..6f26280 100644 (file)
--- a/src/com/android/bluetooth/avrcp/Avrcp.java
+++ b/src/com/android/bluetooth/avrcp/Avrcp.java
@@ -91,7 +91,6 @@ public final class Avrcp {
     private long mLastReportedPosition;
     private long mNextPosMs;
     private long mPrevPosMs;
-    private long mSkipStartTime;
     private int mFeatures;
     private int mRemoteVolume;
     private int mLastRemoteVolume;
@@ -112,7 +111,6 @@ public final class Avrcp {
     private boolean mVolCmdAdjustInProgress;
     private boolean mVolCmdSetInProgress;
     private int mAbsVolRetryTimes;
-    private int mSkipAmount;
 
     private static final int NO_PLAYER_ID = 0;
 
@@ -427,9 +425,13 @@ public final class Avrcp {
             case MSG_NATIVE_REQ_GET_PLAY_STATUS:
             {
                 byte[] address = (byte[]) msg.obj;
-                if (DEBUG) Log.v(TAG, "MSG_NATIVE_REQ_GET_PLAY_STATUS");
-                getPlayStatusRspNative(address, convertPlayStateToPlayStatus(mCurrentPlayState),
-                        (int) mMediaAttributes.getLength(), (int) getPlayPosition());
+                int btstate = convertPlayStateToPlayStatus(mCurrentPlayState);
+                int length = (int) mMediaAttributes.getLength();
+                int position = (int) getPlayPosition();
+                if (DEBUG)
+                    Log.v(TAG, "MSG_NATIVE_REQ_GET_PLAY_STATUS, responding with state " + btstate
+                                    + " len " + length + " pos " + position);
+                getPlayStatusRspNative(address, btstate, length, position);
                 break;
             }
 
@@ -441,11 +443,13 @@ public final class Avrcp {
                 int[] attrIds = elem.mAttrIDs;
                 if (DEBUG) Log.v(TAG, "MSG_NATIVE_REQ_GET_ELEM_ATTRS:numAttr=" + numAttr);
                 textArray = new String[numAttr];
+                StringBuilder responseDebug = new StringBuilder();
+                responseDebug.append("getElementAttr response: ");
                 for (int i = 0; i < numAttr; ++i) {
                     textArray[i] = mMediaAttributes.getString(attrIds[i]);
-                    Log.v(TAG, "getAttributeString:attrId=" + attrIds[i] +
-                            " str=" + textArray[i]);
+                    responseDebug.append("[" + attrIds[i] + "=" + textArray[i] + "] ");
                 }
+                Log.v(TAG, responseDebug.toString());
                 byte[] bdaddr = elem.mAddress;
                 getElementAttrRspNative(bdaddr, numAttr, attrIds, textArray);
                 break;
@@ -472,13 +476,13 @@ public final class Avrcp {
                 break;
 
             case MSG_ADDRESSED_PLAYER_CHANGED_RSP:
-                if (DEBUG)
-                    Log.v(TAG, "MSG_ADDRESSED_PLAYER_CHANGED_RSP: newAddrPlayer = " + msg.arg1);
                 // Later addressed players override earlier ones.
                 if (hasMessages(MSG_ADDRESSED_PLAYER_CHANGED_RSP)) {
                     Log.i(TAG, "MSG_ADDRESSED_PLAYER_CHANGED_RSP: skip, more changes in queue");
                     break;
                 }
+                if (DEBUG)
+                    Log.v(TAG, "MSG_ADDRESSED_PLAYER_CHANGED_RSP: newAddrPlayer = " + msg.arg1);
                 registerNotificationRspAddrPlayerChangedNative(
                         AvrcpConstants.NOTIFICATION_TYPE_CHANGED, msg.arg1, sUIDCounter);
                 break;
@@ -490,12 +494,13 @@ public final class Avrcp {
 
             case MSG_NATIVE_REQ_VOLUME_CHANGE:
                 if (!isAbsoluteVolumeSupported()) {
-                    if (DEBUG) Log.v(TAG, "ignore MSG_NATIVE_REQ_VOLUME_CHANGE");
+                    if (DEBUG) Log.v(TAG, "MSG_NATIVE_REQ_VOLUME_CHANGE ignored, not supported");
                     break;
                 }
-
-                if (DEBUG) Log.v(TAG, "MSG_NATIVE_REQ_VOLUME_CHANGE: volume=" + ((byte) msg.arg1 & 0x7f)
-                        + " ctype=" + msg.arg2);
+                byte absVol = (byte) ((byte) msg.arg1 & 0x7f); // discard MSB as it is RFD
+                if (DEBUG)
+                    Log.v(TAG, "MSG_NATIVE_REQ_VOLUME_CHANGE: volume=" + absVol + " ctype="
+                                    + msg.arg2);
 
                 boolean volAdj = false;
                 if (msg.arg2 == AVRC_RSP_ACCEPT || msg.arg2 == AVRC_RSP_REJ) {
@@ -511,7 +516,6 @@ public final class Avrcp {
                     mAbsVolRetryTimes = 0;
                 }
 
-                byte absVol = (byte) ((byte) msg.arg1 & 0x7f); // discard MSB as it is RFD
                 // convert remote volume to local volume
                 int volIndex = convertToAudioStreamVolume(absVol);
                 if (mInitialRemoteVolume == -1) {
@@ -980,21 +984,18 @@ public final class Avrcp {
     }
 
     private void getRcFeaturesRequestFromNative(byte[] address, int features) {
-        if (DEBUG) Log.v(TAG, "getRcFeaturesRequestFromNative: address=" + address.toString());
         Message msg = mHandler.obtainMessage(MSG_NATIVE_REQ_GET_RC_FEATURES, features, 0,
                 Utils.getAddressStringFromByte(address));
         mHandler.sendMessage(msg);
     }
 
     private void getPlayStatusRequestFromNative(byte[] address) {
-        if (DEBUG) Log.v(TAG, "getPlayStatusRequestFromNative: address" + address.toString());
         Message msg = mHandler.obtainMessage(MSG_NATIVE_REQ_GET_PLAY_STATUS);
         msg.obj = address;
         mHandler.sendMessage(msg);
     }
 
     private void getElementAttrRequestFromNative(byte[] address, byte numAttr, int[] attrs) {
-        if (DEBUG) Log.v(TAG, "getElementAttrRequestFromNative: numAttr=" + numAttr);
         AvrcpCmd avrcpCmdobj = new AvrcpCmd();
         AvrcpCmd.ElementAttrCmd elemAttr = avrcpCmdobj.new ElementAttrCmd(address, numAttr, attrs);
         Message msg = mHandler.obtainMessage(MSG_NATIVE_REQ_GET_ELEM_ATTRS);
@@ -1003,7 +1004,6 @@ public final class Avrcp {
     }
 
     private void registerNotificationRequestFromNative(byte[] address,int eventId, int param) {
-        if (DEBUG) Log.v(TAG, "registerNotificationRequestFromNative: eventId=" + eventId);
         Message msg = mHandler.obtainMessage(MSG_NATIVE_REQ_REGISTER_NOTIFICATION, eventId, param);
         msg.obj = address;
         mHandler.sendMessage(msg);
@@ -1242,7 +1242,6 @@ public final class Avrcp {
 
     private void getFolderItemsRequestFromNative(
             byte[] address, byte scope, long startItem, long endItem, byte numAttr, int[] attrIds) {
-        if (DEBUG) Log.v(TAG, "getFolderItemsRequestFromNative: scope=" + scope + ", numAttr=" + numAttr);
         AvrcpCmd avrcpCmdobj = new AvrcpCmd();
         AvrcpCmd.FolderItemsCmd folderObj = avrcpCmdobj.new FolderItemsCmd(address, scope,
                 startItem, endItem, numAttr, attrIds);
@@ -1252,21 +1251,18 @@ public final class Avrcp {
     }
 
     private void setAddressedPlayerRequestFromNative(byte[] address, int playerId) {
-        if (DEBUG) Log.v(TAG, "setAddrPlayerRequestFromNative: playerId=" + playerId);
         Message msg = mHandler.obtainMessage(MSG_NATIVE_REQ_SET_ADDR_PLAYER, playerId, 0);
         msg.obj = address;
         mHandler.sendMessage(msg);
     }
 
     private void setBrowsedPlayerRequestFromNative(byte[] address, int playerId) {
-        if (DEBUG) Log.v(TAG, "setBrPlayerRequestFromNative: playerId=" + playerId);
         Message msg = mHandler.obtainMessage(MSG_NATIVE_REQ_SET_BR_PLAYER, playerId, 0);
         msg.obj = address;
         mHandler.sendMessage(msg);
     }
 
     private void changePathRequestFromNative(byte[] address, byte direction, byte[] folderUid) {
-        if (DEBUG) Log.v(TAG, "changePathRequestFromNative: direction=" + direction);
         Bundle data = new Bundle();
         Message msg = mHandler.obtainMessage(MSG_NATIVE_REQ_CHANGE_PATH);
         data.putByteArray("BdAddress" , address);
@@ -1278,7 +1274,6 @@ public final class Avrcp {
 
     private void getItemAttrRequestFromNative(byte[] address, byte scope, byte[] itemUid, int uidCounter,
             byte numAttr, int[] attrs) {
-        if (DEBUG) Log.v(TAG, "getItemAttrRequestFromNative: scope=" + scope + ", numAttr=" + numAttr);
         AvrcpCmd avrcpCmdobj = new AvrcpCmd();
         AvrcpCmd.ItemAttrCmd itemAttr = avrcpCmdobj.new ItemAttrCmd(address, scope,
                 itemUid, uidCounter, numAttr, attrs);
@@ -1288,14 +1283,12 @@ public final class Avrcp {
     }
 
     private void searchRequestFromNative(byte[] address, int charsetId, byte[] searchStr) {
-        if (DEBUG) Log.v(TAG, "searchRequestFromNative");
         /* Search is not supported */
-        if (DEBUG) Log.d(TAG, "search is not supported");
+        Log.w(TAG, "searchRequestFromNative: search is not supported");
         searchRspNative(address, AvrcpConstants.RSP_SRCH_NOT_SPRTD, 0, 0);
     }
 
     private void playItemRequestFromNative(byte[] address, byte scope, int uidCounter, byte[] uid) {
-        if (DEBUG) Log.v(TAG, "playItemRequestFromNative: scope=" + scope);
         Bundle data = new Bundle();
         Message msg = mHandler.obtainMessage(MSG_NATIVE_REQ_PLAY_ITEM);
         data.putByteArray("BdAddress" , address);
@@ -1307,14 +1300,12 @@ public final class Avrcp {
     }
 
     private void addToPlayListRequestFromNative(byte[] address, byte scope, byte[] uid, int uidCounter) {
-        if (DEBUG) Log.v(TAG, "addToPlayListRequestFromNative: scope=" + scope);
         /* add to NowPlaying not supported */
-        Log.w(TAG, "Add to NowPlayingList is not supported");
+        Log.w(TAG, "addToPlayListRequestFromNative: not supported! scope=" + scope);
         addToNowPlayingRspNative(address, AvrcpConstants.RSP_INTERNAL_ERR);
     }
 
     private void getTotalNumOfItemsRequestFromNative(byte[] address, byte scope) {
-        if (DEBUG) Log.v(TAG, "getTotalNumOfItemsRequestFromNative: scope=" + scope);
         Bundle data = new Bundle();
         Message msg = mHandler.obtainMessage(MSG_NATIVE_REQ_GET_TOTAL_NUM_OF_ITEMS);
         msg.arg1 = scope;
@@ -2298,7 +2289,6 @@ public final class Avrcp {
         ProfileService.println(sb, "mPlayPosChangedNT: " + mPlayPosChangedNT);
         ProfileService.println(sb, "mNextPosMs: " + mNextPosMs);
         ProfileService.println(sb, "mPrevPosMs: " + mPrevPosMs);
-        ProfileService.println(sb, "mSkipStartTime: " + mSkipStartTime);
         ProfileService.println(sb, "mFeatures: " + mFeatures);
         ProfileService.println(sb, "mRemoteVolume: " + mRemoteVolume);
         ProfileService.println(sb, "mLastRemoteVolume: " + mLastRemoteVolume);
@@ -2308,7 +2298,6 @@ public final class Avrcp {
         ProfileService.println(sb, "mVolCmdAdjustInProgress: " + mVolCmdAdjustInProgress);
         ProfileService.println(sb, "mVolCmdSetInProgress: " + mVolCmdSetInProgress);
         ProfileService.println(sb, "mAbsVolRetryTimes: " + mAbsVolRetryTimes);
-        ProfileService.println(sb, "mSkipAmount: " + mSkipAmount);
         ProfileService.println(sb, "mVolumeMapping: " + mVolumeMapping.toString());
         if (mMediaController != null)
             ProfileService.println(sb, "mMediaController: " + mMediaController.getWrappedInstance()
@@ -2324,6 +2313,10 @@ public final class Avrcp {
             }
         }
 
+        ProfileService.println(sb, "");
+        mAddressedMediaPlayer.dump(sb, mMediaController);
+
+        ProfileService.println(sb, "");
         ProfileService.println(sb, mPassthroughDispatched + " passthrough operations: ");
         if (mPassthroughDispatched > mPassthroughLogs.size())
             ProfileService.println(sb, "  (last " + mPassthroughLogs.size() + ")");