2017-10-28, 22:32
@dantist
Based on the above logs, what seems to be happening is that Hyperion is using JSON to query Kodi and determine the type of player that is now active - video or audio - after receiving the "Player.OnPlay" notification.
Unfortunately, the Hyperion log only captures half of the communication - the responses and not the requests - so I can only guess that Hyperion is issuing a "Player.GetActivePlayers" request after receiving the "Player.OnPlay" notification.
This is the notification and then reply from the #0913 log:
and the same, but from #1024:
Notice that the reply (presumably, for "Player.GetActivePlayers"), is "[]" which indicates there is no active player.
So my guess is that there is now a "timing" issue in Kodi since #0914, introduced by one or both of:
I would suggest that since #0914, whenever Kodi kicks out a "Player.OnPlay" notification, it is now possible (due to the asynchronous open?) for the Kodi player to not yet be "active", so that any client (such as Hyperion) querying Kodi immediately (or very soon) after receiving a "Player.OnPlay" notification, will be informed there is no active player (which is a change in behaviour compared with #0913). If Hyperion had waited 1-2 seconds after receiving the "Player.OnPlay" notification there almost certainly would have been an active video player - but obviously, adding a random delay isn't a solution!
You should open a Kodi trac ticket for this...
(2017-10-25, 17:51)dantist Wrote:(2017-10-25, 12:56)popcornmix Wrote: The contents of /storage/logfiles/hyperion.log when working and not working may be useful
#0913: https://pastebin.com/7pbwUyHk
#1024: https://pastebin.com/pzLZJ1Na
Based on the above logs, what seems to be happening is that Hyperion is using JSON to query Kodi and determine the type of player that is now active - video or audio - after receiving the "Player.OnPlay" notification.
Unfortunately, the Hyperion log only captures half of the communication - the responses and not the requests - so I can only guess that Hyperion is issuing a "Player.GetActivePlayers" request after receiving the "Player.OnPlay" notification.
This is the notification and then reply from the #0913 log:
Code:
KODICHECK INFO: Kodi Message: {"jsonrpc":"2.0","method":"Player.OnPlay","params":{"data":{"item":{"id":2793,"type":"episode"},"player":{"playerid":1,"speed":1}},"sender":"xbmc"}}
KODICHECK INFO: Kodi Message: {"id":666,"jsonrpc":"2.0","result":[{"playerid":1,"type":"video"}]}
Code:
KODICHECK INFO: Kodi Message: {"jsonrpc":"2.0","method":"Player.OnPlay","params":{"data":{"item":{"id":2793,"type":"episode"},"player":{"playerid":1,"speed":1}},"sender":"xbmc"}}
KODICHECK INFO: Kodi Message: {"id":666,"jsonrpc":"2.0","result":[]}
Notice that the reply (presumably, for "Player.GetActivePlayers"), is "[]" which indicates there is no active player.
So my guess is that there is now a "timing" issue in Kodi since #0914, introduced by one or both of:
- VideoPlayer: make OpenFile asynchron (PR:12797, 2 commits, 11 files changed)
- VideoPlayer: fix OnPlayBack callbacks (PR:12799, 2 commits, 3 files changed)
I would suggest that since #0914, whenever Kodi kicks out a "Player.OnPlay" notification, it is now possible (due to the asynchronous open?) for the Kodi player to not yet be "active", so that any client (such as Hyperion) querying Kodi immediately (or very soon) after receiving a "Player.OnPlay" notification, will be informed there is no active player (which is a change in behaviour compared with #0913). If Hyperion had waited 1-2 seconds after receiving the "Player.OnPlay" notification there almost certainly would have been an active video player - but obviously, adding a random delay isn't a solution!
You should open a Kodi trac ticket for this...