Fix ducking deactivation retrial logic

- Issue:
If the ducking deactivation is failed, the retrial for the failure can
be performed after a long period of time.

- Solution:
This patch fixes the logic for the retrial. Through this patch, the code
reset the interval of the timer to zero. The deactivation failure should
be caused by a minor timing issue, so it will only take a short period
of time. So, this patch can make faster the retrial latency.
And also this patch includes some minor coding covention fix.

Change-Id: I540fb25b7bc2c8b3099046d8bca98b267afa95e4
Signed-off-by: Suyeon Hwang <stom.hwang@samsung.com>

diff --git a/server/BackgroundVolume.cpp b/server/BackgroundVolume.cpp
index c7b578b..69542cf 100644 (file)
--- a/server/BackgroundVolume.cpp
+++ b/server/BackgroundVolume.cpp
@@ -38,12 +38,6 @@ static const char* get_ducking_stream(sound_stream_type_e stream_type)
        return "Non matched stream";
 }
 
-static void ducking_state_changed_cb(sound_stream_ducking_h stream_ducking, bool is_ducked, void *user_data)
-{
-       SLOG(LOG_DEBUG, tts_tag(), "[BackgroundVolume] is ducked : %d", is_ducked);
-       return;
-}
-
 BackgroundVolume::BackgroundVolume(long long int duckingDuration):
        mDuckingDuration(duckingDuration),
        mMediaStream(nullptr),
@@ -63,12 +57,15 @@ BackgroundVolume::BackgroundVolume(long long int duckingDuration):
 
 BackgroundVolume::~BackgroundVolume()
 {
-       long long int diff = getDurationAfterDucking();
+       auto diff = getMsecDurationAfterDucking();
        if (diff < mDuckingDuration) {
-               usleep(mDuckingDuration * 1000);
+               usleep((mDuckingDuration - diff) * 1000);
        }
 
-       deactivateDuckingAll();
+       if (false == deactivateDuckingAll()) {
+               SLOG(LOG_WARN, tts_tag(), "[BackgroundVolume] Unknown ducking deactivation failure. One last trial");
+               deactivateDuckingAll();
+       }
 
        if (nullptr != mPostponedModifyTimer) {
                void* result = ecore_timer_del(mPostponedModifyTimer);
@@ -131,22 +128,32 @@ void BackgroundVolume::modifyVolumeOnMainThread(void* data)
        }
 
        if (backgroundVolume->mPostponedModifyTimer != nullptr) {
-               SLOG(LOG_INFO, tts_tag(), "[BackgroundVolume] Reserved volume modification exist. (%p)", backgroundVolume->mPostponedModifyTimer);
+               SLOG(LOG_INFO, tts_tag(), "[BackgroundVolume] Reserved volume modification exist. (%p)",
+                        backgroundVolume->mPostponedModifyTimer);
                return;
        }
 
-       long long int diff = backgroundVolume->getDurationAfterDucking();
+       auto diff = backgroundVolume->getMsecDurationAfterDucking();
        if (diff > backgroundVolume->mDuckingDuration) {
                double ratio = backgroundVolume->mVolumeRatio.load();
                SLOG(LOG_INFO, tts_tag(), "[BackgroundVolume] Modify volume ratio(%lf) directly", ratio);
 
-               backgroundVolume->deactivateDuckingAll();
-               backgroundVolume->activateDuckingAll(0, ratio);
-       } else {
-               double delay = static_cast<double>(backgroundVolume->mDuckingDuration - diff) / 1000.0;
-               backgroundVolume->mPostponedModifyTimer = ecore_timer_add(delay, postponedModifyTimerCb, data);
-               SLOG(LOG_INFO, tts_tag(), "[BackgroundVolume] Delay volume modification (%p), delay(%lf)", backgroundVolume->mPostponedModifyTimer, delay);
+               if (backgroundVolume->deactivateDuckingAll()) {
+                       backgroundVolume->activateDuckingAll(0, ratio);
+                       SLOG(LOG_INFO, tts_tag(), "[BackgroundVolume] Volume modification success. ratio(%lf)", ratio);
+                       return;
+               } else {
+                       SLOG(LOG_WARN, tts_tag(), "[BackgroundVolume] Unknown ducking deactivation failure. Try again.");
+               }
+       }
+
+       auto delay = 0.0;
+       if (diff <= backgroundVolume->mDuckingDuration) {
+               delay = static_cast<double>(backgroundVolume->mDuckingDuration - diff) / 1000.0;
        }
+       backgroundVolume->mPostponedModifyTimer = ecore_timer_add(delay, postponedModifyTimerCb, data);
+       SLOG(LOG_INFO, tts_tag(), "[BackgroundVolume] Delay volume modification (%p), delay(%lf)",
+                backgroundVolume->mPostponedModifyTimer, delay);
 }
 
 Eina_Bool BackgroundVolume::postponedModifyTimerCb(void* data)
