AudioInputProcessor can not RECOGNIZING if the network re-connected after disconnected more than three minutes during playback

[BobXLiu]

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

Briefly summarize your issue:

If the network re-connected after disconnected more than three minutes during play iHR, the client have no response while ask alexa questions. I updated AudioPlayerIntegrationTest file can duplicate this issue. So i checked the log information and found the AudioInputProcessor can not recognize.

What is the expected behavior?

What behavior are you observing?

I checked the log information and found the ContextManager::updateStatesLoop timeout.

2018-01-12 03:44:43.772 [ 7] 0 AudioInputProcessor:setState:from=IDLE,to=RECOGNIZING
2018-01-12 03:44:43.774 [ 4] 0 AudioPlayer:provideState:stateRequestToken=3
2018-01-12 03:44:43.774 [ 9] 0 DialogUXStateAggregator:setState:from=IDLE,to=LISTENING
2018-01-12 03:44:45.775 [ 4] E ContextManager:updateStatesLoopFailed:reason=stateProviderTimedOut
2018-01-12 03:44:45.777 [ 7] E AudioInputProcessor:executeOnContextFailure:error=STATE_PROVIDER_TIMEDOUT
2018-01-12 03:44:45.778 [ 7] 0 AudioInputProcessor:setState:from=RECOGNIZING,to=IDLE
2018-01-12 03:44:45.983 [ 9] 0 DialogUXStateAggregator:setState:from=LISTENING,to=IDLE

The correct behavior should be this:

