search

pannal / Sub-Zero.bundle

Subtitles for Plex, as good you would expect them to be.
Other
1.76k stars 120 forks source link

Subs are not downloaded (Sometimes) #112

Closed sebas77 closed 8 years ago

sebas77 commented 8 years ago

I tried everything and every possible combination, but for some specific TV series episodes, the plugin just won't download any subs. I also disabled all the other agents to be sure there isn't any conflict. The title is found if I search for it manually. The logs don't show anything useful apparently. I can add info if you tell me what to look for.

pannal commented 8 years ago

Please provide a DEBUG log (change the log_level in SZ's settings), thanks!

pannal commented 8 years ago

Closing this due to no response

sebas77 commented 8 years ago

not sure if it's useful, but:

searchAllRecentlyAddedMissing, triggering refresh for title 2016-01-31 11:30:00,167 (630) : DEBUG (logkit:13) - Task: searchAllRecentlyAddedMissing, item stalled for 30 seconds: 874, retrying 2016-01-31 11:30:30,256 (630) : DEBUG (logkit:13) - Task: searchAllRecentlyAddedMissing, item stalled for 30 seconds: 874, retrying 2016-01-31 11:31:00,331 (630) : DEBUG (logkit:13) - Task: searchAllRecentlyAddedMissing, item stalled for 30 seconds: 874, retrying 2016-01-31 11:31:30,407 (630) : DEBUG (logkit:13) - Task: searchAllRecentlyAddedMissing, item stalled for 4 times: 874, skipping 2016-01-31 11:31:31,407 (630) : DEBUG (logkit:13) - Task:

pannal commented 8 years ago

related to #109?

What does "sometimes" mean? How often does that happen? Do you have logs?

sebas77 commented 8 years ago

It means that is 100% not working on specific titles only. I'd say that 80% of the times it works.

sebas77 commented 8 years ago

Another thing I noticed, that could be related is that most of the folders (but not all of them) are set as read only. I wonder if this is the reason why the subs cannot be downloaded.

sebas77 commented 8 years ago

that doesn't appear to be the problem

jamesmacwhite commented 8 years ago

I had this problem, however I since moved Plex Media Server to Linux and this error doesn't seem to be happening on this platform. I migrated my database and cache/metadata folders so its using the same library content still.

I would suggest that it maybe could be a Windows specific area to look at. I'm obviously not saying you should switch to Linux or anything like that.

Amaelh commented 8 years ago

Hello,

same here (as posted in #109 ) : subs are not downloading. I'm under Plex Media Server for Linux, latest version.

2016-04-09 19:39:30,188 (7f52677fe700) : DEBUG (tasks:101) - Task: searchAllRecentlyAddedMissing, triggering refresh for Grimm S05E11, 2016-03-04 (63115) 2016-04-09 19:40:00,288 (7f52677fe700) : DEBUG (tasks:119) - Task: searchAllRecentlyAddedMissing, item stalled for 30 seconds: 63115, retrying 2016-04-09 19:40:30,380 (7f52677fe700) : DEBUG (tasks:119) - Task: searchAllRecentlyAddedMissing, item stalled for 30 seconds: 63115, retrying 2016-04-09 19:41:00,476 (7f52677fe700) : DEBUG (tasks:119) - Task: searchAllRecentlyAddedMissing, item stalled for 30 seconds: 63115, retrying 2016-04-09 19:41:30,571 (7f52677fe700) : DEBUG (tasks:116) - Task: searchAllRecentlyAddedMissing, item stalled for 4 times: 63115, skipping 2016-04-09 19:41:31,572 (7f52677fe700) : DEBUG (tasks:101) - Task: searchAllRecentlyAddedMissing, triggering refresh for Modern Family S07E15, 2016-03-02 (63114) 2016-04-09 19:42:01,669 (7f52677fe700) : DEBUG (tasks:119) - Task: searchAllRecentlyAddedMissing, item stalled for 30 seconds: 63114, retrying 2016-04-09 19:42:31,762 (7f52677fe700) : DEBUG (tasks:119) - Task: searchAllRecentlyAddedMissing, item stalled for 30 seconds: 63114, retrying 2016-04-09 19:43:01,858 (7f52677fe700) : DEBUG (tasks:119) - Task: searchAllRecentlyAddedMissing, item stalled for 30 seconds: 63114, retrying 2016-04-09 19:43:31,951 (7f52677fe700) : DEBUG (tasks:116) - Task: searchAllRecentlyAddedMissing, item stalled for 4 times: 63114, skipping 2016-04-09 19:43:32,953 (7f52677fe700) : DEBUG (tasks:128) - Task: searchAllRecentlyAddedMissing, done. Failed items: [63294, 63359, 63344, 63336, 63328, 63323, 63309, 63293, 63292, 63276, 63258, 63257, 63256, 63234, 63227, 63226, 63214, 63200, 63199, 63198, 63197, 63196, 63195, 63192, 63191, 63190, 63189, 63188, 63163, 63162, 63154, 63135, 63132, 63115, 63114] 2016-04-09 19:43:32,957 (7f52677fe700) : INFO (datakit:131) - Saved the dictionary file 2016-04-09 19:43:32,960 (7f52677fe700) : INFO (datakit:131) - Saved the dictionary file 2016-04-09 20:43:35,143 (7f52677fe700) : DEBUG (background:79) - Scheduler: Running task searchAllRecentlyAddedMissing 2016-04-09 20:43:35,153 (7f52677fe700) : DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/library/sections/5/all?sort=addedAt%3Adesc&X-Plex-Container-Size=200&X-Plex-Container-Start=0&X-Plex-Token=xgRvxaKuiWs5ifmJsMNk' 2016-04-09 20:43:35,369 (7f52677fe700) : DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/library/sections/2/all?sort=addedAt%3Adesc&X-Plex-Container-Size=200&X-Plex-Container-Start=0&X-Plex-Token=xgRvxaKuiWs5ifmJsMNk' 2016-04-09 20:43:35,399 (7f52677fe700) : DEBUG (items:132) - Skipping section: Musique 2016-04-09 20:43:35,399 (7f52677fe700) : DEBUG (items:132) - Skipping section: Photos 2016-04-09 20:43:35,400 (7f52677fe700) : DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/library/sections/1/all?sort=addedAt%3Adesc&X-Plex-Container-Size=200&type=4&X-Plex-Container-Start=0&X-Plex-Token=xgRvxaKuiWs5ifmJsMNk' 2016-04-09 20:43:35,481 (7f52677fe700) : INFO (missing_subtitles:40) - All subtitles exist for 'The Revenant' 2016-04-09 20:43:35,930 (7f52677fe700) : INFO (missing_subtitles:44) - Subs still missing for 'Grimm S05E11, 2016-03-04': set([<Language [fr]>]) 2016-04-09 20:43:35,946 (7f52677fe700) : DEBUG (tasks:101) - Task: searchAllRecentlyAddedMissing, triggering refresh for 11'09''01 September 11 Fr (63294) 2016-04-09 20:44:50,118 (7f52677fe700) : DEBUG (tasks:119) - Task: searchAllRecentlyAddedMissing, item stalled for 30 seconds: 63294, retrying 2016-04-09 20:45:42,257 (7f52677fe700) : DEBUG (tasks:119) - Task: searchAllRecentlyAddedMissing, item stalled for 30 seconds: 63294, retrying 2016-04-09 20:46:25,741 (7f52677fe700) : DEBUG (tasks:119) - Task: searchAllRecentlyAddedMissing, item stalled for 30 seconds: 63294, retrying 2016-04-09 20:47:09,652 (7f52677fe700) : DEBUG (tasks:116) - Task: searchAllRecentlyAddedMissing, item stalled for 4 times: 63294, skipping 2016-04-09 20:47:10,654 (7f52677fe700) : DEBUG (tasks:101) - Task: searchAllRecentlyAddedMissing, triggering refresh for The Big Bang Theory S09E20, 2016-04-07 (63359) 2016-04-09 20:47:40,750 (7f52677fe700) : DEBUG (tasks:119) - Task: searchAllRecentlyAddedMissing, item stalled for 30 seconds: 63359, retrying 2016-04-09 20:48:10,842 (7f52677fe700) : DEBUG (tasks:119) - Task: searchAllRecentlyAddedMissing, item stalled for 30 seconds: 63359, retrying 2016-04-09 20:48:40,937 (7f52677fe700) : DEBUG (tasks:119) - Task: searchAllRecentlyAddedMissing, item stalled for 30 seconds: 63359, retrying 2016-04-09 20:49:11,031 (7f52677fe700) : DEBUG (tasks:116) - Task: searchAllRecentlyAddedMissing, item stalled for 4 times: 63359, skipping

I have no proxy nor firewall on my computer. Can I provide you more details ? I haven't installed wireshark yet but I'm available for any tests if needed.

Note : I already forced my folders to be accessible in write mode to plex as previous logs warned me about this issue.

pannal commented 8 years ago

Does this happen all the time or just for certain items?

Amaelh commented 8 years ago

This happens all the time on my files. I only got one subtitle downloaded yet for all my library

Amaelh commented 8 years ago

If useful, here is the log of the only correct download :

2016-04-10 14:52:19,311 (7f68a63db700) : DEBUG (tasks:119) - Task: searchAllRecentlyAddedMissing, item stalled for 60 seconds: 63294, retrying 2016-04-10 14:52:52,668 (7f68c67fc700) : DEBUG (tasks:116) - Task: searchAllRecentlyAddedMissing, item stalled for 4 times: 63294, skipping 2016-04-10 14:52:55,672 (7f68c67fc700) : DEBUG (tasks:101) - Task: searchAllRecentlyAddedMissing, triggering refresh for The Revenant (63233) 2016-04-10 14:52:55,738 (7f68a6bdc700) : DEBUG (runtime:717) - Handling request GET /:/plugins/com.plexapp.agents.subzero/messaging/function/X0FnZW50S2l0OlNlYXJjaA/Y2VyZWFsMQoxCmxpc3QKMApyMAo/Y2VyZWFsMQoyCmRpY3QKZGljdAo2CnMyCmZyczQKbGFuZ2IwczYKbWFudWFsYjBzNwpwcmltYXJ5aTAKczcKdmVyc2lvbnIxCnM2Cmt3YXJnc3M1Ck1vdmllczEwCm1lZGlhX3R5cGU1Cm5zOApwYXJlbnRJRHM0Mwpjb20ucGxleGFwcC5hZ2VudHMuaW1kYjovL3R0MTY2MzIwMj9sYW5nPWZyczQKZ3VpZGIxczUKZm9yY2VzMjMKY29tLnBsZXhhcHAuYWdlbnRzLmltZGJzMTMKcHJpbWFyeV9hZ2VudHM1CjYzMjMzczIKaWRyMAo 2016-04-10 14:52:55,756 (7f68a6bdc700) : DEBUG (runtime:814) - Found route matching /:/plugins/com.plexapp.agents.subzero/messaging/function/X0FnZW50S2l0OlNlYXJjaA/Y2VyZWFsMQoxCmxpc3QKMApyMAo/Y2VyZWFsMQoyCmRpY3QKZGljdAo2CnMyCmZyczQKbGFuZ2IwczYKbWFudWFsYjBzNwpwcmltYXJ5aTAKczcKdmVyc2lvbnIxCnM2Cmt3YXJnc3M1Ck1vdmllczEwCm1lZGlhX3R5cGU1Cm5zOApwYXJlbnRJRHM0Mwpjb20ucGxleGFwcC5hZ2VudHMuaW1kYjovL3R0MTY2MzIwMj9sYW5nPWZyczQKZ3VpZGIxczUKZm9yY2VzMjMKY29tLnBsZXhhcHAuYWdlbnRzLmltZGJzMTMKcHJpbWFyeV9hZ2VudHM1CjYzMjMzczIKaWRyMAo 2016-04-10 14:52:55,756 (7f68a6bdc700) : INFO (agentkit:946) - Searching for matches for {'id': '63233', 'guid': 'com.plexapp.agents.imdb://tt1663202?lang=fr', 'force': True, 'primaryagent': 'com.plexapp.agents.imdb', 'parentID': None} 2016-04-10 14:52:55,756 (7f68a6bdc700) : DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/library/metadata/63233/tree' 2016-04-10 14:52:55,762 (7f68a6bdc700) : DEBUG (accessor:68) - Creating a new read-only model access point for provider com.plexapp.agents.imdb in namespace 'metadata' 2016-04-10 14:52:55,767 (7f68a6bdc700) : DEBUG (model:32) - Loading model with GUID com.plexapp.agents.imdb://tt1663202?lang=fr 2016-04-10 14:52:55,769 (7f68a6bdc700) : DEBUG (model:234) - Deserializing from /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Metadata/Movies/5/b96cc429b3ed4505de2f9a685b9e0aaaf9a0323.bundle/Contents/com.plexapp.agents.imdb/Info.xml 2016-04-10 14:52:55,775 (7f68a6bdc700) : DEBUG (init:290) - Sub-Zero 1.3.27.491, movies search 2016-04-10 14:52:55,776 (7f68a6bdc700) : DEBUG (runtime:924) - Response: [200] str, 600 bytes 2016-04-10 14:52:55,782 (7f68a6bdc700) : DEBUG (runtime:717) - Handling request GET /:/plugins/com.plexapp.agents.subzero/messaging/function/X0FnZW50S2l0OlVwZGF0ZU1ldGFkYXRh/Y2VyZWFsMQoxCmxpc3QKMApyMAo/Y2VyZWFsMQoxCmRpY3QKMTAKczIKZnJzNApsYW5nYjFzNQpmb3JjZWIwczgKcGVyaW9kaWNzNQo2MzIzM3M0CmRiaWRpMApzNwp2ZXJzaW9ubnMxMApwYXJlbnRHVUlEbnM4CnBhcmVudElEczUKTW92aWVzMTAKbWVkaWFfdHlwZXM0Mwpjb20ucGxleGFwcC5hZ2VudHMuaW1kYjovL3R0MTY2MzIwMj9sYW5nPWZyczQKZ3VpZHM0Cm51bGxzMgppZHIwCg 2016-04-10 14:52:55,782 (7f68a6bdc700) : DEBUG (runtime:814) - Found route matching /:/plugins/com.plexapp.agents.subzero/messaging/function/X0FnZW50S2l0OlVwZGF0ZU1ldGFkYXRh/Y2VyZWFsMQoxCmxpc3QKMApyMAo_/Y2VyZWFsMQoxCmRpY3QKMTAKczIKZnJzNApsYW5nYjFzNQpmb3JjZWIwczgKcGVyaW9kaWNzNQo2MzIzM3M0CmRiaWRpMApzNwp2ZXJzaW9ubnMxMApwYXJlbnRHVUlEbnM4CnBhcmVudElEczUKTW92aWVzMTAKbWVkaWFfdHlwZXM0Mwpjb20ucGxleGFwcC5hZ2VudHMuaW1kYjovL3R0MTY2MzIwMj9sYW5nPWZyczQKZ3VpZHM0Cm51bGxzMgppZHIwCg__ 2016-04-10 14:52:55,783 (7f68a6bdc700) : DEBUG (model:32) - Loading model with GUID com.plexapp.agents.imdb://tt1663202?lang=fr 2016-04-10 14:52:55,784 (7f68a6bdc700) : DEBUG (model:234) - Deserializing from /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Metadata/Movies/5/b96cc429b3ed4505de2f9a685b9e0aaaf9a0323.bundle/Contents/com.plexapp.agents.subzero/Info.xml 2016-04-10 14:52:55,784 (7f68a6bdc700) : DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/library/metadata/63233/tree' 2016-04-10 14:52:55,789 (7f68a6bdc700) : DEBUG (init:294) - Sub-Zero 1.3.27.491, movies update called 2016-04-10 14:52:55,790 (7f68a6bdc700) : DEBUG (init:170) - Scanning video: /home/amael/Téléchargements/Films/The.Revenant.2015.VOSTFR.FANSUB.DVDSCR.XviD.AC3-ZT.www.CpasBien.io.avi, subtitles=False, embedded_subtitles=False 2016-04-10 14:52:55,791 (7f68a6bdc700) : INFO (logger:38) - subliminal_patch.patch_video: Scanning video (hints: {'type': 'movie', 'expected_title': ['The Revenant']}) 'Films/The.Revenant.2015.VOSTFR.FANSUB.DVDSCR.XviD.AC3-ZT.www.CpasBien.io.avi' 2016-04-10 14:52:55,793 (7f68a6bdc700) : DEBUG (logger:28) - guessit.matcher: Property found: type=movie (None) (confidence=1.00) 2016-04-10 14:52:55,797 (7f68a6bdc700) : DEBUG (logger:28) - guessit.matcher: Property found: mimetype=video/x-msvideo (None) (confidence=1.00) 2016-04-10 14:52:55,798 (7f68a6bdc700) : DEBUG (logger:28) - guessit.matcher: Property found: container=avi (None) (confidence=1.00) 2016-04-10 14:52:55,915 (7f68a6bdc700) : DEBUG (logger:28) - guessit.matcher: Found match tree: 00000 111111111111111111111111111111111111111111111111111111111111111111 222 00000 000000000000000000000000000000000000000000000000000000000000000000 000 000000000000000000000000000000000000000000000000000111111111111111 000 000000000000000000000000000000000001112222222222222 00000000000000000000000000000000111 0111122222222 00000000000000000011111122222222 01112222 000000000000011112 0112 Films/___.__.FANSUB.__.._-_.____._ tttttttttttttyyyy xxxxxx fffooo vvvv aaa rr wwwwwwwwwwwwwww ccc Films/The.Revenant.2015.VOSTFR.FANSUB.DVDSCR.XviD.AC3-ZT.www.CpasBien.io.avi 2016-04-10 14:52:55,915 (7f68a6bdc700) : DEBUG (logger:28) - guessit.guess: Updating matching property 'container' with confidence 1.00 2016-04-10 14:52:55,916 (7f68a6bdc700) : DEBUG (logger:28) - guessit.matchtree: Final result: { [0.60] "website": "www.CpasBien.io", [1.00] "mimetype": "video/x-msvideo", [0.60] "videoCodec": "XviD", [1.00] "container": "avi", [0.60] "format": "DVD", [0.48] "subtitleLanguage": [ "fr" ], [0.36] "title": "The Revenant", [0.60] "releaseGroup": "ZT", [0.60] "other": [ "Screener" ], [0.60] "year": 2015, [1.00] "type": "movie", [0.60] "audioCodec": "AC3" } 2016-04-10 14:52:55,917 (7f68a6bdc700) : DEBUG (logger:28) - subliminal_patch.patch_video: Size is 2219216233 2016-04-10 14:52:55,932 (7f68a6bdc700) : DEBUG (logger:28) - subliminal_patch.patch_video: Computed hashes {'opensubtitles': u'be806a5a75d87aea', 'thesubdb': 'b7c710366e15ef071a99954d9a8688cc'} 2016-04-10 14:52:55,932 (7f68a6bdc700) : DEBUG (init:203) - Download best subtitles using settings: min_score: 23, hearing_impaired: don't prefer 2016-04-10 14:52:55,932 (7f68a6bdc700) : INFO (logger:38) - subliminal.api: Downloading best subtitles for <Movie [u'The Revenant', 2015]> 2016-04-10 14:52:55,933 (7f68a6bdc700) : INFO (logger:38) - subliminal_patch.patch_provider_pool: Skipping provider 'addic7ed': not a valid video 2016-04-10 14:52:55,933 (7f68a6bdc700) : INFO (logger:38) - subliminal_patch.patch_provider_pool: Skipping provider 'tvsubtitles': not a valid video 2016-04-10 14:52:55,934 (7f68a6bdc700) : INFO (logger:38) - subliminal.api: Downloaded 0 subtitle(s) 2016-04-10 14:52:55,934 (7f68a6bdc700) : DEBUG (logger:28) - subliminal.api: Terminating initialized providers 2016-04-10 14:52:55,934 (7f68a6bdc700) : DEBUG (init:212) - Using filesystem as subtitle storage 2016-04-10 14:52:55,936 (7f68a6bdc700) : INFO (datakit:131) - Saved the dictionary file 2016-04-10 14:52:55,950 (7f68a6bdc700) : INFO (localmedia:72) - Looking for subtitle media in 1 paths with 15 media files. 2016-04-10 14:52:55,950 (7f68a6bdc700) : INFO (localmedia:73) - Paths: /home/amael/Téléchargements/Films 2016-04-10 14:52:55,951 (7f68a6bdc700) : INFO (subtitlehelpers:131) - Found subtitle file: /home/amael/Téléchargements/Films/The.Revenant.2015.VOSTFR.FANSUB.DVDSCR.XviD.AC3-ZT.www.CpasBien.io.fr.srt language: fr codec: srt format: srt 2016-04-10 14:52:55,952 (7f68a6bdc700) : INFO (subtitlehelpers:131) - Found subtitle file: /home/amael/Téléchargements/Films/The.Revenant.2015.VOSTFR.FANSUB.DVDSCR.XviD.AC3-ZT.www.CpasBien.io.en.srt language: en codec: srt format: srt 2016-04-10 14:52:55,953 (7f68a6bdc700) : DEBUG (background:92) - Scheduler: Sending signal updated_metadata to task searchAllRecentlyAddedMissing (('63233',), {}) 2016-04-10 14:52:55,953 (7f68a6bdc700) : DEBUG (background:95) - Scheduler: Signal accepted by searchAllRecentlyAddedMissing 2016-04-10 14:52:55,955 (7f68a6bdc700) : DEBUG (model:229) - Serializing to /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Metadata/Movies/5/b96cc429b3ed4505de2f9a685b9e0aaaf9a0323.bundle/Contents/com.plexapp.agents.subzero/Info.xml 2016-04-10 14:52:55,955 (7f68a6bdc700) : DEBUG (runtime:924) - Response: [200] str, 16 bytes 2016-04-10 14:53:00,792 (7f68a73dd700) : INFO (datakit:131) - Saved the dictionary file 2016-04-10 14:53:23,188 (7f68a63db700) : DEBUG (tasks:116) - Task: searchAllRecentlyAddedMissing, item stalled for 4 times: 63294, skipping 2016-04-10 14:53:26,192 (7f68a63db700) : DEBUG (tasks:101) - Task: searchAllRecentlyAddedMissing, triggering refresh for The Revenant (63233) 2016-04-10 14:53:26,214 (7f68a63db700) : DEBUG (tasks:108) - Task: searchAllRecentlyAddedMissing, item 63233 done 2016-04-10 14:53:26,264 (7f68c5ffb700) : DEBUG (runtime:717) - Handling request GET /:/plugins/com.plexapp.agents.subzero/messaging/function/X0FnZW50S2l0OlNlYXJjaA/Y2VyZWFsMQoxCmxpc3QKMApyMAo/Y2VyZWFsMQoyCmRpY3QKZGljdAo2CnMyCmZyczQKbGFuZ2IwczYKbWFudWFsYjBzNwpwcmltYXJ5aTAKczcKdmVyc2lvbnIxCnM2Cmt3YXJnc3M1Ck1vdmllczEwCm1lZGlhX3R5cGU1Cm5zOApwYXJlbnRJRHM0Mwpjb20ucGxleGFwcC5hZ2VudHMuaW1kYjovL3R0MTY2MzIwMj9sYW5nPWZyczQKZ3VpZGIxczUKZm9yY2VzMjMKY29tLnBsZXhhcHAuYWdlbnRzLmltZGJzMTMKcHJpbWFyeV9hZ2VudHM1CjYzMjMzczIKaWRyMAo 2016-04-10 14:53:26,265 (7f68c5ffb700) : DEBUG (runtime:814) - Found route matching /:/plugins/com.plexapp.agents.subzero/messaging/function/X0FnZW50S2l0OlNlYXJjaA/Y2VyZWFsMQoxCmxpc3QKMApyMAo/Y2VyZWFsMQoyCmRpY3QKZGljdAo2CnMyCmZyczQKbGFuZ2IwczYKbWFudWFsYjBzNwpwcmltYXJ5aTAKczcKdmVyc2lvbnIxCnM2Cmt3YXJnc3M1Ck1vdmllczEwCm1lZGlhX3R5cGU1Cm5zOApwYXJlbnRJRHM0Mwpjb20ucGxleGFwcC5hZ2VudHMuaW1kYjovL3R0MTY2MzIwMj9sYW5nPWZyczQKZ3VpZGIxczUKZm9yY2VzMjMKY29tLnBsZXhhcHAuYWdlbnRzLmltZGJzMTMKcHJpbWFyeV9hZ2VudHM1CjYzMjMzczIKaWRyMAo 2016-04-10 14:53:26,266 (7f68c5ffb700) : INFO (agentkit:946) - Searching for matches for {'id': '63233', 'guid': 'com.plexapp.agents.imdb://tt1663202?lang=fr', 'force': True, 'primaryagent': 'com.plexapp.agents.imdb', 'parentID': None} 2016-04-10 14:53:26,267 (7f68c5ffb700) : DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/library/metadata/63233/tree' 2016-04-10 14:53:26,274 (7f68c5ffb700) : DEBUG (model:32) - Loading model with GUID com.plexapp.agents.imdb://tt1663202?lang=fr 2016-04-10 14:53:26,275 (7f68c5ffb700) : DEBUG (model:234) - Deserializing from /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Metadata/Movies/5/b96cc429b3ed4505de2f9a685b9e0aaaf9a0323.bundle/Contents/com.plexapp.agents.imdb/Info.xml 2016-04-10 14:53:26,278 (7f68c5ffb700) : DEBUG (init:290) - Sub-Zero 1.3.27.491, movies search 2016-04-10 14:53:26,279 (7f68c5ffb700) : DEBUG (runtime:924) - Response: [200] str, 600 bytes 2016-04-10 14:53:26,286 (7f68c5ffb700) : DEBUG (runtime:717) - Handling request GET /:/plugins/com.plexapp.agents.subzero/messaging/function/X0FnZW50S2l0OlVwZGF0ZU1ldGFkYXRh/Y2VyZWFsMQoxCmxpc3QKMApyMAo/Y2VyZWFsMQoxCmRpY3QKMTAKczIKZnJzNApsYW5nYjFzNQpmb3JjZWIwczgKcGVyaW9kaWNzNQo2MzIzM3M0CmRiaWRpMApzNwp2ZXJzaW9ubnMxMApwYXJlbnRHVUlEbnM4CnBhcmVudElEczUKTW92aWVzMTAKbWVkaWFfdHlwZXM0Mwpjb20ucGxleGFwcC5hZ2VudHMuaW1kYjovL3R0MTY2MzIwMj9sYW5nPWZyczQKZ3VpZHM0Cm51bGxzMgppZHIwCg 2016-04-10 14:53:26,287 (7f68c5ffb700) : DEBUG (runtime:814) - Found route matching /:/plugins/com.plexapp.agents.subzero/messaging/function/X0FnZW50S2l0OlVwZGF0ZU1ldGFkYXRh/Y2VyZWFsMQoxCmxpc3QKMApyMAo_/Y2VyZWFsMQoxCmRpY3QKMTAKczIKZnJzNApsYW5nYjFzNQpmb3JjZWIwczgKcGVyaW9kaWNzNQo2MzIzM3M0CmRiaWRpMApzNwp2ZXJzaW9ubnMxMApwYXJlbnRHVUlEbnM4CnBhcmVudElEczUKTW92aWVzMTAKbWVkaWFfdHlwZXM0Mwpjb20ucGxleGFwcC5hZ2VudHMuaW1kYjovL3R0MTY2MzIwMj9sYW5nPWZyczQKZ3VpZHM0Cm51bGxzMgppZHIwCg 2016-04-10 14:53:26,288 (7f68c5ffb700) : DEBUG (model:32) - Loading model with GUID com.plexapp.agents.imdb://tt1663202?lang=fr 2016-04-10 14:53:26,289 (7f68c5ffb700) : DEBUG (model:234) - Deserializing from /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Metadata/Movies/5/b96cc429b3ed4505de2f9a685b9e0aaaf9a0323.bundle/Contents/com.plexapp.agents.subzero/Info.xml 2016-04-10 14:53:26,290 (7f68c5ffb700) : DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/library/metadata/63233/tree' 2016-04-10 14:53:26,297 (7f68c5ffb700) : DEBUG (init:294) - Sub-Zero 1.3.27.491, movies update called 2016-04-10 14:53:26,299 (7f68c5ffb700) : DEBUG (init:170) - Scanning video: /home/amael/Téléchargements/Films/The.Revenant.2015.VOSTFR.FANSUB.DVDSCR.XviD.AC3-ZT.www.CpasBien.io.avi, subtitles=False, embedded_subtitles=False 2016-04-10 14:53:26,299 (7f68c5ffb700) : INFO (logger:38) - subliminal_patch.patch_video: Scanning video (hints: {'type': 'movie', 'expectedtitle': ['The Revenant']}) 'Films/The.Revenant.2015.VOSTFR.FANSUB.DVDSCR.XviD.AC3-ZT.www.CpasBien.io.avi' 2016-04-10 14:53:26,301 (7f68c5ffb700) : DEBUG (logger:28) - guessit.matcher: Property found: type=movie (None) (confidence=1.00) 2016-04-10 14:53:26,302 (7f68c5ffb700) : DEBUG (logger:28) - guessit.matcher: Property found: mimetype=video/x-msvideo (None) (confidence=1.00) 2016-04-10 14:53:26,302 (7f68c5ffb700) : DEBUG (logger:28) - guessit.matcher: Property found: container=avi (None) (confidence=1.00) 2016-04-10 14:53:26,326 (7f68c5ffb700) : DEBUG (logger:28) - guessit.matcher: Found match tree: 00000 111111111111111111111111111111111111111111111111111111111111111111 222 00000 000000000000000000000000000000000000000000000000000000000000000000 000 000000000000000000000000000000000000000000000000000111111111111111 000 000000000000000000000000000000000001112222222222222 00000000000000000000000000000000111 0111122222222 00000000000000000011111122222222 01112222 000000000000011112 0112 Films/____.__.FANSUB.__.___.-.___._ tttttttttttttyyyy xxxxxx fffooo vvvv aaa rr wwwwwwwwwwwwwww ccc Films/The.Revenant.2015.VOSTFR.FANSUB.DVDSCR.XviD.AC3-ZT.www.CpasBien.io.avi 2016-04-10 14:53:26,327 (7f68c5ffb700) : DEBUG (logger:28) - guessit.guess: Updating matching property 'container' with confidence 1.00 2016-04-10 14:53:26,328 (7f68c5ffb700) : DEBUG (logger:28) - guessit.matchtree: Final result: { [0.60] "website": "www.CpasBien.io", [1.00] "mimetype": "video/x-msvideo", [0.60] "videoCodec": "XviD", [1.00] "container": "avi", [0.60] "format": "DVD", [0.48] "subtitleLanguage": [ "fr" ], [0.36] "title": "The Revenant", [0.60] "releaseGroup": "ZT", [0.60] "other": [ "Screener" ], [0.60] "year": 2015, [1.00] "type": "movie", [0.60] "audioCodec": "AC3" } 2016-04-10 14:53:26,329 (7f68c5ffb700) : DEBUG (logger:28) - subliminal_patch.patch_video: Size is 2219216233 2016-04-10 14:53:26,343 (7f68c5ffb700) : DEBUG (logger:28) - subliminal_patch.patch_video: Computed hashes {'opensubtitles': u'be806a5a75d87aea', 'thesubdb': 'b7c710366e15ef071a99954d9a8688cc'} 2016-04-10 14:53:26,343 (7f68c5ffb700) : DEBUG (init:203) - Download best subtitles using settings: min_score: 23, hearing_impaired: don't prefer 2016-04-10 14:53:26,344 (7f68c5ffb700) : INFO (logger:38) - subliminal.api: Downloading best subtitles for <Movie [u'The Revenant', 2015]> 2016-04-10 14:53:26,344 (7f68c5ffb700) : INFO (logger:38) - subliminal_patch.patch_provider_pool: Skipping provider 'addic7ed': not a valid video 2016-04-10 14:53:26,345 (7f68c5ffb700) : INFO (logger:38) - subliminal_patch.patch_provider_pool: Skipping provider 'tvsubtitles': not a valid video 2016-04-10 14:53:26,345 (7f68c5ffb700) : INFO (logger:38) - subliminal.api: Downloaded 0 subtitle(s) 2016-04-10 14:53:26,345 (7f68c5ffb700) : DEBUG (logger:28) - subliminal.api: Terminating initialized providers 2016-04-10 14:53:26,345 (7f68c5ffb700) : DEBUG (init:212) - Using filesystem as subtitle storage 2016-04-10 14:53:26,347 (7f68c5ffb700) : INFO (datakit:131) - Saved the dictionary file 2016-04-10 14:53:26,348 (7f68c5ffb700) : INFO (localmedia:72) - Looking for subtitle media in 1 paths with 15 media files. 2016-04-10 14:53:26,348 (7f68c5ffb700) : INFO (localmedia:73) - Paths: /home/amael/Téléchargements/Films 2016-04-10 14:53:26,349 (7f68c5ffb700) : INFO (subtitlehelpers:131) - Found subtitle file: /home/amael/Téléchargements/Films/The.Revenant.2015.VOSTFR.FANSUB.DVDSCR.XviD.AC3-ZT.www.CpasBien.io.fr.srt language: fr codec: srt format: srt 2016-04-10 14:53:26,350 (7f68c5ffb700) : INFO (subtitlehelpers:131) - Found subtitle file: /home/amael/Téléchargements/Films/The.Revenant.2015.VOSTFR.FANSUB.DVDSCR.XviD.AC3-ZT.www.CpasBien.io.en.srt language: en codec: srt format: srt 2016-04-10 14:53:26,351 (7f68c5ffb700) : DEBUG (background:92) - Scheduler: Sending signal updated_metadata to task searchAllRecentlyAddedMissing (('63233',), {}) 2016-04-10 14:53:26,352 (7f68c5ffb700) : DEBUG (background:95) - Scheduler: Signal accepted by searchAllRecentlyAddedMissing 2016-04-10 14:53:26,353 (7f68c5ffb700) : DEBUG (model:229) - Serializing to /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Metadata/Movies/5/b96cc429b3ed4505de2f9a685b9e0aaaf9a0323.bundle/Contents/com.plexapp.agents.subzero/Info.xml 2016-04-10 14:53:26,354 (7f68c5ffb700) : DEBUG (runtime:924) - Response: [200] str, 16 bytes 2016-04-10 14:53:29,215 (7f68a63db700) : DEBUG (tasks:101) - Task: searchAllRecentlyAddedMissing, triggering refresh for Z Nation S01E01, Chiens et chats (63375) 2016-04-10 14:53:31,301 (7f68a73dd700) : INFO (datakit:131) - Saved the dictionary file 2016-04-10 14:53:55,739 (7f68c67fc700) : DEBUG (tasks:119) - Task: searchAllRecentlyAddedMissing, item stalled for 60 seconds: 63233, retrying 2016-04-10 14:53:55,813 (7f68a6bdc700) : DEBUG (runtime:717) - Handling request GET /:/plugins/com.plexapp.agents.subzero/messaging/function/X0FnZW50S2l0OlNlYXJjaA/Y2VyZWFsMQoxCmxpc3QKMApyMAo/Y2VyZWFsMQoyCmRpY3QKZGljdAo2CnMyCmZyczQKbGFuZ2IwczYKbWFudWFsYjBzNwpwcmltYXJ5aTAKczcKdmVyc2lvbnIxCnM2Cmt3YXJnc3M1Ck1vdmllczEwCm1lZGlhX3R5cGU1Cm5zOApwYXJlbnRJRHM0Mwpjb20ucGxleGFwcC5hZ2VudHMuaW1kYjovL3R0MTY2MzIwMj9sYW5nPWZyczQKZ3VpZGIxczUKZm9yY2VzMjMKY29tLnBsZXhhcHAuYWdlbnRzLmltZGJzMTMKcHJpbWFyeV9hZ2VudHM1CjYzMjMzczIKaWRyMAo 2016-04-10 14:53:55,815 (7f68a6bdc700) : DEBUG (runtime:814) - Found route matching /:/plugins/com.plexapp.agents.subzero/messaging/function/X0FnZW50S2l0OlNlYXJjaA/Y2VyZWFsMQoxCmxpc3QKMApyMAo/Y2VyZWFsMQoyCmRpY3QKZGljdAo2CnMyCmZyczQKbGFuZ2IwczYKbWFudWFsYjBzNwpwcmltYXJ5aTAKczcKdmVyc2lvbnIxCnM2Cmt3YXJnc3M1Ck1vdmllczEwCm1lZGlhX3R5cGU1Cm5zOApwYXJlbnRJRHM0Mwpjb20ucGxleGFwcC5hZ2VudHMuaW1kYjovL3R0MTY2MzIwMj9sYW5nPWZyczQKZ3VpZGIxczUKZm9yY2VzMjMKY29tLnBsZXhhcHAuYWdlbnRzLmltZGJzMTMKcHJpbWFyeV9hZ2VudHM1CjYzMjMzczIKaWRyMAo 2016-04-10 14:53:55,815 (7f68a6bdc700) : INFO (agentkit:946) - Searching for matches for {'id': '63233', 'guid': 'com.plexapp.agents.imdb://tt1663202?lang=fr', 'force': True, 'primaryagent': 'com.plexapp.agents.imdb', 'parentID': None} 2016-04-10 14:53:55,816 (7f68a6bdc700) : DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/library/metadata/63233/tree' 2016-04-10 14:53:55,824 (7f68a6bdc700) : DEBUG (model:32) - Loading model with GUID com.plexapp.agents.imdb://tt1663202?lang=fr 2016-04-10 14:53:55,824 (7f68a6bdc700) : DEBUG (model:234) - Deserializing from /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Metadata/Movies/5/b96cc429b3ed4505de2f9a685b9e0aaaf9a0323.bundle/Contents/com.plexapp.agents.imdb/Info.xml 2016-04-10 14:53:55,827 (7f68a6bdc700) : DEBUG (init:290) - Sub-Zero 1.3.27.491, movies search 2016-04-10 14:53:55,828 (7f68a6bdc700) : DEBUG (runtime:924) - Response: [200] str, 600 bytes 2016-04-10 14:53:55,834 (7f68a6bdc700) : DEBUG (runtime:717) - Handling request GET /:/plugins/com.plexapp.agents.subzero/messaging/function/X0FnZW50S2l0OlVwZGF0ZU1ldGFkYXRh/Y2VyZWFsMQoxCmxpc3QKMApyMAo/Y2VyZWFsMQoxCmRpY3QKMTAKczIKZnJzNApsYW5nYjFzNQpmb3JjZWIwczgKcGVyaW9kaWNzNQo2MzIzM3M0CmRiaWRpMApzNwp2ZXJzaW9ubnMxMApwYXJlbnRHVUlEbnM4CnBhcmVudElEczUKTW92aWVzMTAKbWVkaWFfdHlwZXM0Mwpjb20ucGxleGFwcC5hZ2VudHMuaW1kYjovL3R0MTY2MzIwMj9sYW5nPWZyczQKZ3VpZHM0Cm51bGxzMgppZHIwCg 2016-04-10 14:53:55,834 (7f68a6bdc700) : DEBUG (runtime:814) - Found route matching /:/plugins/com.plexapp.agents.subzero/messaging/function/X0FnZW50S2l0OlVwZGF0ZU1ldGFkYXRh/Y2VyZWFsMQoxCmxpc3QKMApyMAo_/Y2VyZWFsMQoxCmRpY3QKMTAKczIKZnJzNApsYW5nYjFzNQpmb3JjZWIwczgKcGVyaW9kaWNzNQo2MzIzM3M0CmRiaWRpMApzNwp2ZXJzaW9ubnMxMApwYXJlbnRHVUlEbnM4CnBhcmVudElEczUKTW92aWVzMTAKbWVkaWFfdHlwZXM0Mwpjb20ucGxleGFwcC5hZ2VudHMuaW1kYjovL3R0MTY2MzIwMj9sYW5nPWZyczQKZ3VpZHM0Cm51bGxzMgppZHIwCg__ 2016-04-10 14:53:55,835 (7f68a6bdc700) : DEBUG (model:32) - Loading model with GUID com.plexapp.agents.imdb://tt1663202?lang=fr 2016-04-10 14:53:55,836 (7f68a6bdc700) : DEBUG (model:234) - Deserializing from /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Metadata/Movies/5/b96cc429b3ed4505de2f9a685b9e0aaaf9a0323.bundle/Contents/com.plexapp.agents.subzero/Info.xml 2016-04-10 14:53:55,836 (7f68a6bdc700) : DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/library/metadata/63233/tree' 2016-04-10 14:53:55,842 (7f68a6bdc700) : DEBUG (init:294) - Sub-Zero 1.3.27.491, movies update called 2016-04-10 14:53:55,844 (7f68a6bdc700) : DEBUG (init:170) - Scanning video: /home/amael/Téléchargements/Films/The.Revenant.2015.VOSTFR.FANSUB.DVDSCR.XviD.AC3-ZT.www.CpasBien.io.avi, subtitles=False, embedded_subtitles=False 2016-04-10 14:53:55,844 (7f68a6bdc700) : INFO (logger:38) - subliminal_patch.patch_video: Scanning video (hints: {'type': 'movie', 'expected_title': ['The Revenant']}) 'Films/The.Revenant.2015.VOSTFR.FANSUB.DVDSCR.XviD.AC3-ZT.www.CpasBien.io.avi' 2016-04-10 14:53:55,846 (7f68a6bdc700) : DEBUG (logger:28) - guessit.matcher: Property found: type=movie (None) (confidence=1.00) 2016-04-10 14:53:55,847 (7f68a6bdc700) : DEBUG (logger:28) - guessit.matcher: Property found: mimetype=video/x-msvideo (None) (confidence=1.00) 2016-04-10 14:53:55,847 (7f68a6bdc700) : DEBUG (logger:28) - guessit.matcher: Property found: container=avi (None) (confidence=1.00) 2016-04-10 14:53:55,867 (7f68a6bdc700) : DEBUG (logger:28) - guessit.matcher: Found match tree: 00000 111111111111111111111111111111111111111111111111111111111111111111 222 00000 000000000000000000000000000000000000000000000000000000000000000000 000 000000000000000000000000000000000000000000000000000111111111111111 000 000000000000000000000000000000000001112222222222222 00000000000000000000000000000000111 0111122222222 00000000000000000011111122222222 01112222 000000000000011112 0112 Films/___.__.FANSUB.__.._-_.____.___ tttttttttttttyyyy xxxxxx fffooo vvvv aaa rr wwwwwwwwwwwwwww ccc Films/The.Revenant.2015.VOSTFR.FANSUB.DVDSCR.XviD.AC3-ZT.www.CpasBien.io.avi 2016-04-10 14:53:55,868 (7f68a6bdc700) : DEBUG (logger:28) - guessit.guess: Updating matching property 'container' with confidence 1.00 2016-04-10 14:53:55,868 (7f68a6bdc700) : DEBUG (logger:28) - guessit.matchtree: Final result: { [0.60] "website": "www.CpasBien.io", [1.00] "mimetype": "video/x-msvideo", [0.60] "videoCodec": "XviD", [1.00] "container": "avi", [0.60] "format": "DVD", [0.48] "subtitleLanguage": [ "fr" ], [0.36] "title": "The Revenant", [0.60] "releaseGroup": "ZT", [0.60] "other": [ "Screener" ], [0.60] "year": 2015, [1.00] "type": "movie", [0.60] "audioCodec": "AC3" } 2016-04-10 14:53:55,869 (7f68a6bdc700) : DEBUG (logger:28) - subliminal_patch.patch_video: Size is 2219216233 2016-04-10 14:53:55,884 (7f68a6bdc700) : DEBUG (logger:28) - subliminal_patch.patch_video: Computed hashes {'opensubtitles': u'be806a5a75d87aea', 'thesubdb': 'b7c710366e15ef071a99954d9a8688cc'} 2016-04-10 14:53:55,884 (7f68a6bdc700) : DEBUG (init:203) - Download best subtitles using settings: min_score: 23, hearing_impaired: don't prefer 2016-04-10 14:53:55,884 (7f68a6bdc700) : INFO (logger:38) - subliminal.api: Downloading best subtitles for <Movie [u'The Revenant', 2015]> 2016-04-10 14:53:55,885 (7f68a6bdc700) : INFO (logger:38) - subliminal_patch.patch_provider_pool: Skipping provider 'addic7ed': not a valid video 2016-04-10 14:53:55,885 (7f68a6bdc700) : INFO (logger:38) - subliminal_patch.patch_provider_pool: Skipping provider 'tvsubtitles': not a valid video 2016-04-10 14:53:55,885 (7f68a6bdc700) : INFO (logger:38) - subliminal.api: Downloaded 0 subtitle(s) 2016-04-10 14:53:55,886 (7f68a6bdc700) : DEBUG (logger:28) - subliminal.api: Terminating initialized providers 2016-04-10 14:53:55,886 (7f68a6bdc700) : DEBUG (init:212) - Using filesystem as subtitle storage 2016-04-10 14:53:55,888 (7f68a6bdc700) : INFO (datakit:131) - Saved the dictionary file 2016-04-10 14:53:55,889 (7f68a6bdc700) : INFO (localmedia:72) - Looking for subtitle media in 1 paths with 15 media files. 2016-04-10 14:53:55,889 (7f68a6bdc700) : INFO (localmedia:73) - Paths: /home/amael/Téléchargements/Films 2016-04-10 14:53:55,889 (7f68a6bdc700) : INFO (subtitlehelpers:131) - Found subtitle file: /home/amael/Téléchargements/Films/The.Revenant.2015.VOSTFR.FANSUB.DVDSCR.XviD.AC3-ZT.www.CpasBien.io.fr.srt language: fr codec: srt format: srt 2016-04-10 14:53:55,890 (7f68a6bdc700) : INFO (subtitlehelpers:131) - Found subtitle file: /home/amael/Téléchargements/Films/The.Revenant.2015.VOSTFR.FANSUB.DVDSCR.XviD.AC3-ZT.www.CpasBien.io.en.srt language: en codec: srt format: srt 2016-04-10 14:53:55,892 (7f68a6bdc700) : DEBUG (background:92) - Scheduler: Sending signal updated_metadata to task searchAllRecentlyAddedMissing (('63233',), {}) 2016-04-10 14:53:55,892 (7f68a6bdc700) : DEBUG (background:95) - Scheduler: Signal accepted by searchAllRecentlyAddedMissing 2016-04-10 14:53:55,893 (7f68a6bdc700) : DEBUG (model:229) - Serializing to /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Metadata/Movies/5/b96cc429b3ed4505de2f9a685b9e0aaaf9a0323.bundle/Contents/com.plexapp.agents.subzero/Info.xml 2016-04-10 14:53:55,894 (7f68a6bdc700) : DEBUG (runtime:924) - Response: [200] str, 16 bytes 2016-04-10 14:54:00,844 (7f68a73dd700) : INFO (datakit:131) - Saved the dictionary file

2016-04-10 14:54:29,286 (7f68a63db700) : DEBUG (tasks:119) - Task: searchAllRecentlyAddedMissing, item stalled for 60 seconds: 63375, retrying 2016-04-10 14:54:58,815 (7f68c67fc700) : DEBUG (tasks:119) - Task: searchAllRecentlyAddedMissing, item stalled for 60 seconds: 63233, retrying 2016-04-10 14:54:58,894 (7f68c5ffb700) : DEBUG (runtime:717) - Handling request GET /:/plugins/com.plexapp.agents.subzero/messaging/function/X0FnZW50S2l0OlNlYXJjaA/Y2VyZWFsMQoxCmxpc3QKMApyMAo/Y2VyZWFsMQoyCmRpY3QKZGljdAo2CnMyCmZyczQKbGFuZ2IwczYKbWFudWFsYjBzNwpwcmltYXJ5aTAKczcKdmVyc2lvbnIxCnM2Cmt3YXJnc3M1Ck1vdmllczEwCm1lZGlhX3R5cGU1Cm5zOApwYXJlbnRJRHM0Mwpjb20ucGxleGFwcC5hZ2VudHMuaW1kYjovL3R0MTY2MzIwMj9sYW5nPWZyczQKZ3VpZGIxczUKZm9yY2VzMjMKY29tLnBsZXhhcHAuYWdlbnRzLmltZGJzMTMKcHJpbWFyeV9hZ2VudHM1CjYzMjMzczIKaWRyMAo 2016-04-10 14:54:58,896 (7f68c5ffb700) : DEBUG (runtime:814) - Found route matching /:/plugins/com.plexapp.agents.subzero/messaging/function/X0FnZW50S2l0OlNlYXJjaA/Y2VyZWFsMQoxCmxpc3QKMApyMAo/Y2VyZWFsMQoyCmRpY3QKZGljdAo2CnMyCmZyczQKbGFuZ2IwczYKbWFudWFsYjBzNwpwcmltYXJ5aTAKczcKdmVyc2lvbnIxCnM2Cmt3YXJnc3M1Ck1vdmllczEwCm1lZGlhX3R5cGU1Cm5zOApwYXJlbnRJRHM0Mwpjb20ucGxleGFwcC5hZ2VudHMuaW1kYjovL3R0MTY2MzIwMj9sYW5nPWZyczQKZ3VpZGIxczUKZm9yY2VzMjMKY29tLnBsZXhhcHAuYWdlbnRzLmltZGJzMTMKcHJpbWFyeV9hZ2VudHM1CjYzMjMzczIKaWRyMAo 2016-04-10 14:54:58,896 (7f68c5ffb700) : INFO (agentkit:946) - Searching for matches for {'id': '63233', 'guid': 'com.plexapp.agents.imdb://tt1663202?lang=fr', 'force': True, 'primaryagent': 'com.plexapp.agents.imdb', 'parentID': None} 2016-04-10 14:54:58,897 (7f68c5ffb700) : DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/library/metadata/63233/tree' 2016-04-10 14:54:58,904 (7f68c5ffb700) : DEBUG (model:32) - Loading model with GUID com.plexapp.agents.imdb://tt1663202?lang=fr 2016-04-10 14:54:58,905 (7f68c5ffb700) : DEBUG (model:234) - Deserializing from /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Metadata/Movies/5/b96cc429b3ed4505de2f9a685b9e0aaaf9a0323.bundle/Contents/com.plexapp.agents.imdb/Info.xml 2016-04-10 14:54:58,907 (7f68c5ffb700) : DEBUG (init:290) - Sub-Zero 1.3.27.491, movies search 2016-04-10 14:54:58,909 (7f68c5ffb700) : DEBUG (runtime:924) - Response: [200] str, 600 bytes 2016-04-10 14:54:58,916 (7f68c5ffb700) : DEBUG (runtime:717) - Handling request GET /:/plugins/com.plexapp.agents.subzero/messaging/function/X0FnZW50S2l0OlVwZGF0ZU1ldGFkYXRh/Y2VyZWFsMQoxCmxpc3QKMApyMAo/Y2VyZWFsMQoxCmRpY3QKMTAKczIKZnJzNApsYW5nYjFzNQpmb3JjZWIwczgKcGVyaW9kaWNzNQo2MzIzM3M0CmRiaWRpMApzNwp2ZXJzaW9ubnMxMApwYXJlbnRHVUlEbnM4CnBhcmVudElEczUKTW92aWVzMTAKbWVkaWFfdHlwZXM0Mwpjb20ucGxleGFwcC5hZ2VudHMuaW1kYjovL3R0MTY2MzIwMj9sYW5nPWZyczQKZ3VpZHM0Cm51bGxzMgppZHIwCg 2016-04-10 14:54:58,917 (7f68c5ffb700) : DEBUG (runtime:814) - Found route matching /:/plugins/com.plexapp.agents.subzero/messaging/function/X0FnZW50S2l0OlVwZGF0ZU1ldGFkYXRh/Y2VyZWFsMQoxCmxpc3QKMApyMAo_/Y2VyZWFsMQoxCmRpY3QKMTAKczIKZnJzNApsYW5nYjFzNQpmb3JjZWIwczgKcGVyaW9kaWNzNQo2MzIzM3M0CmRiaWRpMApzNwp2ZXJzaW9ubnMxMApwYXJlbnRHVUlEbnM4CnBhcmVudElEczUKTW92aWVzMTAKbWVkaWFfdHlwZXM0Mwpjb20ucGxleGFwcC5hZ2VudHMuaW1kYjovL3R0MTY2MzIwMj9sYW5nPWZyczQKZ3VpZHM0Cm51bGxzMgppZHIwCg__ 2016-04-10 14:54:58,918 (7f68c5ffb700) : DEBUG (model:32) - Loading model with GUID com.plexapp.agents.imdb://tt1663202?lang=fr 2016-04-10 14:54:58,919 (7f68c5ffb700) : DEBUG (model:234) - Deserializing from /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Metadata/Movies/5/b96cc429b3ed4505de2f9a685b9e0aaaf9a0323.bundle/Contents/com.plexapp.agents.subzero/Info.xml 2016-04-10 14:54:58,920 (7f68c5ffb700) : DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/library/metadata/63233/tree' 2016-04-10 14:54:58,927 (7f68c5ffb700) : DEBUG (init:294) - Sub-Zero 1.3.27.491, movies update called 2016-04-10 14:54:58,929 (7f68c5ffb700) : DEBUG (init:170) - Scanning video: /home/amael/Téléchargements/Films/The.Revenant.2015.VOSTFR.FANSUB.DVDSCR.XviD.AC3-ZT.www.CpasBien.io.avi, subtitles=False, embedded_subtitles=False 2016-04-10 14:54:58,929 (7f68c5ffb700) : INFO (logger:38) - subliminal_patch.patch_video: Scanning video (hints: {'type': 'movie', 'expected_title': ['The Revenant']}) 'Films/The.Revenant.2015.VOSTFR.FANSUB.DVDSCR.XviD.AC3-ZT.www.CpasBien.io.avi' 2016-04-10 14:54:58,931 (7f68c5ffb700) : DEBUG (logger:28) - guessit.matcher: Property found: type=movie (None) (confidence=1.00) 2016-04-10 14:54:58,931 (7f68c5ffb700) : DEBUG (logger:28) - guessit.matcher: Property found: mimetype=video/x-msvideo (None) (confidence=1.00) 2016-04-10 14:54:58,931 (7f68c5ffb700) : DEBUG (logger:28) - guessit.matcher: Property found: container=avi (None) (confidence=1.00) 2016-04-10 14:54:58,952 (7f68c5ffb700) : DEBUG (logger:28) - guessit.matcher: Found match tree: 00000 111111111111111111111111111111111111111111111111111111111111111111 222 00000 000000000000000000000000000000000000000000000000000000000000000000 000 000000000000000000000000000000000000000000000000000111111111111111 000 000000000000000000000000000000000001112222222222222 00000000000000000000000000000000111 0111122222222 00000000000000000011111122222222 01112222 000000000000011112 0112 Films/___.__.FANSUB.__.._-_.____.___ tttttttttttttyyyy xxxxxx fffooo vvvv aaa rr wwwwwwwwwwwwwww ccc Films/The.Revenant.2015.VOSTFR.FANSUB.DVDSCR.XviD.AC3-ZT.www.CpasBien.io.avi 2016-04-10 14:54:58,952 (7f68c5ffb700) : DEBUG (logger:28) - guessit.guess: Updating matching property 'container' with confidence 1.00 2016-04-10 14:54:58,953 (7f68c5ffb700) : DEBUG (logger:28) - guessit.matchtree: Final result: { [0.60] "website": "www.CpasBien.io", [1.00] "mimetype": "video/x-msvideo", [0.60] "videoCodec": "XviD", [1.00] "container": "avi", [0.60] "format": "DVD", [0.48] "subtitleLanguage": [ "fr" ], [0.36] "title": "The Revenant", [0.60] "releaseGroup": "ZT", [0.60] "other": [ "Screener" ], [0.60] "year": 2015, [1.00] "type": "movie", [0.60] "audioCodec": "AC3" } 2016-04-10 14:54:58,954 (7f68c5ffb700) : DEBUG (logger:28) - subliminal_patch.patch_video: Size is 2219216233 2016-04-10 14:54:58,968 (7f68c5ffb700) : DEBUG (logger:28) - subliminal_patch.patch_video: Computed hashes {'opensubtitles': u'be806a5a75d87aea', 'thesubdb': 'b7c710366e15ef071a99954d9a8688cc'} 2016-04-10 14:54:58,969 (7f68c5ffb700) : DEBUG (init:203) - Download best subtitles using settings: min_score: 23, hearing_impaired: don't prefer 2016-04-10 14:54:58,969 (7f68c5ffb700) : INFO (logger:38) - subliminal.api: Downloading best subtitles for <Movie [u'The Revenant', 2015]> 2016-04-10 14:54:58,969 (7f68c5ffb700) : INFO (logger:38) - subliminal_patch.patch_provider_pool: Skipping provider 'addic7ed': not a valid video 2016-04-10 14:54:58,970 (7f68c5ffb700) : INFO (logger:38) - subliminal_patch.patch_provider_pool: Skipping provider 'tvsubtitles': not a valid video 2016-04-10 14:54:58,970 (7f68c5ffb700) : INFO (logger:38) - subliminal.api: Downloaded 0 subtitle(s) 2016-04-10 14:54:58,970 (7f68c5ffb700) : DEBUG (logger:28) - subliminal.api: Terminating initialized providers 2016-04-10 14:54:58,971 (7f68c5ffb700) : DEBUG (init:212) - Using filesystem as subtitle storage 2016-04-10 14:54:58,972 (7f68c5ffb700) : INFO (datakit:131) - Saved the dictionary file 2016-04-10 14:54:58,974 (7f68c5ffb700) : INFO (localmedia:72) - Looking for subtitle media in 1 paths with 15 media files. 2016-04-10 14:54:58,974 (7f68c5ffb700) : INFO (localmedia:73) - Paths: /home/amael/Téléchargements/Films 2016-04-10 14:54:58,974 (7f68c5ffb700) : INFO (subtitlehelpers:131) - Found subtitle file: /home/amael/Téléchargements/Films/The.Revenant.2015.VOSTFR.FANSUB.DVDSCR.XviD.AC3-ZT.www.CpasBien.io.fr.srt language: fr codec: srt format: srt 2016-04-10 14:54:58,975 (7f68c5ffb700) : INFO (subtitlehelpers:131) - Found subtitle file: /home/amael/Téléchargements/Films/The.Revenant.2015.VOSTFR.FANSUB.DVDSCR.XviD.AC3-ZT.www.CpasBien.io.en.srt language: en codec: srt format: srt 2016-04-10 14:54:58,977 (7f68c5ffb700) : DEBUG (background:92) - Scheduler: Sending signal updated_metadata to task searchAllRecentlyAddedMissing (('63233',), {}) 2016-04-10 14:54:58,977 (7f68c5ffb700) : DEBUG (background:95) - Scheduler: Signal accepted by searchAllRecentlyAddedMissing 2016-04-10 14:54:58,978 (7f68c5ffb700) : DEBUG (model:229) - Serializing to /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Metadata/Movies/5/b96cc429b3ed4505de2f9a685b9e0aaaf9a0323.bundle/Contents/com.plexapp.agents.subzero/Info.xml 2016-04-10 14:54:58,979 (7f68c5ffb700) : DEBUG (runtime:924) - Response: [200] str, 16 bytes 2016-04-10 14:55:03,931 (7f68a73dd700) : INFO (datakit:131) - Saved the dictionary file

Amaelh commented 8 years ago

And the direct next one is stalled :

2016-04-10 14:56:32,226 (7f68c5ffb700) : DEBUG (runtime:717) - Handling request GET /video/subzero/item/63192?item_title=Bates+Motel+S04E02%2C+2016-03-14&force=True 2016-04-10 14:56:32,227 (7f68c5ffb700) : DEBUG (runtime:49) - Received packed state data (80 bytes) 2016-04-10 14:56:32,228 (7f68c5ffb700) : DEBUG (runtime:814) - Found route matching /video/subzero/item/63192 2016-04-10 14:56:32,229 (7f68a6bdc700) : DEBUG (runtime:49) - Received packed state data (80 bytes) 2016-04-10 14:56:32,229 (7f68c5ffb700) : DEBUG (runtime:1117) - Created a thread named 'refreshItem' 2016-04-10 14:56:32,230 (7f68a6bdc700) : INFO (items:170) - Forced-refreshing item 63192 2016-04-10 14:56:32,234 (7f68c5ffb700) : DEBUG (runtime:88) - Sending packed state data (107 bytes) 2016-04-10 14:56:32,235 (7f68c5ffb700) : DEBUG (runtime:924) - Response: [200] MediaContainer, 1866 bytes 2016-04-10 14:56:32,288 (7f68a6bdc700) : DEBUG (runtime:717) - Handling request GET /video/subzero?randomize=1460292591&force_title=+ 2016-04-10 14:56:32,289 (7f68a6bdc700) : DEBUG (runtime:49) - Received packed state data (520 bytes) 2016-04-10 14:56:32,290 (7f68a6bdc700) : DEBUG (runtime:814) - Found route matching /video/subzero 2016-04-10 14:56:32,292 (7f68a6bdc700) : DEBUG (runtime:88) - Sending packed state data (547 bytes) 2016-04-10 14:56:32,293 (7f68a6bdc700) : DEBUG (runtime:924) - Response: [200] MediaContainer, 1800 bytes 2016-04-10 14:56:35,416 (7f68a63db700) : DEBUG (tasks:119) - Task: searchAllRecentlyAddedMissing, item stalled for 60 seconds: 63375, retrying 2016-04-10 14:56:36,696 (7f68a6bdc700) : DEBUG (runtime:717) - Handling request GET /video/subzero?randomize=1460292591&force_title=+ 2016-04-10 14:56:36,697 (7f68a6bdc700) : DEBUG (runtime:49) - Received packed state data (520 bytes) 2016-04-10 14:56:36,698 (7f68a6bdc700) : DEBUG (runtime:814) - Found route matching /video/subzero 2016-04-10 14:56:36,702 (7f68a6bdc700) : DEBUG (runtime:88) - Sending packed state data (547 bytes) 2016-04-10 14:56:36,703 (7f68a6bdc700) : DEBUG (runtime:924) - Response: [200] MediaContainer, 1800 bytes 2016-04-10 14:56:36,753 (7f68a6bdc700) : DEBUG (runtime:717) - Handling request GET /video/subzero/missing/refresh 2016-04-10 14:56:36,754 (7f68a6bdc700) : DEBUG (runtime:49) - Received packed state data (80 bytes) 2016-04-10 14:56:36,755 (7f68a6bdc700) : DEBUG (runtime:814) - Found route matching /video/subzero/missing/refresh 2016-04-10 14:56:36,755 (7f68a6bdc700) : DEBUG (runtime:1150) - Scheduled a timed thread named '' 2016-04-10 14:56:36,758 (7f68a6bdc700) : DEBUG (runtime:88) - Sending packed state data (107 bytes) 2016-04-10 14:56:36,758 (7f68a6bdc700) : DEBUG (runtime:924) - Response: [200] MediaContainer, 1892 bytes 2016-04-10 14:56:37,250 (7f68a73dd700) : INFO (datakit:131) - Saved the dictionary file 2016-04-10 14:56:37,755 (7f68c5ffb700) : DEBUG (runtime:1156) - Starting timed thread named '' 2016-04-10 14:56:37,757 (7f68c5ffb700) : DEBUG (runtime:49) - Received packed state data (80 bytes) 2016-04-10 14:56:37,758 (7f68c5ffb700) : DEBUG (background:76) - Scheduler: Not running searchAllRecentlyAddedMissing, as it's currently running. 2016-04-10 14:57:04,951 (7f68c67fc700) : DEBUG (tasks:116) - Task: searchAllRecentlyAddedMissing, item stalled for 4 times: 63233, skipping 2016-04-10 14:57:07,952 (7f68c67fc700) : DEBUG (tasks:101) - Task: searchAllRecentlyAddedMissing, triggering refresh for Z Nation S01E01, Chiens et chats (63375) 2016-04-10 14:57:38,480 (7f68a63db700) : DEBUG (tasks:116) - Task: searchAllRecentlyAddedMissing, item stalled for 4 times: 63375, skipping 2016-04-10 14:57:41,483 (7f68a63db700) : DEBUG (tasks:101) - Task: searchAllRecentlyAddedMissing, triggering refresh for The Big Bang Theory S09E20, 2016-04-07 (63359) 2016-04-10 14:58:08,015 (7f68c67fc700) : DEBUG (tasks:119) - Task: searchAllRecentlyAddedMissing, item stalled for 60 seconds: 63375, retrying

pannal commented 8 years ago

Could you disable the scheduler (Scheduler: Periodically search for recent items with missing subtitles to never), restart the PMS, and force-refresh an item via the Sub-Zero menu and post the log?

Amaelh commented 8 years ago

Done, I no longer see the "stalled" message but i still don't see subtitles files :

2016-04-10 16:00:47,444 (7f88c0587700) : INFO (core:349) - Starting framework core - Version: 2.6.3, Build: ee6e505 (Tue Apr 05 05:27:21 UTC 2016) 2016-04-10 16:00:47,444 (7f88c0587700) : DEBUG (core:361) - Using the elevated policy 2016-04-10 16:00:47,444 (7f88c0587700) : DEBUG (core:450) - Starting runtime component. 2016-04-10 16:00:47,446 (7f88c0587700) : DEBUG (core:450) - Starting caching component. 2016-04-10 16:00:47,447 (7f88c0587700) : DEBUG (core:450) - Starting data component. 2016-04-10 16:00:47,447 (7f88c0587700) : DEBUG (core:450) - Starting networking component. 2016-04-10 16:00:47,447 (7f88c0587700) : DEBUG (networking:282) - Loaded HTTP cookies 2016-04-10 16:00:47,448 (7f88c0587700) : DEBUG (networking:450) - Setting the default network timeout to 20.0 2016-04-10 16:00:47,448 (7f88c0587700) : DEBUG (core:450) - Starting localization component. 2016-04-10 16:00:47,448 (7f88c0587700) : INFO (localization:409) - Setting the default locale to en-us 2016-04-10 16:00:47,449 (7f88c0587700) : DEBUG (localization:427) - Loaded en strings 2016-04-10 16:00:47,449 (7f88c0587700) : DEBUG (core:450) - Starting messaging component. 2016-04-10 16:00:47,449 (7f88c0587700) : DEBUG (core:450) - Starting debugging component. 2016-04-10 16:00:47,450 (7f88b0ff9700) : DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/system/messaging/clear_events/com.plexapp.agents.subzero' 2016-04-10 16:00:47,450 (7f88c0587700) : DEBUG (core:450) - Starting services component. 2016-04-10 16:00:47,451 (7f88c0587700) : DEBUG (core:450) - Starting myplex component. 2016-04-10 16:00:47,451 (7f88c0587700) : DEBUG (core:450) - Starting notifications component. 2016-04-10 16:00:47,615 (7f88c0587700) : DEBUG (accessor:68) - Creating a new model access point for provider com.plexapp.agents.subzero in namespace 'metadata' 2016-04-10 16:00:47,620 (7f88c0587700) : DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/:/plugins/com.plexapp.system/resourceHashes' 2016-04-10 16:00:47,639 (7f88b0ff9700) : DEBUG (services:265) - Plug-in is not daemonized - loading services from system 2016-04-10 16:00:47,640 (7f88c0587700) : DEBUG (runtime:1117) - Created a thread named 'load_all_services' 2016-04-10 16:00:47,642 (7f88c0587700) : DEBUG (runtime:1117) - Created a thread named 'get_serverinfo' 2016-04-10 16:00:47,642 (7f88c0587700) : DEBUG (core:150) - Finished starting framework core 2016-04-10 16:00:47,642 (7f888f7fe700) : DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400' 2016-04-10 16:00:47,642 (7f88b0ff9700) : DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/:/plugins/com.plexapp.system/messaging/function/X0J1bmRsZVNlcnZpY2U6QWxsU2VydmljZXM/Y2VyZWFsMQoxCmxpc3QKMApyMAo/Y2VyZWFsMQoxCmRpY3QKMApyMAo' 2016-04-10 16:00:47,642 (7f88c0587700) : DEBUG (core:560) - Loading plug-in code 2016-04-10 16:00:47,757 (7f88c0587700) : DEBUG (core:566) - Finished loading plug-in code 2016-04-10 16:00:47,815 (7f888f7fe700) : DEBUG (core:538) - Machine identifier is 0278d713e1f36e6bb52119e194996042227b7983 2016-04-10 16:00:47,815 (7f888f7fe700) : DEBUG (core:539) - Server version is 0.9.16.4.1911-ee6e505 2016-04-10 16:00:47,925 (7f88b0ff9700) : DEBUG (services:362) - Loaded services 2016-04-10 16:00:47,931 (7f888ffff700) : DEBUG (services:438) - No shared code to load 2016-04-10 16:00:48,480 (7f88c0587700) : INFO (datakit:93) - Loaded the dictionary file 2016-04-10 16:00:48,748 (7f88c0587700) : DEBUG (preferences:258) - Loaded preferences from DefaultPrefs.json 2016-04-10 16:00:48,749 (7f88c0587700) : DEBUG (preferences:178) - Loaded the user preferences for com.plexapp.agents.subzero 2016-04-10 16:00:48,751 (7f88c0587700) : DEBUG (runtime:640) - Adding a prefix handler for 'Sub-Zero Subtitles' ('/video/subzero') 2016-04-10 16:00:48,754 (7f88c0587700) : DEBUG (agentkit:1104) - Creating new agent class called SubZeroSubtitlesAgentMovies 2016-04-10 16:00:48,754 (7f88c0587700) : DEBUG (agentkit:922) - Updating agent information: [{'media_types': ['Movie'], 'accepts_from': None, 'fallback_agent': None, 'contributes_to': ['com.plexapp.agents.imdb', 'com.plexapp.agents.xbmcnfo', 'com.plexapp.agents.themoviedb', 'com.plexapp.agents.hama'], 'languages': ['en'], 'persist_stored_files': True, 'version': 0, 'primaryprovider': False, 'prefs': True, 'name': 'Sub-Zero Subtitles (Movies, 1.3.27.491)'}] 2016-04-10 16:00:48,755 (7f88c0587700) : DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/:/plugins/com.plexapp.system/messaging/function/X0FnZW50U2VydmljZTpVcGRhdGVJbmZv/Y2VyZWFsMQoxCmxpc3QKMApyMAo/Y2VyZWFsMQo2CmRpY3QKbGlzdApkaWN0Cmxpc3QKbGlzdApsaXN0CjIKczI2CmNvbS5wbGV4YXBwLmFnZW50cy5zdWJ6ZXJvczEwCmlkZW50aWZpZXJyMQpzMTAKYWdlbnRfaW5mbzEKcjIKMTAKcjMKczExCm1lZGlhX3R5cGVzbnMxMgphY2NlcHRzX2Zyb21uczE0CmZhbGxiYWNrX2FnZW50cjQKczE0CmNvbnRyaWJ1dGVzX3RvcjUKczkKbGFuZ3VhZ2VzYjFzMjAKcGVyc2lzdF9zdG9yZWRfZmlsZXNpMApzNwp2ZXJzaW9uYjBzMTYKcHJpbWFyeV9wcm92aWRlcmIxczUKcHJlZnNzMzkKU3ViLVplcm8gU3VidGl0bGVzIChNb3ZpZXMsIDEuMy4yNy40OTEpczQKbmFtZTEKczUKTW92aWU0CnMyMwpjb20ucGxleGFwcC5hZ2VudHMuaW1kYnMyNgpjb20ucGxleGFwcC5hZ2VudHMueGJtY25mb3MyOQpjb20ucGxleGFwcC5hZ2VudHMudGhlbW92aWVkYnMyMwpjb20ucGxleGFwcC5hZ2VudHMuaGFtYTEKczIKZW5yMAo_' 2016-04-10 16:00:48,763 (7f88c0587700) : DEBUG (agentkit:1104) - Creating new agent class called SubZeroSubtitlesAgentTvShows 2016-04-10 16:00:48,764 (7f88c0587700) : DEBUG (agentkit:922) - Updating agent information: [{'media_types': ['Movie'], 'accepts_from': None, 'fallback_agent': None, 'contributes_to': ['com.plexapp.agents.imdb', 'com.plexapp.agents.xbmcnfo', 'com.plexapp.agents.themoviedb', 'com.plexapp.agents.hama'], 'languages': ['en'], 'persist_stored_files': True, 'version': 0, 'primary_provider': False, 'prefs': True, 'name': 'Sub-Zero Subtitles (Movies, 1.3.27.491)'}, {'media_types': ['TV_Show'], 'accepts_from': None, 'fallback_agent': None, 'contributes_to': ['com.plexapp.agents.thetvdb', 'com.plexapp.agents.thetvdbdvdorder', 'com.plexapp.agents.xbmcnfotv', 'com.plexapp.agents.hama'], 'languages': ['en'], 'persist_stored_files': True, 'version': 0, 'primaryprovider': False, 'prefs': True, 'name': 'Sub-Zero Subtitles (TV, 1.3.27.491)'}] 2016-04-10 16:00:48,766 (7f88c0587700) : DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/:/plugins/com.plexapp.system/messaging/function/X0FnZW50U2VydmljZTpVcGRhdGVJbmZv/Y2VyZWFsMQoxCmxpc3QKMApyMAo/Y2VyZWFsMQo5CmRpY3QKbGlzdApkaWN0Cmxpc3QKbGlzdApsaXN0CmRpY3QKbGlzdApsaXN0CjIKczI2CmNvbS5wbGV4YXBwLmFnZW50cy5zdWJ6ZXJvczEwCmlkZW50aWZpZXJyMQpzMTAKYWdlbnRfaW5mbzIKcjIKcjYKMTAKcjMKczExCm1lZGlhX3R5cGVzbnMxMgphY2NlcHRzX2Zyb21uczE0CmZhbGxiYWNrX2FnZW50cjQKczE0CmNvbnRyaWJ1dGVzX3RvcjUKczkKbGFuZ3VhZ2VzYjFzMjAKcGVyc2lzdF9zdG9yZWRfZmlsZXNpMApzNwp2ZXJzaW9uYjBzMTYKcHJpbWFyeV9wcm92aWRlcmIxczUKcHJlZnNzMzkKU3ViLVplcm8gU3VidGl0bGVzIChNb3ZpZXMsIDEuMy4yNy40OTEpczQKbmFtZTEKczUKTW92aWU0CnMyMwpjb20ucGxleGFwcC5hZ2VudHMuaW1kYnMyNgpjb20ucGxleGFwcC5hZ2VudHMueGJtY25mb3MyOQpjb20ucGxleGFwcC5hZ2VudHMudGhlbW92aWVkYnMyMwpjb20ucGxleGFwcC5hZ2VudHMuaGFtYTEKczIKZW4xMApyNwpzMTEKbWVkaWFfdHlwZXNuczEyCmFjY2VwdHNfZnJvbW5zMTQKZmFsbGJhY2tfYWdlbnRyOApzMTQKY29udHJpYnV0ZXNfdG9yNQpzOQpsYW5ndWFnZXNiMXMyMApwZXJzaXN0X3N0b3JlZF9maWxlc2kwCnM3CnZlcnNpb25iMHMxNgpwcmltYXJ5X3Byb3ZpZGVyYjFzNQpwcmVmc3MzNQpTdWItWmVybyBTdWJ0aXRsZXMgKFRWLCAxLjMuMjcuNDkxKXM0Cm5hbWUxCnM3ClRWX1Nob3c0CnMyNgpjb20ucGxleGFwcC5hZ2VudHMudGhldHZkYnMzNApjb20ucGxleGFwcC5hZ2VudHMudGhldHZkYmR2ZG9yZGVyczI4CmNvbS5wbGV4YXBwLmFnZW50cy54Ym1jbmZvdHZzMjMKY29tLnBsZXhhcHAuYWdlbnRzLmhhbWFyMAo_' 2016-04-10 16:00:48,776 (7f88c0587700) : DEBUG (menu:366) - Validate Prefs called. 2016-04-10 16:00:48,815 (7f88c0587700) : DEBUG (menu:395) - Stop logging to console 2016-04-10 16:00:48,815 (7f88c0587700) : DEBUG (menu:397) - Setting log-level to DEBUG 2016-04-10 16:00:48,815 (7f88c0587700) : DEBUG (logger:7) - Registering LoggerHandler for dependency: subliminal 2016-04-10 16:00:48,816 (7f88c0587700) : DEBUG (logger:7) - Registering LoggerHandler for dependency: subliminal_patch 2016-04-10 16:00:48,816 (7f88c0587700) : DEBUG (logger:7) - Registering LoggerHandler for dependency: enzyme 2016-04-10 16:00:48,816 (7f88c0587700) : DEBUG (logger:7) - Registering LoggerHandler for dependency: guessit 2016-04-10 16:00:48,817 (7f88c0587700) : DEBUG (init:44) - Sub-Zero 1.3.27.491 2016-04-10 16:00:48,817 (7f88c0587700) : DEBUG (runtime:1117) - Created a thread named 'worker' 2016-04-10 16:00:48,817 (7f88c0587700) : INFO (core:611) - Started plug-in 2016-04-10 16:00:48,817 (7f88c0587700) : DEBUG (socketinterface:160) - Starting socket server 2016-04-10 16:00:48,818 (7f88c0587700) : DEBUG (runtime:1117) - Created a thread named 'start' 2016-04-10 16:00:48,819 (7f88c0587700) : INFO (socketinterface:184) - Socket server started on port 43107 2016-04-10 16:00:48,819 (7f88c0587700) : INFO (pipeinterface:25) - Entering run loop 2016-04-10 16:00:48,819 (7f88c0587700) : DEBUG (runtime:717) - Handling request GET /:/prefixes 2016-04-10 16:00:48,821 (7f88c0587700) : DEBUG (runtime:814) - Found route matching /:/prefixes 2016-04-10 16:00:48,823 (7f88c0587700) : DEBUG (runtime:924) - Response: [200] MediaContainer, 449 bytes 2016-04-10 16:00:53,817 (7f888ffff700) : INFO (datakit:131) - Saved the dictionary file 2016-04-10 16:00:57,349 (7f888ffff700) : DEBUG (runtime:717) - Handling request GET /video/subzero?randomize=1460296840&force_title=+ 2016-04-10 16:00:57,350 (7f888ffff700) : DEBUG (runtime:49) - Received packed state data (520 bytes) 2016-04-10 16:00:57,361 (7f888ffff700) : DEBUG (runtime:814) - Found route matching /video/subzero 2016-04-10 16:00:57,365 (7f888ffff700) : DEBUG (runtime:88) - Sending packed state data (547 bytes) 2016-04-10 16:00:57,365 (7f888ffff700) : DEBUG (runtime:924) - Response: [200] MediaContainer, 1780 bytes 2016-04-10 16:00:57,403 (7f888ffff700) : DEBUG (runtime:717) - Handling request GET /video/subzero/recent 2016-04-10 16:00:57,404 (7f888ffff700) : DEBUG (runtime:49) - Received packed state data (520 bytes) 2016-04-10 16:00:57,406 (7f888ffff700) : DEBUG (runtime:814) - Found route matching /video/subzero/recent 2016-04-10 16:00:57,414 (7f888ffff700) : DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/library/sections/5/all?sort=addedAt%3Adesc&X-Plex-Container-Size=200&X-Plex-Container-Start=0&X-Plex-Token=xgRvxaKuiWs5ifmJsMNk' 2016-04-10 16:00:57,648 (7f888ffff700) : DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/library/sections/2/all?sort=addedAt%3Adesc&X-Plex-Container-Size=200&X-Plex-Container-Start=0&X-Plex-Token=xgRvxaKuiWs5ifmJsMNk' 2016-04-10 16:00:57,668 (7f888ffff700) : DEBUG (items:132) - Skipping section: Musique 2016-04-10 16:00:57,668 (7f888ffff700) : DEBUG (items:132) - Skipping section: Photos 2016-04-10 16:00:57,669 (7f888ffff700) : DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/library/sections/1/all?sort=addedAt%3Adesc&X-Plex-Container-Size=200&type=4&X-Plex-Container-Start=0&X-Plex-Token=xgRvxaKuiWs5ifmJsMNk' 2016-04-10 16:00:57,766 (7f888ffff700) : INFO (missing_subtitles:44) - Subs still missing for 'The Revenant': set([<Language [fr]>, <Language [en]>]) 2016-04-10 16:00:58,315 (7f888ffff700) : INFO (missing_subtitles:44) - Subs still missing for 'Grimm S05E11, 2016-03-04': set([<Language [fr]>, <Language [en]>]) 2016-04-10 16:00:58,343 (7f888ffff700) : DEBUG (runtime:88) - Sending packed state data (547 bytes) 2016-04-10 16:00:58,343 (7f888ffff700) : DEBUG (runtime:924) - Response: [200] MediaContainer, 8647 bytes 2016-04-10 16:01:10,584 (7f888ffff700) : DEBUG (runtime:717) - Handling request GET /video/subzero/recent 2016-04-10 16:01:10,584 (7f888ffff700) : DEBUG (runtime:49) - Received packed state data (520 bytes) 2016-04-10 16:01:10,585 (7f888ffff700) : DEBUG (runtime:814) - Found route matching /video/subzero/recent 2016-04-10 16:01:10,592 (7f888ffff700) : DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/library/sections/5/all?sort=addedAt%3Adesc&X-Plex-Container-Size=200&X-Plex-Container-Start=0&X-Plex-Token=xgRvxaKuiWs5ifmJsMNk' 2016-04-10 16:01:10,809 (7f888ffff700) : DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/library/sections/2/all?sort=addedAt%3Adesc&X-Plex-Container-Size=200&X-Plex-Container-Start=0&X-Plex-Token=xgRvxaKuiWs5ifmJsMNk' 2016-04-10 16:01:10,835 (7f888ffff700) : DEBUG (items:132) - Skipping section: Musique 2016-04-10 16:01:10,835 (7f888ffff700) : DEBUG (items:132) - Skipping section: Photos 2016-04-10 16:01:10,836 (7f888ffff700) : DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/library/sections/1/all?sort=addedAt%3Adesc&X-Plex-Container-Size=200&type=4&X-Plex-Container-Start=0&X-Plex-Token=xgRvxaKuiWs5ifmJsMNk' 2016-04-10 16:01:10,928 (7f888ffff700) : INFO (missing_subtitles:44) - Subs still missing for 'The Revenant': set([<Language [fr]>, <Language [en]>]) 2016-04-10 16:01:11,464 (7f888ffff700) : INFO (missing_subtitles:44) - Subs still missing for 'Grimm S05E11, 2016-03-04': set([<Language [fr]>, <Language [en]>]) 2016-04-10 16:01:11,493 (7f888ffff700) : DEBUG (runtime:88) - Sending packed state data (547 bytes) 2016-04-10 16:01:11,494 (7f888ffff700) : DEBUG (runtime:924) - Response: [200] MediaContainer, 8647 bytes 2016-04-10 16:01:11,611 (7f888ffff700) : DEBUG (runtime:717) - Handling request GET /video/subzero/item/63293/actions?item_title=Bates+Motel+S04E04%2C+2016-03-28&title=Missing+Subtitles+%3E+Bates+Motel+S04E04%2C+2016-03-28 2016-04-10 16:01:11,613 (7f888ffff700) : DEBUG (runtime:49) - Received packed state data (80 bytes) 2016-04-10 16:01:11,615 (7f888ffff700) : DEBUG (runtime:814) - Found route matching /video/subzero/item/63293/actions 2016-04-10 16:01:11,615 (7f888ffff700) : WARNING (runtime:1065) - Generating a callback path for a function with no route: <function IgnoreMenu at 0x4581cf8> 2016-04-10 16:01:11,618 (7f888ffff700) : DEBUG (runtime:88) - Sending packed state data (107 bytes) 2016-04-10 16:01:11,618 (7f888ffff700) : DEBUG (runtime:924) - Response: [200] MediaContainer, 1178 bytes 2016-04-10 16:01:13,415 (7f888ffff700) : DEBUG (runtime:717) - Handling request GET /video/subzero/item/63293/actions?item_title=Bates+Motel+S04E04%2C+2016-03-28&title=Missing+Subtitles+%3E+Bates+Motel+S04E04%2C+2016-03-28 2016-04-10 16:01:13,416 (7f888ffff700) : DEBUG (runtime:49) - Received packed state data (80 bytes) 2016-04-10 16:01:13,417 (7f888ffff700) : DEBUG (runtime:814) - Found route matching /video/subzero/item/63293/actions 2016-04-10 16:01:13,417 (7f888ffff700) : WARNING (runtime:1065) - Generating a callback path for a function with no route: <function IgnoreMenu at 0x4581cf8> 2016-04-10 16:01:13,419 (7f888ffff700) : DEBUG (runtime:88) - Sending packed state data (107 bytes) 2016-04-10 16:01:13,419 (7f888ffff700) : DEBUG (runtime:924) - Response: [200] MediaContainer, 1178 bytes 2016-04-10 16:01:13,451 (7f888ffff700) : DEBUG (runtime:717) - Handling request GET /video/subzero/item/63293?item_title=Bates+Motel+S04E04%2C+2016-03-28&force=True 2016-04-10 16:01:13,452 (7f888ffff700) : DEBUG (runtime:49) - Received packed state data (80 bytes) 2016-04-10 16:01:13,453 (7f888ffff700) : DEBUG (runtime:814) - Found route matching /video/subzero/item/63293 2016-04-10 16:01:13,455 (7f888e7fc700) : DEBUG (runtime:49) - Received packed state data (80 bytes) 2016-04-10 16:01:13,455 (7f888ffff700) : DEBUG (runtime:1117) - Created a thread named 'refreshItem' 2016-04-10 16:01:13,456 (7f888e7fc700) : INFO (items:170) - Forced-refreshing item 63293 2016-04-10 16:01:13,460 (7f888ffff700) : DEBUG (runtime:88) - Sending packed state data (107 bytes) 2016-04-10 16:01:13,460 (7f888ffff700) : DEBUG (runtime:924) - Response: [200] MediaContainer, 1901 bytes 2016-04-10 16:01:18,458 (7f888effd700) : INFO (datakit:131) - Saved the dictionary file 2016-04-10 16:02:37,364 (7f888effd700) : DEBUG (runtime:717) - Handling request GET /video/subzero/item/63293?item_title=Bates+Motel+S04E04%2C+2016-03-28&force=True 2016-04-10 16:02:37,365 (7f888effd700) : DEBUG (runtime:49) - Received packed state data (80 bytes) 2016-04-10 16:02:37,366 (7f888effd700) : DEBUG (runtime:814) - Found route matching /video/subzero/item/63293 2016-04-10 16:02:37,367 (7f888ffff700) : DEBUG (runtime:49) - Received packed state data (80 bytes) 2016-04-10 16:02:37,367 (7f888effd700) : DEBUG (runtime:1117) - Created a thread named 'refreshItem' 2016-04-10 16:02:37,368 (7f888ffff700) : INFO (items:170) - Forced-refreshing item 63293 2016-04-10 16:02:37,372 (7f888effd700) : DEBUG (runtime:88) - Sending packed state data (107 bytes) 2016-04-10 16:02:37,372 (7f888effd700) : DEBUG (runtime:924) - Response: [200] MediaContainer, 1901 bytes 2016-04-10 16:02:37,412 (7f888ffff700) : DEBUG (runtime:717) - Handling request GET /video/subzero/recent 2016-04-10 16:02:37,413 (7f888ffff700) : DEBUG (runtime:49) - Received packed state data (520 bytes) 2016-04-10 16:02:37,414 (7f888ffff700) : DEBUG (runtime:814) - Found route matching /video/subzero/recent 2016-04-10 16:02:37,419 (7f888ffff700) : DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/library/sections/5/all?sort=addedAt%3Adesc&X-Plex-Container-Size=200&X-Plex-Container-Start=0&X-Plex-Token=xgRvxaKuiWs5ifmJsMNk' 2016-04-10 16:02:37,639 (7f888ffff700) : DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/library/sections/2/all?sort=addedAt%3Adesc&X-Plex-Container-Size=200&X-Plex-Container-Start=0&X-Plex-Token=xgRvxaKuiWs5ifmJsMNk' 2016-04-10 16:02:37,662 (7f888ffff700) : DEBUG (items:132) - Skipping section: Musique 2016-04-10 16:02:37,662 (7f888ffff700) : DEBUG (items:132) - Skipping section: Photos 2016-04-10 16:02:37,663 (7f888ffff700) : DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/library/sections/1/all?sort=addedAt%3Adesc&X-Plex-Container-Size=200&type=4&X-Plex-Container-Start=0&X-Plex-Token=xgRvxaKuiWs5ifmJsMNk' 2016-04-10 16:02:37,754 (7f888ffff700) : INFO (missing_subtitles:44) - Subs still missing for 'The Revenant': set([<Language [fr]>, <Language [en]>]) 2016-04-10 16:02:38,274 (7f888ffff700) : INFO (missing_subtitles:44) - Subs still missing for 'Grimm S05E11, 2016-03-04': set([<Language [fr]>, <Language [en]>]) 2016-04-10 16:02:38,292 (7f888ffff700) : DEBUG (runtime:88) - Sending packed state data (547 bytes) 2016-04-10 16:02:38,292 (7f888ffff700) : DEBUG (runtime:924) - Response: [200] MediaContainer, 8647 bytes 2016-04-10 16:02:42,391 (7f888e7fc700) : INFO (datakit:131) - Saved the dictionary file 2016-04-10 16:03:13,640 (7f888e7fc700) : DEBUG (runtime:717) - Handling request GET /video/subzero/recent 2016-04-10 16:03:13,641 (7f888e7fc700) : DEBUG (runtime:49) - Received packed state data (520 bytes) 2016-04-10 16:03:13,642 (7f888e7fc700) : DEBUG (runtime:814) - Found route matching /video/subzero/recent 2016-04-10 16:03:13,647 (7f888e7fc700) : DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/library/sections/5/all?sort=addedAt%3Adesc&X-Plex-Container-Size=200&X-Plex-Container-Start=0&X-Plex-Token=xgRvxaKuiWs5ifmJsMNk' 2016-04-10 16:03:13,866 (7f888e7fc700) : DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/library/sections/2/all?sort=addedAt%3Adesc&X-Plex-Container-Size=200&X-Plex-Container-Start=0&X-Plex-Token=xgRvxaKuiWs5ifmJsMNk' 2016-04-10 16:03:13,896 (7f888e7fc700) : DEBUG (items:132) - Skipping section: Musique 2016-04-10 16:03:13,897 (7f888e7fc700) : DEBUG (items:132) - Skipping section: Photos 2016-04-10 16:03:13,898 (7f888e7fc700) : DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/library/sections/1/all?sort=addedAt%3Adesc&X-Plex-Container-Size=200&type=4&X-Plex-Container-Start=0&X-Plex-Token=xgRvxaKuiWs5ifmJsMNk' 2016-04-10 16:03:13,993 (7f888e7fc700) : INFO (missing_subtitles:44) - Subs still missing for 'The Revenant': set([<Language [fr]>, <Language [en]>]) 2016-04-10 16:03:14,555 (7f888e7fc700) : INFO (missing_subtitles:44) - Subs still missing for 'Grimm S05E11, 2016-03-04': set([<Language [fr]>, <Language [en]>]) 2016-04-10 16:03:14,576 (7f888e7fc700) : DEBUG (runtime:88) - Sending packed state data (547 bytes) 2016-04-10 16:03:14,576 (7f888e7fc700) : DEBUG (runtime:924) - Response: [200] MediaContainer, 8647 bytes 2016-04-10 16:03:14,687 (7f888e7fc700) : DEBUG (runtime:717) - Handling request GET /video/subzero/item/63115/actions?item_title=Grimm+S05E11%2C+2016-03-04&title=Missing+Subtitles+%3E+Grimm+S05E11%2C+2016-03-04 2016-04-10 16:03:14,688 (7f888e7fc700) : DEBUG (runtime:49) - Received packed state data (80 bytes) 2016-04-10 16:03:14,690 (7f888e7fc700) : DEBUG (runtime:814) - Found route matching /video/subzero/item/63115/actions 2016-04-10 16:03:14,690 (7f888e7fc700) : WARNING (runtime:1065) - Generating a callback path for a function with no route: <function IgnoreMenu at 0x4581cf8> 2016-04-10 16:03:14,693 (7f888e7fc700) : DEBUG (runtime:88) - Sending packed state data (107 bytes) 2016-04-10 16:03:14,693 (7f888e7fc700) : DEBUG (runtime:924) - Response: [200] MediaContainer, 1134 bytes 2016-04-10 16:03:16,462 (7f888e7fc700) : DEBUG (runtime:717) - Handling request GET /video/subzero/item/63115/actions?item_title=Grimm+S05E11%2C+2016-03-04&title=Missing+Subtitles+%3E+Grimm+S05E11%2C+2016-03-04 2016-04-10 16:03:16,463 (7f888e7fc700) : DEBUG (runtime:49) - Received packed state data (80 bytes) 2016-04-10 16:03:16,464 (7f888e7fc700) : DEBUG (runtime:814) - Found route matching /video/subzero/item/63115/actions 2016-04-10 16:03:16,464 (7f888e7fc700) : WARNING (runtime:1065) - Generating a callback path for a function with no route: <function IgnoreMenu at 0x4581cf8> 2016-04-10 16:03:16,465 (7f888e7fc700) : DEBUG (runtime:88) - Sending packed state data (107 bytes) 2016-04-10 16:03:16,466 (7f888e7fc700) : DEBUG (runtime:924) - Response: [200] MediaContainer, 1134 bytes 2016-04-10 16:03:16,486 (7f888e7fc700) : DEBUG (runtime:717) - Handling request GET /video/subzero/item/63115?item_title=Grimm+S05E11%2C+2016-03-04&force=True 2016-04-10 16:03:16,487 (7f888e7fc700) : DEBUG (runtime:49) - Received packed state data (80 bytes) 2016-04-10 16:03:16,488 (7f888e7fc700) : DEBUG (runtime:814) - Found route matching /video/subzero/item/63115 2016-04-10 16:03:16,489 (7f888e7fc700) : DEBUG (runtime:1117) - Created a thread named 'refreshItem' 2016-04-10 16:03:16,490 (7f888effd700) : DEBUG (runtime:49) - Received packed state data (80 bytes) 2016-04-10 16:03:16,491 (7f888effd700) : INFO (items:170) - Forced-refreshing item 63115 2016-04-10 16:03:16,494 (7f888e7fc700) : DEBUG (runtime:88) - Sending packed state data (107 bytes) 2016-04-10 16:03:16,494 (7f888e7fc700) : DEBUG (runtime:924) - Response: [200] MediaContainer, 1895 bytes 2016-04-10 16:03:21,493 (7f888ffff700) : INFO (datakit:131) - Saved the dictionary file

pannal commented 8 years ago

Thanks. Weird, the refresh request never gets through to the PMS. I'll see if I can reproduce this.

Amaelh commented 8 years ago

Thanks !

pannal commented 8 years ago

Could you please install the following testing branch: https://github.com/pannal/Sub-Zero.bundle/archive/stalling-test.zip (installation: https://github.com/pannal/Sub-Zero.bundle#manualdevelopmenttesting-installation)

Then:

Thank you

Amaelh commented 8 years ago

Hello,

thanks for your time. I have done this, please find attached the logs. For every "Refresh TestX" click I get a "Treatment Finished xxxx" notification at bottom of Plex web interface (I think I also had this notification before). Still no subs downloaded though...

Best regards com.plexapp.agents.subzero.log.zip

Amaelh commented 8 years ago

Interesting fact : I can see warnings in PMS logs at the same moment, as well as other warnings/errors at start. Please find attached the log (in WARN only), just tell me if you want them in INFO also.

In the meantime I'll check the errors that seem not related to subzero but could also impact. Plex Media Server.log.zip

Amaelh commented 8 years ago

Hi again,

I corrected the SQLITE database corruption and restarted, now the errors are gone, but still same behaviour for SubZero. Please find attached a verbose PMS log focused on the time I clicked on "Refresh1" button in PMS for one episode.

Best regards pms_debug_extract_refresh1.log.zip

pannal commented 8 years ago

That is so weird. You can browse the Sub-Zero channel (which uses the Plex API) but not trigger a refresh using the Plex API.

What happens when you wget http://127.0.0.1:32400/library/metadata/63190/refresh?X-Plex-Token=XXXXXXXXXXXXXXXXX (replace X's with your Plex token)? Does that trigger?

Amaelh commented 8 years ago

Interesting response : 405 Method Not allowed

wget http://127.0.0.1:32400/library/metadata/63190/refresh?X-Plex-Token=xxxxxxxxxxxxxxxxxxxxxx --2016-04-23 13:41:21-- http://127.0.0.1:32400/library/metadata/63190/refresh?X-Plex-Token=xxxxxxxxxxxxxxxxxxxxxx Connexion à 127.0.0.1:32400… connecté. requête HTTP transmise, en attente de la réponse… 405 Method Not Allowed 2016-04-23 13:41:21 erreur 405 : Method Not Allowed.

Amaelh commented 8 years ago

I also tried the classic metadata request with my plex token to check if it was valid, result is OK only when putting double-quotes around the address :

wget "http://localhost:32400/library/metadata/63188?checkFiles=1&includeExtras=1&X-Plex-Token=xxxxxxxxxxxxxxxxxxx" --2016-04-23 13:48:51-- http://localhost:32400/library/metadata/63188?checkFiles=1&includeExtras=1&X-Plex-Token=xxxxxxxxxxxxxxx Résolution de localhost (localhost)… 127.0.0.1 Connexion à localhost (localhost)|127.0.0.1|:32400… connecté. requête HTTP transmise, en attente de la réponse… 200 OK Taille : 2214 (2,2K) [text/xml] Enregistre : «63188?checkFiles=1&includeExtras=1&X-Plex-Token=xxxxxxxxxxxxxxxxxx»

63188?checkFiles=1&includeExtra 100%[========================================================>] 2,16K --.-KB/s ds 0s

2016-04-23 13:48:51 (281 MB/s) - «63188?checkFiles=1&includeExtras=1&X-Plex-Token=xxxxxxxxxxxxxxx» enregistré [2214/2214]

Same test for the refresh is KO (I also tried in a browser - same result) :

wget "http://127.0.0.1:32400/library/metadata/63190/refresh?X-Plex-Token=xxxxxxxxxxxxxxxxxxx" --2016-04-23 13:49:29-- http://127.0.0.1:32400/library/metadata/63190/refresh?X-Plex-Token=xxxxxxxxxxxxxxx Connexion à 127.0.0.1:32400… connecté. requête HTTP transmise, en attente de la réponse… 405 Method Not Allowed 2016-04-23 13:49:29 erreur 405 : Method Not Allowed.

pannal commented 8 years ago

Yeah that's the expected behaviour because it needs a PUT instead of a GET.

Try curl -XPUT http://127.0.0.1:32400/library/metadata/63190/refresh?X-Plex-Token=xxxxxxxxxxxxxxxxxxx

Amaelh commented 8 years ago

Command line response is OK, Plex logs are doing something, subzero does not log anything.

curl -XPUT "http://127.0.0.1:32400/library/metadata/63190/refresh?X-Plex-Token=xxxxxxxxxxxxxx" <?xml version="1.0" encoding="UTF-8"?>

curl_refresh.txt.zip

Amaelh commented 8 years ago

Note that since reinstall + repair sql corruption the subtitles of movies are downloading, specific TV episodes are downloading (but only one show out of 10).

pannal commented 8 years ago

Can you post all of your sub-zero logs as a zip?

And please take screenshots of your metadata agent configurations and library settings/advanced screen.

pannal commented 8 years ago

Sounds a bit like your TV series metadata agent config is wrong (Sub-Zero not enabled there?). Does manual refresh using the SZ menu on a movie work?

Amaelh commented 8 years ago

Manual refresh on a movie works, on a TV serie no.

In server configuration, agents, TV shows, TheTVDB I have following agents activated (in this order) : 1) Sub-Zero Subtitles 2) Local media Assets 3) The TVDB

