search

xbmc / inputstream.adaptive

kodi inputstream addon for several manifest types
Other
453 stars 242 forks source link

Multiple Periods/IChapter interface: external subtitles get out of sync when seeking forward with mouse on progress bar #324

Closed mediaminister closed 2 years ago

mediaminister commented 5 years ago

Describe the bug

When seeking forward with the mouse on the Kodi progress bar, external subtitles are not synchronized properly.

To Reproduce

Steps to reproduce the behavior:

  1. Download and build VTM GO Add-on
  2. Install VTM GO Add-on in Kodi 19.0-ALPHA1 master branch
  3. Open VTM Go Add-on and go to A-Z --> 13 Geboden
  4. Play 1x02. Aflevering 2
  5. Watch the pre-roll advertisements
  6. Watch the recap of the previous episode and ascertain that the subtitles are in sync
  7. Seek forward with the mouse pointer on the Kodi progress bar to about 15 minutes in the program
  8. Ascertain that the subtitles are out of sync
  9. (Seek a couple of seconds backwards with the mouse pointer on the Kodi progress bar and subtitles are in sync again)

Expected behavior

When seeking forward with the mouse on the Kodi progress bar, external subtitles should be synchronized properly.

Additional context

Log (if available)

Full Kodi Debug Log: kodi.log External WEBVTT Subtitles: 13GEBODEN2_1F633728_272ef5ea-0eaa-4b0a-9a8f-b72ba8d7707e.nl-NL.txt

matthuisman commented 5 years ago

This may be same as my issue I was having here: https://github.com/peak3d/inputstream.adaptive/issues/287#issuecomment-529689654

My issue was just fixed with this commit: https://github.com/peak3d/inputstream.adaptive/commit/98c3062079b27e17cc2ba2efbebc3c75904a2e48

Or, see peak3ds pull request: https://github.com/xbmc/xbmc/pull/16658

Under his open questions "I see also issues when having subtitles not in all chapters, they usually start already during stream 1 / 2 even they belong to stream 3."

mediaminister commented 5 years ago

No, this is another issue, I tested this again with the avsync PR and InputStream Adaptive master branch and it is not fixed yet.

glennguy commented 3 years ago

@mediaminister is this fixed with changes introduced in #685 (2.6.16)?

mediaminister commented 3 years ago

No, not fixed. It only happens when seeking forward with mouse. Seeking forward with mouse, external subtitles get out of sync:

