AllPlay binding: Looking for testers

dominicdesu · October 2, 2016, 11:00am

Hi,

I am currently developing an OH2 binding for AllPlay speakers.
As it is working quite stable for me now, I am looking for other owners of AllPlay-compatible speakers to test the binding before making a pull request.
As the binding is based on AllJoyn, I need to include native libraries for various systems. Currently ARM (RaspberryPi), Linux 32- and 64-bit and Windows 8/10 64-bit are supported. If you have another system and would like to test the binding, please let me know.

The binding should auto-discover your speakers and add them to the inbox in PaperUI.

Here are some example items in case you want to configure them manually:

String LVPanasonicAll8Stream    {channel="allplay:speaker:c28336b4-38a5-4849-8ec7-7cfcc990a705:stream"}
Player LVPanasonicAll8Control    {channel="allplay:speaker:c28336b4-38a5-4849-8ec7-7cfcc990a705:control"}
Dimmer LVPanasonicAll8Volume  {channel="allplay:speaker:c28336b4-38a5-4849-8ec7-7cfcc990a705:volume"}
String LVPanasonicAll8Title "Title [%s]"    {channel="allplay:speaker:c28336b4-38a5-4849-8ec7-7cfcc990a705:currenttitle"}
String LVPanasonicAll8State "Status [%s]"    {channel="allplay:speaker:c28336b4-38a5-4849-8ec7-7cfcc990a705:playstate"}
String LVPanasonicAll8Artist "Artist [%s]"    {channel="allplay:speaker:c28336b4-38a5-4849-8ec7-7cfcc990a705:currentartist"}
String LVPanasonicAll8CoverUrl {channel="allplay:speaker:c28336b4-38a5-4849-8ec7-7cfcc990a705:thumbnailurl"}

Use this command in a rule to play a stream:
LVPanasonicAll8Stream.sendCommand("http://chromaradio.com:8008/listen.pls")

Would be great if I could get your feedback on the binding! Please let me know if it is working for you, and with which speakers / operating system.

Any suggestions & bug reports are very welcome!

Max1968 · October 11, 2016, 6:25pm

Hi Dominic,

I just did a quick check using SSH through a VPN tunnel to my openhab2 server at home, and it seems to work fine… I’m running openhab2 on Ubuntu on a VM on a QNAP NAS, and i just connected to it, downloaded the snapshot and unzipped it to the addons folder.

Afterwards the allplay binding was visible in the paper UI, and after I searched for things it perfectly found my two currently powered on Gramofon devices (www.gramofon.com). I could start and pause remotely (using my cameras to listen to whats going on in my home) , and the tracks were also shown properly using the basic UI, however no album art which is shown in your screenshot on github. Only thing I found weird is that the current duration seems wrong, it is shown as 188640, but i have no idea right now (as i’m away) what should be correct. I also could not test grouping of my speakers for multiroom audio yet (through Spotify app), have you tried this with the Panasonic speakers ? Will this result in an additional thing in openhab2 or how is this supposed to work ?

Great work so far !

dominicdesu · October 11, 2016, 8:55pm

Hi @Max1968 ,
thanks for trying out the binding and your feedback!

no album art which is shown in your screenshot on github

The album art has to be set by the application from which you start the playback. If the application does not set the album art, the binding cannot show it. Can you see the album art in your playback app?
Also, I don’t know if the basic UI can show images, as far as I know the classic UI can’t. Don’t know about the basic UI.
If there should be an album art but it is not displayed, we have to debug.

Only thing I found weird is that the current duration seems wrong, it is shown as 188640

I believe the duration is shown in milliseconds, so 188640 would be 3:08 min which makes more sense I guess? Need to check whether it is possible to display a duration.

I also could not test grouping of my speakers for multiroom audio yet

For the first release of the binding, I didn’t plan to include grouping possibility. However, it should be possible to control already grouped speakers by sending commands to the master speaker of the group. I need to verify this though, good point!

If possible, please try again in a few days if you can still control the speakers and get information from it. I had some issues with the Panasonic speakers, which would disconnect from the current session and then don’t re-anncounce themselves. I added some mechanism to handle such disconnects, but I don’t know if it works in all cases.

Dominic

DevUrandomFoo · January 4, 2017, 10:47am

Hi, I installed the addon but no all-play device will be discovered and manually add don’t work. I’m using a Panasonic all 6.
Maybe you have a never version? I’m using 2.0.0.201610071918.

BR,
Manuel

Kai · January 4, 2017, 11:11am

AllPlay is by now part of the distro, see http://docs.openhab.org/addons/bindings/allplay/readme.html.
So I’d suggest you try the official build!

DevUrandomFoo · January 4, 2017, 11:19am

But I can’t see the allplay binding in my addons. Als tried the online and offline version of openhab2 beta5

Kai · January 4, 2017, 11:25am

It was merged after beta5 was released. So please use a current snapshot from https://openhab.ci.cloudbees.com/job/openHAB-Distribution/.

DevUrandomFoo · January 4, 2017, 12:38pm

Damnit. allplay is working with the current snapshot but they kill the z-wave binding which works fine in beta5

Max1968 · January 10, 2017, 3:08pm

@dominicdesu I did a fresh install of openhab 2, it correctly found my gramofon speakers and I was able to control them - I even had cover art and was able to control groups of speakers (changes where only reflected to the master though, not to all speakers in the group). Somehow I lost connection to all 4 of them now, and i’m not able to reconnect, tried to power off/on the speakers as well as reboot the oh2 server - What information do you need to debug this, it looks like the same issue you had back last year ?

dominicdesu · January 10, 2017, 6:02pm

Hi @Max1968,
I don’t think that powering on/off the speaker helps, however rebooting OH2 should. Did you reboot the physical machine or the OH2 runtime?

To analyze the issue, could you first enable DEBUG level for

org.openhab.binding.allplay = DEBUG 
de.kaizencode.tchaikovsky = DEBUG

Could you then reboot OH2 by stopping it, verifying that the java process is not running anymore, and then starting it again?

If it is still not working, could you provide the log files of what happened after the restart? If it works again, please post the log files as soon as it fails again.

Dominic

Max1968 · January 10, 2017, 6:33pm

Hi @dominicdesu,

first i tried to restart openhab by issuing

systemctl stop openhab2.service
systemctl start openhab2.service

as this didnt solve the issue i rebooted the (virtual) machine and verified it indeed rebooted. Furthermore i set log level for the allplay binding to debug, and afterwards to trace, using the karaf console, but this didnt provide any useful output.

i now set the debug level as requested, using the karaf console again:

openhab> log:list
Logger                                                      | Level
-------------------------------------------------------------------
ROOT                                                        | WARN
de.kaizencode.tchaikovsky                                   | DEBUG
javax.jmdns                                                 | ERROR
org.apache.karaf.kar.internal.KarServiceImpl                | ERROR
org.eclipse.smarthome                                       | INFO
org.jupnp                                                   | ERROR
org.openhab                                                 | INFO
org.openhab.binding.allplay                                 | DEBUG
org.ops4j.pax.web.service.jetty.internal.JettyServerWrapper | ERROR
smarthome.event                                             | INFO
smarthome.event.InboxUpdatedEvent                           | ERROR
smarthome.event.ItemStateEvent                              | ERROR
smarthome.event.ThingStatusInfoEvent                        | ERROR

and rebooted the virtual machine again, all fours speakers are still showing as “offline” although i can manage them using eg the Gramofon app or Spotify on iOS devices or the “IOT Explorer for AllJoyn” on Windows.

log follows:

