Chromecast activation fails ("Could not unpack message")

[Lakritzator]

I use forked-daapd for my multi-room audio system, it's running 24x7 on my "NAS" (ubuntu server 14.x). My players are a couple of Chromecast audios, and a Denon AVR-X1200W

My use-case is to have one (or more) chromecasts play radio around the time we wake up, so I can just turn on a mini-amplifier in my bathroom and radio is playing.

As somehow the playing stuff after a while, I use mpc in a crontab script, where I make sure that before getting up all outputs are disabled and the one I need is enabled. (mpc disable with all the outputs I don't want). Than I enable only the one I need. (should work with mpc enable only <output> but it doesn't). And I use load / play to have the song play, set the volume to 100% (the amplifier is used to control the volume.

Most of the time this works, sometimes it doesn't. mpc commandos sometimes seem to take a long time to complete. This is also is visible in other clients. Now when this doesn't work sometimes forked-daapd just decides to have the Denon play the music (maybe because it didn't disable correctly, maybe just because), which turns on the Amplifier und does exactly what it was told... play a stream at 100% Volume. We already had disco 2x at 4:30 in the morning...

In fact there are multiple things in this issue:

1. "mpd" output control (mpc enable / mpc disable) seems to be flawed
2. "mpd" commands seem to be unstable
3. playing internet radio seems to break every now and than.
4. Outputs seem to be picked at "random" (I actually think it just picked the first) for whatever reason.
5. I don't want my Denon to be at 100% volume, but my Chromecasts should be, it would be nice if I can control a range...?

In the logs I only found a few entries that were of relevance:

• mpd: No speaker to deactivate
• mpd: Error executing command 'enableoutput': Speakers activation failed: 47113 What is interesting about the last entry, there is no 47113 but a 47114 (Chromecast GROUP) and I am 100% sure I didn't try to enable 47113 but 47114!

Sorry for the longer text, but my wife really doesn't like the solution right now... How can I (we?) tackle these issues? What information do you need?

[ejurgensen]

Thanks for your post, it was kind of amusing, and I see your wife's point very well :-) I would very much like to fix these things, but I will need your help to do it. Some patience would also be required, because bugs that can't consistently be reproduced are hard to fix. I also don't have multiple Chromecast audio devices, so testing audio groups is difficult for me.

So the first steps:

1. I need you to confirm that you are using the latest version of forked-daapd (24.1). If you have you have cloned and built from here recently then it is of course perfect.
2. Set the log level to "debug", so I can see what exactly is going on.
3. Protect your wife's sleep by setting "max_volume" in the config for the Denon. This will set a range, like you asked, but is of course no solution for the other stuff.

The next step is to become a bit more clear on what the actual issues are. So next time you have issued a command, and the result is not as expected, I would like you to share the log (maybe through pastebin or gist). Not the entire thing - just the part from where the command is received to where it has been processed.

[Lakritzator]

Thanks for the quick answer, yes the wife was NOT AMUSED to say at least... if this continues she will buy a 5€ radio to put in our bathroom :smile:

I am already at Version 24.1, at least this is what --version tells me, I guess only the merge from a couple of days ago is not in it. I will make some logs.

I don't know where to find this max_volume, I did found something for airplay but how can I set it for a specific device? Is there documentation I don't know of?

[ejurgensen]

The max_volume setting is in the below part of the config. So 1) uncomment the lines with airplay, max_volume and ending bracket, 2) change the "My AirPlay device" to the name of your Denon, 3) set the max_volume to something lower than 11.

# AirPlay/Airport Express device settings
# (make sure you get the capitalization of the device name right)
#airplay "My AirPlay device" {
    # forked-daapd's volume goes to 11! If that's more than you can handle
    # you can set a lower value here
#   max_volume = 11

    # AirPlay password
#   password = "s1kr3t"
#}

[Lakritzator]

Today it happened again, I unfortunately didn't have spare time to put in the volume fix...

I have enabled debug in the log, and here are some details:

mpc outputs gives me: Output 59409 (RP-AC52(F0:79:59:E8:E8:10) is disabled Output 10826 (BadezimmerKromcast) is disabled Output 47114 (Kromcast) is disabled Output 34005 (SchlaffzimmerKromcast) is disabled Output 1 (Computer) is disabled` (Pulled out the denon, to prevent disco, the 1 is probably my laptop)

In the attached log, I can see the following when I try to enable 10826 via `mpc enable 10826'

forked-daapd.txt

Hope this helps!?

[ejurgensen]

Good log output, the interesting part is this: [2016-07-29 04:50:58] [ LOG] cast: Could not unpack message! This means that the Chromecast sent a reply that was unreadable or in an unexpected format. So forked-daapd gives up on the device and tries to enable another device (which in this use case is not desirable, but in others it is). Forked-daapd uses a library to parse messages from the Chromecast, so I'm not sure what to do next. Maybe make a little patch for you in branch here on Github that will log the raw reply? Would you be able to build and run such a modified version of forked-daapd?

I'd also like to know if you seen this error before? You didn't mention it in your original post.

[Lakritzator]

Yeah, make a branch and I can test it, no problem.

Is it possible to turn off the feature that another device is used? Somehow configurable? I really don't know why people would want this...

I don't know if the error was there before, if it is visible in the normal output I must have missed this... if it's only in verbose output than I never saw it.

Btw. what is up with the confusing output IDs, why would mpc enable 10826 give me an error where 10825 is mentioned? Also in the log there are completely different ID's in the output.

[ejurgensen]

Autoselecting a speaker is desirable if you use Remote on iPhone - which is one of the main uses of forked-daapd. In Remote, you can only switch speaker during playback. This would result in a catch 22 if playback cannot be started because the speaker is failing. So autoselection is the solution for that. There is no config option for it, because no one has needed it. If this Chromecast issue wasn't there, then you probably wouldn't either :-)

