After some seconds or song change, sound is gone

[Hanfrey]

Hi,

tried the latest version. Music App is working, Spotify I dont get any sound at all.
When I'm listening around 40seconds later the sound is gone. And need to reconnect to get it back.
I have built it on a Raspberry PI 3B. Any ideas?
This is the log:

2021/07/28 16:13:28 Starting goplay for device Pi: bca06227-f4ab-48b7-8dcb-f51203092507, guid: bca06227-f4ab-48b7-8dcb-f51203092507, Psi: bca06227-f4ab-48b7-8dcb-f51203092507


2021/07/28 16:13:35 request received : GET /info body 70
2021/07/28 16:13:35 response sent : body 374
2021/07/28 16:13:35 request received : POST /pair-verify body 37
2021/07/28 16:13:35 response sent : body 140
2021/07/28 16:13:35 request received : POST /pair-verify body 106
2021/07/28 16:13:35 response sent : body 3
2021/07/28 16:13:35 request received : POST /fp-setup body 16
2021/07/28 16:13:35 response sent : body 142
2021/07/28 16:13:35 request received : POST /fp-setup body 164
2021/07/28 16:13:35 response sent : body 32
2021/07/28 16:13:35 request received : SETUP rtsp://192.168.1.163/3208386018501087130 body 1044
2021/07/28 16:13:35 response sent : body 76
2021/07/28 16:13:35 request received : GET /info body 0
2021/07/28 16:13:35 response sent : body 374
2021/07/28 16:13:35 request received : GET_PARAMETER rtsp://192.168.1.163/3208386018501087130 body 8
2021/07/28 16:13:35 response sent : body 20
2021/07/28 16:13:35 request received : RECORD rtsp://192.168.1.163/3208386018501087130 body 0
2021/07/28 16:13:35 response sent : body 0
2021/07/28 16:13:35 request received : SETPEERS rtsp://192.168.1.163/3208386018501087130 body 128
2021/07/28 16:13:35 response sent : body 0
2021/07/28 16:13:35 request received : POST /command body 5873
2021/07/28 16:13:35 response sent : body 0
2021/07/28 16:13:35 request received : SETUP rtsp://192.168.1.163/3208386018501087130 body 271
2021/07/28 16:13:35 response sent : body 151
2021/07/28 16:13:35 request received : POST /audioMode body 64
2021/07/28 16:13:35 response sent : body 0
2021/07/28 16:13:36 request received : SETRATEANCHORTIME rtsp://192.168.1.163/3208386018501087130 body 190
2021/07/28 16:13:36 response sent : body 0
2021/07/28 16:13:36 request received : POST /command body 5873
2021/07/28 16:13:36 response sent : body 0
2021/07/28 16:13:37 request received : POST /feedback body 0
2021/07/28 16:13:37 response sent : body 0
---
021/07/28 16:16:57 response sent : body 0
2021/07/28 16:16:59 request received : POST /feedback body 0
2021/07/28 16:16:59 response sent : body 0
2021/07/28 16:17:00 request received : SETRATEANCHORTIME rtsp://192.168.1.163/3208386018501087130 body 53
2021/07/28 16:17:00 response sent : body 0
2021/07/28 16:17:01 request received : POST /feedback body 0
2021/07/28 16:17:01 response sent : body 0
2021/07/28 16:17:03 request received : POST /feedback body 0
2021/07/28 16:17:03 response sent : body 0
2021/07/28 16:17:05 request received : POST /feedback body 0
2021/07/28 16:17:05 response sent : body 0
2021/07/28 16:17:07 request received : POST /feedback body 0
2021/07/28 16:17:07 response sent : body 0
2021/07/28 16:17:09 request received : POST /feedback body 0
2021/07/28 16:17:09 response sent : body 0
---

[AlbanSeurat]

As for spotify, this is not - yet - supported (check the README)

For the sound issue, I have replace alsa to PulseAudio yesterday, so the latest version might have undiscovered issue.