2018-01-11 00:42:37.070 [ a] 0 AudioInputProcessor:setState:from=IDLE,to=RECOGNIZING
DialogUXStateAggregator::onStateChanged state = 2
2018-01-11 00:42:37.072 [ d] 0 DialogUXStateAggregator:setState:from=IDLE,to=LISTENING
AudioInputProcessor::executeOnDialogUXStateChanged newState1 = 1
2018-01-11 00:42:37.092 [ 7] 0 ContextManager:buildContextSuccessful:context={"context":[{"header":{"namespace":"AudioPlayer","name":"PlaybackState"},"payload":{"token":"","offsetInMilliseconds":0,"playerActivity":"IDLE"}},{"header":{"namespace":"SpeechSynthesizer","name":"SpeechState"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:NotificationsV4#ACRI#DeviceTTSRendererV4_23c86d05-c229-49dd-8439-c130a251ab9b","offsetInMilliseconds":0,"playerActivity":"FINISHED"}},{"header":{"namespace":"Alerts","name":"AlertsState"},"payload":{"allAlerts":[],"activeAlerts":[]}},{"header":{"namespace":"SpeechRecognizer","name":"RecognizerState"},"payload":{"wakeword":"alexa"}}]}
2018-01-11 00:42:37.100 [ a] 0 AudioInputProcessor:executeOnContextAvailable:jsonContext={"context":[{"header":{"namespace":"AudioPlayer","name":"PlaybackState"},"payload":{"token":"","offsetInMilliseconds":0,"playerActivity":"IDLE"}},{"header":{"namespace":"SpeechSynthesizer","name":"SpeechState"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:NotificationsV4#ACRI#DeviceTTSRendererV4_23c86d05-c229-49dd-8439-c130a251ab9b","offsetInMilliseconds":0,"playerActivity":"FINISHED"}},{"header":{"namespace":"Alerts","name":"AlertsState"},"payload":{"allAlerts":[],"activeAlerts":[]}},{"header":{"namespace":"SpeechRecognizer","name":"RecognizerState"},"payload":{"wakeword":"alexa"}}]}
2018-01-11 00:42:37.101 [ a] 1 FocusManager:acquireChannel:channelName=Dialog,activityId=SpeechRecognizer.Recognize

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.4.0>

Tell us what hardware you're using:

• Desktop / Laptop
• Raspberry Pi
• Other - tell us more:

Tell us about your OS (Type & version):

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

[dhpp]

Thanks @BobXLiu,

This appears related to a known issue we are looking into (particularly where IHR makes user barge-in very slow to take effect, ie. asking Alexa a question, when IHR is playing).

I would ask you some follow-up questions - for the Integration test you provide, it doesn't perform the disconnect & reconnect as far as I can tell. Is this something you did manually? Also, if you wish to modify the test further, could you increase the second sleep on line 589 to something like a minute, as opposed to 10 seconds? I'm curious if it will eventually work with a longer delay. Also, when you were testing this manually, how long did you wait for the barge-in to be successful?

[BobXLiu]

Hi @dhpp ,

Yes, Manually disconnect and re-connected the network.
I updated the AudioPlayerIntegration file, increase time from 10 seconds to 3 minutes after send wav file to AVS . The issue occurs if the network disconnect more than one minute.
If the network re-connected after disconnected 50 seconds during play iHR, the test was OK. This is log information. But when i disconnected network for one minute, the test failed. This is log information.

[boyce-xx]

Hi @dhpp ,
I can see the same issue of AVS cannot re-connect sometimes(during the interaction operation).
below are some logs:

mWisAvs.m_connectionStatusObserver->getConnectionStatus: status = 1, AVSCM::isEnabled = 1, AVSCM::isConnected = 0
2018-02-07 03:46:14.833 [278] 0 MessageRouter:connectionStatusChanged:reason=ACL_CLIENT_REQUEST,newStatus=DISCONNECTED
2018-02-07 03:46:14.834 [278] 0 PostConnectSynchronize:PostConnectSynchronizer::doShutdown().
2018-02-07 03:46:14.834 [3535] 9 PostConnectSynchronize:Exiting postConnectLoop thread
2018-02-07 03:46:14.835 [ 11] 0 DialogUXStateAggregator:setState:from=LISTENING,to=IDLE
2018-02-07 03:46:14.835 [ 4] 1 AlertsCapabilityAgent:executeOnConnectionStatusChanged:status=DISCONNECTED,reason=ACL_CLIENT_REQUEST
2018-02-07 03:46:14.835 [ b] 0 AudioInputProcessor:setState:from=RECOGNIZING,to=IDLE
2018-02-07 03:46:14.879 [3536] 0 HTTP2StreamPool:releaseStream:streamId=10735,numAcquiredStreams=0
2018-02-07 03:46:14.891 [3536] 0 PostConnectSynchronize:onDisconnected()
2018-02-07 03:46:14.891 [3536] 0 PostConnectSynchronize:PostConnectSynchronizer::doShutdown().
start to connect AVS......
2018-02-07 03:46:14.893 [278] 0 MessageRouter:connectionStatusChanged:reason=ACL_CLIENT_REQUEST,newStatus=PENDING
2018-02-07 03:46:14.894 [278] I HTTP2Transport:setupDownchannelStream:url=https://avs-alexa-na.amazon.com/v20160207/directives
2018-02-07 03:46:14.894 [278] 0 HTTP2StreamPool:getStream:streamId=10737,numAcquiredStreams=1
2018-02-07 03:46:14.895 [3539] 9 PostConnectSynchronize:Entering postConnectLoop thread
2018-02-07 03:46:14.895 [ 4] 1 AlertsCapabilityAgent:executeOnConnectionStatusChanged:status=PENDING,reason=ACL_CLIENT_REQUEST
2018-02-07 03:46:18.751 [ 8] E ContextManager:updateStatesLoopFailed:reason=stateProviderTimedOut
2018-02-07 03:46:18.752 [ 8] E PostConnectSynchronize:contextRetrievalFailed:reason=contextRequestErrorOccurred,error=STATE_PROVIDER_TIMEDOUT
2018-02-07 03:46:18.752 [ b] E AudioInputProcessor:executeOnContextFailure:error=STATE_PROVIDER_TIMEDOUT
2018-02-07 03:46:18.838 [353a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid: 06e049fffe072c00-000077e3-0000b44b-96588f08f9a63968-96306b92-1

If the connection with AVS is disconnect, I will use the following codes to reconnect, would you help check if the behavior is correct?

if (m_connectionManager && m_connectionStatusObserver) {
            m_connectionManager->disable();
            m_connectionStatusObserver->waitFor(alexaClientSDK::avsCommon::sdkInterfaces::ConnectionStatusObserverInterface::Status::DISCONNECTED);

            printf("start to connect AVS......\n");

            m_connectionManager->enable();
            m_connectionStatusObserver->waitFor(alexaClientSDK::avsCommon::sdkInterfaces::ConnectionStatusObserverInterface::Status::CONNECTED);
        }

Thanks.

[boyce-xx]

Hi @dhpp
I saw another devices can't get feedback voice, after checked the log, found the connection was disconnected, but I don't know why I got the disconnect event? what is the triggering condition of PostConnectSynchronize:onServerSideDisconnect.

2018-02-07 17:17:40.190 [1159] 0 PostConnectSynchronize:onServerSideDisconnect()
2018-02-07 17:17:40.197 [1159] 0 PostConnectSynchronize:PostConnectSynchronizer::doShutdown().
2018-02-07 17:17:40.198 [1159] 0 MessageRouter:connectionStatusChanged:reason=SERVER_SIDE_DISCONNECT,newStatus=PENDING
2018-02-07 17:17:40.199 [1159] I HTTP2Transport:setupDownchannelStream:url=https\://avs-alexa-na.amazon.com/v20160207/directives
2018-02-07 17:17:40.200 [1159] 0 HTTP2StreamPool:getStream:streamId=7501,numAcquiredStreams=1
AVSConnectionManager::onConnectionStatusChanged: status = 1, reason=12
2018-02-07 17:17:40.201 [1159] 0 HTTP2StreamPool:releaseStream:streamId=6495,numAcquiredStreams=0
2018-02-07 17:17:40.202 [ 11] 0 DialogUXStateAggregator:setState:from=SPEAKING,to=IDLE
2018-02-07 17:17:40.202 [  4] 1 AlertsCapabilityAgent:executeOnConnectionStatusChanged:status=PENDING,reason=SERVER_SIDE_DISCONNECT
HTTP2Transport::setIsStoppingLocked disconnectReason = 10
AudioInputProcessor::executeOnDialogUXStateChanged newState1 = 0
AudioInputProcessor::executeOnDialogUXStateChanged newState2 = 0
2018-02-07 17:17:40.203 [1159] 0 PostConnectSynchronize:onDisconnected()
2018-02-07 17:17:40.204 [1159] 0 PostConnectSynchronize:PostConnectSynchronizer::doShutdown().
HTTP2Transport::setIsStoppingLocked disconnectReason = 0
2018-02-08 01:17:40.204 [  a] 1 FocusManager:releaseChannel:channelName=Dialog
2018-02-07 17:17:40.201 [140d] 9 PostConnectSynchronize:Entering postConnectLoop thread
2018-02-07 17:17:40.204 [ 15] 0 PostConnectSynchronize:PostConnectSynchronizer::doShutdown().
2018-02-07 17:17:40.223 [  8] 0 NotificationsCapabilityAgent:provideState:stateRequestToken=1504
2018-02-07 17:17:40.224 [ 13] 0 SpeechSynthesizer:onFocusChanged:newFocus=NONE
2018-02-07 17:17:40.227 [  8] 9 SpeechSynthesizer:provideState:token=1504
2018-02-07 17:17:40.228 [  5] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=true,stateRequestToken=1504
2018-02-07 17:17:40.232 [  a] 0 SpeechSynthesizer:executeStateChange:newState=FINISHED
2018-02-07 17:17:40.233 [  a] 9 SpeechSynthesizer:stopPlaying
2018-02-07 17:17:40.233 [  a] 9 MediaPlayer:stopCalled
2018-02-07 17:17:40.234 [  5] 0 ContextManager:updateStateLocked:action=updatedState,namespace=Notifications,name=IndicatorState
2018-02-07 17:17:40.245 [  2] 9 BaseStreamSource:~BaseStreamSource
2018-02-07 17:17:40.245 [  2] 0 MediaPlayer:callingOnPlaybackFinished:currentId=4480
2018-02-07 17:17:40.245 [  2] 9 SpeechSynthesizer:onPlaybackFinished:callbackSourceId=4480
2018-02-07 17:17:40.246 [  2] 9 MediaPlayer:tearDownTransientPipelineElements
2018-02-07 17:17:40.246 [  2] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=1728
2018-02-07 17:17:40.490 [  2] 0 MediaPlayer:handleStopCalled:idPassed=4480,currentId=0
2018-02-07 17:17:40.490 [  2] E MediaPlayer:validateSourceAndIdFailed:reason=sourceNotSet
2018-02-07 17:17:40.490 [  2] E MediaPlayer:handleStopFailed
2018-02-07 17:17:40.491 [  a] 0 SpeechSynthesizer:executePlaybackError:type=MEDIA_ERROR_INTERNAL_DEVICE_ERROR,error=stopFailed
2018-02-07 17:17:40.491 [  a] 9 SpeechSynthesizer:setCurrentStateLocked:state=FINISHED
2018-02-07 17:17:40.491 [  a] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0
2018-02-07 17:17:40.491 [  a] 0 ContextManager:updateStateLocked:action=updatedState,namespace=SpeechSynthesizer,name=SpeechState
2018-02-07 17:17:40.491 [  a] 9 SpeechSynthesizer:releaseForegroundFocus
2018-02-07 17:17:40.492 [ 13] 9 SpeechSynthesizer:onFocusChangedSuccess
2018-02-07 17:17:40.492 [  a] 1 FocusManager:releaseChannel:channelName=Dialog
2018-02-07 17:17:40.492 [  a] 0 CapabilityAgent:removingMessageIdFromMap:messageId=297a0501-f6f6-4bb0-bbaa-91ae49db5eb2
2018-02-07 17:17:40.492 [ 13] E FocusManager:releaseChannelHelperFailed:reason=observerDoesNotOwnChannel,channel=Dialog
2018-02-07 17:17:40.494 [  a] 0 DirectiveProcessor:onHandlingFailed:messageId=297a0501-f6f6-4bb0-bbaa-91ae49db5eb2,directiveBeingPreHandled=(nullptr),description=stopFailed
2018-02-07 17:17:40.494 [  a] 0 DirectiveProcessor:scrubDialogRequestIdLocked:dialogRequestId=082fdcf1-7fa6-42f8-8e60-79245c0e1340
2018-02-07 17:17:40.494 [  a] 0 CapabilityAgent:removingMessageIdFromMap:messageId=297a0501-f6f6-4bb0-bbaa-91ae49db5eb2
2018-02-07 17:17:40.495 [  a] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=1504
2018-02-07 17:17:40.495 [  a] E SpeechSynthesizer:executeProvideStateFailed:reason=currentInfoIsNull
2018-02-07 17:17:40.495 [  a] 0 SpeechSynthesizer:executePlaybackFinished
2018-02-07 17:17:40.495 [  a] E SpeechSynthesizer:executePlaybackFinishedIgnored:reason=nullptrDirectiveInfo
2018-02-07 17:17:41.228 [140e] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 065e57fffe71d762-000001ca-0001eb28-82cddd7d7f05fd78-1bbfd293-1
2018-02-07 17:17:45.231 [  8] E ContextManager:updateStatesLoopFailed:reason=stateProviderTimedOut
2018-02-07 17:17:45.231 [  8] E PostConnectSynchronize:contextRetrievalFailed:reason=contextRequestErrorOccurred,error=STATE_PROVIDER_TIMEDOUT
m_connectionStatusObserver->getConnectionStatus: status = 1, AVSCM::isEnabled = 1, AVSCM::isConnected = 0

[boyce-xx]

update status: I can still see the issue in SDK V1.5.0

[sanjayrd]

@boyce-xx,

One possible reason for a server-side disconnect is others using the same credentials as yourself (same refresh token). Is that possible?

Thanks,
Sanjay

[boyce-xx]

Hi @sanjayrd ,
Thanks for your reminding, our each test device has its unique refreshtoken.json file, won't be the same.
And update status tested with SDK V1.6.0: Can still see the issue;

I noticed the latest state of AudioPlayer is Playing before I start a new recognize.

2018-03-12 03:16:44.840 [ 9] 0 AudioPlayer:changeActivity:from=IDLE,to=PLAYING

when I reconnect the network, the music can't be resume, so if it's the cause that I can't start the next request?

posted test procedure as below:

1. give a request: Alexa, play kiss FM.
2. wait for a moment after you heard the FM audio, then remove the router network.
3. reconnect the router network after 3 minutes.
4. then give another request, found that the sound cue sound can't be played, and also can't start the next recognize(Alexa, what is the time).

[scotthea-amazon]

Hi boyce-xx,

Have you waited between step 3 and step 4 for the connection to AVS to have been re-established?

This looks like it may be related to issue 447. Can you try specifying a short timeout (e.g. 10 milliseconds) as a new final parameter in AttachmentReaderSource.cpp's call to read() and let us know if that resolves the issue?

Thank you,
-SWH

[boyce-xx]

Hi @scotthea-amazon ,
Yes, I am waiting over 5 minutes between step 3 and step 4, the music can't be resumed.

The issue still can be seen even I add a timeout(10 milliseconds) in read() calls.
auto size = m_reader->read(info.data, info.size, &status, std::chrono::milliseconds(10));

[bandkenamazoncom]

Hi @boyce-xx, we have just released version 1.7. Are you still having issues with the delay with the newest version?

[kclchan]

I am closing this issue due to inactivity. Please feel free to re-open it if it has been closed in error.