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

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

leaudio: Add AF logs to LeAudioHistory 

This patch adds additional dumpsys logs of the communication between Audio Framework
and Bluetooth module. Example logs are shown below:

::le_audio  2023-04-19 09:18:43.552 AF -->  GID 1    METADATA_UPDATE: Reconfigure                : 00:00:00:00:00:00      MEDIA->GAME
::le_audio  2023-04-19 09:18:43.553 AF -->  GID 1    RESUME_REQ: LocalSource                     : 00:00:00:00:00:00      r_state: IDLE, s_state: IDLE
::le_audio  2023-04-19 09:18:44.835 AF <--  GID 1    RESUME_CONFIRMED: LocalSource               : 00:00:00:00:00:00      s_state: READY_TO_START-> STARTED
::le_audio  2023-04-19 09:19:09.749 AF -->  GID 1    METADATA_UPDATE: MetadataUpdate             : 00:00:00:00:00:00      Sink: GAME (0x0008)Source: GAME | LIVE (0x0048)
::le_audio  2023-04-19 09:19:12.777 AF -->  GID 1    SUSPEND_REQ: LocalSource                    : 00:00:00:00:00:00      r_state: IDLE, s_state: STARTED
::le_audio  2023-04-19 09:19:12.777 AF <--  GID 1    SUSPEND_CONFIRMED: LocalSource              : 00:00:00:00:00:00      r_state: IDLEs_state: READY_TO_RELEASE

Bug: 278570065
Tag: #feature
Test: manual
Change-Id: I87b25e0ccf69afd29283b5f83be16256dc92406c
parent 40599d0f

system/bta/le_audio/client.cc

