I wonder if we miss messages from the server; as even with massive timeout values the problem persists; I noticed that the “wait” methods register only after the command was sent. Could this result in a race condition were we miss the answer (if it is too fast; insted of too slow)?
For example:
// Give up since we timed out waiting for playlist to update
squeezeBoxServerHandler.setVolume(mac, playerState.getVolume());
waitForVolume(playerState.getVolume());
should 1st register then send the command:
SqueezeBoxNotificationListener listener = new SqueezeBoxNotificationListener(mac);
squeezeBoxServerHandler.registerSqueezeBoxPlayerListener(listener);
squeezeBoxServerHandler.setVolume(mac, targetVolume);
or the runtime is slow for any reason … I´ll give it a try if I refactor the thing to properly register 1st; as it could happen (and according to Murphy it will).
ok … my setup needs both, higher timouts and proper synchronization; then tts seems to work. My prototype has some problems with dynamically created playlists - but that´s not a big issue. I´ll give it a couple of days to run to see if it remains stable.
I factored the notification handling out into its own class to make the classes smaller; might in any case be worth a consideration.
@mhilbush
Strange; problem still persists - if I remove the wiat for the prefset confirmation of the command it works. Using trace I see that I only receive prefset messages for power and playlist item played; but not for stop and volume. Do you have any idea?
2017-12-24 13:06:52.673 [INFO ] [e.smarthome.model.script.Debug.rules] - TTS test - start ...
2017-12-24 13:06:52.677 [DEBUG] [eezebox.internal.SqueezeBoxAudioSink] - Processing audioStream http://192.168.0.73:8080/audio/049e28a9-501b-4754-83a0-5b195af940e1.mp3 of format AudioFormat [codec=MP3, container=NONE, bitDepth=16, bitRate=64000, frequency=44100]
2017-12-24 13:06:52.678 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Play notification sound on player 00:04:20:29:62:0e at URI http://192.168.0.73:8080/audio/049e28a9-501b-4754-83a0-5b195af940e1.mp3
2017-12-24 13:06:52.681 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Cur State: vol=16, mut=NOT MUTED, pwr=OFF, stp=STOPPED, ctl=PAUSED, shf=OFF, rpt=OFF, tix=0, tnm=1, tim=46
2017-12-24 13:06:52.685 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Initializing notification volume to current player volume
2017-12-24 13:06:52.687 [DEBUG] [.internal.SqueezeBoxPlayNotification] - Current number of tracks in the playlist: 1
2017-12-24 13:06:52.688 [DEBUG] [.internal.SqueezeBoxPlayNotification] - Setting up player for notification
2017-12-24 13:06:52.688 [DEBUG] [.internal.SqueezeBoxPlayNotification] - Powering on the player
2017-12-24 13:06:52.689 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: 00:04:20:29:62:0e power 1
2017-12-24 13:06:52.694 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Registering player listener
2017-12-24 13:06:52.695 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: 00:04:20:29:62:0e playlist add http://192.168.0.73:8080/audio/049e28a9-501b-4754-83a0-5b195af940e1.mp3
2017-12-24 13:06:52.696 [TRACE] [.internal.SqueezeBoxPlayNotification] - Waiting up to 50000 ms for playlist to be updated...
2017-12-24 13:06:52.713 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: 00%3A04%3A20%3A29%3A62%3A0e power 1
2017-12-24 13:06:52.714 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled player update message type 'power'.
2017-12-24 13:06:52.717 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: 00%3A04%3A20%3A29%3A62%3A0e displaynotify showbriefly HASH(0x99c7344)
2017-12-24 13:06:52.718 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled player update message type 'displaynotify'.
2017-12-24 13:06:52.722 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: 00%3A04%3A20%3A29%3A62%3A0e playlist add http%3A%2F%2F192.168.0.73%3A8080%2Faudio%2F049e28a9-501b-4754-83a0-5b195af940e1.mp3
2017-12-24 13:06:52.722 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled playlist message type '[00%3A04%3A20%3A29%3A62%3A0e, playlist, add, http%3A%2F%2F192.168.0.73%3A8080%2Faudio%2F049e28a9-501b-4754-83a0-5b195af940e1.mp3]'
2017-12-24 13:06:52.726 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: 00%3A04%3A20%3A28%3A65%3Ac7 menustatus ARRAY(0x962fba4) add 00%3A04%3A20%3A28%3A65%3Ac7
2017-12-24 13:06:52.727 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled player update message type 'menustatus'.
2017-12-24 13:06:52.730 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: 00%3A04%3A20%3A2a%3A3b%3A21 menustatus ARRAY(0x99e0c0c) add 00%3A04%3A20%3A2a%3A3b%3A21
2017-12-24 13:06:52.731 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled player update message type 'menustatus'.
2017-12-24 13:06:52.734 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: 00%3A04%3A20%3A29%3Aa7%3A27 menustatus ARRAY(0x99e54d4) add 00%3A04%3A20%3A29%3Aa7%3A27
2017-12-24 13:06:52.735 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled player update message type 'menustatus'.
2017-12-24 13:06:52.738 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: 00%3A04%3A20%3A28%3A65%3A91 menustatus ARRAY(0x9810fb4) add 00%3A04%3A20%3A28%3A65%3A91
2017-12-24 13:06:52.739 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled player update message type 'menustatus'.
2017-12-24 13:06:52.742 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: 00%3A04%3A20%3A23%3A52%3A3c menustatus ARRAY(0x9631814) add 00%3A04%3A20%3A23%3A52%3A3c
2017-12-24 13:06:52.742 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled player update message type 'menustatus'.
2017-12-24 13:06:52.746 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: 00%3A04%3A20%3A2a%3A37%3A4b menustatus ARRAY(0x99c53c4) add 00%3A04%3A20%3A2a%3A37%3A4b
2017-12-24 13:06:52.747 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled player update message type 'menustatus'.
2017-12-24 13:06:52.750 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: 4b%3A22%3A1b%3A57%3Aca%3A87 menustatus ARRAY(0x980a0bc) add 4b%3A22%3A1b%3A57%3Aca%3A87
2017-12-24 13:06:52.751 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled player update message type 'menustatus'.
2017-12-24 13:06:52.822 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: 00%3A04%3A20%3A29%3A62%3A0e prefset server power 1
2017-12-24 13:06:52.824 [TRACE] [ebox.handler.SqueezeBoxPlayerHandler] - Updating channel power for thing squeezebox:squeezeboxplayer:D841762A-D007-4609-988D-EC0A58A82A56:00042029620e with mac 00:04:20:29:62:0e to state ON
2017-12-24 13:07:00.169 [INFO ] [.smarthome.model.script.Wecker.rules] - TimeToAlarm - Timer: null
2017-12-24 13:07:40.051 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: players 0
2017-12-24 13:07:43.612 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unregistering player listener
2017-12-24 13:07:43.613 [WARN ] [.internal.SqueezeBoxPlayNotification] - TIMEOUT after 50000 waiting for playlist to update!
2017-12-24 13:07:43.615 [ERROR] [.internal.SqueezeBoxPlayNotification] - TIMEOUT
How does the communication look with your LMS and what version of the server do you use?
Looking specifically at the playlist add at TRACE level… The key line is this one, which indicates that the playlist contains the new entry. I don’t see that line in your log, and I have no idea why not. It’s important to have this, as it’s used later to delete the TTS playlist entry.
2017-12-24 11:46:29.582 [TRACE] [ndler.SqueezeBoxNotificationListener] - Number of playlist tracks is 2 for player 00:26:18:57:f0:31
2017-12-24 11:46:29.225 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Playing notification
2017-12-24 11:46:29.225 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: 00:26:18:57:f0:31 playlist add http://192.168.10.30:8080/audio/de9d481a-8199-44f9-8d60-3674ddb4531b.mp3
2017-12-24 11:46:29.226 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Registering player listener
2017-12-24 11:46:29.226 [TRACE] [ebox.handler.SqueezeBoxPlayerHandler] - Waiting up to 5000 ms for playlist to be updated...
2017-12-24 11:46:29.234 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: 00%3A26%3A18%3A57%3Af0%3A31 displaynotify showbriefly HASH(0x8247630)
2017-12-24 11:46:29.234 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled player update message type 'displaynotify'.
2017-12-24 11:46:29.237 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: 00%3A26%3A18%3A57%3Af0%3A31 playlist add http%3A%2F%2F192.168.10.30%3A8080%2Faudio%2Fde9d481a-8199-44f9-8d60-3674ddb4531b.mp3
2017-12-24 11:46:29.238 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled playlist message type '[00%3A26%3A18%3A57%3Af0%3A31, playlist, add, http%3A%2F%2F192.168.10.30%3A8080%2Faudio%2Fde9d481a-8199-44f9-8d60-3674ddb4531b.mp3]'
2017-12-24 11:46:29.238 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: 00%3A26%3A18%3A57%3Af0%3A31 playlist load_done
2017-12-24 11:46:29.239 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled playlist message type '[00%3A26%3A18%3A57%3Af0%3A31, playlist, load_done]'
2017-12-24 11:46:29.574 [TRACE] [ndler.SqueezeBoxNotificationListener] - Mode is stop for player 00:26:18:57:f0:31
2017-12-24 11:46:29.578 [TRACE] [ebox.handler.SqueezeBoxPlayerHandler] - Updating channel currentPlayingTime for thing squeezebox:squeezeboxplayer:BD72319C-1EC2-4FD3-8A1C-877B6796A80C:00261857f031 with mac 00:26:18:57:f0:31 to state 0
2017-12-24 11:46:29.580 [TRACE] [ndler.SqueezeBoxNotificationListener] - Volume is 53 for player 00:26:18:57:f0:31
2017-12-24 11:46:29.582 [TRACE] [ndler.SqueezeBoxNotificationListener] - Number of playlist tracks is 2 for player 00:26:18:57:f0:31
2017-12-24 11:46:29.583 [TRACE] [ebox.handler.SqueezeBoxPlayerHandler] - Updating channel numberPlaylistTracks for thing squeezebox:squeezeboxplayer:BD72319C-1EC2-4FD3-8A1C-877B6796A80C:00261857f031 with mac 00:26:18:57:f0:31 to state 2
2017-12-24 11:46:29.628 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unregistering player listener
2017-12-24 11:46:29.629 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Done waiting 400 ms for playlist to update
I´ve tried the same server version as you do; still the same issue. I wonder if I shall change the playlist wait to expect the “load_done” message; as this is seen on both our systems. What do you think?
Early on I considered using load_done, as it will indicate that the playlist add is successful. However, without the playlist number, it’s not possible to delete the TTS playlist item from the playlist once the TTS item has finished playing.
Also, since you’re having timeout issues on volume commands, load_done won’t help with those issues.
It almost seems like messages from the LMS are being dropped somewhere. Is your LMS running on the same hardware as OH?
By any chance, do you have a backup of the OH version that worked, and would it be possible to revert to that backup in order to confirm that this issue goes away?
I think you also mentioned that you had 8 players. Would it be possible to reduce the number of players (by deleting the player Things), in order to see if that is having any influence on the behavior you’re seeing.
I´ll try to revert back to OH 2.1 binding and log the trace to see if it is different. OH and the LMS are on the same hardware - also tried some SW players to verify if the problem exists there as well.
I played a little with telnet and I only receive a prefset for volume if the volume actually changes; if I send the same value as it is already then no response arrives:
Here I already only send a volume update if the target volume does not match the player state; thus you do not see this requests. Do you get a response if you set the same volume twice?
In TRACE mode, I see a player status message every couple seconds. I suspect it’s picking up the volume from that message in the event it doesn’t get a prefset volume message. That explains why some volume sets are a couple hundred ms and others are 2-3000 ms.
Those status messages I see in TRACE mode seem to cycle through my 3 players sequentially. I suspect I’m just getting lucky that I get one for the right player when waiting for the volume update. I suspect you’re less lucky with 8 players.
Can you delete a few of your player things to see what happens?
