[Milhouse]

ps.
When I use ./texturecache.py qax tvshows "Baby Daddy" than the tool is finishing its job
in above log baby daddy as example is stalling on the callback part and in the 2nd log (much smaller btw) you see it is finishing ok

http://we.tl/9aYzHwj4WY

This isn't doing a scan, which is why it succeeds - from what I can tell it found no QA issues that needed fixing.

Thanks for such quick reply

http://we.tl/G60T1HbY3H

started with empty logfile
started with ./texturecache.py qax tvshows

logfile 5MB ..
(sorry I have too much tvshows)

It looks like you've got some other process that is starting a video library clean while the script is running, which is conflicting with the subsequent video library scan started by texturecache.py.

In the following log detail, while texturecache.py is removing a Baby Daddy Season 4 episode, a library clean is started. The texturecache.py script sees the "OnCleanStarted" notification, which it simply ignores as it's not relevant to it's current processing. The library clean is not being started by texturecache.py - the library clean must be being started from the GUI, or an addon or some other external script/cron:

Code:

2016-01-30 09:09:10.367642:MainThread: Removing episodeid 6858 from media library.
2016-01-30 09:09:10.367965:MainThread: libRemove.JSON SOCKET REQUEST: [{"jsonrpc": "2.0", "params": {"episodeid": 6858}, "method": "VideoLibrary.RemoveEpisode", "id": "libRemove"}]
2016-01-30 09:09:10.374653:MainThread: libRemove.BUFFER RECEIVED (len 113)
2016-01-30 09:09:10.375537:MainThread: libRemove.PARSING JSON DATA: {"jsonrpc":"2.0","method":"VideoLibrary.OnRemove","params":{"data":{"id":6858,"type":"episode"},"sender":"xbmc"}}
2016-01-30 09:09:10.376097:MainThread: libRemove.PARSING COMPLETE, elapsed time: 0.000556 seconds
2016-01-30 09:09:10.377243:MainThread: libRemove.IGNORING NOTIFICATION [{"params": {"data": {"type": "episode", "id": 6858}, "sender": "xbmc"}, "jsonrpc": "2.0", "method": "VideoLibrary.OnRemove"}]
2016-01-30 09:09:10.377620:MainThread: libRemove.READING SOCKET FOR A RESPONSE...
2016-01-30 09:09:10.411303:MainThread: libRemove.BUFFER RECEIVED (len 95)
2016-01-30 09:09:10.411673:MainThread: libRemove.PARSING JSON DATA: {"jsonrpc":"2.0","method":"VideoLibrary.OnCleanStarted","params":{"data":null,"sender":"xbmc"}}
2016-01-30 09:09:10.411862:MainThread: libRemove.PARSING COMPLETE, elapsed time: 0.000249 seconds
2016-01-30 09:09:10.412136:MainThread: libRemove.IGNORING NOTIFICATION [{"params": {"data": null, "sender": "xbmc"}, "jsonrpc": "2.0", "method": "VideoLibrary.OnCleanStarted"}]
2016-01-30 09:09:10.412302:MainThread: libRemove.READING SOCKET FOR A RESPONSE...
2016-01-30 09:09:10.482488:MainThread: libRemove.BUFFER RECEIVED (len 48)
2016-01-30 09:09:10.482981:MainThread: libRemove.PARSING JSON DATA: {"id":"libRemove","jsonrpc":"2.0","result":"OK"}

Subsequently, when the texturecache.py script tries to start a library scan - when the library clean is still running - the scan request is silently ignored by Kodi because there is a library clean in progress:

Code:

2016-01-30 09:09:10.790270:MainThread: Rescanning directory: smb://SHARK/Usenet/TV/Baby Daddy/Season 4...
2016-01-30 09:09:10.790723:MainThread: libRescan.JSON SOCKET REQUEST: [{"jsonrpc": "2.0", "params": {"directory": "smb://SHARK/Usenet/TV/Baby Daddy/Season 4", "showdialogs": false}, "method": "VideoLibrary.Scan", "id": "libRescan"}]
2016-01-30 09:09:10.792881:MainThread: libRescan.BUFFER RECEIVED (len 48)
2016-01-30 09:09:10.793348:MainThread: libRescan.PARSING JSON DATA: {"id":"libRescan","jsonrpc":"2.0","result":"OK"}
2016-01-30 09:09:10.793600:MainThread: libRescan.PARSING COMPLETE, elapsed time: 0.000292 seconds
2016-01-30 09:09:10.793822:MainThread: libRescan.PERFORMING CALLBACK: Name [jsonWaitForScanFinished], with Id [libRescan], Method [OK], Params [None]
2016-01-30 09:09:10.794070:MainThread: libRescan.CALLBACK RESULT: [False] Name [jsonWaitForScanFinished], Id [libRescan], Method [OK], Params [None]
2016-01-30 09:09:10.794276:MainThread: libRescan.READING SOCKET UNTIL CALLBACK SUCCEEDS...
2016-01-30 09:09:28.459701:MainThread: libRescan.BUFFER RECEIVED (len 96)
2016-01-30 09:09:28.459934:MainThread: libRescan.PARSING JSON DATA: {"jsonrpc":"2.0","method":"VideoLibrary.OnCleanFinished","params":{"data":null,"sender":"xbmc"}}
2016-01-30 09:09:28.460025:MainThread: libRescan.PARSING COMPLETE, elapsed time: 0.000131 seconds
2016-01-30 09:09:28.460109:MainThread: libRescan.PERFORMING CALLBACK: Name [jsonWaitForScanFinished], with Id [None], Method [VideoLibrary.OnCleanFinished], Params [{u'data': None, u'sender': u'xbmc'}]
2016-01-30 09:09:28.460176:MainThread: libRescan.CALLBACK RESULT: [False] Name [jsonWaitForScanFinished], Id [None], Method [VideoLibrary.OnCleanFinished], Params [{u'data': None, u'sender': u'xbmc'}]
2016-01-30 09:09:28.460231:MainThread: libRescan.READING SOCKET UNTIL CALLBACK SUCCEEDS...

Consequently, the texturecache.py script never sees a "VideoLibrary.OnScanFinished" notification and is left hanging, waiting forever for a notification that is never going to come (unless you manually start another library scan).

18 seconds after the library scan request (which didn't start, despite the "OK" result), the library clean finishes but again this notification is not relevant as the texturecache.py script is waiting for a scan to finish, not a clean... so it continues to wait.

Perhaps I could add some sort of "state" so that the script knows if a library clean has been started (or queries the clean/scan status before trying to kick off a scan, and polls/waits for it to complete)... nah, just stop running whatever process is automatically starting the library clean.

If you want to clean your library you can use the texturecache.py script (aclean/vclean), but to avoid hanging the script while it is trying to run a library scan simply stop cleaning your library at the same time!