New Install of Alexa Sample App on Raspberry Pi 3 - No audio received

[brightselect]

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

Briefly summarize your issue:

I just installed Avs-device-sdk on the Raspberry Stretch (Pi 3) following the wiki. The install went fine. All tests run through with 100% passed. The Alexa sample app starts and is responding to the commands but there is no audio from the speaker. I am using the 3.5mm audio jack and usb microphone. Am able to record and play the test recording using instructions in the step by step guide. Also playback on youtube using browser works fine. The debug log shows errors¨
InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.¨

What is the expected behavior?

Alexa should respond with playback of the respective command on the speaker

What behavior are you observing?

There is no audio from the speaker. There are errors in the log file

Provide the steps to reproduce the issue, if applicable:

Follow steps in the https://github.com/alexa/avs-device-sdk/wiki/Raspberry-Pi-Quick-Start-Guide-with-Script

Start Sample App.

Say Alexa - Play News or Ẅhat is time or What is the weather

Tell us about your environment:

What version of the AVS Device SDK are you using?

 Last version from https://github.com/alexa/avs-device-sdk/wiki/Raspberry-Pi-Quick-Start-Guide-with-Script

Tell us what hardware you're using:

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

Tell us about your OS (Type & version):

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

LOG FILES
############################

Listening...

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