+126 −18
Original line number Diff line number Diff line
@@ -510,32 +510,74 @@ class LeAudioClientImpl : public LeAudioClient { 


  void SuspendedForReconfiguration() {

    if (audio_sender_state_ > AudioState::IDLE) {

      LeAudioLogHistory::Get()->AddLogHistory(

          kLogBtCallAf, active_group_id_, RawAddress::kEmpty,

          kLogAfSuspendForReconfig + "LocalSource",

          "r_state: " + ToString(audio_receiver_state_) +

              "s_state: " + ToString(audio_sender_state_));

      le_audio_source_hal_client_->SuspendedForReconfiguration();

    }

    if (audio_receiver_state_ > AudioState::IDLE) {

      LeAudioLogHistory::Get()->AddLogHistory(

          kLogBtCallAf, active_group_id_, RawAddress::kEmpty,

          kLogAfSuspendForReconfig + "LocalSink",

          "r_state: " + ToString(audio_receiver_state_) +

              "s_state: " + ToString(audio_sender_state_));

      le_audio_sink_hal_client_->SuspendedForReconfiguration();

    }

  }



  void ReconfigurationComplete(uint8_t directions) {

    if (directions & le_audio::types::kLeAudioDirectionSink) {

      LeAudioLogHistory::Get()->AddLogHistory(

          kLogBtCallAf, active_group_id_, RawAddress::kEmpty,

          kLogAfReconfigComplete + "LocalSource",

          "r_state: " + ToString(audio_receiver_state_) +

              "s_state: " + ToString(audio_sender_state_));



      le_audio_source_hal_client_->ReconfigurationComplete();

    }

    if (directions & le_audio::types::kLeAudioDirectionSource) {

      LeAudioLogHistory::Get()->AddLogHistory(

          kLogBtCallAf, active_group_id_, RawAddress::kEmpty,

          kLogAfReconfigComplete + "LocalSink",

          "r_state: " + ToString(audio_receiver_state_) +

              "s_state: " + ToString(audio_sender_state_));



      le_audio_sink_hal_client_->ReconfigurationComplete();

    }

  }



  void CancelStreamingRequest() {

    if (audio_sender_state_ >= AudioState::READY_TO_START) {

  void CancelLocalAudioSourceStreamingRequest() {

    le_audio_source_hal_client_->CancelStreamingRequest();



    LeAudioLogHistory::Get()->AddLogHistory(

        kLogBtCallAf, active_group_id_, RawAddress::kEmpty,

        kLogAfCancel + "LocalSource",

        "s_state: " + ToString(audio_sender_state_));



    audio_sender_state_ = AudioState::IDLE;

  }



    if (audio_receiver_state_ >= AudioState::READY_TO_START) {

  void CancelLocalAudioSinkStreamingRequest() {

    le_audio_sink_hal_client_->CancelStreamingRequest();



    LeAudioLogHistory::Get()->AddLogHistory(

        kLogBtCallAf, active_group_id_, RawAddress::kEmpty,

        kLogAfCancel + "LocalSink",

        "s_state: " + ToString(audio_receiver_state_));



    audio_receiver_state_ = AudioState::IDLE;

  }



  void CancelStreamingRequest() {

    if (audio_sender_state_ >= AudioState::READY_TO_START) {

      CancelLocalAudioSourceStreamingRequest();

    }



    if (audio_receiver_state_ >= AudioState::READY_TO_START) {

      CancelLocalAudioSinkStreamingRequest();

    }

  }



  void ControlPointNotificationHandler(
@@ -3145,6 +3187,28 @@ class LeAudioClientImpl : public LeAudioClient { 
    if (written != to_write) LOG(ERROR) << __func__ << ", not all data sinked";

  }



  void ConfirmLocalAudioSourceStreamingRequest() {

    le_audio_source_hal_client_->ConfirmStreamingRequest();



    LeAudioLogHistory::Get()->AddLogHistory(

        kLogBtCallAf, active_group_id_, RawAddress::kEmpty,

        kLogAfResumeConfirm + "LocalSource",

        "s_state: " + ToString(audio_sender_state_) + "-> STARTED");



    audio_sender_state_ = AudioState::STARTED;

  }



  void ConfirmLocalAudioSinkStreamingRequest() {

    le_audio_sink_hal_client_->ConfirmStreamingRequest();



    LeAudioLogHistory::Get()->AddLogHistory(

        kLogBtCallAf, active_group_id_, RawAddress::kEmpty,

        kLogAfResumeConfirm + "LocalSink",

        "r_state: " + ToString(audio_receiver_state_) + "-> STARTED");



    audio_receiver_state_ = AudioState::STARTED;

  }



  bool StartSendingAudio(int group_id) {

    LOG(INFO) << __func__;
@@ -3200,8 +3264,7 @@ class LeAudioClientImpl : public LeAudioClient { 
    }



    le_audio_source_hal_client_->UpdateRemoteDelay(remote_delay_ms);

    le_audio_source_hal_client_->ConfirmStreamingRequest();

    audio_sender_state_ = AudioState::STARTED;

    ConfirmLocalAudioSourceStreamingRequest();

    /* We update the target audio allocation before streamStarted that the

     * offloder would know how to configure offloader encoder. We should check

     * if we need to update the current
@@ -3264,8 +3327,7 @@ class LeAudioClientImpl : public LeAudioClient { 
          lc3_setup_decoder(dt_us, sr_hz, af_hz, lc3_decoder_right_mem);

    }

    le_audio_sink_hal_client_->UpdateRemoteDelay(remote_delay_ms);

    le_audio_sink_hal_client_->ConfirmStreamingRequest();

    audio_receiver_state_ = AudioState::STARTED;

    ConfirmLocalAudioSinkStreamingRequest();

    /* We update the target audio allocation before streamStarted that the

     * offloder would know how to configure offloader decoder. We should check

     * if we need to update the current
@@ -3510,6 +3572,11 @@ class LeAudioClientImpl : public LeAudioClient { 
        "audio_sender_state_: %s",

        active_group_id_, ToString(audio_receiver_state_).c_str(),

        ToString(audio_sender_state_).c_str());

    LeAudioLogHistory::Get()->AddLogHistory(

        kLogAfCallBt, active_group_id_, RawAddress::kEmpty,

        kLogAfSuspend + "LocalSource",

        "r_state: " + ToString(audio_receiver_state_) +

            ", s_state: " + ToString(audio_sender_state_));



    /* Note: This callback is from audio hal driver.

     * Bluetooth peer is a Sink for Audio Framework.
@@ -3541,6 +3608,12 @@ class LeAudioClientImpl : public LeAudioClient { 
    LOG_INFO("OUT: audio_receiver_state_: %s,  audio_sender_state_: %s",

             ToString(audio_receiver_state_).c_str(),

             ToString(audio_sender_state_).c_str());



    LeAudioLogHistory::Get()->AddLogHistory(

        kLogBtCallAf, active_group_id_, RawAddress::kEmpty,

        kLogAfSuspendConfirm + "LocalSource",

        "r_state: " + ToString(audio_receiver_state_) +

            "s_state: " + ToString(audio_sender_state_));

  }



  void OnLocalAudioSourceResume() {
@@ -3549,6 +3622,12 @@ class LeAudioClientImpl : public LeAudioClient { 
        "audio_sender_state_: %s",

        active_group_id_, ToString(audio_receiver_state_).c_str(),

        ToString(audio_sender_state_).c_str());

    LeAudioLogHistory::Get()->AddLogHistory(

        kLogAfCallBt, active_group_id_, RawAddress::kEmpty,

        kLogAfResume + "LocalSource",

        "r_state: " + ToString(audio_receiver_state_) +

            ", s_state: " + ToString(audio_sender_state_));



    /* Note: This callback is from audio hal driver.

     * Bluetooth peer is a Sink for Audio Framework.

     * e.g. Peer is a speaker
@@ -3566,7 +3645,7 @@ class LeAudioClientImpl : public LeAudioClient { 
            le_audio::types::kLeAudioDirectionSink)) {

      LOG(ERROR) << __func__ << ", invalid resume request for context type: "

                 << ToHexString(configuration_context_type_);

      le_audio_source_hal_client_->CancelStreamingRequest();

      CancelLocalAudioSourceStreamingRequest();

      return;

    }
@@ -3580,7 +3659,7 @@ class LeAudioClientImpl : public LeAudioClient { 
    switch (audio_sender_state_) {

      case AudioState::STARTED:

        /* Looks like previous Confirm did not get to the Audio Framework*/

        le_audio_source_hal_client_->ConfirmStreamingRequest();

        ConfirmLocalAudioSourceStreamingRequest();

        break;

      case AudioState::IDLE:

        switch (audio_receiver_state_) {
@@ -3589,7 +3668,7 @@ class LeAudioClientImpl : public LeAudioClient { 
            if (OnAudioResume(group)) {

              audio_sender_state_ = AudioState::READY_TO_START;

            } else {

              le_audio_source_hal_client_->CancelStreamingRequest();

              CancelLocalAudioSourceStreamingRequest();

            }

            break;

          case AudioState::READY_TO_START:
@@ -3705,10 +3784,9 @@ class LeAudioClientImpl : public LeAudioClient { 
          case AudioState::IDLE:

          case AudioState::READY_TO_RELEASE:

            /* Stream is up just restore it */

            audio_sender_state_ = AudioState::STARTED;

            if (alarm_is_scheduled(suspend_timeout_))

              alarm_cancel(suspend_timeout_);

            le_audio_source_hal_client_->ConfirmStreamingRequest();

            ConfirmLocalAudioSourceStreamingRequest();

            le_audio::MetricsCollector::Get()->OnStreamStarted(

                active_group_id_, configuration_context_type_);

            break;
@@ -3730,6 +3808,11 @@ class LeAudioClientImpl : public LeAudioClient { 
        "audio_sender_state_: %s",

        active_group_id_, ToString(audio_receiver_state_).c_str(),

        ToString(audio_sender_state_).c_str());

    LeAudioLogHistory::Get()->AddLogHistory(

        kLogAfCallBt, active_group_id_, RawAddress::kEmpty,

        kLogAfSuspend + "LocalSink",

        "r_state: " + ToString(audio_receiver_state_) +

            ", s_state: " + ToString(audio_sender_state_));



    StartVbcCloseTimeout();
@@ -3761,6 +3844,12 @@ class LeAudioClientImpl : public LeAudioClient { 
    LOG_INFO("OUT: audio_receiver_state_: %s,  audio_sender_state_: %s",

             ToString(audio_receiver_state_).c_str(),

             ToString(audio_sender_state_).c_str());



    LeAudioLogHistory::Get()->AddLogHistory(

        kLogBtCallAf, active_group_id_, RawAddress::kEmpty,

        kLogAfSuspendConfirm + "LocalSink",

        "r_state: " + ToString(audio_receiver_state_) +

            "s_state: " + ToString(audio_sender_state_));

  }



  inline bool IsDirectionAvailableForCurrentConfiguration(
@@ -3777,6 +3866,12 @@ class LeAudioClientImpl : public LeAudioClient { 
        "audio_sender_state_: %s",

        active_group_id_, ToString(audio_receiver_state_).c_str(),

        ToString(audio_sender_state_).c_str());

    LeAudioLogHistory::Get()->AddLogHistory(

        kLogAfCallBt, active_group_id_, RawAddress::kEmpty,

        kLogAfResume + "LocalSink",

        "r_state: " + ToString(audio_receiver_state_) +

            ", s_state: " + ToString(audio_sender_state_));



    /* Stop the VBC close watchdog if needed */

    StopVbcCloseTimeout();
@@ -3804,7 +3899,7 @@ class LeAudioClientImpl : public LeAudioClient { 
            le_audio::types::kLeAudioDirectionSource)) {

      LOG(ERROR) << __func__ << ", invalid resume request for context type: "

                 << ToHexString(configuration_context_type_);

      le_audio_sink_hal_client_->CancelStreamingRequest();

      CancelLocalAudioSinkStreamingRequest();

      return;

    }
@@ -3817,7 +3912,7 @@ class LeAudioClientImpl : public LeAudioClient { 


    switch (audio_receiver_state_) {

      case AudioState::STARTED:

        le_audio_sink_hal_client_->ConfirmStreamingRequest();

        ConfirmLocalAudioSinkStreamingRequest();

        break;

      case AudioState::IDLE:

        switch (audio_sender_state_) {
@@ -3825,7 +3920,7 @@ class LeAudioClientImpl : public LeAudioClient { 
            if (OnAudioResume(group)) {

              audio_receiver_state_ = AudioState::READY_TO_START;

            } else {

              le_audio_sink_hal_client_->CancelStreamingRequest();

              CancelLocalAudioSinkStreamingRequest();

            }

            break;

          case AudioState::READY_TO_START:
@@ -3942,10 +4037,9 @@ class LeAudioClientImpl : public LeAudioClient { 
          case AudioState::READY_TO_START:

          case AudioState::READY_TO_RELEASE:

            /* Stream is up just restore it */

            audio_receiver_state_ = AudioState::STARTED;

            if (alarm_is_scheduled(suspend_timeout_))

              alarm_cancel(suspend_timeout_);

            le_audio_sink_hal_client_->ConfirmStreamingRequest();

            ConfirmLocalAudioSinkStreamingRequest();

            break;

          case AudioState::RELEASING:

            /* Wait until releasing is completed */
@@ -4494,6 +4588,13 @@ class LeAudioClientImpl : public LeAudioClient { 
      LOG_DEBUG("Changing configuration context from %s to %s",

                ToString(configuration_context_type_).c_str(),

                ToString(new_configuration_context).c_str());



      LeAudioLogHistory::Get()->AddLogHistory(

          kLogAfCallBt, active_group_id_, RawAddress::kEmpty,

          kLogAfMetadataUpdate + "Reconfigure",

          ToString(configuration_context_type_) + "->" +

              ToString(new_configuration_context));



      if (SetConfigurationAndStopStreamWhenNeeded(group,

                                                  new_configuration_context)) {

        return;
@@ -4507,6 +4608,13 @@ class LeAudioClientImpl : public LeAudioClient { 
          ToString(configuration_context_type_).c_str(),

          ToString(metadata_context_types_.sink).c_str(),

          ToString(metadata_context_types_.source).c_str());



      LeAudioLogHistory::Get()->AddLogHistory(

          kLogAfCallBt, active_group_id_, RawAddress::kEmpty,

          kLogAfMetadataUpdate + "Updating...",

          "Sink: " + ToString(metadata_context_types_.sink) +

              "Source: " + ToString(metadata_context_types_.source));



      GroupStream(group->group_id_, configuration_context_type_,

                  metadata_context_types_);

    }

system/bta/le_audio/le_audio_log_history.h

+12 −0
Original line number Diff line number Diff line
@@ -27,6 +27,8 @@ static std::string kLogControlPointCmd("ASCS_CP_CMD"); 
static std::string kLogControlPointNotif("ASCS_CP_NOTIF");

static std::string kLogAseStateNotif("ASE_NOTIF");

static std::string kLogHciEvent("HCI_EVENT");

static std::string kLogAfCallBt("AF --> ");

static std::string kLogBtCallAf("AF <-- ");



/* Operations on SM and ASEs */

static std::string kLogStateChangedOp("STATE CHANGED");
@@ -52,6 +54,16 @@ static std::string kLogSetDataPathOp("SET_DATA_PATH: "); 
static std::string kLogRemoveDataPathOp("REMOVE_DATA_PATH: ");

static std::string kLogDataPathCompleteOp("DATA_PATH_COMPLETE: ");



/* AF Client operations */

static std::string kLogAfResume("RESUME_REQ: ");

static std::string kLogAfSuspend("SUSPEND_REQ: ");

static std::string kLogAfMetadataUpdate("METADATA_UPDATE: ");

static std::string kLogAfResumeConfirm("RESUME_CONFIRMED: ");

static std::string kLogAfSuspendConfirm("SUSPEND_CONFIRMED: ");

static std::string kLogAfCancel("REQUEST_CANCELED: ");

static std::string kLogAfReconfigComplete("RECONFIG_COMPLETE_EVT: ");

static std::string kLogAfSuspendForReconfig("SUSPEND_FOR_RECONFIG_EVT: ");



class LeAudioLogHistory {

 public:

  virtual ~LeAudioLogHistory(void) = default;