Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit e1c81a13 authored by Łukasz Rymanowski's avatar Łukasz Rymanowski
Browse files

vc: Remove internal operation cancel 

Volume control had an internal operation cancel mechanism which was
intended to unblock the queue with outstanding VC operations.

However, it turns out it does not makes sense, because if operation will
be canceled, new operation will be put on the GATT queue with
old/possibly invalid change counter.

So we tried to recover from remote issue but it will not work.

From now on, internal timer is used just to monitor on how long it takes
to process operation and helps to debug issues.

This patch also adds some stress test added when trying to understand
this issue.

Bug: 328369455
Test: atest bluetooth_vc_test
Flag; Exempt, no functional change.

Change-Id: I8f3e24a0ac28780c3728d73fc8b854412160d402
parent bee744ee

system/bta/vc/vc.cc

+31 −22
Original line number Diff line number Diff line
@@ -803,8 +803,30 @@ class VolumeControlImpl : public VolumeControl { 
    }

  }



  static void operation_callback(void* data) {

    instance->CancelVolumeOperation(PTR_TO_INT(data));

  static void operation_timeout_callback(void* data) {

    if (!instance) {

      log::warn(" There is no instance.");

      return;

    }

    instance->OperationMonitorTimeoutFired(PTR_TO_INT(data));

  }



  void OperationMonitorTimeoutFired(int operation_id) {

    auto op = find_if(

        ongoing_operations_.begin(), ongoing_operations_.end(),

        [operation_id](auto& it) { return it.operation_id_ == operation_id; });



    if (op == ongoing_operations_.end()) {

      log::error("Could not find operation_id: {}", operation_id);

      return;

    }



    log::warn("Operation {} is taking too long for devices:", operation_id);

    for (const auto& addr : op->devices_) {

      log::warn("  {},", ADDRESS_TO_LOGGABLE_CSTR(addr));

    }

    alarm_set_on_mloop(op->operation_timeout_, kOperationMonitorTimeoutMs,

                       operation_timeout_callback, INT_TO_PTR(operation_id));

  }



  void StartQueueOperation(void) {
@@ -815,16 +837,18 @@ class VolumeControlImpl : public VolumeControl { 


    auto op = &ongoing_operations_.front();



    log::info("operation_id: {}", op->operation_id_);

    log::info(" Current operation_id: {}", op->operation_id_);



    if (op->IsStarted()) {

      log::info("wait until operation {} is complete", op->operation_id_);

      log::info("Operation {} is started, wait until it is complete",

                op->operation_id_);

      return;

    }



    op->Start();



    alarm_set_on_mloop(op->operation_timeout_, 3000, operation_callback,

    alarm_set_on_mloop(op->operation_timeout_, kOperationMonitorTimeoutMs,

                       operation_timeout_callback,

                       INT_TO_PTR(op->operation_id_));

    devices_control_point_helper(

        op->devices_, op->opcode_,
@@ -832,23 +856,6 @@ class VolumeControlImpl : public VolumeControl { 
        op->operation_id_);

  }



  void CancelVolumeOperation(int operation_id) {

    log::info("canceling operation_id: {}", operation_id);



    auto op = find_if(

        ongoing_operations_.begin(), ongoing_operations_.end(),

        [operation_id](auto& it) { return it.operation_id_ == operation_id; });



    if (op == ongoing_operations_.end()) {

      log::error("Could not find operation_id: {}", operation_id);

      return;

    }



    /* Possibly close GATT operations */

    ongoing_operations_.erase(op);

    StartQueueOperation();

  }



  void PrepareVolumeControlOperation(std::vector<RawAddress> devices,

                                     int group_id, bool is_autonomous,

                                     uint8_t opcode,
@@ -1127,6 +1134,8 @@ class VolumeControlImpl : public VolumeControl { 
  std::list<VolumeOperation> ongoing_operations_;

  int latest_operation_id_;



  static constexpr uint64_t kOperationMonitorTimeoutMs = 3000;



  void verify_device_ready(VolumeControlDevice* device, uint16_t handle) {

    if (device->IsReady()) return;

system/bta/vc/vc_test.cc

+136 −1
Original line number Diff line number Diff line
@@ -1023,7 +1023,7 @@ class VolumeControlCallbackTest : public VolumeControlTest { 
  }

};



TEST_F(VolumeControlCallbackTest, test_volume_state_changed) {

TEST_F(VolumeControlCallbackTest, test_volume_state_changed_stress) {

  std::vector<uint8_t> value({0x03, 0x01, 0x02});

  EXPECT_CALL(*callbacks, OnVolumeStateChanged(test_address, 0x03, true, true));

  GetNotificationEvent(0x0021, value);
@@ -1156,6 +1156,8 @@ class VolumeControlValueSetTest : public VolumeControlTest { 
                              std::vector<uint8_t> value,

                              tGATT_WRITE_TYPE write_type, GATT_WRITE_OP_CB cb,

                              void* cb_data) {

          uint8_t write_rsp;



          std::vector<uint8_t> ntf_value(

              {value[0], 0, static_cast<uint8_t>(value[1] + 1)});

          switch (value[0]) {
@@ -1180,6 +1182,7 @@ class VolumeControlValueSetTest : public VolumeControlTest { 
              break;

          }

          GetNotificationEvent(0x0021, ntf_value);

          cb(conn_id, GATT_SUCCESS, 0x0024, 0, &write_rsp, cb_data);

        });

  }
@@ -1278,6 +1281,138 @@ TEST_F(VolumeControlValueSetTest, test_set_volume) { 
  VolumeControl::Get()->SetVolume(test_address, 0x20);

}



TEST_F(VolumeControlValueSetTest, test_set_volume_stress) {

  uint8_t n = 100;

  uint8_t change_cnt = 0;

  uint8_t vol = 1;



  for (uint8_t i = 1; i < n; i++) {

    const std::vector<uint8_t> vol_x10({0x04, change_cnt, vol});

    EXPECT_CALL(gatt_queue,

                WriteCharacteristic(conn_id, 0x0024, vol_x10, GATT_WRITE, _, _))

        .Times(1);

    VolumeControl::Get()->SetVolume(test_address, vol);

    Mock::VerifyAndClearExpectations(&gatt_queue);

    change_cnt++;

    vol++;

  }

}



TEST_F(VolumeControlValueSetTest, test_set_volume_stress_2) {

  uint8_t change_cnt = 0;

  uint8_t vol = 1;



  // In this test we simulate notification coming later and operations will be

  // queued

  ON_CALL(gatt_queue, WriteCharacteristic(conn_id, 0x0024, _, GATT_WRITE, _, _))

      .WillByDefault([](uint16_t conn_id, uint16_t handle,

                        std::vector<uint8_t> value, tGATT_WRITE_TYPE write_type,

                        GATT_WRITE_OP_CB cb, void* cb_data) {

        uint8_t write_rsp;



        switch (value[0]) {

          case 0x04:  // set abs. volume

            break;

          default:

            break;

        }

        cb(conn_id, GATT_SUCCESS, handle, 0, &write_rsp, cb_data);

      });



  const std::vector<uint8_t> vol_x10({0x04, /*change_cnt*/ 0, 0x10});

  std::vector<uint8_t> ntf_value_x10({0x10, 0, 1});

  const std::vector<uint8_t> vol_x11({0x04, /*change_cnt*/ 1, 0x11});

  std::vector<uint8_t> ntf_value_x11({0x11, 0, 2});

  const std::vector<uint8_t> vol_x12({0x04, /*change_cnt*/ 2, 0x12});

  std::vector<uint8_t> ntf_value_x12({0x12, 0, 3});

  const std::vector<uint8_t> vol_x13({0x04, /*change_cnt*/ 3, 0x13});

  std::vector<uint8_t> ntf_value_x13({0x13, 0, 4});



  EXPECT_CALL(gatt_queue,

              WriteCharacteristic(conn_id, 0x0024, vol_x10, GATT_WRITE, _, _))

      .Times(1);

  EXPECT_CALL(gatt_queue,

              WriteCharacteristic(conn_id, 0x0024, vol_x11, GATT_WRITE, _, _))

      .Times(1);

  EXPECT_CALL(gatt_queue,

              WriteCharacteristic(conn_id, 0x0024, vol_x12, GATT_WRITE, _, _))

      .Times(1);

  EXPECT_CALL(gatt_queue,

              WriteCharacteristic(conn_id, 0x0024, vol_x13, GATT_WRITE, _, _))

      .Times(1);



  VolumeControl::Get()->SetVolume(test_address, 0x10);

  VolumeControl::Get()->SetVolume(test_address, 0x11);

  GetNotificationEvent(0x0021, ntf_value_x10);

  GetNotificationEvent(0x0021, ntf_value_x11);

  VolumeControl::Get()->SetVolume(test_address, 0x12);

  VolumeControl::Get()->SetVolume(test_address, 0x13);

  GetNotificationEvent(0x0021, ntf_value_x12);

  GetNotificationEvent(0x0021, ntf_value_x13);



  Mock::VerifyAndClearExpectations(&gatt_queue);

}



TEST_F(VolumeControlValueSetTest, test_set_volume_stress_3) {

  uint8_t change_cnt = 0;

  uint8_t vol = 1;



  /* In this test we simulate notification coming later and operations will be

   * queued but some will be removed from the queue

   */

  ON_CALL(gatt_queue, WriteCharacteristic(conn_id, 0x0024, _, GATT_WRITE, _, _))

      .WillByDefault([](uint16_t conn_id, uint16_t handle,

                        std::vector<uint8_t> value, tGATT_WRITE_TYPE write_type,

                        GATT_WRITE_OP_CB cb, void* cb_data) {

        uint8_t write_rsp;



        switch (value[0]) {

          case 0x04:  // set abs. volume

            break;

          default:

            break;

        }

        cb(conn_id, GATT_SUCCESS, handle, 0, &write_rsp, cb_data);

      });



  const std::vector<uint8_t> vol_x10({0x04, /*change_cnt*/ 0, 0x10});

  std::vector<uint8_t> ntf_value_x10({0x10, 0, 1});

  const std::vector<uint8_t> vol_x11({0x04, /*change_cnt*/ 1, 0x11});

  std::vector<uint8_t> ntf_value_x11({0x11, 0, 2});

  const std::vector<uint8_t> vol_x12({0x04, /*change_cnt*/ 1, 0x12});

  std::vector<uint8_t> ntf_value_x12({0x12, 0, 3});

  const std::vector<uint8_t> vol_x13({0x04, /*change_cnt*/ 1, 0x13});

  std::vector<uint8_t> ntf_value_x13({0x13, 0, 4});



  EXPECT_CALL(gatt_queue,

              WriteCharacteristic(conn_id, 0x0024, vol_x10, GATT_WRITE, _, _))

      .Times(1);



  // Those two belowe will be removed from the queue

  EXPECT_CALL(gatt_queue,

              WriteCharacteristic(conn_id, 0x0024, vol_x11, GATT_WRITE, _, _))

      .Times(0);

  EXPECT_CALL(gatt_queue,

              WriteCharacteristic(conn_id, 0x0024, vol_x12, GATT_WRITE, _, _))

      .Times(0);



  // This one shall be sent with a change count 1.

  EXPECT_CALL(gatt_queue,

              WriteCharacteristic(conn_id, 0x0024, vol_x13, GATT_WRITE, _, _))

      .Times(1);



  VolumeControl::Get()->SetVolume(test_address, 0x10);

  VolumeControl::Get()->SetVolume(test_address, 0x11);

  VolumeControl::Get()->SetVolume(test_address, 0x12);

  VolumeControl::Get()->SetVolume(test_address, 0x13);

  GetNotificationEvent(0x0021, ntf_value_x10);

  GetNotificationEvent(0x0021, ntf_value_x11);

  GetNotificationEvent(0x0021, ntf_value_x12);

  GetNotificationEvent(0x0021, ntf_value_x13);



  Mock::VerifyAndClearExpectations(&gatt_queue);

}



TEST_F(VolumeControlValueSetTest, test_mute_unmute) {

  std::vector<uint8_t> mute_x0({0x06, 0x00});

  EXPECT_CALL(gatt_queue,