The error would have been visible on normal log level (that's what [LOG] indicates).

Don't know about those id's. Yes, they do seem rather confusing. As I remember, the MPD protocol has a size limit to the id's, so that is why you see short id's and long id's in the log. Doesn't explain why 10826 becomes 10825, of course.

[Lakritzator]

Interesting fact, I do understand it and it's kinda funny that this made me wake up about 3 times now at 4:30

I probably overlooked the error, sorry.

Ah yes, had a quick look in the source... the short ID is just a "int 32" cast on the int 64 ID.

I also don't understand the funny output ID -1 "bug", in the output it uses the result for the safe_atou32 of the argument string... maybe the argument is wronly passed? Anyway, I can't search forked repositories on Github so this has to wait.

Any idee when you might be able to supply the branch, not to stress you (!!) but just so I can plan it a bit?

P.S. In mpd.c function mpd_command_enableoutput it says: ret = asprintf(errmsg, "Missing argument for command 'disableoutput'");

Probably it should be: ret = asprintf(errmsg, "Missing argument for command 'enableoutput'");

[ejurgensen]

Fixed the typos in mpd.c, thanks. Here is a branch where the raw reply from the Chromecast will be logged (base64-encoded): https://github.com/ejurgensen/forked-daapd/tree/dbgcast

Hope the bug shows up soon again!

[ejurgensen]

BTW, here is the explanation of the off-by-one thing: http://git.musicpd.org/cgit/master/mpc.git/tree/src/command.c#n163

So just something mpc does internally for presentation purposes. A bit odd, maybe, but nothing to worry about.

[Lakritzator]

How can I check if your changes are active, I switched to the branch did a make clean and started forked-daapd. The problem seems to be reproducable in the current state of my infrastructur but the log doesn't add anything. Is "forked-daapd -d 5" right?

[Lakritzator]

make clean and make install ofcourse.. :smile:

And I just checked the git status, but it would be weird if I made a mistak (use git daily)

root@nas:~/forked-daapd# git status
# On branch origin/dbgcast
# Changes not staged for commit:
#   (use "git add <file>..." to update what will be committed)
#   (use "git checkout -- <file>..." to discard changes in working directory)
#
#       modified:   forked-daapd.conf

Oh, and the volume setting max_volume works very nicely, the one time I saw it in the config I wasn't sure it woud work for my AV-Reciever, forgetting it supports AirPlay. Or does the setting work for any device?

[Lakritzator]

This is really weird, there isn't a single Chromecast working anymore when I try to control it from forked-daapd. Playing from the Chome browser doesn't give any issues.

This is why I am able to reproduce the problem, currently nothing goes when it's Chomecast related.

I don't know when this started, we somewhat got used to not having music as I didn't have time to look what the problem was. There might be different reasons, maybe an ubuntu library update? Or maybe it did start with a pull on the git repo, but others should than have the same issue...

Any idea? I'm still hoping to get more information in the logs, but up to now it's just the single line that was already there...

[ejurgensen]

Mine works ok. There must be more information in the logs if you built using the dbgcast branch. It should be very verbose about the exact communication. Are you sure got it installed and running ok?

[Lakritzator]

Oh, I didn't notice the file was not uploaded. Here is it: fd.txt

It might be more verbose, but I don't see the message....? Maybe it helps you.

[ejurgensen]

It is clear from the log that you are not running the "dbgcast" version of forked-daapd. It is still the old version. If you did "make install" the new version might be in /usr/local/sbin, and if you didn't you can just run it from your build dir.

Anyway, I suddenly got the bug as well, and this led me to a possible fix. I have added that to the branch, as you can see above. You can get it with git pull. It fixed the problem for me, and I hope it also works for you. Please let me know.

[Lakritzator]

Hi, I overloaded the fact that the branch switch didn't work, professionals make mistakes when they quickly want to do something :)

So, I got your changes and this made it possible to play again, at least there is that! Thanks. I will check your change later on, as I am curious what the problem was.

But last night at 4:30 my crontab job kicked in and tried to play my internet radio stream on the bathroom chromecast. Somehow this didn't work, I have attached the log: forked-daapd-startplay.txt

Important to know, it is visible in the log that it was still playing (started it at 01:30) and than the script kicks in. (I could build a check for the state, and skip, but still I think this should have worked)

mpc clear
mpc outputs | grep -E "Denon|BadezimmerKromcast|WohnzimmerKromcast|Schlaffzimmer" | cut -d\  -f2 | xargs mpc disable
sleep 2
mpc outputs | grep -E "BadezimmerKromcast" | cut -d\  -f2 | xargs mpc enable
sleep 2
mpc outputs |grep enabled | grep Denon
if [ "$?" == "0" ]; then
   echo "Not the Denon!!"
   exit
fi
mpc load file:/mnt/serverdisk/music/Playlists/Radio
mpc play 1
mpc volume 100

One other detail, my home-automation is requesting status updates via mpc every couple of seconds, this might be visible in the log too.

Can you see what went wrong?

[Lakritzator]

I have to add, while writing my previous comment, I also managed to start the playing again.

Just because I wanted to try the scenario from last night again, I did start the script again just now... and it failed again. (error: Failed to start playback)

Maybe it helps to have another log, the scenario was the same. forked-daapd-again.txt

Important: It's not directly reproducable, I can't just start the script 2x to provoke it.

[ejurgensen]

It seems the original problem is now resolved, but that you are now running into the same as issue #270. This is where the Chromecast sometimes seems to omit a response that forked-daapd is expecting. I'll be looking at that soon.

[ejurgensen]

I've added a commit to the dbgcast branch, which I hope fixes the second issue. I was, however, not able to reproduce this problem. I even copied your script and ran it a bunch of times, but that didn't trigger the problem either. So I could only test my fix by simulating the problem. That means I don't know if it actually solves the true problem. In any case, I hope you will test with this fix.

[Lakritzator]

I will try to test this tonight, thanks a lot!

[Lakritzator]

I was able to reproduce the problem that the playback didn't start correctly. After a couple of tries, where everything went well, it suddenly failed.

It's the last try, so probably you'd just want to scroll back from the end.

forked-daapd-playingbug.txt

[ejurgensen]

Thanks for the quick test. From your log, I spotted yet a problem. I've added a new commit to dbgcast, which should fix it. Hope you will pull it and test again. Still not sure it will fix the actual issue, though.

Wish I could test myself. Do you just run the script a few times? If so, is the device playing from forked-daapd when you run the script? Is it a Chromecast or a Chromecast Audio?

[Lakritzator]

No problem, I gladly test this.

The device is a Chromecast Audio

It's not always reproducible, it seems that I usually need to wait a while after the script worked. But that is not a fact... 😞

It was playing from forked-daapd when the script was run, but the definition of "was it playing" depends on person to person. As the script clears the queue, disables all the outputs (mpc enable only xxxxx doesn't work) and than enables the bathroom chromecast (my lastname is Krom, that is why Kromcast 😄 ) loads a playlist and starts playing item 1. That means, that at the time the play is ordered, it doesn't play...

[Lakritzator]

I just wanted to report back that with the changes from 4 days ago I don't see any problems any more! The system has been playing for a couple of days, and the script always worked.

Do you need logs, or something?

If possible, I still would like to have the possibility to disable the "take any output" feature you explained, this could wreak havoc in my house! :wink:

[ejurgensen]

Sounds good, thanks for the feedback. To confirm that the changes actually make a difference it would be great if you could extract from the logs with the following command: grep "cast:" /var/log/forked-daapd | grep -10 "trying GET_STATUS"

If this returns empty then the condition didn't occur, so you should continue testing.

I'll consider an option, but to keep the peace at home couldn't your script first mute, then check what is selected and then turn up the volume if ok?

[Lakritzator]

Is this okay?

/var/log/forked-daapd.log:[2016-08-05 11:45:08] [DEBUG]     cast: REPLY DUMP (len 217): CAASCnJlY2VpdmVyLTAaCHNlbmRlci0wIiN1cm46eC1jYXN0OmNvbS5nb29nbGUuY2FzdC5yZWNlaXZlcigAMpcBeyJyZXF1ZXN0SWQiOjEsInN0YXR1cyI6eyJ2b2x1bWUiOnsiY29udHJvbFR5cGUiOiJhdHRlbnVhdGlvbiIsImxldmVsIjoxLjAsIm11dGVkIjpmYWxzZSwic3RlcEludGVydmFsIjowLjA1MDAwMDAwMDc0NTA1ODA2fX0sInR5cGUiOiJSRUNFSVZFUl9TVEFUVVMifQ==
/var/log/forked-daapd.log:[2016-08-05 11:45:08] [DEBUG]     cast: RX 217 receiver-0 sender-0 urn:x-cast:com.google.cast.receiver {"requestId":1,"status":{"volume":{"controlType":"attenuation","level":1.0,"muted":false,"stepInterval":0.05000000074505806}},"type":"RECEIVER_STATUS"}
/var/log/forked-daapd.log:[2016-08-05 11:45:08] [DEBUG]     cast: Preparing to send message type 7 to 'BadezimmerKromcast'
/var/log/forked-daapd.log:[2016-08-05 11:45:08] [DEBUG]     cast: TX 115 sender-0 receiver-0 urn:x-cast:com.google.cast.receiver {"type":"LAUNCH","requestId":2,"appId":"CC1AD845"}
/var/log/forked-daapd.log:[2016-08-05 11:45:09] [DEBUG]     cast: New data from 'BadezimmerKromcast'
/var/log/forked-daapd.log:[2016-08-05 11:45:09] [DEBUG]     cast: Received 519 bytes
/var/log/forked-daapd.log:[2016-08-05 11:45:09] [DEBUG]     cast: Received 519 bytes
/var/log/forked-daapd.log:[2016-08-05 11:45:09] [DEBUG]     cast: REPLY DUMP (len 1034): CAASCnJlY2VpdmVyLTAaASoiI3Vybjp4LWNhc3Q6Y29tLmdvb2dsZS5jYXN0LnJlY2VpdmVyKAAyyAN7InJlcXVlc3RJZCI6Miwic3RhdHVzIjp7ImFwcGxpY2F0aW9ucyI6W3siYXBwSWQiOiJDQzFBRDg0NSIsImRpc3BsYXlOYW1lIjoiRGVmYXVsdCBNZWRpYSBSZWNlaXZlciIsImlzSWRsZVNjcmVlbiI6ZmFsc2UsIm5hbWVzcGFjZXMiOlt7Im5hbWUiOiJ1cm46eC1jYXN0OmNvbS5nb29nbGUuY2FzdC5tZWRpYSJ9LHsibmFtZSI6InVybjp4LWNhc3Q6Y29tLmdvb2dsZS5jYXN0LmluamVjdCJ9XSwic2Vzc2lvbklkIjoiNDZFODc3N0UtMEM1My00QTVELTg3QkMtMTc1REIwN0UzOUNFIiwic3RhdHVzVGV4dCI6IlJlYWR5IFRvIENhc3QiLCJ0cmFuc3BvcnRJZCI6IndlYi0xNSJ9XSwidm9sdW1lIjp7ImNvbnRyb2xUeXBlIjoiYXR0ZW51YXRpb24iLCJsZXZlbCI6MS4wLCJtdXRlZCI6ZmFsc2UsInN0ZXBJbnRlcnZhbCI6MC4wNTAwMDAwMDA3NDUwNTgwNn19LCJ0eXBlIjoiUkVDRUlWRVJfU1RBVFVTIn0AAAIDCAASCnJlY2VpdmVyLTAaASoiI3Vybjp4LWNhc3Q6Y29tLmdvb2dsZS5jYXN0LnJlY2VpdmVyKAAyyAN7InJlcXVlc3RJZCI6MCwic3RhdHVzIjp7ImFwcGxpY2F0aW9ucyI6W3siYXBwSWQiOiJDQzFBRDg0NSIsImRpc3BsYXlOYW1lIjoiRGVmYXVsdCBNZWRpYSBSZWNlaXZlciIsImlzSWRsZVNjcmVlbiI6ZmFsc2UsIm5hbWVzcGFjZXMiOlt7Im5hbWUiOiJ1cm46eC1jYXN0OmNvbS5nb29nbGUuY2FzdC5tZWRpYSJ9LHsibmFtZSI6InVybjp4LWNhc3Q6Y29tLmdvb2dsZS5jYXN0LmluamVjdCJ9XSwic2Vzc2lvbklkIjoiNDZFODc3N0UtMEM1My00QTVELTg3QkMtMTc1REIwN0UzOUNFIiwic3RhdHVzVGV4dCI6IlJlYWR5IFRvIENhc3QiLCJ0cmFuc3BvcnRJZCI6IndlYi0xNSJ9XSwidm9sdW1lIjp7ImNvbnRyb2xUeXBlIjoiYXR0ZW51YXRpb24iLCJsZXZlbCI6MS4wLCJtdXRlZCI6ZmFsc2UsInN0ZXBJbnRlcnZhbCI6MC4wNTAwMDAwMDA3NDUwNTgwNn19LCJ0eXBlIjoiUkVDRUlWRVJfU1RBVFVTIn0=
/var/log/forked-daapd.log:[2016-08-05 11:45:09] [  LOG]     cast: Could not unpack message!
/var/log/forked-daapd.log:[2016-08-05 11:45:13] [  LOG]     cast: Request 2 timed out, will run empty callback
/var/log/forked-daapd.log:[2016-08-05 11:45:13] [  LOG]     cast: No RECEIVER_STATUS reply to our LAUNCH - trying GET_STATUS instead
/var/log/forked-daapd.log:[2016-08-05 11:45:13] [DEBUG]     cast: Preparing to send message type 5 to 'BadezimmerKromcast'
/var/log/forked-daapd.log:[2016-08-05 11:45:13] [DEBUG]     cast: TX 100 sender-0 receiver-0 urn:x-cast:com.google.cast.receiver {"type":"GET_STATUS","requestId":3}
/var/log/forked-daapd.log:[2016-08-05 11:45:13] [DEBUG]     cast: New data from 'BadezimmerKromcast'
/var/log/forked-daapd.log:[2016-08-05 11:45:13] [DEBUG]     cast: Received 526 bytes
/var/log/forked-daapd.log:[2016-08-05 11:45:13] [DEBUG]     cast: REPLY DUMP (len 522): CAASCnJlY2VpdmVyLTAaCHNlbmRlci0wIiN1cm46eC1jYXN0OmNvbS5nb29nbGUuY2FzdC5yZWNlaXZlcigAMsgDeyJyZXF1ZXN0SWQiOjMsInN0YXR1cyI6eyJhcHBsaWNhdGlvbnMiOlt7ImFwcElkIjoiQ0MxQUQ4NDUiLCJkaXNwbGF5TmFtZSI6IkRlZmF1bHQgTWVkaWEgUmVjZWl2ZXIiLCJpc0lkbGVTY3JlZW4iOmZhbHNlLCJuYW1lc3BhY2VzIjpbeyJuYW1lIjoidXJuOngtY2FzdDpjb20uZ29vZ2xlLmNhc3QubWVkaWEifSx7Im5hbWUiOiJ1cm46eC1jYXN0OmNvbS5nb29nbGUuY2FzdC5pbmplY3QifV0sInNlc3Npb25JZCI6IjQ2RTg3NzdFLTBDNTMtNEE1RC04N0JDLTE3NURCMDdFMzlDRSIsInN0YXR1c1RleHQiOiJSZWFkeSBUbyBDYXN0IiwidHJhbnNwb3J0SWQiOiJ3ZWItMTUifV0sInZvbHVtZSI6eyJjb250cm9sVHlwZSI6ImF0dGVudWF0aW9uIiwibGV2ZWwiOjEuMCwibXV0ZWQiOmZhbHNlLCJzdGVwSW50ZXJ2YWwiOjAuMDUwMDAwMDAwNzQ1MDU4MDZ9fSwidHlwZSI6IlJFQ0VJVkVSX1NUQVRVUyJ9
/var/log/forked-daapd.log:[2016-08-05 11:45:13] [DEBUG]     cast: RX 522 receiver-0 sender-0 urn:x-cast:com.google.cast.receiver {"requestId":3,"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":"46E8777E-0C53-4A5D-87BC-175DB07E39CE","statusText":"Ready To Cast","transportId":"web-15"}],"volume":{"controlType":"attenuation","level":1.0,"muted":false,"stepInterval":0.05000000074505806}},"type":"RECEIVER_STATUS"}
/var/log/forked-daapd.log:[2016-08-05 11:45:13] [DEBUG]     cast: Preparing to send message type 9 to 'BadezimmerKromcast'
/var/log/forked-daapd.log:[2016-08-05 11:45:13] [DEBUG]     cast: TX 84 sender-0 web-15 urn:x-cast:com.google.cast.tp.connection {"type":"CONNECT"}
/var/log/forked-daapd.log:[2016-08-05 11:45:13] [DEBUG]     cast: Preparing to send message type 11 to 'BadezimmerKromcast'
/var/log/forked-daapd.log:[2016-08-05 11:45:13] [DEBUG]     cast: TX 93 sender-0 web-15 urn:x-cast:com.google.cast.media {"type":"GET_STATUS","requestId":4}

