Sometimes sample app gets stuck in "Speaking" mode forever

[Sergogr]

I updated my SDK to the latest version (1.0.3), and found a new issue.
Sometimes (roughly 1 out of 10) sample app gets stuck in "speaking" state forever. Issue happens during regular question-answer interaction (no music/barge-in).
Debug log is attached. Please note, the log is not truncated, there was actually no call to DialogUXStateAggregator:setState

speaking_forever.txt

[mradulan]

Hi @Sergogr , are you running on Raspberry Pi Or Linux or MacOS? Also in your log, it looks like you were using MediaPlayer. Does this happen in normal questions to Alexa? Like 'Whats up?', 'What's the weather outside?'

[mradulan]

can you put a log in DialogUXStateAggregator.cpp in transitionFromSpeakingFinished(), to check if it actually calls that function after Speaking State?

[Sergogr]

Hi @mradulan, I am running on Raspberry Pi. This happens in normal questions to Alexa. I will add the log in transitionFromSpeakingFinished() later, and let you know.

[Sergogr]

Hi @mradulan I added the log and I see that transitionFromSpeakingFinished() is not getting called when the issue happens. BTW, it seems that asking "Alexa what's up" and then "Alexa what is the time" repeatedly makes it easier to reproduce (~30% chance).

[mradulan]

Hi @Sergogr , can you put a log in MediaPlayer.cpp in sendPlaybackFinished function and in SpeechSynthesizer in onPlaybackFinished to check if it gets called?

[Sergogr]

@mradulan Please look carefully at the log that I attached in the very first message. It is clear from that log that both of those functions were called. Here is the excerpt:
2017-09-25 18:13:35.292 [ 2] 9 MediaPlayer:messageReceived:messageType=eos
2017-09-25 18:13:35.292 [ 2] 9 BaseStreamSource:~BaseStreamSource

2017-09-25 18:13:35.292 [ 2] 0 MediaPlayer:callingOnPlaybackFinished <--- this is from sendPlaybackFinished
2017-09-25 18:13:35.292 [ 2] 9 SpeechSynthesizer:onPlaybackFinished

2017-09-25 18:13:35.293 [ 2] 9 MediaPlayer:tearDownPipeline
2017-09-25 18:13:35.293 [ a] 0 SpeechSynthesizer:executePlaybackFinished
2017-09-25 18:13:35.293 [ a] 0 SpeechSynthesizer:executeProvideState:stateReques

[mradulan]

for some reason the onDialogUXStateChanged is not getting called i.e the DialogUXStateAggregator is not being notified.

[mradulan]

I am assuming that you hear some speech in SPEAKING state and then it gets stuck. Can you put a log in onStateChanged(SpeechSynthesizerObserver::SpeechSynthesizerState state) in DialogUXStateAggregator.cpp to see if it reached the state SpeechSynthesizerObserver::SpeechSynthesizerState::FINISHED

[ryan-esty]

I have a similar problem. I put in some logging in onStateChanged and I see it hits the FINISHED case and proceeds just like the other times. The one thing I see is in the broken trace doStopSuccess is delayed by something. Below is the snippets between doStop->sendPlaybackFinished
working trace as follows:
2017-10-19 12:11:10.691 [ 2] 0 MediaPlayer:callingOnPlaybackFinished
2017-10-19 12:11:10.691 [ 2] 9 SpeechSynthesizer:onPlaybackFinished
2017-10-19 12:11:10.691 [ 2] 9 MediaPlayer:doStopSuccess