I did listen for hours yesterday without problems - on a Linux desktop - and your messages does not prompt any errors.

What client are you using (iPhone ? HomePod ? Mac Apple Music ?)

[Hanfrey]

iPhone with iOS 14.6.
Is there a way I can get you better logs?

[AlbanSeurat]

Usually the logs are good enough - All errors should be reported.
I use goplay2 also on my Raspberry Pi 1B.
I will "stress test" to try to reproduce the issue.

You can try to look at pulseaudio logs as specified here : https://fedoraproject.org/wiki/How_to_debug_PulseAudio_problems but I have some concerns that it will be either too verbose or useless...

I have added some logs on the latest main branch. It logs when the player add silence to the audio stream to "sync audio clocks". Let me know if you can have a look. I will also look on my side.

[AlbanSeurat]

I have updated git main branch where I have remove temporary audio sync (which is still WIP anyway).
On resources constraint computer, it seems to cause issues (ex: raspi1).
Let me know if you still have the issue with the latest main branch (commit : ee330ab)

[Hanfrey]

Much better, but still after some minutes or change of song its gone.

`2021/07/29 08:41:50 response sent : body 0
2021/07/29 08:41:52 request received : POST /feedback body 0
2021/07/29 08:41:52 response sent : body 0
2021/07/29 08:41:54 request received : POST /feedback body 0
2021/07/29 08:41:54 response sent : body 0
2021/07/29 08:41:56 request received : SETRATEANCHORTIME rtsp://192.168.1.163/3589820991905680461 body 53
2021/07/29 08:41:56 response sent : body 0
2021/07/29 08:41:57 request received : POST /feedback body 0
2021/07/29 08:41:57 response sent : body 0
2021/07/29 08:41:58 server.go:62: Error:error decoding to pcm EOF
2021/07/29 08:41:58 request received : TEARDOWN rtsp://192.168.1.163/3589820991905680461 body 84
2021/07/29 08:41:58 response sent : body 0
2021/07/29 08:41:59 request received : POST /feedback body 0
2021/07/29 08:41:59 response sent : body 0

`

But maybe thats now an error in the log?

[AlbanSeurat]

2021/07/29 08:41:58 server.go:62: Error:error decoding to pcm EOF
This error means that the network connection is closed by your iPhone (or a network issue).
Just after you receive the TEARDOWN command witch mean your iPhone want to stop playing the song...
What is strange is that it happens just after you change the anchor time (change of position in the song or change of song).

I did not encounter this behaviour during my tests yesterday on raspi1 (listen to for 2/3 hours).

I am working actively to improve audio sync (including buffering).
You probably heard that when you change the song, it continue during a little bit the previous song, the new git branch eliminates that. You may want to try the branch (feature/audio-sync) as it improve things around "SETRATEANCHORTIME".

Be careful, it is actively developed and things may brake.

[Hanfrey]

As additional information, when the error occured with the pcm eof, I did not change the song or the position or anything else. Also no network error. It just stops in the middle of a song.

I just tested also the branch.

5 Songs played so far, without problems :).