[Lakritzator]

I know I can make workaround for it, but it's not just that.

In general, just consider you have a multi-room system, and you try to play something in room A... it starts playing in room B! Sure I can understand the why, due to the details you gave me, this doesn't mean it's wanted.

[ejurgensen]

Good to hear it is working, but the log output is actually not ok. Still a problem with the unpacking. The good part is that the log made me understand the problem and why some responses from the device went missing. So now I am pretty sure I can fix both this and issue #270. Won't have time for it before next weekend, however. fre. 5. aug. 2016 kl. 14.37 skrev Robin Krom notifications@github.com:

I know I can make workaround for it, but it's not just that.

In general, just consider you have a multi-room system, and you try to play something in room A... it starts playing in room B! Sure I can understand the why, due to the details you gave me, this doesn't mean it's wanted.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/ejurgensen/forked-daapd/issues/275#issuecomment-237829170, or mute the thread https://github.com/notifications/unsubscribe-auth/ABGmTsncm8KbxxAeSQmv6Sl85QHin48Kks5qcyB2gaJpZM4JRnEP .

[Lakritzator]

Super! :+1:

Next weekend is 6-7 or 13-14? Just so I have an idea when I need to take action, it is not a problem if it's the last.

[ejurgensen]

13-14 fre. 5. aug. 2016 kl. 16.27 skrev Robin Krom notifications@github.com:

