Jump to content

Plugin path play slow Vs direct smb path play instant


scalda
 Share

Recommended Posts

Angelblue05

@@scalda

 

I'm checking your log again. From the looks of it, when you started playback, there was still updating happening which could explain the delay you've been experiencing. At least looking at the logs, it seems ItemCount (I think it's votes?) was still being written to database. Is it possible for you to let your Kodi run a bit to see if things settles?

 

Edit: Even when kodi was shutting down, itemcount was still being pulled from your server. I thought maybe they were the same item, but it seems to be different ones each time.

Edited by Angelblue05
Link to comment
Share on other sites

Ok well I'm going to have to revert back to the earlier release as I can't have it keep polling the database everytime something is played as it's just to many data read and writes to my sd card and it slows my system down, which is a shame as it was working so well didn't have any problems till you reverted back to using the plugin location to store information for local playback

Link to comment
Share on other sites

Angelblue05

I don't think it's constantly pulling data, it's more the fact that it was still writing information to your database at the moment of playback. This stops when the information is fully set. If you allow it to finish then it would most likely resolve your issue. 

Link to comment
Share on other sites

I don't think it's constantly pulling data, it's more the fact that it was still writing information to your database at the moment of playback. This stops when the information is fully set. If you allow it to finish then it would most likely resolve your issue.

That would be for every file that I play I would have to pause it as soon as it started so the database can write the changes that it needs ie the path to the file as you have already stated that's what it does. The problem that no one seems to be grasping is that kodi is getting a Path substitute from the plugin folder before the media is ever played and then changing this path in the database when it goes to play the file where as before there was no path substitute and it just played straight from the file location on my server via smb and no database changes and that are made til the file is finished playing to update the play count and watched status

Link to comment
Share on other sites

yeah no problem, you should probably do that, just head back to a pre 0.1.0 release to go back to the old way.

 

DB polling will still happen, you may need to roll back the old old addon, the one that does nto sync the DB if you truly want to move away from DB sync issues.

I don't have any database sync issues it's the file playbacks from the path substitute in the plugin folder like it was when the Addon first came out and then it was changed to the direct smb path and since then it has worked flawlessly this is what I'm trying to get across I love the Addon and it's the thing I have been waiting for, for a long time I never used the old Addon as it wasn't what I wanted and needed

Link to comment
Share on other sites

Angelblue05

Well as null_pointer said you know what you can do. We do not write the path to database when playback starts. However I am super confused about the fact that you have smb path in 0.1.81 when the playback path using plugin:// has been in place since 0.1.0.... Were all the paths smb? or just the first ones?

 

What I see in your log is it looks like the connection dropped right after your initial sync.

15:21:04 T:4780 ERROR: Starting new HTTP connection (1): 192.168.1.140

If you look at these lines too: The plugin:// seems to have responded quickly so the path redirection is not the problem.

15:21:38 T:1156  NOTICE: EMBY PlayUtils -> logMsg : Path exists.
15:21:39 T:1156  NOTICE: EMBY PlayUtils -> logMsg : File is direct playing.
15:21:39 T:4800  NOTICE: DVDPlayer: Opening: smb://USERNAME:PASSWORD@MEDIASERVER-3/TV/The Blacklist/Season 2/The Blacklist - 2x01 - Lord Baltimore.mkv
15:30:34 T:4076  NOTICE: EMBY PlayUtils -> logMsg : Path exists.
15:30:34 T:4076  NOTICE: EMBY PlayUtils -> logMsg : File is direct playing.
15:30:34 T:4800  NOTICE: DVDPlayer: Opening: smb://USERNAME:PASSWORD@MEDIASERVER-3/Movies/Project Almanac (2015)/Project Almanac (2015).mkv 

It looks like the problem is there. I think the only way to find out what Kodi is doing is if you set back your Emby for Kodi log back to info and enable actual Kodi debug so we see whats holding up when you click the item, and the parameter is returned to the addon.

15:21:29 T:1156  NOTICE: -->Python Interpreter Initialized<--
15:21:38 T:1156  NOTICE: Parameter string: ?id=d0327f2c125ff96baab3cca2174c781b&mode=play

Either way, it's up to you how you want to deal with this, go back or keep trying to help us out to improve the add-on. When I look at your playback later, it seems to have taken 2-3seconds each time.

Edited by Angelblue05
Link to comment
Share on other sites

hi i have just done a clean install of your addon on my pi2, i deleted all current databases, and i have just gone to play avatar and it took longer then 10 seconds to play please find attached log file

 

https://dl.dropboxusercontent.com/u/8871364/Captures/kodi%2024-05-2015.log

 

also here is the part of the log stating the initial play of the video showing, also the sync update and then me stopping it and it running the update again

14:10:12 T:1956884480   DEBUG: OnPlayMedia plugin://plugin.video.emby/movies/dbb6d7af2127fda91ccb63a2f9e24dc8/?id=dbb6d7af2127fda91ccb63a2f9e24dc8&mode=play
14:10:12 T:1956884480   DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
14:10:12 T:1956884480   DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
14:10:12 T:1956884480   DEBUG: StartScript - calling plugin Emby('plugin://plugin.video.emby/movies/dbb6d7af2127fda91ccb63a2f9e24dc8/','1','?id=dbb6d7af2127fda91ccb63a2f9e24dc8&mode=play')
14:10:12 T:1494217760  NOTICE: Thread LanguageInvoker start, auto delete: false
14:10:12 T:1956884480   DEBUG: WaitOnScriptResult - waiting on the Emby (id=9) plugin...
14:10:12 T:1494217760    INFO: initializing python engine.
14:10:12 T:1494217760   DEBUG: CPythonInvoker(9, /home/osmc/.kodi/addons/Emby.Kodi-master/default.py): start processing
14:10:12 T:1863316512   DEBUG: PushCecKeypress - received key  b duration 77
14:10:12 T:1494217760  NOTICE: -->Python Interpreter Initialized<--
14:10:12 T:1494217760   DEBUG: CPythonInvoker(9, /home/osmc/.kodi/addons/Emby.Kodi-master/default.py): the source file to load is "/home/osmc/.kodi/addons/Emby.Kodi-master/default.py"
14:10:12 T:1494217760   DEBUG: CPythonInvoker(9, /home/osmc/.kodi/addons/Emby.Kodi-master/default.py): setting the Python path to /home/osmc/.kodi/addons/Emby.Kodi-master:/home/osmc/.kodi/addons/script.module.requests/lib:/usr/lib/python2.7:/usr/lib/python2.7/plat-arm-linux-gnueabihf:/usr/lib/python2.7/lib-tk:/usr/lib/python2.7/lib-old:/usr/lib/python2.7/lib-dynload:/usr/local/lib/python2.7/dist-packages:/usr/lib/python2.7/dist-packages:/usr/lib/python2.7/dist-packages/PILcompat:/usr/lib/python2.7/dist-packages/gtk-2.0
14:10:12 T:1494217760   DEBUG: CPythonInvoker(9, /home/osmc/.kodi/addons/Emby.Kodi-master/default.py): entering source directory /home/osmc/.kodi/addons/Emby.Kodi-master
14:10:12 T:1494217760   DEBUG: CPythonInvoker(9, /home/osmc/.kodi/addons/Emby.Kodi-master/default.py): instantiating addon using automatically obtained id of "plugin.video.emby" dependent on version 2.1.0 of the xbmc.python api
14:10:13 T:1494217760  NOTICE: Parameter string: ?id=dbb6d7af2127fda91ccb63a2f9e24dc8&mode=play
14:10:13 T:1494217760  NOTICE: PLAY Called
14:10:13 T:1494217760  NOTICE: EMBY PlayUtils -> File is direct playing.
14:10:13 T:1956884480   DEBUG: WaitOnScriptResult- plugin returned successfully
14:10:13 T:1494217760    INFO: CPythonInvoker(9, /home/osmc/.kodi/addons/Emby.Kodi-master/default.py): script successfully run
14:10:13 T:1956884480   DEBUG: Loading settings for smb://scott:password@MEDIASERVER/x$/Kids movies/Avatar (2009)/Avatar (2009).mkv
14:10:13 T:1956884480   DEBUG: CPlayerCoreFactory::GetPlayers(smb://USERNAME:PASSWORD@MEDIASERVER/x$/Kids movies/Avatar (2009)/Avatar (2009).mkv)
14:10:13 T:1956884480   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: system rules
14:10:13 T:1956884480   DEBUG: CPlayerSelectionRule::GetPlayers: matches rule: system rules
14:10:13 T:1956884480   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: rtv
14:10:13 T:1956884480   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: hdhomerun/myth/mms/udp
14:10:13 T:1956884480   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: lastfm/shout
14:10:13 T:1956884480   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: rtmp
14:10:13 T:1956884480   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: rtsp
14:10:13 T:1956884480   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: streams
14:10:13 T:1956884480   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: dvd
14:10:13 T:1956884480   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: dvdimage
14:10:13 T:1956884480   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: sdp/asf
14:10:13 T:1956884480   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: nsv
14:10:13 T:1956884480   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: radio
14:10:13 T:1956884480   DEBUG: CPlayerCoreFactory::GetPlayers: matched 0 rules with players
14:10:13 T:1956884480   DEBUG: CPlayerCoreFactory::GetPlayers: adding videodefaultplayer (1)
14:10:13 T:1956884480   DEBUG: CPlayerCoreFactory::GetPlayers: for video=1, audio=0
14:10:13 T:1956884480   DEBUG: CPlayerCoreFactory::GetPlayers: for video=1, audio=1
14:10:13 T:1956884480   DEBUG: CPlayerCoreFactory::GetPlayers: adding player: DVDPlayer (1)
14:10:13 T:1956884480   DEBUG: CPlayerCoreFactory::GetPlayers: added 1 players
14:10:13 T:1956884480  NOTICE: DVDPlayer: Opening: smb://USERNAME:PASSWORD@MEDIASERVER/x$/Kids movies/Avatar (2009)/Avatar (2009).mkv
14:10:13 T:1956884480 WARNING: CDVDMessageQueue(player)::Put MSGQ_NOT_INITIALIZED
14:10:13 T:1956884480   DEBUG: CMMALRenderer::CMMALRenderer
14:10:13 T:1956884480   DEBUG: CRenderManager::UpdateDisplayLatency - Latency set to 0 msec
14:10:13 T:1956884480   DEBUG: CMMALRenderer::UnInit
14:10:13 T:1956884480   DEBUG: CMMALRenderer::PreInit
14:10:13 T:1387258912  NOTICE: Thread CMMALRenderer start, auto delete: false
14:10:13 T:1378870304  NOTICE: Thread DVDPlayer start, auto delete: false
14:10:13 T:1378870304  NOTICE: Creating InputStream
14:10:13 T:1378870304   DEBUG: CSMBFile::Open - opened x$/Kids movies/Avatar (2009)/Avatar (2009).mkv, fd=10000
14:10:13 T:1494217760    INFO: Python script stopped
14:10:13 T:1494217760   DEBUG: Thread LanguageInvoker 1494217760 terminating
14:10:13 T:1378870304   DEBUG: ScanForExternalSubtitles: Searching for subtitles...
14:10:13 T:1956884480   DEBUG: ------ Window Init (DialogBusy.xml) ------
14:10:19 T:1595200544   DEBUG: script.module.osmcsetting.updates :  - blurp 52 - DialogBusy.xml
14:10:40 T:1523373088   DEBUG: Thread JobWorker 1523373088 terminating (autodelete)
14:10:40 T:1460663328   DEBUG: Thread JobWorker 1460663328 terminating (autodelete)
14:10:41 T:1956884480   DEBUG: SECTION:UnloadDelayed(DLL: special://xbmcbin/system/ImageLib-arm.so)
14:10:41 T:1956884480   DEBUG: Unloading: /ImageLib-arm.so
14:10:54 T:1863316512   DEBUG: PushCecKeypress - received key ea duration 0
14:10:54 T:1956884480   DEBUG: OnKey: 234 (0xea) pressed, action is PlayPause
14:10:54 T:1863316512   DEBUG: PushCecKeypress - received key ea duration 77
14:11:09 T:1595200544   DEBUG: script.module.osmcsetting.updates :  - blurp 52 - DialogBusy.xml
14:11:12 T:1378870304   DEBUG: ScanForExternalSubtitles: END (total time: 59553 ms)
14:11:12 T:1378870304  NOTICE: Creating Demuxer
14:11:12 T:1378870304   DEBUG: Open - probing detected format [matroska,webm]
14:11:12 T:1378870304   DEBUG: Open - avformat_find_stream_info starting
14:11:13 T:1378870304   DEBUG: Open - av_find_stream_info finished
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]: Input #0, matroska,webm, from 'smb://scott:password@MEDIASERVER/x$/Kids movies/Avatar (2009)/Avatar (2009).mkv':
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:   Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     encoder         : mkv2rls v1.2 (date: 2010 febr 17)
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:   Duration: 02:41:41.65, start: 0.000000, bitrate: 9674 kb/s
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.0: start 0.000000, end 377.961000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 00:00:00.000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.1: start 377.961000, end 473.598000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 00:06:17.961
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.2: start 473.598000, end 724.891000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 00:07:53.598
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.3: start 724.891000, end 840.465000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 00:12:04.891
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.4: start 840.465000, end 1200.574000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 00:14:00.465
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.5: start 1200.574000, end 1440.230000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 00:20:00.574
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.6: start 1440.230000, end 1613.278000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 00:24:00.230
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.7: start 1613.278000, end 1901.900000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 00:26:53.278
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.8: start 1901.900000, end 2013.428000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 00:31:41.900
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.9: start 2013.428000, end 2143.850000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 00:33:33.428
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.10: start 2143.850000, end 2611.859000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 00:35:43.850
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.11: start 2611.859000, end 2963.627000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 00:43:31.859
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.12: start 2963.627000, end 3269.975000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 00:49:23.627
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.13: start 3269.975000, end 3596.051000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 00:54:29.975
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.14: start 3596.051000, end 3910.198000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 00:59:56.051
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.15: start 3910.198000, end 4296.417000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 01:05:10.198
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.16: start 4296.417000, end 4511.006000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 01:11:36.417
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.17: start 4511.006000, end 4829.116000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 01:15:11.006
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.18: start 4829.116000, end 5081.910000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 01:20:29.116
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.19: start 5081.910000, end 5764.801000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 01:24:41.910
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.20: start 5764.801000, end 5875.786000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 01:36:04.801
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.21: start 5875.786000, end 6273.100000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 01:37:55.786
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.22: start 6273.100000, end 6495.489000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 01:44:33.100
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.23: start 6495.489000, end 6833.868000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 01:48:15.489
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.24: start 6833.868000, end 6932.884000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 01:53:53.868
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.25: start 6932.884000, end 7118.820000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 01:55:32.884
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.26: start 7118.820000, end 7325.568000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 01:58:38.820
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.27: start 7325.568000, end 7533.859000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 02:02:05.568
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.28: start 7533.859000, end 7801.835000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 02:05:33.859
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.29: start 7801.835000, end 8167.284000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 02:10:01.835
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.30: start 8167.284000, end 8390.841000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 02:16:07.284
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.31: start 8390.841000, end 8750.325000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 02:19:50.841
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.32: start 8750.325000, end 9074.065000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 02:25:50.325
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.33: start 9074.065000, end 9305.296000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 02:31:14.065
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Chapter #0.34: start 9305.296000, end 9701.651000
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : 02:35:05.296
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Stream #0:0(eng): Video: h264 (High), yuv420p, 1920x1080, SAR 1:1 DAR 16:9, 23.98 fps, 23.98 tbr, 1k tbn, 47.95 tbc (default)
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Stream #0:1(eng): Audio: dts (DTS), 48000 Hz, 5.1(side), fltp, 1536 kb/s (default)
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : English DTS 1509kbps
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Stream #0:2(eng): Subtitle: subrip (forced)
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : English
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Stream #0:3(eng): Subtitle: subrip
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:     Metadata:
14:11:13 T:1378870304    INFO: ffmpeg[522FE420]:       title           : English
14:11:13 T:1378870304   DEBUG: CDVDDemuxFFmpeg::AddStream(0, ...) -> 0
14:11:13 T:1378870304   DEBUG: CDVDDemuxFFmpeg::AddStream(1, ...) -> 1
14:11:13 T:1378870304   DEBUG: CDVDDemuxFFmpeg::AddStream(2, ...) -> 2
14:11:13 T:1378870304   DEBUG: CDVDDemuxFFmpeg::AddStream(3, ...) -> 3
14:11:13 T:1378870304   DEBUG: COMXCoreComponent::Initialize OMX.broadcom.clock input port 80 output port 81 m_handle 0x741dbcd0
14:11:13 T:1378870304   DEBUG: OMXClock::OMXStop
14:11:13 T:1378870304   DEBUG: OMXClock::OMXSetSpeed(0.00) pause_resume:1
14:11:13 T:1378870304  NOTICE: Opening stream: 0 source: 256
14:11:13 T:1378870304   DEBUG: DllBcm: Using omx system library
14:11:13 T:1378870304   DEBUG: COMXCoreComponent::Initialize OMX.broadcom.video_decode input port 130 output port 131 m_handle 0x741f5410
14:11:13 T:1378870304   DEBUG: COMXCoreComponent::AllocInputBuffers component(OMX.broadcom.video_decode) - port(130), nBufferCountMin(1), nBufferCountActual(120), nBufferSize(81920), nBufferAlignmen(16)
14:11:13 T:1378870304   DEBUG: COMXVideo::Open - decoder_component(0x0x741f5410), input_port(0x82), output_port(0x83) deinterlace 1 hdmiclocksync 0
14:11:13 T:1378870304    INFO: OMXPlayerVideo::OpenDecoder : Video codec omx-h264 width 1920 height 1080 profile 100 fps 23.976025
14:11:13 T:1378870304  NOTICE: Creating video thread
14:11:13 T:1378870304  NOTICE: Opening stream: 1 source: 256
14:11:13 T:1460663328  NOTICE: Thread OMXPlayerVideo start, auto delete: false
14:11:13 T:1460663328   DEBUG: COMXPlayerVideo - CDVDMsg::PLAYER_STARTED 0
14:11:13 T:1378870304  NOTICE: Creating audio thread
14:11:13 T:1460663328   DEBUG: COMXPlayerVideo - CDVDMsg::GENERAL_SYNCHRONIZE
14:11:13 T:1378870304  NOTICE: Opening stream: 2 source: 256
14:11:13 T:1523373088  NOTICE: Thread OMXPlayerAudio start, auto delete: false
14:11:13 T:1378870304   DEBUG: FactoryCodec - Overlay: Text Subtitle Decoder - Opening
14:11:13 T:1378870304   DEBUG: FactoryCodec - Overlay: Text Subtitle Decoder - Opened
14:11:13 T:1523373088   DEBUG: COMXPlayerAudio - CDVDMsg::PLAYER_STARTED 0
14:11:13 T:1523373088   DEBUG: COMXPlayerAudio - CDVDMsg::GENERAL_SYNCHRONIZE
14:11:13 T:1378870304   DEBUG: ReadEditDecisionLists - Checking for edit decision lists (EDL) on local drive or remote share for: smb://scott:password@MEDIASERVER/x$/Kids movies/Avatar (2009)/Avatar (2009).mkv
14:11:13 T:1378870304   DEBUG: OnPlayBackStarted: play state was 1, starting 1
14:11:13 T:1378870304   DEBUG: CDVDPlayer::SetCaching - caching state 3
14:11:13 T:1460663328   DEBUG: COMXPlayerVideo - CDVDMsg::PLAYER_SETSPEED 0
14:11:13 T:1460663328   DEBUG: COMXPlayerVideo - CDVDMsg::PLAYER_STARTED 0
14:11:13 T:1523373088   DEBUG: COMXPlayerAudio - CDVDMsg::PLAYER_SETSPEED 0
14:11:13 T:1523373088   DEBUG: COMXPlayerAudio - CDVDMsg::PLAYER_STARTED 0
14:11:13 T:1460663328    INFO: COMXPlayerVideo - Stillframe left, switching to normal playback
14:11:13 T:1460663328   DEBUG: OMXVideo::Decode VDec : setStartTime 0.000000
14:11:13 T:1460663328    INFO: Output - renderer not started
14:11:13 T:1378870304   DEBUG: CDVDPlayer::HandleMessages - player started 2
14:11:13 T:1378870304   DEBUG: CDVDPlayer::HandleMessages player started 2 (s:1000 a:0 v:1)
14:11:13 T:1523373088   DEBUG: COMXAudioCodecOMX::Decode(0x4fd11120,2012) format=8(8) chan=6 samples=512 size=2048 data=0x556f84b0,0x6fdd8d60,0x6fda7340,0x5a1cd750,0x6fd0f660,0x6fd20200,(nil),(nil)
14:11:13 T:1523373088   DEBUG: COMXAudioCodecOMX::GetData size=12288/12288 line=2048/2048 buf=0x55638560, desired=49152
14:11:13 T:1378870304   DEBUG: CDVDPlayer::HandleMessages - player started 1
14:11:13 T:1378870304   DEBUG: CDVDPlayer::HandleMessages player started RESET
14:11:13 T:1378870304  NOTICE: OMXClock using audio as reference
14:11:13 T:1378870304   DEBUG: OMXClock::OMXReset audio / video : 1 / 1 wait mask 0->3 state : 2->1
14:11:13 T:1378870304   DEBUG: CDVDPlayer::HandleMessages player started 1 (s:1000 a:1 v:1)
14:11:13 T:1378870304   DEBUG: CDVDPlayer::SetCaching - caching state 4
14:11:13 T:1523373088   DEBUG: COMXPlayerAudio - CDVDMsg::PLAYER_SETSPEED 1000
14:11:13 T:1460663328   DEBUG: COMXPlayerVideo - CDVDMsg::PLAYER_SETSPEED 1000
14:11:13 T:1523373088   DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_RESYNC(-4503599627370496.000000, 10000.000000, 1)
14:11:13 T:1460663328   DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_RESYNC(-4503599627370496.000000, 0)
14:11:13 T:1460663328    INFO: Output - renderer not started
14:11:13 T:1523373088    INFO: Previous line repeats 3 times.
14:11:13 T:1523373088   DEBUG: COMXAudio::SetCodingType OMX_AUDIO_CodingPCM
14:11:13 T:1523373088   DEBUG: COMXAudio:SetAudioProps hdmi_stream_channels 0 hdmi_channel_map 0b02c4c8
14:11:13 T:1523373088    INFO: COMXAudio::Initialize remap:(nil) chan:6->6 norm:0 upmix:0 60f:3f
14:11:13 T:1523373088    INFO: COMXAudio::Initialize    1.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00
14:11:13 T:1523373088    INFO: COMXAudio::Initialize    0.00   1.00   0.00   0.00   0.00   0.00   0.00   0.00
14:11:13 T:1523373088    INFO: COMXAudio::Initialize    0.00   0.00   1.00   0.00   0.00   0.00   0.00   0.00
14:11:13 T:1523373088    INFO: COMXAudio::Initialize    0.00   0.00   0.00   1.00   0.00   0.00   0.00   0.00
14:11:13 T:1523373088    INFO: COMXAudio::Initialize    0.00   0.00   0.00   0.00   1.00   0.00   0.00   0.00
14:11:13 T:1523373088    INFO: COMXAudio::Initialize    0.00   0.00   0.00   0.00   0.00   1.00   0.00   0.00
14:11:13 T:1523373088    INFO: COMXAudio::Initialize    0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00
14:11:13 T:1523373088    INFO: Previous line repeats 1 times.
14:11:13 T:1523373088   DEBUG: COMXCoreComponent::Initialize OMX.broadcom.audio_decode input port 120 output port 121 m_handle 0x5a1042f8
14:11:13 T:1460663328    INFO: Output - renderer not started
14:11:13 T:1523373088    INFO: Previous line repeats 3 times.
14:11:13 T:1523373088   DEBUG: COMXCoreComponent::AllocInputBuffers component(OMX.broadcom.audio_decode) - port(120), nBufferCountMin(4), nBufferCountActual(16), nBufferSize(49152), nBufferAlignmen(16)
14:11:13 T:1460663328    INFO: Output - renderer not started
14:11:13 T:1956884480    INFO: Previous line repeats 3 times.
14:11:13 T:1956884480   DEBUG: ------ Window Init (VideoOverlay.xml) ------
14:11:13 T:1956884480    INFO: Loading skin file: VideoOverlay.xml, load type: KEEP_IN_MEMORY
14:11:13 T:1523373088   DEBUG: COMXAudio::Initialize Input bps 32 samplerate 48000 channels 6 buffer size 2304000 bytes per second 1152000
14:11:13 T:1523373088   DEBUG: pcm->direction      : input
14:11:13 T:1523373088   DEBUG: pcm->nPortIndex     : 0
14:11:13 T:1523373088   DEBUG: pcm->eNumData       : 0
14:11:13 T:1523373088   DEBUG: pcm->eEndian        : 1
14:11:13 T:1523373088   DEBUG: pcm->bInterleaved   : 1
14:11:13 T:1523373088   DEBUG: pcm->nBitPerSample  : 32
14:11:13 T:1523373088   DEBUG: pcm->ePCMMode       : 0
14:11:13 T:1523373088   DEBUG: pcm->nChannels      : 6
14:11:13 T:1523373088   DEBUG: pcm->nSamplingRate  : 48000
14:11:13 T:1523373088   DEBUG: COMXAudio::Initialize device passthrough 0 hwdecode 0
14:11:13 T:1523373088    INFO: Audio codec  channels 6 samplerate 48000 bitspersample 16
14:11:13 T:1523373088   DEBUG: COMXAudio::Decode ADec : setStartTime 0.000000
14:11:13 T:1523373088   DEBUG: COMXCoreComponent::Initialize OMX.broadcom.audio_mixer input port 232 output port 231 m_handle 0x55f9d5b0
14:11:13 T:1523373088   DEBUG: COMXCoreComponent::Initialize OMX.broadcom.audio_render input port 100 output port 100 m_handle 0x5a132370
14:11:13 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=0.00 (* 1000.00 * 0.00)
14:11:13 T:1523373088   DEBUG: COMXAudio::PortSettingsChanged - Output bps 16 samplerate 48000 channels 8 buffer size 2304000 bytes per second 768000
14:11:13 T:1523373088   DEBUG: pcm->direction      : output
14:11:13 T:1523373088   DEBUG: pcm->nPortIndex     : 231
14:11:13 T:1523373088   DEBUG: pcm->eNumData       : 0
14:11:13 T:1523373088   DEBUG: pcm->eEndian        : 1
14:11:13 T:1523373088   DEBUG: pcm->bInterleaved   : 1
14:11:13 T:1523373088   DEBUG: pcm->nBitPerSample  : 16
14:11:13 T:1523373088   DEBUG: pcm->ePCMMode       : 0
14:11:13 T:1523373088   DEBUG: pcm->nChannels      : 8
14:11:13 T:1523373088   DEBUG: pcm->nSamplingRate  : 48000
14:11:13 T:1523373088   DEBUG: COMXAudio::PortSettingsChanged - bits:32 mode:0 channels:6 srate:48000 nopassthrough
14:11:13 T:1460663328    INFO: Output - renderer not started
14:11:13 T:1460663328    INFO: Previous line repeats 11 times.
14:11:13 T:1460663328   DEBUG: COMXVideo::PortSettingsChanged - 1920x1080@23.98 interlace:0 deinterlace:0
14:11:13 T:1460663328   DEBUG: ResolutionUpdateCallBack - change configuration. video:1920x1080. framerate: 23.98. 1920x1080 format: BYPASS
14:11:13 T:1460663328   DEBUG: CMMALRenderer::Configure - 1920x1080->1920x1080@23.98 flags:10 format:14 ext:0 orient:0
14:11:13 T:1460663328  NOTICE: Display resolution USER : 1920x1080 (1920x1080) @ 59.94 - Full Screen (23)
14:11:13 T:1460663328   DEBUG: CXBMCRenderManager::Configure - 3
14:11:13 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=0.00 (* 1000.00 * 0.00)
14:11:13 T:1956884480    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:13 T:1460663328   DEBUG: COMXCoreComponent::Initialize OMX.broadcom.video_render input port 90 output port 90 m_handle 0x5501ee98
14:11:13 T:1956884480    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:13 T:1956884480   DEBUG: Activating window ID: 12005
14:11:13 T:1460663328   DEBUG: COMXCoreComponent::Initialize OMX.broadcom.video_scheduler input port 10 output port 11 m_handle 0x54cff6b0
14:11:13 T:1956884480   DEBUG: ------ Window Deinit (MyVideoNav.xml) ------
14:11:13 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:13 T:1523373088    INFO: COMXPlayerAudio - Switching to normal playback
14:11:13 T:1378870304   DEBUG: CDVDPlayer::HandleMessages - player started 1
14:11:13 T:1378870304   DEBUG: CDVDPlayer::HandleMessages player started RESET
14:11:13 T:1378870304   DEBUG: CDVDPlayer::HandleMessages player started 1 (s:1000 a:1 v:1)
14:11:13 T:1378870304   DEBUG: CDVDPlayer::SetCaching - caching state 0
14:11:13 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:13 T:1956884480   DEBUG: ------ Window Init (VideoFullScreen.xml) ------
14:11:13 T:1956884480    INFO: Loading skin file: VideoFullScreen.xml, load type: KEEP_IN_MEMORY
14:11:13 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:13 T:1378870304   DEBUG: CDVDPlayer::OMXDoProcessing Resume 0.36,1.45 (A:01 V:01) EOF:0 FULL:0 T:0.20
14:11:13 T:1378870304   DEBUG: OMXClock::OMXSetSpeed(1.00) pause_resume:1
14:11:13 T:1956884480   DEBUG: PlayFile: OpenFile succeed, play state 2
14:11:13 T:1956884480   DEBUG: OnPlayBackStarted: play state was 2, starting 0
14:11:13 T:1956884480   DEBUG: ------ Window Deinit (VideoOverlay.xml) ------
14:11:13 T:1956884480   DEBUG: OMXPlayerVideo::SetVideoRect 0,0,1920,1080 -> 47,28,1873,1055 (0,0,0,0,mono)
14:11:13 T:1956884480   DEBUG: COMXVideo::SetVideoRect 0,0,1920,1080 -> 47,28,1826,1027 mode:1
14:11:13 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:13 T:1956884480   DEBUG: CGUIInfoManager::SetCurrentMovie(smb://USERNAME:PASSWORD@MEDIASERVER/x$/Kids movies/Avatar (2009)/Avatar (2009).mkv)
14:11:13 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:13 T:1956884480    INFO: Previous line repeats 3 times.
14:11:13 T:1956884480   DEBUG: CAnnouncementManager - Announcement: OnPlay from xbmc
14:11:13 T:1956884480   DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnPlay
14:11:13 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:13 T:1561383968  NOTICE: EMBY Player -> onPlayBackStarted: smb://scott:password@MEDIASERVER/x$/Kids movies/Avatar (2009)/Avatar (2009).mkv
14:11:13 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:13 T:1523373088    INFO: Previous line repeats 19 times.
14:11:13 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.32)
14:11:13 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.37)
14:11:13 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.41)
14:11:13 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.33)
14:11:13 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.20)
14:11:13 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.12)
14:11:13 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.06)
14:11:13 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.03)
14:11:13 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.02)
14:11:13 T:1523373088    INFO: Previous line repeats 3 times.
14:11:13 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.01)
14:11:13 T:1956884480    INFO: Previous line repeats 47 times.
14:11:13 T:1956884480   DEBUG: ------ Window Deinit (DialogBusy.xml) ------
14:11:13 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.01)
14:11:13 T:1561383968    INFO: Previous line repeats 11 times.
14:11:13 T:1561383968  NOTICE: EMBY Player -> Sending POST play started.
14:11:13 T:1362093088  NOTICE: EMBY WebSocketThread -> Message : {"MessageType":"PlaybackStart","Data":{"SupportedCommands":["MoveUp","MoveDown","MoveLeft","MoveRight","Select","Back","ToggleContextMenu","ToggleFullscreen","ToggleOsdMenu","GoHome","PageUp","NextLetter","GoToSearch","GoToSettings","PageDown","PreviousLetter","TakeScreenshot","VolumeUp","VolumeDown","ToggleMute","SendString","DisplayMessage","Mute","Unmute","SetVolume","Play","Playstate","PlayNext"],"QueueableMediaTypes":["Video"],"PlayableMediaTypes":["Audio","Video"],"Id":"167a004eb84b5ee206ddbdac4d6cbe47","UserId":"bd22e3af178580034fb62751dfc2cdbe","UserPrimaryImageTag":"efec01a4cf132f783b9958e8b11ff9bf","UserName":"scott","AdditionalUsers":[],"ApplicationVersion":"0.1.91","Client":"Kodi","LastActivityDate":"2015-05-24T14:11:11.8187422Z","DeviceName":"Kodi Lounge","NowPlayingItem":{"Name":"Avatar","Id":"dbb6d7af2127fda91ccb63a2f9e24dc8","Type":"Movie","MediaType":"Video","RunTimeTicks":97016510000,"PrimaryImageTag":"e9a1c94a41785d3b0bdf4841f7beeaed","PrimaryImageItemId":"dbb6d7af2127fda91ccb63a2f9e24dc8","LogoImageTag":"bbbfe21edd6e64d3d0c8b21257857d6c","LogoItemId":"dbb6d7af2127fda91ccb63a2f9e24dc8","BackdropImageTag":"44be64034e95ffcd7bd68e1395625282","BackdropItemId":"dbb6d7af2127fda91ccb63a2f9e24dc8","ProductionYear":2009,"Artists":[],"MediaStreams":[{"Codec":"h264","Language":"eng","IsInterlaced":false,"BitRate":9674075,"BitDepth":8,"RefFrames":4,"IsDefault":true,"IsForced":false,"Height":1080,"Width":1920,"AverageFrameRate":23.97602,"RealFrameRate":23.97602,"Profile":"High","Type":"Video","AspectRatio":"16:9","Index":0,"IsExternal":false,"IsTextSubtitleStream":false,"SupportsExternalStream":false,"PixelFormat":"yuv420p","Level":41,"IsAnamorphic":false,"IsCabac":true},{"Codec":"dca","Language":"eng","IsInterlaced":false,"ChannelLayout":"5.1","BitRate":1536000,"Channels":6,"SampleRate":48000,"IsDefault":true,"IsForced":false,"Profile":"DTS","Type":"Audio","Index":1,"IsExternal":false,"IsTextSubtitleStream":false,"SupportsExternalStream":false,"Level":0},{"Codec":"srt","Language":"eng","IsInterlaced":false,"IsDefault":false,"IsForced":true,"Type":"Subtitle","Index":2,"IsExternal":false,"IsTextSubtitleStream":true,"SupportsExternalStream":true,"Level":0},{"Codec":"srt","Language":"eng","IsInterlaced":false,"IsDefault":false,"IsForced":false,"Type":"Subtitle","Index":3,"IsExternal":false,"IsTextSubtitleStream":true,"SupportsExternalStream":true,"Level":0}],"ChapterImagesItemId":"dbb6d7af2127fda91ccb63a2f9e24dc8","Chapters":[{"StartPositionTicks":0,"Name":"Chapter 1","ImageTag":"b0940280f2a86edd640355eb5c1f863e"},{"StartPositionTicks":3779610000,"Name":"Chapter 2","ImageTag":"9c86891e6cb1da57aad1dfce0338e809"},{"StartPositionTicks":4735980000,"Name":"Chapter 3","ImageTag":"ecf834d3945aafedd6c3addeff57b5c5"},{"StartPositionTicks":7248910000,"Name":"Chapter 4","ImageTag":"ecf0b56ff8b61af85e1d1330adaec0d1"},{"StartPositionTicks":8404650000,"Name":"Chapter 5","ImageTag":"ca43a710687472e45ec3b66bdc23ee32"},{"StartPositionTicks":12005740000,"Name":"Chapter 6","ImageTag":"6e46c02d43a2c6b140ee499573c07664"},{"StartPositionTicks":14402300000,"Name":"Chapter 7","ImageTag":"c5f564cd47e02022794526adb6bf0192"},{"StartPositionTicks":16132780000,"Name":"Chapter 8","ImageTag":"ea02be48dcaffde068297eae7ae15ef7"},{"StartPositionTicks":19019000000,"Name":"Chapter 9","ImageTag":"26fe86effb82f6c901adc1ae081ea0fd"},{"StartPositionTicks":20134280000,"Name":"Chapter 10","ImageTag":"98d04fa4eede535f0343ca245128c357"},{"StartPositionTicks":21438500000,"Name":"Chapter 11","ImageTag":"313a2ff1ca11aa6f00ef9ecb4048d529"},{"StartPositionTicks":26118590000,"Name":"Chapter 12","ImageTag":"6f971c3e0fb49d330e83e02f648c0aac"},{"StartPositionTicks":29636270000,"Name":"Chapter 13","ImageTag":"1ccd84b49f7899c56333398313f01c2c"},{"StartPositionTicks":32699750000,"Name":"Chapter 14","ImageTag":"7ae2e1b1d77a92d2b16d2c99e63ca4b4"},{"StartPositionTicks":35960510000,"Name":"Chapter 15","ImageTag":"4358bdc63ae6a1ad8763be18fdfaf550"},{"StartPositionTicks":39101980000,"Name":"Chapter 16","ImageTag":"a9b8694407d6439e28e65df987c01c8d"},{"StartPositionTicks":42964170000,"Name":"Chapter 17","ImageTag":"323dc61ab6029165c81eefa79bae5ca3"},{"StartPositionTicks":45110060000,"Name":"Chapter 18","ImageTag":"cc73eb2c6dc1a52fdeb0585c75eba4ff"},{"StartPositionTicks":48291160000,"Name":"Chapter 19","ImageTag":"76571aed6acfa9824c6dab6f7e48a922"},{"StartPositionTicks":50819100000,"Name":"Chapter 20","ImageTag":"fb43afcd176ba24e11434513bbe4da61"},{"StartPositionTicks":57648010000,"Name":"Chapter 21","ImageTag":"ac25ff1aeedf1bc8fcff4a9135aec07b"},{"StartPositionTicks":58757860000,"Name":"Chapter 22","ImageTag":"0aaee5e40883aa4b1947ac6f30eab984"},{"StartPositionTicks":62731000000,"Name":"Chapter 23","ImageTag":"91d87234335588e6529340e9fe73c16e"},{"StartPositionTicks":64954890000,"Name":"Chapter 24","ImageTag":"4c64beb7af92e6d788fcf46e449a57c7"},{"StartPositionTicks":68338680000,"Name":"Chapter 25","ImageTag":"0fafd14135489897e06fc579d64890e6"},{"StartPositionTicks":69328840000,"Name":"Chapter 26","ImageTag":"b1fe430cabfee1a88cc29c286ed08d7e"},{"StartPositionTicks":71188200000,"Name":"Chapter 27","ImageTag":"d0de176a5fa6305a79081d5ee035ac4c"},{"StartPositionTicks":73255680000,"Name":"Chapter 28","ImageTag":"76358bf332e82cf11e10dcb55a7479e2"},{"StartPositionTicks":75338590000,"Name":"Chapter 29","ImageTag":"4ed92a908124900749691b461bf0889d"},{"StartPositionTicks":78018350000,"Name":"Chapter 30","ImageTag":"ebbdec58917a0ec33522aa31a502fd72"},{"StartPositionTicks":81672840000,"Name":"Chapter 31","ImageTag":"a9d479939301baf5fed151902aa054ed"},{"StartPositionTicks":83908410000,"Name":"Chapter 32","ImageTag":"37688fcb28300ae6169910c2b131b55d"},{"StartPositionTicks":87503250000,"Name":"Chapter 33","ImageTag":"a94f045e79c767d02caf3dbc9ff767c1"},{"StartPositionTicks":90740650000,"Name":"Chapter 34","ImageTag":"7370aca979e8a0dcffb31b91d5df974c"},{"StartPositionTicks":93052960000,"Name":"Chapter 35","ImageTag":"3d3bde3cf780fbc9ed34ec9bc868d03c"}]},"DeviceId":"E4F75B40B26E47498C620071CB917F6E","SupportsRemoteControl":true,"PlayState":{"PositionTicks":0,"CanSeek":true,"IsPaused":false,"IsMuted":false,"AudioStreamIndex":1,"SubtitleStreamIndex":2,"MediaSourceId":"dbb6d7af2127fda91ccb63a2f9e24dc8","PlayMethod":"DirectPlay"}}}
14:11:13 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.01)
14:11:13 T:1561383968    INFO: Previous line repeats 2 times.
14:11:13 T:1561383968  NOTICE: EMBY Player -> ADDING_FILE: {'smb://scott:password@MEDIASERVER/x$/Kids movies/Avatar (2009)/Avatar (2009).mkv': {'refresh_id': 'dbb6d7af2127fda91ccb63a2f9e24dc8', 'AudioStreamIndex': '1', 'SubtitleStreamIndex': '2', 'currentPosition': 0, 'item_id': 'dbb6d7af2127fda91ccb63a2f9e24dc8', 'currentfile': 'smb://scott:password@MEDIASERVER/x$/Kids movies/Avatar (2009)/Avatar (2009).mkv', 'runtime': '97016510000', 'Type': 'Movie', 'playmethod': 'DirectPlay'}}
14:11:13 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.01)
14:11:14 T:1362093088    INFO: Previous line repeats 9 times.
14:11:14 T:1362093088  NOTICE: EMBY WebSocketThread -> Message : {"MessageType":"UserDataChanged","Data":{"UserId":"bd22e3af178580034fb62751dfc2cdbe","UserDataList":[{"PlaybackPositionTicks":0,"PlayCount":1,"IsFavorite":false,"LastPlayedDate":"2015-05-24T14:11:11.8187422Z","Played":false,"Key":"19995","ItemId":"dbb6d7af2127fda91ccb63a2f9e24dc8"},{"PlayedPercentage":1.77514792899408,"UnplayedItemCount":166,"PlaybackPositionTicks":0,"PlayCount":0,"IsFavorite":false,"Played":false,"Key":"1756a1b1-9c82-088a-a8d2-fd407f0bc90d","ItemId":"1756a1b19c82088aa8d2fd407f0bc90d"}]}}
14:11:14 T:1362093088  NOTICE: EMBY WebSocketThread -> Message : Doing UserDataChanged
14:11:14 T:1362093088  NOTICE: EMBY WebSocketThread -> Message : Doing UserDataChanged : UserDataList : [{u'ItemId': u'dbb6d7af2127fda91ccb63a2f9e24dc8', u'IsFavorite': False, u'Played': False, u'LastPlayedDate': u'2015-05-24T14:11:11.8187422Z', u'PlaybackPositionTicks': 0, u'Key': u'19995', u'PlayCount': 1}, {u'ItemId': u'1756a1b19c82088aa8d2fd407f0bc90d', u'IsFavorite': False, u'Played': False, u'PlayedPercentage': 1.77514792899408, u'UnplayedItemCount': 166, u'PlaybackPositionTicks': 0, u'Key': u'1756a1b1-9c82-088a-a8d2-fd407f0bc90d', u'PlayCount': 0}]
14:11:14 T:1362093088  NOTICE: EMBY WebSocketThread -> Message : Doing UserDataChanged : Processing Updated : [u'dbb6d7af2127fda91ccb63a2f9e24dc8', u'1756a1b19c82088aa8d2fd407f0bc90d']
14:11:14 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.01)
14:11:14 T:1956884480    INFO: Previous line repeats 1 times.
14:11:14 T:1956884480   DEBUG: ------ Window Init (DialogKaiToast.xml) ------
14:11:14 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.01)
14:11:14 T:1561383968    INFO: Previous line repeats 11 times.
14:11:14 T:1561383968  NOTICE: EMBY WebSocketThread -> sendProgressUpdate
14:11:14 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.01)
14:11:15 T:1362093088    INFO: Previous line repeats 11 times.
14:11:15 T:1362093088  NOTICE: UPDATE movie to Kodi library -> Id: dbb6d7af2127fda91ccb63a2f9e24dc8 - Title: Avatar
14:11:15 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.01)
14:11:19 T:1561383968    INFO: Previous line repeats 84 times.
14:11:19 T:1561383968  NOTICE: EMBY WebSocketThread -> sendProgressUpdate
14:11:19 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.01)
14:11:20 T:1494217760    INFO: Previous line repeats 25 times.
14:11:20 T:1494217760  NOTICE: Thread VideoInfoScanner start, auto delete: false
14:11:20 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.01)
14:11:20 T:1956884480    INFO: Previous line repeats 3 times.
14:11:20 T:1956884480   DEBUG: ------ Window Init (DialogExtendedProgressBar.xml) ------
14:11:20 T:1494217760  NOTICE: VideoInfoScanner: Starting scan ..
14:11:20 T:1494217760   DEBUG: CAnnouncementManager - Announcement: OnScanStarted from xbmc
14:11:20 T:1494217760   DEBUG: GOT ANNOUNCEMENT, type: 16, from xbmc, message OnScanStarted
14:11:20 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.01)
14:11:20 T:1956884480    INFO: Previous line repeats 6 times.
14:11:20 T:1956884480   DEBUG: ------ Window Deinit (DialogKaiToast.xml) ------
14:11:20 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.01)
14:11:20 T:1494217760    INFO: Previous line repeats 1 times.
14:11:20 T:1494217760  NOTICE: VideoInfoScanner: Finished scan. Scanning for video info took 00:00
14:11:20 T:1494217760   DEBUG: CAnnouncementManager - Announcement: OnScanFinished from xbmc
14:11:20 T:1494217760   DEBUG: GOT ANNOUNCEMENT, type: 16, from xbmc, message OnScanFinished
14:11:20 T:1494217760   DEBUG: Thread VideoInfoScanner 1494217760 terminating
14:11:20 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.01)
14:11:20 T:1956884480    INFO: Previous line repeats 2 times.
14:11:20 T:1956884480   DEBUG: ------ Window Deinit (DialogExtendedProgressBar.xml) ------
14:11:20 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.01)
14:11:21 T:1569772576    INFO: Previous line repeats 22 times.
14:11:21 T:1569772576   DEBUG: RunQuery took 5 ms for 0 items query: select * from movieview  WHERE (movieview.idFile  IN (SELECT DISTINCT idFile FROM bookmark WHERE type = 1))
14:11:21 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.01)
14:11:21 T:1586811936   DEBUG: RunQuery took 12 ms for 0 items query: select * from movieview  WHERE (movieview.idFile  IN (SELECT DISTINCT idFile FROM bookmark WHERE type = 1))
14:11:21 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.01)
14:11:22 T:1523373088    INFO: Previous line repeats 2 times.
14:11:22 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:22 T:1569772576   DEBUG: RunQuery took 177 ms for 24 items query: SELECT * FROM tvshowview  WHERE ( ((tvshowview.watchedcount > 0 AND tvshowview.watchedcount < tvshowview.totalCount) OR (tvshowview.watchedcount = 0 AND EXISTS (SELECT 1 FROM episodeview WHERE episodeview.idShow = tvshowview.idShow AND episodeview.resumeTimeInSeconds > 0))))
14:11:22 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:22 T:1586811936   DEBUG: RunQuery took 192 ms for 24 items query: SELECT * FROM tvshowview  WHERE ( ((tvshowview.watchedcount > 0 AND tvshowview.watchedcount < tvshowview.totalCount) OR (tvshowview.watchedcount = 0 AND EXISTS (SELECT 1 FROM episodeview WHERE episodeview.idShow = tvshowview.idShow AND episodeview.resumeTimeInSeconds > 0))))
14:11:22 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:22 T:1569772576    INFO: Previous line repeats 1 times.
14:11:22 T:1569772576   DEBUG: RunQuery took 11 ms for 49 items query: select * from episodeview  WHERE (episodeview.idShow = 107) AND (((episodeview.playCount IS NULL OR episodeview.playCount < 1)))
14:11:22 T:1569772576   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:22 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:22 T:1586811936    INFO: Previous line repeats 1 times.
14:11:22 T:1586811936   DEBUG: RunQuery took 15 ms for 49 items query: select * from episodeview  WHERE (episodeview.idShow = 107) AND (((episodeview.playCount IS NULL OR episodeview.playCount = 0)))
14:11:22 T:1586811936   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:22 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:22 T:1569772576   DEBUG: RunQuery took 14 ms for 85 items query: select * from episodeview  WHERE (episodeview.idShow = 16) AND (((episodeview.playCount IS NULL OR episodeview.playCount < 1)))
14:11:22 T:1569772576   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:22 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:22 T:1586811936    INFO: Previous line repeats 1 times.
14:11:22 T:1586811936   DEBUG: RunQuery took 19 ms for 85 items query: select * from episodeview  WHERE (episodeview.idShow = 16) AND (((episodeview.playCount IS NULL OR episodeview.playCount = 0)))
14:11:22 T:1586811936   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:22 T:1569772576   DEBUG: RunQuery took 5 ms for 4 items query: select * from episodeview  WHERE (episodeview.idShow = 94) AND (((episodeview.playCount IS NULL OR episodeview.playCount < 1)))
14:11:22 T:1569772576   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:22 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:22 T:1569772576    INFO: Previous line repeats 2 times.
14:11:22 T:1569772576   DEBUG: RunQuery took 11 ms for 2 items query: select * from episodeview  WHERE (episodeview.idShow = 40) AND (((episodeview.playCount IS NULL OR episodeview.playCount < 1)))
14:11:22 T:1569772576   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:22 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:22 T:1586811936   DEBUG: RunQuery took 15 ms for 4 items query: select * from episodeview  WHERE (episodeview.idShow = 94) AND (((episodeview.playCount IS NULL OR episodeview.playCount = 0)))
14:11:22 T:1586811936   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:22 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:22 T:1569772576    INFO: Previous line repeats 1 times.
14:11:22 T:1569772576   DEBUG: RunQuery took 37 ms for 286 items query: select * from episodeview  WHERE (episodeview.idShow = 97) AND (((episodeview.playCount IS NULL OR episodeview.playCount < 1)))
14:11:22 T:1569772576   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:22 T:1586811936   DEBUG: RunQuery took 5 ms for 2 items query: select * from episodeview  WHERE (episodeview.idShow = 40) AND (((episodeview.playCount IS NULL OR episodeview.playCount = 0)))
14:11:22 T:1586811936   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:22 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:22 T:1586811936    INFO: Previous line repeats 1 times.
14:11:22 T:1586811936   DEBUG: RunQuery took 41 ms for 286 items query: select * from episodeview  WHERE (episodeview.idShow = 97) AND (((episodeview.playCount IS NULL OR episodeview.playCount = 0)))
14:11:22 T:1586811936   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:22 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:22 T:1569772576    INFO: Previous line repeats 1 times.
14:11:22 T:1569772576   DEBUG: RunQuery took 5 ms for 4 items query: select * from episodeview  WHERE (episodeview.idShow = 47) AND (((episodeview.playCount IS NULL OR episodeview.playCount < 1)))
14:11:22 T:1569772576   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:22 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:22 T:1569772576    INFO: Previous line repeats 1 times.
14:11:22 T:1569772576   DEBUG: RunQuery took 7 ms for 1 items query: select * from episodeview  WHERE (episodeview.idShow = 3) AND (((episodeview.playCount IS NULL OR episodeview.playCount < 1)))
14:11:22 T:1569772576   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:22 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:22 T:1586811936   DEBUG: RunQuery took 8 ms for 4 items query: select * from episodeview  WHERE (episodeview.idShow = 47) AND (((episodeview.playCount IS NULL OR episodeview.playCount = 0)))
14:11:22 T:1586811936   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:22 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:23 T:1569772576    INFO: Previous line repeats 1 times.
14:11:23 T:1569772576   DEBUG: RunQuery took 11 ms for 19 items query: select * from episodeview  WHERE (episodeview.idShow = 62) AND (((episodeview.playCount IS NULL OR episodeview.playCount < 1)))
14:11:23 T:1569772576   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:23 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:23 T:1586811936   DEBUG: RunQuery took 11 ms for 1 items query: select * from episodeview  WHERE (episodeview.idShow = 3) AND (((episodeview.playCount IS NULL OR episodeview.playCount = 0)))
14:11:23 T:1586811936   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:23 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:23 T:1561383968  NOTICE: EMBY WebSocketThread -> sendProgressUpdate
14:11:23 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:23 T:1569772576   DEBUG: RunQuery took 18 ms for 102 items query: select * from episodeview  WHERE (episodeview.idShow = 30) AND (((episodeview.playCount IS NULL OR episodeview.playCount < 1)))
14:11:23 T:1569772576   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:23 T:1586811936   DEBUG: RunQuery took 6 ms for 19 items query: select * from episodeview  WHERE (episodeview.idShow = 62) AND (((episodeview.playCount IS NULL OR episodeview.playCount = 0)))
14:11:23 T:1586811936   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:23 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:23 T:1569772576    INFO: Previous line repeats 2 times.
14:11:23 T:1569772576   DEBUG: RunQuery took 5 ms for 1 items query: select * from episodeview  WHERE (episodeview.idShow = 33) AND (((episodeview.playCount IS NULL OR episodeview.playCount < 1)))
14:11:23 T:1569772576   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:23 T:1586811936   DEBUG: RunQuery took 17 ms for 102 items query: select * from episodeview  WHERE (episodeview.idShow = 30) AND (((episodeview.playCount IS NULL OR episodeview.playCount = 0)))
14:11:23 T:1586811936   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:23 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:23 T:1569772576    INFO: Previous line repeats 1 times.
14:11:23 T:1569772576   DEBUG: RunQuery took 13 ms for 19 items query: select * from episodeview  WHERE (episodeview.idShow = 53) AND (((episodeview.playCount IS NULL OR episodeview.playCount < 1)))
14:11:23 T:1569772576   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:23 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:23 T:1586811936   DEBUG: RunQuery took 11 ms for 1 items query: select * from episodeview  WHERE (episodeview.idShow = 33) AND (((episodeview.playCount IS NULL OR episodeview.playCount = 0)))
14:11:23 T:1586811936   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:23 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:23 T:1569772576    INFO: Previous line repeats 1 times.
14:11:23 T:1569772576   DEBUG: RunQuery took 6 ms for 6 items query: select * from episodeview  WHERE (episodeview.idShow = 72) AND (((episodeview.playCount IS NULL OR episodeview.playCount < 1)))
14:11:23 T:1569772576   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:23 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:23 T:1586811936   DEBUG: RunQuery took 15 ms for 19 items query: select * from episodeview  WHERE (episodeview.idShow = 53) AND (((episodeview.playCount IS NULL OR episodeview.playCount = 0)))
14:11:23 T:1586811936   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:23 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:23 T:1569772576    INFO: Previous line repeats 1 times.
14:11:23 T:1569772576   DEBUG: RunQuery took 12 ms for 10 items query: select * from episodeview  WHERE (episodeview.idShow = 76) AND (((episodeview.playCount IS NULL OR episodeview.playCount < 1)))
14:11:23 T:1569772576   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:23 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:23 T:1586811936   DEBUG: RunQuery took 10 ms for 6 items query: select * from episodeview  WHERE (episodeview.idShow = 72) AND (((episodeview.playCount IS NULL OR episodeview.playCount = 0)))
14:11:23 T:1586811936   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:23 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:23 T:1569772576   DEBUG: RunQuery took 7 ms for 21 items query: select * from episodeview  WHERE (episodeview.idShow = 28) AND (((episodeview.playCount IS NULL OR episodeview.playCount < 1)))
14:11:23 T:1569772576   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:23 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:23 T:1586811936   DEBUG: RunQuery took 11 ms for 10 items query: select * from episodeview  WHERE (episodeview.idShow = 76) AND (((episodeview.playCount IS NULL OR episodeview.playCount = 0)))
14:11:23 T:1586811936   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:23 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:23 T:1569772576    INFO: Previous line repeats 1 times.
14:11:23 T:1569772576   DEBUG: RunQuery took 11 ms for 13 items query: select * from episodeview  WHERE (episodeview.idShow = 78) AND (((episodeview.playCount IS NULL OR episodeview.playCount < 1)))
14:11:23 T:1569772576   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:23 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:23 T:1586811936   DEBUG: RunQuery took 12 ms for 21 items query: select * from episodeview  WHERE (episodeview.idShow = 28) AND (((episodeview.playCount IS NULL OR episodeview.playCount = 0)))
14:11:23 T:1586811936   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:23 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:23 T:1569772576    INFO: Previous line repeats 1 times.
14:11:23 T:1569772576   DEBUG: RunQuery took 16 ms for 40 items query: select * from episodeview  WHERE (episodeview.idShow = 37) AND (((episodeview.playCount IS NULL OR episodeview.playCount < 1)))
14:11:23 T:1569772576   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:23 T:1586811936   DEBUG: RunQuery took 6 ms for 13 items query: select * from episodeview  WHERE (episodeview.idShow = 78) AND (((episodeview.playCount IS NULL OR episodeview.playCount = 0)))
14:11:23 T:1586811936   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:23 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:24 T:1569772576    INFO: Previous line repeats 2 times.
14:11:24 T:1569772576   DEBUG: RunQuery took 12 ms for 19 items query: select * from episodeview  WHERE (episodeview.idShow = 60) AND (((episodeview.playCount IS NULL OR episodeview.playCount < 1)))
14:11:24 T:1569772576   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:24 T:1586811936   DEBUG: RunQuery took 14 ms for 40 items query: select * from episodeview  WHERE (episodeview.idShow = 37) AND (((episodeview.playCount IS NULL OR episodeview.playCount = 0)))
14:11:24 T:1586811936   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:24 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:24 T:1569772576    INFO: Previous line repeats 1 times.
14:11:24 T:1569772576   DEBUG: RunQuery took 8 ms for 24 items query: select * from episodeview  WHERE (episodeview.idShow = 79) AND (((episodeview.playCount IS NULL OR episodeview.playCount < 1)))
14:11:24 T:1569772576   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:24 T:1586811936   DEBUG: RunQuery took 7 ms for 19 items query: select * from episodeview  WHERE (episodeview.idShow = 60) AND (((episodeview.playCount IS NULL OR episodeview.playCount = 0)))
14:11:24 T:1586811936   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:24 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:24 T:1569772576    INFO: Previous line repeats 2 times.
14:11:24 T:1569772576   DEBUG: RunQuery took 10 ms for 1 items query: select * from episodeview  WHERE (episodeview.idShow = 82) AND (((episodeview.playCount IS NULL OR episodeview.playCount < 1)))
14:11:24 T:1569772576   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:24 T:1586811936   DEBUG: RunQuery took 12 ms for 24 items query: select * from episodeview  WHERE (episodeview.idShow = 79) AND (((episodeview.playCount IS NULL OR episodeview.playCount = 0)))
14:11:24 T:1586811936   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:24 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:24 T:1586811936    INFO: Previous line repeats 2 times.
14:11:24 T:1586811936   DEBUG: RunQuery took 6 ms for 1 items query: select * from episodeview  WHERE (episodeview.idShow = 82) AND (((episodeview.playCount IS NULL OR episodeview.playCount = 0)))
14:11:24 T:1586811936   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:24 T:1569772576   DEBUG: RunQuery took 12 ms for 20 items query: select * from episodeview  WHERE (episodeview.idShow = 19) AND (((episodeview.playCount IS NULL OR episodeview.playCount < 1)))
14:11:24 T:1569772576   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:24 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:24 T:1586811936    INFO: Previous line repeats 1 times.
14:11:24 T:1586811936   DEBUG: RunQuery took 13 ms for 20 items query: select * from episodeview  WHERE (episodeview.idShow = 19) AND (((episodeview.playCount IS NULL OR episodeview.playCount = 0)))
14:11:24 T:1586811936   DEBUG: DatabaseUtils::GetSortFieldList: unknown field 25
14:11:24 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:24 T:1569772576    INFO: Previous line repeats 1 times.
14:11:24 T:1569772576   DEBUG: RunQuery took 53 ms for 386 items query: select * from movieview  WHERE ((movieview.playCount IS NULL OR movieview.playCount < 1))
14:11:24 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:24 T:1586811936   DEBUG: RunQuery took 47 ms for 386 items query: select * from movieview  WHERE ((movieview.playCount IS NULL OR movieview.playCount = 0))
14:11:24 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:25 T:1569772576    INFO: Previous line repeats 25 times.
14:11:25 T:1569772576   DEBUG: RunQuery took 430 ms for 3951 items query: select * from episodeview  WHERE ((episodeview.playCount IS NULL OR episodeview.playCount < 1))
14:11:25 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:25 T:1586811936   DEBUG: RunQuery took 435 ms for 3951 items query: select * from episodeview  WHERE ((episodeview.playCount IS NULL OR episodeview.playCount < 1))
14:11:25 T:1523373088    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1000.00 * 0.00)
14:11:27 T:1561383968    INFO: Previous line repeats 30 times.
14:11:27 T:1561383968  NOTICE: EMBY WebSocketThread -> sendProgressUpdate