Edit:
And 3 Songs later its gone again :(.

If I try to reconnect then:

2021/07/29 12:53:32 response sent : body 0
2021/07/29 12:53:34 request received : POST /feedback body 0
2021/07/29 12:53:34 response sent : body 0
2021/07/29 12:53:35 server.go:62: Error:error decoding to pcm EOF
2021/07/29 12:53:35 request received : TEARDOWN rtsp://192.168.1.163/17908395563336484027 body 84
2021/07/29 12:53:35 response sent : body 0
2021/07/29 12:53:35 request received : TEARDOWN rtsp://192.168.1.163/17908395563336484027 body 42
2021/07/29 12:53:35 response sent : body 0
2021/07/29 12:53:35 server.go:37: Error:Event error : EOF
2021/07/29 12:53:35 server.go:76: Error:Error parsing RSTP request EOF 
2021/07/29 12:53:38 request received : GET /info body 70
2021/07/29 12:53:38 response sent : body 374
2021/07/29 12:53:38 request received : POST /pair-verify body 37
2021/07/29 12:53:38 response sent : body 140
2021/07/29 12:53:38 request received : POST /pair-verify body 106
2021/07/29 12:53:38 response sent : body 3
2021/07/29 12:53:38 request received : POST /fp-setup body 16
2021/07/29 12:53:38 response sent : body 142
2021/07/29 12:53:38 request received : POST /fp-setup body 164
2021/07/29 12:53:38 response sent : body 32
2021/07/29 12:53:38 request received : SETUP rtsp://192.168.1.163/2815465839488287524 body 1046
2021/07/29 12:53:38 response sent : body 76
2021/07/29 12:53:38 request received : GET /info body 0
2021/07/29 12:53:38 response sent : body 374
2021/07/29 12:53:38 request received : GET_PARAMETER rtsp://192.168.1.163/2815465839488287524 body 8
2021/07/29 12:53:38 response sent : body 19
2021/07/29 12:53:38 request received : RECORD rtsp://192.168.1.163/2815465839488287524 body 0
2021/07/29 12:53:38 response sent : body 0
2021/07/29 12:53:38 request received : SETPEERS rtsp://192.168.1.163/2815465839488287524 body 129
2021/07/29 12:53:38 response sent : body 0
2021/07/29 12:53:38 request received : POST /command body 5873
2021/07/29 12:53:38 response sent : body 0
2021/07/29 12:53:40 request received : POST /feedback body 0
2021/07/29 12:53:40 response sent : body 0
2021/07/29 12:53:41 request received : SETUP rtsp://192.168.1.163/2815465839488287524 body 271
2021/07/29 12:53:41 response sent : body 151
2021/07/29 12:53:41 request received : POST /audioMode body 64
2021/07/29 12:53:41 response sent : body 0
2021/07/29 12:53:41 request received : SETRATEANCHORTIME rtsp://192.168.1.163/2815465839488287524 body 190

Complete restart of goplay2 and I can play again.

[AlbanSeurat]

Hello,

This unexpected network - related - issue is really a behaviour I have never encountered.
On my experience for every "error decoding to pcm EOF", there was a "real" network issue.

Anyway, to save CPU time I have moved part of the PCM decoding elsewhere. I push my changes on the feature/audio-sync branch.

Do you have many other things running on your raspberry? Is is possible that there was some swapping or cpu congestion ? Which version of libfdk-acc have you on your system ?

[Hanfrey]

So, I tried the newest commit:

pcm eof error is gone from logs, it just stops. First, try after 40seconds, second try after 2:30min, no error in the log.

libfdk-aac-dev (1:2.0.0-dmo1).

Network: iPhone is in 5GHz Network, PI 3B is connected per Ethernet. I just have running Homebridge on the Pi, don't think this takes so much CPU time, since I'm not doing anything at that moment, just idle.

Maybe I just try it again in 1-2 Months?

[AlbanSeurat]

Let's do that :). I have a Raspberry Pi 3b, I will install goplay2 on it. Which distrib are you using ?

Sorry to not be more helpful, I have no issue like yours and the absence of logs puzzles me. Alls errors are catched and logged. That is really strange as it work seamlessly on my raspi1, linux and mac...

[Hanfrey]

Pretty old -> Raspbian GNU/Linux 9 (stretch). I have it running since years for homebridge.
At first I also had built the goplay in the docker container and took it out from the container, but since the Makefile is gone, this didnt work anymore. I also tried it on my macbook, but there I even cant connect :(.

[AlbanSeurat]

Thanks.
As for Apple Music on Mac, it is known as not working. It need to support some custom crypto (MFI version 3, usually back by some hardware HSM...). One step at a time...
As for docker, I will remove the build as it is worthless (Bonjour does not work by default with docker) and the build is quite simple anyway.

I let you know when I have improve things. I will probably add some more verbose logs (like request body and responses).

Thanks again for you help