Super! 👍

Next weekend is 6-7 or 13-14? Just so I have an idea when I need to take action, it is not a problem if it's the last.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/ejurgensen/forked-daapd/issues/275#issuecomment-237849863, or mute the thread https://github.com/notifications/unsubscribe-auth/ABGmTu4GsKGyapoKgjbyhFdvmI9I7Q4Rks5qczpDgaJpZM4JRnEP .

[Lakritzator]

Today it stopped playing our radio stream, once you have a little time can you try to explain what happened?

[2016-08-06 07:43:57] [ INFO]     http: Skipping Shoutcast metadata request for http://mp3.webradio.antenne.de:80 (requires libevent>=2.1.4 or libav 10)
[2016-08-06 07:43:57] [DEBUG]     cast: New data from 'BadezimmerKromcast'
[2016-08-06 07:43:57] [DEBUG]     cast: Received 92 bytes
[2016-08-06 07:43:57] [DEBUG]     cast: REPLY DUMP (len 88): CAASC1RyQG4kcDBydC0wGgtUckBuJHAwcnQtMCIndXJuOngtY2FzdDpjb20uZ29vZ2xlLmNhc3QudHAuaGVhcnRiZWF0KAAyD
3sidHlwZSI6IlBJTkcifQ==
[2016-08-06 07:43:57] [DEBUG]     cast: Preparing to send message type 2 to 'BadezimmerKromcast'
[2016-08-06 07:44:02] [ INFO]     http: Skipping Shoutcast metadata request for http://mp3.webradio.antenne.de:80 (requires libevent>=2.1.4 or libav 10)
[2016-08-06 07:44:03] [DEBUG]     cast: New data from 'BadezimmerKromcast'
[2016-08-06 07:44:03] [DEBUG]     cast: Received 92 bytes
[2016-08-06 07:44:03] [DEBUG]     cast: REPLY DUMP (len 88): CAASC1RyQG4kcDBydC0wGgtUckBuJHAwcnQtMCIndXJuOngtY2FzdDpjb20uZ29vZ2xlLmNhc3QudHAuaGVhcnRiZWF0KAAyD
3sidHlwZSI6IlBJTkcifQ==
[2016-08-06 07:44:03] [DEBUG]     cast: Preparing to send message type 2 to 'BadezimmerKromcast'
[2016-08-06 07:44:07] [ INFO]     http: Skipping Shoutcast metadata request for http://mp3.webradio.antenne.de:80 (requires libevent>=2.1.4 or libav 10)
[2016-08-06 07:44:08] [DEBUG]     cast: New data from 'BadezimmerKromcast'
[2016-08-06 07:44:08] [DEBUG]     cast: Received 92 bytes
[2016-08-06 07:44:08] [DEBUG]     cast: REPLY DUMP (len 88): CAASC1RyQG4kcDBydC0wGgtUckBuJHAwcnQtMCIndXJuOngtY2FzdDpjb20uZ29vZ2xlLmNhc3QudHAuaGVhcnRiZWF0KAAyD
3sidHlwZSI6IlBJTkcifQ==
[2016-08-06 07:44:08] [DEBUG]     cast: Preparing to send message type 2 to 'BadezimmerKromcast'
[2016-08-06 07:44:12] [ INFO]     http: Skipping Shoutcast metadata request for http://mp3.webradio.antenne.de:80 (requires libevent>=2.1.4 or libav 10)
[2016-08-06 07:44:13] [DEBUG]     cast: New data from 'BadezimmerKromcast'
[2016-08-06 07:44:13] [DEBUG]     cast: Received 92 bytes
[2016-08-06 07:44:13] [DEBUG]     cast: REPLY DUMP (len 88): CAASC1RyQG4kcDBydC0wGgtUckBuJHAwcnQtMCIndXJuOngtY2FzdDpjb20uZ29vZ2xlLmNhc3QudHAuaGVhcnRiZWF0KAAyD
3sidHlwZSI6IlBJTkcifQ==
[2016-08-06 07:44:13] [DEBUG]     cast: Preparing to send message type 2 to 'BadezimmerKromcast'
[2016-08-06 07:44:17] [ INFO]     http: Skipping Shoutcast metadata request for http://mp3.webradio.antenne.de:80 (requires libevent>=2.1.4 or libav 10)
[2016-08-06 07:44:18] [DEBUG]     cast: New data from 'BadezimmerKromcast'
[2016-08-06 07:44:18] [DEBUG]     cast: Received 92 bytes
[2016-08-06 07:44:18] [DEBUG]     cast: REPLY DUMP (len 88): CAASC1RyQG4kcDBydC0wGgtUckBuJHAwcnQtMCIndXJuOngtY2FzdDpjb20uZ29vZ2xlLmNhc3QudHAuaGVhcnRiZWF0KAAyD
3sidHlwZSI6IlBJTkcifQ==
[2016-08-06 07:44:18] [DEBUG]     cast: Preparing to send message type 2 to 'BadezimmerKromcast'
[2016-08-06 07:44:22] [ INFO]     http: Skipping Shoutcast metadata request for http://mp3.webradio.antenne.de:80 (requires libevent>=2.1.4 or libav 10)
[2016-08-06 07:44:23] [DEBUG]     cast: New data from 'BadezimmerKromcast'
[2016-08-06 07:44:23] [DEBUG]     cast: Received 92 bytes
[2016-08-06 07:44:23] [DEBUG]     cast: REPLY DUMP (len 88): CAASC1RyQG4kcDBydC0wGgtUckBuJHAwcnQtMCIndXJuOngtY2FzdDpjb20uZ29vZ2xlLmNhc3QudHAuaGVhcnRiZWF0KAAyD
3sidHlwZSI6IlBJTkcifQ==
[2016-08-06 07:44:23] [DEBUG]     cast: Preparing to send message type 2 to 'BadezimmerKromcast'
[2016-08-06 07:44:27] [ INFO]     http: Skipping Shoutcast metadata request for http://mp3.webradio.antenne.de:80 (requires libevent>=2.1.4 or libav 10)
[2016-08-06 07:44:28] [DEBUG]     cast: New data from 'BadezimmerKromcast'
[2016-08-06 07:44:28] [DEBUG]     cast: Received 92 bytes
[2016-08-06 07:44:28] [DEBUG]     cast: REPLY DUMP (len 88): CAASC1RyQG4kcDBydC0wGgtUckBuJHAwcnQtMCIndXJuOngtY2FzdDpjb20uZ29vZ2xlLmNhc3QudHAuaGVhcnRiZWF0KAAyD
3sidHlwZSI6IlBJTkcifQ==
[2016-08-06 07:44:28] [DEBUG]     cast: Preparing to send message type 2 to 'BadezimmerKromcast'
[2016-08-06 07:44:32] [ INFO]     http: Skipping Shoutcast metadata request for http://mp3.webradio.antenne.de:80 (requires libevent>=2.1.4 or libav 10)
[2016-08-06 07:44:33] [DEBUG]     cast: New data from 'BadezimmerKromcast'
[2016-08-06 07:44:33] [DEBUG]     cast: Received 92 bytes
[2016-08-06 07:44:33] [DEBUG]     cast: REPLY DUMP (len 88): CAASC1RyQG4kcDBydC0wGgtUckBuJHAwcnQtMCIndXJuOngtY2FzdDpjb20uZ29vZ2xlLmNhc3QudHAuaGVhcnRiZWF0KAAyD
3sidHlwZSI6IlBJTkcifQ==
[2016-08-06 07:44:33] [DEBUG]     cast: Preparing to send message type 2 to 'BadezimmerKromcast'
[2016-08-06 07:44:37] [ INFO]     http: Skipping Shoutcast metadata request for http://mp3.webradio.antenne.de:80 (requires libevent>=2.1.4 or libav 10)
[2016-08-06 07:44:39] [DEBUG]     cast: New data from 'BadezimmerKromcast'
[2016-08-06 07:44:39] [DEBUG]     cast: Received 92 bytes
[2016-08-06 07:44:39] [DEBUG]     cast: REPLY DUMP (len 88): CAASC1RyQG4kcDBydC0wGgtUckBuJHAwcnQtMCIndXJuOngtY2FzdDpjb20uZ29vZ2xlLmNhc3QudHAuaGVhcnRiZWF0KAAyD
3sidHlwZSI6IlBJTkcifQ==
[2016-08-06 07:44:39] [DEBUG]     cast: Preparing to send message type 2 to 'BadezimmerKromcast'
[2016-08-06 07:44:42] [ INFO]     http: Skipping Shoutcast metadata request for http://mp3.webradio.antenne.de:80 (requires libevent>=2.1.4 or libav 10)
[2016-08-06 07:44:43] [DEBUG]     cast: New data from 'BadezimmerKromcast'
[2016-08-06 07:44:43] [DEBUG]     cast: Received 301 bytes
[2016-08-06 07:44:43] [DEBUG]     cast: Received 299 bytes
[2016-08-06 07:44:43] [  LOG]     cast: Session error: A TLS packet with unexpected length was received.
[2016-08-06 07:44:43] [DEBUG]     cast: Preparing to send message type 4 to 'BadezimmerKromcast'
[2016-08-06 07:44:43] [  LOG]     cast: Could not send message, TLS error
[2016-08-06 07:44:43] [DEBUG]   player: Callback from Chromecast to device_streaming_cb
[2016-08-06 07:44:43] [  LOG]   player: The Chromecast device 'BadezimmerKromcast' FAILED
[2016-08-06 07:44:43] [  LOG]     cast: Bug! Shutdown request got wanted_state that is higher than current state
[2016-08-06 07:44:43] [DEBUG]    xcode: Flushing output stream #0 encoder
[2016-08-06 07:44:43] [DEBUG]      mpd: Listener callback called with event type 2.
[2016-08-06 07:44:43] [DEBUG]      mpd: Listener callback called with event type 1.
[2016-08-06 07:44:43] [DEBUG]      mpd: Notify clients waiting for idle results: 2
[2016-08-06 07:44:43] [DEBUG]      mpd: Notify clients waiting for idle results: 1
[2016-08-06 07:44:44] [DEBUG]   player: Player status: stopped