also once it started playing kodi did a increment database update please see attached photo of the of the change in the database that you have stated it doensn't do yet there it is in the photo after the play of the file so from this it is doing excactly what i have been saying

Capture21.JPG

 

this shows that what i have been saying along is happening, and shows that you guys have been contradicting everything you have been saying regarding this matter

  • Like 1
Link to comment
Share on other sites

Hopefully this will get sorted soon.

 

There's not a lot more you can do other than wait for the devs to work out a solution.

Link to comment
Share on other sites

That is interesting.  You definitely do NOT have the path to your TV shows added as source right?  Can you check that sources.xml is blank?

 

You seem to be getting very frustrated by this - we are trying to help but don't understand what is going wrong - but we will get it resolved.  We are all using this ourselves and are not seeing this - I just checked my own db.

 

xnappo

 

5561f13448f14_mydb.jpg

Edited by xnappo
Link to comment
Share on other sites

That is interesting. You definitely do NOT have the path to your TV shows added as source right? Can you check that sources.xml is blank?

 

You seem to be getting very frustrated by this - we are trying to help but don't understand what is going wrong - but we will get it resolved. We are all using this ourselves and are not seeing this - I just checked my own db.

 

xnappo

 

No there are no sources added to kodi at all. All information comes from the emby server via your add on.

 