2021-06-09 10:45:29.209 T:31556   DEBUG <general>: ProcessMouse: trying mouse action leftclick
2021-06-09 10:45:29.211 T:31624   DEBUG <general>: CVideoPlayer::SetCaching - caching state 2
2021-06-09 10:45:29.211 T:31624   DEBUG <general>: CDVDClock::SetSpeedAdjust - adjusted:0.000000
2021-06-09 10:45:29.211 T:31624   DEBUG <general>: demuxer seek to: 833826.000000
2021-06-09 10:45:29.211 T:31624    INFO <general>: AddOnLog: inputstream.adaptive: PosTime (833826)
2021-06-09 10:45:29.211 T:31643   DEBUG <general>: CurlFile::ParseAndCorrectUrl() adding custom header option 'connection: keep-alive'
2021-06-09 10:45:29.211 T:31643   DEBUG <general>: CurlFile::Open(0x7f4350025b90) https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/video-C9579F33725E44D4EA1E538E3A72A03D2495BE806A406E-200.mp4?hdntl=exp=1623249905~acl=/*~hmac=248be51bfc73de05a03dd5aaedd5c57949dcb601d6aab721e43a767dd60b941a
2021-06-09 10:45:29.225 T:31637   DEBUG <general>: CDVDAudio::Pause - pausing audio stream
2021-06-09 10:45:29.254 T:31624    INFO <general>: AddOnLog: inputstream.adaptive: seekTime(795.5) for Stream:1 continues at 796.0 (PTS: 796080000)
2021-06-09 10:45:29.255 T:31644   DEBUG <general>: CurlFile::ParseAndCorrectUrl() adding custom header option 'connection: keep-alive'
2021-06-09 10:45:29.255 T:31644   DEBUG <general>: CurlFile::Open(0x7f43541289b0) https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/audio-B0A7438C236B541D7E6CACD771FC0E897A370B844B1634-200.mp4?hdntl=exp=1623249905~acl=/*~hmac=248be51bfc73de05a03dd5aaedd5c57949dcb601d6aab721e43a767dd60b941a
2021-06-09 10:45:29.304 T:31644   DEBUG <general>: AddOnLog: inputstream.adaptive: Download finished: https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/audio-B0A7438C236B541D7E6CACD771FC0E897A370B844B1634-200.mp4?hdntl=exp=1623249905~acl=/*~hmac=248be51bfc73de05a03dd5aaedd5c57949dcb601d6aab721e43a767dd60b941a , avg speed: 6924976.85byte/s, current speed: 2057591.00byte/s
2021-06-09 10:45:29.304 T:31624    INFO <general>: AddOnLog: inputstream.adaptive: seekTime(796.0) for Stream:3 continues at 796.0 (PTS: 796072925)
2021-06-09 10:45:29.311 T:31624    INFO <general>: AddOnLog: inputstream.adaptive: seekTime(795.5) for Stream:1 continues at 796.0 (PTS: 796080000)
2021-06-09 10:45:29.311 T:31624    INFO <general>: AddOnLog: inputstream.adaptive: seekTime(796.0) for Stream:3 continues at 796.0 (PTS: 796072925)
2021-06-09 10:45:29.311 T:31624   DEBUG <general>: demuxer seek to: 833826.000000, success
2021-06-09 10:45:29.311 T:31624   DEBUG <general>: CVideoPlayer::FlushBuffers - flushing buffers
2021-06-09 10:45:29.339 T:31637   DEBUG <general>: CDVDAudio::Flush - flush audio stream
2021-06-09 10:45:29.339 T:31637   DEBUG <general>: CDVDAudio::Pause - pausing audio stream
2021-06-09 10:45:29.359 T:31634 WARNING <general>: OutputPicture - timeout waiting for buffer
2021-06-09 10:45:29.360 T:31634   DEBUG <general>: CVideoPlayerVideo - CDVDMsg::GENERAL_SYNCHRONIZE
2021-06-09 10:45:29.361 T:31637   DEBUG <general>: CVideoPlayerAudio - CDVDMsg::GENERAL_SYNCHRONIZE
2021-06-09 10:45:29.361 T:31624   DEBUG <general>: CVideoPlayer - CDVDMsg::GENERAL_SYNCHRONIZE
2021-06-09 10:45:29.366 T:31634   DEBUG <general>: CVideoPlayerVideo - Stillframe left, switching to normal playback
2021-06-09 10:45:29.367 T:31634    INFO <general>: CVDPAU::Release pre-cleanup
2021-06-09 10:45:29.371 T:31646    INFO <general>: CMixer::OnExit: Output Thread terminated
2021-06-09 10:45:29.371 T:31646   DEBUG <general>: Thread Vdpau Mixer 139927328577280 terminating
2021-06-09 10:45:29.374 T:31624   DEBUG <general>: CVideoPlayer::HandleMessages - player started 1
2021-06-09 10:45:29.375 T:31588   DEBUG <general>: OnAVChange: CApplication::OnAVChange
2021-06-09 10:45:29.417 T:31582    INFO <general>: [plugin.video.vtm.go] [resources.lib.service] Player: [onPlayBackSeek] called
2021-06-09 10:45:29.417 T:31582    INFO <general>: [plugin.video.vtm.go] [resources.lib.service] Player: [onAVChange] called
2021-06-09 10:45:29.430 T:31644   DEBUG <general>: CurlFile::ParseAndCorrectUrl() adding custom header option 'connection: keep-alive'
2021-06-09 10:45:29.430 T:31644   DEBUG <general>: CurlFile::Open(0x7f4354127ea0) https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/audio-B0A7438C236B541D7E6CACD771FC0E897A370B844B1634-201.mp4?hdntl=exp=1623249905~acl=/*~hmac=248be51bfc73de05a03dd5aaedd5c57949dcb601d6aab721e43a767dd60b941a
2021-06-09 10:45:29.447 T:31634   DEBUG <general>: CDVDVideoCodecFFmpeg - Updated codec: ff-h264
2021-06-09 10:45:29.451 T:31643   DEBUG <general>: AddOnLog: inputstream.adaptive: Download finished: https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/video-C9579F33725E44D4EA1E538E3A72A03D2495BE806A406E-200.mp4?hdntl=exp=1623249905~acl=/*~hmac=248be51bfc73de05a03dd5aaedd5c57949dcb601d6aab721e43a767dd60b941a , avg speed: 7522583.00byte/s, current speed: 7522583.00byte/s
2021-06-09 10:45:29.463 T:31644   DEBUG <general>: AddOnLog: inputstream.adaptive: Download finished: https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/audio-B0A7438C236B541D7E6CACD771FC0E897A370B844B1634-201.mp4?hdntl=exp=1623249905~acl=/*~hmac=248be51bfc73de05a03dd5aaedd5c57949dcb601d6aab721e43a767dd60b941a , avg speed: 7092861.97byte/s, current speed: 3059212.00byte/s
2021-06-09 10:45:29.481 T:31634   DEBUG <general>: CDVDVideoCodecFFmpeg - Updated codec: ff-h264-vdpau
2021-06-09 10:45:29.484 T:31634    INFO <general>:  (VDPAU) screenWidth:1280 vidWidth:1280 surfaceWidth:1280
2021-06-09 10:45:29.484 T:31634    INFO <general>:  (VDPAU) screenHeight:720 vidHeight:720 surfaceHeight:720
2021-06-09 10:45:29.503 T:31643   DEBUG <general>: CurlFile::ParseAndCorrectUrl() adding custom header option 'connection: keep-alive'
2021-06-09 10:45:29.503 T:31643   DEBUG <general>: CurlFile::Open(0x7f43500250b0) https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/video-C9579F33725E44D4EA1E538E3A72A03D2495BE806A406E-201.mp4?hdntl=exp=1623249905~acl=/*~hmac=248be51bfc73de05a03dd5aaedd5c57949dcb601d6aab721e43a767dd60b941a
2021-06-09 10:45:29.517 T:31667   DEBUG <general>: Thread Vdpau Output start, auto delete: false
2021-06-09 10:45:29.517 T:31667    INFO <general>: COutput::OnStartup: Output Thread created
2021-06-09 10:45:29.517 T:31668   DEBUG <general>: Thread Vdpau Mixer start, auto delete: false
2021-06-09 10:45:29.517 T:31668    INFO <general>: CMixer::OnStartup: Output Thread created
2021-06-09 10:45:29.517 T:31668    INFO <general>:  (VDPAU) Creating the video mixer
2021-06-09 10:45:29.523 T:31667    INFO <general>: VDPAU::COutput::InitBufferPool - Output Surface created
2021-06-09 10:45:29.564 T:31634   DEBUG <general>: Skipped 6 duplicate messages..
2021-06-09 10:45:29.564 T:31634   DEBUG <general>: CRenderManager::Configure - change configuration. 1280x720. display: 1280x720. framerate: 25.00.
2021-06-09 10:45:29.565 T:31556   DEBUG <general>: DeleteRenderer - deleting renderer
2021-06-09 10:45:29.566 T:31556    INFO <general>:  (VDPAU) Close
2021-06-09 10:45:29.566 T:31556    INFO <general>:  (VDPAU) FiniVDPAUOutput
2021-06-09 10:45:29.570 T:31645    INFO <general>: COutput::OnExit: Output Thread terminated
2021-06-09 10:45:29.570 T:31645   DEBUG <general>: Thread Vdpau Output 139927336969984 terminating
2021-06-09 10:45:29.586 T:31556   DEBUG <general>: LinuxRendererGL: Cleaning up GL resources
2021-06-09 10:45:29.586 T:31556    INFO <general>: CInteropState::Init: vdpau gl interop initialized
2021-06-09 10:45:29.587 T:31556    INFO <general>: GL: Using VDPAU render method
2021-06-09 10:45:29.587 T:31556    INFO <general>: GL: Using GL_ARB_pixel_buffer_object
2021-06-09 10:45:29.587 T:31556    INFO <general>: Using GL_TEXTURE_2D
2021-06-09 10:45:29.587 T:31556   DEBUG <general>: CRenderManager::Configure - 5
2021-06-09 10:45:29.614 T:31624   DEBUG <general>: CVideoPlayer::HandleMessages - player started 2
2021-06-09 10:45:29.614 T:31624   DEBUG <general>: CVideoPlayer::SetCaching - caching state 3
2021-06-09 10:45:29.614 T:31574   DEBUG <general>: OnAVChange: CApplication::OnAVChange
2021-06-09 10:45:29.614 T:31624   DEBUG <general>: CDVDClock::SetSpeedAdjust - adjusted:0.000000
2021-06-09 10:45:29.614 T:31624   DEBUG <general>: CVideoPlayer::SetCaching - caching state 0
2021-06-09 10:45:29.614 T:31624   DEBUG <general>: CDVDClock::SetSpeedAdjust - adjusted:0.000000
2021-06-09 10:45:29.614 T:31624   DEBUG <general>: VideoPlayer::Sync - Audio - pts: 834668564.000000, cache: 301859.408617, totalcache: 900000.035763
2021-06-09 10:45:29.614 T:31624   DEBUG <general>: VideoPlayer::Sync - Video - pts: 834397000.000000, cache: 50000.000000, totalcache: 100000.000000
2021-06-09 10:45:29.614 T:31637   DEBUG <general>: CVideoPlayerAudio - CDVDMsg::GENERAL_RESYNC(834297000.000000), level: 48, cache: 575528.115617
2021-06-09 10:45:29.614 T:31637   DEBUG <general>: CDVDAudio::Resume - resume audio stream
2021-06-09 10:45:29.615 T:31565   DEBUG <general>: ActiveAE - start sync of audio stream
2021-06-09 10:45:29.616 T:31634   DEBUG <general>: CVideoPlayerVideo - CDVDMsg::GENERAL_RESYNC(834297000.000000)
2021-06-09 10:45:29.617 T:31582    INFO <general>: [plugin.video.vtm.go] [resources.lib.service] Player: [onAVChange] called
2021-06-09 10:45:29.697 T:31644   DEBUG <general>: CurlFile::ParseAndCorrectUrl() adding custom header option 'connection: keep-alive'
2021-06-09 10:45:29.697 T:31644   DEBUG <general>: CurlFile::Open(0x7f43541289b0) https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/audio-B0A7438C236B541D7E6CACD771FC0E897A370B844B1634-202.mp4?hdntl=exp=1623249905~acl=/*~hmac=248be51bfc73de05a03dd5aaedd5c57949dcb601d6aab721e43a767dd60b941a
2021-06-09 10:45:29.733 T:31565   DEBUG <general>: ActiveAE::SyncStream - average error of -231.696851, start adjusting
2021-06-09 10:45:29.733 T:31565   DEBUG <general>: ActiveAE::SyncStream - average error -0.018846 below threshold of 30.000000
2021-06-09 10:45:29.742 T:31644   DEBUG <general>: AddOnLog: inputstream.adaptive: Download finished: https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/audio-B0A7438C236B541D7E6CACD771FC0E897A370B844B1634-202.mp4?hdntl=exp=1623249905~acl=/*~hmac=248be51bfc73de05a03dd5aaedd5c57949dcb601d6aab721e43a767dd60b941a , avg speed: 6631497.70byte/s, current speed: 2288545.00byte/s
2021-06-09 10:45:29.747 T:31643   DEBUG <general>: AddOnLog: inputstream.adaptive: Download finished: https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/video-C9579F33725E44D4EA1E538E3A72A03D2495BE806A406E-201.mp4?hdntl=exp=1623249905~acl=/*~hmac=248be51bfc73de05a03dd5aaedd5c57949dcb601d6aab721e43a767dd60b941a , avg speed: 6506736.00byte/s, current speed: 6506736.00byte/s
2021-06-09 10:45:29.758 T:31643   DEBUG <general>: CurlFile::ParseAndCorrectUrl() adding custom header option 'connection: keep-alive'
2021-06-09 10:45:29.758 T:31643   DEBUG <general>: CurlFile::Open(0x7f435001fef0) https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/video-C9579F33725E44D4EA1E538E3A72A03D2495BE806A406E-202.mp4?hdntl=exp=1623249905~acl=/*~hmac=248be51bfc73de05a03dd5aaedd5c57949dcb601d6aab721e43a767dd60b941a
2021-06-09 10:45:29.961 T:31643   DEBUG <general>: AddOnLog: inputstream.adaptive: Download finished: https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/video-C9579F33725E44D4EA1E538E3A72A03D2495BE806A406E-202.mp4?hdntl=exp=1623249905~acl=/*~hmac=248be51bfc73de05a03dd5aaedd5c57949dcb601d6aab721e43a767dd60b941a , avg speed: 7312536.00byte/s, current speed: 7312536.00byte/s
2021-06-09 10:45:30.782 T:31637   DEBUG <general>: CDVDClock::ErrorAdjust - CVideoPlayerAudio::OutputPacket - error:-49974.027085, adjusted:-49974.027085
2021-06-09 10:45:32.010 T:31644   DEBUG <general>: CurlFile::ParseAndCorrectUrl() adding custom header option 'connection: keep-alive'
2021-06-09 10:45:32.011 T:31644   DEBUG <general>: CurlFile::Open(0x7f435401f040) https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/audio-B0A7438C236B541D7E6CACD771FC0E897A370B844B1634-203.mp4?hdntl=exp=1623249905~acl=/*~hmac=248be51bfc73de05a03dd5aaedd5c57949dcb601d6aab721e43a767dd60b941a
2021-06-09 10:45:32.036 T:31644   DEBUG <general>: AddOnLog: inputstream.adaptive: Download finished: https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/audio-B0A7438C236B541D7E6CACD771FC0E897A370B844B1634-203.mp4?hdntl=exp=1623249905~acl=/*~hmac=248be51bfc73de05a03dd5aaedd5c57949dcb601d6aab721e43a767dd60b941a , avg speed: 6997277.21byte/s, current speed: 4037560.00byte/s
2021-06-09 10:45:32.583 T:31556   DEBUG <general>: ------ Window Deinit (Pointer.xml) ------
2021-06-09 10:45:33.213 T:31643   DEBUG <general>: CurlFile::ParseAndCorrectUrl() adding custom header option 'connection: keep-alive'
2021-06-09 10:45:33.213 T:31643   DEBUG <general>: CurlFile::Open(0x7f4350024fa0) https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/video-C9579F33725E44D4EA1E538E3A72A03D2495BE806A406E-203.mp4?hdntl=exp=1623249905~acl=/*~hmac=248be51bfc73de05a03dd5aaedd5c57949dcb601d6aab721e43a767dd60b941a
2021-06-09 10:45:33.468 T:31643   DEBUG <general>: AddOnLog: inputstream.adaptive: Download finished: https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/video-C9579F33725E44D4EA1E538E3A72A03D2495BE806A406E-203.mp4?hdntl=exp=1623249905~acl=/*~hmac=248be51bfc73de05a03dd5aaedd5c57949dcb601d6aab721e43a767dd60b941a , avg speed: 6243000.00byte/s, current speed: 6243000.00byte/s

Seeking backwards with mouse works 100% perfect:

2021-06-09 10:53:00.240 T:31701   DEBUG <general>: ProcessMouse: trying mouse action leftclick
2021-06-09 10:53:00.248 T:31939   DEBUG <general>: CVideoPlayer::SetCaching - caching state 2
2021-06-09 10:53:00.248 T:31939   DEBUG <general>: CDVDClock::SetSpeedAdjust - adjusted:0.000000
2021-06-09 10:53:00.248 T:31939   DEBUG <general>: demuxer seek to: 509163.000000
2021-06-09 10:53:00.248 T:31939    INFO <general>: AddOnLog: inputstream.adaptive: PosTime (509163)
2021-06-09 10:53:00.248 T:31952   DEBUG <general>: CurlFile::ParseAndCorrectUrl() adding custom header option 'connection: keep-alive'
2021-06-09 10:53:00.248 T:31952   DEBUG <general>: CurlFile::Open(0x7f67600f05b0) https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/video-C9579F33725E44D4EA1E538E3A72A03D2495BE806A406E-121.mp4?hdntl=exp=1623250356~acl=/*~hmac=8aad39aef4631fcdf77a0feaab235e27fd8f49a8c3524dd3f471dd11095d936d
2021-06-09 10:53:00.274 T:31947   DEBUG <general>: CDVDAudio::Pause - pausing audio stream
2021-06-09 10:53:00.308 T:31939    INFO <general>: AddOnLog: inputstream.adaptive: seekTime(476.4) for Stream:1 continues at 480.0 (PTS: 480080000)
2021-06-09 10:53:00.308 T:31953   DEBUG <general>: CurlFile::ParseAndCorrectUrl() adding custom header option 'connection: keep-alive'
2021-06-09 10:53:00.308 T:31953   DEBUG <general>: CurlFile::Open(0x7f6750110760) https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/audio-B0A7438C236B541D7E6CACD771FC0E897A370B844B1634-121.mp4?hdntl=exp=1623250356~acl=/*~hmac=8aad39aef4631fcdf77a0feaab235e27fd8f49a8c3524dd3f471dd11095d936d
2021-06-09 10:53:00.364 T:31953   DEBUG <general>: AddOnLog: inputstream.adaptive: Download finished: https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/audio-B0A7438C236B541D7E6CACD771FC0E897A370B844B1634-121.mp4?hdntl=exp=1623250356~acl=/*~hmac=8aad39aef4631fcdf77a0feaab235e27fd8f49a8c3524dd3f471dd11095d936d , avg speed: 6559440.87byte/s, current speed: 1800035.00byte/s
2021-06-09 10:53:00.365 T:31939    INFO <general>: AddOnLog: inputstream.adaptive: seekTime(480.0) for Stream:3 continues at 480.0 (PTS: 480072562)
2021-06-09 10:53:00.371 T:31939    INFO <general>: AddOnLog: inputstream.adaptive: seekTime(476.4) for Stream:1 continues at 480.0 (PTS: 480080000)
2021-06-09 10:53:00.371 T:31939    INFO <general>: AddOnLog: inputstream.adaptive: seekTime(480.0) for Stream:3 continues at 480.0 (PTS: 480072562)
2021-06-09 10:53:00.371 T:31939   DEBUG <general>: demuxer seek to: 509163.000000, success
2021-06-09 10:53:00.371 T:31939   DEBUG <general>: CVideoPlayer::FlushBuffers - flushing buffers
2021-06-09 10:53:00.389 T:31945 WARNING <general>: OutputPicture - timeout waiting for buffer
2021-06-09 10:53:00.444 T:31947   DEBUG <general>: CDVDAudio::Flush - flush audio stream
2021-06-09 10:53:00.444 T:31947   DEBUG <general>: CDVDAudio::Pause - pausing audio stream
2021-06-09 10:53:00.444 T:31947   DEBUG <general>: CVideoPlayerAudio - CDVDMsg::GENERAL_SYNCHRONIZE
2021-06-09 10:53:00.444 T:31945   DEBUG <general>: CVideoPlayerVideo - CDVDMsg::GENERAL_SYNCHRONIZE
2021-06-09 10:53:00.444 T:31939   DEBUG <general>: CVideoPlayer - CDVDMsg::GENERAL_SYNCHRONIZE
2021-06-09 10:53:00.447 T:31729    INFO <general>: [plugin.video.vtm.go] [resources.lib.service] Player: [onPlayBackSeek] called
2021-06-09 10:53:00.448 T:31945   DEBUG <general>: CVideoPlayerVideo - Stillframe left, switching to normal playback
2021-06-09 10:53:00.448 T:31945    INFO <general>: CVDPAU::Release pre-cleanup
2021-06-09 10:53:00.451 T:31978    INFO <general>: CMixer::OnExit: Output Thread terminated
2021-06-09 10:53:00.451 T:31978   DEBUG <general>: Thread Vdpau Mixer 140081924232960 terminating
2021-06-09 10:53:00.458 T:31939   DEBUG <general>: CVideoPlayer::HandleMessages - player started 1
2021-06-09 10:53:00.458 T:31922   DEBUG <general>: OnAVChange: CApplication::OnAVChange
2021-06-09 10:53:00.470 T:31952   DEBUG <general>: AddOnLog: inputstream.adaptive: Download finished: https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/video-C9579F33725E44D4EA1E538E3A72A03D2495BE806A406E-121.mp4?hdntl=exp=1623250356~acl=/*~hmac=8aad39aef4631fcdf77a0feaab235e27fd8f49a8c3524dd3f471dd11095d936d , avg speed: 7140574.00byte/s, current speed: 7140574.00byte/s
2021-06-09 10:53:00.510 T:31945   DEBUG <general>: CDVDVideoCodecFFmpeg - Updated codec: ff-h264
2021-06-09 10:53:00.520 T:31953   DEBUG <general>: CurlFile::ParseAndCorrectUrl() adding custom header option 'connection: keep-alive'
2021-06-09 10:53:00.520 T:31953   DEBUG <general>: CurlFile::Open(0x7f6750110aa0) https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/audio-B0A7438C236B541D7E6CACD771FC0E897A370B844B1634-122.mp4?hdntl=exp=1623250356~acl=/*~hmac=8aad39aef4631fcdf77a0feaab235e27fd8f49a8c3524dd3f471dd11095d936d
2021-06-09 10:53:00.548 T:31729    INFO <general>: [plugin.video.vtm.go] [resources.lib.service] Player: [onAVChange] called
2021-06-09 10:53:00.564 T:31945   DEBUG <general>: CDVDVideoCodecFFmpeg - Updated codec: ff-h264-vdpau
2021-06-09 10:53:00.570 T:31945    INFO <general>:  (VDPAU) screenWidth:1280 vidWidth:1280 surfaceWidth:1280
2021-06-09 10:53:00.570 T:31945    INFO <general>:  (VDPAU) screenHeight:720 vidHeight:720 surfaceHeight:720
2021-06-09 10:53:00.596 T:31986   DEBUG <general>: Thread Vdpau Output start, auto delete: false
2021-06-09 10:53:00.596 T:31986    INFO <general>: COutput::OnStartup: Output Thread created
2021-06-09 10:53:00.596 T:31987   DEBUG <general>: Thread Vdpau Mixer start, auto delete: false
2021-06-09 10:53:00.596 T:31987    INFO <general>: CMixer::OnStartup: Output Thread created
2021-06-09 10:53:00.596 T:31987    INFO <general>:  (VDPAU) Creating the video mixer
2021-06-09 10:53:00.601 T:31986    INFO <general>: VDPAU::COutput::InitBufferPool - Output Surface created
2021-06-09 10:53:00.635 T:31953   DEBUG <general>: Skipped 3 duplicate messages..
2021-06-09 10:53:00.635 T:31953   DEBUG <general>: AddOnLog: inputstream.adaptive: Download finished: https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/audio-B0A7438C236B541D7E6CACD771FC0E897A370B844B1634-122.mp4?hdntl=exp=1623250356~acl=/*~hmac=8aad39aef4631fcdf77a0feaab235e27fd8f49a8c3524dd3f471dd11095d936d , avg speed: 6537411.81byte/s, current speed: 878208.00byte/s
2021-06-09 10:53:00.637 T:31986    INFO <general>: VDPAU::COutput::InitBufferPool - Output Surface created
2021-06-09 10:53:00.655 T:31952   DEBUG <general>: Skipped 1 duplicate messages..
2021-06-09 10:53:00.655 T:31952   DEBUG <general>: CurlFile::ParseAndCorrectUrl() adding custom header option 'connection: keep-alive'
2021-06-09 10:53:00.655 T:31952   DEBUG <general>: CurlFile::Open(0x7f67600f08f0) https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/video-C9579F33725E44D4EA1E538E3A72A03D2495BE806A406E-122.mp4?hdntl=exp=1623250356~acl=/*~hmac=8aad39aef4631fcdf77a0feaab235e27fd8f49a8c3524dd3f471dd11095d936d
2021-06-09 10:53:00.657 T:31986    INFO <general>: VDPAU::COutput::InitBufferPool - Output Surface created
2021-06-09 10:53:00.657 T:31945   DEBUG <general>: CRenderManager::Configure - change configuration. 1280x720. display: 1280x720. framerate: 25.00.
2021-06-09 10:53:00.658 T:31701   DEBUG <general>: DeleteRenderer - deleting renderer
2021-06-09 10:53:00.658 T:31701    INFO <general>:  (VDPAU) Close
2021-06-09 10:53:00.658 T:31701    INFO <general>:  (VDPAU) FiniVDPAUOutput
2021-06-09 10:53:00.661 T:31977    INFO <general>: COutput::OnExit: Output Thread terminated
2021-06-09 10:53:00.661 T:31977   DEBUG <general>: Thread Vdpau Output 140082883315456 terminating
2021-06-09 10:53:00.670 T:31701   DEBUG <general>: LinuxRendererGL: Cleaning up GL resources
2021-06-09 10:53:00.670 T:31701    INFO <general>: CInteropState::Init: vdpau gl interop initialized
2021-06-09 10:53:00.671 T:31701    INFO <general>: GL: Using VDPAU render method
2021-06-09 10:53:00.671 T:31701    INFO <general>: GL: Using GL_ARB_pixel_buffer_object
2021-06-09 10:53:00.671 T:31701    INFO <general>: Using GL_TEXTURE_2D
2021-06-09 10:53:00.671 T:31701   DEBUG <general>: CRenderManager::Configure - 5
2021-06-09 10:53:00.718 T:31939   DEBUG <general>: CVideoPlayer::HandleMessages - player started 2
2021-06-09 10:53:00.718 T:31921   DEBUG <general>: OnAVChange: CApplication::OnAVChange
2021-06-09 10:53:00.718 T:31939   DEBUG <general>: CVideoPlayer::SetCaching - caching state 3
2021-06-09 10:53:00.719 T:31939   DEBUG <general>: CDVDClock::SetSpeedAdjust - adjusted:0.000000
2021-06-09 10:53:00.719 T:31939   DEBUG <general>: CVideoPlayer::SetCaching - caching state 0
2021-06-09 10:53:00.719 T:31939   DEBUG <general>: CDVDClock::SetSpeedAdjust - adjusted:0.000000
2021-06-09 10:53:00.719 T:31939   DEBUG <general>: VideoPlayer::Sync - Audio - pts: 513147201.000000, cache: 301859.408617, totalcache: 900000.035763
2021-06-09 10:53:00.719 T:31939   DEBUG <general>: VideoPlayer::Sync - Video - pts: 512876000.000000, cache: 50000.000000, totalcache: 100000.000000
2021-06-09 10:53:00.720 T:31947   DEBUG <general>: CVideoPlayerAudio - CDVDMsg::GENERAL_RESYNC(512776000.000000), level: 46, cache: 580919.958617
2021-06-09 10:53:00.720 T:31947   DEBUG <general>: CDVDAudio::Resume - resume audio stream
2021-06-09 10:53:00.720 T:31945   DEBUG <general>: CVideoPlayerVideo - CDVDMsg::GENERAL_RESYNC(512776000.000000)
2021-06-09 10:53:00.721 T:31712   DEBUG <general>: ActiveAE - start sync of audio stream
2021-06-09 10:53:00.749 T:31729    INFO <general>: [plugin.video.vtm.go] [resources.lib.service] Player: [onAVChange] called
2021-06-09 10:53:00.839 T:31712   DEBUG <general>: ActiveAE::SyncStream - average error of -238.280375, start adjusting
2021-06-09 10:53:00.839 T:31712   DEBUG <general>: ActiveAE::SyncStream - average error -0.003731 below threshold of 30.000000
2021-06-09 10:53:00.879 T:31953   DEBUG <general>: CurlFile::ParseAndCorrectUrl() adding custom header option 'connection: keep-alive'
2021-06-09 10:53:00.879 T:31953   DEBUG <general>: CurlFile::Open(0x7f675009a7a0) https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/audio-B0A7438C236B541D7E6CACD771FC0E897A370B844B1634-123.mp4?hdntl=exp=1623250356~acl=/*~hmac=8aad39aef4631fcdf77a0feaab235e27fd8f49a8c3524dd3f471dd11095d936d
2021-06-09 10:53:00.899 T:31952   DEBUG <general>: AddOnLog: inputstream.adaptive: Download finished: https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/video-C9579F33725E44D4EA1E538E3A72A03D2495BE806A406E-122.mp4?hdntl=exp=1623250356~acl=/*~hmac=8aad39aef4631fcdf77a0feaab235e27fd8f49a8c3524dd3f471dd11095d936d , avg speed: 7527576.00byte/s, current speed: 7527576.00byte/s
2021-06-09 10:53:00.918 T:31953   DEBUG <general>: AddOnLog: inputstream.adaptive: Download finished: https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/audio-B0A7438C236B541D7E6CACD771FC0E897A370B844B1634-123.mp4?hdntl=exp=1623250356~acl=/*~hmac=8aad39aef4631fcdf77a0feaab235e27fd8f49a8c3524dd3f471dd11095d936d , avg speed: 7052131.07byte/s, current speed: 2587769.00byte/s
2021-06-09 10:53:00.930 T:31952   DEBUG <general>: CurlFile::ParseAndCorrectUrl() adding custom header option 'connection: keep-alive'
2021-06-09 10:53:00.930 T:31952   DEBUG <general>: CurlFile::Open(0x7f67600f0c30) https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/video-C9579F33725E44D4EA1E538E3A72A03D2495BE806A406E-123.mp4?hdntl=exp=1623250356~acl=/*~hmac=8aad39aef4631fcdf77a0feaab235e27fd8f49a8c3524dd3f471dd11095d936d
2021-06-09 10:53:01.139 T:31952   DEBUG <general>: AddOnLog: inputstream.adaptive: Download finished: https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/video-C9579F33725E44D4EA1E538E3A72A03D2495BE806A406E-123.mp4?hdntl=exp=1623250356~acl=/*~hmac=8aad39aef4631fcdf77a0feaab235e27fd8f49a8c3524dd3f471dd11095d936d , avg speed: 7561421.00byte/s, current speed: 7561421.00byte/s
2021-06-09 10:53:01.887 T:31947   DEBUG <general>: CDVDClock::ErrorAdjust - CVideoPlayerAudio::OutputPacket - error:-50517.585002, adjusted:-50517.585002
2021-06-09 10:53:03.455 T:31701   DEBUG <general>: ------ Window Deinit (Pointer.xml) ------
2021-06-09 10:53:03.602 T:31953   DEBUG <general>: CurlFile::ParseAndCorrectUrl() adding custom header option 'connection: keep-alive'
2021-06-09 10:53:03.602 T:31953   DEBUG <general>: CurlFile::Open(0x7f6750110760) https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/audio-B0A7438C236B541D7E6CACD771FC0E897A370B844B1634-124.mp4?hdntl=exp=1623250356~acl=/*~hmac=8aad39aef4631fcdf77a0feaab235e27fd8f49a8c3524dd3f471dd11095d936d
2021-06-09 10:53:03.626 T:31953   DEBUG <general>: AddOnLog: inputstream.adaptive: Download finished: https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/audio-B0A7438C236B541D7E6CACD771FC0E897A370B844B1634-124.mp4?hdntl=exp=1623250356~acl=/*~hmac=8aad39aef4631fcdf77a0feaab235e27fd8f49a8c3524dd3f471dd11095d936d , avg speed: 7238160.20byte/s, current speed: 4193375.00byte/s
2021-06-09 10:53:04.325 T:31952   DEBUG <general>: CurlFile::ParseAndCorrectUrl() adding custom header option 'connection: keep-alive'
2021-06-09 10:53:04.326 T:31952   DEBUG <general>: CurlFile::Open(0x7f67600f1450) https://dpp-anvato-live.akamaized.net/eu/vod/10000001/21/05/10/10259869/video-C9579F33725E44D4EA1E538E3A72A03D2495BE806A406E-124.mp4?hdntl=exp=1623250356~acl=/*~hmac=8aad39aef4631fcdf77a0feaab235e27fd8f49a8c3524dd3f471dd11095d936d
CastagnaIT commented 2 years ago

@mediaminister can you check if this problem occurs on Kodi 20 nexus?

mediaminister commented 2 years ago

@CastagnaIT I don't see any external subtitles in the latest nightly build (KodiSetup-20220224-8dab1656-master-x64.exe) But this bug is still present in Kodi 19.3

There seems to be a problem with getting a subtitle font?

2022-02-25 17:31:11.357 T:6492    DEBUG <general>: CUtil::GetExternalStreamDetailsFromFilename - Language = 'dut' / Name = '(External)' / Flag = '1' from C:\Users\user\AppData\Roaming\Kodi\userdata\addon_data\plugin.video.vtm.go\temp\nl.default
2022-02-25 17:31:11.357 T:6492     INFO <general>: Opening stream: 0 source: 1024
2022-02-25 17:31:11.358 T:6492     INFO <general>: CDVDSubtitlesLibass: Using libass version 1502000
2022-02-25 17:31:11.359 T:6492     INFO <general>: CDVDSubtitlesLibass: Creating ASS library structure
2022-02-25 17:31:11.359 T:6492     INFO <general>: CDVDSubtitlesLibass: Initializing ASS Renderer
2022-02-25 17:31:11.359 T:6492    DEBUG <general>: CDVDSubtitlesLibass: [ass] libass API version: 0x1502000
2022-02-25 17:31:11.359 T:6492    DEBUG <general>: CDVDSubtitlesLibass: [ass] libass source: d9d4e118ce59c7aee2a54d8d5785664addd704dc
2022-02-25 17:31:11.362 T:6492    DEBUG <general>: CDVDSubtitlesLibass: [ass] Shaper: FriBidi 1.0.8 (SIMPLE) HarfBuzz-ng 2.8.0 (COMPLEX)
2022-02-25 17:31:11.362 T:6492     INFO <general>: CDVDSubtitlesLibass: Initializing ASS library font settings
2022-02-25 17:31:11.363 T:6492    ERROR <general>: XFILE::CDirectory::GetDirectory - Error getting C:\Users\user\AppData\Roaming\Kodi\cache\fonts\
2022-02-25 17:31:11.363 T:6492    ERROR <general>: XFILE::CDirectory::GetDirectory - Error getting special://temp/fonts/
2022-02-25 17:31:11.368 T:9168     INFO <general>: CDVDVideoCodecFFmpeg::CDropControl: calculated diff time: 40000
2022-02-25 17:31:11.379 T:6492    DEBUG <general>: CDVDSubtitlesLibass: [ass] Using font provider directwrite (with GDI)
2022-02-25 17:31:11.379 T:6492    DEBUG <general>: Created subtitles parser: WebVTT Subtitle Parser
2022-02-25 17:31:11.379 T:6492     INFO <general>: CDVDSubtitlesLibass: Creating new ASS track
CastagnaIT commented 2 years ago

ah no it is only a stupid error output because the folder is not existent i will have to check to remove that log output

mediaminister commented 2 years ago

But nevertheless no external (vtt-)subtitles are shown in Kodi Nexus I removed Kodi 20 and installed Kodi 19.3 while preserving the user settings and the external subtitles are shown, but with the sync bug.

CastagnaIT commented 2 years ago

if your webvtt files are as the attacched one in the first post, then your files not follow the W3C webvtt standard because all timestamps format are wrong

e.g.: 00:00:20,347 --> 00:00:22,307 line:90% position:50% align:middle

make use of , to separate millisecs where istead must be a dot .

then the correct format is: 00:00:20.347 --> 00:00:22.307 line:90% position:50% align:middle

this is the problem that make your file to not works

mediaminister commented 2 years ago

No, the current WebVTT is valid. https://dvt-subtitles.persgroep.be/DELUIZENM1_1F647803_ae079e1d-0fda-4bcf-8ebf-f764a4059722_vtt_nl.vtt Checked with https://quuz.org/webvtt/

CastagnaIT commented 2 years ago

ah wait i opened the wrong file now i redownload it

CastagnaIT commented 2 years ago

yes this last file posted it is correct and to me works correclty on Kodi 20 either opening it via GUI with local files or opening it with an ISA stream

why do you say it doesn't work? with which method do you open it?

mediaminister commented 2 years ago

Thanks for confirming that the file works. The file is loaded with the VTM GO add-on.

CastagnaIT commented 2 years ago

i do not know how works that addon, but a fast looking to the script seem doing a lot of unusual things with subtitles

it download and edit the subs files separately from the ISA management, and seem to add these files externally from hdd i am wondering if all these things break the subs or cause something weird that prevent kodi to load or select the subs track

i have seen that also use xbmc.Player().setSubtitles to add the modified subtitles from hdd maybe xbmc.Player().setSubtitles not works? the only thing you can try is to create an addon test that load a free video stream to ISA then after the playback add a subs from hdd by using xbmc.Player().setSubtitles and see if the subs are loaded and listed in GUI. if the kodi python module not works you will have to open an issue on kodi repo.

IMO I think that addon should use if possible a proxy to remove all those unusual subs workarounds, in this way you can provide to ISA the data already modified. Then you have to replace the subtitles links in the manifest with the addon proxy endpoint, when ISA download the subs will ask the subs to the addon proxy, that will provide the modified subs downloaded directly from the source

forgot to say that on webvtt files it is also possible add X-TIMESTAMP-MAP property to shift the time without change the timestamps in whole file

CastagnaIT commented 2 years ago

given enough time for feedback closed as cleanup process