A bit later:

[2016-08-06 07:46:20] [ WARN]   stream: Connection failed; stopping mp3 streaming to client
[2016-08-06 07:46:20] [ INFO]   stream: No more clients, will stop streaming
[2016-08-06 07:46:20] [ INFO]   stream: Beginning mp3 streaming to ::ffff:192.168.2.26:43647

Is that the bug you talked about?

[ejurgensen]

I'm afraid this is another bug, but hats of for your testing. You're finding the sore points, and that is the first step towards stable operation.

This error is on the transport layer, maybe the device is hanging up because of some issue. That's as close as I can get right now, but please keep an eye out for it. I would like to know if it happens again and if there is any pattern.

[ejurgensen]

I got around to attempt a new fix for this issue along with #270. I ended up changing a bit more than I expected, so I've made a new branch: https://github.com/ejurgensen/forked-daapd/tree/dbgcast2

I hope you have the opportunity to test it. Probably best to "make clean" after switching to this branch, just to be certain that it is the new changes that you test with.

I don't expect that these changes will do anything about the radio issue. Have you seen more of that issue?

[Lakritzator]

Thanks!

I will test this, and report back.

Unfortunately (for the sake of reproducibility) I haven't seen the radio issue. I did check every day, but it seemed to be play stable.

[ejurgensen]