The thing is once the path is changed to the smb path in the database the file plays Instantly

Edited by scalda
Link to comment
Share on other sites

No there are no sources added to kodi at all. All information comes from the emby server via your add on.

 

The thing is once the path is changed to the smb path in the database the file plays Instantly

Oh - so you edited the DB manually, and now it is fast.  Yes that makes sense - we need to figure out why going through the Python script is slow.  Again, we had to change it to do that to fix a bunch of other problems!

 

Thanks,

xnappo

  • Like 1
Link to comment
Share on other sites

Oh - so you edited the DB manually, and now it is fast. Yes that makes sense - we need to figure out why going through the Python script is slow. Again, we had to change it to do that to fix a bunch of other problems!

 

Thanks,

xnappo

I never edited the database manually your emby addon does itself when a file is first played. Even angleblue stated in one of the previous post that when a file is first played the database gets changed to the direct smb path and then you guys decided that's not what its doing even thou I quoted it a few times, and what I was saying is wrong according to you all

Link to comment
Share on other sites

That is interesting.  You definitely do NOT have the path to your TV shows added as source right?  Can you check that sources.xml is blank?

 

You seem to be getting very frustrated by this - we are trying to help but don't understand what is going wrong - but we will get it resolved.  We are all using this ourselves and are not seeing this - I just checked my own db.

 