@@ -157,8 +164,13 @@ Eina_Bool BackgroundVolume::postponedModifyTimerCb(void* data)
        }
 
        BackgroundVolume* backgroundVolume = static_cast<BackgroundVolume*>(data);
-       double ratio = backgroundVolume->mVolumeRatio.load();
-       backgroundVolume->deactivateDuckingAll();
+       auto ratio = backgroundVolume->mVolumeRatio.load();
+
+       if (false == backgroundVolume->deactivateDuckingAll()) {
+               SLOG(LOG_WARN, tts_tag(), "[BackgroundVolume] Unknown ducking deactivation failure. Try again.");
+               ecore_timer_interval_set(backgroundVolume->mPostponedModifyTimer, 0.0);
+               return EINA_TRUE;
+       }
        backgroundVolume->activateDuckingAll(0, ratio);
 
        SLOG(LOG_INFO, tts_tag(), "[BackgroundVolume] Delayed volume modification success. ratio(%lf)", ratio);
@@ -253,38 +265,48 @@ void BackgroundVolume::recoverVolumeOnMainThread(void* data)
 
        BackgroundVolume* backgroundVolume = static_cast<BackgroundVolume*>(data);
        if (nullptr != backgroundVolume->mPostponedRecoverTimer) {
-               SLOG(LOG_INFO, tts_tag(), "[BackgroundVolume] Reserved volume recover exist. (%p)", backgroundVolume->mPostponedRecoverTimer);
+               SLOG(LOG_INFO, tts_tag(), "[BackgroundVolume] Reserved recover timer already exist. (%p)",
+                        backgroundVolume->mPostponedRecoverTimer);
                return;
        }
 
        if (nullptr != backgroundVolume->mPostponedModifyTimer) {
-               void* result = ecore_timer_del(backgroundVolume->mPostponedModifyTimer);
+               auto result = ecore_timer_del(backgroundVolume->mPostponedModifyTimer);
                backgroundVolume->mPostponedModifyTimer = nullptr;
                SLOG(LOG_ERROR, tts_tag(), "[BackgroundVolume] Remove modification timer. result(%p)", result);
        }
 
-       if (false == backgroundVolume->deactivateDuckingAll()) {
-               SLOG(LOG_INFO, tts_tag(), "[BackgroundVolume] Direct deactivation is failed. Try again after some moments");
-               long long int diff = backgroundVolume->getDurationAfterDucking();
-               double delay = static_cast<double>(backgroundVolume->mDuckingDuration - diff) / 1000.0;
-               backgroundVolume->mPostponedRecoverTimer = ecore_timer_add(delay, postponedRecoverTimerCb, data);
-               SLOG(LOG_INFO, tts_tag(), "[BackgroundVolume] Delay deactivation (%p), delay(%lf)", backgroundVolume->mPostponedRecoverTimer, delay);
+       auto diff = backgroundVolume->getMsecDurationAfterDucking();
+       if (diff > backgroundVolume->mDuckingDuration) {
+               SLOG(LOG_INFO, tts_tag(), "[BackgroundVolume] Direct ducking deactivate");
+               if (backgroundVolume->deactivateDuckingAll()) {
+                       SLOG(LOG_INFO, tts_tag(), "[BackgroundVolume] Volume recovery success");
+                       return;
+               } else {
+                       SLOG(LOG_WARN, tts_tag(), "[BackgroundVolume] Unknown ducking deactivation failure. Try again.");
+               }
+       }
+
+       auto delay = 0.0;
+       if (diff <= backgroundVolume->mDuckingDuration) {
+               delay = static_cast<double>(backgroundVolume->mDuckingDuration - diff) / 1000.0;
        }
+       backgroundVolume->mPostponedRecoverTimer = ecore_timer_add(delay, postponedRecoverTimerCb, data);
+       SLOG(LOG_INFO, tts_tag(), "[BackgroundVolume] Delay volume recovery (%p), delay(%lf)",
+                backgroundVolume->mPostponedRecoverTimer, delay);
 }
 
-long long int BackgroundVolume::getDurationAfterDucking()
+long long int BackgroundVolume::getMsecDurationAfterDucking()
 {
        auto currentTime = chrono::steady_clock::now();
-       chrono::milliseconds diff = chrono::duration_cast<chrono::milliseconds>(currentTime - mChangeVolumeTime);
-
-       return diff.count();
+       return chrono::duration_cast<chrono::milliseconds>(currentTime - mChangeVolumeTime).count();
 }
 
 bool BackgroundVolume::deactivateDuckingAll()
 {
        if (false == isDuckingHandleValid()) {
                SLOG(LOG_WARN, tts_tag(), "[BackgroundVolume] There are some invalid handles. Skip ducking deactivation.");
-               return false;
+               return true;
        }
 
        bool result = true;
@@ -304,11 +326,12 @@ Eina_Bool BackgroundVolume::postponedRecoverTimerCb(void* data)
 
        BackgroundVolume* backgroundVolume = static_cast<BackgroundVolume*>(data);
        if (false == backgroundVolume->deactivateDuckingAll()) {
-               SLOG(LOG_ERROR, tts_tag(), "[BackgroundVolume] Try again.");
+               SLOG(LOG_WARN, tts_tag(), "[BackgroundVolume] Unknown ducking deactivation failure. Try again.");
+               ecore_timer_interval_set(backgroundVolume->mPostponedRecoverTimer, 0.0);
                return EINA_TRUE;
        }
 
-       SLOG(LOG_INFO, tts_tag(), "[BackgroundVolume] Delayed unset policy success");
+       SLOG(LOG_INFO, tts_tag(), "[BackgroundVolume] Delayed volume recovery success");
        backgroundVolume->mPostponedRecoverTimer = nullptr;
        return EINA_FALSE;
 }
