Merge "AVRCP: increase log info density"
diff --git a/jni/com_android_bluetooth_avrcp.cpp b/jni/com_android_bluetooth_avrcp.cpp
index 26af2ed..2a13ea7 100644
--- a/jni/com_android_bluetooth_avrcp.cpp
+++ b/jni/com_android_bluetooth_avrcp.cpp
@@ -59,7 +59,6 @@
 
 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 @@
 
 /** 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_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_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_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_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_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_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_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 @@
                                            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 @@
   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
--- a/src/com/android/bluetooth/avrcp/AddressedMediaPlayer.java
+++ b/src/com/android/bluetooth/avrcp/AddressedMediaPlayer.java
@@ -27,6 +27,7 @@
 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 @@
     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 @@
         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 @@
             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 9508b26..d18fe07 100644
--- a/src/com/android/bluetooth/avrcp/Avrcp.java
+++ b/src/com/android/bluetooth/avrcp/Avrcp.java
@@ -91,7 +91,6 @@
     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 @@
     private boolean mVolCmdAdjustInProgress;
     private boolean mVolCmdSetInProgress;
     private int mAbsVolRetryTimes;
-    private int mSkipAmount;
 
     private static final int NO_PLAYER_ID = 0;
 
@@ -427,9 +425,13 @@
             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 @@
                 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 @@
                 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 @@
 
             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 @@
                     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 @@
     }
 
     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 @@
     }
 
     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 @@
 
     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 @@
     }
 
     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 @@
 
     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 @@
     }
 
     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 @@
     }
 
     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;
@@ -2301,7 +2292,6 @@
         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);
@@ -2311,7 +2301,6 @@
         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()
@@ -2327,6 +2316,10 @@
             }
         }
 
+        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() + ")");