xnappo

 

5561f13448f14_mydb.jpg

@@xnappo if this is a view of your database, do you have folders in your plugin folder for all the movies and tv shows? with the id as i don't have folders in mine?

Link to comment
Share on other sites

No - the ids are now stored in another table in the database instead of the .strm files.  Look in the DB viewer at the 'emby' table.

 

I fired up my Pi (which I only use for debugging Pi issues) and I definitely see that it is slow to start playing.  I stripped the code down to just the bare minimum needed to start playback, and it gets close to the speed of just having the path.  But then.. A bunch of stuff won't work right (resume, artwork during playback, server reporting and control..).

 

So I am not sure what the fix is here - having the direct path causes all sorts of havok because the Kodi DB code tries to take over.  

 

xnappo

Link to comment
Share on other sites

Can a moderator change the title of this thread to: plugin path play slow vs direct smb path play instant

Link to comment
Share on other sites

Can a moderator change the title of this thread to: plugin path play slow vs direct smb path play instant

Done.

Link to comment
Share on other sites

No - the ids are now stored in another table in the database instead of the .strm files. Look in the DB viewer at the 'emby' table.

 

I fired up my Pi (which I only use for debugging Pi issues) and I definitely see that it is slow to start playing. I stripped the code down to just the bare minimum needed to start playback, and it gets close to the speed of just having the path. But then.. A bunch of stuff won't work right (resume, artwork during playback, server reporting and control..).

 

