xnappo 1592 Posted June 11, 2015 Share Posted June 11, 2015 (edited) What kind of lag? It may take up to 30 seconds. Sometimes if you delete something, it is true it may not disappear until you go out and back in. There hasn't been any change in the delete code itself - and I really can't think of anything else changed recently that could affect this (but I will look through the changes). The amount of time it takes the server to do this is unpredictable. In the old addon - I actually locked the user out from doing anything with a progress bar that waited the max amount of time I had seen it take, but that seems silly. xnappo Edited June 11, 2015 by xnappo Link to comment Share on other sites More sharing options...
mobamoba 12 Posted June 11, 2015 Author Share Posted June 11, 2015 The lag is nothing drastic certainly, but there's no indicator that the process is working - it feels like you clicked delete and it just stays there. I wonder if you were onto something with indicating that the process was working. Instead of a progress indicator, would deleting from the Kodi library first and the Emby server second in the background make the show disappear instantly? Or even, on the dialogue box confirming that you want Emby to delete the file, an indicator a la, "Note: It may take a few minutes for Emby to remove the file from Kodi" or something? Even as someone who understood what was going on due to this thread, I still couldn't totally tell if anything was happening or if the process was glitching. Link to comment Share on other sites More sharing options...
xnappo 1592 Posted June 11, 2015 Share Posted June 11, 2015 (edited) Yeah, I will try to come up with something. As I said in the old addon we had a progress indicator, and people didn't like it (it blocked moving on to doing anything else until complete). Probably just an auto-timed message saying 'file deleted on server, update in progress' or something. Edited June 11, 2015 by xnappo Link to comment Share on other sites More sharing options...
mobamoba 12 Posted June 12, 2015 Author Share Posted June 12, 2015 There's still something glitching with Emby delete. Just now, I hit stop at the end of a video I was watching and Emby delete never appeared. Instead the video immediately vanished from the list as something (Emby? Kodi?) had marked it watched and swept it out of view. I then had to get rid of it manually (show watched videos, context menu to manage library, etc.). Below is the relevant portion of the log as maybe it will help debug why Emby delete never appeared at all: 20:57:57 T:7428 NOTICE: CDVDPlayer::CloseFile() 20:57:57 T:7428 NOTICE: DVDPlayer: waiting for threads to exit 20:57:57 T:8036 NOTICE: CDVDPlayer::OnExit() 20:57:57 T:8036 NOTICE: Closing stream player 1 20:57:57 T:8036 NOTICE: Waiting for audio thread to exit 20:57:57 T:2336 NOTICE: thread end: CDVDPlayerAudio::OnExit() 20:57:57 T:8036 NOTICE: Closing audio device 20:57:57 T:8036 NOTICE: Deleting audio codec 20:57:57 T:8036 NOTICE: Closing stream player 2 20:57:57 T:8036 NOTICE: waiting for video thread to exit 20:57:57 T:7008 NOTICE: thread end: video_thread 20:57:57 T:8036 NOTICE: deleting video codec 20:57:57 T:8036 NOTICE: DXVA::CDecoder::Close - closing decoder 20:57:57 T:8036 NOTICE: DXVA::Close - closing decoder context 20:57:57 T:8036 NOTICE: Closing stream player 3 20:57:57 T:7428 NOTICE: DVDPlayer: finished waiting 20:57:57 T:7004 NOTICE: Thread BackgroundLoader start, auto delete: false 20:57:57 T:1780 NOTICE: Thread JobWorker start, auto delete: true 20:57:57 T:7428 NOTICE: CDVDPlayer::CloseFile() 20:57:57 T:7428 NOTICE: DVDPlayer: waiting for threads to exit 20:57:57 T:7428 NOTICE: DVDPlayer: finished waiting 20:57:57 T:7428 NOTICE: CDVDPlayer::CloseFile() 20:57:57 T:7428 NOTICE: DVDPlayer: waiting for threads to exit 20:57:57 T:3716 NOTICE: EMBY Player -> onPlayBackStopped 20:57:57 T:7428 NOTICE: DVDPlayer: finished waiting 20:57:57 T:6440 NOTICE: Thread JobWorker start, auto delete: true 20:57:57 T:3716 NOTICE: Emby -> updatePlayCountFromKodi Called 20:57:57 T:7940 NOTICE: Thread BackgroundLoader start, auto delete: false 20:57:57 T:6572 NOTICE: Thread FileCache start, auto delete: false 20:57:58 T:2832 NOTICE: EMBY WebSocketThread -> Message : {"MessageType":"UserDataChanged","Data":{"UserId":"f23a949b5da2dd2cb526bf4fa8738d39","UserDataList":[{"PlaybackPositionTicks":0,"PlayCount":1,"IsFavorite":false,"Played":true,"Key":"259765002006","ItemId":"7e20d03d9893472ffe50af03405be550"},{"PlayedPercentage":20,"UnplayedItemCount":4,"PlaybackPositionTicks":0,"PlayCount":0,"IsFavorite":false,"Played":false,"Key":"259765002","ItemId":"3007c5d72c66a6ea5e16c8d74771869d"}]}} 20:57:58 T:2832 NOTICE: EMBY WebSocketThread -> Message : Doing UserDataChanged 20:57:58 T:2832 NOTICE: EMBY WebSocketThread -> Message : Doing UserDataChanged : UserDataList : [{u'ItemId': u'7e20d03d9893472ffe50af03405be550', u'IsFavorite': False, u'Played': True, u'PlaybackPositionTicks': 0, u'Key': u'259765002006', u'PlayCount': 1}, {u'ItemId': u'3007c5d72c66a6ea5e16c8d74771869d', u'IsFavorite': False, u'Played': False, u'PlayedPercentage': 20, u'UnplayedItemCount': 4, u'PlaybackPositionTicks': 0, u'Key': u'259765002', u'PlayCount': 0}] 20:57:58 T:2832 NOTICE: EMBY WebSocketThread -> Message : Doing UserDataChanged : Processing Updated : [u'7e20d03d9893472ffe50af03405be550', u'3007c5d72c66a6ea5e16c8d74771869d'] 20:57:58 T:7988 NOTICE: Thread FileCache start, auto delete: false 20:57:58 T:2832 NOTICE: UPDATE episode to Kodi library -> Id: 7e20d03d9893472ffe50af03405be550 - Title: Armies of One 20:57:58 T:4520 NOTICE: Thread VideoInfoScanner start, auto delete: false 20:57:58 T:4520 NOTICE: VideoInfoScanner: Starting scan .. 20:57:58 T:4520 NOTICE: VideoInfoScanner: Finished scan. Scanning for video info took 00:00 20:57:58 T:6972 NOTICE: Thread BackgroundLoader start, auto delete: false 20:57:58 T:7604 NOTICE: Thread FileCache start, auto delete: false 20:57:59 T:2832 NOTICE: EMBY WebSocketThread -> Message : {"MessageType":"ScheduledTaskEnded","Data":{"StartTimeUtc":"2015-06-12T00:57:59.5815443Z","EndTimeUtc":"2015-06-12T00:57:59.5815443Z","Status":"Completed","Name":"Organize new media files","Key":"AutoOrganize","Id":"415f8db75e909cdef2a3da79d1e2c636"}} 20:58:01 T:3828 NOTICE: Thread FileCache start, auto delete: false 20:58:06 T:1520 NOTICE: Thread BackgroundLoader start, auto delete: false 20:58:11 T:7520 NOTICE: Thread FileCache start, auto delete: false 20:58:13 T:4508 NOTICE: Previous line repeats 2 times. 20:58:13 T:4508 NOTICE: Thread BackgroundLoader start, auto delete: false 20:58:19 T:3716 NOTICE: Intercepted remove from sender: xbmc method: VideoLibrary.OnRemove data: {"id":54,"type":"episode"} 20:58:19 T:6692 NOTICE: Thread BackgroundLoader start, auto delete: false 20:58:19 T:3716 NOTICE: Deleting Emby ID: 7e20d03d9893472ffe50af03405be550 from database 20:58:21 T:3716 NOTICE: Deleting via URL: {server}/mediabrowser/Items/7e20d03d9893472ffe50af03405be550 20:58:21 T:3716 NOTICE: Intercepted remove from sender: xbmc method: VideoLibrary.OnRemove data: {"id":54,"type":"episode"} 20:58:23 T:3656 NOTICE: Previous line repeats 1 times. 20:58:23 T:3656 NOTICE: Thread BackgroundLoader start, auto delete: false 20:58:26 T:2832 NOTICE: EMBY WebSocketThread -> Message : {"MessageType":"LibraryChanged","Data":{"FoldersAddedTo":[],"FoldersRemovedFrom":["3007c5d72c66a6ea5e16c8d74771869d"],"ItemsAdded":[],"ItemsRemoved":["7e20d03d9893472ffe50af03405be550"],"ItemsUpdated":[]}} 20:58:26 T:2832 NOTICE: EMBY WebSocketThread -> Message : WebSocket LibraryChanged : Items Added : [] 20:58:26 T:2832 NOTICE: EMBY WebSocketThread -> Message : WebSocket LibraryChanged : Items Updated : [] 20:58:26 T:2832 NOTICE: EMBY WebSocketThread -> Message : WebSocket LibraryChanged : Items Removed : [u'7e20d03d9893472ffe50af03405be550'] 20:58:26 T:2832 NOTICE: EMBY WebSocketThread -> Type: None 20:58:26 T:2832 NOTICE: EMBY WebSocketThread -> Message : Doing LibraryChanged : Items Removed : Calling deleteItemFromKodiLibrary: 7e20d03d9893472ffe50af03405be550 20:58:26 T:2832 NOTICE: EMBY WebSocketThread -> Message : Doing LibraryChanged : Items Removed : Calling deleteItemFromKodiLibrary (musiclibrary): 7e20d03d9893472ffe50af03405be550 20:58:26 T:2832 ERROR: ERROR:root:global name 'WriteKodiMusicDB' is not defined 20:58:26 T:2832 NOTICE: . 20:58:27 T:6644 NOTICE: Thread BackgroundLoader start, auto delete: false 20:59:37 T:7452 NOTICE: Previous line repeats 4 times. 20:59:37 T:7452 NOTICE: ES: Client from 127.0.0.1 timed out Link to comment Share on other sites More sharing options...
xnappo 1592 Posted June 12, 2015 Share Posted June 12, 2015 That is weird that the music delete is triggering. That missing import could maybe be causing the watched state issue some people are having Link to comment Share on other sites More sharing options...
Angelblue05 4130 Posted June 12, 2015 Share Posted June 12, 2015 (edited) This is the problem, the door is way too open. It needs to also validate that the item to remove is actually a music item. which it doesn't.: #Process music library addon = xbmcaddon.Addon(id='plugin.video.emby') if addon.getSetting("enableMusicSync") == "true": connection = utils.KodiSQL("music") cursor = connection.cursor() for item in itemsRemoved: self.logMsg("Message : Doing LibraryChanged : Items Removed : Calling deleteItemFromKodiLibrary (musiclibrary): " + item, 0) WriteKodiMusicDB().deleteItemFromKodiLibrary(item, connection, cursor) connection.commit() cursor.close() Then, realizing that WriteKodiMusicDB() is not imported causing the websocket to maybe restart or close (maybe connected to people that has the server offline online problem). Edited June 12, 2015 by Angelblue05 Link to comment Share on other sites More sharing options...
xnappo 1592 Posted June 12, 2015 Share Posted June 12, 2015 Yep, this makes sense since we recently defaulted music sync on instead of off. Link to comment Share on other sites More sharing options...
mobamoba 12 Posted June 17, 2015 Author Share Posted June 17, 2015 I'm using 1.0.08 and the new behavior is that Emby delete shows up on stop but it doesn't delete from Kodi library. Looking in the logs I can see an error is being thrown during the stop/delete/library removal process, and I've pasted it below: 20:18:58 T:5852 NOTICE: Thread BackgroundLoader start, auto delete: false20:18:58 T:7444 ERROR: ERROR:root:no such column: None20:18:58 T:7444 NOTICE: .20:18:58 T:7444 ERROR: File "C:\Users\Matt\AppData\Roaming\Kodi\addons\plugin.video.emby\resources\lib\websocket.py", line 894, in _callback20:18:58 T:7444 ERROR: callback(self, *args)20:18:58 T:7444 ERROR: File "C:\Users\Matt\AppData\Roaming\Kodi\addons\plugin.video.emby\resources\lib\WebSocketClient.py", line 174, in on_message20:18:58 T:7444 ERROR: self.remove_items(itemsRemoved)20:18:58 T:7444 ERROR: File "C:\Users\Matt\AppData\Roaming\Kodi\addons\plugin.video.emby\resources\lib\WebSocketClient.py", line 266, in remove_items20:18:58 T:7444 ERROR: showTotalCount = ReadKodiDB().getShowTotalCount(showId, connection, cursor) # Check if there are no episodes left20:18:58 T:7444 ERROR: File "C:\Users\Matt\AppData\Roaming\Kodi\addons\plugin.video.emby\resources\lib\ReadKodiDB.py", line 104, in getShowTotalCount20:18:58 T:7444 ERROR: cursor.execute(command)20:18:58 T:6428 ERROR: EXCEPTION Thrown (PythonToCppException) : -->Python callback/script returned the following error<-- - NOTE: IGNORING THIS CAN LEAD TO MEMORY LEAKS! Error Type: <type 'exceptions.AttributeError'> Error Contents: 'str' object has no attribute 'get' Traceback (most recent call last): File "C:\Users\Matt\AppData\Roaming\Kodi\addons\plugin.video.emby\resources\lib\KodiMonitor.py", line 146, in onNotification item = result.get("Items")[0] AttributeError: 'str' object has no attribute 'get' -->End of Python script error report<--20:18:58 T:6428 NOTICE: Intercepted remove from sender: xbmc method: VideoLibrary.OnRemove data: {"id":94,"type":"episode"}20:19:56 T:3260 NOTICE: Previous line repeats 1 times.20:19:56 T:3260 NOTICE: ES: Client from 127.0.0.1 timed out Link to comment Share on other sites More sharing options...
Angelblue05 4130 Posted June 17, 2015 Share Posted June 17, 2015 @@mobamoba Can you post your entire log? This is the only way to actually know what the caused the error. Thanks. Link to comment Share on other sites More sharing options...
mobamoba 12 Posted June 17, 2015 Author Share Posted June 17, 2015 Well earlier today I reset the Kodi database because things were showing up in Emby and they weren't showing up in Kodi and so the current log is enormous with a list of all my stuff in it so I'd rather not post the whole thing. I watched three shows and the above error showed up in the log after hitting stop for all three. If there's a way I can cut the log down to just the info you need to understand the error, let me know and I'll post that. Link to comment Share on other sites More sharing options...
Angelblue05 4130 Posted June 17, 2015 Share Posted June 17, 2015 Ok, if you can capture at least 50 lines before the error - hopefully it will be enough info.... Link to comment Share on other sites More sharing options...
mobamoba 12 Posted June 17, 2015 Author Share Posted June 17, 2015 Is this enough?: 'runtime': '36747900000', 'Type': 'Episode', 'playmethod': 'DirectPlay'}}19:23:45 T:7444 NOTICE: EMBY WebSocketThread -> Message : {"MessageType":"UserDataChanged","Data":{"UserId":"f23a949b5da2dd2cb526bf4fa8738d39","UserDataList":[{"PlaybackPositionTicks":0,"PlayCount":1,"IsFavorite":false,"LastPlayedDate":"2015-06-16T23:23:44.5520028Z","Played":false,"Key":"259765002010","ItemId":"8cdc9153e428504730c468ac7c5cc4c7"},{"PlayedPercentage":0,"UnplayedItemCount":1,"PlaybackPositionTicks":0,"PlayCount":0,"IsFavorite":false,"Played":false,"Key":"259765002","ItemId":"3007c5d72c66a6ea5e16c8d74771869d"}]}}19:23:45 T:7444 NOTICE: EMBY WebSocketThread -> Message : Doing UserDataChanged19:23:45 T:7444 NOTICE: EMBY WebSocketThread -> Message : Doing UserDataChanged : UserDataList : [{u'ItemId': u'8cdc9153e428504730c468ac7c5cc4c7', u'IsFavorite': False, u'Played': False, u'LastPlayedDate': u'2015-06-16T23:23:44.5520028Z', u'PlaybackPositionTicks': 0, u'Key': u'259765002010', u'PlayCount': 1}, {u'ItemId': u'3007c5d72c66a6ea5e16c8d74771869d', u'IsFavorite': False, u'Played': False, u'PlayedPercentage': 0, u'UnplayedItemCount': 1, u'PlaybackPositionTicks': 0, u'Key': u'259765002', u'PlayCount': 0}]19:23:45 T:7444 NOTICE: EMBY WebSocketThread -> Message : Doing UserDataChanged : Processing Updated : [u'8cdc9153e428504730c468ac7c5cc4c7', u'3007c5d72c66a6ea5e16c8d74771869d']19:23:45 T:7444 NOTICE: UPDATE episode to Kodi library -> Id: 8cdc9153e428504730c468ac7c5cc4c7 - Title: Bullets and Tears19:23:45 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate19:23:45 T:5336 NOTICE: CDVDVideoCodecFFmpeg::GetFormat - Creating DXVA(1280x720)19:23:45 T:5336 NOTICE: DXVA::CDecoder::Close - closing decoder19:23:45 T:5604 NOTICE: Thread VideoInfoScanner start, auto delete: false19:23:45 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate19:23:45 T:5604 NOTICE: VideoInfoScanner: Starting scan ..19:23:45 T:5604 NOTICE: VideoInfoScanner: Finished scan. Scanning for video info took 00:0019:23:46 T:5336 NOTICE: CDVDVideoCodecFFmpeg::GetFormat - Creating DXVA(1280x720)19:23:46 T:5336 NOTICE: DXVA::CDecoder::Close - closing decoder19:23:46 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate19:23:47 T:5336 NOTICE: CDVDVideoCodecFFmpeg::GetFormat - Creating DXVA(1280x720)19:23:47 T:5336 NOTICE: DXVA::CDecoder::Close - closing decoder19:23:47 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate19:23:48 T:5336 NOTICE: CDVDVideoCodecFFmpeg::GetFormat - Creating DXVA(1280x720)19:23:48 T:5336 NOTICE: DXVA::CDecoder::Close - closing decoder19:23:48 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate19:24:49 T:3260 NOTICE: Previous line repeats 15 times.19:24:49 T:3260 NOTICE: ES: Client from 127.0.0.1 timed out19:24:51 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate19:25:53 T:5336 NOTICE: Previous line repeats 15 times.19:25:53 T:5336 NOTICE: CDVDVideoCodecFFmpeg::GetFormat - Creating DXVA(1280x720)19:25:53 T:5336 NOTICE: DXVA::CDecoder::Close - closing decoder19:25:54 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate19:25:54 T:5336 NOTICE: CDVDVideoCodecFFmpeg::GetFormat - Creating DXVA(1280x720)19:25:54 T:5336 NOTICE: DXVA::CDecoder::Close - closing decoder19:25:54 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate19:25:55 T:5336 NOTICE: CDVDVideoCodecFFmpeg::GetFormat - Creating DXVA(1280x720)19:25:55 T:5336 NOTICE: DXVA::CDecoder::Close - closing decoder19:25:55 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate19:25:55 T:5336 NOTICE: CDVDVideoCodecFFmpeg::GetFormat - Creating DXVA(1280x720)19:25:55 T:5336 NOTICE: DXVA::CDecoder::Close - closing decoder19:25:56 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate19:25:56 T:5336 NOTICE: CDVDVideoCodecFFmpeg::GetFormat - Creating DXVA(1280x720)19:25:56 T:5336 NOTICE: DXVA::CDecoder::Close - closing decoder19:25:56 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate19:26:24 T:7444 NOTICE: Previous line repeats 7 times.19:26:24 T:7444 NOTICE: EMBY WebSocketThread -> Message : {"MessageType":"ScheduledTaskEnded","Data":{"StartTimeUtc":"2015-06-16T23:26:24.0131234Z","EndTimeUtc":"2015-06-16T23:26:24.0131234Z","Status":"Completed","Name":"Organize new media files","Key":"AutoOrganize","Id":"415f8db75e909cdef2a3da79d1e2c636"}}19:26:26 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate19:26:26 T:7440 NOTICE: Thread JobWorker start, auto delete: true19:26:27 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate19:27:52 T:3260 NOTICE: Previous line repeats 21 times.19:27:52 T:3260 NOTICE: ES: Client from 127.0.0.1 timed out19:27:52 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate19:31:25 T:7444 NOTICE: Previous line repeats 51 times.19:31:25 T:7444 NOTICE: EMBY WebSocketThread -> Message : {"MessageType":"ScheduledTaskEnded","Data":{"StartTimeUtc":"2015-06-16T23:31:25.2213515Z","EndTimeUtc":"2015-06-16T23:31:25.2213515Z","Status":"Completed","Name":"Organize new media files","Key":"AutoOrganize","Id":"415f8db75e909cdef2a3da79d1e2c636"}}19:31:26 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate19:32:44 T:3260 NOTICE: Previous line repeats 18 times.19:32:44 T:3260 NOTICE: ES: Client from 127.0.0.1 timed out19:32:45 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate19:36:26 T:7444 NOTICE: Previous line repeats 53 times.19:36:26 T:7444 NOTICE: EMBY WebSocketThread -> Message : {"MessageType":"ScheduledTaskEnded","Data":{"StartTimeUtc":"2015-06-16T23:36:26.4105786Z","EndTimeUtc":"2015-06-16T23:36:26.4105786Z","Status":"Completed","Name":"Organize new media files","Key":"AutoOrganize","Id":"415f8db75e909cdef2a3da79d1e2c636"}}19:36:26 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate19:40:43 T:3260 NOTICE: Previous line repeats 62 times.19:40:43 T:3260 NOTICE: ES: Client from 127.0.0.1 timed out19:40:44 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate19:41:27 T:7444 NOTICE: Previous line repeats 10 times.19:41:27 T:7444 NOTICE: EMBY WebSocketThread -> Message : {"MessageType":"ScheduledTaskEnded","Data":{"StartTimeUtc":"2015-06-16T23:41:27.6018057Z","EndTimeUtc":"2015-06-16T23:41:27.6018057Z","Status":"Completed","Name":"Organize new media files","Key":"AutoOrganize","Id":"415f8db75e909cdef2a3da79d1e2c636"}}19:41:29 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate19:46:28 T:7444 NOTICE: Previous line repeats 72 times.19:46:28 T:7444 NOTICE: EMBY WebSocketThread -> Message : {"MessageType":"ScheduledTaskEnded","Data":{"StartTimeUtc":"2015-06-16T23:46:28.7940330Z","EndTimeUtc":"2015-06-16T23:46:28.7940330Z","Status":"Completed","Name":"Organize new media files","Key":"AutoOrganize","Id":"415f8db75e909cdef2a3da79d1e2c636"}}19:46:29 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate19:47:17 T:3260 NOTICE: Previous line repeats 11 times.19:47:17 T:3260 NOTICE: ES: Client from 127.0.0.1 timed out19:47:18 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate19:51:30 T:7444 NOTICE: Previous line repeats 61 times.19:51:30 T:7444 NOTICE: EMBY WebSocketThread -> Message : {"MessageType":"ScheduledTaskEnded","Data":{"StartTimeUtc":"2015-06-16T23:51:29.9902604Z","EndTimeUtc":"2015-06-16T23:51:29.9902604Z","Status":"Completed","Name":"Organize new media files","Key":"AutoOrganize","Id":"415f8db75e909cdef2a3da79d1e2c636"}}19:51:33 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate19:55:55 T:3260 NOTICE: Previous line repeats 63 times.19:55:55 T:3260 NOTICE: ES: Client from 127.0.0.1 timed out19:55:56 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate19:56:31 T:7444 NOTICE: Previous line repeats 8 times.19:56:31 T:7444 NOTICE: EMBY WebSocketThread -> Message : {"MessageType":"ScheduledTaskEnded","Data":{"StartTimeUtc":"2015-06-16T23:56:31.1814875Z","EndTimeUtc":"2015-06-16T23:56:31.1814875Z","Status":"Completed","Name":"Organize new media files","Key":"AutoOrganize","Id":"415f8db75e909cdef2a3da79d1e2c636"}}19:56:33 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate19:57:42 T:3260 NOTICE: Previous line repeats 16 times.19:57:42 T:3260 NOTICE: ES: Client from 127.0.0.1 timed out19:57:43 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate20:01:32 T:7444 NOTICE: Previous line repeats 55 times.20:01:32 T:7444 NOTICE: EMBY WebSocketThread -> Message : {"MessageType":"ScheduledTaskEnded","Data":{"StartTimeUtc":"2015-06-17T00:01:32.3667144Z","EndTimeUtc":"2015-06-17T00:01:32.3667144Z","Status":"Completed","Name":"Organize new media files","Key":"AutoOrganize","Id":"415f8db75e909cdef2a3da79d1e2c636"}}20:01:33 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate20:02:35 T:3260 NOTICE: Previous line repeats 15 times.20:02:35 T:3260 NOTICE: ES: Client from 127.0.0.1 timed out20:02:38 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate20:06:33 T:7444 NOTICE: Previous line repeats 57 times.20:06:33 T:7444 NOTICE: EMBY WebSocketThread -> Message : {"MessageType":"ScheduledTaskEnded","Data":{"StartTimeUtc":"2015-06-17T00:06:33.5629418Z","EndTimeUtc":"2015-06-17T00:06:33.5629418Z","Status":"Completed","Name":"Organize new media files","Key":"AutoOrganize","Id":"415f8db75e909cdef2a3da79d1e2c636"}}20:06:36 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate20:07:25 T:3260 NOTICE: Previous line repeats 11 times.20:07:25 T:3260 NOTICE: ES: Client from 127.0.0.1 timed out20:07:26 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate20:11:34 T:7444 NOTICE: Previous line repeats 60 times.20:11:34 T:7444 NOTICE: EMBY WebSocketThread -> Message : {"MessageType":"ScheduledTaskEnded","Data":{"StartTimeUtc":"2015-06-17T00:11:34.7531689Z","EndTimeUtc":"2015-06-17T00:11:34.7531689Z","Status":"Completed","Name":"Organize new media files","Key":"AutoOrganize","Id":"415f8db75e909cdef2a3da79d1e2c636"}}20:11:36 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate20:16:05 T:3260 NOTICE: Previous line repeats 65 times.20:16:05 T:3260 NOTICE: ES: Client from 127.0.0.1 timed out20:16:07 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate20:16:36 T:7444 NOTICE: Previous line repeats 6 times.20:16:36 T:7444 NOTICE: EMBY WebSocketThread -> Message : {"MessageType":"ScheduledTaskEnded","Data":{"StartTimeUtc":"2015-06-17T00:16:35.9453961Z","EndTimeUtc":"2015-06-17T00:16:35.9453961Z","Status":"Completed","Name":"Organize new media files","Key":"AutoOrganize","Id":"415f8db75e909cdef2a3da79d1e2c636"}}20:16:36 T:6428 NOTICE: EMBY WebSocketThread -> sendProgressUpdate20:18:40 T:5412 NOTICE: Previous line repeats 30 times.20:18:40 T:5412 NOTICE: CDVDPlayer::CloseFile()20:18:40 T:5412 NOTICE: DVDPlayer: waiting for threads to exit20:18:40 T:7040 NOTICE: CDVDPlayer::OnExit()20:18:40 T:7040 NOTICE: Closing stream player 120:18:40 T:7040 NOTICE: Waiting for audio thread to exit20:18:40 T:3532 NOTICE: thread end: CDVDPlayerAudio::OnExit()20:18:40 T:7040 NOTICE: Closing audio device20:18:40 T:7040 NOTICE: Deleting audio codec20:18:40 T:7040 NOTICE: Closing stream player 220:18:40 T:7040 NOTICE: waiting for video thread to exit20:18:40 T:5336 NOTICE: thread end: video_thread20:18:40 T:7040 NOTICE: deleting video codec20:18:40 T:7040 NOTICE: DXVA::CDecoder::Close - closing decoder20:18:40 T:7040 NOTICE: DXVA::Close - closing decoder context20:18:40 T:7040 NOTICE: Closing stream player 320:18:40 T:5412 NOTICE: DVDPlayer: finished waiting20:18:40 T:3328 NOTICE: Thread BackgroundLoader start, auto delete: false20:18:40 T:6428 NOTICE: EMBY Player -> onPlayBackStopped20:18:40 T:5412 NOTICE: CDVDPlayer::CloseFile()20:18:40 T:6428 NOTICE: EMBY Player -> emby Service -> played_information : {'R:\\Recorded TV\\Sorted\\Banshee\\Season 2\\10 - Bullets and Tears.mkv': {'paused': 'false', 'refresh_id': 'a7745896c480487de37207ec076e2d2b', 'AudioStreamIndex': '1', 'SubtitleStreamIndex': '2', 'currentPosition': 3356.38623046875, 'item_id': '8cdc9153e428504730c468ac7c5cc4c7', 'currentfile': 'R:\\Recorded TV\\Sorted\\Banshee\\Season 2\\10 - Bullets and Tears.mkv', 'runtime': '36747900000', 'Type': 'Episode', 'playmethod': 'DirectPlay'}}20:18:40 T:5412 NOTICE: DVDPlayer: waiting for threads to exit20:18:40 T:6428 NOTICE: EMBY Player -> emby Service -> item_url : R:\Recorded TV\Sorted\Banshee\Season 2\10 - Bullets and Tears.mkv20:18:40 T:5412 NOTICE: DVDPlayer: finished waiting20:18:40 T:6428 NOTICE: EMBY Player -> emby Service -> item_data : {'paused': 'false', 'refresh_id': 'a7745896c480487de37207ec076e2d2b', 'AudioStreamIndex': '1', 'SubtitleStreamIndex': '2', 'currentPosition': 3356.38623046875, 'item_id': '8cdc9153e428504730c468ac7c5cc4c7', 'currentfile': 'R:\\Recorded TV\\Sorted\\Banshee\\Season 2\\10 - Bullets and Tears.mkv', 'runtime': '36747900000', 'Type': 'Episode', 'playmethod': 'DirectPlay'}20:18:40 T:5412 NOTICE: CDVDPlayer::CloseFile()20:18:40 T:6428 NOTICE: EMBY Player -> emby Service -> runtimeticks:3674790000020:18:40 T:5412 NOTICE: DVDPlayer: waiting for threads to exit20:18:40 T:6428 NOTICE: EMBY Player -> emby Service -> Percent Complete:0.913354567327 Mark Played At:0.920:18:40 T:5412 NOTICE: DVDPlayer: finished waiting20:18:40 T:7444 NOTICE: EMBY WebSocketThread -> Message : {"MessageType":"PlaybackStopped","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":"88d4564917841e701ea7a34e613e48fd","UserId":"f23a949b5da2dd2cb526bf4fa8738d39","UserName":"Matt","AdditionalUsers":[],"ApplicationVersion":"1.0.08","Client":"Kodi","LastActivityDate":"2015-06-17T00:18:40.3855137Z","DeviceName":"Kodi","DeviceId":"5F6752490791471382C9E065476E32AB","SupportsRemoteControl":true,"PlayState":{"CanSeek":false,"IsPaused":false,"IsMuted":false}}}20:18:40 T:8044 NOTICE: Thread JobWorker start, auto delete: true20:18:40 T:7444 NOTICE: EMBY WebSocketThread -> Message : {"MessageType":"UserDataChanged","Data":{"UserId":"f23a949b5da2dd2cb526bf4fa8738d39","UserDataList":[{"PlaybackPositionTicks":0,"PlayCount":1,"IsFavorite":false,"LastPlayedDate":"2015-06-16T23:23:44.5520028Z","Played":true,"Key":"259765002010","ItemId":"8cdc9153e428504730c468ac7c5cc4c7"},{"PlayedPercentage":100,"UnplayedItemCount":0,"PlaybackPositionTicks":0,"PlayCount":0,"IsFavorite":false,"Played":true,"Key":"259765002","ItemId":"3007c5d72c66a6ea5e16c8d74771869d"}]}}20:18:40 T:7444 NOTICE: EMBY WebSocketThread -> Message : Doing UserDataChanged20:18:40 T:7444 NOTICE: EMBY WebSocketThread -> Message : Doing UserDataChanged : UserDataList : [{u'ItemId': u'8cdc9153e428504730c468ac7c5cc4c7', u'IsFavorite': False, u'Played': True, u'LastPlayedDate': u'2015-06-16T23:23:44.5520028Z', u'PlaybackPositionTicks': 0, u'Key': u'259765002010', u'PlayCount': 1}, {u'ItemId': u'3007c5d72c66a6ea5e16c8d74771869d', u'IsFavorite': False, u'Played': True, u'PlayedPercentage': 100, u'UnplayedItemCount': 0, u'PlaybackPositionTicks': 0, u'Key': u'259765002', u'PlayCount': 0}]20:18:40 T:7444 NOTICE: EMBY WebSocketThread -> Message : Doing UserDataChanged : Processing Updated : [u'8cdc9153e428504730c468ac7c5cc4c7', u'3007c5d72c66a6ea5e16c8d74771869d']20:18:41 T:7444 NOTICE: UPDATE episode to Kodi library -> Id: 8cdc9153e428504730c468ac7c5cc4c7 - Title: Bullets and Tears20:18:41 T:6164 NOTICE: Thread VideoInfoScanner start, auto delete: false20:18:41 T:6164 NOTICE: VideoInfoScanner: Starting scan ..20:18:41 T:6164 NOTICE: VideoInfoScanner: Finished scan. Scanning for video info took 00:0020:18:41 T:1820 NOTICE: Thread BackgroundLoader start, auto delete: false20:18:42 T:6428 NOTICE: Deleting via URL: {server}/mediabrowser/Items/8cdc9153e428504730c468ac7c5cc4c720:18:43 T:6428 NOTICE: Emby -> updatePlayCountFromKodi Called20:18:43 T:8088 NOTICE: Thread BackgroundLoader start, auto delete: false20:18:54 T:7760 NOTICE: Previous line repeats 3 times.20:18:54 T:7760 NOTICE: Thread JobWorker start, auto delete: true20:18:55 T:1908 NOTICE: Thread BackgroundLoader start, auto delete: false20:18:55 T:7892 NOTICE: Thread JobWorker start, auto delete: true20:18:57 T:6428 NOTICE: Intercepted remove from sender: xbmc method: VideoLibrary.OnRemove data: {"id":94,"type":"episode"}20:18:57 T:7444 NOTICE: EMBY WebSocketThread -> Message : {"MessageType":"LibraryChanged","Data":{"FoldersAddedTo":[],"FoldersRemovedFrom":["3007c5d72c66a6ea5e16c8d74771869d"],"ItemsAdded":[],"ItemsRemoved":["8cdc9153e428504730c468ac7c5cc4c7"],"ItemsUpdated":[]}}20:18:57 T:7444 NOTICE: EMBY WebSocketThread -> Message : WebSocket LibraryChanged : Items Added : []20:18:57 T:7444 NOTICE: EMBY WebSocketThread -> Message : WebSocket LibraryChanged : Items Updated : []20:18:57 T:7444 NOTICE: EMBY WebSocketThread -> Message : WebSocket LibraryChanged : Items Removed : [u'8cdc9153e428504730c468ac7c5cc4c7']20:18:57 T:6428 NOTICE: Deleting Emby ID: 8cdc9153e428504730c468ac7c5cc4c7 from database20:18:57 T:7444 NOTICE: EMBY WebSocketThread -> Type: episode20:18:57 T:7444 NOTICE: EMBY WebSocketThread -> Message : Doing LibraryChanged : Items Removed : Calling deleteItemFromKodiLibrary: 8cdc9153e428504730c468ac7c5cc4c720:18:58 T:6192 NOTICE: Thread BackgroundLoader start, auto delete: false20:18:58 T:7444 NOTICE: EMBY WebSocketThread -> ShowID: None20:18:58 T:5852 NOTICE: Thread BackgroundLoader start, auto delete: false20:18:58 T:7444 ERROR: ERROR:root:no such column: None20:18:58 T:7444 NOTICE: .20:18:58 T:7444 ERROR: File "C:\Users\Matt\AppData\Roaming\Kodi\addons\plugin.video.emby\resources\lib\websocket.py", line 894, in _callback20:18:58 T:7444 ERROR: callback(self, *args)20:18:58 T:7444 ERROR: File "C:\Users\Matt\AppData\Roaming\Kodi\addons\plugin.video.emby\resources\lib\WebSocketClient.py", line 174, in on_message20:18:58 T:7444 ERROR: self.remove_items(itemsRemoved)20:18:58 T:7444 ERROR: File "C:\Users\Matt\AppData\Roaming\Kodi\addons\plugin.video.emby\resources\lib\WebSocketClient.py", line 266, in remove_items20:18:58 T:7444 ERROR: showTotalCount = ReadKodiDB().getShowTotalCount(showId, connection, cursor) # Check if there are no episodes left20:18:58 T:7444 ERROR: File "C:\Users\Matt\AppData\Roaming\Kodi\addons\plugin.video.emby\resources\lib\ReadKodiDB.py", line 104, in getShowTotalCount20:18:58 T:7444 ERROR: cursor.execute(command)20:18:58 T:6428 ERROR: EXCEPTION Thrown (PythonToCppException) : -->Python callback/script returned the following error<-- - NOTE: IGNORING THIS CAN LEAD TO MEMORY LEAKS! Error Type: <type 'exceptions.AttributeError'> Error Contents: 'str' object has no attribute 'get' Traceback (most recent call last): File "C:\Users\Matt\AppData\Roaming\Kodi\addons\plugin.video.emby\resources\lib\KodiMonitor.py", line 146, in onNotification item = result.get("Items")[0] AttributeError: 'str' object has no attribute 'get' -->End of Python script error report<--20:18:58 T:6428 NOTICE: Intercepted remove from sender: xbmc method: VideoLibrary.OnRemove data: {"id":94,"type":"episode"}20:19:56 T:3260 NOTICE: Previous line repeats 1 times.20:19:56 T:3260 NOTICE: ES: Client from 127.0.0.1 timed out 1 Link to comment Share on other sites More sharing options...
mobamoba 12 Posted June 30, 2015 Author Share Posted June 30, 2015 I'm still having sporadic problems with this FYI. Sometimes I'll get Emby Delete and sometimes a show will get marked watched without Emby Delete ever appearing. Here's part of my log from a recent example if this helps sort out the problem: 15:00:51 T:5888 NOTICE: ES: Client from 127.0.0.1 timed out15:03:06 T:1832 NOTICE: EMBY WebSocketThread -> Message : {"MessageType":"ScheduledTaskEnded","Data":{"StartTimeUtc":"2015-06-30T19:03:05.8535513Z","EndTimeUtc":"2015-06-30T19:03:05.8535513Z","Status":"Completed","Name":"Organize new media files","Key":"AutoOrganize","Id":"415f8db75e909cdef2a3da79d1e2c636"}}15:04:28 T:5696 NOTICE: CDVDVideoCodecFFmpeg::GetFormat - Creating DXVA(1280x736)15:04:28 T:5696 NOTICE: DXVA::CDecoder::Close - closing decoder15:04:28 T:2232 NOTICE: CDVDPlayerAudio::OutputPacket skipping a packets of duration 2315:04:28 T:5696 NOTICE: Previous line repeats 1 times.15:04:28 T:5696 NOTICE: CDVDVideoCodecFFmpeg::GetFormat - Creating DXVA(1280x736)15:04:28 T:5696 NOTICE: DXVA::CDecoder::Close - closing decoder15:04:28 T:2232 NOTICE: CDVDPlayerAudio::OutputPacket skipping a packets of duration 2315:04:29 T:5696 NOTICE: CDVDVideoCodecFFmpeg::GetFormat - Creating DXVA(1280x736)15:04:29 T:5696 NOTICE: DXVA::CDecoder::Close - closing decoder15:04:29 T:2232 NOTICE: CDVDPlayerAudio::OutputPacket skipping a packets of duration 2315:04:30 T:5696 NOTICE: Previous line repeats 1 times.15:04:30 T:5696 NOTICE: CDVDVideoCodecFFmpeg::GetFormat - Creating DXVA(1280x736)15:04:30 T:5696 NOTICE: DXVA::CDecoder::Close - closing decoder15:04:30 T:2232 NOTICE: CDVDPlayerAudio::OutputPacket skipping a packets of duration 2315:04:32 T:5696 NOTICE: CDVDVideoCodecFFmpeg::GetFormat - Creating DXVA(1280x736)15:04:32 T:5696 NOTICE: DXVA::CDecoder::Close - closing decoder15:04:32 T:2232 NOTICE: CDVDPlayerAudio::OutputPacket skipping a packets of duration 2315:04:33 T:5696 NOTICE: CDVDVideoCodecFFmpeg::GetFormat - Creating DXVA(1280x736)15:04:33 T:5696 NOTICE: DXVA::CDecoder::Close - closing decoder15:04:33 T:2232 NOTICE: CDVDPlayerAudio::OutputPacket skipping a packets of duration 2315:05:34 T:5888 NOTICE: ES: Client from 127.0.0.1 timed out15:07:33 T:3236 NOTICE: CDVDPlayer::CloseFile()15:07:33 T:3236 NOTICE: DVDPlayer: waiting for threads to exit15:07:33 T:6956 NOTICE: CDVDPlayer::OnExit()15:07:33 T:6956 NOTICE: Closing stream player 115:07:33 T:6956 NOTICE: Waiting for audio thread to exit15:07:33 T:2232 NOTICE: thread end: CDVDPlayerAudio::OnExit()15:07:33 T:6956 NOTICE: Closing audio device15:07:33 T:6956 NOTICE: Deleting audio codec15:07:33 T:6956 NOTICE: Closing stream player 215:07:33 T:6956 NOTICE: waiting for video thread to exit15:07:33 T:5696 NOTICE: thread end: video_thread15:07:33 T:6956 NOTICE: deleting video codec15:07:33 T:6956 NOTICE: DXVA::CDecoder::Close - closing decoder15:07:33 T:6956 NOTICE: DXVA::Close - closing decoder context15:07:33 T:6956 NOTICE: Closing stream player 315:07:33 T:3236 NOTICE: DVDPlayer: finished waiting15:07:33 T:5468 NOTICE: Thread BackgroundLoader start, auto delete: false15:07:33 T:3236 NOTICE: Previous line repeats 1 times.15:07:33 T:3236 NOTICE: CDVDPlayer::CloseFile()15:07:33 T:3236 NOTICE: DVDPlayer: waiting for threads to exit15:07:33 T:3236 NOTICE: DVDPlayer: finished waiting15:07:33 T:3236 NOTICE: CDVDPlayer::CloseFile()15:07:33 T:3236 NOTICE: DVDPlayer: waiting for threads to exit15:07:33 T:3236 NOTICE: DVDPlayer: finished waiting15:07:33 T:4692 NOTICE: EMBY Player -> onPlayBackStopped15:07:33 T:2776 NOTICE: Thread JobWorker start, auto delete: true15:07:33 T:2776 NOTICE: Previous line repeats 1 times.15:07:33 T:2776 WARNING: XFILE::CFileFactory::CreateLoader - unsupported protocol(plugin) in plugin://plugin.video.emby/tvshows/93ac24798b4fd3a0e5c7d29e80f8551b/?id=f5518c4cce591deb6ed488031a458882&mode=play15:07:33 T:2776 ERROR: InputStream: Error opening, plugin://plugin.video.emby/tvshows/93ac24798b4fd3a0e5c7d29e80f8551b/?id=f5518c4cce591deb6ed488031a458882&mode=play15:07:33 T:2776 WARNING: XFILE::CFileFactory::CreateLoader - unsupported protocol(plugin) in plugin://plugin.video.emby/tvshows/93ac24798b4fd3a0e5c7d29e80f8551b/?id=af41433648ab42c84a4da2397d3615a7&mode=play15:07:33 T:2776 ERROR: InputStream: Error opening, plugin://plugin.video.emby/tvshows/93ac24798b4fd3a0e5c7d29e80f8551b/?id=af41433648ab42c84a4da2397d3615a7&mode=play15:07:34 T:7844 NOTICE: Thread FileCache start, auto delete: false15:07:34 T:1832 NOTICE: Previous line repeats 1 times.15:07:34 T:1832 NOTICE: EMBY WebSocketThread -> Message : {"MessageType":"UserDataChanged","Data":{"UserId":"f23a949b5da2dd2cb526bf4fa8738d39","UserDataList":[{"PlaybackPositionTicks":0,"PlayCount":2,"IsFavorite":false,"LastPlayedDate":"2015-06-30T18:49:42.0255750Z","Played":true,"Key":"183411003006","ItemId":"f5518c4cce591deb6ed488031a458882"},{"PlayedPercentage":50,"UnplayedItemCount":1,"PlaybackPositionTicks":0,"PlayCount":0,"IsFavorite":false,"Played":false,"Key":"183411003","ItemId":"f4c638d66fdce748ff6a7eefb99a368c"}]}}15:07:34 T:1832 NOTICE: EMBY WebSocketThread -> Message : Doing UserDataChanged15:07:34 T:1832 NOTICE: EMBY WebSocketThread -> Message : Doing UserDataChanged : UserDataList : [{u'ItemId': u'f5518c4cce591deb6ed488031a458882', u'IsFavorite': False, u'Played': True, u'LastPlayedDate': u'2015-06-30T18:49:42.0255750Z', u'PlaybackPositionTicks': 0, u'Key': u'183411003006', u'PlayCount': 2}, {u'ItemId': u'f4c638d66fdce748ff6a7eefb99a368c', u'IsFavorite': False, u'Played': False, u'PlayedPercentage': 50, u'UnplayedItemCount': 1, u'PlaybackPositionTicks': 0, u'Key': u'183411003', u'PlayCount': 0}]15:07:34 T:1832 NOTICE: EMBY WebSocketThread -> Message : Doing UserDataChanged : Processing Updated : [u'f5518c4cce591deb6ed488031a458882', u'f4c638d66fdce748ff6a7eefb99a368c']15:07:34 T:8032 NOTICE: Thread FileCache start, auto delete: false15:07:34 T:2776 NOTICE: VideoInfoScanner: Starting scan ..15:07:34 T:2776 NOTICE: VideoInfoScanner: Finished scan. Scanning for video info took 00:0015:07:34 T:3892 NOTICE: Thread BackgroundLoader start, auto delete: false15:07:34 T:2776 WARNING: XFILE::CFileFactory::CreateLoader - unsupported protocol(plugin) in plugin://plugin.video.emby/tvshows/93ac24798b4fd3a0e5c7d29e80f8551b/?id=af41433648ab42c84a4da2397d3615a7&mode=play15:07:34 T:2776 ERROR: InputStream: Error opening, plugin://plugin.video.emby/tvshows/93ac24798b4fd3a0e5c7d29e80f8551b/?id=af41433648ab42c84a4da2397d3615a7&mode=play15:07:34 T:5020 NOTICE: Thread BackgroundLoader start, auto delete: false15:07:34 T:2776 WARNING: XFILE::CFileFactory::CreateLoader - unsupported protocol(plugin) in plugin://plugin.video.emby/tvshows/93ac24798b4fd3a0e5c7d29e80f8551b/?id=af41433648ab42c84a4da2397d3615a7&mode=play15:07:34 T:2776 ERROR: InputStream: Error opening, plugin://plugin.video.emby/tvshows/93ac24798b4fd3a0e5c7d29e80f8551b/?id=af41433648ab42c84a4da2397d3615a7&mode=play15:07:34 T:5820 NOTICE: Thread FileCache start, auto delete: false15:07:39 T:7516 NOTICE: Previous line repeats 1 times.15:07:39 T:7516 NOTICE: Thread BackgroundLoader start, auto delete: false15:07:39 T:2776 WARNING: XFILE::CFileFactory::CreateLoader - unsupported protocol(plugin) in plugin://plugin.video.emby/tvshows/93ac24798b4fd3a0e5c7d29e80f8551b/?id=f5518c4cce591deb6ed488031a458882&mode=play15:07:39 T:2776 ERROR: InputStream: Error opening, plugin://plugin.video.emby/tvshows/93ac24798b4fd3a0e5c7d29e80f8551b/?id=f5518c4cce591deb6ed488031a458882&mode=play15:07:41 T:3140 NOTICE: Thread FileCache start, auto delete: false15:07:46 T:5628 NOTICE: Previous line repeats 4 times. Link to comment Share on other sites More sharing options...
xnappo 1592 Posted June 30, 2015 Share Posted June 30, 2015 What version is this log from? If 1.1.15, please try 1.1.16. Link to comment Share on other sites More sharing options...
mobamoba 12 Posted July 1, 2015 Author Share Posted July 1, 2015 I'm on the beta channel so I'm using whatever is the most recent update you guys pushed. It just happened again, i.e. the item gets marked as watched on stop but Emby delete doesn't show up. BTW this behavior is inconsistent as sometimes Emby delete does show up. Below is from a recent log where it didn't show up. 14:20:17 T:5888 NOTICE: ES: Client from 127.0.0.1 timed out14:22:28 T:3236 NOTICE: CDVDPlayer::CloseFile()14:22:28 T:3236 NOTICE: DVDPlayer: waiting for threads to exit14:22:28 T:1208280 NOTICE: CDVDPlayer::OnExit()14:22:28 T:1208280 NOTICE: Closing stream player 114:22:28 T:1208280 NOTICE: Waiting for audio thread to exit14:22:28 T:1208300 NOTICE: thread end: CDVDPlayerAudio::OnExit()14:22:28 T:1208280 NOTICE: Closing audio device14:22:28 T:1208280 NOTICE: Deleting audio codec14:22:28 T:1208280 NOTICE: Closing stream player 214:22:28 T:1208280 NOTICE: waiting for video thread to exit14:22:28 T:1208296 NOTICE: thread end: video_thread14:22:28 T:1208280 NOTICE: deleting video codec14:22:28 T:1208280 NOTICE: DXVA::CDecoder::Close - closing decoder14:22:28 T:1208280 NOTICE: DXVA::Close - closing decoder context14:22:28 T:1208280 NOTICE: Closing stream player 314:22:28 T:3236 NOTICE: DVDPlayer: finished waiting14:22:28 T:1318496 NOTICE: Thread BackgroundLoader start, auto delete: false14:22:28 T:1318508 NOTICE: Thread JobWorker start, auto delete: true14:22:28 T:3236 NOTICE: CDVDPlayer::CloseFile()14:22:28 T:3236 NOTICE: DVDPlayer: waiting for threads to exit14:22:28 T:3236 NOTICE: DVDPlayer: finished waiting14:22:28 T:3236 NOTICE: CDVDPlayer::CloseFile()14:22:28 T:3236 NOTICE: DVDPlayer: waiting for threads to exit14:22:28 T:3236 NOTICE: DVDPlayer: finished waiting14:22:28 T:4416 NOTICE: EMBY Player -> onPlayBackStopped14:22:29 T:2136 NOTICE: EMBY WebSocketThread -> Message : {"MessageType":"UserDataChanged","Data":{"UserId":"f23a949b5da2dd2cb526bf4fa8738d39","UserDataList":[{"PlaybackPositionTicks":0,"PlayCount":1,"IsFavorite":false,"LastPlayedDate":"2015-07-01T18:03:24.7584372Z","Played":true,"Key":"183411003010","ItemId":"af41433648ab42c84a4da2397d3615a7"},{"PlayedPercentage":100,"UnplayedItemCount":0,"PlaybackPositionTicks":0,"PlayCount":0,"IsFavorite":false,"Played":true,"Key":"183411003","ItemId":"f4c638d66fdce748ff6a7eefb99a368c"}]}}14:22:29 T:2136 NOTICE: EMBY WebSocketThread -> Message : Doing UserDataChanged14:22:29 T:2136 NOTICE: EMBY WebSocketThread -> Message : Doing UserDataChanged : UserDataList : [{u'ItemId': u'af41433648ab42c84a4da2397d3615a7', u'IsFavorite': False, u'Played': True, u'LastPlayedDate': u'2015-07-01T18:03:24.7584372Z', u'PlaybackPositionTicks': 0, u'Key': u'183411003010', u'PlayCount': 1}, {u'ItemId': u'f4c638d66fdce748ff6a7eefb99a368c', u'IsFavorite': False, u'Played': True, u'PlayedPercentage': 100, u'UnplayedItemCount': 0, u'PlaybackPositionTicks': 0, u'Key': u'183411003', u'PlayCount': 0}]14:22:29 T:2136 NOTICE: EMBY WebSocketThread -> Message : Doing UserDataChanged : Processing Updated : [u'af41433648ab42c84a4da2397d3615a7', u'f4c638d66fdce748ff6a7eefb99a368c']14:22:29 T:1318508 NOTICE: VideoInfoScanner: Starting scan ..14:22:29 T:1318508 NOTICE: VideoInfoScanner: Finished scan. Scanning for video info took 00:0014:22:29 T:1318632 NOTICE: Thread BackgroundLoader start, auto delete: false14:22:34 T:1318508 NOTICE: Previous line repeats 2 times.14:22:34 T:1318508 WARNING: XFILE::CFileFactory::CreateLoader - unsupported protocol(plugin) in plugin://plugin.video.emby/tvshows/93ac24798b4fd3a0e5c7d29e80f8551b/?id=af41433648ab42c84a4da2397d3615a7&mode=play14:22:34 T:1318508 ERROR: InputStream: Error opening, plugin://plugin.video.emby/tvshows/93ac24798b4fd3a0e5c7d29e80f8551b/?id=af41433648ab42c84a4da2397d3615a7&mode=play14:22:37 T:1319404 NOTICE: Thread LanguageInvoker start, auto delete: false Link to comment Share on other sites More sharing options...
xnappo 1592 Posted July 1, 2015 Share Posted July 1, 2015 (edited) You are talking about it offering you the option to delete? Do you have the 'Auto play next' feature also enabled? (Netflix style thing) Thanks, xnappo Edited July 1, 2015 by xnappo Link to comment Share on other sites More sharing options...
mobamoba 12 Posted July 1, 2015 Author Share Posted July 1, 2015 (edited) Yeah I'm talking about the thing that asks if you want to delete the file from the Emby server - it doesn't show up consistently. I don't have the Netflix-style thing enabled. ETA: Actually I'm stlil on 1.1.13. I'm using Isengard beta2 so I can't force refresh to update the addon and for whatever reason, it's not updating me automatically (I have it set to auto update). I tried seting auto update to "notify" then manually updating the addon but "update" is grayed out so that doesn't work either. Edited July 1, 2015 by mobamoba Link to comment Share on other sites More sharing options...
xnappo 1592 Posted July 1, 2015 Share Posted July 1, 2015 Can't see what is going on. Please bump up the log level and post the whole thing (see 'how to report a problem' sticky) Link to comment Share on other sites More sharing options...
mobamoba 12 Posted July 1, 2015 Author Share Posted July 1, 2015 Okay. Like I mentioned, it's sporadic, so I'll increase the log level and upload next time it happens. Link to comment Share on other sites More sharing options...
mobamoba 12 Posted July 2, 2015 Author Share Posted July 2, 2015 Log is attached (I put the level to Info not Debug). If you jump to 21:32:24, you'll see a show I watched last night where Emby delete worked, i.e. I hit stop at the end, the show was marked as watched, and Emby asked me if I wanted to delete, and, after hitting yes, the show was removed from both the library and physically on my disk. If you then jump to 13:28:07, you'll see a show I watched today where Emby delete failed, i.e. I hit stop at the end and the show was marked as watched but the Emby delete dialogue never appeared and I had to go find the show and delete it manually through the Kodi context menu from both the library and the physical disk. My computer wasn't rebooted nor was Kodi restarted between those two shows. Emby delete simply worked on one then didn't on the other and perhaps my log will help you understand why. Thanks. kodi.log Link to comment Share on other sites More sharing options...
Recommended Posts