2017-01-10 19:17:46.917 [INFO ] [ore.internal.i18n.LocaleProviderImpl] - Locale set to de_DE
2017-01-10 19:17:49.406 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'youless.items'
2017-01-10 19:17:49.466 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'rrd4j.persist'
2017-01-10 19:17:49.484 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'SpeedTest.items'
2017-01-10 19:17:49.491 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'plex.items'
2017-01-10 19:17:49.507 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Presence.items'
2017-01-10 19:17:49.538 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Zipabox.items'
2017-01-10 19:17:49.579 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'RaspberryCameras.items'
2017-01-10 19:17:49.600 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Weather.items'
2017-01-10 19:17:49.634 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'networkhealth.items'
2017-01-10 19:17:52.206 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at /start
2017-01-10 19:17:52.835 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2017-01-10 19:17:52.955 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
2017-01-10 19:17:53.038 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2017-01-10 19:17:53.146 [INFO ] [b.core.service.AbstractActiveService] - HTTP Refresh Service has been started
2017-01-10 19:17:53.541 [INFO ] [eather.internal.common.WeatherConfig] - ProviderConfig[providerName=WUNDERGROUND,apiKey=xxxxxxxxxxxxxxxx]
2017-01-10 19:17:53.541 [INFO ] [eather.internal.common.WeatherConfig] - LocationConfig[providerName=WUNDERGROUND,language=de,updateInterval=1,latitude=xxxxxxxxx,longitude=xxxxxxxxx,woeid=<null>,locationId=home,name=xxxxxxxx]
2017-01-10 19:17:55.434 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro job-daily-sun at midnight for thing astro:sun:local
2017-01-10 19:17:55.439 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro job-positional with interval of 300 seconds for thing astro:sun:local
2017-01-10 19:17:55.440 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro job-daily-sun at midnight for thing astro:sun:local
2017-01-10 19:17:55.441 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro job-positional with interval of 300 seconds for thing astro:sun:local
2017-01-10 19:17:55.442 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro job-daily-moon at midnight for thing astro:moon:local
2017-01-10 19:17:55.442 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro job-positional with interval of 300 seconds for thing astro:moon:local
2017-01-10 19:17:56.689 [INFO ] [ternal.scheduler.WeatherJobScheduler] - Starting and scheduling weatherJob-home with interval of 1 minutes
2017-01-10 19:17:56.754 [INFO ] [.astro.internal.job.AbstractDailyJob] - Scheduled astro event-jobs for thing astro:moon:local
2017-01-10 19:17:56.831 [INFO ] [.astro.internal.job.AbstractDailyJob] - Scheduled astro event-jobs for thing astro:sun:local
2017-01-10 19:18:00.143 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2017-01-10 19:18:00.160 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2017-01-10 19:18:00.163 [DEBUG] [org.openhab.binding.allplay         ] - BundleEvent STARTING - org.openhab.binding.allplay
2017-01-10 19:18:00.169 [DEBUG] [org.openhab.binding.allplay         ] - BundleEvent STARTED - org.openhab.binding.allplay
2017-01-10 19:18:00.209 [DEBUG] [lplay.internal.AllPlayHandlerFactory] - Activating AllPlayHandlerFactory
2017-01-10 19:18:00.398 [DEBUG] [lplay.internal.AllPlayHandlerFactory] - Connecting to AllPlay
2017-01-10 19:18:00.439 [INFO ] [de.kaizencode.tchaikovsky.AllPlay   ] - Connecting to AllJoyn bus
2017-01-10 19:18:00.494 [INFO ] [de.kaizencode.tchaikovsky.AllPlay   ] - Successfully connected to allJoyn bus with bus name :kyemsCJR.2
2017-01-10 19:18:00.495 [DEBUG] [ikovsky.discovery.SpeakerBusListener] - Registering signal handler
2017-01-10 19:18:00.564 [DEBUG] [ovsky.discovery.SpeakerAboutListener] - Registering signal handler
2017-01-10 19:18:00.582 [DEBUG] [org.openhab.binding.allplay         ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=org.openhab.binding.allplay.internal.AllPlayHandlerFactory, component.id=207, service.id=340, service.bundleid=209, service.scope=bundle} - org.openhab.binding.allplay
2017-01-10 19:18:00.583 [DEBUG] [lplay.internal.AllPlayHandlerFactory] - Creating AllPlayHandler for thing allplay:speaker:4d56f675-1187-4bb2-ab40-a63b52d0c86c
2017-01-10 19:18:00.587 [DEBUG] [lplay.internal.AllPlayHandlerFactory] - Creating AllPlayHandler for thing allplay:speaker:e204fd21-161d-418e-ac44-438d018037e7
2017-01-10 19:18:00.587 [DEBUG] [lplay.internal.AllPlayHandlerFactory] - Creating AllPlayHandler for thing allplay:speaker:44d8a58b-4144-4a13-8533-5a5e119fdbec
2017-01-10 19:18:00.588 [DEBUG] [lplay.internal.AllPlayHandlerFactory] - Creating AllPlayHandler for thing allplay:speaker:5bb542e6-1198-4afb-bcd8-d91a611708f6
2017-01-10 19:18:00.590 [DEBUG] [overy.AllPlaySpeakerDiscoveryService] - Starting scan for AllPlay devices
2017-01-10 19:18:00.591 [INFO ] [de.kaizencode.tchaikovsky.AllPlay   ] - Connecting to AllJoyn bus
2017-01-10 19:18:00.612 [INFO ] [de.kaizencode.tchaikovsky.AllPlay   ] - Successfully connected to allJoyn bus with bus name :kyemsCJR.3
2017-01-10 19:18:00.612 [DEBUG] [ikovsky.discovery.SpeakerBusListener] - Registering signal handler
2017-01-10 19:18:00.616 [DEBUG] [ovsky.discovery.SpeakerAboutListener] - Registering signal handler
2017-01-10 19:18:00.623 [DEBUG] [ovsky.discovery.SpeakerAboutListener] - New SpeakerAnnouncedListener org.openhab.binding.allplay.discovery.AllPlaySpeakerDiscoveryService@17dbddce has been added
2017-01-10 19:18:00.623 [DEBUG] [ikovsky.discovery.SpeakerBusListener] - New SpeakerAnnouncedListener org.openhab.binding.allplay.discovery.AllPlaySpeakerDiscoveryService@17dbddce has been added
2017-01-10 19:18:00.628 [DEBUG] [org.openhab.binding.allplay         ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={component.name=org.openhab.binding.allplay.discovery, component.id=208, service.id=341, service.bundleid=209, service.scope=bundle} - org.openhab.binding.allplay
2017-01-10 19:18:00.641 [INFO ] [ikovsky.discovery.SpeakerBusListener] - foundAdvertisedName net.allplay.MediaPlayer.i44d8a58b-4144-4a13-8533-5a5e119fdbec.ryvV68Uqk - 256 - net.allplay.MediaPlayer
2017-01-10 19:18:00.641 [INFO ] [ikovsky.discovery.SpeakerBusListener] - Joining session with host [net.allplay.MediaPlayer.i44d8a58b-4144-4a13-8533-5a5e119fdbec.ryvV68Uqk], port [1]
2017-01-10 19:18:00.643 [INFO ] [ikovsky.discovery.SpeakerBusListener] - foundAdvertisedName net.allplay.MediaPlayer.i44d8a58b-4144-4a13-8533-5a5e119fdbec.ryvV68Uqk.quiet - 256 - net.allplay.MediaPlayer
2017-01-10 19:18:00.644 [INFO ] [ikovsky.discovery.SpeakerBusListener] - foundAdvertisedName net.allplay.MediaPlayer.i44d8a58b-4144-4a13-8533-5a5e119fdbec.ryvV68Uqk - 4 - net.allplay.MediaPlayer
2017-01-10 19:18:00.644 [INFO ] [ikovsky.discovery.SpeakerBusListener] - Joining session with host [net.allplay.MediaPlayer.i44d8a58b-4144-4a13-8533-5a5e119fdbec.ryvV68Uqk], port [1]
2017-01-10 19:18:00.651 [INFO ] [ikovsky.discovery.SpeakerBusListener] - foundAdvertisedName net.allplay.MediaPlayer.i44d8a58b-4144-4a13-8533-5a5e119fdbec.ryvV68Uqk.quiet - 4 - net.allplay.MediaPlayer
2017-01-10 19:18:00.657 [INFO ] [ikovsky.discovery.SpeakerBusListener] - foundAdvertisedName net.allplay.MediaPlayer.i4d56f675-1187-4bb2-ab40-a63b52d0c86c.rRXetIC5A - 256 - net.allplay.MediaPlayer
2017-01-10 19:18:00.657 [INFO ] [ikovsky.discovery.SpeakerBusListener] - Joining session with host [net.allplay.MediaPlayer.i4d56f675-1187-4bb2-ab40-a63b52d0c86c.rRXetIC5A], port [1]
2017-01-10 19:18:00.658 [INFO ] [ikovsky.discovery.SpeakerBusListener] - foundAdvertisedName net.allplay.MediaPlayer.i4d56f675-1187-4bb2-ab40-a63b52d0c86c.rRXetIC5A.quiet - 256 - net.allplay.MediaPlayer
2017-01-10 19:18:00.659 [INFO ] [ikovsky.discovery.SpeakerBusListener] - foundAdvertisedName net.allplay.MediaPlayer.i4d56f675-1187-4bb2-ab40-a63b52d0c86c.rRXetIC5A - 4 - net.allplay.MediaPlayer
2017-01-10 19:18:00.663 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Initializing AllPlay handler for speaker 4d56f675-1187-4bb2-ab40-a63b52d0c86c
2017-01-10 19:18:00.663 [DEBUG] [ovsky.discovery.SpeakerAboutListener] - New SpeakerAnnouncedListener org.openhab.binding.allplay.handler.AllPlayHandler@d96771d has been added
2017-01-10 19:18:00.663 [DEBUG] [ikovsky.discovery.SpeakerBusListener] - New SpeakerAnnouncedListener org.openhab.binding.allplay.handler.AllPlayHandler@d96771d has been added
2017-01-10 19:18:00.663 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Starting discovery for speaker 4d56f675-1187-4bb2-ab40-a63b52d0c86c
2017-01-10 19:18:00.664 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel control triggered with command REFRESH
2017-01-10 19:18:00.664 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
2017-01-10 19:18:00.664 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel coverart triggered with command REFRESH
2017-01-10 19:18:00.665 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
2017-01-10 19:18:00.665 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel currentalbum triggered with command REFRESH
2017-01-10 19:18:00.665 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
2017-01-10 19:18:00.665 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel currentartist triggered with command REFRESH
2017-01-10 19:18:00.665 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
2017-01-10 19:18:00.665 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel currenttitle triggered with command REFRESH
2017-01-10 19:18:00.665 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
2017-01-10 19:18:00.666 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel volume triggered with command REFRESH
2017-01-10 19:18:00.666 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
2017-01-10 19:18:00.666 [INFO ] [ikovsky.discovery.SpeakerBusListener] - foundAdvertisedName net.allplay.MediaPlayer.i4d56f675-1187-4bb2-ab40-a63b52d0c86c.rRXetIC5A - 256 - net.allplay.MediaPlayer.i4d56f675-1187-4bb2-ab40-a63b52d0c86c
2017-01-10 19:18:00.666 [INFO ] [ikovsky.discovery.SpeakerBusListener] - Joining session with host [net.allplay.MediaPlayer.i4d56f675-1187-4bb2-ab40-a63b52d0c86c.rRXetIC5A], port [1]
2017-01-10 19:18:00.668 [INFO ] [ikovsky.discovery.SpeakerBusListener] - foundAdvertisedName net.allplay.MediaPlayer.i4d56f675-1187-4bb2-ab40-a63b52d0c86c.rRXetIC5A - 4 - net.allplay.MediaPlayer.i4d56f675-1187-4bb2-ab40-a63b52d0c86c
2017-01-10 19:18:00.668 [INFO ] [ikovsky.discovery.SpeakerBusListener] - Joining session with host [net.allplay.MediaPlayer.i4d56f675-1187-4bb2-ab40-a63b52d0c86c.rRXetIC5A], port [1]
2017-01-10 19:18:00.668 [INFO ] [ikovsky.discovery.SpeakerBusListener] - foundAdvertisedName net.allplay.MediaPlayer.i4d56f675-1187-4bb2-ab40-a63b52d0c86c.rRXetIC5A.quiet - 256 - net.allplay.MediaPlayer.i4d56f675-1187-4bb2-ab40-a63b52d0c86c
2017-01-10 19:18:00.668 [INFO ] [ikovsky.discovery.SpeakerBusListener] - foundAdvertisedName net.allplay.MediaPlayer.i4d56f675-1187-4bb2-ab40-a63b52d0c86c.rRXetIC5A.quiet - 4 - net.allplay.MediaPlayer.i4d56f675-1187-4bb2-ab40-a63b52d0c86c
2017-01-10 19:18:00.670 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Initializing AllPlay handler for speaker e204fd21-161d-418e-ac44-438d018037e7
2017-01-10 19:18:00.670 [DEBUG] [ovsky.discovery.SpeakerAboutListener] - New SpeakerAnnouncedListener org.openhab.binding.allplay.handler.AllPlayHandler@53cf95b has been added
2017-01-10 19:18:00.671 [DEBUG] [ikovsky.discovery.SpeakerBusListener] - New SpeakerAnnouncedListener org.openhab.binding.allplay.handler.AllPlayHandler@53cf95b has been added
2017-01-10 19:18:00.671 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Starting discovery for speaker e204fd21-161d-418e-ac44-438d018037e7
2017-01-10 19:18:00.682 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Initializing AllPlay handler for speaker 44d8a58b-4144-4a13-8533-5a5e119fdbec
2017-01-10 19:18:00.682 [DEBUG] [ovsky.discovery.SpeakerAboutListener] - New SpeakerAnnouncedListener org.openhab.binding.allplay.handler.AllPlayHandler@5eb2efaf has been added
2017-01-10 19:18:00.682 [DEBUG] [ikovsky.discovery.SpeakerBusListener] - New SpeakerAnnouncedListener org.openhab.binding.allplay.handler.AllPlayHandler@5eb2efaf has been added
2017-01-10 19:18:00.682 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Starting discovery for speaker 44d8a58b-4144-4a13-8533-5a5e119fdbec
2017-01-10 19:18:00.683 [INFO ] [ikovsky.discovery.SpeakerBusListener] - Joining session with host [net.allplay.MediaPlayer.i4d56f675-1187-4bb2-ab40-a63b52d0c86c.rRXetIC5A], port [1]
2017-01-10 19:18:00.688 [INFO ] [ikovsky.discovery.SpeakerBusListener] - foundAdvertisedName net.allplay.MediaPlayer.i44d8a58b-4144-4a13-8533-5a5e119fdbec.ryvV68Uqk - 256 - net.allplay.MediaPlayer.i44d8a58b-4144-4a13-8533-5a5e119fdbec
2017-01-10 19:18:00.688 [INFO ] [ikovsky.discovery.SpeakerBusListener] - Joining session with host [net.allplay.MediaPlayer.i44d8a58b-4144-4a13-8533-5a5e119fdbec.ryvV68Uqk], port [1]
2017-01-10 19:18:00.688 [INFO ] [ikovsky.discovery.SpeakerBusListener] - foundAdvertisedName net.allplay.MediaPlayer.i44d8a58b-4144-4a13-8533-5a5e119fdbec.ryvV68Uqk - 4 - net.allplay.MediaPlayer.i44d8a58b-4144-4a13-8533-5a5e119fdbec
2017-01-10 19:18:00.688 [INFO ] [ikovsky.discovery.SpeakerBusListener] - Joining session with host [net.allplay.MediaPlayer.i44d8a58b-4144-4a13-8533-5a5e119fdbec.ryvV68Uqk], port [1]
2017-01-10 19:18:00.699 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel control triggered with command REFRESH
2017-01-10 19:18:00.699 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
2017-01-10 19:18:00.699 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel coverart triggered with command REFRESH
2017-01-10 19:18:00.699 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
2017-01-10 19:18:00.700 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel currentalbum triggered with command REFRESH
2017-01-10 19:18:00.700 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
2017-01-10 19:18:00.700 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel currentartist triggered with command REFRESH
2017-01-10 19:18:00.700 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
2017-01-10 19:18:00.700 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel currenttitle triggered with command REFRESH
2017-01-10 19:18:00.700 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
2017-01-10 19:18:00.700 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel volume triggered with command REFRESH
2017-01-10 19:18:00.700 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
2017-01-10 19:18:00.701 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel control triggered with command REFRESH
2017-01-10 19:18:00.701 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
2017-01-10 19:18:00.701 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel coverart triggered with command REFRESH
2017-01-10 19:18:00.701 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
2017-01-10 19:18:00.701 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel currentalbum triggered with command REFRESH
2017-01-10 19:18:00.701 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
2017-01-10 19:18:00.701 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel currentartist triggered with command REFRESH
2017-01-10 19:18:00.701 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
2017-01-10 19:18:00.701 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel currenttitle triggered with command REFRESH
2017-01-10 19:18:00.701 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
2017-01-10 19:18:00.701 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel volume triggered with command REFRESH
2017-01-10 19:18:00.701 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
2017-01-10 19:18:00.703 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Initializing AllPlay handler for speaker 5bb542e6-1198-4afb-bcd8-d91a611708f6
2017-01-10 19:18:00.703 [DEBUG] [ovsky.discovery.SpeakerAboutListener] - New SpeakerAnnouncedListener org.openhab.binding.allplay.handler.AllPlayHandler@20988a81 has been added
2017-01-10 19:18:00.703 [DEBUG] [ikovsky.discovery.SpeakerBusListener] - New SpeakerAnnouncedListener org.openhab.binding.allplay.handler.AllPlayHandler@20988a81 has been added
2017-01-10 19:18:00.703 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Starting discovery for speaker 5bb542e6-1198-4afb-bcd8-d91a611708f6
2017-01-10 19:18:00.704 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel control triggered with command REFRESH
2017-01-10 19:18:00.704 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
2017-01-10 19:18:00.704 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel coverart triggered with command REFRESH
2017-01-10 19:18:00.704 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
2017-01-10 19:18:00.704 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel currentalbum triggered with command REFRESH
2017-01-10 19:18:00.704 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
2017-01-10 19:18:00.704 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel currentartist triggered with command REFRESH
2017-01-10 19:18:00.704 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
2017-01-10 19:18:00.704 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel currenttitle triggered with command REFRESH
2017-01-10 19:18:00.704 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
2017-01-10 19:18:00.704 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel volume triggered with command REFRESH
2017-01-10 19:18:00.704 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
2017-01-10 19:18:01.608 [INFO ] [b.core.service.AbstractActiveService] - Plex Refresh Service has been started
2017-01-10 19:18:05.665 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'allplay:speaker:e204fd21-161d-418e-ac44-438d018037e7' takes more than 5000ms.
2017-01-10 19:18:05.684 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'allplay:speaker:5bb542e6-1198-4afb-bcd8-d91a611708f6' takes more than 5000ms.

PaperUI:

IoT Explorer:

(sometimes it takes a while until all four devices are found, but these 3 show up right away at least)

I did not do a full clean reinstall of OH2, what I did instead was change to the latest APT repository and “apt-get install openhab2” after cleaning the tmp and cache directories, thus it might be some leftover of the previous OH2 installation. Is there something else i need to clean, as i dont want to create all my habpanels again ?

dominicdesu · January 10, 2017, 7:46pm

@Max1968, thanks for the details logs. It should not be necessary to clean any caches.

Don’t know if this is causing the issue, but your speakers announce themselve twice, once for TCP (4) and once for UDP (256):

2017-01-10 19:18:00.668 [INFO ] [ikovsky.discovery.SpeakerBusListener] - foundAdvertisedName net.allplay.MediaPlayer.i4d56f675-1187-4bb2-ab40-a63b52d0c86c.rRXetIC5A.quiet - 256 - net.allplay.MediaPlayer.i4d56f675-1187-4bb2-ab40-a63b52d0c86c
2017-01-10 19:18:00.668 [INFO ] [ikovsky.discovery.SpeakerBusListener] - foundAdvertisedName net.allplay.MediaPlayer.i4d56f675-1187-4bb2-ab40-a63b52d0c86c.rRXetIC5A.quiet - 4 - net.allplay.MediaPlayer.i4d56f675-1187-4bb2-ab40-a63b52d0c86c

Therefore the binding is trying to connect twice to the same speaker. Maybe both connect attempt block each other in some way…
If I understand the AllJoyn documentation correctly, the possible transports should be summed up, so there should be only one message with 260 as the value. However, this seems not to be the case for your speakers (my Panasonic Speakers only uses TCP).

I have updated the binding to only connect to TCP-announced speakers, could you try if this fixes your issue? Please restart the OH2 service once after updating the binding if possible.
You can download the binding here: https://drive.google.com/file/d/0B5RwWQEiYx5tSU51dDlEejNTNVU/view?usp=sharing

dominicdesu · January 10, 2017, 8:02pm

Could also be a threading issue. In this case I need to investigate which blocks to make thread safe. Will have a look in the next few days if I can find something.

Max1968 · January 10, 2017, 8:55pm

i copied the jar file into addons folder, stopped and restarted OH2 but it still seems to be using the version from the apt repository:

208 | Resolved |  80 | 2.0.0.201701091302    | openHAB Paper UI Theme Fragment, Hosts: 196
209 | Active   |  80 | 2.0.0.201701091302    | AllPlay Binding
210 | Active   |  80 | 1.9.0.201701100211    | openHAB Plex Binding

i’m not sure i correctly copied it or the jar file is broken, but i can only check this tomorrow eve… or is there anything else i need to do to manually install this updated binding when using the apt repositories ?

dominicdesu · January 11, 2017, 5:28pm

I would assume you have to first uninstall the old binding, and then copy the new binding into your addons folder.

Max1968 · January 12, 2017, 10:33am

Update - First of all I did not copy the binding into the addons folder, but the google drive html page instead, this was the reason why the bundle did not install.

However when i realized this i deleted the file from the addons folder and tried to manually uninstall the allplay bundle using paper UI - this was not possible, paper ui showed a spinning wheel “uninstalling” for ages and karf still showed the bundle as “Stopping”. So I decided to give it another try as follows:

Stopped OH using systemctl
Copied the bundle from google drive to addons folder
Started OH again using systemctl

Karaf then showed both bundles in parallel:

209 | Stopping  |  80 | 2.0.0.201701091302    | AllPlay Binding
212 | Installed |  80 | 2.0.0.201701101935    | AllPlay Binding

However, after I did this the bundle seemed to be working again, at least it correctly identified the speakers and showed two of them as online and the other two which are powered off right now as offline. I had messages though in the log files about allplay binding being uninstalled and then initializing again:

10:55:23.647 [DEBUG] [org.openhab.binding.allplay         ] - BundleEvent UNRESOLVED - org.openhab.binding.allplay
10:55:23.657 [DEBUG] [org.openhab.binding.allplay         ] - BundleEvent UNINSTALLED - org.openhab.binding.allplay
10:55:23.697 [DEBUG] [org.openhab.binding.allplay         ] - BundleEvent RESOLVED - org.openhab.binding.allplay
10:55:23.699 [DEBUG] [org.openhab.binding.allplay         ] - BundleEvent STARTING - org.openhab.binding.allplay
10:55:23.707 [DEBUG] [org.openhab.binding.allplay         ] - BundleEvent STARTED - org.openhab.binding.allplay
10:55:23.709 [DEBUG] [org.openhab.binding.allplay         ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={component.name=org.openhab.binding.allplay.discovery, component.id=197, service.id=327, service.bundleid=212, service.scope=bundle} - org.openhab.binding.allplay
10:55:23.845 [DEBUG] [overy.AllPlaySpeakerDiscoveryService] - Starting scan for AllPlay devices
10:55:23.909 [INFO ] [marthome.event.ItemStateChangedEvent] - ObservationTime changed from NULL to 2017-01-12T10:54:59.000+0100
10:55:23.911 [INFO ] [marthome.event.ItemStateChangedEvent] - CurrentGasMeter changed from NULL to 0
10:55:23.911 [INFO ] [marthome.event.ItemStateChangedEvent] - GasMeterSignal changed from NULL to 48
10:55:23.912 [INFO ] [marthome.event.ItemStateChangedEvent] - PlexTVPower changed from NULL to OFF
10:55:23.913 [INFO ] [marthome.event.ItemStateChangedEvent] - Temp_Feel changed from NULL to 3.00
10:55:23.913 [INFO ] [marthome.event.ItemStateChangedEvent] - Wind_Speed_Beaufort changed from NULL to 0.00
10:55:24.159 [INFO ] [de.kaizencode.tchaikovsky.AllPlay   ] - Connecting to AllJoyn bus
10:55:24.182 [INFO ] [de.kaizencode.tchaikovsky.AllPlay   ] - Successfully connected to allJoyn bus with bus name :qSEMi_AH.2
10:55:24.183 [DEBUG] [ikovsky.discovery.SpeakerBusListener] - Registering signal handler
10:55:24.205 [DEBUG] [ovsky.discovery.SpeakerAboutListener] - Registering signal handler
10:55:24.210 [DEBUG] [ovsky.discovery.SpeakerAboutListener] - New SpeakerAnnouncedListener org.openhab.binding.allplay.discovery.AllPlaySpeakerDiscoveryService@62cabd6a has been added
10:55:24.210 [DEBUG] [ikovsky.discovery.SpeakerBusListener] - New SpeakerAnnouncedListener org.openhab.binding.allplay.discovery.AllPlaySpeakerDiscoveryService@62cabd6a has been added
10:55:24.219 [DEBUG] [org.openhab.binding.allplay         ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=org.openhab.binding.allplay.internal.AllPlayHandlerFactory, component.id=199, service.id=329, service.bundleid=212, service.scope=bundle} - org.openhab.binding.allplay
10:55:24.228 [DEBUG] [lplay.internal.AllPlayHandlerFactory] - Activating AllPlayHandlerFactory
10:55:24.231 [DEBUG] [lplay.internal.AllPlayHandlerFactory] - Connecting to AllPlay
10:55:24.232 [INFO ] [de.kaizencode.tchaikovsky.AllPlay   ] - Connecting to AllJoyn bus
10:55:24.234 [INFO ] [ikovsky.discovery.SpeakerBusListener] - foundAdvertisedName net.allplay.MediaPlayer.i4d56f675-1187-4bb2-ab40-a63b52d0c86c.rRXetIC5A - 256 - net.allplay.MediaPlayer
10:55:24.235 [INFO ] [ikovsky.discovery.SpeakerBusListener] - foundAdvertisedName net.allplay.MediaPlayer.i4d56f675-1187-4bb2-ab40-a63b52d0c86c.rRXetIC5A.quiet - 256 - net.allplay.MediaPlayer
10:55:24.235 [INFO ] [ikovsky.discovery.SpeakerBusListener] - foundAdvertisedName net.allplay.MediaPlayer.i4d56f675-1187-4bb2-ab40-a63b52d0c86c.rRXetIC5A - 4 - net.allplay.MediaPlayer
10:55:24.237 [INFO ] [ikovsky.discovery.SpeakerBusListener] - foundAdvertisedName net.allplay.MediaPlayer.i4d56f675-1187-4bb2-ab40-a63b52d0c86c.rRXetIC5A.quiet - 4 - net.allplay.MediaPlayer
10:55:24.237 [INFO ] [ikovsky.discovery.SpeakerBusListener] - Joining session with host [net.allplay.MediaPlayer.i4d56f675-1187-4bb2-ab40-a63b52d0c86c.rRXetIC5A], port [1]
10:55:24.246 [INFO ] [ikovsky.discovery.SpeakerBusListener] - foundAdvertisedName net.allplay.MediaPlayer.i5bb542e6-1198-4afb-bcd8-d91a611708f6.ro-2XfhFL - 256 - net.allplay.MediaPlayer
10:55:24.246 [INFO ] [ikovsky.discovery.SpeakerBusListener] - foundAdvertisedName net.allplay.MediaPlayer.i5bb542e6-1198-4afb-bcd8-d91a611708f6.ro-2XfhFL.quiet - 256 - net.allplay.MediaPlayer
10:55:24.246 [INFO ] [ikovsky.discovery.SpeakerBusListener] - foundAdvertisedName net.allplay.MediaPlayer.i5bb542e6-1198-4afb-bcd8-d91a611708f6.ro-2XfhFL - 4 - net.allplay.MediaPlayer
10:55:24.247 [INFO ] [ikovsky.discovery.SpeakerBusListener] - Joining session with host [net.allplay.MediaPlayer.i5bb542e6-1198-4afb-bcd8-d91a611708f6.ro-2XfhFL], port [1]
10:55:24.247 [INFO ] [ikovsky.discovery.SpeakerBusListener] - foundAdvertisedName net.allplay.MediaPlayer.i5bb542e6-1198-4afb-bcd8-d91a611708f6.ro-2XfhFL.quiet - 4 - net.allplay.MediaPlayer
10:55:24.250 [INFO ] [de.kaizencode.tchaikovsky.AllPlay   ] - Successfully connected to allJoyn bus with bus name :qSEMi_AH.3
10:55:24.250 [DEBUG] [ikovsky.discovery.SpeakerBusListener] - Registering signal handler
10:55:24.254 [DEBUG] [ovsky.discovery.SpeakerAboutListener] - Registering signal handler
10:55:24.260 [DEBUG] [lplay.internal.AllPlayHandlerFactory] - Creating AllPlayHandler for thing allplay:speaker:4d56f675-1187-4bb2-ab40-a63b52d0c86c
10:55:24.265 [DEBUG] [org.openhab.binding.allplay         ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.audio.AudioSink}={service.id=330, service.bundleid=212, service.scope=singleton} - org.openhab.binding.allplay
10:55:24.278 [DEBUG] [lplay.internal.AllPlayHandlerFactory] - Creating AllPlayHandler for thing allplay:speaker:e204fd21-161d-418e-ac44-438d018037e7
10:55:24.279 [DEBUG] [org.openhab.binding.allplay         ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.audio.AudioSink}={service.id=331, service.bundleid=212, service.scope=singleton} - org.openhab.binding.allplay
10:55:24.281 [DEBUG] [lplay.internal.AllPlayHandlerFactory] - Creating AllPlayHandler for thing allplay:speaker:44d8a58b-4144-4a13-8533-5a5e119fdbec
10:55:24.282 [DEBUG] [org.openhab.binding.allplay         ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.audio.AudioSink}={service.id=332, service.bundleid=212, service.scope=singleton} - org.openhab.binding.allplay
10:55:24.283 [DEBUG] [lplay.internal.AllPlayHandlerFactory] - Creating AllPlayHandler for thing allplay:speaker:5bb542e6-1198-4afb-bcd8-d91a611708f6
10:55:24.284 [DEBUG] [org.openhab.binding.allplay         ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.audio.AudioSink}={service.id=333, service.bundleid=212, service.scope=singleton} - org.openhab.binding.allplay
10:55:24.297 [INFO ] [core.karaf.internal.FeatureInstaller] - Uninstalled 'openhab-binding-allplay'
10:55:24.301 [INFO ] [smarthome.event.ExtensionEvent      ] - Extension 'binding-allplay' has been uninstalled.
10:55:24.308 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'allplay:speaker:4d56f675-1187-4bb2-ab40-a63b52d0c86c' changed from UNINITIALIZED to INITIALIZING
10:55:24.310 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Initializing AllPlay handler for speaker 4d56f675-1187-4bb2-ab40-a63b52d0c86c
10:55:24.311 [DEBUG] [ovsky.discovery.SpeakerAboutListener] - New SpeakerAnnouncedListener org.openhab.binding.allplay.handler.AllPlayHandler@674f6622 has been added
10:55:24.311 [DEBUG] [ikovsky.discovery.SpeakerBusListener] - New SpeakerAnnouncedListener org.openhab.binding.allplay.handler.AllPlayHandler@674f6622 has been added
10:55:24.311 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Starting discovery for speaker 4d56f675-1187-4bb2-ab40-a63b52d0c86c
10:55:24.312 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel control triggered with command REFRESH
10:55:24.313 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
10:55:24.313 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel coverart triggered with command REFRESH
10:55:24.313 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
10:55:24.313 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel currentalbum triggered with command REFRESH
10:55:24.313 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
10:55:24.313 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel currentartist triggered with command REFRESH
10:55:24.313 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
10:55:24.313 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel currenttitle triggered with command REFRESH
10:55:24.313 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
10:55:24.313 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel volume triggered with command REFRESH
10:55:24.313 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
.....
org.openhab.binding.allplay.handler.AllPlayHandler@2fa68fac has been added
10:55:24.340 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Starting discovery for speaker 5bb542e6-1198-4afb-bcd8-d91a611708f6
10:55:24.343 [INFO ] [ikovsky.discovery.SpeakerBusListener] - foundAdvertisedName net.allplay.MediaPlayer.i5bb542e6-1198-4afb-bcd8-d91a611708f6.ro-2XfhFL - 256 - net.allplay.MediaPlayer.i5bb542e6-1198-4afb-bcd8-d91a611708f6
10:55:24.343 [INFO ] [ikovsky.discovery.SpeakerBusListener] - foundAdvertisedName net.allplay.MediaPlayer.i5bb542e6-1198-4afb-bcd8-d91a611708f6.ro-2XfhFL - 4 - net.allplay.MediaPlayer.i5bb542e6-1198-4afb-bcd8-d91a611708f6
10:55:24.343 [INFO ] [ikovsky.discovery.SpeakerBusListener] - Joining session with host [net.allplay.MediaPlayer.i5bb542e6-1198-4afb-bcd8-d91a611708f6.ro-2XfhFL], port [1]
10:55:24.344 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel control triggered with command REFRESH
10:55:24.344 [INFO ] [ikovsky.discovery.SpeakerBusListener] - foundAdvertisedName net.allplay.MediaPlayer.i5bb542e6-1198-4afb-bcd8-d91a611708f6.ro-2XfhFL.quiet - 256 - net.allplay.MediaPlayer.i5bb542e6-1198-4afb-bcd8-d91a611708f6
10:55:24.344 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
10:55:24.344 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel coverart triggered with command REFRESH
10:55:24.344 [INFO ] [ikovsky.discovery.SpeakerBusListener] - foundAdvertisedName net.allplay.MediaPlayer.i5bb542e6-1198-4afb-bcd8-d91a611708f6.ro-2XfhFL.quiet - 4 - net.allplay.MediaPlayer.i5bb542e6-1198-4afb-bcd8-d91a611708f6
10:55:24.344 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
10:55:24.344 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel currentalbum triggered with command REFRESH
10:55:24.344 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
10:55:24.344 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel currentartist triggered with command REFRESH
10:55:24.344 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
10:55:24.345 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel currenttitle triggered with command REFRESH
10:55:24.345 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
....
10:55:24.347 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel currentartist triggered with command REFRESH
10:55:24.347 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
10:55:24.347 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel currenttitle triggered with command REFRESH
10:55:24.347 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
10:55:24.348 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel volume triggered with command REFRESH
10:55:24.348 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
10:55:24.348 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'allplay:speaker:5bb542e6-1198-4afb-bcd8-d91a611708f6' changed from INITIALIZING to OFFLINE: Waiting for speaker to be discovered
10:55:24.351 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'allplay:speaker:44d8a58b-4144-4a13-8533-5a5e119fdbec' changed from UNINITIALIZED to INITIALIZING
10:55:24.352 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'allplay:speaker:5bb542e6-1198-4afb-bcd8-d91a611708f6' changed from UNINITIALIZED to INITIALIZING
10:55:24.352 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel control triggered with command REFRESH
10:55:24.352 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
10:55:24.352 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel coverart triggered with command REFRESH
10:55:24.352 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
10:55:24.352 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel currentalbum triggered with command REFRESH
10:55:24.353 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
10:55:24.353 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel currentartist triggered with command REFRESH
10:55:24.353 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
10:55:24.353 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel currenttitle triggered with command REFRESH
10:55:24.353 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
10:55:24.353 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Channel volume triggered with command REFRESH
10:55:24.353 [WARN ] [nding.allplay.handler.AllPlayHandler] - Cannot execute command, speaker null is not discovered/connected!
10:55:24.353 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'allplay:speaker:44d8a58b-4144-4a13-8533-5a5e119fdbec' changed from INITIALIZING to OFFLINE: Waiting for speaker to be discovered
10:55:24.408 [INFO ] [ikovsky.discovery.SpeakerBusListener] - Joined session from local bus [:qSEMi_AH.2] to remote host [net.allplay.MediaPlayer.i5bb542e6-1198-4afb-bcd8-d91a611708f6.ro-2XfhFL] on sessionId [803840897]
10:55:24.431 [DEBUG] [overy.AllPlaySpeakerDiscoveryService] - Speaker EGLivingGramofon (5bb542e6-1198-4afb-bcd8-d91a611708f6) found by discovery service
10:55:24.751 [INFO ] [ikovsky.discovery.SpeakerBusListener] - Joined session from local bus [:qSEMi_AH.2] to remote host [net.allplay.MediaPlayer.i4d56f675-1187-4bb2-ab40-a63b52d0c86c.rRXetIC5A] on sessionId [853753424]
10:55:24.867 [INFO ] [ikovsky.discovery.SpeakerBusListener] - Joined session from local bus [:qSEMi_AH.3] to remote host [net.allplay.MediaPlayer.i4d56f675-1187-4bb2-ab40-a63b52d0c86c.rRXetIC5A] on sessionId [1077185591]
10:55:24.805 [INFO ] [ikovsky.discovery.SpeakerBusListener] - Joined session from local bus [:qSEMi_AH.3] to remote host [net.allplay.MediaPlayer.i5bb542e6-1198-4afb-bcd8-d91a611708f6.ro-2XfhFL] on sessionId [-1931079785]
10:55:25.434 [INFO ] [marthome.event.ItemStateChangedEvent] - PlexTVVolume changed from NULL to 100
10:55:25.434 [INFO ] [marthome.event.ItemStateChangedEvent] - PlexTVPause changed from NULL to OFF
10:55:25.448 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Speaker announcement received for speaker EGLivingGramofon (5bb542e6-1198-4afb-bcd8-d91a611708f6). Own id is 4d56f675-1187-4bb2-ab40-a63b52d0c86c
10:55:25.449 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Speaker announcement received for speaker EGLivingGramofon (5bb542e6-1198-4afb-bcd8-d91a611708f6). Own id is e204fd21-161d-418e-ac44-438d018037e7
10:55:25.449 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Speaker announcement received for speaker EGLivingGramofon (5bb542e6-1198-4afb-bcd8-d91a611708f6). Own id is 44d8a58b-4144-4a13-8533-5a5e119fdbec
10:55:25.449 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Speaker announcement received for speaker EGLivingGramofon (5bb542e6-1198-4afb-bcd8-d91a611708f6). Own id is 5bb542e6-1198-4afb-bcd8-d91a611708f6
10:55:25.449 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Speaker announcement received for handled speaker EGLivingGramofon (5bb542e6-1198-4afb-bcd8-d91a611708f6)
10:55:25.449 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Connecting to speaker EGLivingGramofon (5bb542e6-1198-4afb-bcd8-d91a611708f6)
10:55:25.449 [DEBUG] [de.tchaikovsky.bus.SpeakerBusHandler] - Joining session with host [net.allplay.MediaPlayer.i5bb542e6-1198-4afb-bcd8-d91a611708f6.ro-2XfhFL], port [1]
10:55:25.453 [DEBUG] [overy.AllPlaySpeakerDiscoveryService] - Speaker EGTVGramofon (4d56f675-1187-4bb2-ab40-a63b52d0c86c) found by discovery service
10:55:25.454 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Speaker announcement received for speaker EGTVGramofon (4d56f675-1187-4bb2-ab40-a63b52d0c86c). Own id is 4d56f675-1187-4bb2-ab40-a63b52d0c86c
10:55:25.454 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Speaker announcement received for handled speaker EGTVGramofon (4d56f675-1187-4bb2-ab40-a63b52d0c86c)
10:55:25.454 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Connecting to speaker EGTVGramofon (4d56f675-1187-4bb2-ab40-a63b52d0c86c)
10:55:25.454 [DEBUG] [de.tchaikovsky.bus.SpeakerBusHandler] - Joining session with host [net.allplay.MediaPlayer.i4d56f675-1187-4bb2-ab40-a63b52d0c86c.rRXetIC5A], port [1]
10:55:25.467 [DEBUG] [de.tchaikovsky.bus.SpeakerBusHandler] - Joined session from local bus [:qSEMi_AH.3] to remote host [net.allplay.MediaPlayer.i5bb542e6-1198-4afb-bcd8-d91a611708f6.ro-2XfhFL] on sessionId [2087207657]
10:55:25.470 [DEBUG] [de.tchaikovsky.bus.SpeakerBusHandler] - Created ProxyBusObject BusName [net.allplay.MediaPlayer.i5bb542e6-1198-4afb-bcd8-d91a611708f6.ro-2XfhFL], object path [/net/allplay/MediaPlayer]
10:55:25.498 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Connected to speaker EGLivingGramofon (5bb542e6-1198-4afb-bcd8-d91a611708f6)
10:55:25.498 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'allplay:speaker:5bb542e6-1198-4afb-bcd8-d91a611708f6' changed from OFFLINE: Waiting for speaker to be discovered to ONLINE
10:55:25.501 [DEBUG] [de.tchaikovsky.bus.SpeakerBusHandler] - Joined session from local bus [:qSEMi_AH.3] to remote host [net.allplay.MediaPlayer.i4d56f675-1187-4bb2-ab40-a63b52d0c86c.rRXetIC5A] on sessionId [-1916133693]
10:55:25.501 [DEBUG] [de.tchaikovsky.bus.SpeakerBusHandler] - Created ProxyBusObject BusName [net.allplay.MediaPlayer.i4d56f675-1187-4bb2-ab40-a63b52d0c86c.rRXetIC5A], object path [/net/allplay/MediaPlayer]
10:55:25.524 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Connected to speaker EGTVGramofon (4d56f675-1187-4bb2-ab40-a63b52d0c86c)
10:55:25.525 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'allplay:speaker:4d56f675-1187-4bb2-ab40-a63b52d0c86c' changed from OFFLINE: Waiting for speaker to be discovered to ONLINE
10:55:25.528 [DEBUG] [nding.allplay.handler.AllPlayHandler] - EGLivingGramofon: Mute changed to false
10:55:25.549 [DEBUG] [nding.allplay.handler.AllPlayHandler] - EGLivingGramofon: LoopMode changed to NONE
10:55:25.616 [DEBUG] [nding.allplay.handler.AllPlayHandler] - EGTVGramofon: Mute changed to false
10:55:25.654 [DEBUG] [nding.allplay.handler.AllPlayHandler] - EGLivingGramofon: ShuffleMode changed to SHUFFLE
10:55:25.661 [DEBUG] [nding.allplay.handler.AllPlayHandler] - EGTVGramofon: LoopMode changed to NONE
10:55:25.672 [DEBUG] [nding.allplay.handler.AllPlayHandler] - EGLivingGramofon: PlayState changed to TRANSITIONING at position 0 and index -1
10:55:25.675 [DEBUG] [nding.allplay.handler.AllPlayHandler] - EGLivingGramofon: PlaylistItem changed to The Kinks - All Day and All of the Night (spotify://)
10:55:25.676 [INFO ] [marthome.event.ItemStateChangedEvent] - allplay_speaker_5bb542e6_1198_4afb_bcd8_d91a611708f6_control changed from NULL to PAUSE
10:55:25.676 [INFO ] [marthome.event.ItemStateChangedEvent] - allplay_speaker_5bb542e6_1198_4afb_bcd8_d91a611708f6_currentartist changed from NULL to The Kinks
10:55:25.678 [INFO ] [marthome.event.ItemStateChangedEvent] - allplay_speaker_5bb542e6_1198_4afb_bcd8_d91a611708f6_currenttitle changed from NULL to All Day and All of the Night
10:55:25.678 [INFO ] [marthome.event.ItemStateChangedEvent] - allplay_speaker_5bb542e6_1198_4afb_bcd8_d91a611708f6_currentalbum changed from NULL to Kinks (Deluxe Edition)
10:55:25.682 [DEBUG] [nding.allplay.handler.AllPlayHandler] - EGTVGramofon: ShuffleMode changed to LINEAR
10:55:25.685 [DEBUG] [nding.allplay.handler.AllPlayHandler] - EGLivingGramofon: Cover art URL changed to http://o.scdn.co/640/6170f663983673a7bbb59b3be0374da140f6993f
10:55:25.690 [DEBUG] [nding.allplay.handler.AllPlayHandler] - EGTVGramofon: PlayState changed to STOPPED at position 8594398611209696400 and index -1
10:55:25.692 [INFO ] [marthome.event.ItemStateChangedEvent] - allplay_speaker_4d56f675_1187_4bb2_ab40_a63b52d0c86c_control changed from NULL to PAUSE
10:55:25.702 [DEBUG] [nding.allplay.handler.AllPlayHandler] - EGTVGramofon: Volume changed to 50
10:55:25.702 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Absolute volume 50 has been converted to volume 50%
10:55:25.704 [INFO ] [marthome.event.ItemStateChangedEvent] - allplay_speaker_4d56f675_1187_4bb2_ab40_a63b52d0c86c_volume changed from NULL to 50
10:55:25.712 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Speaker announcement received for speaker EGTVGramofon (4d56f675-1187-4bb2-ab40-a63b52d0c86c). Own id is e204fd21-161d-418e-ac44-438d018037e7
10:55:25.712 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Speaker announcement received for speaker EGTVGramofon (4d56f675-1187-4bb2-ab40-a63b52d0c86c). Own id is 44d8a58b-4144-4a13-8533-5a5e119fdbec
10:55:25.712 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Speaker announcement received for speaker EGTVGramofon (4d56f675-1187-4bb2-ab40-a63b52d0c86c). Own id is 5bb542e6-1198-4afb-bcd8-d91a611708f6
10:55:25.921 [DEBUG] [nding.allplay.handler.AllPlayHandler] - MediaType:
10:55:25.925 [INFO ] [marthome.event.ItemStateChangedEvent] - allplay_speaker_5bb542e6_1198_4afb_bcd8_d91a611708f6_coverart changed from NULL to raw type: 39822 bytes
10:55:25.930 [DEBUG] [nding.allplay.handler.AllPlayHandler] - EGLivingGramofon: Volume changed to 50
10:55:25.930 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Absolute volume 50 has been converted to volume 50%
10:55:25.932 [INFO ] [marthome.event.ItemStateChangedEvent] - allplay_speaker_5bb542e6_1198_4afb_bcd8_d91a611708f6_volume changed from NULL to 50

In order to correct the bundle hickup I tried again to uninstall the bundle from Paper UI (maybe I did something wrong again here, as meanwhile I think it cleaned up everything itself meanwhile and I should just have checked bundle status again after a while). this resulted in a crash of Karaf console, however OH still seems to be running fine:

10:57:11.833 [DEBUG] [org.openhab.binding.allplay         ] - BundleEvent STOPPING - org.openhab.binding.allplay
10:57:11.835 [DEBUG] [org.openhab.binding.allplay         ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.discovery.DiscoveryService}={component.name=org.openhab.binding.allplay.discovery, component.id=197, service.id=327, service.bundleid=212, service.scope=bundle} - org.openhab.binding.allplay
10:57:11.837 [DEBUG] [org.openhab.binding.allplay         ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=org.openhab.binding.allplay.internal.AllPlayHandlerFactory, component.id=199, service.id=329, service.bundleid=212, service.scope=bundle} - org.openhab.binding.allplay
10:57:11.839 [DEBUG] [org.openhab.binding.allplay         ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.core.audio.AudioSink}={service.id=331, service.bundleid=212, service.scope=singleton} - org.openhab.binding.allplay
10:57:11.842 [DEBUG] [org.openhab.binding.allplay         ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.core.audio.AudioSink}={service.id=332, service.bundleid=212, service.scope=singleton} - org.openhab.binding.allplay
10:57:11.843 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'allplay:speaker:e204fd21-161d-418e-ac44-438d018037e7' changed from OFFLINE: Waiting for speaker to be discovered to UNINITIALIZED (HANDLER_MISSING_ERROR)
10:57:11.844 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'allplay:speaker:44d8a58b-4144-4a13-8533-5a5e119fdbec' changed from OFFLINE: Waiting for speaker to be discovered to UNINITIALIZED (HANDLER_MISSING_ERROR)
10:57:11.845 [DEBUG] [org.openhab.binding.allplay         ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.core.audio.AudioSink}={service.id=333, service.bundleid=212, service.scope=singleton} - org.openhab.binding.allplay
10:57:11.846 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Disconnecting from speaker EGLivingGramofon (5bb542e6-1198-4afb-bcd8-d91a611708f6)
10:57:11.847 [DEBUG] [ovsky.discovery.SpeakerAboutListener] - SpeakerAnnouncedListener org.openhab.binding.allplay.handler.AllPlayHandler@2fa68fac has been removed
10:57:11.847 [DEBUG] [ikovsky.discovery.SpeakerBusListener] - SpeakerAnnouncedListener org.openhab.binding.allplay.handler.AllPlayHandler@2fa68fac has been removed
10:57:11.849 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'allplay:speaker:5bb542e6-1198-4afb-bcd8-d91a611708f6' changed from ONLINE to UNINITIALIZED (HANDLER_MISSING_ERROR)
10:57:11.849 [DEBUG] [org.openhab.binding.allplay         ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.core.audio.AudioSink}={service.id=330, service.bundleid=212, service.scope=singleton} - org.openhab.binding.allplay
10:57:11.854 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'allplay:speaker:4d56f675-1187-4bb2-ab40-a63b52d0c86c' changed from ONLINE to UNINITIALIZED (HANDLER_MISSING_ERROR)
10:57:11.855 [DEBUG] [nding.allplay.handler.AllPlayHandler] - Disconnecting from speaker EGTVGramofon (4d56f675-1187-4bb2-ab40-a63b52d0c86c)
10:57:11.855 [DEBUG] [ovsky.discovery.SpeakerAboutListener] - SpeakerAnnouncedListener org.openhab.binding.allplay.handler.AllPlayHandler@674f6622 has been removed
10:57:11.855 [DEBUG] [ikovsky.discovery.SpeakerBusListener] - SpeakerAnnouncedListener org.openhab.binding.allplay.handler.AllPlayHandler@674f6622 has been removed

openhab> bundle:list
START LEVEL 100 , List Threshold: 50
 ID | State    | Lvl | Version               | Name
-----------------------------------------------------------------------------------------------------
.......
208 | Resolved |  80 | 2.0.0.201701091302    | openHAB Paper UI Theme Fragment, Hosts: 196
210 | Active   |  80 | 1.9.0.201701100211    | openHAB Plex Binding
211 | Active   |  80 | 2.0.0.201612122156    | Animated Climacons Iconset
212 | Active   |  80 | 2.0.0.201701101935    | AllPlay Binding
openhab>

it seems to be working fine now, I can control speakers and such so my original issue seems solved. However, although for sure I did not always follow the recommended way of installing/uninstalling the binding, I think something might still be going wrong in regards of uninstalling the allplay binding in case it lost connection to its speakers. Of course it might all be solved with this TCP/UDP issue as well. Just let me know if i should try to reproduce this and what steps i should follow in case you need to futher investigate this.

dominicdesu · January 12, 2017, 5:50pm

Hm, could you check in /var/lib/openhab2/ if you have a related log file (something like hs_err_pid*.log)?

Max1968 · January 12, 2017, 7:43pm

attached - just remove the pdf extension as .log is not allowed here

hs_err_pid13002.log.pdf (153.4 KB)

dominicdesu · January 12, 2017, 8:44pm

Thanks!
My current assumption is that the native binding deadlocked when the binding tried to (re-)connect to 8 speakers (4x TCP, 4x UDP) at the same time. (Actually the issue is in the Java library I wrote to control AllJoyn as it is using the native library incorrectly). Then the binding tried to disconnect when you uninstalled it, which finally caused the JVM crash.
I need to update the Java library accordingly and will create a new PR which should hopefully fix this issue in the future.

Thanks for your great support to figure out the cause of the issue. Would be great if you could also test the updated binding when it’s finished and before I’ll create the PR.

dominicdesu · January 16, 2017, 5:45pm

Hi @Max1968, would you mind trying out the latest version of the binding before I’ll create a PR for it?
You can just copy it over the existing binding in your addons folder, but it would be great if you could provide the log files after you replaced it. I would like to see how it handles your UPD/TCP speakers.

Here is the latest version: https://drive.google.com/file/d/0B5RwWQEiYx5tSlU4WWVJdjNON1U/view?usp=sharing