Skip to content
This repository has been archived by the owner on Jan 16, 2024. It is now read-only.

avs-sdk-crash in speaking/thinking state #391

Closed
dhananjayj29 opened this issue Dec 14, 2017 · 20 comments
Closed

avs-sdk-crash in speaking/thinking state #391

dhananjayj29 opened this issue Dec 14, 2017 · 20 comments

Comments

@dhananjayj29
Copy link

Hi ,
I have built avs-sdk and sample app for my Linux embedded system environment.
sdk version : 1.2.1
while running the sample app through command line interface , am getting the crash after every 2-3 queries . below are the detailed logs and stack trace for my crash .

below are the logs , SDK is crashing so frequently here:

2018-01-08 23:18:36.847 [ a] 9 MediaPlayer:playCalled
2018-01-08 23:18:36.848 [ 2] 0 MediaPlayer:handlePlayCalled:idPassed=1,currentId=1
2018-01-08 23:18:36.848 [ 2] 0 MediaPlayer:handlePlay:attemptBuffering=0
2018-01-08 23:18:36.864 [ 2] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2018-01-08 23:18:36.864 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:36.864 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:36.864 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:36.865 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:36.865 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:36.865 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:36.867 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:36.867 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:36.867 [ 2] 9 MediaPlayer:State Change:oldState=NULL,newState=READY,pendingState=PLAYING
2018-01-08 23:18:36.867 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:36.867 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:36.867 [ 2] 9 MediaPlayer:messageReceived:messageType=stream-status
2018-01-08 23:18:36.867 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:36.868 [ 14] 9 BaseStreamSource:onNeedDataCalled:size=4096
2018-01-08 23:18:36.868 [ 2] 9 MediaPlayer:messageReceived:messageType=stream-status
2018-01-08 23:18:36.868 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:36.868 [ 2] 9 MediaPlayer:messageReceived:messageType=stream-status
2018-01-08 23:18:36.868 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:36.868 [ 2] 9 MediaPlayer:messageReceived:messageType=stream-status
2018-01-08 23:18:36.868 [ 2] 9 BaseStreamSource:handleNeedDataCalled
2018-01-08 23:18:36.868 [ 2] 9 BaseStreamSource:installOnReadDataHandler:action=newSourceId,sourceId=16
2018-01-08 23:18:36.869 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2018-01-08 23:18:36.869 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2018-01-08 23:18:36.869 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2018-01-08 23:18:36.869 [ 2] 9 AttachmentReaderSource:read:size=3185,status=0
2018-01-08 23:18:36.930 [ 14] 9 MediaPlayer:onPadAddedCalled
2018-01-08 23:18:37.223 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2018-01-08 23:18:37.224 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:37.224 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:37.224 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:37.224 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:37.224 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:37.224 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:37.225 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2018-01-08 23:18:37.225 [ 2] 9 MediaPlayer:handlePadAddedSignalCalled
2018-01-08 23:18:37.244 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2018-01-08 23:18:37.245 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:37.245 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2018-01-08 23:18:37.247 [ 2] 9 MediaPlayer:messageReceived:messageType=stream-start
2018-01-08 23:18:37.529 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2018-01-08 23:18:37.529 [ 10] 0 AudioInputProcessor:onSendCompleted:status=SUCCESS
2018-01-08 23:18:37.530 [ 10] 0 HTTP2Transport:cleanupFinishedStream:streamId=9,result=200
2018-01-08 23:18:37.530 [ 2] 9 MediaPlayer:messageReceived:messageType=latency
2018-01-08 23:18:37.530 [ 2] 9 MediaPlayer:messageReceived:messageType=stream-status
2018-01-08 23:18:37.530 [ 2] 9 MediaPlayer:messageReceived:messageType=tag
2018-01-08 23:18:37.530 [ 2] 0 MediaPlayer:callingOnTags
2018-01-08 23:18:37.531 [ 2] 9 MediaPlayer:messageReceived:messageType=tag
2018-01-08 23:18:37.531 [ 2] 0 MediaPlayer:callingOnTags
2018-01-08 23:18:37.531 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:37.531 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:37.531 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:37.531 [ 2] 9 MediaPlayer:State Change:oldState=READY,newState=PAUSED,pendingState=PLAYING
2018-01-08 23:18:37.531 [ 2] 9 MediaPlayer:messageReceived:messageType=async-done
2018-01-08 23:18:37.532 [ 2] 9 MediaPlayer:messageReceived:messageType=new-clock
2018-01-08 23:18:37.530 [ 10] 0 HTTP2StreamPool:releaseStream:streamId=9,numAcquiredStreams=1
2018-01-08 23:18:37.532 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:37.532 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:37.532 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:37.532 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:37.533 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:37.533 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:37.533 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:37.533 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:37.533 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:37.533 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:37.533 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:37.533 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2018-01-08 23:18:37.534 [ 2] 9 MediaPlayer:State Change:oldState=PAUSED,newState=PLAYING,pendingState=VOID_PENDING
2018-01-08 23:18:37.534 [ 2] 0 MediaPlayer:callingOnPlaybackStarted:currentId=1
2018-01-08 23:18:37.534 [ 2] 9 SpeechSynthesizer:onPlaybackStarted:callbackSourceId=1
2018-01-08 23:18:37.534 [ a] 0 SpeechSynthesizer:executePlaybackStarted
2018-01-08 23:18:37.534 [ 2] 9 MediaPlayer:messageReceived:messageType=tag
2018-01-08 23:18:37.534 [ a] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0
2018-01-08 23:18:37.534 [ a] 9 MediaPlayer:getOffsetCalled
2018-01-08 23:18:37.534 [ 2] 0 MediaPlayer:callingOnTags
2018-01-08 23:18:37.534 [ 2] 9 AttachmentReaderSource:read:size=1388,status=0
2018-01-08 23:18:37.535 [ 2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=1,currentId=1
2018-01-08 23:18:37.537 [ a] 0 ContextManager:updateStateLocked:action=updatedState,state={"token":"amzn1.as-ct.v1.Domain:Application:Knowledge#ACRI#1681976a-a9b0-48d7-9905-d9600e680406#Alexa3P:1.0/2e
2018-01-08 23:18:37.537 [ 13] 9 SpeechSynthesizer:onFocusChangedSuccess
2018-01-08 23:18:37.537 [ a] 0 EventBuilder:buildJsonEventString:messageId=5e253201-b5df-47ae-9663-105c8ad1889d,namespace=SpeechSynthesizer,name=SpeechStarted
2018-01-08 23:18:37.537 [ a] 9 HTTP2Transport:enqueueRequest:jsonContent={"event":{"header":{"namespace":"SpeechSynthesizer","name":"SpeechStarted","messageId":"5e253201-b5df-47ae-9663-105c8ad1889}
2018-01-08 23:18:37.538 [ 2] I InProcessAttachmentReader:readFailed:reason=SDS is closed
2018-01-08 23:18:37.878 [ 2] 9 AttachmentReaderSource:read:size=0,status=3
2018-01-08 23:18:37.878 [ 2] 9 BaseStreamSource:signalEndOfDataCalled
2018-01-08 23:18:37.878 [ 10] 0 HTTP2Transport:processNextOutgoingMessage:jsonContent={"event":{"header":{"namespace":"SpeechSynthesizer","name":"SpeechStarted","messageId":"5e253201-b5df-47ae-9663}
2018-01-08 23:18:37.879 [ 10] 0 HTTP2StreamPool:getStream:streamId=11,numAcquiredStreams=2
2018-01-08 23:18:37.879 [ 2] 9 BaseStreamSource:clearOnReadDataHandlerCalled:sourceId=16
terminate called after throwing an instance of 'std::future_error'
2018-01-08 23:18:37.879 [ 10] 9 HTTP2

(gdb) bt
#0 __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:57
#1 0xb6a52950 in __GI_abort () at abort.c:89
#2 0xb6c3a58c in __gnu_cxx::__verbose_terminate_handler () atgcc-4.8.2-r0/gcc-4.8.2/libstdc++-v3/libsupc++/vterminate.cc:95
#3 0xb6c383d8 in __cxxabiv1::__terminate (handler=) at /gcc-4.8.2/libstdc++-v3/libsupc++/eh_terminate.cc:38
#4 0xb6c38400 in std::terminate () at /gcc-4.8.2-r0/gcc-4.8.2/libstdc++-v3/libsupc++/eh_terminate.cc:48
#5 0xb6c8ca84 in std::(anonymous namespace)::execute_native_thread_routine (__p=)
atmp-eglibc/work-shared/gcc-4.8.2-r0/gcc-4.8.2/libstdc++-v3/src/c++11/thread.cc:92
#6 0xb6eeb040 in start_thread (arg=0xae2ff440) at pthread_create.c:314
#7 0xb6af10e0 in ?? () at ../ports/sysdeps/unix/sysv/linux/arm/clone.S:92 from //lib/libc.so.6
#8 0xb6af10e0 in ?? () at ../ports/sysdeps/unix/sysv/linux/arm/clone.S:92 fromlib/libc.so.6
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

Can someone help to find out root cause and possible fix for this issue.
@dhananjayj29
Copy link
Author

I have ran MediaPlayer test and below are the logs for the similar crash:

2017-12-09 08:08:28.013 [ 1] 0 MediaPlayer:handleSetObserverCalled
2017-12-09 08:08:28.014 [ 1] 0 MediaPlayer:handleSetSourceCalled
2017-12-09 08:08:28.018 [ 1] 0 MediaPlayer:handlePlayCalled:idPassed=1,currentId=1
2017-12-09 08:08:28.018 [ 1] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-09 08:08:28.048 [ 1] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-09 08:08:28.140 [ 1] 0 MediaPlayer:callingOnTags
2017-12-09 08:08:28.140 [ 1] 0 MediaPlayer:callingOnTags
2017-12-09 08:08:28.147 [ 1] 0 MediaPlayer:callingOnPlaybackStarted:currentId=1
2017-12-09 08:08:28.149 [ 1] 0 MediaPlayer:callingOnTags
2017-12-09 08:08:30.835 [ 1] 0 MediaPlayer:callingOnPlaybackFinished:currentId=1
[ OK ] MediaPlayerTest.testStartPlayWaitForEnd (4199 ms)
[ RUN ] MediaPlayerTest.testStartPlayForUrl
2017-12-09 08:08:30.860 [ 2] 0 MediaPlayer:handleSetObserverCalled
2017-12-09 08:08:30.860 [ 3] 0 MediaPlayer:handleSetSourceForUrlCalled
2017-12-09 08:08:30.861 [ 3] 0 UrlSource:initCalledForUrlSource
2017-12-09 08:08:30.862 [ 2] 0 MediaPlayer:handlePlayCalled:idPassed=2,currentId=2
2017-12-09 08:08:30.862 [ 2] 0 MediaPlayer:handlePlay:attemptBuffering=1
2017-12-09 08:08:30.881 [ 2] 0 MediaPlayer:handlePlay:startingState=PAUSED,stateReturn=FAILURE
2017-12-09 08:08:30.881 [ 2] E MediaPlayer:handlePlayFailed:reason=gstElementSetStateFailure
2017-12-09 08:08:30.881 [ 2] 0 MediaPlayer:callingOnPlaybackError:type=MEDIA_ERROR_INTERNAL_DEVICE_ERROR,error=MediaPlayer:handlePlayFailed:reason=gstElementSetStateFailure,currentId=2
2017-12-09 08:08:30.881 [ 2] E MediaPlayerTest:onPlaybackError:type=MEDIA_ERROR_INTERNAL_DEVICE_ERROR,error=MediaPlayer:handlePlayFailed:reason=gstElementSetStateFailure
/home/dhananjay/AVSDevelopement/git_repos/avs-device-sdk/MediaPlayer/test/MediaPlayerTest.cpp:629: Failure
Value of: m_playerObserver->waitForPlaybackStarted(sourceId)
Actual: false
Expected: true
[ FAILED ] MediaPlayerTest.testStartPlayForUrl (5024 ms)
[ RUN ] MediaPlayerTest.testSetSourceEmptyUrl
2017-12-09 08:08:35.883 [ 4] 0 MediaPlayer:handleSetObserverCalled
2017-12-09 08:08:35.884 [ 5] 0 MediaPlayer:handleSetSourceForUrlCalled
2017-12-09 08:08:35.884 [ 5] 0 UrlSource:initCalledForUrlSource
2017-12-09 08:08:35.884 [ 5] E UrlSource:initFailed:reason=startingParsePlaylistFailed
2017-12-09 08:08:35.884 [ 5] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=UrlSource
2017-12-09 08:08:35.885 [ 5] E MediaPlayer:handleSetSourceForUrlFailed:reason=sourceIsNullptr
[ OK ] MediaPlayerTest.testSetSourceEmptyUrl (10 ms)
[ RUN ] MediaPlayerTest.testConsecutiveSetSource
2017-12-09 08:08:35.892 [ 6] 0 MediaPlayer:handleSetObserverCalled
2017-12-09 08:08:35.893 [ 7] 0 MediaPlayer:handleSetSourceForUrlCalled
2017-12-09 08:08:35.893 [ 7] 0 UrlSource:initCalledForUrlSource
2017-12-09 08:08:35.893 [ 7] E UrlSource:initFailed:reason=startingParsePlaylistFailed
2017-12-09 08:08:35.893 [ 7] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=UrlSource
2017-12-09 08:08:35.893 [ 7] E MediaPlayer:handleSetSourceForUrlFailed:reason=sourceIsNullptr
2017-12-09 08:08:35.894 [ 8] 0 MediaPlayer:handleSetSourceForUrlCalled
2017-12-09 08:08:35.894 [ 8] 0 UrlSource:initCalledForUrlSource
2017-12-09 08:08:35.895 [ 6] 0 MediaPlayer:handlePlayCalled:idPassed=3,currentId=3
2017-12-09 08:08:35.895 [ 6] 0 MediaPlayer:handlePlay:attemptBuffering=1
2017-12-09 08:08:35.911 [ 6] 0 MediaPlayer:handlePlay:startingState=PAUSED,stateReturn=FAILURE
2017-12-09 08:08:35.911 [ 6] E MediaPlayer:handlePlayFailed:reason=gstElementSetStateFailure
2017-12-09 08:08:35.911 [ 6] 0 MediaPlayer:callingOnPlaybackError:type=MEDIA_ERROR_INTERNAL_DEVICE_ERROR,error=MediaPlayer:handlePlayFailed:reason=gstElementSetStateFailure,currentId=3
2017-12-09 08:08:35.911 [ 6] E MediaPlayerTest:onPlaybackError:type=MEDIA_ERROR_INTERNAL_DEVICE_ERROR,error=MediaPlayer:handlePlayFailed:reason=gstElementSetStateFailure
/home/dhananjay/AVSDevelopement/git_repos/avs-device-sdk/MediaPlayer/test/MediaPlayerTest.cpp:653: Failure
Value of: m_playerObserver->waitForPlaybackStarted(id)
Actual: false
Expected: true
[ FAILED ] MediaPlayerTest.testConsecutiveSetSource (5030 ms)
[ RUN ] MediaPlayerTest.testStartPlayWaitForEndStartPlayAgain
2017-12-09 08:08:40.922 [ 9] 0 MediaPlayer:handleSetObserverCalled
2017-12-09 08:08:40.923 [ 9] 0 MediaPlayer:handleSetSourceCalled
2017-12-09 08:08:40.926 [ 9] 0 MediaPlayer:handlePlayCalled:idPassed=4,currentId=4
2017-12-09 08:08:40.926 [ 9] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-09 08:08:40.937 [ 9] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-09 08:08:41.019 [ 9] 0 MediaPlayer:callingOnTags
2017-12-09 08:08:41.020 [ 9] 0 MediaPlayer:callingOnTags
2017-12-09 08:08:41.025 [ 9] 0 MediaPlayer:callingOnPlaybackStarted:currentId=4
2017-12-09 08:08:41.027 [ 9] 0 MediaPlayer:callingOnTags
2017-12-09 08:08:43.735 [ 9] 0 MediaPlayer:callingOnPlaybackFinished:currentId=4
2017-12-09 08:08:43.758 [ 9] 0 MediaPlayer:handleSetSourceCalled
2017-12-09 08:08:43.760 [ 9] 0 MediaPlayer:handlePlayCalled:idPassed=5,currentId=5
2017-12-09 08:08:43.760 [ 9] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-09 08:08:43.772 [ 9] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-09 08:08:43.850 [ 9] 0 MediaPlayer:callingOnTags
2017-12-09 08:08:43.851 [ 9] 0 MediaPlayer:callingOnTags
2017-12-09 08:08:43.854 [ 9] 0 MediaPlayer:callingOnPlaybackStarted:currentId=5
2017-12-09 08:08:43.860 [ 9] 0 MediaPlayer:callingOnTags
2017-12-09 08:08:46.575 [ 9] 0 MediaPlayer:callingOnPlaybackFinished:currentId=5
[ OK ] MediaPlayerTest.testStartPlayWaitForEndStartPlayAgain (5679 ms)
[ RUN ] MediaPlayerTest.testStopPlay
2017-12-09 08:08:46.603 [ a] 0 MediaPlayer:handleSetObserverCalled
2017-12-09 08:08:46.603 [ a] 0 MediaPlayer:handleSetSourceCalled
2017-12-09 08:08:46.605 [ a] 0 MediaPlayer:handlePlayCalled:idPassed=6,currentId=6
2017-12-09 08:08:46.606 [ a] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-09 08:08:46.616 [ a] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-09 08:08:46.693 [ a] 0 MediaPlayer:callingOnTags
2017-12-09 08:08:46.694 [ a] 0 MediaPlayer:callingOnTags
2017-12-09 08:08:46.698 [ a] 0 MediaPlayer:callingOnPlaybackStarted:currentId=6
2017-12-09 08:08:46.712 [ a] 0 MediaPlayer:callingOnTags
2017-12-09 08:08:51.705 [ a] 0 MediaPlayer:handleStopCalled:idPassed=6,currentId=6
2017-12-09 08:08:51.727 [ a] 0 MediaPlayer:callingOnPlaybackStopped:currentId=6
[ OK ] MediaPlayerTest.testStopPlay (5135 ms)
[ RUN ] MediaPlayerTest.testStartPlayCallAfterStopPlay
2017-12-09 08:08:51.737 [ b] 0 MediaPlayer:handleSetObserverCalled
2017-12-09 08:08:51.738 [ b] 0 MediaPlayer:handleSetSourceCalled
2017-12-09 08:08:51.740 [ b] 0 MediaPlayer:handlePlayCalled:idPassed=7,currentId=7
2017-12-09 08:08:51.740 [ b] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-09 08:08:51.751 [ b] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-09 08:08:51.827 [ b] 0 MediaPlayer:callingOnTags
2017-12-09 08:08:51.827 [ b] 0 MediaPlayer:callingOnTags
2017-12-09 08:08:51.830 [ b] 0 MediaPlayer:callingOnPlaybackStarted:currentId=7
2017-12-09 08:08:51.835 [ b] 0 MediaPlayer:callingOnTags
2017-12-09 08:08:53.854 [ b] 0 MediaPlayer:handleStopCalled:idPassed=7,currentId=7
2017-12-09 08:08:53.867 [ b] 0 MediaPlayer:callingOnPlaybackStopped:currentId=7
2017-12-09 08:08:53.867 [ c] E MediaPlayer:playFailed:reason=sourceNotSet
[ OK ] MediaPlayerTest.testStartPlayCallAfterStopPlay (2139 ms)
[ RUN ] MediaPlayerTest.testStartPlayCallAfterStopPlayDifferentSource
2017-12-09 08:08:53.877 [ d] 0 MediaPlayer:handleSetObserverCalled
2017-12-09 08:08:53.877 [ d] 0 MediaPlayer:handleSetSourceCalled
2017-12-09 08:08:53.879 [ d] 0 MediaPlayer:handlePlayCalled:idPassed=8,currentId=8
2017-12-09 08:08:53.879 [ d] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-09 08:08:53.889 [ d] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-09 08:08:53.970 [ d] 0 MediaPlayer:callingOnTags
2017-12-09 08:08:53.970 [ d] 0 MediaPlayer:callingOnTags
2017-12-09 08:08:53.972 [ d] 0 MediaPlayer:callingOnPlaybackStarted:currentId=8
2017-12-09 08:08:53.977 [ d] 0 MediaPlayer:callingOnTags
2017-12-09 08:08:54.985 [ d] 0 MediaPlayer:handleStopCalled:idPassed=8,currentId=8
2017-12-09 08:08:54.998 [ d] 0 MediaPlayer:callingOnPlaybackStopped:currentId=8
2017-12-09 08:08:54.999 [ d] 0 MediaPlayer:handleSetSourceCalled
2017-12-09 08:08:55.001 [ d] 0 MediaPlayer:handlePlayCalled:idPassed=9,currentId=9
2017-12-09 08:08:55.001 [ d] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-09 08:08:55.011 [ d] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-09 08:08:55.090 [ d] 0 MediaPlayer:callingOnTags
2017-12-09 08:08:55.090 [ d] 0 MediaPlayer:callingOnTags
2017-12-09 08:08:55.102 [ d] 0 MediaPlayer:callingOnPlaybackStarted:currentId=9
2017-12-09 08:08:55.103 [ d] 0 MediaPlayer:callingOnTags
2017-12-09 08:08:56.114 [ d] 0 MediaPlayer:handleStopCalled:idPassed=9,currentId=9
2017-12-09 08:08:56.135 [ d] 0 MediaPlayer:callingOnPlaybackStopped:currentId=9
[ OK ] MediaPlayerTest.testStartPlayCallAfterStopPlayDifferentSource (2268 ms)
[ RUN ] MediaPlayerTest.testPauseDuringPlay
2017-12-09 08:08:56.146 [ e] 0 MediaPlayer:handleSetObserverCalled
2017-12-09 08:08:56.146 [ e] 0 MediaPlayer:handleSetSourceCalled
2017-12-09 08:08:56.149 [ e] 0 MediaPlayer:handlePlayCalled:idPassed=10,currentId=10
terminate called after throwing an instance of 'std::future_error'
what(): Promise already satisfied
Stack Strace:

(gdb) bt
#0 __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:57
#1 0xb6be6950 in __GI_abort () at abort.c:89
#2 0xb6d5d58c in __gnu_cxx::__verbose_terminate_handler () at /libsupc++/vterminate.cc:95
#3 0xb6d5b3d8 in __cxxabiv1::__terminate (handler=) at /libsupc++/eh_terminate.cc:38
#4 0xb6d5b400 in std::terminate () at eh_terminate.cc:48
#5 0xb6d5b73c in __cxxabiv1::__cxa_throw (obj=0xb4a05ec8, tinfo=, dest=)
at /u02/yoctobms/build/info3-low/tmp-eglibc/work-shared/gcc-4.8.2-r0/gcc-4.8.2/libstdc++-v3/libsupc++/eh_throw.cc:84
#6 0xb6dae824 in std::__throw_future_error (__i=__i@entry=2) at functexcept.cc:109
#7 0xb6ed4ef0 in _M_set_result (__ignore_failure=false, __res=..., this=0x96a78) at future:360
#8 std::promise::set_value(bool&&) (this=this@entry=0xb6984218 <g_idle_dispatch>,
__r=__r@entry=<unknown type in /usr/lib/libMediaPlayer.so, CU 0x46162, DIE 0x89a5d>)
at /future:994
#9 0xb6eccbe4 in alexaClientSDK::mediaPlayer::MediaPlayer::handlePlay (this=0xa9108, id=, promise=0xbe9a383c)
at /home/dhananjay/AVSDevelopement/git_repos/avs-device-sdk/MediaPlayer/src/MediaPlayer.cpp:1026
#10 0xb6eccfdc in operator() (__closure=) at avs-device-sdk/MediaPlayer/src/MediaPlayer.cpp:228
#11 std::_Function_handler<int(), alexaClientSDK::mediaPlayer::MediaPlayer::play(alexaClientSDK::avsCommon::utils::mediaPlayer::MediaPlayerInterface::SourceId)::__lambda9>::_M_invoke(const std::_Any_data &) (__functor=...) at /functional:2056
#12 0xb69878dc in g_main_dispatch (context=0x26b000) at gmain.c:3154
#13 g_main_context_dispatch (context=context@entry=0x26b000) at gmain.c:3769
#14 0xb6987c44 in g_main_context_iterate (context=0x26b000, block=block@entry=1, dispatch=dispatch@entry=1, self=) at gmain.c:3840
#15 0xb6987fa0 in g_main_loop_run (loop=0xad370) at gmain.c:4034
#16 0xb6daf9a8 in std::(anonymous namespace)::execute_native_thread_routine (__p=)
at thread.cc:84
#17 0xb6de4040 in start_thread (arg=0xb5373450) at pthread_create.c:314
#18 0xb6c850e0 in ?? () at ../ports/sysdeps/unix/sysv/linux/arm/clone.S:92 from lib/libc.so.6
#19 0xb6c850e0 in ?? () at ../ports/sysdeps/unix/sysv/linux/arm/clone.S:92 from lib/libc.so.6
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

@sanjayrd
Copy link
Contributor

Hi @dhananjayj29,

Would it be possible for you to upgrade to v1.3? We've made significant stability improvements in this release and we believe it should solve the crash you are seeing.

If not, could you give me some reproduction steps so that I can try to reproduce locally?

Thanks,
Sanjay

@dhananjayj29
Copy link
Author

Hi
Thanks for the reply,
I have moved to 1.3 version and there are improvements seen for this issue.
On previous version it crashed / aborted after every 2-3 times . and in latest v1.3 version it is aborting 1 out of 10 times.

Below are the logs

2017-12-08 23:27:08.369 [ 10] I InProcessAttachmentReader:readFailed:reason=SDS is closed
2017-12-08 23:27:09.002 [ 10] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid: 0279dafffe599f4c-000043e3-0003c553-22557efc9270e84b-d17d1d20-41
2017-12-08 23:27:09.304 [ b] I DirectiveSequencer:onDirective:directive={"namespace:"SpeechSynthesizer",name:"Speak",messageId:"1454533d-3b5b-42c3-a123-6c867f11a010",dialogRequestId:"83492d12-029d}
2017-12-08 23:27:09.305 [ c] I DirectiveRouter:preHandleDirective:messageId=1454533d-3b5b-42c3-a123-6c867f11a010,action=calling
2017-12-08 23:27:09.305 [ c] 0 CapabilityAgent:addingMessageIdToMap:messageId=1454533d-3b5b-42c3-a123-6c867f11a010
2017-12-08 23:27:09.305 [ c] 9 SpeechSynthesizer:preHandleDirective:messageId=1454533d-3b5b-42c3-a123-6c867f11a010
2017-12-08 23:27:09.305 [ d] I DirectiveRouter:handleDirective:messageId=1454533d-3b5b-42c3-a123-6c867f11a010,action=calling
2017-12-08 23:27:09.305 [ 8] 0 SpeechSynthesizer:executePreHandle:messageId=1454533d-3b5b-42c3-a123-6c867f11a010
2017-12-08 23:27:09.305 [ d] 9 SpeechSynthesizer:handleDirective:messageId=1454533d-3b5b-42c3-a123-6c867f11a010
2017-12-08 23:27:09.310 [ 8] 0 SpeechSynthesizer:executeHandle:messageId=1454533d-3b5b-42c3-a123-6c867f11a010
2017-12-08 23:27:09.310 [ 8] 1 FocusManager:acquireChannel:channelName=Dialog,activityId=SpeechSynthesizer.Speak
2017-12-08 23:27:09.311 [ 12] 9 AudioInputProcessor:onFocusChanged:newFocus=NONE
2017-12-08 23:27:09.311 [ 12] 0 SpeechSynthesizer:onFocusChanged:newFocus=FOREGROUND
2017-12-08 23:27:09.311 [ 9] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=NONE
2017-12-08 23:27:09.312 [ 9] 0 AudioInputProcessor:executeOnFocusChanged:reason=Lost focus
2017-12-08 23:27:09.312 [ 9] 0 AudioInputProcessor:setState:from=BUSY,to=IDLE
2017-12-08 23:27:09.312 [ 12] 9 SpeechSynthesizer:setCurrentStateLocked:state=GAINING_FOCUS
2017-12-08 23:27:09.312 [ 8] 0 SpeechSynthesizer:executeStateChange:newState=PLAYING
2017-12-08 23:27:09.312 [ 8] 9 SpeechSynthesizer:startPlaying
2017-12-08 23:27:09.312 [ 8] 9 MediaPlayer:setSourceCalled:sourceType=AttachmentReader
2017-12-08 23:27:09.312 [ 2] 0 MediaPlayer:handleSetSourceCalled
2017-12-08 23:27:09.312 [ 2] 9 MediaPlayer:tearDownTransientPipelineElements
2017-12-08 23:27:09.313 [ 2] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-08 23:27:09.315 [ 8] 9 MediaPlayer:playCalled
2017-12-08 23:27:09.316 [ 2] 0 MediaPlayer:handlePlayCalled:idPassed=7,currentId=7
terminate called after throwing an instance of 'std::future_error'
what(): Promise already satisfied

Reproduction steps:
Environment:
linux embedded device , sdk v1.3

  1. Start Sample APP
  2. Press t on command line
  3. Ask query
  4. repeat steps 1 to 3 for sevaral times . (10 times)
    Sample app will abort from MediaPlayer handlePlayCalled() API.

Also can be reproduced by simply executing MediaPlayer test

@sanjayrd sanjayrd mentioned this issue Dec 16, 2017
Closed
@sanjayrd
Copy link
Contributor

Hi @dhananjayj29,

Unfortunately, I was unable to reproduce this in my environment. However, it looks the error is coming from here. Could you maybe sprinkle in some log messages in there to see exactly when/where the promise is being set twice? From what I'm seeing in the code, anytime a promise is set, it immediately returns.

Thanks,
Sanjay

@anu-mathur
Copy link

Hi @dhananjayj29
Can we talk more about your use case with the AVS Device SDK? Please fill out this Contact Form and I will get in touch with you!
Thanks

@dhananjayj29
Copy link
Author

Thanks anu-mathur I filled the form.
I will paste the logs

@dhananjayj29
Copy link
Author

I have added the logs in the suggested functions as below:

void MediaPlayer::handlePlay(SourceId id, std::promise* promise) {
ACSDK_DEBUG(LX("handlePlayCalled").d("idPassed", id).d("currentId", (m_currentId)));
if (!validateSourceAndId(id)) {
ACSDK_ERROR(LX("handlePlayFailed"));
promise->set_value(false);
return;
}
ACSDK_DEBUG(LX("handlePlayCalled after validate source and ID \n"));

GstState curState;
auto stateChange = gst_element_get_state(m_pipeline.pipeline, &curState, NULL, TIMEOUT_ZERO_NANOSECONDS);
if (stateChange == GST_STATE_CHANGE_FAILURE) {
    ACSDK_ERROR(LX("handlePlayFailed").d("reason", "gstElementGetStateFailed"));
    promise->set_value(false);
    return;
}
ACSDK_DEBUG(LX("handlePlayCalled after gst_element_get_state\n"));

if (curState == GST_STATE_PLAYING) {
    ACSDK_DEBUG(LX("handlePlayFailed").d("reason", "alreadyPlaying"));
    promise->set_value(false);
    return;
}
ACSDK_DEBUG(LX("handlePlayCalled after GST_STATE_PLAYING\n"));
if (m_playPending) {
    ACSDK_DEBUG(LX("handlePlayFailed").d("reason", "playCurrentlyPending"));
    promise->set_value(false);
    return;
}

ACSDK_DEBUG(LX("handlePlayCalled before set state\n"));
m_playbackFinishedSent = false;
m_playbackStartedSent = false;
m_playPending = true;
m_pauseImmediately = false;
promise->set_value(true);

gboolean attemptBuffering;
g_object_get(m_pipeline.decoder, "use-buffering", &attemptBuffering, NULL);
ACSDK_DEBUG(LX("handlePlay").d("attemptBuffering", attemptBuffering));

GstState startingState = GST_STATE_PLAYING;
if (attemptBuffering) {
    /*
     * Set pipeline to PAUSED state to attempt buffering.
     * The pipeline will be set to PLAY in two ways:
     * i) If buffering is supported, then upon receiving buffer percent = 100.
     * ii) If buffering is not supported, then the pipeline will be set to PLAY immediately.
     */
    startingState = GST_STATE_PAUSED;
}

stateChange = gst_element_set_state(m_pipeline.pipeline, startingState);
ACSDK_DEBUG(LX("handlePlay")
                .d("startingState", gst_element_state_get_name(startingState))
                                                                                                                                                                                       1127,19       74%

Below are the details of crash
out of 10 times system crashed 4 times with below logs:

########################################

2017-12-19 15:14:42.570 [ 3] 1 AlertsCapabilityAgent:executeOnConnectionStatusChanged:status=CONNECTED,reason=ACL_CLIENT_REQUEST
2017-12-19 15:15:16.800 [ 9] 0 AudioInputProcessor:setState:from=IDLE,to=RECOGNIZING
2017-12-19 15:15:16.802 [ 11] 0 DialogUXStateAggregator:setState:from=IDLE,to=LISTENING
2017-12-19 15:15:16.802 [ 6] 0 ContextManager:buildContextSuccessful:context={"context":[{"header":{"namespace":"Speaker","name":"VolumeState"},"payload":{"volume":100,"muted":false}},{"header}
2017-12-19 15:15:16.803 [ 9] 0 AudioInputProcessor:executeOnContextAvailable:jsonContext={"context":[{"header":{"namespace":"Speaker","name":"VolumeState"},"payload":{"volume":100,"muted":false}
2017-12-19 15:15:16.803 [ 9] 1 FocusManager:acquireChannel:channelName=Dialog,activityId=SpeechRecognizer.Recognize
############################

Listening...

############################

2017-12-19 15:15:16.804 [ 12] 9 AudioInputProcessor:onFocusChanged:newFocus=FOREGROUND
2017-12-19 15:15:16.803 [ 9] I DirectiveProcessor:setDialogRequestIdLocked:oldValue=,newValue=2cbaf616-7d1f-4522-a9cf-6364d3399fc9
2017-12-19 15:15:16.804 [ 9] 0 DirectiveProcessor:scrubDialogRequestIdLocked:reason=emptyDialogRequestId
2017-12-19 15:15:16.805 [ 9] 0 EventBuilder:buildJsonEventString:messageId=02cab8a7-e20e-4f35-ae8d-7ae31a2c3333,namespace=SpeechRecognizer,name=Recognize
2017-12-19 15:15:16.805 [ 9] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=FOREGROUND
2017-12-19 15:15:16.805 [ 9] 9 HTTP2Transport:enqueueRequest:jsonContent={"context":[{"header":{"namespace":"Speaker","name":"VolumeState"},"payload":{"volume":100,"muted":false}},{"header":{}
2017-12-19 15:15:16.907 [ 10] 0 HTTP2Transport:processNextOutgoingMessage:jsonContent={"context":[{"header":{"namespace":"Speaker","name":"VolumeState"},"payload":{"volume":100,"muted":false}},}
2017-12-19 15:15:16.907 [ 10] 0 HTTP2StreamPool:getStream:streamId=9,numAcquiredStreams=2
2017-12-19 15:15:16.908 [ 10] 9 HTTP2Transport:insertActiveStream:handle=0xb32b3ad8
2017-12-19 15:15:16.908 [ 10] I HTTP2Stream:libcurl:streamId=9,text=Found bundle for host avs-alexa-eu.amazon.com: 0xb3201910 [can multiplex]
2017-12-19 15:15:16.908 [ 10] I HTTP2Stream:libcurl:streamId=9,text=Conn: 0 (0xb32019b0) Receive pipe weight: (-1/0), penalized: (nil)
2017-12-19 15:15:16.908 [ 10] I HTTP2Stream:libcurl:streamId=9,text=Multiplexed connection found!
2017-12-19 15:15:16.908 [ 10] I HTTP2Stream:libcurl:streamId=9,text=Found connection 0, with requests in the pipe (1)
2017-12-19 15:15:16.908 [ 10] I HTTP2Stream:libcurl:streamId=9,text=Re-using existing connection! (#0) with host avs-alexa-eu.amazon.com
2017-12-19 15:15:16.909 [ 10] I HTTP2Stream:libcurl:streamId=9,text=Using Stream ID: 5 (easy handle 0xb32b3ad8)
2017-12-19 15:15:20.509 [ b] 0 MessageInterpreter:receive:messageId=79ccf874-38b2-4da2-b77a-c7affc317197:No dialogRequestId attached to message.
2017-12-19 15:15:20.509 [ b] I DirectiveSequencer:onDirective:directive={"namespace:"SpeechRecognizer",name:"StopCapture",messageId:"79ccf874-38b2-4da2-b77a-c7affc317197",dialogRequestId:""}
2017-12-19 15:15:20.509 [ c] I DirectiveRouter:preHandleDirective:messageId=79ccf874-38b2-4da2-b77a-c7affc317197,action=calling
2017-12-19 15:15:20.509 [ c] 0 CapabilityAgent:addingMessageIdToMap:messageId=79ccf874-38b2-4da2-b77a-c7affc317197
2017-12-19 15:15:20.510 [ d] I DirectiveRouter:handleDirective:messageId=79ccf874-38b2-4da2-b77a-c7affc317197,action=calling
2017-12-19 15:15:20.510 [ 9] 0 AudioInputProcessor:stopCapture:stopImmediately=true
2017-12-19 15:15:20.510 [ 9] 0 AudioInputProcessor:setState:from=RECOGNIZING,to=BUSY
2017-12-19 15:15:20.510 [ 9] 0 DirectiveProcessor:onHandlingCompeted:messageId=79ccf874-38b2-4da2-b77a-c7affc317197,directiveBeingPreHandled=(nullptr)
2017-12-19 15:15:20.510 [ 9] 0 CapabilityAgent:removingMessageIdFromMap:messageId=79ccf874-38b2-4da2-b77a-c7affc317197
2017-12-19 15:15:20.510 [ 11] 0 DialogUXStateAggregator:setState:from=LISTENING,to=THINKING
###########################

Thinking...

###########################

2017-12-19 15:15:20.527 [ 10] I InProcessAttachmentReader:readFailed:reason=SDS is closed
2017-12-19 15:15:21.209 [ 10] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid: 066737fffe5f62a4-00007f15-0006a7b8-1ac754cedc881332-08e1603b-5
2017-12-19 15:15:21.517 [ b] I DirectiveSequencer:onDirective:directive={"namespace:"SpeechSynthesizer",name:"Speak",messageId:"dbea3066-7e8e-481d-95dd-df4699a03886",dialogRequestId:"2cbaf616-7d1f}
2017-12-19 15:15:21.517 [ c] I DirectiveRouter:preHandleDirective:messageId=dbea3066-7e8e-481d-95dd-df4699a03886,action=calling
2017-12-19 15:15:21.517 [ c] 0 CapabilityAgent:addingMessageIdToMap:messageId=dbea3066-7e8e-481d-95dd-df4699a03886
2017-12-19 15:15:21.518 [ c] 9 SpeechSynthesizer:preHandleDirective:messageId=dbea3066-7e8e-481d-95dd-df4699a03886
2017-12-19 15:15:21.518 [ 8] 0 SpeechSynthesizer:executePreHandle:messageId=dbea3066-7e8e-481d-95dd-df4699a03886
2017-12-19 15:15:21.518 [ d] I DirectiveRouter:handleDirective:messageId=dbea3066-7e8e-481d-95dd-df4699a03886,action=calling
2017-12-19 15:15:21.518 [ d] 9 SpeechSynthesizer:handleDirective:messageId=dbea3066-7e8e-481d-95dd-df4699a03886
2017-12-19 15:15:21.522 [ 8] 0 SpeechSynthesizer:executeHandle:messageId=dbea3066-7e8e-481d-95dd-df4699a03886
2017-12-19 15:15:21.523 [ 8] 1 FocusManager:acquireChannel:channelName=Dialog,activityId=SpeechSynthesizer.Speak
2017-12-19 15:15:21.523 [ 12] 9 AudioInputProcessor:onFocusChanged:newFocus=NONE
2017-12-19 15:15:21.523 [ 12] 0 SpeechSynthesizer:onFocusChanged:newFocus=FOREGROUND
2017-12-19 15:15:21.523 [ 9] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=NONE
2017-12-19 15:15:21.523 [ 12] 9 SpeechSynthesizer:setCurrentStateLocked:state=GAINING_FOCUS
2017-12-19 15:15:21.523 [ 9] 0 AudioInputProcessor:executeOnFocusChanged:reason=Lost focus
2017-12-19 15:15:21.524 [ 9] 0 AudioInputProcessor:setState:from=BUSY,to=IDLE
2017-12-19 15:15:21.524 [ 8] 0 SpeechSynthesizer:executeStateChange:newState=PLAYING
2017-12-19 15:15:21.524 [ 8] 9 SpeechSynthesizer:startPlaying
2017-12-19 15:15:21.524 [ 8] 9 MediaPlayer:setSourceCalled:sourceType=AttachmentReader
2017-12-19 15:15:21.524 [ 2] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 15:15:21.524 [ 2] 9 MediaPlayer:tearDownTransientPipelineElements
2017-12-19 15:15:21.525 [ 2] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 15:15:21.547 [ 8] 9 MediaPlayer:playCalled
2017-12-19 15:15:21.547 [ 2] 0 MediaPlayer:handlePlayCalled:idPassed=1,currentId=1
2017-12-19 15:15:21.547 [ 2] 0 MediaPlayer:handlePlayCalled after validate source and ID

2017-12-19 15:15:21.548 [ 2] 0 MediaPlayer:handlePlayCalled after gst_element_get_state

2017-12-19 15:15:21.548 [ 2] 0 MediaPlayer:handlePlayCalled after GST_STATE_PLAYING

2017-12-19 15:15:21.548 [ 2] 0 MediaPlayer:handlePlayCalled before set state

2 times it crashed with below logs:

:20:22.266 [ 9] 0 AudioInputProcessor:setState:from=IDLE,to=RECOGNIZING
2017-12-19 15:20:22.267 [ 11] 0 DialogUXStateAggregator:setState:from=IDLE,to=LISTENING
2017-12-19 15:20:22.267 [ 6] 0 ContextManager:buildContextSuccessful:context={"context":[{"header":{"namespace":"Speaker","name":"VolumeState"},"payload":{"volume":100,"muted":false}},{"header}
2017-12-19 15:20:22.268 [ 9] 0 AudioInputProcessor:executeOnContextAvailable:jsonContext={"context":[{"header":{"namespace":"Speaker","name":"VolumeState"},"payload":{"volume":100,"muted":false}
2017-12-19 15:20:22.268 [ 9] 1 FocusManager:acquireChannel:channelName=Dialog,activityId=SpeechRecognizer.Recognize
2017-12-19 15:20:22.268 [ 9] I DirectiveProcessor:setDialogRequestIdLocked:oldValue=83e9feb8-3b84-4d6e-95c8-b0c8f615e77e,newValue=c8806c59-e64c-4b87-a0b7-1b5fd104f07b
2017-12-19 15:20:22.268 [ 9] 0 DirectiveProcessor:scrubDialogRequestIdLocked:dialogRequestId=83e9feb8-3b84-4d6e-95c8-b0c8f615e77e
2017-12-19 15:20:22.269 [ 9] 0 EventBuilder:buildJsonEventString:messageId=d8affa2c-7d50-4321-bba1-b79986226e78,namespace=SpeechRecognizer,name=Recognize
2017-12-19 15:20:22.269 [ 12] 9 AudioInputProcessor:onFocusChanged:newFocus=FOREGROUND
2017-12-19 15:20:22.269 [ 9] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=FOREGROUND
2017-12-19 15:20:22.270 [ 9] 9 HTTP2Transport:enqueueRequest:jsonContent={"context":[{"header":{"namespace":"Speaker","name":"VolumeState"},"payload":{"volume":100,"muted":false}},{"header":{}
############################

Listening...

############################

2017-12-19 15:20:22.297 [ 10] 0 HTTP2Transport:processNextOutgoingMessage:jsonContent={"context":[{"header":{"namespace":"Speaker","name":"VolumeState"},"payload":{"volume":100,"muted":false}},}
2017-12-19 15:20:22.638 [ 10] 0 HTTP2StreamPool:getStream:streamId=15,numAcquiredStreams=2
2017-12-19 15:20:22.638 [ 10] 9 HTTP2Transport:insertActiveStream:handle=0xb3ccba58
2017-12-19 15:20:22.639 [ 10] I HTTP2Stream:libcurl:streamId=15,text=Found bundle for host avs-alexa-eu.amazon.com: 0xb3c19ae0 [can multiplex]
2017-12-19 15:20:22.639 [ 10] I HTTP2Stream:libcurl:streamId=15,text=Conn: 0 (0xb3c19418) Receive pipe weight: (-1/0), penalized: (nil)
2017-12-19 15:20:22.639 [ 10] I HTTP2Stream:libcurl:streamId=15,text=Multiplexed connection found!
2017-12-19 15:20:22.639 [ 10] I HTTP2Stream:libcurl:streamId=15,text=Found connection 0, with requests in the pipe (1)
2017-12-19 15:20:22.639 [ 10] I HTTP2Stream:libcurl:streamId=15,text=Re-using existing connection! (#0) with host avs-alexa-eu.amazon.com
2017-12-19 15:20:22.640 [ 10] I HTTP2Stream:libcurl:streamId=15,text=Using Stream ID: b (easy handle 0xb3ccba58)
2017-12-19 15:20:26.700 [ b] 0 MessageInterpreter:receive:messageId=b132def7-81fb-4427-ae7b-207f112b9ce1:No dialogRequestId attached to message.
2017-12-19 15:20:26.700 [ b] I DirectiveSequencer:onDirective:directive={"namespace:"SpeechRecognizer",name:"StopCapture",messageId:"b132def7-81fb-4427-ae7b-207f112b9ce1",dialogRequestId:""}
2017-12-19 15:20:26.700 [ c] I DirectiveRouter:preHandleDirective:messageId=b132def7-81fb-4427-ae7b-207f112b9ce1,action=calling
2017-12-19 15:20:26.700 [ c] 0 CapabilityAgent:addingMessageIdToMap:messageId=b132def7-81fb-4427-ae7b-207f112b9ce1
2017-12-19 15:20:26.701 [ d] I DirectiveRouter:handleDirective:messageId=b132def7-81fb-4427-ae7b-207f112b9ce1,action=calling
2017-12-19 15:20:26.701 [ 9] 0 AudioInputProcessor:stopCapture:stopImmediately=true
2017-12-19 15:20:26.701 [ 9] 0 AudioInputProcessor:setState:from=RECOGNIZING,to=BUSY
2017-12-19 15:20:26.701 [ 9] 0 DirectiveProcessor:onHandlingCompeted:messageId=b132def7-81fb-4427-ae7b-207f112b9ce1,directiveBeingPreHandled=(nullptr)
2017-12-19 15:20:26.701 [ 9] 0 CapabilityAgent:removingMessageIdFromMap:messageId=b132def7-81fb-4427-ae7b-207f112b9ce1
2017-12-19 15:20:26.701 [ 11] 0 DialogUXStateAggregator:setState:from=LISTENING,to=THINKING
###########################

Thinking...

###########################

2017-12-19 15:20:26.718 [ 10] I InProcessAttachmentReader:readFailed:reason=SDS is closed
2017-12-19 15:20:27.401 [ 10] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid: 0248bbfffe45d0a6-0000486d-0006ad24-e108796344105224-c82fe2d2-11
2017-12-19 15:20:27.762 [ b] I DirectiveSequencer:onDirective:directive={"namespace:"SpeechSynthesizer",name:"Speak",messageId:"72fcd302-0f99-4462-b2e2-09b57594d611",dialogRequestId:"c8806c59-e64c}
2017-12-19 15:20:27.763 [ c] I DirectiveRouter:preHandleDirective:messageId=72fcd302-0f99-4462-b2e2-09b57594d611,action=calling
2017-12-19 15:20:27.763 [ c] 0 CapabilityAgent:addingMessageIdToMap:messageId=72fcd302-0f99-4462-b2e2-09b57594d611
2017-12-19 15:20:27.763 [ c] 9 SpeechSynthesizer:preHandleDirective:messageId=72fcd302-0f99-4462-b2e2-09b57594d611
2017-12-19 15:20:27.763 [ 7] 0 SpeechSynthesizer:executePreHandle:messageId=72fcd302-0f99-4462-b2e2-09b57594d611
2017-12-19 15:20:27.763 [ d] I DirectiveRouter:handleDirective:messageId=72fcd302-0f99-4462-b2e2-09b57594d611,action=calling
2017-12-19 15:20:27.763 [ d] 9 SpeechSynthesizer:handleDirective:messageId=72fcd302-0f99-4462-b2e2-09b57594d611
2017-12-19 15:20:27.766 [ 7] 0 SpeechSynthesizer:executeHandle:messageId=72fcd302-0f99-4462-b2e2-09b57594d611
2017-12-19 15:20:27.766 [ 7] 1 FocusManager:acquireChannel:channelName=Dialog,activityId=SpeechSynthesizer.Speak
2017-12-19 15:20:27.766 [ 12] 9 AudioInputProcessor:onFocusChanged:newFocus=NONE
2017-12-19 15:20:27.767 [ 12] 0 SpeechSynthesizer:onFocusChanged:newFocus=FOREGROUND
2017-12-19 15:20:27.767 [ 9] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=NONE
2017-12-19 15:20:27.767 [ 12] 9 SpeechSynthesizer:setCurrentStateLocked:state=GAINING_FOCUS
2017-12-19 15:20:27.767 [ 9] 0 AudioInputProcessor:executeOnFocusChanged:reason=Lost focus
2017-12-19 15:20:27.767 [ 9] 0 AudioInputProcessor:setState:from=BUSY,to=IDLE
2017-12-19 15:20:27.767 [ 7] 0 SpeechSynthesizer:executeStateChange:newState=PLAYING
2017-12-19 15:20:27.767 [ 7] 9 SpeechSynthesizer:startPlaying
2017-12-19 15:20:27.769 [ 7] 9 MediaPlayer:setSourceCalled:sourceType=AttachmentReader
2017-12-19 15:20:27.770 [ 2] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 15:20:27.770 [ 2] 9 MediaPlayer:tearDownTransientPipelineElements
2017-12-19 15:20:27.770 [ 2] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 15:20:27.772 [ 7] 9 MediaPlayer:playCalled
2017-12-19 15:20:27.772 [ 2] 0 MediaPlayer:handlePlayCalled:idPassed=2,currentId=2
2017-12-19 15:20:27.772 [ 2] 0 MediaPlayer:handlePlayCalled after validate source and ID

2017-12-19 15:20:27.773 [ 2] 0 MediaPlayer:handlePlayCalled after gst_element_get_state

2017-12-19 15:20:27.773 [ 2] 0 MediaPlayer:handlePlayCalled after GST_STATE_PLAYING

2017-12-19 15:20:27.773 [ 2] 0 MediaPlayer:handlePlayCalled before set state

2017-12-19 15:20:27.773 [ 2] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 15:20:27.789 [ 2] 9 AttachmentReaderSource:handleSeekData:offset=0
2017-12-19 15:20:27.790 [ 2] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 15:20:27.790 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:27.790 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:27.790 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:27.790 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:27.790 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:27.790 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:27.790 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:27.791 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:27.791 [ 2] 9 MediaPlayer:State Change:oldState=NULL,newState=READY,pendingState=PLAYING
2017-12-19 15:20:27.791 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:27.791 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:27.791 [ 2] 9 MediaPlayer:messageReceived:messageType=stream-status
2017-12-19 15:20:27.791 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:27.791 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:27.791 [ 2] 9 MediaPlayer:messageReceived:messageType=stream-status
2017-12-19 15:20:27.791 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:27.792 [ 2] 9 MediaPlayer:messageReceived:messageType=stream-status
2017-12-19 15:20:28.132 [ 2] 9 MediaPlayer:messageReceived:messageType=stream-status
2017-12-19 15:20:27.792 [ 14] 9 BaseStreamSource:onNeedDataCalled:size=4096
2017-12-19 15:20:28.132 [ 2] 9 BaseStreamSource:handleNeedDataCalled
2017-12-19 15:20:28.133 [ 2] 9 BaseStreamSource:installOnReadDataHandler:action=newSourceId,sourceId=19
2017-12-19 15:20:28.133 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-12-19 15:20:28.133 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-12-19 15:20:28.133 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-12-19 15:20:28.133 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-12-19 15:20:28.133 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-12-19 15:20:28.133 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-12-19 15:20:28.133 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-12-19 15:20:28.134 [ 2] 9 AttachmentReaderSource:read:size=3187,status=0
2017-12-19 15:20:28.151 [ 14] 9 MediaPlayer:onPadAddedCalled
2017-12-19 15:20:28.373 [ 10] 0 AudioInputProcessor:onSendCompleted:status=SUCCESS
2017-12-19 15:20:28.374 [ 10] 0 HTTP2Transport:cleanupFinishedStream:streamId=15,result=200
2017-12-19 15:20:28.374 [ 10] 0 HTTP2StreamPool:releaseStream:streamId=15,numAcquiredStreams=1
2017-12-19 15:20:28.374 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-12-19 15:20:28.374 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:28.374 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:28.374 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:28.375 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:28.375 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:28.375 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:28.375 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-12-19 15:20:28.375 [ 2] 9 MediaPlayer:handlePadAddedSignalCalled
2017-12-19 15:20:28.404 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:28.404 [ 2] 9 MediaPlayer:messageReceived:messageType=stream-start
2017-12-19 15:20:28.404 [ 2] 9 AttachmentReaderSource:read:size=3914,status=0
2017-12-19 15:20:28.404 [ 2] I InProcessAttachmentReader:readFailed:reason=SDS is closed
2017-12-19 15:20:28.404 [ 2] 9 AttachmentReaderSource:read:size=0,status=3
2017-12-19 15:20:28.404 [ 2] 9 AttachmentReaderSource:handleReadData:info=signalingEndOfData
2017-12-19 15:20:28.404 [ 2] 9 BaseStreamSource:signalEndOfDataCalled
2017-12-19 15:20:28.404 [ 2] 9 BaseStreamSource:gstAppSrcEndOfStreamSuccess
2017-12-19 15:20:28.406 [ 2] 9 BaseStreamSource:clearOnReadDataHandlerCalled:sourceId=19
2017-12-19 15:20:28.443 [ 2] 9 MediaPlayer:messageReceived:messageType=latency
2017-12-19 15:20:28.445 [ 2] 9 MediaPlayer:messageReceived:messageType=tag
2017-12-19 15:20:28.445 [ 2] 0 MediaPlayer:callingOnTags
2017-12-19 15:20:28.446 [ 2] 9 MediaPlayer:messageReceived:messageType=tag
2017-12-19 15:20:28.446 [ 2] 0 MediaPlayer:callingOnTags
2017-12-19 15:20:28.446 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:28.446 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:28.446 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:28.446 [ 2] 9 MediaPlayer:State Change:oldState=READY,newState=PAUSED,pendingState=PLAYING
2017-12-19 15:20:28.446 [ 2] 9 MediaPlayer:messageReceived:messageType=async-done
2017-12-19 15:20:28.446 [ 2] 9 MediaPlayer:messageReceived:messageType=new-clock
2017-12-19 15:20:28.447 [ 2] 9 MediaPlayer:messageReceived:messageType=stream-status
2017-12-19 15:20:28.449 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:28.449 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:28.449 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:28.449 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:28.449 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:28.449 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:28.449 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:28.450 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:28.450 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:28.450 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:28.450 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:28.450 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:20:28.450 [ 2] 9 MediaPlayer:State Change:oldState=PAUSED,newState=PLAYING,pendingState=VOID_PENDING
2017-12-19 15:20:28.450 [ 2] 0 MediaPlayer:callingOnPlaybackStarted:currentId=2
2017-12-19 15:20:28.450 [ 2] 9 SpeechSynthesizer:onPlaybackStarted:callbackSourceId=2
2017-12-19 15:20:28.450 [ 7] 0 SpeechSynthesizer:executePlaybackStarted
2017-12-19 15:20:28.450 [ 7] 9 SpeechSynthesizer:setCurrentStateLocked:state=PLAYING
2017-12-19 15:20:28.450 [ 7] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0
2017-12-19 15:20:28.451 [ 7] 9 MediaPlayer:getOffsetCalled
2017-12-19 15:20:28.451 [ 2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=2,currentId=2
2017-12-19 15:20:28.451 [ 7] 0 ContextManager:updateStateLocked:action=updatedState,state={"token":"amzn1.as-ct.v1.Domain:Application:Knowledge#ACRI#2af004b9-c075-4724-99e0-fc03f36e12f4#Alexa3P:1.0/2e
2017-12-19 15:20:28.451 [ 12] 9 SpeechSynthesizer:onFocusChangedSuccess
2017-12-19 15:20:28.452 [ 7] 0 EventBuilder:buildJsonEventString:messageId=80830356-acee-4911-b873-a5d1f978a41f,namespace=SpeechSynthesizer,name=SpeechStarted
2017-12-19 15:20:28.792 [ 7] 9 HTTP2Transport:enqueueRequest:jsonContent={"event":{"header":{"namespace":"SpeechSynthesizer","name":"SpeechStarted","messageId":"80830356-acee-4911-b873-a5d1f978a41}
2017-12-19 15:20:28.452 [ 11] 0 DialogUXStateAggregator:setState:from=THINKING,to=SPEAKING
2017-12-19 15:20:28.454 [ 2] 9 MediaPlayer:messageReceived:messageType=tag
###########################

and single time it stuck with below logs:

17-12-19 15:23:05.767 [ c] 9 SpeechSynthesizer:preHandleDirective:messageId=10439ed8-cb51-42dc-852b-0983d033a224
2017-12-19 15:23:05.767 [ d] I DirectiveRouter:handleDirective:messageId=10439ed8-cb51-42dc-852b-0983d033a224,action=calling
2017-12-19 15:23:05.768 [ d] 9 SpeechSynthesizer:handleDirective:messageId=10439ed8-cb51-42dc-852b-0983d033a224
2017-12-19 15:23:05.768 [ 8] 0 SpeechSynthesizer:executePreHandle:messageId=10439ed8-cb51-42dc-852b-0983d033a224
2017-12-19 15:23:05.771 [ 8] 0 SpeechSynthesizer:executeHandle:messageId=10439ed8-cb51-42dc-852b-0983d033a224
2017-12-19 15:23:05.771 [ 8] 1 FocusManager:acquireChannel:channelName=Dialog,activityId=SpeechSynthesizer.Speak
2017-12-19 15:23:05.772 [ 12] 9 AudioInputProcessor:onFocusChanged:newFocus=NONE
2017-12-19 15:23:05.772 [ 12] 0 SpeechSynthesizer:onFocusChanged:newFocus=FOREGROUND
2017-12-19 15:23:05.772 [ 12] 9 SpeechSynthesizer:setCurrentStateLocked:state=GAINING_FOCUS
2017-12-19 15:23:05.772 [ 9] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=NONE
2017-12-19 15:23:05.772 [ 9] 0 AudioInputProcessor:executeOnFocusChanged:reason=Lost focus
2017-12-19 15:23:05.772 [ 9] 0 AudioInputProcessor:setState:from=BUSY,to=IDLE
2017-12-19 15:23:05.772 [ 8] 0 SpeechSynthesizer:executeStateChange:newState=PLAYING
2017-12-19 15:23:05.772 [ 8] 9 SpeechSynthesizer:startPlaying
2017-12-19 15:23:05.772 [ 8] 9 MediaPlayer:setSourceCalled:sourceType=AttachmentReader
2017-12-19 15:23:05.773 [ 2] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 15:23:05.773 [ 2] 9 MediaPlayer:tearDownTransientPipelineElements
2017-12-19 15:23:05.773 [ 2] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 15:23:05.775 [ 8] 9 MediaPlayer:playCalled
2017-12-19 15:23:05.776 [ 2] 0 MediaPlayer:handlePlayCalled:idPassed=2,currentId=2
2017-12-19 15:23:05.776 [ 2] 0 MediaPlayer:handlePlayCalled after validate source and ID

2017-12-19 15:23:05.776 [ 2] 0 MediaPlayer:handlePlayCalled after gst_element_get_state

2017-12-19 15:23:05.776 [ 2] 0 MediaPlayer:handlePlayCalled after GST_STATE_PLAYING

2017-12-19 15:23:05.776 [ 2] 0 MediaPlayer:handlePlayCalled before set state

2017-12-19 15:23:05.776 [ 2] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 15:23:05.796 [ 2] 9 AttachmentReaderSource:handleSeekData:offset=0
2017-12-19 15:23:05.796 [ 2] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 15:23:05.796 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:23:05.797 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:23:05.797 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:23:05.797 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:23:05.797 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:23:05.797 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:23:05.797 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:23:05.797 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:23:05.797 [ 2] 9 MediaPlayer:State Change:oldState=NULL,newState=READY,pendingState=PLAYING
2017-12-19 15:23:05.797 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:23:05.797 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:23:05.798 [ 2] 9 MediaPlayer:messageReceived:messageType=stream-status
2017-12-19 15:23:05.798 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:23:05.798 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:23:05.798 [ 2] 9 MediaPlayer:messageReceived:messageType=stream-status
2017-12-19 15:23:05.798 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:23:05.798 [ 2] 9 MediaPlayer:messageReceived:messageType=stream-status
2017-12-19 15:23:05.799 [ 2] 9 MediaPlayer:messageReceived:messageType=stream-status
2017-12-19 15:23:05.799 [ 14] 9 BaseStreamSource:onNeedDataCalled:size=4096
2017-12-19 15:23:06.139 [ 2] 9 BaseStreamSource:handleNeedDataCalled
2017-12-19 15:23:06.139 [ 2] 9 BaseStreamSource:installOnReadDataHandler:action=newSourceId,sourceId=19
2017-12-19 15:23:06.139 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-12-19 15:23:06.140 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-12-19 15:23:06.140 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-12-19 15:23:06.140 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-12-19 15:23:06.140 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-12-19 15:23:06.140 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-12-19 15:23:06.140 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-12-19 15:23:06.140 [ 2] 9 AttachmentReaderSource:read:size=3187,status=0
2017-12-19 15:23:06.167 [ 14] 9 MediaPlayer:onPadAddedCalled
2017-12-19 15:23:06.408 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-12-19 15:23:06.409 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:23:06.409 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:23:06.409 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:23:06.409 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:23:06.409 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:23:06.409 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:23:06.409 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-12-19 15:23:06.409 [ 2] 9 MediaPlayer:handlePadAddedSignalCalled
2017-12-19 15:23:06.448 [ 2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-12-19 15:23:06.448 [ 2] 9 MediaPlayer:messageReceived:messageType=stream-start
2017-12-19 15:23:06.448 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-12-19 15:23:06.448 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-12-19 15:23:06.630 [ f] 0 AudioInputProcessor:onSendCompleted:status=SUCCESS
2017-12-19 15:23:06.630 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-12-19 15:23:06.630 [ 2] 9 MediaPlayer:messageReceived:messageType=latency
2017-12-19 15:23:06.630 [ 2] 9 MediaPlayer:messageReceived:messageType=tag
2017-12-19 15:23:06.631 [ 2] 0 MediaPlayer:callingOnTags
2017-12-19 15:23:06.631 [ 2] 9 MediaPlayer:messageReceived:messageType=tag
2017-12-19 15:23:06.631 [ 2] 0 MediaPlayer:callingOnTags
2017-12-19 15:23:06.632 [ 2] 9 MediaPlayer:messageReceived:messageType=stream-status
2017-12-19 15:23:06.632 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-12-19 15:23:06.633 [ 2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-12-19 15:23:06.633 [ 2] 9 AttachmentReaderSource:read:size=1866,status=0
2017-12-19 15:23:06.633 [ 2] I InProcessAttachmentReader:readFailed:reason=SDS is closed
2017-12-19 15:23:06.633 [ 2] 9 AttachmentReaderSource:read:size=0,status=3
2017-12-19 15:23:06.633 [ 2] 9 AttachmentReaderSource:handleReadData:info=signalingEndOfData
2017-12-19 15:23:06.633 [ 2] 9 BaseStreamSource:signalEndOfDataCalled
2017-12-19 15:23:06.633 [ 2] 9 BaseStreamSource:gstAppSrcEndOfStreamSuccess
2017-12-19 15:23:06.634 [ 2] 9 BaseStreamSource:clearOnReadDataHandlerCalled:sourceId=19
2017-12-19 15:23:06.634 [ f] 0 HTTP2Transport:cleanupFinishedStream:streamId=15,result=200
2017-12-19 15:23:06.634 [ f] 0 HTTP2StreamPool:releaseStream:streamId=15,numAcquiredStreams=1
I have moved to v1.3.0 version and still lots of crashes are seen , pl suggest the solution.

@dhananjayj29
Copy link
Author

Hi
Any updates on this issue ?

@mradulan
Copy link
Contributor

@dhananjayj29 , looking into the issue, do you still see it when your run MediaPlayer tests? or only from the Sample App interaction.

@dhananjayj29
Copy link
Author

Hi mradulan ,
It crashed even with MediaPlayerTest below are the logs:

crash 1:

[==========] Running 35 tests from 1 test case.
[----------] Global test environment set-up.
[----------] 35 tests from MediaPlayerTest
[ RUN ] MediaPlayerTest.testStartPlayWaitForEnd
2017-12-19 12:01:39.925 [ 1] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:01:39.926 [ 1] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:01:39.926 [ 1] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:01:39.944 [ 1] 0 MediaPlayer:handlePlayCalled:idPassed=1,currentId=1
2017-12-19 12:01:39.944 [ 1] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:01:40.022 [ 1] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:01:40.149 [ 1] 0 MediaPlayer:callingOnTags
2017-12-19 12:01:40.150 [ 1] 0 MediaPlayer:callingOnTags
2017-12-19 12:01:40.159 [ 1] 0 MediaPlayer:callingOnPlaybackStarted:currentId=1
2017-12-19 12:01:40.160 [ 1] 0 MediaPlayer:callingOnTags
2017-12-19 12:01:42.848 [ 1] 0 MediaPlayer:callingOnPlaybackFinished:currentId=1
2017-12-19 12:01:42.849 [ 1] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=2688
2017-12-19 12:01:42.860 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testStartPlayWaitForEnd (5356 ms)
[ RUN ] MediaPlayerTest.testStartPlayWaitForEndStartPlayAgain
2017-12-19 12:01:42.866 [ 3] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:01:42.867 [ 3] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:01:42.867 [ 3] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:01:42.870 [ 3] 0 MediaPlayer:handlePlayCalled:idPassed=2,currentId=2
2017-12-19 12:01:42.870 [ 3] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:01:42.885 [ 3] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:01:42.972 [ 3] 0 MediaPlayer:callingOnTags
2017-12-19 12:01:42.972 [ 3] 0 MediaPlayer:callingOnTags
2017-12-19 12:01:42.976 [ 3] 0 MediaPlayer:callingOnPlaybackStarted:currentId=2
2017-12-19 12:01:42.988 [ 3] 0 MediaPlayer:callingOnTags
2017-12-19 12:01:45.668 [ 3] 0 MediaPlayer:callingOnPlaybackFinished:currentId=2
2017-12-19 12:01:45.669 [ 3] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=2688
2017-12-19 12:01:45.690 [ 3] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:01:45.691 [ 3] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:01:45.693 [ 3] 0 MediaPlayer:handlePlayCalled:idPassed=3,currentId=3
2017-12-19 12:01:45.693 [ 3] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:01:45.708 [ 3] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:01:45.790 [ 3] 0 MediaPlayer:callingOnTags
2017-12-19 12:01:45.790 [ 3] 0 MediaPlayer:callingOnTags
2017-12-19 12:01:45.791 [ 3] 0 MediaPlayer:callingOnPlaybackStarted:currentId=3
2017-12-19 12:01:45.797 [ 3] 0 MediaPlayer:callingOnTags
2017-12-19 12:01:48.478 [ 3] 0 MediaPlayer:callingOnPlaybackFinished:currentId=3
2017-12-19 12:01:48.479 [ 3] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=2688
2017-12-19 12:01:48.499 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testStartPlayWaitForEndStartPlayAgain (5638 ms)
[ RUN ] MediaPlayerTest.testStopPlay
2017-12-19 12:01:48.506 [ 4] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:01:48.506 [ 4] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:01:48.507 [ 4] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:01:48.510 [ 4] 0 MediaPlayer:handlePlayCalled:idPassed=4,currentId=4
2017-12-19 12:01:48.510 [ 4] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:01:48.526 [ 4] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:01:48.611 [ 4] 0 MediaPlayer:callingOnTags
2017-12-19 12:01:48.612 [ 4] 0 MediaPlayer:callingOnTags
2017-12-19 12:01:48.616 [ 4] 0 MediaPlayer:callingOnPlaybackStarted:currentId=4
2017-12-19 12:01:48.626 [ 4] 0 MediaPlayer:callingOnTags
2017-12-19 12:01:53.639 [ 4] 0 MediaPlayer:handleStopCalled:idPassed=4,currentId=4
2017-12-19 12:01:53.652 [ 4] 0 MediaPlayer:callingOnPlaybackStopped:currentId=4
2017-12-19 12:01:53.653 [ 4] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:01:53.656 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testStopPlay (5157 ms)
[ RUN ] MediaPlayerTest.testStartPlayCallAfterStopPlay
2017-12-19 12:01:53.663 [ 5] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:01:53.663 [ 5] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:01:53.663 [ 5] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:01:53.665 [ 5] 0 MediaPlayer:handlePlayCalled:idPassed=5,currentId=5
2017-12-19 12:01:53.665 [ 5] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:01:53.681 [ 5] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:01:53.762 [ 5] 0 MediaPlayer:callingOnTags
2017-12-19 12:01:53.763 [ 5] 0 MediaPlayer:callingOnTags
2017-12-19 12:01:53.765 [ 5] 0 MediaPlayer:callingOnPlaybackStarted:currentId=5
2017-12-19 12:01:53.769 [ 5] 0 MediaPlayer:callingOnTags
2017-12-19 12:01:55.779 [ 5] 0 MediaPlayer:handleStopCalled:idPassed=5,currentId=5
2017-12-19 12:01:55.801 [ 5] 0 MediaPlayer:callingOnPlaybackStopped:currentId=5
2017-12-19 12:01:55.801 [ 5] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:01:55.802 [ 5] 0 MediaPlayer:handlePlayCalled:idPassed=5,currentId=0
2017-12-19 12:01:55.802 [ 5] E MediaPlayer:validateSourceAndIdFailed:reason=sourceNotSet
2017-12-19 12:01:55.803 [ 5] E MediaPlayer:handlePlayFailed
2017-12-19 12:01:55.805 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testStartPlayCallAfterStopPlay (2149 ms)
[ RUN ] MediaPlayerTest.testStartPlayCallAfterStopPlayDifferentSource
2017-12-19 12:01:55.812 [ 6] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:01:55.812 [ 6] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:01:55.812 [ 6] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:01:55.814 [ 6] 0 MediaPlayer:handlePlayCalled:idPassed=6,currentId=6
2017-12-19 12:01:55.815 [ 6] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:01:55.832 [ 6] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:01:55.916 [ 6] 0 MediaPlayer:callingOnTags
2017-12-19 12:01:55.917 [ 6] 0 MediaPlayer:callingOnTags
2017-12-19 12:01:55.920 [ 6] 0 MediaPlayer:callingOnPlaybackStarted:currentId=6
2017-12-19 12:01:55.925 [ 6] 0 MediaPlayer:callingOnTags
2017-12-19 12:01:56.949 [ 6] 0 MediaPlayer:handleStopCalled:idPassed=6,currentId=6
2017-12-19 12:01:56.970 [ 6] 0 MediaPlayer:callingOnPlaybackStopped:currentId=6
2017-12-19 12:01:56.971 [ 6] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:01:56.972 [ 6] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:01:56.972 [ 6] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:01:56.974 [ 6] 0 MediaPlayer:handlePlayCalled:idPassed=7,currentId=7
2017-12-19 12:01:56.974 [ 6] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:01:56.991 [ 6] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:01:57.072 [ 6] 0 MediaPlayer:callingOnTags
2017-12-19 12:01:57.073 [ 6] 0 MediaPlayer:callingOnTags
2017-12-19 12:01:57.076 [ 6] 0 MediaPlayer:callingOnPlaybackStarted:currentId=7
2017-12-19 12:01:57.089 [ 6] 0 MediaPlayer:callingOnTags
2017-12-19 12:01:58.099 [ 6] 0 MediaPlayer:handleStopCalled:idPassed=7,currentId=7
2017-12-19 12:01:58.115 [ 6] 0 MediaPlayer:callingOnPlaybackStopped:currentId=7
2017-12-19 12:01:58.116 [ 6] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:01:58.119 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testStartPlayCallAfterStopPlayDifferentSource (2314 ms)
[ RUN ] MediaPlayerTest.testPauseDuringPlay
2017-12-19 12:01:58.125 [ 7] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:01:58.126 [ 7] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:01:58.126 [ 7] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:01:58.129 [ 7] 0 MediaPlayer:handlePlayCalled:idPassed=8,currentId=8
2017-12-19 12:01:58.130 [ 7] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:01:58.144 [ 7] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:01:58.225 [ 7] 0 MediaPlayer:callingOnTags
2017-12-19 12:01:58.226 [ 7] 0 MediaPlayer:callingOnTags
2017-12-19 12:01:58.228 [ 7] 0 MediaPlayer:callingOnPlaybackStarted:currentId=8
2017-12-19 12:01:58.242 [ 7] 0 MediaPlayer:callingOnTags
2017-12-19 12:01:59.249 [ 7] 0 MediaPlayer:handlePauseCalled:idPassed=8,currentId=8
2017-12-19 12:01:59.262 [ 7] 0 MediaPlayer:callingOnPlaybackPaused:currentId=8
2017-12-19 12:01:59.273 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testPauseDuringPlay (1154 ms)
[ RUN ] MediaPlayerTest.testResumeAfterPauseThenStop
2017-12-19 12:01:59.282 [ 8] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:01:59.283 [ 8] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:01:59.283 [ 8] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:01:59.285 [ 8] 0 MediaPlayer:handlePlayCalled:idPassed=9,currentId=9
2017-12-19 12:01:59.285 [ 8] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:01:59.301 [ 8] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:01:59.382 [ 8] 0 MediaPlayer:callingOnTags
2017-12-19 12:01:59.382 [ 8] 0 MediaPlayer:callingOnTags
2017-12-19 12:01:59.384 [ 8] 0 MediaPlayer:callingOnPlaybackStarted:currentId=9
2017-12-19 12:01:59.384 [ 8] 0 MediaPlayer:handlePauseCalled:idPassed=9,currentId=9
2017-12-19 12:01:59.386 [ 8] 0 MediaPlayer:callingOnPlaybackPaused:currentId=9
2017-12-19 12:01:59.387 [ 8] 0 MediaPlayer:handleResumeCalled:idPassed=9,currentId=9
2017-12-19 12:01:59.390 [ 8] 0 MediaPlayer:callingOnPlaybackResumed:currentId=9
2017-12-19 12:01:59.400 [ 8] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:02.055 [ 8] 0 MediaPlayer:callingOnPlaybackFinished:currentId=9
2017-12-19 12:02:02.055 [ 8] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=2688
2017-12-19 12:02:02.079 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testResumeAfterPauseThenStop (2806 ms)
[ RUN ] MediaPlayerTest.testStopAfterPause
2017-12-19 12:02:02.087 [ 9] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:02:02.087 [ 9] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:02:02.087 [ 9] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:02.089 [ 9] 0 MediaPlayer:handlePlayCalled:idPassed=10,currentId=10
2017-12-19 12:02:02.089 [ 9] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:02:02.104 [ 9] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:02:02.190 [ 9] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:02.192 [ 9] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:02.193 [ 9] 0 MediaPlayer:callingOnPlaybackStarted:currentId=10
2017-12-19 12:02:02.198 [ 9] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:02.415 [ 9] 0 MediaPlayer:handlePauseCalled:idPassed=10,currentId=10
2017-12-19 12:02:02.422 [ 9] 0 MediaPlayer:callingOnPlaybackPaused:currentId=10
2017-12-19 12:02:02.422 [ 9] 0 MediaPlayer:handleStopCalled:idPassed=10,currentId=10
2017-12-19 12:02:02.430 [ 9] 0 MediaPlayer:callingOnPlaybackStopped:currentId=10
2017-12-19 12:02:02.430 [ 9] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:02.433 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testStopAfterPause (354 ms)
[ RUN ] MediaPlayerTest.testPauseAfterPause
2017-12-19 12:02:02.440 [ a] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:02:02.440 [ a] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:02:02.440 [ a] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:02.442 [ a] 0 MediaPlayer:handlePlayCalled:idPassed=11,currentId=11
2017-12-19 12:02:02.443 [ a] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:02:02.459 [ a] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:02:02.542 [ a] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:02.542 [ a] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:02.546 [ a] 0 MediaPlayer:callingOnPlaybackStarted:currentId=11
2017-12-19 12:02:02.546 [ a] 0 MediaPlayer:handlePauseCalled:idPassed=11,currentId=11
2017-12-19 12:02:02.548 [ a] 0 MediaPlayer:callingOnPlaybackPaused:currentId=11
2017-12-19 12:02:02.548 [ a] 0 MediaPlayer:handlePauseCalled:idPassed=11,currentId=11
2017-12-19 12:02:02.548 [ a] E MediaPlayer:handlePauseFailed:reason=noAudioPlaying
2017-12-19 12:02:02.548 [ a] 0 MediaPlayer:handleStopCalled:idPassed=11,currentId=11
terminate called after throwing an instance of 'std::future_error'
what(): Promise already satisfied
Aborted (core dumped)

crash 2:
[ RUN ] MediaPlayerTest.testStartPlayWaitForEnd
2017-12-19 12:02:28.269 [ 1] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:02:28.270 [ 1] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:02:28.270 [ 1] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:28.284 [ 1] 0 MediaPlayer:handlePlayCalled:idPassed=1,currentId=1
2017-12-19 12:02:28.284 [ 1] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:02:28.363 [ 1] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:02:28.494 [ 1] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:28.494 [ 1] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:28.502 [ 1] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:28.502 [ 1] 0 MediaPlayer:callingOnPlaybackStarted:currentId=1
2017-12-19 12:02:31.195 [ 1] 0 MediaPlayer:callingOnPlaybackFinished:currentId=1
2017-12-19 12:02:31.196 [ 1] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=2688
2017-12-19 12:02:31.217 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testStartPlayWaitForEnd (3084 ms)
[ RUN ] MediaPlayerTest.testStartPlayWaitForEndStartPlayAgain
2017-12-19 12:02:31.223 [ 3] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:02:31.224 [ 3] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:02:31.224 [ 3] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:31.227 [ 3] 0 MediaPlayer:handlePlayCalled:idPassed=2,currentId=2
2017-12-19 12:02:31.227 [ 3] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:02:31.242 [ 3] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:02:31.325 [ 3] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:31.326 [ 3] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:31.327 [ 3] 0 MediaPlayer:callingOnPlaybackStarted:currentId=2
2017-12-19 12:02:31.334 [ 3] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:34.015 [ 3] 0 MediaPlayer:callingOnPlaybackFinished:currentId=2
2017-12-19 12:02:34.016 [ 3] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=2688
2017-12-19 12:02:34.032 [ 3] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:02:34.032 [ 3] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:34.034 [ 3] 0 MediaPlayer:handlePlayCalled:idPassed=3,currentId=3
2017-12-19 12:02:34.034 [ 3] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:02:34.050 [ 3] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:02:34.130 [ 3] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:34.130 [ 3] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:34.134 [ 3] 0 MediaPlayer:callingOnPlaybackStarted:currentId=3
2017-12-19 12:02:34.146 [ 3] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:36.835 [ 3] 0 MediaPlayer:callingOnPlaybackFinished:currentId=3
2017-12-19 12:02:36.835 [ 3] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=2688
2017-12-19 12:02:36.857 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testStartPlayWaitForEndStartPlayAgain (5640 ms)
[ RUN ] MediaPlayerTest.testStopPlay
2017-12-19 12:02:36.863 [ 4] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:02:36.864 [ 4] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:02:36.864 [ 4] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:36.867 [ 4] 0 MediaPlayer:handlePlayCalled:idPassed=4,currentId=4
2017-12-19 12:02:36.867 [ 4] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:02:36.882 [ 4] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:02:36.966 [ 4] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:36.967 [ 4] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:36.969 [ 4] 0 MediaPlayer:callingOnPlaybackStarted:currentId=4
2017-12-19 12:02:36.984 [ 4] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:41.975 [ 4] 0 MediaPlayer:handleStopCalled:idPassed=4,currentId=4
2017-12-19 12:02:41.993 [ 4] 0 MediaPlayer:callingOnPlaybackStopped:currentId=4
2017-12-19 12:02:41.993 [ 4] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:41.997 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testStopPlay (5140 ms)
[ RUN ] MediaPlayerTest.testStartPlayCallAfterStopPlay
2017-12-19 12:02:42.003 [ 5] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:02:42.004 [ 5] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:02:42.005 [ 5] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:42.007 [ 5] 0 MediaPlayer:handlePlayCalled:idPassed=5,currentId=5
2017-12-19 12:02:42.007 [ 5] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:02:42.022 [ 5] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:02:42.102 [ 5] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:42.103 [ 5] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:42.104 [ 5] 0 MediaPlayer:callingOnPlaybackStarted:currentId=5
2017-12-19 12:02:42.113 [ 5] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:44.125 [ 5] 0 MediaPlayer:handleStopCalled:idPassed=5,currentId=5
2017-12-19 12:02:44.139 [ 5] 0 MediaPlayer:callingOnPlaybackStopped:currentId=5
2017-12-19 12:02:44.140 [ 5] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:44.141 [ 5] 0 MediaPlayer:handlePlayCalled:idPassed=5,currentId=0
2017-12-19 12:02:44.141 [ 5] E MediaPlayer:validateSourceAndIdFailed:reason=sourceNotSet
2017-12-19 12:02:44.141 [ 5] E MediaPlayer:handlePlayFailed
2017-12-19 12:02:44.143 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testStartPlayCallAfterStopPlay (2146 ms)
[ RUN ] MediaPlayerTest.testStartPlayCallAfterStopPlayDifferentSource
2017-12-19 12:02:44.150 [ 6] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:02:44.150 [ 6] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:02:44.151 [ 6] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:44.153 [ 6] 0 MediaPlayer:handlePlayCalled:idPassed=6,currentId=6
2017-12-19 12:02:44.153 [ 6] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:02:44.170 [ 6] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:02:44.256 [ 6] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:44.256 [ 6] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:44.259 [ 6] 0 MediaPlayer:callingOnPlaybackStarted:currentId=6
2017-12-19 12:02:44.266 [ 6] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:45.275 [ 6] 0 MediaPlayer:handleStopCalled:idPassed=6,currentId=6
2017-12-19 12:02:45.292 [ 6] 0 MediaPlayer:callingOnPlaybackStopped:currentId=6
2017-12-19 12:02:45.292 [ 6] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:45.294 [ 6] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:02:45.294 [ 6] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:45.297 [ 6] 0 MediaPlayer:handlePlayCalled:idPassed=7,currentId=7
2017-12-19 12:02:45.297 [ 6] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:02:45.311 [ 6] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:02:45.397 [ 6] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:45.398 [ 6] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:45.401 [ 6] 0 MediaPlayer:callingOnPlaybackStarted:currentId=7
2017-12-19 12:02:45.407 [ 6] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:46.415 [ 6] 0 MediaPlayer:handleStopCalled:idPassed=7,currentId=7
2017-12-19 12:02:46.436 [ 6] 0 MediaPlayer:callingOnPlaybackStopped:currentId=7
2017-12-19 12:02:46.436 [ 6] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:46.439 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testStartPlayCallAfterStopPlayDifferentSource (2296 ms)
[ RUN ] MediaPlayerTest.testPauseDuringPlay
2017-12-19 12:02:46.446 [ 7] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:02:46.446 [ 7] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:02:46.446 [ 7] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:46.448 [ 7] 0 MediaPlayer:handlePlayCalled:idPassed=8,currentId=8
2017-12-19 12:02:46.449 [ 7] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:02:46.464 [ 7] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:02:46.545 [ 7] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:46.546 [ 7] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:46.547 [ 7] 0 MediaPlayer:callingOnPlaybackStarted:currentId=8
2017-12-19 12:02:46.552 [ 7] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:47.565 [ 7] 0 MediaPlayer:handlePauseCalled:idPassed=8,currentId=8
2017-12-19 12:02:47.581 [ 7] 0 MediaPlayer:callingOnPlaybackPaused:currentId=8
2017-12-19 12:02:47.592 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testPauseDuringPlay (1153 ms)
[ RUN ] MediaPlayerTest.testResumeAfterPauseThenStop
2017-12-19 12:02:47.599 [ 8] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:02:47.600 [ 8] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:02:47.600 [ 8] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:47.602 [ 8] 0 MediaPlayer:handlePlayCalled:idPassed=9,currentId=9
2017-12-19 12:02:47.602 [ 8] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:02:47.618 [ 8] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:02:47.702 [ 8] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:47.702 [ 8] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:47.704 [ 8] 0 MediaPlayer:callingOnPlaybackStarted:currentId=9
2017-12-19 12:02:47.706 [ 8] 0 MediaPlayer:handlePauseCalled:idPassed=9,currentId=9
2017-12-19 12:02:47.708 [ 8] 0 MediaPlayer:callingOnPlaybackPaused:currentId=9
2017-12-19 12:02:47.708 [ 8] 0 MediaPlayer:handleResumeCalled:idPassed=9,currentId=9
2017-12-19 12:02:47.711 [ 8] 0 MediaPlayer:callingOnPlaybackResumed:currentId=9
2017-12-19 12:02:47.717 [ 8] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:50.395 [ 8] 0 MediaPlayer:callingOnPlaybackFinished:currentId=9
2017-12-19 12:02:50.396 [ 8] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=2688
2017-12-19 12:02:50.408 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testResumeAfterPauseThenStop (2816 ms)
[ RUN ] MediaPlayerTest.testStopAfterPause
2017-12-19 12:02:50.416 [ 9] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:02:50.416 [ 9] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:02:50.417 [ 9] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:50.419 [ 9] 0 MediaPlayer:handlePlayCalled:idPassed=10,currentId=10
2017-12-19 12:02:50.419 [ 9] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:02:50.437 [ 9] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:02:50.517 [ 9] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:50.518 [ 9] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:50.520 [ 9] 0 MediaPlayer:callingOnPlaybackStarted:currentId=10
2017-12-19 12:02:50.536 [ 9] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:50.745 [ 9] 0 MediaPlayer:handlePauseCalled:idPassed=10,currentId=10
2017-12-19 12:02:50.753 [ 9] 0 MediaPlayer:callingOnPlaybackPaused:currentId=10
2017-12-19 12:02:50.753 [ 9] 0 MediaPlayer:handleStopCalled:idPassed=10,currentId=10
2017-12-19 12:02:50.761 [ 9] 0 MediaPlayer:callingOnPlaybackStopped:currentId=10
2017-12-19 12:02:50.762 [ 9] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:50.767 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testStopAfterPause (359 ms)
[ RUN ] MediaPlayerTest.testPauseAfterPause
2017-12-19 12:02:50.773 [ a] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:02:50.773 [ a] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:02:50.774 [ a] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:50.776 [ a] 0 MediaPlayer:handlePlayCalled:idPassed=11,currentId=11
2017-12-19 12:02:50.777 [ a] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:02:50.792 [ a] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:02:50.877 [ a] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:50.877 [ a] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:50.880 [ a] 0 MediaPlayer:callingOnPlaybackStarted:currentId=11
2017-12-19 12:02:50.880 [ a] 0 MediaPlayer:handlePauseCalled:idPassed=11,currentId=11
2017-12-19 12:02:50.882 [ a] 0 MediaPlayer:callingOnPlaybackPaused:currentId=11
2017-12-19 12:02:50.882 [ a] 0 MediaPlayer:handlePauseCalled:idPassed=11,currentId=11
2017-12-19 12:02:50.882 [ a] E MediaPlayer:handlePauseFailed:reason=noAudioPlaying
2017-12-19 12:02:50.883 [ a] 0 MediaPlayer:handleStopCalled:idPassed=11,currentId=11
2017-12-19 12:02:50.892 [ a] 0 MediaPlayer:callingOnPlaybackStopped:currentId=11
2017-12-19 12:02:50.892 [ a] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:50.895 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testPauseAfterPause (128 ms)
[ RUN ] MediaPlayerTest.testResumeAfterPlay
2017-12-19 12:02:50.901 [ b] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:02:50.902 [ b] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:02:50.902 [ b] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:50.904 [ b] 0 MediaPlayer:handlePlayCalled:idPassed=12,currentId=12
2017-12-19 12:02:50.904 [ b] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:02:50.923 [ b] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:02:51.003 [ b] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:51.003 [ b] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:51.014 [ b] 0 MediaPlayer:callingOnPlaybackStarted:currentId=12
2017-12-19 12:02:51.015 [ b] 0 MediaPlayer:handleResumeCalled:idPassed=12,currentId=12
2017-12-19 12:02:51.015 [ b] E MediaPlayer:handleResumeFailed:reason=alreadyPlaying
2017-12-19 12:02:51.016 [ b] 0 MediaPlayer:handleStopCalled:idPassed=12,currentId=12
2017-12-19 12:02:51.026 [ b] 0 MediaPlayer:callingOnPlaybackStopped:currentId=12
2017-12-19 12:02:51.027 [ b] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:51.030 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testResumeAfterPlay (135 ms)
[ RUN ] MediaPlayerTest.testGetOffsetInMilliseconds
2017-12-19 12:02:51.037 [ c] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:02:51.038 [ c] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:02:51.038 [ c] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:51.040 [ c] 0 MediaPlayer:handlePlayCalled:idPassed=13,currentId=13
2017-12-19 12:02:51.040 [ c] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:02:51.057 [ c] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:02:51.140 [ c] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:51.140 [ c] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:51.142 [ c] 0 MediaPlayer:callingOnPlaybackStarted:currentId=13
2017-12-19 12:02:51.148 [ c] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:52.155 [ c] 0 MediaPlayer:handleGetOffsetCalled:idPassed=13,currentId=13
2017-12-19 12:02:52.156 [ c] 0 MediaPlayer:handleStopCalled:idPassed=13,currentId=13
2017-12-19 12:02:52.180 [ c] 0 MediaPlayer:callingOnPlaybackStopped:currentId=13
2017-12-19 12:02:52.181 [ c] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:52.182 [ c] 0 MediaPlayer:handleGetOffsetCalled:idPassed=13,currentId=0
2017-12-19 12:02:52.182 [ c] E MediaPlayer:validateSourceAndIdFailed:reason=sourceNotSet
2017-12-19 12:02:52.184 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testGetOffsetInMilliseconds (1154 ms)
[ RUN ] MediaPlayerTest.testGetOffsetInMillisecondsNullPipeline
2017-12-19 12:02:52.191 [ d] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:02:52.191 [ d] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:02:52.192 [ d] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:52.193 [ d] 0 MediaPlayer:handleGetOffsetCalled:idPassed=15,currentId=14
2017-12-19 12:02:52.194 [ d] E MediaPlayer:validateSourceAndIdFailed:reason=sourceIdMismatch
2017-12-19 12:02:52.197 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testGetOffsetInMillisecondsNullPipeline (13 ms)
[ RUN ] MediaPlayerTest.testGetOffsetWhenStoppedFails
2017-12-19 12:02:52.203 [ e] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:02:52.203 [ e] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:02:52.203 [ e] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:52.205 [ e] 0 MediaPlayer:handlePlayCalled:idPassed=15,currentId=15
2017-12-19 12:02:52.206 [ e] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:02:52.221 [ e] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:02:52.303 [ e] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:52.303 [ e] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:52.307 [ e] 0 MediaPlayer:callingOnPlaybackStarted:currentId=15
2017-12-19 12:02:52.313 [ e] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:53.315 [ e] 0 MediaPlayer:handleStopCalled:idPassed=15,currentId=15
2017-12-19 12:02:53.330 [ e] 0 MediaPlayer:callingOnPlaybackStopped:currentId=15
2017-12-19 12:02:53.330 [ e] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:53.331 [ e] 0 MediaPlayer:handleGetOffsetCalled:idPassed=15,currentId=0
2017-12-19 12:02:53.331 [ e] E MediaPlayer:validateSourceAndIdFailed:reason=sourceNotSet
2017-12-19 12:02:53.333 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testGetOffsetWhenStoppedFails (1136 ms)
[ RUN ] MediaPlayerTest.testGetOffsetWhenPaused
2017-12-19 12:02:53.340 [ f] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:02:53.340 [ f] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:02:53.341 [ f] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:53.343 [ f] 0 MediaPlayer:handlePlayCalled:idPassed=16,currentId=16
2017-12-19 12:02:53.343 [ f] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:02:53.359 [ f] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:02:53.442 [ f] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:53.442 [ f] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:53.444 [ f] 0 MediaPlayer:callingOnPlaybackStarted:currentId=16
2017-12-19 12:02:53.456 [ f] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:54.455 [ f] 0 MediaPlayer:handlePauseCalled:idPassed=16,currentId=16
2017-12-19 12:02:54.459 [ f] 0 MediaPlayer:callingOnPlaybackPaused:currentId=16
2017-12-19 12:02:54.459 [ f] 0 MediaPlayer:handleGetOffsetCalled:idPassed=16,currentId=16
2017-12-19 12:02:54.470 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testGetOffsetWhenPaused (1137 ms)
[ RUN ] MediaPlayerTest.testPlayingTwoAttachments
2017-12-19 12:02:54.477 [ 10] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:02:54.477 [ 10] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:02:54.478 [ 10] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:54.480 [ 10] 0 MediaPlayer:handlePlayCalled:idPassed=17,currentId=17
2017-12-19 12:02:54.480 [ 10] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:02:54.497 [ 10] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:02:54.581 [ 10] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:54.581 [ 10] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:54.584 [ 10] 0 MediaPlayer:callingOnPlaybackStarted:currentId=17
2017-12-19 12:02:54.592 [ 10] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:55.595 [ 10] 0 MediaPlayer:handleGetOffsetCalled:idPassed=17,currentId=17
2017-12-19 12:02:57.275 [ 10] 0 MediaPlayer:callingOnPlaybackFinished:currentId=17
2017-12-19 12:02:57.275 [ 10] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=2688
2017-12-19 12:02:57.300 [ 10] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:02:57.301 [ 10] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:57.303 [ 10] 0 MediaPlayer:handlePlayCalled:idPassed=18,currentId=18
2017-12-19 12:02:57.303 [ 10] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:02:57.319 [ 10] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:02:57.403 [ 10] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:57.403 [ 10] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:57.415 [ 10] 0 MediaPlayer:callingOnPlaybackStarted:currentId=18
2017-12-19 12:02:57.417 [ 10] 0 MediaPlayer:callingOnTags
2017-12-19 12:02:58.425 [ 10] 0 MediaPlayer:handleGetOffsetCalled:idPassed=18,currentId=18
2017-12-19 12:02:58.426 [ 10] 0 MediaPlayer:handleStopCalled:idPassed=18,currentId=18
2017-12-19 12:02:58.443 [ 10] 0 MediaPlayer:callingOnPlaybackStopped:currentId=18
2017-12-19 12:02:58.443 [ 10] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:58.446 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testPlayingTwoAttachments (3976 ms)
[ RUN ] MediaPlayerTest.testUnsteadyReads
2017-12-19 12:02:58.453 [ 11] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:02:58.453 [ 11] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:02:58.453 [ 11] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:02:58.456 [ 11] 0 MediaPlayer:handlePlayCalled:idPassed=19,currentId=19
2017-12-19 12:02:58.456 [ 11] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:02:58.471 [ 11] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:03:00.426 [ 11] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:00.427 [ 11] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:00.429 [ 11] 0 MediaPlayer:callingOnPlaybackStarted:currentId=19
2017-12-19 12:03:00.435 [ 11] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:08.501 [ 11] 0 MediaPlayer:callingOnPlaybackFinished:currentId=19
2017-12-19 12:03:08.502 [ 11] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=8064
2017-12-19 12:03:08.528 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testUnsteadyReads (10081 ms)
[ RUN ] MediaPlayerTest.testRecoveryFromPausedReads
2017-12-19 12:03:08.535 [ 12] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:03:08.535 [ 12] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:03:08.536 [ 12] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:03:08.537 [ 12] 0 MediaPlayer:handlePlayCalled:idPassed=20,currentId=20
2017-12-19 12:03:08.538 [ 12] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:03:08.555 [ 12] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:03:10.613 [ 12] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:10.614 [ 12] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:10.616 [ 12] 0 MediaPlayer:callingOnPlaybackStarted:currentId=20
2017-12-19 12:03:10.624 [ 12] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:20.761 [ 12] 0 MediaPlayer:callingOnPlaybackFinished:currentId=20
2017-12-19 12:03:20.762 [ 12] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=8064
2017-12-19 12:03:20.788 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testRecoveryFromPausedReads (12259 ms)
[ RUN ] MediaPlayerTest.testRepeatAttachment
2017-12-19 12:03:20.800 [ 13] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:03:20.802 [ 13] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:03:20.802 [ 13] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:03:20.804 [ 13] 0 MediaPlayer:handlePlayCalled:idPassed=21,currentId=21
2017-12-19 12:03:20.805 [ 13] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:03:20.826 [ 13] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:03:20.922 [ 13] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:20.922 [ 13] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:20.924 [ 13] 0 MediaPlayer:callingOnPlaybackStarted:currentId=21
2017-12-19 12:03:20.929 [ 13] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:23.611 [ 13] 0 MediaPlayer:callingOnPlaybackFinished:currentId=21
2017-12-19 12:03:23.611 [ 13] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=2688
2017-12-19 12:03:23.629 [ 13] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:03:23.629 [ 13] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:03:23.632 [ 13] 0 MediaPlayer:handlePlayCalled:idPassed=22,currentId=22
2017-12-19 12:03:23.633 [ 13] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:03:23.648 [ 13] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:03:23.729 [ 13] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:23.730 [ 13] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:23.734 [ 13] 0 MediaPlayer:callingOnPlaybackStarted:currentId=22
2017-12-19 12:03:23.742 [ 13] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:26.411 [ 13] 0 MediaPlayer:callingOnPlaybackFinished:currentId=22
2017-12-19 12:03:26.412 [ 13] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=2688
2017-12-19 12:03:26.438 [ 13] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:03:26.438 [ 13] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:03:26.440 [ 13] 0 MediaPlayer:handlePlayCalled:idPassed=23,currentId=23
2017-12-19 12:03:26.440 [ 13] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:03:26.457 [ 13] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:03:26.539 [ 13] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:26.540 [ 13] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:26.544 [ 13] 0 MediaPlayer:callingOnPlaybackStarted:currentId=23
2017-12-19 12:03:26.548 [ 13] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:29.221 [ 13] 0 MediaPlayer:callingOnPlaybackFinished:currentId=23
2017-12-19 12:03:29.222 [ 13] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=2688
2017-12-19 12:03:29.246 [ 13] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:03:29.247 [ 13] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:03:29.249 [ 13] 0 MediaPlayer:handlePlayCalled:idPassed=24,currentId=24
2017-12-19 12:03:29.249 [ 13] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:03:29.268 [ 13] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:03:29.350 [ 13] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:29.350 [ 13] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:29.353 [ 13] 0 MediaPlayer:callingOnPlaybackStarted:currentId=24
2017-12-19 12:03:29.362 [ 13] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:32.031 [ 13] 0 MediaPlayer:callingOnPlaybackFinished:currentId=24
2017-12-19 12:03:32.031 [ 13] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=2688
2017-12-19 12:03:32.053 [ 13] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:03:32.053 [ 13] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:03:32.055 [ 13] 0 MediaPlayer:handlePlayCalled:idPassed=25,currentId=25
2017-12-19 12:03:32.056 [ 13] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:03:32.073 [ 13] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:03:32.155 [ 13] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:32.155 [ 13] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:32.157 [ 13] 0 MediaPlayer:callingOnPlaybackStarted:currentId=25
2017-12-19 12:03:32.163 [ 13] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:34.841 [ 13] 0 MediaPlayer:callingOnPlaybackFinished:currentId=25
2017-12-19 12:03:34.842 [ 13] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=2688
2017-12-19 12:03:34.860 [ 13] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:03:34.860 [ 13] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:03:34.863 [ 13] 0 MediaPlayer:handlePlayCalled:idPassed=26,currentId=26
2017-12-19 12:03:34.863 [ 13] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:03:34.880 [ 13] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:03:34.962 [ 13] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:34.962 [ 13] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:34.965 [ 13] 0 MediaPlayer:callingOnPlaybackStarted:currentId=26
2017-12-19 12:03:34.972 [ 13] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:37.661 [ 13] 0 MediaPlayer:callingOnPlaybackFinished:currentId=26
2017-12-19 12:03:37.661 [ 13] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=2688
2017-12-19 12:03:37.686 [ 13] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:03:37.686 [ 13] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:03:37.688 [ 13] 0 MediaPlayer:handlePlayCalled:idPassed=27,currentId=27
2017-12-19 12:03:37.688 [ 13] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:03:37.704 [ 13] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:03:37.786 [ 13] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:37.787 [ 13] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:37.790 [ 13] 0 MediaPlayer:callingOnPlaybackStarted:currentId=27
2017-12-19 12:03:37.794 [ 13] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:40.471 [ 13] 0 MediaPlayer:callingOnPlaybackFinished:currentId=27
2017-12-19 12:03:40.471 [ 13] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=2688
2017-12-19 12:03:40.493 [ 13] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:03:40.493 [ 13] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:03:40.495 [ 13] 0 MediaPlayer:handlePlayCalled:idPassed=28,currentId=28
2017-12-19 12:03:40.496 [ 13] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:03:40.510 [ 13] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:03:40.602 [ 13] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:40.603 [ 13] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:40.611 [ 13] 0 MediaPlayer:callingOnPlaybackStarted:currentId=28
2017-12-19 12:03:40.622 [ 13] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:43.291 [ 13] 0 MediaPlayer:callingOnPlaybackFinished:currentId=28
2017-12-19 12:03:43.292 [ 13] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=2688
2017-12-19 12:03:43.316 [ 13] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:03:43.316 [ 13] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:03:43.318 [ 13] 0 MediaPlayer:handlePlayCalled:idPassed=29,currentId=29
2017-12-19 12:03:43.319 [ 13] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:03:43.336 [ 13] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:03:43.419 [ 13] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:43.420 [ 13] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:43.424 [ 13] 0 MediaPlayer:callingOnPlaybackStarted:currentId=29
2017-12-19 12:03:43.431 [ 13] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:46.101 [ 13] 0 MediaPlayer:callingOnPlaybackFinished:currentId=29
2017-12-19 12:03:46.101 [ 13] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=2688
2017-12-19 12:03:46.124 [ 13] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:03:46.124 [ 13] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:03:46.126 [ 13] 0 MediaPlayer:handlePlayCalled:idPassed=30,currentId=30
2017-12-19 12:03:46.126 [ 13] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:03:46.143 [ 13] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:03:46.225 [ 13] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:46.225 [ 13] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:46.228 [ 13] 0 MediaPlayer:callingOnPlaybackStarted:currentId=30
2017-12-19 12:03:46.242 [ 13] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:48.921 [ 13] 0 MediaPlayer:callingOnPlaybackFinished:currentId=30
2017-12-19 12:03:48.924 [ 13] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=2688
2017-12-19 12:03:48.935 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testRepeatAttachment (28147 ms)
[ RUN ] MediaPlayerTest.testSetVolumePlays
2017-12-19 12:03:48.943 [ 14] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:03:48.943 [ 14] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:03:48.943 [ 14] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:03:48.945 [ 14] 0 MediaPlayer:handlePlayCalled:idPassed=31,currentId=31
2017-12-19 12:03:48.946 [ 14] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:03:48.963 [ 14] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:03:49.043 [ 14] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:49.043 [ 14] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:49.047 [ 14] 0 MediaPlayer:callingOnPlaybackStarted:currentId=31
2017-12-19 12:03:49.062 [ 14] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:50.051 [ 14] 0 MediaPlayer:handlePauseCalled:idPassed=31,currentId=31
2017-12-19 12:03:50.062 [ 14] 0 MediaPlayer:callingOnPlaybackPaused:currentId=31
2017-12-19 12:03:50.063 [ 14] 0 MediaPlayer:handleResumeCalled:idPassed=31,currentId=31
2017-12-19 12:03:50.065 [ 14] 0 MediaPlayer:callingOnPlaybackResumed:currentId=31
2017-12-19 12:03:51.441 [ 14] 0 MediaPlayer:callingOnPlaybackFinished:currentId=31
2017-12-19 12:03:51.441 [ 14] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=2688
2017-12-19 12:03:51.463 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testSetVolumePlays (2528 ms)
[ RUN ] MediaPlayerTest.testAdjustVolumePlaysDuringPlay
2017-12-19 12:03:51.469 [ 15] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:03:51.470 [ 15] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:03:51.470 [ 15] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:03:51.472 [ 15] 0 MediaPlayer:handlePlayCalled:idPassed=32,currentId=32
2017-12-19 12:03:51.472 [ 15] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:03:51.488 [ 15] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:03:51.568 [ 15] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:51.568 [ 15] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:51.570 [ 15] 0 MediaPlayer:callingOnPlaybackStarted:currentId=32
2017-12-19 12:03:51.580 [ 15] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:54.261 [ 15] 0 MediaPlayer:callingOnPlaybackFinished:currentId=32
2017-12-19 12:03:54.261 [ 15] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=2688
2017-12-19 12:03:54.282 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testAdjustVolumePlaysDuringPlay (2820 ms)
[ RUN ] MediaPlayerTest.testAdjustVolumePlays
2017-12-19 12:03:54.289 [ 16] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:03:54.289 [ 16] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:03:54.290 [ 16] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:03:54.292 [ 16] 0 MediaPlayer:handlePlayCalled:idPassed=33,currentId=33
2017-12-19 12:03:54.292 [ 16] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:03:54.308 [ 16] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:03:54.393 [ 16] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:54.393 [ 16] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:54.396 [ 16] 0 MediaPlayer:callingOnPlaybackStarted:currentId=33
2017-12-19 12:03:54.408 [ 16] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:55.401 [ 16] 0 MediaPlayer:handlePauseCalled:idPassed=33,currentId=33
2017-12-19 12:03:55.410 [ 16] 0 MediaPlayer:callingOnPlaybackPaused:currentId=33
2017-12-19 12:03:55.410 [ 16] 0 MediaPlayer:handleResumeCalled:idPassed=33,currentId=33
2017-12-19 12:03:55.413 [ 16] 0 MediaPlayer:callingOnPlaybackResumed:currentId=33
2017-12-19 12:03:56.791 [ 16] 0 MediaPlayer:callingOnPlaybackFinished:currentId=33
2017-12-19 12:03:56.791 [ 16] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=2688
2017-12-19 12:03:56.812 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testAdjustVolumePlays (2529 ms)
[ RUN ] MediaPlayerTest.testAdjustVolumeOutOfBounds
2017-12-19 12:03:56.819 [ 17] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:03:56.820 [ 17] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:03:56.820 [ 17] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:03:56.824 [ 17] 0 MediaPlayer:handlePlayCalled:idPassed=34,currentId=34
2017-12-19 12:03:56.824 [ 17] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:03:56.839 [ 17] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:03:56.923 [ 17] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:56.923 [ 17] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:56.926 [ 17] 0 MediaPlayer:callingOnPlaybackStarted:currentId=34
2017-12-19 12:03:56.944 [ 17] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:57.941 [ 17] 0 MediaPlayer:handlePauseCalled:idPassed=34,currentId=34
2017-12-19 12:03:57.957 [ 17] 0 MediaPlayer:callingOnPlaybackPaused:currentId=34
2017-12-19 12:03:57.958 [ 17] 0 MediaPlayer:handleResumeCalled:idPassed=34,currentId=34
2017-12-19 12:03:57.964 [ 17] 0 MediaPlayer:callingOnPlaybackResumed:currentId=34
2017-12-19 12:03:58.281 [ 17] 0 MediaPlayer:callingOnPlaybackFinished:currentId=34
2017-12-19 12:03:58.282 [ 17] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=2688
2017-12-19 12:03:58.305 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testAdjustVolumeOutOfBounds (1492 ms)
[ RUN ] MediaPlayerTest.testSetMutePlays
2017-12-19 12:03:58.314 [ 18] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:03:58.314 [ 18] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:03:58.315 [ 18] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:03:58.317 [ 18] 0 MediaPlayer:handlePlayCalled:idPassed=35,currentId=35
2017-12-19 12:03:58.318 [ 18] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:03:58.344 [ 18] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:03:58.429 [ 18] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:58.430 [ 18] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:58.434 [ 18] 0 MediaPlayer:callingOnPlaybackStarted:currentId=35
2017-12-19 12:03:58.442 [ 18] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:59.451 [ 18] 0 MediaPlayer:handlePauseCalled:idPassed=35,currentId=35
2017-12-19 12:03:59.458 [ 18] 0 MediaPlayer:callingOnPlaybackPaused:currentId=35
2017-12-19 12:03:59.459 [ 18] 0 MediaPlayer:handleResumeCalled:idPassed=35,currentId=35
2017-12-19 12:03:59.462 [ 18] 0 MediaPlayer:callingOnPlaybackResumed:currentId=35
2017-12-19 12:03:59.791 [ 18] 0 MediaPlayer:callingOnPlaybackFinished:currentId=35
2017-12-19 12:03:59.791 [ 18] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=2688
2017-12-19 12:03:59.820 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testSetMutePlays (1515 ms)
[ RUN ] MediaPlayerTest.testGetSpeakerSettings
2017-12-19 12:03:59.827 [ 19] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:03:59.827 [ 19] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:03:59.827 [ 19] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:03:59.832 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testGetSpeakerSettings (12 ms)
[ RUN ] MediaPlayerTest.testRoundingEdgeCase
2017-12-19 12:03:59.838 [ 1a] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:03:59.838 [ 1a] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:03:59.839 [ 1a] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:03:59.844 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testRoundingEdgeCase (11 ms)
[ RUN ] MediaPlayerTest.testReadTags
2017-12-19 12:03:59.850 [ 1b] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:03:59.851 [ 1b] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:03:59.852 [ 1b] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:03:59.854 [ 1b] 0 MediaPlayer:handlePlayCalled:idPassed=38,currentId=38
2017-12-19 12:03:59.854 [ 1b] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:03:59.868 [ 1b] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:03:59.953 [ 1b] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:59.953 [ 1b] 0 MediaPlayer:callingOnTags
2017-12-19 12:03:59.956 [ 1b] 0 MediaPlayer:callingOnPlaybackStarted:currentId=38
2017-12-19 12:03:59.960 [ 1b] 0 MediaPlayer:callingOnTags
2017-12-19 12:04:02.636 [ 1b] 0 MediaPlayer:callingOnPlaybackFinished:currentId=38
2017-12-19 12:04:02.637 [ 1b] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=2688
2017-12-19 12:04:02.660 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testReadTags (2816 ms)
[ RUN ] MediaPlayerTest.testConsecutiveSameApiCalls
2017-12-19 12:04:02.669 [ 1c] 0 MediaPlayer:handleSetObserverCalled
2017-12-19 12:04:02.669 [ 1c] 0 MediaPlayer:handleSetSourceCalled
2017-12-19 12:04:02.669 [ 1c] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 12:04:02.671 [ 1c] 0 MediaPlayer:handlePlayCalled:idPassed=39,currentId=39
2017-12-19 12:04:02.671 [ 1c] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-12-19 12:04:02.687 [ 1c] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-19 12:04:02.688 [ 1c] 0 MediaPlayer:handlePlayCalled:idPassed=39,currentId=39
2017-12-19 12:04:02.688 [ 1c] 0 MediaPlayer:handlePlayFailed:reason=playCurrentlyPending
2017-12-19 12:04:02.767 [ 1c] 0 MediaPlayer:callingOnTags
2017-12-19 12:04:02.767 [ 1c] 0 MediaPlayer:callingOnTags
2017-12-19 12:04:02.770 [ 1c] 0 MediaPlayer:callingOnPlaybackStarted:currentId=39
2017-12-19 12:04:02.770 [ 1c] 0 MediaPlayer:handlePauseCalled:idPassed=39,currentId=39
2017-12-19 12:04:02.771 [ 1c] 0 MediaPlayer:handlePauseCalled:idPassed=39,currentId=39
2017-12-19 12:04:02.771 [ 1c] 0 MediaPlayer:handlePauseFailed:reason=pauseCurrentlyPending
2017-12-19 12:04:02.773 [ 1c] 0 MediaPlayer:callingOnPlaybackPaused:currentId=39
2017-12-19 12:04:02.773 [ 1c] 0 MediaPlayer:handleResumeCalled:idPassed=39,currentId=39
2017-12-19 12:04:02.775 [ 1c] 0 MediaPlayer:callingOnPlaybackResumed:currentId=39
2017-12-19 12:04:02.776 [ 1c] 0 MediaPlayer:handleResumeCalled:idPassed=39,currentId=39
2017-12-19 12:04:02.777 [ 1c] E MediaPlayer:handleResumeFailed:reason=alreadyPlaying
terminate called after throwing an instance of 'std::future_error'
what(): Promise already satisfied
Aborted (core dumped)

Pl provide some pointer , i want to fix this in some urgency

@mradulan
Copy link
Contributor

what is the version of gstreamer?

@dhananjayj29
Copy link
Author

gstreamer along with all gst plugins 1.10.4

@sanjayrd
Copy link
Contributor

Hi @dhananjayj29,

Looking through the code, I really don't see any code paths that could cause a promise to be set twice. For example, in play(), a local stack std::promise variable is created and passed into a separate function as a pointer. This is the same for each function (resume(), pause(), etc.). In those separate functions, any time a promise value is set, it appears to return immediately. I'm a little confused about how this could be happening unless GStreamer is invoking that same function twice.

Could you possibly provide some sort stack trace from the point at which the exception is thrown? If you could run the code in some sort of debugger and paste the stack trace when the exception occurs, that might be helpful.

Another possible helpful thing would be to log the address of each promise pointer that is passed into handlePlay() or handlePause(), etc. If we end up seeing the addresses being the same, it could be that there's some sort of issue cleaning up or initializing promises.

One more question - is this crash only happening on your embedded linux environment or other environments as well? Also, what version of GCC are you using?

Thanks,
Sanjay

@dhananjayj29
Copy link
Author

Here are the answers of you questions:

  1. Stack Trace:
    #0 __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:57
    crawler setup test #1 0xb6912950 in __GI_abort () at abort.c:89
    make error: The LWA response body indicated an unrecoverable error: invalid_grant #2 0xb6afa58c in __gnu_cxx::__verbose_terminate_handler () at /libsupc++/vterminate.cc:95
    Missing thread link to ExampleLogger #3 0xb6af83d8 in __cxxabiv1::__terminate (handler=) at /libstdc++-v3/libsupc++/eh_terminate.cc:38
    Added missing pthread linking_lib to ExampleLogger. #4 0xb6af8400 in std::terminate () at gcc-4.8.2-r0/gcc-4.8.2/libstdc++-v3/libsupc++/eh_terminate.cc:48
    MessageRouter::send() does not take the m_connectionMutex #5 0xb6af873c in __cxxabiv1::__cxa_throw (obj=0xb3727e20, tinfo=, dest=)
    at gcc-4.8.2/libstdc++-v3/libsupc++/eh_throw.cc:84
    Why isn't sendExceptionEncountered called when directive isn't handled #6 0xb6b4b824 in std::__throw_future_error (__i=__i@entry=2) at gcc-4.8.2-r0/gcc-4.8.2/libstdc++-v3/src/c++11/functexcept.cc:109
    Accessing audio stream response . #7 0xb6f584dc in _M_set_result (__ignore_failure=false, __res=..., this=0xb3601c80) at /ysroots/c++/future:360
    MessageRouter::disconnectAllTransportsLocked flow leads to erase while iterating transports vector #8 std::promise::set_value(bool&&) (this=this@entry=0xb6432218 <g_idle_dispatch>,
    __r=__r@entry=<unknown type in /usr/local/i3l-target/sysroots/cortexa7hf-vfp-neon-kpit-linux-gnueabi/usr/lib/.debug/libMediaPlayer.so, CU 0x47a98, DIE 0x88a41>)
    at /u03/yoctobms/build/info3-low/tmp-eglibc/sysroots/info3-low/usr/include/c++/future:994
    Build errors when building with KittAi enabled #9 0xb6f50eec in alexaClientSDK::mediaPlayer::MediaPlayer::handlePlay (this=0xa7af0, id=, promise=0xab92b874)
    at /usr/src/debug/avs-device-sdk/1.0-r0/git/MediaPlayer/src/MediaPlayer.cpp:1103
    HTTP2Transport race may lead to deadlock #10 0xb6f5133c in operator() (__closure=) at /usr/src/debug/avs-device-sdk/1.0-r0/git/MediaPlayer/src/MediaPlayer.cpp:218
    Sample App using AVS SDK #11 std::_Function_handler<int(), alexaClientSDK::mediaPlayer::MediaPlayer::play(alexaClientSDK::avsCommon::utils::mediaPlayer::MediaPlayerInterface::SourceId)::__lambda10>::_M_invoke(const std::_Any_data &) (__functor=...) at /c++/functional:2056
    Test 1 in AudioInputProcessorIntegrationTest.cpp #12 0xb64358dc in g_main_dispatch (context=0xa6ce8) at /usr/src/debug/glib-2.0/1_2.46.2-r0/glib-2.46.2/glib/gmain.c:3154
    Empty payload in directives from AVS #13 g_main_context_dispatch (context=context@entry=0xa6ce8) at /usr/src/debug/glib-2.0/1_2.46.2-r0/glib-2.46.2/glib/gmain.c:3769
    How to save the response audio to a local file(.mp3) in v0.4 SDK #14 0xb6435c44 in g_main_context_iterate (context=0xa6ce8, block=block@entry=1, dispatch=dispatch@entry=1, self=) at /usr/src/debug/glib-2.0/1_2.46.2-r0/glib-2.46.2/glib/gmain.c:3840
    Building with MediaPlayer error #15 0xb6435fa0 in g_main_loop_run (loop=0x8b6f8) at /usr/src/debug/glib-2.0/1_2.46.2-r0/glib-2.46.2/glib/gmain.c:4034
    Added handling of first directive SetEndPoint, it raises Exception. #16 0xb6b4c9a8 in std::(anonymous namespace)::execute_native_thread_routine (__p=)
    at //gcc-4.8.2-r0/gcc-4.8.2/libstdc++-v3/src/c++11/thread.cc:84
    Crash in HTTP2Transport::cleanupFinishedStreams() #17 0xb6b8a040 in start_thread (arg=0xb31ff410) at pthread_create.c:314
    "MediaPlayerTest" running error #18 0xb69b10e0 in ?? () at ../ports/sysdeps/unix/sysv/linux/arm/clone.S:92 from /lib/libc.so.6
    Wake word engine support in v0.4 sdk #19 0xb69b10e0 in ?? () at ../ports/sysdeps/unix/sysv/linux/arm/clone.S:92 from/lib/libc.so.6
    Backtrace stopped: previous frame identical to this frame (corrupt stack?)

stack trace from where the Play function is called:

(gdb) bt

#0 0xb6b8ed08 in __pthread_cond_wait (cond=0xb3601ca0, mutex=0x0) at pthread_cond_wait.c:187
#1 0xb6b49350 in __gthread_cond_wait (__mutex=, __cond=__cond@entry=0xb3601ca0)
at /bits/gthr-default.h:864
#2 std::condition_variable::wait (this=this@entry=0xb3601ca0, __lock=...) at /u03/yoctobms/build/info3-low/tmp-eglibc/work-shared/gcc-4.8.2-r0/gcc-4.8.2/libstdc++-v3/src/c++11/condition_variable.cc:52
#3 0x00038b18 in waitstd::__future_base::_State_base::wait()::__lambda0 (__p=..., __lock=..., this=0xb3601ca0)
at /usr/include/c++/condition_variable:93
#4 wait (this=0xb3601c80) at /usr/local/i3l-target/avs/sysroots/cortexa7hf-vfp-neon-kpit-linux-gnueabi/usr/include/c++/future:327
#5 _M_get_result (this=) at /c++/future:595
#6 std::future::get (this=) atc++/future:674
#7 0xb6f54e4c in alexaClientSDK::mediaPlayer::MediaPlayer::play (this=0xa7af0, id=) at /usr/src/debug/avs-device-sdk/1.0-r0/git/MediaPlayer/src/MediaPlayer.cpp:223
#8 0xb67c41a4 in alexaClientSDK::capabilityAgents::speechSynthesizer::SpeechSynthesizer::startPlaying (this=this@entry=0x1afba8)
at /usr/src/debug/avs-device-sdk/1.0-r0/git/CapabilityAgents/SpeechSynthesizer/src/SpeechSynthesizer.cpp:714
#9 0xb67c4ac4 in alexaClientSDK::capabilityAgents::speechSynthesizer::SpeechSynthesizer::executeStateChange (this=0x1afba8)
at /usr/src/debug/avs-device-sdk/1.0-r0/git/CapabilityAgents/SpeechSynthesizer/src/SpeechSynthesizer.cpp:529
#10 0x00037d18 in operator() (this=0xb3601e7c) atfunctional:2464
#11 operator() (this=0xb3601e78) at/c++/future:1227
#12 std::_Function_handler<std::unique_ptr<std::__future_base::_Result_base, std::__future_base::_Result_base::_Deleter> (), std::__future_base::_Task_setter<std::unique_ptr<std::__future_base::_Result, std::__future_base::_Result_base::_Deleter>, void> >::_M_invoke(std::_Any_data const&) (__functor=...)
at usr/include/c++/functional:2057
#13 0xb67d13f8 in operator() (this=) at //functional:2464
#14 std::__future_base::_State_base::_M_do_set(std::function<std::unique_ptr<std::__future_base::_Result_base, std::__future_base::_Result_base::_Deleter> ()>&, bool&) (this=0xb36020c8, __f=...,
__set=@0xab92bd1f: false) at/c++/future:469
#15 0xb6b902e4 in __GI___pthread_once (once_control=0xb360211c, init_routine=0x23bb8 <__once_proxy>) at ../ports/sysdeps/unix/sysv/linux/arm/nptl/pthread_once.c:76
#16 0xb67cf8bc in __gthread_once (__func=, __once=0xb360211c) at/bits/gthr-default.h:699
#17 call_once<void (std::__future_base::_State_base::)(std::function<std::unique_ptr<std::__future_base::_Result_base, std::__future_base::_Result_base::_Deleter>()>&, bool&), std::__future_base::_State_base const, std::reference_wrapper<std::function<std::unique_ptr<std::__future_base::_Result_base, std::__future_base::_Result_base::_Deleter>()> >, std::reference_wrapper > (__f=,
__once=...) at /usr/include/c++/mutex:786
#18 _M_set_result (__ignore_failure=false, __res=..., this=0xb36020c8) at future:358
#19 std::__future_base::_Task_state<std::_BindalexaClientSDK::capabilityAgents::speechSynthesizer::SpeechSynthesizer::onFocusChanged(alexaClientSDK::avsCommon::avs::FocusState)::__lambda16(), std::allocator, void()>::_M_run(void) (this=0xb36020c8) at /u03/yoctobms/build/info3-low/tmp-eglibc/sysroots/info3-low/usr/include/c++/future:1276
#20 0xb67bf8fc in operator() (this=) at /future:1407
#21 operator() (__closure=0xb3602200) at /usr/src/debug/avs-device-sdk/1.0-r0/git/AVSCommon/Utils/include/AVSCommon/Utils/Threading/TaskQueue.h:185
#22 std::_Function_handler<void(), alexaClientSDK::avsCommon::utils::threading::TaskQueue::pushTo(bool, Task, Args&& ...) [with Task = alexaClientSDK::capabilityAgents::speechSynthesizer::SpeechSynthesizer::onFocusChanged(alexaClientSDK::avsCommon::avs::FocusState)::__lambda16; Args = {}; decltype (task(alexaClientSDK::avsCommon::utils::threading::TaskQueue::pushTo::args ...)) = void]::__lambda6>::_M_invoke(const std::_Any_data &) (__functor=...) at functional:2071
#23 0xb6e5753c in operator() (this=0xb36021e8) at :2464
#24 alexaClientSDK::avsCommon::utils::threading::TaskThread::processTasksLoop (this=0x1b0310) at /usr/src/debug/avs-device-sdk/1.0-r0/git/AVSCommon/Utils/src/TaskThread.cpp:52
#25 0xb6b4c9a8 in std::(anonymous namespace)::execute_native_thread_routine (__p=)
at /gcc-4.8.2/libstdc++-v3/src/c++11/thread.cc:84
#26 0xb6b8a040 in start_thread (arg=0xab92c410) at pthread_create.c:314
#27 0xb69b10e0 in ?? () at ../ports/sysdeps/unix/sysv/linux/arm/clone.S:92 from lib/libc.so.6
#28 0xb69b10e0 in ?? () at ../ports/sysdeps/unix/sysv/linux/arm/clone.S:92 from /cortexa7hf-vfp-neon-lib/libc.so.6
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

  1. GCC version 4.8.2

  2. I have tried this in ubuntu 14.04 , it crashed there also but less frequently. , in my embedded linux it almost crashed after every 2nd attempt now.

  3. Regarding the logs for all the local promise , I will paste shortly.

@dhananjayj29
Copy link
Author

Here are the logs for MediaPlayerTest:

[==========] Running 35 tests from 1 test case.
[----------] Global test environment set-up.
[----------] 35 tests from MediaPlayerTest
[ RUN ] MediaPlayerTest.testStartPlayWaitForEnd
setObserver &promise0xbef398d4
2017-12-19 11:49:40.318 [ 1] 0 MediaPlayer:handleSetObserverCalled
handlesetObserver promise0xbef398d4
setSource attachmentreader &promise0xbef39864
2017-12-19 11:49:40.320 [ 1] 0 MediaPlayer:handleSetSourceCalled
handlesetAttachmentReaderSource promise0xbef39864
2017-12-19 11:49:40.321 [ 1] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
Play &promise0xbef398a4
2017-12-19 11:49:40.343 [ 1] 0 MediaPlayer:handlePlayCalled:idPassed=1,currentId=1
handlePlay promise0xbef398a4
2017-12-19 11:49:40.343 [ 1] 0 MediaPlayer:handlePlayCalled after validate source and ID

2017-12-19 11:49:40.343 [ 1] 0 MediaPlayer:handlePlayCalled after gst_element_get_state

2017-12-19 11:49:40.343 [ 1] 0 MediaPlayer:handlePlayCalled after GST_STATE_PLAYING

2017-12-19 11:49:40.343 [ 1] 0 MediaPlayer:handlePlayCalled before set state

2017-12-19 11:49:40.351 [ 1] 0 MediaPlayer:handlePlay:attemptBuffering=0
Failed to create secure directory (/home/root/.config/pulse): Read-only file system
2017-12-19 11:49:40.507 [ 1] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
OnPadAdded &promise0xb54f5b44
handlePadAdded promise0xb54f5b44
2017-12-19 11:49:40.823 [ 1] 0 MediaPlayer:callingOnTags
2017-12-19 11:49:40.825 [ 1] 0 MediaPlayer:callingOnTags
2017-12-19 11:49:40.846 [ 1] 0 MediaPlayer:callingOnTags
2017-12-19 11:49:40.867 [ 1] 0 MediaPlayer:callingOnPlaybackStarted:currentId=1
2017-12-19 11:49:43.531 [ 1] 0 MediaPlayer:callingOnPlaybackFinished:currentId=1
2017-12-19 11:49:43.532 [ 1] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=2688
2017-12-19 11:49:43.562 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testStartPlayWaitForEnd (3506 ms)
[ RUN ] MediaPlayerTest.testStartPlayWaitForEndStartPlayAgain
setObserver &promise0xbef398d4
2017-12-19 11:49:43.574 [ 3] 0 MediaPlayer:handleSetObserverCalled
handlesetObserver promise0xbef398d4
setSource istream &promise0xbef3985c
2017-12-19 11:49:43.575 [ 3] 0 MediaPlayer:handleSetSourceCalled
handlesetsourceCalled promise0xbef3985c
2017-12-19 11:49:43.576 [ 3] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
Play &promise0xbef39894
2017-12-19 11:49:43.578 [ 3] 0 MediaPlayer:handlePlayCalled:idPassed=2,currentId=2
handlePlay promise0xbef39894
2017-12-19 11:49:43.578 [ 3] 0 MediaPlayer:handlePlayCalled after validate source and ID

2017-12-19 11:49:43.579 [ 3] 0 MediaPlayer:handlePlayCalled after gst_element_get_state

2017-12-19 11:49:43.579 [ 3] 0 MediaPlayer:handlePlayCalled after GST_STATE_PLAYING

2017-12-19 11:49:43.579 [ 3] 0 MediaPlayer:handlePlayCalled before set state

2017-12-19 11:49:43.579 [ 3] 0 MediaPlayer:handlePlay:attemptBuffering=0
Failed to create secure directory (/home/root/.config/pulse): Read-only file system
2017-12-19 11:49:43.599 [ 3] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
OnPadAdded &promise0xb54f5b44
handlePadAdded promise0xb54f5b44
2017-12-19 11:49:43.722 [ 3] 0 MediaPlayer:callingOnTags
2017-12-19 11:49:43.723 [ 3] 0 MediaPlayer:callingOnTags
2017-12-19 11:49:43.728 [ 3] 0 MediaPlayer:callingOnPlaybackStarted:currentId=2
2017-12-19 11:49:43.738 [ 3] 0 MediaPlayer:callingOnTags
2017-12-19 11:49:46.411 [ 3] 0 MediaPlayer:callingOnPlaybackFinished:currentId=2
2017-12-19 11:49:46.411 [ 3] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=2688
setSource attachmentreader &promise0xbef39854
2017-12-19 11:49:46.437 [ 3] 0 MediaPlayer:handleSetSourceCalled
handlesetAttachmentReaderSource promise0xbef39854
2017-12-19 11:49:46.437 [ 3] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
Play &promise0xbef39894
2017-12-19 11:49:46.451 [ 3] 0 MediaPlayer:handlePlayCalled:idPassed=3,currentId=3
handlePlay promise0xbef39894
2017-12-19 11:49:46.451 [ 3] 0 MediaPlayer:handlePlayCalled after validate source and ID

2017-12-19 11:49:46.451 [ 3] 0 MediaPlayer:handlePlayCalled after gst_element_get_state

2017-12-19 11:49:46.451 [ 3] 0 MediaPlayer:handlePlayCalled after GST_STATE_PLAYING

2017-12-19 11:49:46.451 [ 3] 0 MediaPlayer:handlePlayCalled before set state

2017-12-19 11:49:46.451 [ 3] 0 MediaPlayer:handlePlay:attemptBuffering=0
Failed to create secure directory (/home/root/.config/pulse): Read-only file system
2017-12-19 11:49:46.487 [ 3] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
OnPadAdded &promise0xb54f5b44
handlePadAdded promise0xb54f5b44
2017-12-19 11:49:46.612 [ 3] 0 MediaPlayer:callingOnTags
2017-12-19 11:49:46.613 [ 3] 0 MediaPlayer:callingOnTags
2017-12-19 11:49:46.618 [ 3] 0 MediaPlayer:callingOnPlaybackStarted:currentId=3
2017-12-19 11:49:46.635 [ 3] 0 MediaPlayer:callingOnTags
2017-12-19 11:49:49.320 [ 3] 0 MediaPlayer:callingOnPlaybackFinished:currentId=3
2017-12-19 11:49:49.320 [ 3] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=2688
2017-12-19 11:49:49.338 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testStartPlayWaitForEndStartPlayAgain (5775 ms)
[ RUN ] MediaPlayerTest.testStopPlay
setObserver &promise0xbef398d4
2017-12-19 11:49:49.349 [ 4] 0 MediaPlayer:handleSetObserverCalled
handlesetObserver promise0xbef398d4
setSource istream &promise0xbef39884
2017-12-19 11:49:49.351 [ 4] 0 MediaPlayer:handleSetSourceCalled
handlesetsourceCalled promise0xbef39884
2017-12-19 11:49:49.351 [ 4] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
Play &promise0xbef398bc
2017-12-19 11:49:49.354 [ 4] 0 MediaPlayer:handlePlayCalled:idPassed=4,currentId=4
handlePlay promise0xbef398bc
2017-12-19 11:49:49.354 [ 4] 0 MediaPlayer:handlePlayCalled after validate source and ID

2017-12-19 11:49:49.355 [ 4] 0 MediaPlayer:handlePlayCalled after gst_element_get_state

2017-12-19 11:49:49.355 [ 4] 0 MediaPlayer:handlePlayCalled after GST_STATE_PLAYING

2017-12-19 11:49:49.355 [ 4] 0 MediaPlayer:handlePlayCalled before set state

2017-12-19 11:49:49.355 [ 4] 0 MediaPlayer:handlePlay:attemptBuffering=0
Failed to create secure directory (/home/root/.config/pulse): Read-only file system
2017-12-19 11:49:49.375 [ 4] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
OnPadAdded &promise0xb54f5b44
handlePadAdded promise0xb54f5b44
2017-12-19 11:49:49.491 [ 4] 0 MediaPlayer:callingOnTags
2017-12-19 11:49:49.491 [ 4] 0 MediaPlayer:callingOnTags
2017-12-19 11:49:49.503 [ 4] 0 MediaPlayer:callingOnPlaybackStarted:currentId=4
2017-12-19 11:49:49.505 [ 4] 0 MediaPlayer:callingOnTags
Stop &promise0xbef398bc
2017-12-19 11:49:54.513 [ 4] 0 MediaPlayer:handleStopCalled:idPassed=4,currentId=4
handleStop promise0xbef398bc
2017-12-19 11:49:54.535 [ 4] 0 MediaPlayer:callingOnPlaybackStopped:currentId=4
2017-12-19 11:49:54.542 [ 4] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 11:49:54.546 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testStopPlay (5209 ms)
[ RUN ] MediaPlayerTest.testStartPlayCallAfterStopPlay
setObserver &promise0xbef398d4
2017-12-19 11:49:54.558 [ 5] 0 MediaPlayer:handleSetObserverCalled
handlesetObserver promise0xbef398d4
setSource istream &promise0xbef39884
2017-12-19 11:49:54.559 [ 5] 0 MediaPlayer:handleSetSourceCalled
handlesetsourceCalled promise0xbef39884
2017-12-19 11:49:54.559 [ 5] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
Play &promise0xbef398bc
2017-12-19 11:49:54.564 [ 5] 0 MediaPlayer:handlePlayCalled:idPassed=5,currentId=5
handlePlay promise0xbef398bc
2017-12-19 11:49:54.565 [ 5] 0 MediaPlayer:handlePlayCalled after validate source and ID

2017-12-19 11:49:54.565 [ 5] 0 MediaPlayer:handlePlayCalled after gst_element_get_state

2017-12-19 11:49:54.565 [ 5] 0 MediaPlayer:handlePlayCalled after GST_STATE_PLAYING

2017-12-19 11:49:54.565 [ 5] 0 MediaPlayer:handlePlayCalled before set state

2017-12-19 11:49:54.565 [ 5] 0 MediaPlayer:handlePlay:attemptBuffering=0
Failed to create secure directory (/home/root/.config/pulse): Read-only file system
2017-12-19 11:49:54.601 [ 5] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
OnPadAdded &promise0xb54f5b44
handlePadAdded promise0xb54f5b44
2017-12-19 11:49:54.753 [ 5] 0 MediaPlayer:callingOnTags
2017-12-19 11:49:54.753 [ 5] 0 MediaPlayer:callingOnTags
2017-12-19 11:49:54.759 [ 5] 0 MediaPlayer:callingOnPlaybackStarted:currentId=5
2017-12-19 11:49:54.771 [ 5] 0 MediaPlayer:callingOnTags
Stop &promise0xbef398bc
2017-12-19 11:49:56.761 [ 5] 0 MediaPlayer:handleStopCalled:idPassed=5,currentId=5
handleStop promise0xbef398bc
2017-12-19 11:49:56.779 [ 5] 0 MediaPlayer:callingOnPlaybackStopped:currentId=5
Play &promise0xbef398bc
2017-12-19 11:49:56.779 [ 5] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 11:49:56.781 [ 5] 0 MediaPlayer:handlePlayCalled:idPassed=5,currentId=0
handlePlay promise0xbef398bc
2017-12-19 11:49:56.781 [ 5] E MediaPlayer:validateSourceAndIdFailed:reason=sourceNotSet
2017-12-19 11:49:56.781 [ 5] E MediaPlayer:handlePlayFailed
2017-12-19 11:49:56.784 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testStartPlayCallAfterStopPlay (2237 ms)
[ RUN ] MediaPlayerTest.testStartPlayCallAfterStopPlayDifferentSource
setObserver &promise0xbef398d4
2017-12-19 11:49:56.795 [ 6] 0 MediaPlayer:handleSetObserverCalled
handlesetObserver promise0xbef398d4
setSource attachmentreader &promise0xbef39854
2017-12-19 11:49:56.800 [ 6] 0 MediaPlayer:handleSetSourceCalled
handlesetAttachmentReaderSource promise0xbef39854
2017-12-19 11:49:56.800 [ 6] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
Play &promise0xbef39894
2017-12-19 11:49:56.803 [ 6] 0 MediaPlayer:handlePlayCalled:idPassed=6,currentId=6
handlePlay promise0xbef39894
2017-12-19 11:49:56.803 [ 6] 0 MediaPlayer:handlePlayCalled after validate source and ID

2017-12-19 11:49:56.803 [ 6] 0 MediaPlayer:handlePlayCalled after gst_element_get_state

2017-12-19 11:49:56.803 [ 6] 0 MediaPlayer:handlePlayCalled after GST_STATE_PLAYING

2017-12-19 11:49:56.803 [ 6] 0 MediaPlayer:handlePlayCalled before set state

2017-12-19 11:49:56.803 [ 6] 0 MediaPlayer:handlePlay:attemptBuffering=0
Failed to create secure directory (/home/root/.config/pulse): Read-only file system
2017-12-19 11:49:56.823 [ 6] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
OnPadAdded &promise0xb54f5b44
handlePadAdded promise0xb54f5b44
2017-12-19 11:49:56.942 [ 6] 0 MediaPlayer:callingOnTags
2017-12-19 11:49:56.942 [ 6] 0 MediaPlayer:callingOnTags
2017-12-19 11:49:56.949 [ 6] 0 MediaPlayer:callingOnPlaybackStarted:currentId=6
2017-12-19 11:49:56.954 [ 6] 0 MediaPlayer:callingOnTags
Stop &promise0xbef39894
2017-12-19 11:49:57.961 [ 6] 0 MediaPlayer:handleStopCalled:idPassed=6,currentId=6
handleStop promise0xbef39894
2017-12-19 11:49:57.975 [ 6] 0 MediaPlayer:callingOnPlaybackStopped:currentId=6
setSource attachmentreader &promise0xbef39854
2017-12-19 11:49:57.975 [ 6] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 11:49:57.977 [ 6] 0 MediaPlayer:handleSetSourceCalled
handlesetAttachmentReaderSource promise0xbef39854
2017-12-19 11:49:57.977 [ 6] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
Play &promise0xbef39894
2017-12-19 11:49:57.986 [ 6] 0 MediaPlayer:handlePlayCalled:idPassed=7,currentId=7
handlePlay promise0xbef39894
2017-12-19 11:49:57.986 [ 6] 0 MediaPlayer:handlePlayCalled after validate source and ID

2017-12-19 11:49:57.986 [ 6] 0 MediaPlayer:handlePlayCalled after gst_element_get_state

2017-12-19 11:49:57.986 [ 6] 0 MediaPlayer:handlePlayCalled after GST_STATE_PLAYING

2017-12-19 11:49:57.986 [ 6] 0 MediaPlayer:handlePlayCalled before set state

2017-12-19 11:49:57.987 [ 6] 0 MediaPlayer:handlePlay:attemptBuffering=0
Failed to create secure directory (/home/root/.config/pulse): Read-only file system
2017-12-19 11:49:58.006 [ 6] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
OnPadAdded &promise0xb54f5b44
handlePadAdded promise0xb54f5b44
2017-12-19 11:49:58.127 [ 6] 0 MediaPlayer:callingOnTags
2017-12-19 11:49:58.127 [ 6] 0 MediaPlayer:callingOnTags
2017-12-19 11:49:58.128 [ 6] 0 MediaPlayer:callingOnPlaybackStarted:currentId=7
2017-12-19 11:49:58.143 [ 6] 0 MediaPlayer:callingOnTags
Stop &promise0xbef39894
2017-12-19 11:49:59.142 [ 6] 0 MediaPlayer:handleStopCalled:idPassed=7,currentId=7
handleStop promise0xbef39894
2017-12-19 11:49:59.161 [ 6] 0 MediaPlayer:callingOnPlaybackStopped:currentId=7
2017-12-19 11:49:59.162 [ 6] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 11:49:59.168 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testStartPlayCallAfterStopPlayDifferentSource (2384 ms)
[ RUN ] MediaPlayerTest.testPauseDuringPlay
setObserver &promise0xbef398d4
2017-12-19 11:49:59.179 [ 7] 0 MediaPlayer:handleSetObserverCalled
handlesetObserver promise0xbef398d4
setSource istream &promise0xbef39884
2017-12-19 11:49:59.181 [ 7] 0 MediaPlayer:handleSetSourceCalled
handlesetsourceCalled promise0xbef39884
2017-12-19 11:49:59.181 [ 7] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
Play &promise0xbef398bc
2017-12-19 11:49:59.184 [ 7] 0 MediaPlayer:handlePlayCalled:idPassed=8,currentId=8
handlePlay promise0xbef398bc
2017-12-19 11:49:59.184 [ 7] 0 MediaPlayer:handlePlayCalled after validate source and ID

2017-12-19 11:49:59.184 [ 7] 0 MediaPlayer:handlePlayCalled after gst_element_get_state

2017-12-19 11:49:59.184 [ 7] 0 MediaPlayer:handlePlayCalled after GST_STATE_PLAYING

2017-12-19 11:49:59.184 [ 7] 0 MediaPlayer:handlePlayCalled before set state

2017-12-19 11:49:59.185 [ 7] 0 MediaPlayer:handlePlay:attemptBuffering=0
Failed to create secure directory (/home/root/.config/pulse): Read-only file system
2017-12-19 11:49:59.207 [ 7] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
OnPadAdded &promise0xb54f5b44
handlePadAdded promise0xb54f5b44
2017-12-19 11:49:59.338 [ 7] 0 MediaPlayer:callingOnTags
2017-12-19 11:49:59.338 [ 7] 0 MediaPlayer:callingOnTags
2017-12-19 11:49:59.345 [ 7] 0 MediaPlayer:callingOnPlaybackStarted:currentId=8
2017-12-19 11:49:59.356 [ 7] 0 MediaPlayer:callingOnTags
pause &promise0xbef398bc
2017-12-19 11:50:00.346 [ 7] 0 MediaPlayer:handlePauseCalled:idPassed=8,currentId=8
handlePause promise0xbef398bc
2017-12-19 11:50:00.352 [ 7] 0 MediaPlayer:callingOnPlaybackPaused:currentId=8
2017-12-19 11:50:00.369 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testPauseDuringPlay (1200 ms)
[ RUN ] MediaPlayerTest.testResumeAfterPauseThenStop
setObserver &promise0xbef398d4
2017-12-19 11:50:00.381 [ 8] 0 MediaPlayer:handleSetObserverCalled
handlesetObserver promise0xbef398d4
setSource istream &promise0xbef39884
2017-12-19 11:50:00.381 [ 8] 0 MediaPlayer:handleSetSourceCalled
handlesetsourceCalled promise0xbef39884
2017-12-19 11:50:00.382 [ 8] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
Play &promise0xbef398bc
2017-12-19 11:50:00.384 [ 8] 0 MediaPlayer:handlePlayCalled:idPassed=9,currentId=9
handlePlay promise0xbef398bc
2017-12-19 11:50:00.384 [ 8] 0 MediaPlayer:handlePlayCalled after validate source and ID

2017-12-19 11:50:00.384 [ 8] 0 MediaPlayer:handlePlayCalled after gst_element_get_state

2017-12-19 11:50:00.385 [ 8] 0 MediaPlayer:handlePlayCalled after GST_STATE_PLAYING

2017-12-19 11:50:00.385 [ 8] 0 MediaPlayer:handlePlayCalled before set state

2017-12-19 11:50:00.385 [ 8] 0 MediaPlayer:handlePlay:attemptBuffering=0
Failed to create secure directory (/home/root/.config/pulse): Read-only file system
2017-12-19 11:50:00.403 [ 8] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
OnPadAdded &promise0xb54f5b44
handlePadAdded promise0xb54f5b44
2017-12-19 11:50:00.534 [ 8] 0 MediaPlayer:callingOnTags
2017-12-19 11:50:00.535 [ 8] 0 MediaPlayer:callingOnTags
2017-12-19 11:50:00.538 [ 8] 0 MediaPlayer:callingOnPlaybackStarted:currentId=9
pause &promise0xbef398bc
2017-12-19 11:50:00.539 [ 8] 0 MediaPlayer:handlePauseCalled:idPassed=9,currentId=9
handlePause promise0xbef398bc
2017-12-19 11:50:00.540 [ 8] 0 MediaPlayer:callingOnPlaybackPaused:currentId=9
resume &promise0xbef398bc
2017-12-19 11:50:00.541 [ 8] 0 MediaPlayer:handleResumeCalled:idPassed=9,currentId=9
handleResume promise0xbef398bc
2017-12-19 11:50:00.543 [ 8] 0 MediaPlayer:callingOnPlaybackResumed:currentId=9
2017-12-19 11:50:00.546 [ 8] 0 MediaPlayer:callingOnTags
2017-12-19 11:50:03.106 [ 8] 0 MediaPlayer:callingOnPlaybackFinished:currentId=9
2017-12-19 11:50:03.106 [ 8] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=2688
2017-12-19 11:50:03.133 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testResumeAfterPauseThenStop (2764 ms)
[ RUN ] MediaPlayerTest.testStopAfterPause
setObserver &promise0xbef398d4
2017-12-19 11:50:03.150 [ 9] 0 MediaPlayer:handleSetObserverCalled
handlesetObserver promise0xbef398d4
setSource istream &promise0xbef39884
2017-12-19 11:50:03.151 [ 9] 0 MediaPlayer:handleSetSourceCalled
handlesetsourceCalled promise0xbef39884
2017-12-19 11:50:03.151 [ 9] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
Play &promise0xbef398bc
2017-12-19 11:50:03.154 [ 9] 0 MediaPlayer:handlePlayCalled:idPassed=10,currentId=10
handlePlay promise0xbef398bc
2017-12-19 11:50:03.155 [ 9] 0 MediaPlayer:handlePlayCalled after validate source and ID

2017-12-19 11:50:03.155 [ 9] 0 MediaPlayer:handlePlayCalled after gst_element_get_state

2017-12-19 11:50:03.156 [ 9] 0 MediaPlayer:handlePlayCalled after GST_STATE_PLAYING

2017-12-19 11:50:03.156 [ 9] 0 MediaPlayer:handlePlayCalled before set state

2017-12-19 11:50:03.156 [ 9] 0 MediaPlayer:handlePlay:attemptBuffering=0
Failed to create secure directory (/home/root/.config/pulse): Read-only file system
2017-12-19 11:50:03.191 [ 9] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
OnPadAdded &promise0xb54f5b44
handlePadAdded promise0xb54f5b44
2017-12-19 11:50:03.350 [ 9] 0 MediaPlayer:callingOnTags
2017-12-19 11:50:03.351 [ 9] 0 MediaPlayer:callingOnTags
2017-12-19 11:50:03.352 [ 9] 0 MediaPlayer:callingOnPlaybackStarted:currentId=10
2017-12-19 11:50:03.367 [ 9] 0 MediaPlayer:callingOnTags
pause &promise0xbef398bc
2017-12-19 11:50:03.576 [ 9] 0 MediaPlayer:handlePauseCalled:idPassed=10,currentId=10
handlePause promise0xbef398bc
2017-12-19 11:50:03.584 [ 9] 0 MediaPlayer:callingOnPlaybackPaused:currentId=10
Stop &promise0xbef398bc
2017-12-19 11:50:03.585 [ 9] 0 MediaPlayer:handleStopCalled:idPassed=10,currentId=10
handleStop promise0xbef398bc
2017-12-19 11:50:03.598 [ 9] 0 MediaPlayer:callingOnPlaybackStopped:currentId=10
2017-12-19 11:50:03.603 [ 9] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 11:50:03.607 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testStopAfterPause (475 ms)
[ RUN ] MediaPlayerTest.testPauseAfterPause
setObserver &promise0xbef398d4
2017-12-19 11:50:03.616 [ a] 0 MediaPlayer:handleSetObserverCalled
handlesetObserver promise0xbef398d4
setSource istream &promise0xbef39884
2017-12-19 11:50:03.617 [ a] 0 MediaPlayer:handleSetSourceCalled
handlesetsourceCalled promise0xbef39884
2017-12-19 11:50:03.617 [ a] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
Play &promise0xbef398bc
2017-12-19 11:50:03.620 [ a] 0 MediaPlayer:handlePlayCalled:idPassed=11,currentId=11
handlePlay promise0xbef398bc
2017-12-19 11:50:03.620 [ a] 0 MediaPlayer:handlePlayCalled after validate source and ID

2017-12-19 11:50:03.620 [ a] 0 MediaPlayer:handlePlayCalled after gst_element_get_state

2017-12-19 11:50:03.620 [ a] 0 MediaPlayer:handlePlayCalled after GST_STATE_PLAYING

2017-12-19 11:50:03.620 [ a] 0 MediaPlayer:handlePlayCalled before set state

2017-12-19 11:50:03.620 [ a] 0 MediaPlayer:handlePlay:attemptBuffering=0
Failed to create secure directory (/home/root/.config/pulse): Read-only file system
2017-12-19 11:50:03.650 [ a] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
OnPadAdded &promise0xb54f5b44
handlePadAdded promise0xb54f5b44
2017-12-19 11:50:03.788 [ a] 0 MediaPlayer:callingOnTags
2017-12-19 11:50:03.789 [ a] 0 MediaPlayer:callingOnTags
2017-12-19 11:50:03.796 [ a] 0 MediaPlayer:callingOnPlaybackStarted:currentId=11
pause &promise0xbef398bc
2017-12-19 11:50:03.796 [ a] 0 MediaPlayer:handlePauseCalled:idPassed=11,currentId=11
handlePause promise0xbef398bc
2017-12-19 11:50:03.798 [ a] 0 MediaPlayer:callingOnPlaybackPaused:currentId=11
pause &promise0xbef398bc
2017-12-19 11:50:03.806 [ a] 0 MediaPlayer:handlePauseCalled:idPassed=11,currentId=11
handlePause promise0xbef398bc
2017-12-19 11:50:03.806 [ a] E MediaPlayer:handlePauseFailed:reason=noAudioPlaying
Stop &promise0xbef398bc
2017-12-19 11:50:03.807 [ a] 0 MediaPlayer:handleStopCalled:idPassed=11,currentId=11
handleStop promise0xbef398bc
2017-12-19 11:50:03.816 [ a] 0 MediaPlayer:callingOnPlaybackStopped:currentId=11
2017-12-19 11:50:03.817 [ a] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 11:50:03.820 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testPauseAfterPause (213 ms)
[ RUN ] MediaPlayerTest.testResumeAfterPlay
setObserver &promise0xbef398d4
2017-12-19 11:50:03.828 [ b] 0 MediaPlayer:handleSetObserverCalled
handlesetObserver promise0xbef398d4
setSource istream &promise0xbef39884
2017-12-19 11:50:03.829 [ b] 0 MediaPlayer:handleSetSourceCalled
handlesetsourceCalled promise0xbef39884
2017-12-19 11:50:03.829 [ b] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
Play &promise0xbef398bc
2017-12-19 11:50:03.832 [ b] 0 MediaPlayer:handlePlayCalled:idPassed=12,currentId=12
handlePlay promise0xbef398bc
2017-12-19 11:50:03.832 [ b] 0 MediaPlayer:handlePlayCalled after validate source and ID

2017-12-19 11:50:03.832 [ b] 0 MediaPlayer:handlePlayCalled after gst_element_get_state

2017-12-19 11:50:03.832 [ b] 0 MediaPlayer:handlePlayCalled after GST_STATE_PLAYING

2017-12-19 11:50:03.832 [ b] 0 MediaPlayer:handlePlayCalled before set state

2017-12-19 11:50:03.833 [ b] 0 MediaPlayer:handlePlay:attemptBuffering=0
Failed to create secure directory (/home/root/.config/pulse): Read-only file system
2017-12-19 11:50:03.851 [ b] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
OnPadAdded &promise0xb54f5b44
handlePadAdded promise0xb54f5b44
2017-12-19 11:50:03.971 [ b] 0 MediaPlayer:callingOnTags
2017-12-19 11:50:03.971 [ b] 0 MediaPlayer:callingOnTags
2017-12-19 11:50:03.976 [ b] 0 MediaPlayer:callingOnPlaybackStarted:currentId=12
resume &promise0xbef398bc
2017-12-19 11:50:03.977 [ b] 0 MediaPlayer:handleResumeCalled:idPassed=12,currentId=12
handleResume promise0xbef398bc
2017-12-19 11:50:03.977 [ b] E MediaPlayer:handleResumeFailed:reason=alreadyPlaying
Stop &promise0xbef398bc
2017-12-19 11:50:03.977 [ b] 0 MediaPlayer:handleStopCalled:idPassed=12,currentId=12
handleStop promise0xbef398bc
2017-12-19 11:50:03.994 [ b] 0 MediaPlayer:callingOnPlaybackStopped:currentId=12
2017-12-19 11:50:03.997 [ b] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 11:50:04.003 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testResumeAfterPlay (183 ms)
[ RUN ] MediaPlayerTest.testGetOffsetInMilliseconds
setObserver &promise0xbef398d4
2017-12-19 11:50:04.018 [ c] 0 MediaPlayer:handleSetObserverCalled
handlesetObserver promise0xbef398d4
setSource attachmentreader &promise0xbef39854
2017-12-19 11:50:04.018 [ c] 0 MediaPlayer:handleSetSourceCalled
handlesetAttachmentReaderSource promise0xbef39854
2017-12-19 11:50:04.019 [ c] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
Play &promise0xbef39894
2017-12-19 11:50:04.021 [ c] 0 MediaPlayer:handlePlayCalled:idPassed=13,currentId=13
handlePlay promise0xbef39894
2017-12-19 11:50:04.022 [ c] 0 MediaPlayer:handlePlayCalled after validate source and ID

2017-12-19 11:50:04.022 [ c] 0 MediaPlayer:handlePlayCalled after gst_element_get_state

2017-12-19 11:50:04.022 [ c] 0 MediaPlayer:handlePlayCalled after GST_STATE_PLAYING

2017-12-19 11:50:04.022 [ c] 0 MediaPlayer:handlePlayCalled before set state

2017-12-19 11:50:04.022 [ c] 0 MediaPlayer:handlePlay:attemptBuffering=0
Failed to create secure directory (/home/root/.config/pulse): Read-only file system
2017-12-19 11:50:04.043 [ c] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
OnPadAdded &promise0xb54f5b44
handlePadAdded promise0xb54f5b44
2017-12-19 11:50:04.172 [ c] 0 MediaPlayer:callingOnTags
2017-12-19 11:50:04.172 [ c] 0 MediaPlayer:callingOnTags
2017-12-19 11:50:04.178 [ c] 0 MediaPlayer:callingOnPlaybackStarted:currentId=13
2017-12-19 11:50:04.190 [ c] 0 MediaPlayer:callingOnTags
getOffset &promise0xbef39894
2017-12-19 11:50:05.186 [ c] 0 MediaPlayer:handleGetOffsetCalled:idPassed=13,currentId=13
handleGetOffset promise0xbef39894
Stop &promise0xbef39894
2017-12-19 11:50:05.187 [ c] 0 MediaPlayer:handleStopCalled:idPassed=13,currentId=13
handleStop promise0xbef39894
2017-12-19 11:50:05.209 [ c] 0 MediaPlayer:callingOnPlaybackStopped:currentId=13
getOffset &promise0xbef39894
2017-12-19 11:50:05.209 [ c] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 11:50:05.210 [ c] 0 MediaPlayer:handleGetOffsetCalled:idPassed=13,currentId=0
handleGetOffset promise0xbef39894
2017-12-19 11:50:05.211 [ c] E MediaPlayer:validateSourceAndIdFailed:reason=sourceNotSet
2017-12-19 11:50:05.218 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testGetOffsetInMilliseconds (1214 ms)
[ RUN ] MediaPlayerTest.testGetOffsetInMillisecondsNullPipeline
setObserver &promise0xbef398d4
2017-12-19 11:50:05.230 [ d] 0 MediaPlayer:handleSetObserverCalled
handlesetObserver promise0xbef398d4
setSource attachmentreader &promise0xbef39864
2017-12-19 11:50:05.231 [ d] 0 MediaPlayer:handleSetSourceCalled
handlesetAttachmentReaderSource promise0xbef39864
2017-12-19 11:50:05.231 [ d] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
getOffset &promise0xbef398a4
2017-12-19 11:50:05.234 [ d] 0 MediaPlayer:handleGetOffsetCalled:idPassed=15,currentId=14
handleGetOffset promise0xbef398a4
2017-12-19 11:50:05.234 [ d] E MediaPlayer:validateSourceAndIdFailed:reason=sourceIdMismatch
2017-12-19 11:50:05.241 [ 2] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testGetOffsetInMillisecondsNullPipeline (23 ms)
[ RUN ] MediaPlayerTest.testGetOffsetWhenStoppedFails
setObserver &promise0xbef398d4
2017-12-19 11:50:05.253 [ e] 0 MediaPlayer:handleSetObserverCalled
handlesetObserver promise0xbef398d4
setSource attachmentreader &promise0xbef3985c
2017-12-19 11:50:05.253 [ e] 0 MediaPlayer:handleSetSourceCalled
handlesetAttachmentReaderSource promise0xbef3985c
2017-12-19 11:50:05.254 [ e] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
Play &promise0xbef3989c
2017-12-19 11:50:05.258 [ e] 0 MediaPlayer:handlePlayCalled:idPassed=15,currentId=15
handlePlay promise0xbef3989c
2017-12-19 11:50:05.258 [ e] 0 MediaPlayer:handlePlayCalled after validate source and ID

2017-12-19 11:50:05.258 [ e] 0 MediaPlayer:handlePlayCalled after gst_element_get_state

2017-12-19 11:50:05.258 [ e] 0 MediaPlayer:handlePlayCalled after GST_STATE_PLAYING

2017-12-19 11:50:05.258 [ e] 0 MediaPlayer:handlePlayCalled before set state

2017-12-19 11:50:05.258 [ e] 0 MediaPlayer:handlePlay:attemptBuffering=0
Failed to create secure directory (/home/root/.config/pulse): Read-only file system
2017-12-19 11:50:05.279 [ e] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
OnPadAdded &promise0xb54f5b44
handlePadAdded promise0xb54f5b44
2017-12-19 11:50:05.425 [ e] 0 MediaPlayer:callingOnTags
2017-12-19 11:50:05.426 [ e] 0 MediaPlayer:callingOnTags
2017-12-19 11:50:05.428 [ e] 0 MediaPlayer:callingOnPlaybackStarted:currentId=15
2017-12-19 11:50:05.437 [ e] 0 MediaPlayer:callingOnTags
Stop &promise0xbef3989c
2017-12-19 11:50:06.436 [ e] 0 MediaPlayer:handleStopCalled:idPassed=15,currentId=15
handleStop promise0xbef3989c
2017-12-19 11:50:06.456 [ e] 0 MediaPlayer:callingOnPlaybackStopped:currentId=15
getOffset &promise0xbef3989c
2017-12-19 11:50:06.457 [ e] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2017-12-19 11:50:06.458 [ e] 0 MediaPlayer:handleGetOffsetCalled:idPassed=15,currentId=0
handleGetOffset promise0xbef3989c
2017-12-19 11:50:06.458 [ e] E MediaPlayer:validateSourceAndIdFailed:reason=sourceNotSet
2017-12-19 11:50:06.461 [ 2] E RequiresShutdown:RequiresShutdownFailed:reason=notShutdown,name=
[ OK ] MediaPlayerTest.testGetOffsetWhenStoppedFails (1220 ms)
[ RUN ] MediaPlayerTest.testGetOffsetWhenPaused
setObserver &promise0xbef398d4
2017-12-19 11:50:06.469 [ f] 0 MediaPlayer:handleSetObserverCalled
handlesetObserver promise0xbef398d4
setSource attachmentreader &promise0xbef3985c
2017-12-19 11:50:06.469 [ f] 0 MediaPlayer:handleSetSourceCalled
handlesetAttachmentReaderSource promise0xbef3985c
2017-12-19 11:50:06.469 [ f] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
terminate called after throwing an instance of 'std::future_error'
what(): Promise already satisfied
Aborted (core dumped)
root@info3-low:#
root@info3-low:~#

I can see the same promise being used in multiple methods, though it is stack variable.
You were correct , this is initialization or cleanup issue. Do you know how to cleanup std::promise after being set to true in the case of handlePlay.
I am still struggling to understand this weird issue. is G++ is the culprit here.

@dhananjayj29
Copy link
Author

regarding the ubuntu 14.04 , I am having some issue with the setup today for v1.3 version and could not get the logs. so for ubuntu 14.04 m still not sure whether same issue occurs or not.

As previous testing for ubuntu 14.04 was done on v1.1.0 and there I found multiple issues with promise setting which were resolved in v1.3 version.

@sanjayrd
Copy link
Contributor

sanjayrd commented Jan 2, 2018

Hi @dhananjayj29,

Thanks for confirming. It doesn't really seem to be a code or std::promise issue, but rather some sort of issue with your compiler possibly re-using memory twice when allocating promises, or not cleaning up the metadata associated with a promise properly - either way, very strange.

I've been searching around and couldn't find any known issues around GCC 4.8.2 about this sort of behavior unfortunately.

I wonder if it would be possible to allocate the std::promises differently, maybe as a heap variable instead to guarantee a different address be used.

Thanks,
Sanjay

@dhananjayj29
Copy link
Author

used heap variables .. and fixed this issue

@yerasiprathyusha
Copy link

yerasiprathyusha commented Apr 5, 2018 •
edited
Loading

Hi @dhananjayj29,

I am also facing the same issue on embedded environment (arm7l with openwrt using AVS device sdkVersion: 1.6.0). Can you please share the fixes you did about using std::promises as heap variable. It will be really helpful for me.

Thank in advance

@kclchan kclchan mentioned this issue Dec 12, 2018
Closed
8 tasks
@charlesexu
Copy link

Hi @dhananjayj29, I have the similar issue porting avs device sdk (version 1.9.0) on an Amlogic board. Could you please share your fix about using std::promises as heap variable. Thanks.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
6 participants
@sanjayrd @yerasiprathyusha @mradulan @anu-mathur @dhananjayj29 @charlesexu