Since I will be away for about a week I went ahead and added the changes to the master branch right away. Worked ok when I tested, so I am crossing my fingers that the change is alright.

BTW Please add your request for a config option to disable autoselection as a new issue. That will help me remember it :-)

[Lakritzator]

I didn't manage to test it anyway, but I will switch to master.

I will add the request, thanks.

[Lakritzator]

I finally had time to switch back to master, let's see how it behaves.

Is the following normal?

[2016-08-17 19:17:46] [  LOG]     main: Forked Media Server Version 24.1 taking off
[2016-08-17 19:17:46] [  LOG]     main: mDNS init
[2016-08-17 19:17:46] [  LOG]     mdns: Avahi state change: Client running
[2016-08-17 19:17:46] [  LOG]       db: ANALYZE failed: step failed: attempt to write a readonly database
[2016-08-17 19:17:46] [  LOG]       db: Error setting playlist title, query UPDATE playlists SET title = 'Library' WHERE type = 0 AND special_id = 0;, error: step failed: attempt to write a readonly database
[2016-08-17 19:17:46] [  LOG]       db: Error setting playlist title, query UPDATE playlists SET title = 'Music' WHERE type = 0 AND special_id = 6;, error: step failed: attempt to write a readonly database
[2016-08-17 19:17:46] [  LOG]       db: Error setting playlist title, query UPDATE playlists SET title = 'Movies' WHERE type = 0 AND special_id = 4;, error: step failed: attempt to write a readonly database
[2016-08-17 19:17:46] [  LOG]       db: Error setting playlist title, query UPDATE playlists SET title = 'TV Shows' WHERE type = 0 AND special_id = 5;, error: step failed: attempt to write a readonly database
[2016-08-17 19:17:46] [  LOG]       db: Error setting playlist title, query UPDATE playlists SET title = 'Podcasts' WHERE type = 0 AND special_id = 1;, error: step failed: attempt to write a readonly database
[2016-08-17 19:17:46] [  LOG]       db: Error setting playlist title, query UPDATE playlists SET title = 'Audiobooks' WHERE type = 0 AND special_id = 7;, error: step failed: attempt to write a readonly database
[2016-08-17 19:17:46] [  LOG]       db: Database OK with 84281 active files and 11 active playlists
[2016-08-17 19:17:46] [  LOG]       db: Error 'step failed: attempt to write a readonly database' while runnning 'DELETE FROM inotify;'
[2016-08-17 19:17:46] [  LOG]     scan: Error: could not clear old watches from DB

