BLE: Logging Improvement in stack.

Module : Gatt Server and Client.

Change-Id: I0eebf9647d68086cccebbf3a56488c145c99a7ee

bta/gatt/bta_gattc_int.h

@@ -40,7 +40,7 @@
  *  Constants and data types
  ****************************************************************************/
 enum {
-  BTA_GATTC_API_OPEN_EVT = BTA_SYS_EVT_START(BTA_ID_GATTC),
+  BTA_GATTC_API_OPEN_EVT = BTA_SYS_EVT_START(BTA_ID_GATTC), // 0x1F00
   BTA_GATTC_INT_OPEN_FAIL_EVT,
   BTA_GATTC_API_CANCEL_OPEN_EVT,
   BTA_GATTC_INT_CANCEL_OPEN_OK_EVT,

bta/gatt/bta_gattc_main.cc

@@ -280,10 +280,8 @@ const tBTA_GATTC_ST_TBL bta_gattc_st_tbl[] = {
 /* GATTC control block */
 tBTA_GATTC_CB bta_gattc_cb;
 
-#if (BTA_GATT_DEBUG == TRUE)
 static const char* gattc_evt_code(tBTA_GATTC_INT_EVT evt_code);
 static const char* gattc_state_code(tBTA_GATTC_STATE state_code);
-#endif
 
 /*******************************************************************************
  *
@@ -304,14 +302,9 @@ bool bta_gattc_sm_execute(tBTA_GATTC_CLCB* p_clcb, uint16_t event,
   bool rt = true;
   tBTA_GATTC_STATE in_state = p_clcb->state;
   uint16_t in_event = event;
-#if (BTA_GATT_DEBUG == TRUE)
   VLOG(1) << StringPrintf("%s: State 0x%02x [%s], Event 0x%x[%s]", __func__,
                           in_state, gattc_state_code(in_state), in_event,
                           gattc_evt_code(in_event));
-#else
-  VLOG(1) << StringPrintf("%s: State 0x%02x, Event 0x%x", __func__, in_state,
-                          in_event);
-#endif
 
   /* look up the state table for the current state */
   state_table = bta_gattc_st_tbl[p_clcb->state];
@@ -365,9 +358,8 @@ bool bta_gattc_sm_execute(tBTA_GATTC_CLCB* p_clcb, uint16_t event,
 bool bta_gattc_hdl_event(BT_HDR* p_msg) {
   tBTA_GATTC_CLCB* p_clcb = NULL;
   bool rt = true;
-#if (BTA_GATT_DEBUG == TRUE)
   VLOG(1) << __func__ << ": Event:" << gattc_evt_code(p_msg->event);
-#endif
+
   switch (p_msg->event) {
 
     case BTA_GATTC_API_OPEN_EVT:
@@ -402,7 +394,6 @@ bool bta_gattc_hdl_event(BT_HDR* p_msg) {
 /*****************************************************************************
  *  Debug Functions
  ****************************************************************************/
-#if (BTA_GATT_DEBUG == TRUE)
 
 /*******************************************************************************
  *
@@ -478,4 +469,3 @@ static const char* gattc_state_code(tBTA_GATTC_STATE state_code) {
   }
 }
 
-#endif /* Debug Functions */

bta/gatt/bta_gatts_int.h

@@ -36,7 +36,7 @@
  *  Constants and data types
  ****************************************************************************/
 enum {
-  BTA_GATTS_API_REG_EVT = BTA_SYS_EVT_START(BTA_ID_GATTS),
+  BTA_GATTS_API_REG_EVT = BTA_SYS_EVT_START(BTA_ID_GATTS), // 0x2000
   BTA_GATTS_INT_START_IF_EVT,
   BTA_GATTS_API_DEREG_EVT,
   BTA_GATTS_API_INDICATION_EVT,

bta/gatt/bta_gatts_main.cc

@@ -44,6 +44,7 @@ tBTA_GATTS_CB bta_gatts_cb;
  ******************************************************************************/
 bool bta_gatts_hdl_event(BT_HDR* p_msg) {
   tBTA_GATTS_CB* p_cb = &bta_gatts_cb;
+  VLOG(1) << __func__ << ": event = " << +p_msg->event;
 
   switch (p_msg->event) {
     case BTA_GATTS_API_DISABLE_EVT:

bta/sys/bta_sys.h

@@ -92,7 +92,7 @@ typedef uint16_t tBTA_SYS_HW_MODULE;
 #define BTA_ID_MCE 29           /* Message Client Equipment */
 #define BTA_ID_HL 30            /* Health Device Profile*/
 #define BTA_ID_GATTC 31         /* GATT Client */
-#define BTA_ID_GATTS 32         /* GATT Client */
+#define BTA_ID_GATTS 32         /* GATT Server */
 #define BTA_ID_SDP 33           /* SDP Client */
 #define BTA_ID_TWS_PLUS 34      /* TWS+ Interface */
 #define BTA_ID_BAT 35           /* Broadcast Audio Transmitter  */

bta/sys/bta_sys_main.cc

@@ -456,11 +456,11 @@ void bta_sys_event(BT_HDR* p_msg) {
   uint8_t id;
   bool freebuf = true;
 
-  APPL_TRACE_EVENT("%s: Event 0x%x", __func__, p_msg->event);
-
   /* get subsystem id from event */
   id = (uint8_t)(p_msg->event >> 8);
 
+  APPL_TRACE_EVENT("%s: Event: 0x%x id: 0x%x", __func__, p_msg->event, id);
+
   /* verify id and call subsystem event handler */
   if ((id < BTA_ID_MAX) && (bta_sys_cb.reg[id] != NULL)) {
     freebuf = (*bta_sys_cb.reg[id]->evt_hdlr)(p_msg);

btif/src/btif_gatt_client.cc

@@ -138,7 +138,7 @@ void btif_gattc_upstreams_evt(uint16_t event, char* p_param) {
     }
 
     case BTA_GATTC_OPEN_EVT: {
-      DVLOG(1) << "BTA_GATTC_OPEN_EVT " << p_data->open.remote_bda;
+      VLOG(1) << "BTA_GATTC_OPEN_EVT " << p_data->open.remote_bda;
       HAL_CBACK(bt_gatt_callbacks, client->open_cb, p_data->open.conn_id,
                 p_data->open.status, p_data->open.client_if,
                 p_data->open.remote_bda);

conf/bt_stack.conf

@@ -34,7 +34,7 @@ TRC_HID_DEV=2
 # See libchrome/base/logging.h for description on how to configure your logs.
 # sample configuration:
 #LoggingV=--v=0
-#LoggingVModule=--vmodule=*/btm/*=1,btm_ble_multi*=2,btif_*=1
+LoggingVModule=--vmodule=*/btm/*=1,btm_ble_multi*=2,*/bta/gatt/*=1,*/stack/gatt/*=1,*/stack/smp/*=1,btif_ble*=1
 
 # PTS testing helpers
 

stack/gatt/gatt_cl.cc

@@ -1084,6 +1084,9 @@ void gatt_client_handle_server_rsp(tGATT_TCB& tcb, uint8_t op_code,
   alarm_cancel(p_clcb->gatt_rsp_timer_ent);
   p_clcb->retry_count = 0;
 
+  VLOG(1) << __func__ << " op_code: " << +op_code << ", len = " << +len
+                      << "rsp_code: " << +rsp_code;
+
   /* the size of the message may not be bigger than the local max PDU size*/
   /* The message has to be smaller than the agreed MTU, len does not count
    * op_code */

stack/gatt/gatt_main.cc

@@ -912,6 +912,9 @@ void gatt_data_process(tGATT_TCB& tcb, BT_HDR* p_buf) {
   uint16_t msg_len = p_buf->len - 1;
   STREAM_TO_UINT8(op_code, p);
 
+  LOG(INFO) << __func__ << " op_code = " << +op_code
+                        << ", msg_len = " << +msg_len;
+
   /* remove the two MSBs associated with sign write and write cmd */
   pseudo_op_code = op_code & (~GATT_WRITE_CMD_MASK);
 

stack/gatt/gatt_sr.cc

@@ -872,6 +872,8 @@ void gatts_process_write_req(tGATT_TCB& tcb, tGATT_SRV_LIST_ELEM& el,
   uint8_t sec_flag, key_size, *p = p_data;
   uint16_t conn_id;
 
+  VLOG(1) << __func__ << " handle: " << +handle << ", len: " << +len;
+
   memset(&sr_data, 0, sizeof(tGATTS_DATA));
 
   switch (op_code) {
@@ -956,6 +958,8 @@ static void gatts_process_read_req(tGATT_TCB& tcb, tGATT_SRV_LIST_ELEM& el,
   size_t buf_len = sizeof(BT_HDR) + tcb.payload_size + L2CAP_MIN_OFFSET;
   uint16_t offset = 0;
 
+  VLOG(1) << __func__ << " handle: " << +handle << ", len: " << +len;
+
   if (op_code == GATT_REQ_READ_BLOB && len < sizeof(uint16_t)) {
     /* Error: packet length is too short */
     LOG(ERROR) << __func__ << ": packet length=" << len
@@ -1183,7 +1187,10 @@ void gatts_process_value_conf(tGATT_TCB& tcb, uint8_t op_code) {
 void gatt_server_handle_client_req(tGATT_TCB& tcb, uint8_t op_code,
                                    uint16_t len, uint8_t* p_data) {
   /* there is pending command, discard this one */
-  if (!gatt_sr_cmd_empty(tcb) && op_code != GATT_HANDLE_VALUE_CONF) return;
+  if (!gatt_sr_cmd_empty(tcb) && op_code != GATT_HANDLE_VALUE_CONF) {
+    LOG(ERROR) << __func__ << "Server Command Queue is not empty. Discard this cmd.";
+    return;
+  }
 
   /* the size of the message may not be bigger than the local max PDU size*/
   /* The message has to be smaller than the agreed MTU, len does not include op