broken trace as follows:
2017-10-19 12:11:15.348 [ 2] 0 MediaPlayer:callingOnPlaybackFinished
2017-10-19 12:11:15.348 [ 2] 9 SpeechSynthesizer:onPlaybackFinished
2017-10-19 12:11:15.348 [ 9] 0 SpeechSynthesizer:executePlaybackFinished
2017-10-19 12:11:15.348 [ 9] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0
2017-10-19 12:11:15.349 [ 9] 0 ContextManager:updateStateLocked:action=updatedState,state={"token":"amzn1.as-ct.v1.Domain:Application:Knowledge#ACRI#02b187b9-e07f-494a-bb91-d9b9794698c3#Alexa3P:1.0/2017/10/19/12/cc02570f467140b7aa790ee008d7af91/11:11::TNIH_2V.bc0ed249-dbda-446f-8a3a-9c400dab181eZXV/1","offsetInMilliseconds":0,"playerActivity":"FINISHED"},namespace=SpeechSynthesizer,name=SpeechState
2017-10-19 12:11:15.349 [ 9] 9 SpeechSynthesizer:releaseForegroundFocus
2017-10-19 12:11:15.349 [ 9] 1 FocusManager:releaseChannel:channelName=Dialog
2017-10-19 12:11:15.349 [ 9] 0 EventBuilder:buildJsonEventString:messageId=31bff71f-8c1a-4aa2-b501-75188713134c,namespace=SpeechSynthesizer,name=SpeechFinished
2017-10-19 12:11:15.349 [ 9] 9 SpeechSynthesizer:setHandlingCompleted
2017-10-19 12:11:15.349 [ 9] 0 DirectiveProcessor:onHandlingCompeted:messageId=bb7436f5-9364-4878-ad85-6e5c2ec335c2,directiveBeingPreHandled=(nullptr)
2017-10-19 12:11:15.349 [ 9] 0 CapabilityAgent:removingMessageIdFromMap:messageId=bb7436f5-9364-4878-ad85-6e5c2ec335c2
2017-10-19 12:11:15.350 [ 10] 0 SpeechSynthesizer:onFocusChanged:newFocus=NONE
2017-10-19 12:11:15.350 [ 2] 9 MediaPlayer:doStopSuccess

[ryan-esty]

At least for me, after more investigation, transitionFromSpeakingFinished is never called from m_multiturnSpeakingToListeningTimer. Which is the same issue @Sergogr has found and I'm using SDK 1.1.0. This is being caused by m_multiturnSpeakingToListeningTimer lapsing so the timer's task never gets called. What's the correct way to fix this? I'm sure there is a reason why we aren't calling the task when the timer expires but without it we get stuck.

[kencecka]

Hi @Sergogr, @ryan-esty,

Please try adding 'm_stopping = false;' at this point in Timer.h. It should resolve the issue.

Ken

[ryan-esty]

@kencecka,

That code was already there but I still get stuck. The only way that I can get out is if I put a call to task() before the return while it is waiting to stop or the time elapsed.

Ryan

[kencecka]

Ok. As you suspected in your previous comment, adding a call to task() before the return is not correct for the Timer class - we only get into that code block if the timer has been asked to stop, and stopping should not implicitly cause the task to execute out of schedule.

A correct fix for this would need to happen in the code which is asking the timer to stop; if the calling code wants the timer task executed when stopping, it should call it directly rather than expecting the timer to do it during the stop call.

I've reviewed the code in DialogUXStateAggregator.cpp related to the m_multiturnSpeakingToListeningTimer. The timer's task is to change state to IDLE when the timer expires. The only place the timer is stopped prematurely is during a setState() call, when the state is being intentionally changed away from FINISHED.

Unfortunately, I've been unable to reproduce the issue you are seeing with some simple/repeated multiturn testing. Can you outline the specific steps you are following that lead to this stuck state?

Ken

[ryan-esty]

@kencecka If I take out the call to task() all I do is ask alexa for a series of questions with a single response. After a couple of iterations I will notice I get stuck in the speaking state. In our current design we no longer care if it gets stuck in speaking as we don't have a KWD but have to do something external to listen for the next question. I attached the last bit of the log on the last listen transition. I said Hi when we first connected and what time it is next. On the second interaction it was stuck in speaking and never came out.

Ryan
issue_189_stuck_speaking.txt

[ryan-esty]

All,

I finally upgraded to 1.2.1 and I have yet to see the stuck in speaking issue as I was seeing. It only took a couple of tries on our platform to get in this state. I hope it if fixed for the rest in this thread.

Ryan

[ryan-esty]

@Sergogr,

Did this fix your issue?

Ryan

[sanjayrd]

Closing due to inactivity. Please reopen if you're still encountering this issue in our latest release @Sergogr.

Thanks,
Sanjay