In TV show library, advanced I checked the "TheTVDB" agent

Amaelh commented 8 years ago

Please find attached my entire log as well as the screen captures.

agents library com.plexapp.agents.subzero.log.zip

Amaelh commented 8 years ago

As I indicated before one show is working and not the others.

Please find attached two log files of "Forced refreshes" : -> request_OK.txt : SubZero log for a working show -> request_KO.txt : SubZero log for a broken show request_OK.txt.zip request_KO.txt.zip

pannal commented 8 years ago

I really can't figure out why this would happen.

Did you try re-creating the library or creating a second library to see whether that fixes it? For now I don't think that this is Sub-Zero related, as the server simply doesn't accept the refresh request, or doesn't forward it to Sub-Zero.

Even your direct curl refresh didn't go through. I've noticed something in your curl_refresh.txt, though: Apr 23, 2016 14:09:35 [0x7f354f3ff700] WARN - Unable to load episode file [seasons/2/episodes/3.xml] and Apr 23, 2016 14:09:35 [0x7f35447ff700] DEBUG - Refreshing metadata for 'Amarillo' (agent: ) (empty agent?)

How do the working logs compare to that?

Also in the first Plex Media Server.log you posted I can see: Apr 23, 2016 11:39:59 [0x7f2b20bff700] WARN - Request for plug-in [com.plexapp.agents.subzero] but it doesn't exist., together with many WARN - Unable to load episode file - have you fixed those? Or just the SQLite error? How did you fix your database corruption issue?

Something seems really fishy with your setup.

Amaelh commented 8 years ago

Well done !! I deleted library and recreated it, and now all works. It downloaded subs for everything !

The one TV show that was working before was the only one I added after having configured everything properly, so there might be something related.

Thanks in for all your time, maybe you could add a hint about this in your instructions ? "If some TV shows are not downloading try to delete/recreate library".

You can close this ticket :)

pannal commented 8 years ago

Great to hear!

pannal commented 8 years ago

For the record: How did you fix your database corruption issue? (Before you recreated the library)

Amaelh commented 8 years ago

I performed a dump of the existing database and then loaded it back to a new file (see guide on plex support forum at https://support.plex.tv/hc/en-us/articles/201100678-Repair-a-Corrupt-Database )

pannal commented 8 years ago

Thanks, I'll include that info in the docs.