2018-01-29 20:57:43.926 [ 4] 0 ContextManager:updateStateLocked:action=updatedState,state={"isEnabled":false,"isVisualIndicatorPersisted":false},namespace=Notifications,name=IndicatorState
2018-01-29 20:57:43.926 [ 9] 0 AudioPlayer:executeProvideState:sendToken=true,stateRequestToken=3
2018-01-29 20:57:43.927 [ 9] 9 MediaPlayer:getOffsetCalled
2018-01-29 20:57:43.927 [ 2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=3,currentId=3
2018-01-29 20:57:43.927 [ 9] 0 ContextManager:updateStateLocked:action=updatedState,state={"token":"amzn1.as-ct.v1.Domain:Application:DailyBriefing:TTS#ACRI#url#ACRI#DailyBriefingPrompt.55e7939c-a88d-4249-abb7-6ab9f40d9660:ChannelItem:0:0","offsetInMilliseconds":22569,"playerActivity":"PLAYING"},namespace=AudioPlayer,name=PlaybackState
2018-01-29 20:57:43.928 [ 7] 0 ContextManager:buildContextSuccessful:context={"context":[{"header":{"namespace":"Speaker","name":"VolumeState"},"payload":{"volume":100,"muted":false}},{"header":{"namespace":"Notifications","name":"IndicatorState"},"payload":{"isEnabled":false,"isVisualIndicatorPersisted":false}},{"header":{"namespace":"SpeechSynthesizer","name":"SpeechState"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:DailyBriefing:TTS#ACRI#DailyBriefingPrompt.ChannelIntroduction.55e7939c-a88d-4249-abb7-6ab9f40d9660:Say:DAILYBRIEFING:DailyBriefingIntroduction","offsetInMilliseconds":0,"playerActivity":"FINISHED"}},{"header":{"namespace":"AudioPlayer","name":"PlaybackState"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:DailyBriefing:TTS#ACRI#url#ACRI#DailyBriefingPrompt.55e7939c-a88d-4249-abb7-6ab9f40d9660:ChannelItem:0:0","offsetInMilliseconds":22569,"playerActivity":"PLAYING"}},{"header":{"namespace":"SpeechRecognizer","name":"RecognizerState"},"payload":{"wakeword":"alexa"}},{"header":{"namespace":"Alerts","name":"AlertsState"},"payload":{"allAlerts":[],"activeAlerts":[]}}]}
2018-01-29 20:57:43.929 [ a] 0 AudioInputProcessor:executeOnContextAvailable:jsonContext={"context":[{"header":{"namespace":"Speaker","name":"VolumeState"},"payload":{"volume":100,"muted":false}},{"header":{"namespace":"Notifications","name":"IndicatorState"},"payload":{"isEnabled":false,"isVisualIndicatorPersisted":false}},{"header":{"namespace":"SpeechSynthesizer","name":"SpeechState"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:DailyBriefing:TTS#ACRI#DailyBriefingPrompt.ChannelIntroduction.55e7939c-a88d-4249-abb7-6ab9f40d9660:Say:DAILYBRIEFING:DailyBriefingIntroduction","offsetInMilliseconds":0,"playerActivity":"FINISHED"}},{"header":{"namespace":"AudioPlayer","name":"PlaybackState"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:DailyBriefing:TTS#ACRI#url#ACRI#DailyBriefingPrompt.55e7939c-a88d-4249-abb7-6ab9f40d9660:ChannelItem:0:0","offsetInMilliseconds":22569,"playerActivity":"PLAYING"}},{"header":{"namespace":"SpeechRecognizer","name":"RecognizerState"},"payload":{"wakeword":"alexa"}},{"header":{"namespace":"Alerts","name":"AlertsState"},"payload":{"allAlerts":[],"activeAlerts":[]}}]}
2018-01-29 20:57:43.929 [ a] 1 FocusManager:acquireChannel:channelName=Dialog,activityId=SpeechRecognizer.Recognize
2018-01-29 20:57:43.929 [ a] I DirectiveProcessor:setDialogRequestIdLocked:oldValue=7723a4cb-01c8-45a0-940e-a6bf7c4e174e,newValue=12450185-ee90-4b87-ae75-b67daa700af0
2018-01-29 20:57:43.930 [ a] 0 DirectiveProcessor:scrubDialogRequestIdLocked:dialogRequestId=7723a4cb-01c8-45a0-940e-a6bf7c4e174e
2018-01-29 20:57:43.931 [ a] 0 EventBuilder:buildJsonEventString:messageId=2f3505ac-6571-4664-8d64-eaf4bacf6fcc,namespace=SpeechRecognizer,name=Recognize
2018-01-29 20:57:43.932 [ e] 0 AudioPlayer:onFocusChanged:newFocus=BACKGROUND
2018-01-29 20:57:43.932 [ 9] 1 AudioPlayer:executeOnFocusChanged:from=FOREGROUND,to=BACKGROUND,m_currentActivity=PLAYING
2018-01-29 20:57:43.932 [ 9] 1 AudioPlayer:executeOnFocusChanged:action=pauseMediaPlayer
2018-01-29 20:57:43.932 [ 9] 9 MediaPlayer:pausedCalled
2018-01-29 20:57:43.933 [ 2] 0 MediaPlayer:handlePauseCalled:idPassed=3,currentId=3
2018-01-29 20:57:43.935 [ 2] 9 MediaPlayer:messageReceived:type=state-changed,source=audio_sink-actual-sink-omxhdmiaudio
2018-01-29 20:57:43.935 [ 2] 9 MediaPlayer:messageReceived:type=state-changed,source=audio_sink
2018-01-29 20:57:43.935 [ 2] 9 MediaPlayer:messageReceived:type=state-changed,source=volume
2018-01-29 20:57:43.935 [ 2] 9 MediaPlayer:messageReceived:type=state-changed,source=converter
2018-01-29 20:57:43.935 [ 2] 9 MediaPlayer:messageReceived:type=state-changed,source=decodedQueue
2018-01-29 20:57:43.936 [ 2] 9 MediaPlayer:messageReceived:type=state-changed,source=avdec_mp3-2
2018-01-29 20:57:43.936 [ 2] 9 MediaPlayer:messageReceived:type=state-changed,source=mpegaudioparse2
2018-01-29 20:57:43.936 [ 2] 9 MediaPlayer:messageReceived:type=state-changed,source=id3demux2
2018-01-29 20:57:43.936 [ 2] 9 MediaPlayer:messageReceived:type=state-changed,source=typefind
2018-01-29 20:57:43.936 [ 2] 9 MediaPlayer:messageReceived:type=state-changed,source=decoder
2018-01-29 20:57:43.936 [ 2] 9 MediaPlayer:messageReceived:type=state-changed,source=src
2018-01-29 20:57:43.936 [ 2] 9 MediaPlayer:messageReceived:type=state-changed,source=audio-pipeline
2018-01-29 20:57:43.936 [ 2] 9 MediaPlayer:State Change:oldState=PLAYING,newState=PAUSED,pendingState=VOID_PENDING
2018-01-29 20:57:43.936 [ 2] 0 MediaPlayer:callingOnPlaybackPaused:currentId=3
2018-01-29 20:57:43.936 [ 2] 0 AudioPlayer:onPlaybackPaused:id=3
2018-01-29 20:57:43.936 [ 9] 1 AudioPlayer:executeOnPlaybackPaused:id=3
2018-01-29 20:57:43.937 [ 9] 1 AudioPlayer:sendEventWithTokenAndOffset:eventName=PlaybackPaused
2018-01-29 20:57:43.937 [ 9] 9 MediaPlayer:getOffsetCalled
2018-01-29 20:57:43.937 [ 2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=3,currentId=3
2018-01-29 20:57:43.938 [ 9] 0 EventBuilder:buildJsonEventString:messageId=1567daf4-7d65-4475-9b0e-40a234d574b9,namespace=AudioPlayer,name=PlaybackPaused
2018-01-29 20:57:43.938 [ 9] 9 HTTP2Transport:enqueueRequest:jsonContent={"event":{"header":{"namespace":"AudioPlayer","name":"PlaybackPaused","messageId":"1567daf4-7d65-4475-9b0e-40a234d574b9"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:DailyBriefing:TTS#ACRI#url#ACRI#DailyBriefingPrompt.55e7939c-a88d-4249-abb7-6ab9f40d9660:ChannelItem:0:0","offsetInMilliseconds":21814}}}
2018-01-29 20:57:43.938 [ 9] 0 AudioPlayer:changeActivity:from=PLAYING,to=PAUSED
2018-01-29 20:57:43.939 [ 9] 0 AudioPlayer:executeProvideState:sendToken=false,stateRequestToken=0
2018-01-29 20:57:43.939 [ e] 9 AudioInputProcessor:onFocusChanged:newFocus=FOREGROUND
2018-01-29 20:57:43.939 [ 9] 9 MediaPlayer:getOffsetCalled
2018-01-29 20:57:43.939 [ 2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=3,currentId=3
2018-01-29 20:57:43.939 [ a] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=FOREGROUND
2018-01-29 20:57:43.939 [ a] 9 HTTP2Transport:enqueueRequest:jsonContent={"context":[{"header":{"namespace":"Speaker","name":"VolumeState"},"payload":{"volume":100,"muted":false}},{"header":{"namespace":"Notifications","name":"IndicatorState"},"payload":{"isEnabled":false,"isVisualIndicatorPersisted":false}},{"header":{"namespace":"SpeechSynthesizer","name":"SpeechState"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:DailyBriefing:TTS#ACRI#DailyBriefingPrompt.ChannelIntroduction.55e7939c-a88d-4249-abb7-6ab9f40d9660:Say:DAILYBRIEFING:DailyBriefingIntroduction","offsetInMilliseconds":0,"playerActivity":"FINISHED"}},{"header":{"namespace":"AudioPlayer","name":"PlaybackState"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:DailyBriefing:TTS#ACRI#url#ACRI#DailyBriefingPrompt.55e7939c-a88d-4249-abb7-6ab9f40d9660:ChannelItem:0:0","offsetInMilliseconds":22569,"playerActivity":"PLAYING"}},{"header":{"namespace":"SpeechRecognizer","name":"RecognizerState"},"payload":{"wakeword":"alexa"}},{"header":{"namespace":"Alerts","name":"AlertsState"},"payload":{"allAlerts":[],"activeAlerts":[]}}],"event":{"header":{"namespace":"SpeechRecognizer","name":"Recognize","messageId":"2f3505ac-6571-4664-8d64-eaf4bacf6fcc","dialogRequestId":"12450185-ee90-4b87-ae75-b67daa700af0"},"payload":{"profile":"NEAR_FIELD","format":"AUDIO_L16_RATE_16000_CHANNELS_1","initiator":{"type":"WAKEWORD","payload":{"wakeWordIndices":{"startIndexInSamples":8000,"endIndexInSamples":15680}}}}}}
2018-01-29 20:57:43.940 [ 9] 0 ContextManager:updateStateLocked:action=updatedState,state={"token":"amzn1.as-ct.v1.Domain:Application:DailyBriefing:TTS#ACRI#url#ACRI#DailyBriefingPrompt.55e7939c-a88d-4249-abb7-6ab9f40d9660:ChannelItem:0:0","offsetInMilliseconds":21814,"playerActivity":"PAUSED"},namespace=AudioPlayer,name=PlaybackState
2018-01-29 20:57:43.940 [ 9] 9 MediaPlayer:getOffsetCalled
2018-01-29 20:57:43.940 [ 2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=3,currentId=3
2018-01-29 20:57:43.940 [ 9] 1 AudioPlayer:notifyObserver:playerActivity=PAUSED
2018-01-29 20:57:43.940 [ 9] 9 TemplateRuntime:onPlayerActivityChanged
2018-01-29 20:57:43.941 [ c] 0 TemplateRuntime:onPlayerActivityChangedInExecutor
2018-01-29 20:57:43.941 [ c] 0 TemplateRuntime:executeAudioPlayerInfoUpdates:audioItemId=amzn1.as-ct.v1.Domain:Application:DailyBriefing:TTS#ACRI#url#ACRI#DailyBriefingPrompt.55e7939c-a88d-4249-abb7-6ab9f40d9660:ChannelItem:0:0,offset=21814,audioPlayerState=PAUSED,isRenderTemplatelastReceived=false
2018-01-29 20:57:43.941 [ c] 0 TemplateRuntime:executeRenderPlayerInfoCallbacks
2018-01-29 20:57:43.973 [ 17] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:43.973 [ 16] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:44.029 [ b] 0 HTTP2Transport:processNextOutgoingMessage:jsonContent={"event":{"header":{"namespace":"AudioPlayer","name":"PlaybackPaused","messageId":"1567daf4-7d65-4475-9b0e-40a234d574b9"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:DailyBriefing:TTS#ACRI#url#ACRI#DailyBriefingPrompt.55e7939c-a88d-4249-abb7-6ab9f40d9660:ChannelItem:0:0","offsetInMilliseconds":21814}}}
2018-01-29 20:57:44.029 [ b] 0 HTTP2StreamPool:getStream:streamId=61,numAcquiredStreams=2
2018-01-29 20:57:44.030 [ b] 9 HTTP2Transport:insertActiveStream:handle=0x6f7d4520
2018-01-29 20:57:44.030 [ b] I HTTP2Stream:libcurl:streamId=61,text=Found bundle for host avs-alexa-na.amazon.com: 0x6f701020 [can multiplex]
2018-01-29 20:57:44.030 [ b] I HTTP2Stream:libcurl:streamId=61,text=Conn: 0 (0x6f700778) Receive pipe weight: (-1/0), penalized: (nil)
2018-01-29 20:57:44.030 [ b] I HTTP2Stream:libcurl:streamId=61,text=Multiplexed connection found!
2018-01-29 20:57:44.030 [ b] I HTTP2Stream:libcurl:streamId=61,text=Found connection 0, with requests in the pipe (1)
2018-01-29 20:57:44.030 [ b] I HTTP2Stream:libcurl:streamId=61,text=Re-using existing connection! (#0) with host avs-alexa-na.amazon.com
2018-01-29 20:57:44.031 [ b] I HTTP2Stream:libcurl:streamId=61,text=Using Stream ID: 3d (easy handle 0x6f7d4520)
2018-01-29 20:57:44.073 [ 17] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:44.073 [ 16] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:44.174 [ 17] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:44.174 [ 16] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:44.274 [ 17] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:44.274 [ 16] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:44.375 [ 17] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:44.375 [ 16] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:44.396 [ b] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid: 0a6690fffe928ed2-00007724-00001bd3-df7950c0883fd5ec-6f66cb2a-61
2018-01-29 20:57:44.396 [ b] I HTTP2Stream:libcurl:streamId=61,text=Curl_http_done: called premature == 0
2018-01-29 20:57:44.396 [ b] 0 HTTP2Transport:cleanupFinishedStream:streamId=61,result=204
2018-01-29 20:57:44.396 [ b] 0 HTTP2StreamPool:releaseStream:streamId=61,numAcquiredStreams=1
2018-01-29 20:57:44.397 [ b] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2018-01-29 20:57:44.397 [ b] 0 HTTP2Transport:processNextOutgoingMessage:jsonContent={"context":[{"header":{"namespace":"Speaker","name":"VolumeState"},"payload":{"volume":100,"muted":false}},{"header":{"namespace":"Notifications","name":"IndicatorState"},"payload":{"isEnabled":false,"isVisualIndicatorPersisted":false}},{"header":{"namespace":"SpeechSynthesizer","name":"SpeechState"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:DailyBriefing:TTS#ACRI#DailyBriefingPrompt.ChannelIntroduction.55e7939c-a88d-4249-abb7-6ab9f40d9660:Say:DAILYBRIEFING:DailyBriefingIntroduction","offsetInMilliseconds":0,"playerActivity":"FINISHED"}},{"header":{"namespace":"AudioPlayer","name":"PlaybackState"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:DailyBriefing:TTS#ACRI#url#ACRI#DailyBriefingPrompt.55e7939c-a88d-4249-abb7-6ab9f40d9660:ChannelItem:0:0","offsetInMilliseconds":22569,"playerActivity":"PLAYING"}},{"header":{"namespace":"SpeechRecognizer","name":"RecognizerState"},"payload":{"wakeword":"alexa"}},{"header":{"namespace":"Alerts","name":"AlertsState"},"payload":{"allAlerts":[],"activeAlerts":[]}}],"event":{"header":{"namespace":"SpeechRecognizer","name":"Recognize","messageId":"2f3505ac-6571-4664-8d64-eaf4bacf6fcc","dialogRequestId":"12450185-ee90-4b87-ae75-b67daa700af0"},"payload":{"profile":"NEAR_FIELD","format":"AUDIO_L16_RATE_16000_CHANNELS_1","initiator":{"type":"WAKEWORD","payload":{"wakeWordIndices":{"startIndexInSamples":8000,"endIndexInSamples":15680}}}}}}
2018-01-29 20:57:44.397 [ b] 0 HTTP2StreamPool:getStream:streamId=63,numAcquiredStreams=2
2018-01-29 20:57:44.397 [ b] 9 HTTP2Transport:insertActiveStream:handle=0x6f7d4520
2018-01-29 20:57:44.397 [ b] I HTTP2Stream:libcurl:streamId=63,text=Found bundle for host avs-alexa-na.amazon.com: 0x6f701020 [can multiplex]
2018-01-29 20:57:44.398 [ b] I HTTP2Stream:libcurl:streamId=63,text=Conn: 0 (0x6f700778) Receive pipe weight: (-1/0), penalized: (nil)
2018-01-29 20:57:44.398 [ b] I HTTP2Stream:libcurl:streamId=63,text=Multiplexed connection found!
2018-01-29 20:57:44.398 [ b] I HTTP2Stream:libcurl:streamId=63,text=Found connection 0, with requests in the pipe (1)
2018-01-29 20:57:44.398 [ b] I HTTP2Stream:libcurl:streamId=63,text=Re-using existing connection! (#0) with host avs-alexa-na.amazon.com
2018-01-29 20:57:44.398 [ b] I HTTP2Stream:libcurl:streamId=63,text=Using Stream ID: 3f (easy handle 0x6f7d4520)
2018-01-29 20:57:44.475 [ 17] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:44.475 [ 16] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:44.575 [ 17] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:44.576 [ 16] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:44.676 [ 17] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:44.676 [ 16] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:44.777 [ 17] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:44.777 [ 16] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:44.877 [ 17] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:44.878 [ 16] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:44.978 [ 17] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:44.978 [ 16] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:45.078 [ 17] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:45.078 [ 16] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:45.179 [ 17] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:45.179 [ 16] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:45.279 [ 17] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:45.279 [ 16] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:45.379 [ 17] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:45.379 [ 16] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:45.479 [ 17] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:45.479 [ 16] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:45.579 [ 17] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:45.580 [ 16] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:45.680 [ 17] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:45.680 [ 16] 9 InProcessAttachmentWriter:AttachmentWriter has timed out while attempting a write.
2018-01-29 20:57:45.718 [ f] 0 MessageInterpreter:receive:messageId=4ed3d253-24b5-4898-a052-cc6b30835885:No dialogRequestId attached to message.
2018-01-29 20:57:45.718 [ f] I DirectiveSequencer:onDirective:directive={"namespace:"SpeechRecognizer",name:"StopCapture",messageId:"4ed3d253-24b5-4898-a052-cc6b30835885",dialogRequestId:""}
2018-01-29 20:57:45.718 [ 10] I DirectiveRouter:preHandleDirective:messageId=4ed3d253-24b5-4898-a052-cc6b30835885,action=calling
2018-01-29 20:57:45.719 [ 10] 0 CapabilityAgent:addingMessageIdToMap:messageId=4ed3d253-24b5-4898-a052-cc6b30835885
2018-01-29 20:57:45.720 [ 11] I DirectiveRouter:handleDirective:messageId=4ed3d253-24b5-4898-a052-cc6b30835885,action=calling
2018-01-29 20:57:45.720 [ a] 0 AudioInputProcessor:stopCapture:stopImmediately=true
2018-01-29 20:57:45.720 [ a] 0 AudioInputProcessor:setState:from=RECOGNIZING,to=BUSY
2018-01-29 20:57:45.721 [ d] 0 DialogUXStateAggregator:setState:from=LISTENING,to=THINKING
2018-01-29 20:57:45.721 [ a] 0 DirectiveProcessor:onHandlingCompeted:messageId=4ed3d253-24b5-4898-a052-cc6b30835885,directiveBeingPreHandled=(nullptr)
2018-01-29 20:57:45.722 [ a] 0 CapabilityAgent:removingMessageIdFromMap:messageId=4ed3d253-24b5-4898-a052-cc6b30835885

[frozenberg]

Hi @brightselect,

The error messages you are seeing are actually expected and benign. The problem lies elsewhere. What does your boot/config.txt file look like?

Apparently some users are reporting sound issues being fixed by commenting out the line hdmi_force_hotplug=1.

Just for clarification: sound is working through the 3.5mm jack but not through speakers, or your speakers are plugged into the 3.5mm jack? Have you tried with an hdmi?

Fede

[brightselect]

it works with hdmi, although the stream gets terminated before the message is finished
it does not work with speakers connected to the audio jack. commenting the hdmi_force_hotplug=1 did not fix the issue. I am able to record a test file using command line and then playback to the audio jack

[frozenberg]

I see. Can you try running gst-launch-1.0 -m audiotestsrc ! autoaudiosink and tell me if you get a tone?

And as a follow-up, can you try changing line 577 inMediaPlayer.cpp from

m_pipeline.audioSink = gst_element_factory_make("autoaudiosink", "audio_sink");

to

m_pipeline.audioSink = gst_element_factory_make("alsasink", "audio_sink");

?

Thanks
Fede

[Doxylamin]

I actually have the same problem at the moment. Unfortunately it seems, that gst-launch-1.0 wasn't installed during the automated setup procedure.

[frozenberg]

Hi @Doxylamin,

That's interesting! Were you able to install the package needed for gst-launch?

If not, run sudo apt-get install gstreamer1.0-tools and let me know if that works. We will update the automated setup script with that if necessary since it seems to be a useful debugging tool.

[brightselect]

Hi Fede

I did the following but it did not fix issue. There is a new error in the log from media player "could not open audio device". Detailed log is below. Thanks for helping with this

1] installed gstreamer1.0-tools - This did not fix issue. so changed Mediaplayer
2] ran gst-launch-1.0 -m audiotestsrc ! autoaudiosink - There was no tone
3] Changed the code on MediaPlayer

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

Thinking...

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

2018-01-30 21:11:18.146 [ b] I InProcessAttachmentReader:readFailed:reason=SDS is closed
2018-01-30 21:11:18.758 [ b] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid: 060981fffe2b68be-00001b38-00021b54-e688bb1299b17310-2e4d84ec-5
2018-01-30 21:11:18.834 [ f] I DirectiveSequencer:onDirective:directive={"namespace:"SpeechSynthesizer",name:"Speak",messageId:"e2f3d3ab-3143-4578-9575-5b977dab3c6a",dialogRequestId:"52a8d85d-5115-4477-b063-ba12fd1e7794"}
2018-01-30 21:11:18.835 [ 10] I DirectiveRouter:preHandleDirective:messageId=e2f3d3ab-3143-4578-9575-5b977dab3c6a,action=calling
2018-01-30 21:11:18.835 [ 10] 0 CapabilityAgent:addingMessageIdToMap:messageId=e2f3d3ab-3143-4578-9575-5b977dab3c6a
2018-01-30 21:11:18.835 [ 10] 9 SpeechSynthesizer:preHandleDirective:messageId=e2f3d3ab-3143-4578-9575-5b977dab3c6a
2018-01-30 21:11:18.836 [ 8] 0 SpeechSynthesizer:executePreHandle:messageId=e2f3d3ab-3143-4578-9575-5b977dab3c6a
2018-01-30 21:11:18.836 [ 11] I DirectiveRouter:handleDirective:messageId=e2f3d3ab-3143-4578-9575-5b977dab3c6a,action=calling
2018-01-30 21:11:18.836 [ 11] 9 SpeechSynthesizer:handleDirective:messageId=e2f3d3ab-3143-4578-9575-5b977dab3c6a
2018-01-30 21:11:18.839 [ 8] 0 SpeechSynthesizer:executeHandle:messageId=e2f3d3ab-3143-4578-9575-5b977dab3c6a
2018-01-30 21:11:18.839 [ 8] 1 FocusManager:acquireChannel:channelName=Dialog,activityId=SpeechSynthesizer.Speak
2018-01-30 21:11:18.840 [ e] 9 AudioInputProcessor:onFocusChanged:newFocus=NONE
2018-01-30 21:11:18.840 [ a] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=NONE
2018-01-30 21:11:18.840 [ e] 0 SpeechSynthesizer:onFocusChanged:newFocus=FOREGROUND
2018-01-30 21:11:18.840 [ a] 0 AudioInputProcessor:executeOnFocusChanged:reason=Lost focus
2018-01-30 21:11:18.840 [ a] 0 AudioInputProcessor:setState:from=BUSY,to=IDLE
2018-01-30 21:11:18.840 [ e] 9 SpeechSynthesizer:setCurrentStateLocked:state=GAINING_FOCUS
2018-01-30 21:11:18.841 [ 8] 0 SpeechSynthesizer:executeStateChange:newState=PLAYING
2018-01-30 21:11:18.841 [ 8] 9 SpeechSynthesizer:startPlaying
2018-01-30 21:11:18.841 [ 8] 9 MediaPlayer:setSourceCalled:sourceType=AttachmentReader
2018-01-30 21:11:18.841 [ 2] 0 MediaPlayer:handleSetSourceCalled
2018-01-30 21:11:18.841 [ 2] 9 MediaPlayer:tearDownTransientPipelineElements
2018-01-30 21:11:18.842 [ 2] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2018-01-30 21:11:18.845 [ 8] 9 MediaPlayer:playCalled
2018-01-30 21:11:18.845 [ 2] 0 MediaPlayer:handlePlayCalled:idPassed=2,currentId=2
2018-01-30 21:11:18.846 [ 2] 0 MediaPlayer:handlePlay:attemptBuffering=0
2018-01-30 21:11:18.846 [ 2] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=FAILURE
2018-01-30 21:11:18.847 [ 2] E MediaPlayer:handlePlayFailed::reason=gstElementSetStateFailure
2018-01-30 21:11:18.847 [ 2] 0 MediaPlayer:callingOnPlaybackError:type=MEDIA_ERROR_INTERNAL_DEVICE_ERROR,error=reason=gstElementSetStateFailure,currentId=2
2018-01-30 21:11:18.847 [ 2] 9 SpeechSynthesizer:onPlaybackError:callbackSourceId=2
2018-01-30 21:11:18.847 [ 2] 9 MediaPlayer:tearDownTransientPipelineElements
2018-01-30 21:11:18.847 [ 8] 0 SpeechSynthesizer:executePlaybackError:type=MEDIA_ERROR_INTERNAL_DEVICE_ERROR,error=reason=gstElementSetStateFailure
2018-01-30 21:11:18.847 [ 8] 9 SpeechSynthesizer:setCurrentStateLocked:state=FINISHED
2018-01-30 21:11:18.847 [ 8] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0
2018-01-30 21:11:18.847 [ 2] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2018-01-30 21:11:18.847 [ 2] 9 BaseStreamSource:~BaseStreamSource
2018-01-30 21:11:18.848 [ 8] 0 ContextManager:updateStateLocked:action=updatedState,state={"token":"amzn1.as-ct.v1.Domain:Application:Weather#ACRI#c5010329-b126-419b-ac0b-2afa17488dfa#Alexa3P:1.0/2018/01/30/21/60e8dc47110741de96da042f3d773f23/11:16::TNIH_2V.4a0a7a1c-a944-48a7-9098-c08e51f229a3ZXV/0","offsetInMilliseconds":0,"playerActivity":"FINISHED"},namespace=SpeechSynthesizer,name=SpeechState
2018-01-30 21:11:18.848 [ 8] 9 SpeechSynthesizer:releaseForegroundFocus
2018-01-30 21:11:18.848 [ 8] 1 FocusManager:releaseChannel:channelName=Dialog
2018-01-30 21:11:18.849 [ 8] 0 CapabilityAgent:removingMessageIdFromMap:messageId=e2f3d3ab-3143-4578-9575-5b977dab3c6a
2018-01-30 21:11:18.849 [ 2] 9 MediaPlayer:messageReceived:type=error,source=audio_sink
2018-01-30 21:11:18.849 [ 2] E MediaPlayer:handleBusMessageError:source=audio_sink,error=Could not open audio device for playback.,debug=gstalsasink.c(863): gst_alsasink_open (): /GstPipeline:audio-pipeline/GstAlsaSink:audio_sink:
Playback open error on device 'default': Invalid argument
2018-01-30 21:11:18.849 [ 8] 0 EventBuilder:buildJsonEventString:messageId=b443e3a9-0788-4d67-96fb-0527ddfe4d1e,namespace=System,name=ExceptionEncountered
2018-01-30 21:11:18.850 [ 8] 9 HTTP2Transport:enqueueRequest:jsonContent={"context":[],"event":{"header":{"namespace":"System","name":"ExceptionEncountered","messageId":"b443e3a9-0788-4d67-96fb-0527ddfe4d1e"},"payload":{"unparsedDirective":"{\"directive\":{\"header\":{\"namespace\":\"SpeechSynthesizer\",\"name\":\"Speak\",\"messageId\":\"e2f3d3ab-3143-4578-9575-5b977dab3c6a\",\"dialogRequestId\":\"52a8d85d-5115-4477-b063-ba12fd1e7794\"},\"payload\":{\"url\":\"cid:c5010329-b126-419b-ac0b-2afa17488dfa#Alexa3P:1.0/2018/01/30/21/60e8dc47110741de96da042f3d773f23/11:16::TNIH_2V.4a0a7a1c-a944-48a7-9098-c08e51f229a3ZXV/0_649552231\",\"format\":\"AUDIO_MPEG\",\"token\":\"amzn1.as-ct.v1.Domain:Application:Weather#ACRI#c5010329-b126-419b-ac0b-2afa17488dfa#Alexa3P:1.0/2018/01/30/21/60e8dc47110741de96da042f3d773f23/11:16::TNIH_2V.4a0a7a1c-a944-48a7-9098-c08e51f229a3ZXV/0\"}}}","error":{"type":"INTERNAL_ERROR","message":"reason=gstElementSetStateFailure"}}}}
2018-01-30 21:11:18.851 [ 8] 0 DirectiveProcessor:onHandlingFailed:messageId=e2f3d3ab-3143-4578-9575-5b977dab3c6a,directiveBeingPreHandled=(nullptr),description=reason=gstElementSetStateFailure
2018-01-30 21:11:18.851 [ 8] 0 DirectiveProcessor:scrubDialogRequestIdLocked:dialogRequestId=52a8d85d-5115-4477-b063-ba12fd1e7794
2018-01-30 21:11:18.851 [ 8] 0 CapabilityAgent:removingMessageIdFromMap:messageId=e2f3d3ab-3143-4578-9575-5b977dab3c6a
2018-01-30 21:11:18.853 [ b] 0 HTTP2Transport:processNextOutgoingMessage:jsonContent={"context":[],"event":{"header":{"namespace":"System","name":"ExceptionEncountered","messageId":"b443e3a9-0788-4d67-96fb-0527ddfe4d1e"},"payload":{"unparsedDirective":"{\"directive\":{\"header\":{\"namespace\":\"SpeechSynthesizer\",\"name\":\"Speak\",\"messageId\":\"e2f3d3ab-3143-4578-9575-5b977dab3c6a\",\"dialogRequestId\":\"52a8d85d-5115-4477-b063-ba12fd1e7794\"},\"payload\":{\"url\":\"cid:c5010329-b126-419b-ac0b-2afa17488dfa#Alexa3P:1.0/2018/01/30/21/60e8dc47110741de96da042f3d773f23/11:16::TNIH_2V.4a0a7a1c-a944-48a7-9098-c08e51f229a3ZXV/0_649552231\",\"format\":\"AUDIO_MPEG\",\"token\":\"amzn1.as-ct.v1.Domain:Application:Weather#ACRI#c5010329-b126-419b-ac0b-2afa17488dfa#Alexa3P:1.0/2018/01/30/21/60e8dc47110741de96da042f3d773f23/11:16::TNIH_2V.4a0a7a1c-a944-48a7-9098-c08e51f229a3ZXV/0\"}}}","error":{"type":"INTERNAL_ERROR","message":"reason=gstElementSetStateFailure"}}}}
2018-01-30 21:11:18.853 [ b] 0 HTTP2StreamPool:getStream:streamId=11,numAcquiredStreams=3
2018-01-30 21:11:18.854 [ b] 9 HTTP2Transport:insertActiveStream:handle=0x63000018
2018-01-30 21:11:18.855 [ b] I HTTP2Stream:libcurl:streamId=11,text=Found bundle for host avs-alexa-na.amazon.com: 0x74002068 [can multiplex]
2018-01-30 21:11:18.855 [ b] I HTTP2Stream:libcurl:streamId=11,text=Conn: 0 (0x74001758) Receive pipe weight: (-1/0), penalized: (nil)
2018-01-30 21:11:18.855 [ b] I HTTP2Stream:libcurl:streamId=11,text=Multiplexed connection found!
2018-01-30 21:11:18.855 [ b] I HTTP2Stream:libcurl:streamId=11,text=Found connection 0, with requests in the pipe (2)
2018-01-30 21:11:18.855 [ b] I HTTP2Stream:libcurl:streamId=11,text=Re-using existing connection! (#0) with host avs-alexa-na.amazon.com
2018-01-30 21:11:18.856 [ b] I HTTP2Stream:libcurl:streamId=11,text=Using Stream ID: b (easy handle 0x63000018)
2018-01-30 21:11:19.021 [ b] I HTTP2Stream:libcurl:streamId=9,text=Curl_http_done: called premature == 0
2018-01-30 21:11:19.021 [ b] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid: 060981fffe2b68be-00001b38-00021b31-9299d56529b1d3c2-a1dcc8a1-11
2018-01-30 21:11:19.021 [ b] I HTTP2Stream:libcurl:streamId=11,text=Curl_http_done: called premature == 0
2018-01-30 21:11:19.022 [ b] 0 AudioInputProcessor:onSendCompleted:status=SUCCESS
2018-01-30 21:11:19.022 [ b] 0 HTTP2Transport:cleanupFinishedStream:streamId=9,result=200
2018-01-30 21:11:19.022 [ b] 0 HTTP2StreamPool:releaseStream:streamId=9,numAcquiredStreams=2
2018-01-30 21:11:19.022 [ b] 0 HTTP2Transport:cleanupFinishedStream:streamId=11,result=204
2018-01-30 21:11:19.022 [ b] 0 HTTP2StreamPool:releaseStream:streamId=11,numAcquiredStreams=1
2018-01-30 21:11:19.022 [ b] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2018-01-30 21:11:19.053 [ d] 0 DialogUXStateAggregator:setState:from=THINKING,to=IDLE

[brightselect]

Hi Fede, Doxylamin
some good news. i was able to get this to work in a full headless mode. I reverted the MediaPlayer code back to the original. Looks like the problem is with hooking hdmi to a monitor with no speaker and using the 3.55mm jack for audio. Installing the gstreamer-tools helped since I had tried headless mode before posting the issue.

Thanks

[Doxylamin]

@brightselect Cool! Have the same setup as you. So it worked without a monitor attached and gstreamer-tools installed, have I got this right?

[brightselect]

yes, that is correct. Don't connect a monitor. you can enable vnc or ssh into the device to start the app

[XcafebabeX]

@brightselect it worked ,thx.