[ejurgensen]

Certainly not, but it seems to be just a permission problem. Maybe you are now running as daapd, and before it was root? ons. 17. aug. 2016 kl. 18.33 skrev Robin Krom notifications@github.com:

I finally had time to switch back to master, let's see how it behaves.

Is the following normal?

[2016-08-17 19:17:46] [ LOG] main: Forked Media Server Version 24.1 taking off [2016-08-17 19:17:46] [ LOG] main: mDNS init [2016-08-17 19:17:46] [ LOG] mdns: Avahi state change: Client running [2016-08-17 19:17:46] [ LOG] db: ANALYZE failed: step failed: attempt to write a readonly database [2016-08-17 19:17:46] [ LOG] db: Error setting playlist title, query UPDATE playlists SET title = 'Library' WHERE type = 0 AND special_id = 0;, error: step failed: attempt to write a readonly database [2016-08-17 19:17:46] [ LOG] db: Error setting playlist title, query UPDATE playlists SET title = 'Music' WHERE type = 0 AND special_id = 6;, error: step failed: attempt to write a readonly database [2016-08-17 19:17:46] [ LOG] db: Error setting playlist title, query UPDATE playlists SET title = 'Movies' WHERE type = 0 AND special_id = 4;, error: step failed: attempt to write a readonly database [2016-08-17 19:17:46] [ LOG] db: Error setting playlist title, query UPDATE playlists SET title = 'TV Shows' WHERE type = 0 AND special_id = 5;, error: step failed: attempt to write a readonly database [2016-08-17 19:17:46] [ LOG] db: Error setting playlist title, query UPDATE playlists SET title = 'Podcasts' WHERE type = 0 AND special_id = 1;, error: step failed: attempt to write a readonly database [2016-08-17 19:17:46] [ LOG] db: Error setting playlist title, query UPDATE playlists SET title = 'Audiobooks' WHERE type = 0 AND special_id = 7;, error: step failed: attempt to write a readonly database [2016-08-17 19:17:46] [ LOG] db: Database OK with 84281 active files and 11 active playlists [2016-08-17 19:17:46] [ LOG] db: Error 'step failed: attempt to write a readonly database' while runnning 'DELETE FROM inotify;' [2016-08-17 19:17:46] [ LOG] scan: Error: could not clear old watches from DB

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/ejurgensen/forked-daapd/issues/275#issuecomment-240486523, or mute the thread https://github.com/notifications/unsubscribe-auth/ABGmThlXgLsblFn8WN1871ItSXbfv6POks5qg0XfgaJpZM4JRnEP .