So I am not sure what the fix is here - having the direct path causes all sorts of havok because the Kodi DB code tries to take over.

 

xnappo

Then why doesn't it cause havoc once you add on changes the file path in the database? And what pi are you using? As this is my pi2 model b, but I do have the same thing on the pi1 model be 2. Also what os are you using? And version of kodi on that os? Edited by scalda
Link to comment
Share on other sites

Then why doesn't it cause havoc once you add on changes the file path in the database? And what pi are you using? As this is my pi2 model b, but I do have the same thing on the pi1 model be 2. Also what os are you using? And version of kodi on that os?

 

Yeah, I know - it does seem to work.  We made this change a long time ago (to me anyway) and I am trying to dig up the bugs we had that led us to give up this line of operation.

 

Certainly off-network playback and transcoding will not work - but if it were just that it could be made an option to use real paths.  

 

xnappo

Link to comment
Share on other sites

@@xnappo

 

Would you like me to record a video of me playing a new file and showing what it does and then post a screenshot of the database?

Link to comment
Share on other sites

Yeah, I know - it does seem to work. We made this change a long time ago (to me anyway) and I am trying to dig up the bugs we had that led us to give up this line of operation.

 

Certainly off-network playback and transcoding will not work - but if it were just that it could be made an option to use real paths.

 

