2016-12-04, 16:14
nfs handling with nfs cache seems to be quite difficult according to some readings I have done.
So I ended mounting my nfs sources at the OS level at boot with systemd instead of using the Kodi embedded nfs driver.
The result is the library scan is working fine (except from some file names decoding issues we'll see later).
Now, the interactive version doesn't seem to catch the temp srt saved by the subtitles addon.
From what I've read in default.py CleanSubs shall notice any new subtitle saved there and log it as CLEANSUBS >> SUBS ADDED.
But it doesn't happen here. Is it possible that opensubtitles deletes the temp file too fast before CleanSubs has a chance to notice it ?
Log excerpt :
So I ended mounting my nfs sources at the OS level at boot with systemd instead of using the Kodi embedded nfs driver.
The result is the library scan is working fine (except from some file names decoding issues we'll see later).
Now, the interactive version doesn't seem to catch the temp srt saved by the subtitles addon.
From what I've read in default.py CleanSubs shall notice any new subtitle saved there and log it as CLEANSUBS >> SUBS ADDED.
But it doesn't happen here. Is it possible that opensubtitles deletes the temp file too fast before CleanSubs has a chance to notice it ?
Log excerpt :
Code:
12:31:30 T:139763302070336 DEBUG: ------ Window Init (DialogSeekBar.xml) ------
12:31:30 T:139761171814144 DEBUG: StartScript - calling plugin OpenSubtitles.org('plugin://service.subtitles.opensubtitles/','16','?action=search&languages=English%2CFrench&preferredlanguage=French')
12:31:30 T:139760697861888 DEBUG: Thread LanguageInvoker start, auto delete: false
12:31:30 T:139760697861888 INFO: initializing python engine.
12:31:30 T:139760697861888 DEBUG: CPythonInvoker(26, /storage/.kodi/addons/service.subtitles.opensubtitles/service.py): start processing
12:31:30 T:139760697861888 DEBUG: -->Python Interpreter Initialized<--
12:31:30 T:139760697861888 DEBUG: CPythonInvoker(26, /storage/.kodi/addons/service.subtitles.opensubtitles/service.py): the source file to load is "/storage/.kodi/addons/service.subtitles.opensubtitles/service.py"
12:31:30 T:139760697861888 DEBUG: CPythonInvoker(26, /storage/.kodi/addons/service.subtitles.opensubtitles/service.py): setting the Python path to /storage/.kodi/addons/service.subtitles.opensubtitles:/usr/lib/python27.zip:/usr/lib/python2.7:/usr/lib/python2.7/plat-linux2:/usr/lib/python2.7/lib-tk:/usr/lib/python2.7/lib-old:/usr/lib/python2.7/lib-dynload:/usr/lib/python2.7/site-packages:/usr/lib/python2.7/site-packages/gtk-2.0
12:31:30 T:139760697861888 DEBUG: CPythonInvoker(26, /storage/.kodi/addons/service.subtitles.opensubtitles/service.py): entering source directory /storage/.kodi/addons/service.subtitles.opensubtitles
12:31:30 T:139760697861888 DEBUG: CPythonInvoker(26, /storage/.kodi/addons/service.subtitles.opensubtitles/service.py): instantiating addon using automatically obtained id of "service.subtitles.opensubtitles" dependent on version 2.1.0 of the xbmc.python api
12:31:30 T:139760628635392 DEBUG: CDVDAudio::Pause - pausing audio stream
12:31:30 T:139760697861888 DEBUG: ### [__main__] - action 'search' called
12:31:30 T:139760697861888 DEBUG: ### [__main__] - VideoPlayer.OriginalTitle not found
12:31:30 T:139760697861888 DEBUG: ### [OSUtilities] - Search String [ The+100+S01E02 ]
12:31:30 T:139760697861888 DEBUG: ### [OSUtilities] - Hash Standard file
12:31:30 T:139760697861888 DEBUG: ### [OSUtilities] - OpenSubtitles module hash [6da2988fc1f619cf] and size [1582480208]
12:31:30 T:139763302070336 DEBUG: LIRC: Update - NEW at 222753:a1 0 KEY_EJECTCD_UP devinput (KEY_EJECTCD_UP)
12:31:30 T:139762097878784 DEBUG: CLEANSUBS >> CURRENT WINDOW 10153 - STARTING TIMER
12:31:31 T:139760697861888 INFO: CPythonInvoker(26, /storage/.kodi/addons/service.subtitles.opensubtitles/service.py): script successfully run
12:31:31 T:139760697861888 INFO: Python script stopped
12:31:31 T:139760697861888 DEBUG: Thread LanguageInvoker 139760697861888 terminating
12:31:31 T:139762097878784 DEBUG: CLEANSUBS >> CURRENT WINDOW 10153 - STARTING TIMER
12:31:40 T:139763302070336 DEBUG: Previous line repeats 2 times.
12:31:40 T:139763302070336 DEBUG: LIRC: Update - NEW at 232056:6c 0 KEY_DOWN devinput (KEY_DOWN)
12:31:40 T:139763302070336 DEBUG: OnKey: 167 (0xa7, obc88) pressed, action is Down
12:31:40 T:139763302070336 DEBUG: LIRC: Update - NEW at 232596:6c 0 KEY_DOWN_UP devinput (KEY_DOWN_UP)
12:31:41 T:139763302070336 DEBUG: LIRC: Update - NEW at 233225:160 0 KEY_OK devinput (KEY_OK)
12:31:41 T:139763302070336 DEBUG: OnKey: 11 (0x0b, obc244) pressed, action is Select
12:31:41 T:139762379773696 DEBUG: StartScript - calling plugin OpenSubtitles.org('plugin://service.subtitles.opensubtitles/','17','?action=download&link=http://dl.opensubtitles.org/en/download/src-api/vrf-f5bb4/sid-YkpnMD,63f3ExnRLjWPuIL4/sub/5622714&ID=1954208603&filename=The.100.S01E02.PROPER.HDTV.x264-2HD.srt&format=srt')
12:31:41 T:139760697861888 DEBUG: Thread LanguageInvoker start, auto delete: false
12:31:41 T:139760697861888 INFO: initializing python engine.
12:31:41 T:139760697861888 DEBUG: CPythonInvoker(27, /storage/.kodi/addons/service.subtitles.opensubtitles/service.py): start processing
12:31:41 T:139760697861888 DEBUG: -->Python Interpreter Initialized<--
12:31:41 T:139760697861888 DEBUG: CPythonInvoker(27, /storage/.kodi/addons/service.subtitles.opensubtitles/service.py): the source file to load is "/storage/.kodi/addons/service.subtitles.opensubtitles/service.py"
12:31:41 T:139760697861888 DEBUG: CPythonInvoker(27, /storage/.kodi/addons/service.subtitles.opensubtitles/service.py): setting the Python path to /storage/.kodi/addons/service.subtitles.opensubtitles:/usr/lib/python27.zip:/usr/lib/python2.7:/usr/lib/python2.7/plat-linux2:/usr/lib/python2.7/lib-tk:/usr/lib/python2.7/lib-old:/usr/lib/python2.7/lib-dynload:/usr/lib/python2.7/site-packages:/usr/lib/python2.7/site-packages/gtk-2.0
12:31:41 T:139760697861888 DEBUG: CPythonInvoker(27, /storage/.kodi/addons/service.subtitles.opensubtitles/service.py): entering source directory /storage/.kodi/addons/service.subtitles.opensubtitles
12:31:41 T:139760697861888 DEBUG: CPythonInvoker(27, /storage/.kodi/addons/service.subtitles.opensubtitles/service.py): instantiating addon using automatically obtained id of "service.subtitles.opensubtitles" dependent on version 2.1.0 of the xbmc.python api
12:31:41 T:139763302070336 DEBUG: LIRC: Update - NEW at 233806:160 0 KEY_OK_UP devinput (KEY_OK_UP)
12:31:42 T:139760697861888 DEBUG: ### [OSUtilities] - Download Using XMLRPC
12:31:42 T:139760697861888 INFO: CPythonInvoker(27, /storage/.kodi/addons/service.subtitles.opensubtitles/service.py): script successfully run
12:31:42 T:139762379773696 DEBUG: OnDownloadComplete - Saving subtitle special://temp/The 100 S01E02 Signes de vie.fr.srt to /storage/video2/Series/The 100 (2014)/Season 1/The 100 S01E02 Signes de vie.fr.srt
12:31:42 T:139760808883968 DEBUG: GetExternalStreamDetailsFromFilename - Language = 'fre' / Name = '(Externe)' / Flag = '0' from /storage/video2/Series/The 100 (2014)/Season 1/The 100 S01E02 Signes de vie.fr.srt
12:31:42 T:139760808883968 NOTICE: Closing stream player 3
12:31:42 T:139760808883968 NOTICE: Opening stream: 0 source: 1025
12:31:42 T:139760697861888 INFO: Python script stopped
12:31:42 T:139760697861888 DEBUG: Thread LanguageInvoker 139760697861888 terminating
12:31:42 T:139763302070336 DEBUG: ------ Window Deinit (DialogSubtitles.xml) ------
12:31:42 T:139763302061824 DEBUG: CAnnouncementManager - Announcement: OnPlay from xbmc
12:31:42 T:139763302061824 DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnPlay
12:31:42 T:139760628635392 DEBUG: CDVDAudio::Resume - resume audio stream
12:31:42 T:139760603457280 DEBUG: CVideoPlayerVideo::CalcDropRequirement - hurry: 1
12:31:42 T:139763201865472 DEBUG: ActiveAE - start sync of audio stream
12:31:42 T:139760603457280 DEBUG: CVideoPlayerVideo::CalcDropRequirement - hurry: 1
12:31:42 T:139763201865472 DEBUG: Previous line repeats 2 times.
12:31:42 T:139763201865472 DEBUG: ActiveAE::SyncStream - average error of 210.734221, start adjusting
12:31:42 T:139763201865472 DEBUG: ActiveAE::SyncStream - average error 29.391795, last average error: 210.734221
12:31:42 T:139763201865472 DEBUG: ActiveAE::SyncStream - average error of -2.608576, start adjusting
12:31:42 T:139763201865472 DEBUG: ActiveAE::SyncStream - average error -2.608576 below threshold of 30.000000
12:31:43 T:139762097878784 DEBUG: CLEANSUBS >> GONNA STOP TIMER - NOT IN SUBS DIALOG ANYMORE
12:31:44 T:139762097878784 DEBUG: CLEANSUBS >> STOPPING TIMER
12:31:44 T:139760628635392 DEBUG: CDVDClock::ErrorAdjust - CVideoPlayerAudio::OutputPacket - error:20056.161718, adjusted:41708.333333
12:31:44 T:139760603457280 DEBUG: CPullupCorrection: detected pattern of length 1: 41708.33, frameduration: 41708.333333
12:31:45 T:139763302070336 DEBUG: ------ Window Deinit (DialogSeekBar.xml) ------
12:31:47 T:139763302070336 DEBUG: LIRC: Update - NEW at 239082:a4 0 KEY_PLAYPAUSE devinput (KEY_PLAYPAUSE)
12:31:47 T:139763302070336 DEBUG: OnKey: homepage (0xea) pressed, action is PlayPause
12:31:47 T:139763302061824 DEBUG: CAnnouncementManager - Announcement: OnPause from xbmc
12:31:47 T:139763302070336 DEBUG: ------ Window Init (DialogSeekBar.xml) ------
12:31:47 T:139763302061824 DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnPause
12:31:47 T:139760628635392 DEBUG: CDVDAudio::Pause - pausing audio stream
12:31:47 T:139760603457280 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
12:31:47 T:139763302070336 DEBUG: LIRC: Update - NEW at 239637:a4 0 KEY_PLAYPAUSE_UP devinput (KEY_PLAYPAUSE_UP)
12:32:11 T:139760706254592 DEBUG: Thread JobWorker 139760706254592 terminating (autodelete)
12:32:11 T:139762388166400 DEBUG: Thread JobWorker 139762388166400 terminating (autodelete)
12:32:11 T:139761171814144 DEBUG: Thread JobWorker 139761171814144 terminating (autodelete)
12:32:12 T:139762379773696 DEBUG: Thread JobWorker 139762379773696 terminating (autodelete)
12:32:51 T:139763302070336 NOTICE: NFS is idle. Closing the remaining connections.
12:34:20 T:139763302070336 DEBUG: LIRC: Update - NEW at 392422:80 0 KEY_STOP devinput (KEY_STOP)
12:34:20 T:139763302070336 DEBUG: OnKey: guide (0xe0) pressed, action is Stop
12:34:20 T:139763302070336 NOTICE: CVideoPlayer::CloseFile()
12:34:20 T:139763302070336 NOTICE: VideoPlayer: waiting for threads to exit
12:34:20 T:139760808883968 NOTICE: CVideoPlayer::OnExit()
12:34:20 T:139760808883968 NOTICE: Closing stream player 1
12:34:20 T:139760808883968 NOTICE: Waiting for audio thread to exit
12:34:20 T:139760628635392 ERROR: Got MSGQ_ABORT or MSGO_IS_ERROR return true
12:34:20 T:139760628635392 NOTICE: thread end: CVideoPlayerAudio::OnExit()
12:34:20 T:139760628635392 DEBUG: Thread VideoPlayerAudio 139760628635392 terminating
12:34:20 T:139760808883968 NOTICE: Closing audio device
12:34:20 T:139760808883968 DEBUG: CDVDAudio::Flush - flush audio stream
12:34:20 T:139763201865472 DEBUG: CActiveAE::DiscardStream - audio stream deleted
12:34:20 T:139763201865472 DEBUG: CActiveAE::ClearDiscardedBuffers - buffer pool deleted
12:34:20 T:139760808883968 DEBUG: Previous line repeats 2 times.
12:34:20 T:139760808883968 NOTICE: Deleting audio codec
12:34:20 T:139763193472768 INFO: CActiveAESink::OpenSink - initialize sink
12:34:20 T:139760808883968 NOTICE: Closing stream player 2
12:34:20 T:139760808883968 NOTICE: waiting for video thread to exit
12:34:20 T:139763193472768 DEBUG: CActiveAESink::OpenSink - trying to open device ALSA:hdmi:CARD=PCH,DEV=2
12:34:20 T:139763193472768 INFO: CAESinkALSA::Initialize - Attempting to open device "hdmi:CARD=PCH,DEV=2"
12:34:20 T:139760603457280 ERROR: Got MSGQ_ABORT or MSGO_IS_ERROR return true
12:34:20 T:139760603457280 NOTICE: thread end: video_thread
12:34:20 T:139760603457280 DEBUG: Thread VideoPlayerVideo 139760603457280 terminating
12:34:20 T:139760808883968 NOTICE: deleting video codec
12:34:20 T:139760808883968 DEBUG: VAAPI::Release pre-cleanup
12:34:20 T:139763193472768 INFO: CAESinkALSA::Initialize - Opened device "hdmi:CARD=PCH,DEV=2,AES0=0x04,AES1=0x82,AES2=0x00,AES3=0x00"
12:34:20 T:139760808883968 NOTICE: Closing stream player 3
12:34:20 T:139763193472768 INFO: CAESinkALSA::InitializeHW - Your hardware does not support AE_FMT_FLOAT, trying other formats
12:34:20 T:139763193472768 INFO: CAESinkALSA::InitializeHW - Using data format AE_FMT_S32NE
12:34:20 T:139763193472768 DEBUG: CAESinkALSA::InitializeHW - Request: periodSize 2205, bufferSize 8820
12:34:20 T:139760808883968 DEBUG: OnPlayBackStopped: play state was 2, starting 0
12:34:20 T:139763302061824 DEBUG: CAnnouncementManager - Announcement: OnStop from xbmc
12:34:20 T:139760808883968 DEBUG: Thread VideoPlayer 139760808883968 terminating
12:34:20 T:139763302070336 NOTICE: VideoPlayer: finished waiting
12:34:20 T:139763302061824 DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnStop
12:34:20 T:139763302070336 DEBUG: DeleteRenderer - deleting renderer
12:34:20 T:139763302070336 NOTICE: VAAPI::Close
12:34:20 T:139760655914752 NOTICE: COutput::OnExit: Output Thread terminated
12:34:20 T:139760655914752 DEBUG: Thread Vaapi-Output 139760655914752 terminating
12:34:20 T:139763302070336 DEBUG: VAAPI::FiniVAAPIOutput destroying 5 video surfaces
12:34:20 T:139763302070336 NOTICE: VAAPI::Close - closing decoder context
12:34:20 T:139763193472768 DEBUG: CAESinkALSA::InitializeHW - Got: periodSize 2205, bufferSize 8820
12:34:20 T:139763193472768 DEBUG: CAESinkALSA::InitializeHW - Setting timeout to 200 ms
12:34:20 T:139762097878784 DEBUG: CLEANSUBS >> PLAYBACK >>STOPPED<<