Unable to cast to Chromecast Audio device

[BonkaBonka]

The log:

[2016-06-25 11:29:59] [  LOG]     cast: No RECEIVER_STATUS reply to our LAUNCH - aborting
[2016-06-25 11:29:59] [  LOG]   player: Cannot start playback: no output started
[2016-06-25 11:29:59] [  LOG]     cast: Bug! Shutdown request got wanted_state that is higher than current state
[2016-06-25 11:29:59] [  LOG]      mpd: Error executing command 'play': Failed to start playback

In case it matters, I'm using the ympd web client to control forked-daapd and am trying to play a single .mp3 file.

[ejurgensen]

Thanks for reporting this. I had a look at it, but was not able to understand how this happens. Does it happen every time? In that case it would be great if you could repeat and submit the relevant parts of the log with the log level set to "debug" in the config.

[BonkaBonka]

Sorry this took so long to get to you:

[2016-06-27 21:56:14] [ INFO]     cast: Connection to 'Family Room' established using TLS1.2
[2016-06-27 21:56:14] [DEBUG]     cast: TX 88 sender-0 receiver-0 urn:x-cast:com.google.cast.tp.connection {"type":"CONNECT"}
[2016-06-27 21:56:14] [DEBUG]     cast: TX 100 sender-0 receiver-0 urn:x-cast:com.google.cast.receiver {"type":"GET_STATUS","request
Id":1}
[2016-06-27 21:56:14] [ INFO]   player: Using selected Chromecast device 'Family Room'
[2016-06-27 21:56:14] [DEBUG]     cast: RX 538 receiver-0 sender-0 urn:x-cast:com.google.cast.receiver {"requestId":1,"status":{"app
lications":[{"appId":"CC1AD845","displayName":"Default Media Receiver","isIdleScreen":false,"namespaces":[{"name":"urn:x-cast:com.go
ogle.cast.media"},{"name":"urn:x-cast:com.google.cast.inject"}],"sessionId":"2D8B4268-1A52-4476-AA04-3D049F96F4FA","statusText":"Rea
dy To Cast","transportId":"web-19"}],"volume":{"controlType":"attenuation","level":0.22745098173618317,"muted":false,"stepInterval":
0.05000000074505806}},"type":"RECEIVER_STATUS"}
[2016-06-27 21:56:14] [DEBUG]     cast: TX 115 sender-0 receiver-0 urn:x-cast:com.google.cast.receiver {"type":"LAUNCH","requestId":2,"appId":"CC1AD845"}
[2016-06-27 21:56:14] [DEBUG]     cast: RX 226 receiver-0 * urn:x-cast:com.google.cast.receiver {"requestId":0,"status":{"volume":{"controlType":"attenuation","level":0.22745098173618317,"muted":false,"stepInterval":0.05000000074505806}},"type":"RECEIVER_STATUS"}
[2016-06-27 21:56:14] [DEBUG]     cast: RX 452 receiver-0 * urn:x-cast:com.google.cast.receiver {"requestId":0,"status":{"volume":{"controlType":"attenuation","level":0.22745098173618317,"muted":false,"stepInterval":0.05000000074505806}},"type":"RECEIVER_STATUS"}
[2016-06-27 21:56:15] [DEBUG]     cast: RX 1062 receiver-0 * urn:x-cast:com.google.cast.receiver {"requestId":0,"status":{"applications":[{"appId":"CC1AD845","displayName":"Default Media Receiver","isIdleScreen":false,"namespaces":[{"name":"urn:x-cast:com.google.cast.media"},{"name":"urn:x-cast:com.google.cast.inject"}],"sessionId":"7441062C-6D43-4002-B89A-B0B55D0DC6EE","statusText":"Ready To Cast","transportId":"web-20"}],"volume":{"controlType":"attenuation","level":0.22745098173618317,"muted":false,"stepInterval":0.05000000074505806}},"type":"RECEIVER_STATUS"}
[2016-06-27 21:56:19] [ WARN]     cast: Request timeout, will run empty callbacks
[2016-06-27 21:56:19] [  LOG]     cast: No RECEIVER_STATUS reply to our LAUNCH - aborting
[2016-06-27 21:56:19] [DEBUG]     cast: TX 86 sender-0 receiver-0 urn:x-cast:com.google.cast.tp.connection {"type":"CLOSE"}
[2016-06-27 21:56:19] [DEBUG]   player: Callback from Chromecast to device_restart_cb
[2016-06-27 21:56:19] [  LOG]   player: Cannot start playback: no output started
[2016-06-27 21:56:19] [  LOG]     cast: Bug! Shutdown request got wanted_state that is higher than current state
[2016-06-27 21:56:19] [DEBUG]    xcode: Flushing output stream #0 encoder
[2016-06-27 21:56:19] [DEBUG]   ffmpeg: Statistics: 229376 bytes read, 0 seeks
[2016-06-27 21:56:19] [DEBUG]      mpd: Listener callback called with event type 1.
[2016-06-27 21:56:19] [  LOG]      mpd: Error executing command 'play': Failed to start playback
[2016-06-27 21:56:19] [DEBUG]      mpd: Notify clients waiting for idle results: 1
[2016-06-27 21:56:19] [DEBUG]      mpd: MPD message: status
[2016-06-27 21:56:19] [DEBUG]   player: Player status: stopped
[2016-06-27 21:56:19] [DEBUG]      mpd: MPD message: outputs

Annoyingly, this seems to be somewhat network related - that is to say, when I first got home last night and before all the neighbors cranked up their Netflix, I wasn't able to duplicate the bug! After dinner, I had nothing but trouble and was only rarely ever able to make it work (with pauses and fast-forwards caused by congestion).

So, perhaps relaxing the timing a bit on the callback would make it work more often.

[ejurgensen]

Seems there might be two separate problems: 1) Playback not starting, 2) Interruptions during playback. The latter might well be caused by network problems, which could disturb the mp3 stream. The cause of the former is likely something else, because your log suggests that the Chromecast did indeed "respond" before the timeout (with 3 broadcasts at 21:56:14-15), but not with the expected response (which would not be a broadcast). I need to investigate further what could be the cause of the missing response.

[ejurgensen]

I think I found the bug and have it fixed with the latest commits referenced above. Please let me know if the problem persists.