xnappo

Also I said a couple of posts back that it would be great for remote access but for local network play it's pointless. So why can't it be enabled when http is used instead of smb is enabled?

Link to comment
Share on other sites

I am still confused - are you saying when you play a file back, the SMB path is being ADDED to the database automatically?

 

So yes - since I am still confused, please post a video.

Link to comment
Share on other sites

I am still confused - are you saying when you play a file back, the SMB path is being ADDED to the database automatically?

 

So yes - since I am still confused, please post a video.

@@xnappo

 

yes it is doing it's self i am not manually editing the database like you think i am i have no need to do it that would mess up what i'm trying to get across 

 

i have just played 5 videos and they took quicker then what avatar did earlier i wish i caught that one really, but as you can see i played videos and then in the corner you can see it running the increment database update, then the image is of the database changes it made

 

 

video: 

 

https://www.youtube.com/watch?v=W8k_JYlBEtk

 

Log file: https://dl.dropboxusercontent.com/u/8871364/Captures/kodi%20log%202%20with%205%20movies%2024-05-2015.log

 

 

DB image 

 

Capture22.JPG

Edited by scalda
Link to comment
Share on other sites

Thanks - that helps a lot.

 

The time from when you click a movie to playback starting doesn't look all that bad - but this weird database issue is definitely a problem.

 

@@marcelveldt - any ideas here?  I can't seem to recreate this problem...

Link to comment
Share on other sites

Thanks - that helps a lot.

 

The time from when you click a movie to playback starting doesn't look all that bad - but this weird database issue is definitely a problem.

 

@@marcelveldt - any ideas here?  I can't seem to recreate this problem...

 

yes the play isn't bad but once that smb path is in its even faster and instant

 

this is a screenshot of my daughters database using the same version as my main pi and it shows the same smb path updates

 

Capture23.JPG

 

I have just installed a new pi in my bedroom so i will be checking that one as well once i go and reboot for it to do the initial sync,. once that is done i will be doing the same thing again, to check it

Edited by scalda
Link to comment
Share on other sites

@@scalda - one thing I see if your logs that is not in mine is even where there is not .srt file you get:

ScanForExternalSubtitles: Searching for subtitles...

I am wondering if when it searches the path for subtitles it ends up scraping the path into the db.

 

I tried playing around with the subtitles settings, but could not reproduce this log message.  Do you know how to turn it on/off?

Link to comment
Share on other sites

Guest
This topic is now closed to further replies.
 Share

×
×
  • Create New...