[Lakritzator]

Don't know what happened, I fixed the permissions and now it's okay... I will monitor the stability and report back this weekend. Than we can close this issue.

Thanks

[Lakritzator]

Damn, due to the entry in the logs with the following metadata request for http://mp3.webradio.antenne.de:80 (requires libevent>=2.1.4 or libav 10) I updated libav to 10 Now forked-daapd crashes as soon as I try to play something, there is nothing in the logs. Any tipps?

[Lakritzator]

It must be something with the update:

[ 1162.524108] forked-daapd[9351]: segfault at 0 ip 00007f101e7d8ba8 sp 00007fff65fd3740 error 4 in libavutil.so.52.18.0[7f101e7c9000+23000]
[ 1320.372317] forked-daapd[12732]: segfault at 0 ip 00007ff384ceeba8 sp 00007ffcbe961610 error 4 in libavutil.so.52.18.0[7ff384cdf000+23000]
[ 1368.721905] forked-daapd[12825]: segfault at 0 ip 00007f43c5759ba8 sp 00007fff514989d0 error 4 in libavutil.so.52.18.0[7f43c574a000+23000]
[ 1396.596968] forked-daapd[12854]: segfault at 0 ip 00007f95e959dba8 sp 00007ffcc0f2de70 error 4 in libavutil.so.52.18.0[7f95e958e000+23000]
[ 2511.102839] forked-daapd[20001]: segfault at ffffffffffffffff ip 00007f5cd6fbe903 sp 00007f5cbf7fdc80 error 5 in libavutil.so.52.18.0[7f5cd6fb5000+23000]
[ 2623.106004] forked-daapd[20358] general protection ip:7faf8f9f4bac sp:7faf84fdbc60 error:0 in libavutil.so.52.18.0[7faf8f9e5000+23000]
[ 2814.857261] forked-daapd[20619]: segfault at 0 ip 00007f0cc1796ba8 sp 00007ffedbcd9d90 error 4 in libavutil.so.52.18.0[7f0cc1787000+23000]

[Lakritzator]

I got it working again after updating to libav11 AND rebooting, (and configure, make etc a couple of times) But now at night I had the following:

[2016-08-20 01:40:31] [  LOG]     cast: No heartbeat from 'WohnzimmerKromcast', shutting down
[2016-08-20 01:40:31] [  LOG]   player: The Chromecast device 'WohnzimmerKromcast' FAILED
[2016-08-20 04:30:01] [  LOG]      mpd: No speaker to deactivate
[2016-08-20 04:30:02] [  LOG]      mpd: No speaker to deactivate
[2016-08-20 08:22:44] [  LOG]     cast: Session error: The TLS connection was non-properly terminated.
[2016-08-20 08:22:44] [  LOG]     cast: Could not send message, TLS error
[2016-08-20 08:22:44] [  LOG]   player: The Chromecast device 'BadezimmerKromcast' FAILED

The first failed one, livingroom, is the time I went to bed as I though I fixed it. This should be correct. The no speaker to deactive is probably okay, as my script tries to deactivate something. The second failed is not correct, it should have been there and was playing before.

I didn't have debug on... sorry

[ejurgensen]

Can you reproduce with debug mode? Also with #DEBUG_CONNECTION in outputs/cast.c uncommented.

[Lakritzator]

Ah, after the make install with having the cast.c changed it segfaults like yesterday: [69513.153447] forked-daapd[26104]: segfault at 0 ip 00007f99370a6ba8 sp 00007fffba6c77e0 error 4 in libavutil.so.52.18.0[7f9937097000+23000] The last thing in the log with -d 5 is always [2016-08-20 20:45:12] [ WARN] ffmpeg: First timestamp is missing, assuming 0.

Damn, why did it work yesterday?

[Lakritzator]

It's official, I broke it... nothing worrks anymore. I updated to Ubuntu 16, and it still doesn't work. Tried to move back to the branch 'origin/dbgcast2', this doesn't work either.

When it doesn't segfault, it just doesn't respond to mpc commands.

If you have any tips what I can do: forked-daapd.txt

[ejurgensen]

Sorry to hear that. Not sure what you could can do except try to reset - especially get rid of libav stuff you might have built/installed yourself, and just use the standard Ubuntu ones. In any case it is slightly off topic, so perhaps you can send me an email (espenjurgensen@gmail.com) and we can sort it out that way.

[ejurgensen]

Any news on this?

[dboosh]

i can confirm...i had the same chromecast unpacking issue using the stable build via apt-get on ubuntu yakkety. i did an apt-get remove then built the main branch and bug went away...did not mess around with any custom libraries or user permissions or anything...very plain-jane default setup worked fine.

i have stumbled upon some other bugs but am early in determining how to reproduce them...will get back with more focused info as i am eager to give back to this nifty project.

[ejurgensen]

Good to hear, will close this then. Thanks for examining how to reproduce the other bugs you have seen, that is very helpful.