@@ -332,35 +355,43 @@ bool BackgroundVolume::deactivateDucking(sound_stream_type_e type)
        return true;
 }
 
+static void ducking_state_changed_cb(sound_stream_ducking_h stream_ducking, bool is_ducked, void *user_data)
+{
+       SLOG(LOG_DEBUG, tts_tag(), "[BackgroundVolume] is ducked : %d", is_ducked);
+}
+
 int BackgroundVolume::createHandles()
 {
        SLOG(LOG_INFO, tts_tag(), "[BackgroundVolume] Create ducking handles");
 
        if (nullptr == mMediaStream) {
-               int ret = sound_manager_create_stream_ducking(SOUND_STREAM_TYPE_MEDIA,
-       ducking_state_changed_cb, nullptr, &mMediaStream);
+               int ret = sound_manager_create_stream_ducking(SOUND_STREAM_TYPE_MEDIA, ducking_state_changed_cb, nullptr,
+                                                                                                         &mMediaStream);
                if (SOUND_MANAGER_ERROR_NONE != ret) {
-                       SLOG(LOG_ERROR, tts_tag(), "[BackgroundVolume] Fail to create stream ducking for type media, ret(%d/%s)", ret, get_error_message(ret));
+                       SLOG(LOG_ERROR, tts_tag(), "[BackgroundVolume] Fail to create stream ducking for media, (%d/%s)",
+                                ret, get_error_message(ret));
                        mMediaStream = nullptr;
                        return TTSD_ERROR_OPERATION_FAILED;
                }
        }
 
        if (nullptr == mNotificationStream) {
-               int ret = sound_manager_create_stream_ducking(SOUND_STREAM_TYPE_NOTIFICATION,
-       ducking_state_changed_cb, nullptr, &mNotificationStream);
+               int ret = sound_manager_create_stream_ducking(SOUND_STREAM_TYPE_NOTIFICATION, ducking_state_changed_cb,
+                                                                                                         nullptr, &mNotificationStream);
                if (SOUND_MANAGER_ERROR_NONE != ret) {
-                       SLOG(LOG_ERROR, tts_tag(), "[BackgroundVolume] Fail to create stream ducking for notification type, ret(%d/%s)", ret, get_error_message(ret));
+                       SLOG(LOG_ERROR, tts_tag(), "[BackgroundVolume] Fail to create stream ducking for notification, (%d/%s)",
+                                ret, get_error_message(ret));
                        mNotificationStream = nullptr;
                        return TTSD_ERROR_OPERATION_FAILED;
                }
        }
 
        if (nullptr == mAlarmStream) {
-               int ret = sound_manager_create_stream_ducking(SOUND_STREAM_TYPE_ALARM,
-       ducking_state_changed_cb, nullptr, &mAlarmStream);
+               int ret = sound_manager_create_stream_ducking(SOUND_STREAM_TYPE_ALARM, ducking_state_changed_cb, nullptr,
+                                                                                                         &mAlarmStream);
                if (SOUND_MANAGER_ERROR_NONE != ret) {
-                       SLOG(LOG_ERROR, tts_tag(), "[BackgroundVolume] Fail to create stream ducking for alarm type, ret(%d/%s)", ret, get_error_message(ret));
+                       SLOG(LOG_ERROR, tts_tag(), "[BackgroundVolume] Fail to create stream ducking for alarm, (%d/%s)",
+                                ret, get_error_message(ret));
                        mAlarmStream = nullptr;
                        return TTSD_ERROR_OPERATION_FAILED;
                }

diff --git a/server/BackgroundVolume.h b/server/BackgroundVolume.h
index 2367abb..05e0680 100644 (file)
--- a/server/BackgroundVolume.h
+++ b/server/BackgroundVolume.h
@@ -43,7 +43,7 @@ private:
 
        int createHandles();
        bool isDuckingHandleValid();
-       long long int getDurationAfterDucking();
+       long long int getMsecDurationAfterDucking();
        sound_stream_ducking_h getStreamDuckingHandle(sound_stream_type_e type);
 
        void activateDuckingAll(unsigned int duration, double ratio);