met SERVER_SIDE_DISCONNECT, then WWE didn't work anymore

[ada1013]

IMPORTANT: Before you create an issue, please take a look at our Issue Reporting Guide.

Briefly summarize your issue:

we used FRR_RAR_utterances_US voice files to do a long time stress test, but met some unrecoverable problem that SampleApp reconnected to network but WWE didn't have any response unless we re-execute SampleApp. There is a quarter chance to see this issue. The debug9 log:
avs_final 2_listening.log

What is the expected behavior?

SampleApp re-connect to network and Alexa still works.

What behavior are you observing?

SERVER_SIDE_DISCONNECT then re-connecting, but WWE can't work as usual.

Provide the steps to reproduce the issue, if applicable:

Tell us about your environment:

What version of the AVS Device SDK are you using?

  <1.12.1>

Tell us what hardware you're using:

• Desktop / Laptop
• Raspberry Pi
• [ *] Other - tell us more: our own devices

Tell us about your OS (Type & version):

• [* ] Linux
• MacOS
• Raspbian Stretch
• Raspbian Jessy
• Other - tell us more:

[kclchan]

Hi @ada1013,

From the log, I see this error that indicates SpeechSynthesizer failed to release focus:

2019-10-18 02:23:52.262 [  c] E SpeechSynthesizer:onFocusChangeFailed:reason=stateChangeTimeout,messageId=90675717-42f7-472c-a8ed-f1a1fca87d6c

And earlier we see:

2019-10-18 02:23:47.291 [  a] 9 SpeechSynthesizer:cancelDirective:messageId=90675717-42f7-472c-a8ed-f1a1fca87d6c
2019-10-18 02:23:47.291 [  a] 9 DirectiveProcessor:processCancelingQueueLocked:size=0
2019-10-18 02:23:47.291 [  e] 0 SpeechSynthesizer:executeCancel:messageId=90675717-42f7-472c-a8ed-f1a1fca87d6c
2019-10-18 02:23:47.291 [  d] 0 EventBuilder:buildJsonEventString:messageId=adaa0e49-eee7-4c61-9f81-8bbdd650692e,namespace=SpeechRecognizer,name=Recognize
2019-10-18 02:23:47.291 [  e] 0 SpeechSynthesizer:executeCancel:messageId=90675717-42f7-472c-a8ed-f1a1fca87d6c
2019-10-18 02:23:47.291 [  e] 9 SpeechSynthesizer:stopPlaying
2019-10-18 02:23:47.291 [  e] 9 MediaPlayer:stopCalled
2019-10-18 02:23:47.291 [  f] 0 MediaPlayer:handleStopCalled:idPassed=295,currentId=295

And I don't see any onPlaybackStopped callback from MediaPlayer.

Here are some questions:

1. Did you make any modification to the MediaPlayer?
2. Is this issue only happening when there's a SERVER_SIDE_DISCONNECT?
3. I notice that you are running v1.12.1 version of the SDK. Would it be possible to test it on v1.15 and see if you could still reproduce it?

Thanks,
Kenneth

[ada1013]

Hi Kenneth,

Thanks for your response.

1. We did not modify AVS SDK except SampleApp.
2. Yes, this issue is only happening when there is a SERVER_SIDE_DISCONNECT.
3. We do have a timeline to upgrade to v1.15, I will see how soon we can get a test result for this issue.

Regards,
Ada

[ada1013]

Hi team,

We have tried v1.15 without modifying MediaPlayer today, and it had the same issue, we found the Alexa stopped since the logs as below just appeared. We believe it's some kinds of race condition to cause this issue. Please let us know if you have any suggestion, thanks~

[ e] 9 MediaPlayer:stopCalled
[ f] 0 MediaPlayer:handleStopCalled:idPassed=295,currentId=295
[154] 9 MediaPlayer:onPadAddedCalled

Regards,
Ada

[ada1013]

Hi Team,

We have found that the SDK stuck in :
MediaPlayer.cpp handleStop():
stateChangeRet = gst_element_set_state(m_pipeline.pipeline, GST_STATE_NULL);

We have searched gsteamer official web site and there is a clue: https://gstreamer.freedesktop.org/documentation/gstreamer/gstelement.html?gi-language=c,

gst_element_call_async
Calls func from another thread and passes user_data to it. This is to be used for cases when a state change has to be performed from a streaming thread, directly via gst_element_set_state or indirectly e.g. via SEEK events.
Calling those functions directly from the streaming thread will cause deadlocks in many situations, as they might involve waiting for the streaming thread to shut down from this very streaming thread

Someone also discussed about it, for example, in gstreamer git lab, there was a patch for it:
https://gitlab.freedesktop.org/gstreamer/gst-plugins-base/commit/48460f5ace99db253505fdd431ec6f98215dbda4
It uses “gst_element_call_async” to replace “g_source_set_callback” to call gst_element_set_state (element, GST_STATE_NULL);
Please help to check it, thanks.

[caleighatamazon]

Hi @ada1013, thanks for all of this information. We suspect this could be a bug in our code. I'm going to make an issue to investigate this and track it internally. I'll let you know when there are updates.