search

xbmc / vfs.rar

RAR VFS addon for Kodi
GNU General Public License v2.0
37 stars 24 forks source link

Playback fails constantly, (at different points) on different sets #60

Closed noybman closed 4 years ago

noybman commented 4 years ago

VFS.RAR 2.2.0 seems to be broken with Kodi 18.6 all of a sudden.

I'm going to revert to a previous version of the lib (I'm on Windows 8.1 Pro) however as of the last week, playback of any video content fails to complete.

In some cases, I can get 20 minutes into a movie. In other cases, it lasts for 3 minutes, or 10 seconds.

It is the same point in time on each item. Meaning, the video that fails at 17 minutes fails at 17 minutes all of the time. If I extract it, it plays just fine.

noybman commented 4 years ago

I just found 2.0.8 on the mirrors.kodi.tv (https://mirrors.kodi.tv/addons/leia/vfs.rar+windows-x86_64/) and when I put 2.0.8 on it works fine. The videos play to the end without closing.

AlwinEsch commented 4 years ago

I look to fix this asap, checked the newer Version with much different RAR's on different OS where it has worked, but unfortunately Murphy's law came back and the others by users went wrong.

Think to found now one to reproduce this error and to fix.

But then it is really better to use the older version for now.

noybman commented 4 years ago

AlwinEsch, if I can assist please send me a note or request what info you need. Thank you for confirming it is broken.

It might be a good idea to re-release the previous version as a 2.2.1 or something then as I suspect many people on Windows at least might run into this.

AlwinEsch commented 4 years ago

Have created a fix request here https://github.com/xbmc/vfs.rar/pull/61

Can you test with addon for your OS from here https://jenkins.kodi.tv/blue/organizations/jenkins/xbmc%2Fvfs.rar/detail/PR-61/3/artifacts

Seems to work better on them and plays by me correct but need to have it confirmed :smile:

noybman commented 4 years ago

This does not fix it. I was easily able to load up one of the files that was crashing it before, fast forwarded into it, and at 12:06 minutes it ends abruptly. Oddly enough, if I recall correctly, the 2.2.0 version ended abruptly on this same video at 11:07 last time. When I put 2.0.8 back in, I can watch or fast forward the entire thing.

AlwinEsch commented 4 years ago

Can you send me a link to alwinus@kodi.tv about a RAR that makes mistakes or URL where I can get one to test.

AlwinEsch commented 4 years ago

I can reproduce now the error and have a base to search for them, seen also my other fix was then related to another error.

AlwinEsch commented 4 years ago

Seen it use the wrong file size on my example, the size showed in kodi is 313.2 MByte but it should have 4409 Mbyte.

It play untitl it reach this size and then stop, thats also why it is always the same time.

Can you confirm that also on others the size is lower shown?

There seems in size calculation something wrong.

noybman commented 4 years ago

Please tell me where to get the info you are looking for? What you are saying makes sense.

AlwinEsch commented 4 years ago

Is if you go over „Videos“ in Kodi‘s main menu to see them as files (not by „TV Shows“), there it is showed as file list with the size of his entries.

noybman commented 4 years ago

On the skin I'm using, "Estuary MOD V2" it does not show me file sizes on scanned content. When I open info, it gives me content details, not file details.

I can switch skins, but if you've confirmed that it is reporting incorrect file sizes, this makes sense why it would end abruptly!

AlwinEsch commented 4 years ago

Found the bug and easy to fix. RAR lib gives this:

  unsigned int UnpSize; // 32 bit size of them and limited then to 4GByte
  unsigned int UnpSizeHigh; // This then needed if higher

to give the size, but Kodi/I'm has taken only the UnpSize.

it should (UnpSizeHigh<<32)|UnpSize to have correct.

So to speak, it always worked with videos smaller than 4GByte, but if more was missing something.

Beet4 commented 4 years ago

Found the bug and easy to fix. RAR lib gives this:

  unsigned int UnpSize; // 32 bit size of them and limited then to 4GByte
  unsigned int UnpSizeHigh; // This then needed if higher

to give the size, but Kodi/I'm has taken only the UnpSize.

it should (UnpSizeHigh<<32)|UnpSize to have correct.

So to speak, it always worked with videos smaller than 4GByte, but if more was missing something.

Nice to read that you have found the bug for this issue. It was a bit frustrating that suddenly I could no longer resume a video stopped at a given point or fastforward on movies stored in RAR. Took a while until I realised vfs.rar was updated. When can we expect a fix to be released? :)

AlwinEsch commented 4 years ago

If nothing goes wrong today.

AlwinEsch commented 4 years ago

Have brought in the last changes, hopefully this then fixed and new version released.

sleeve commented 4 years ago

2.2.1 seems to be performing way better for me. I'll continue to test though to see if any other strange playback behavior pops up.

Update: Did some more testing on Android TV (Nvidia Shield 2019) and the issue is still happening on 2.2.1 (armv7). It seems to be working fine on Windows 10 (x86_64) though so I'm not quite sure whats going on between the platforms. Only other difference that I can think of is the Shield is on Wi-Fi and Windows is on wired Ethernet so there may be some slower caching or something going on?

noybman commented 4 years ago

Sleeve, do you know that 2.2.1 is the latest fix? I haven't seen a note on a new commit yet and the 2.2.1 version AlwinEsch uploaded via commit #61 is still the only one I see uploaded on the link he provided.

The version 2.2.1 from 3/8 is still broken like it was on 3/8 (even on Windows 10)

AlwinEsch commented 4 years ago

Also here I need to ask for security reasons, did you restart Kodi afterwards? Is a little stupid in Kodi that after an update until the next Kodi start the old one could still run.

Furthermore, and wants to be safe, haven't you installed vfs.libarchive? If so, this is in conflict and is taken instead of it.

Checked on my Amazon FireTV (armv7) with Leia 18.6 and ran normal.

The only thing I urgently need to do is to improve about #64, there it takes too long for Seek on password-encrypted packages. But this is a way that was not possible in the old version, so I think you only have some without a password.

Can you upload a Debug Log from Kodi to see more what happens inside.

noybman commented 4 years ago

AlwinEsch, when I tested 2.2.1 it was on 3/8/20. You posted a link to go obtain that copy to test. I tested it and it didn't work. Yes, I had to restart Kodi for it to see 2.2.1.

In response to us indicating it didn't work, you said you had another fix and you'd update it. You then implied you updated it. You haven't given us a link to 2.2.2, and the date of 2.2.1 is still 3/8/20.

What do you want me to test?

On March 12, 2020 6:57:28 AM EDT, Alwin Esch notifications@github.com wrote:

Also here I need to ask for security reasons, did you restart Kodi afterwards? Is a little stupid in Kodi that after an update until the next Kodi start the old one could still run.

Furthermore, and wants to be safe, haven't you installed vfs.libarchive? If so, this is in conflict and is taken instead of it.

Checked on my Amazon FireTV (armv7) with Leia 18.6 and ran normal.

The only thing I urgently need to do is to improve about #64, there it takes too long for Seek on password-encrypted packages. But this is a way that was not possible in the old version, so I think you only have some without a password.

Can you upload a Debug Log from Kodi to see more what happens inside.

-- You are receiving this because you authored the thread. Reply to this email directly or view it on GitHub: https://github.com/xbmc/vfs.rar/issues/60#issuecomment-598125524

-- Sent from my Android device with K-9 Mail. Please excuse my brevity.

sleeve commented 4 years ago

@noybman I believe the (3/8/20) version of 2.2.1 was just a test/beta version and that AlwinEsch added a few more fixes to that branch/PR before releasing the final version of 2.2.1 (3/10/20) that is now live on the Kodi Add-on repo. You can manually get the final version of 2.2.1 here:

https://mirrors.kodi.tv/addons/leia/

@AlwinEsch I just re-tested 2.0.8/2.2.0/2.2.1 (armv7) from the above mirror URL on Nvidia Shield 2019 and made sure to quit and restart Kodi after installing/uninstalling every version of vfs.rar. I am still seeing the same failing results. Most videos in .rar archives start to play just fine but when I press up to fast-forward 10min it tries to cache the data and then playback stops. 2.2.1 actually has the same behavior as 2.2.0 on Nvidia Shield, when I downgrade back to 2.0.8 the problems are fixed. I also re-tested 2.2.1 on Windows 10 and it works fine with the same videos.

I do not have vfs.libarchive installed and the .rar archives that I'm testing with are not password protected.

For privacy reasons I won't share the whole kodi.log file but here is a snippet of it when trying to fast-forward 10min, this is right after Kodi/CRARControl parses through the 81 .rar files (chunks/volumes) .rar-.r81. 

DEBUG: AddOnLog: RAR archive support: CRARControl::VolumeChange: Next volume is smb://192.168.1.200/videos/Video.Test.2013.1080p.x264-KODI/test1080p-kodi.r81
2020-03-12 13:30:52.703 T:18058   DEBUG: CDVDVideoCodecAndroidMediaCodec::AddData dts:2502000.00 pts:2544000.00 sz:1728 indexBuffer:-1 current state (3)
2020-03-12 13:30:52.703 T:18045   DEBUG: Seek - waiting for position 8202913469.
2020-03-12 13:30:52.704 T:18058   DEBUG: CDVDVideoCodecAndroidMediaCodec::AddData dts:2502000.00 pts:2544000.00 sz:1728 indexBuffer:-1 current state (3)
2020-03-12 13:30:52.714 T:17976   DEBUG: Previous line repeats 7 times.
2020-03-12 13:30:52.714 T:17976   DEBUG: PrepareNextRender: frameOnScreen: 2192350.808406 renderPts: 2236375.568653 nextFramePts: 2294000.000000 -> diff: -57624.431347  render: 0 forceNext: 0
2020-03-12 13:30:52.714 T:18058   DEBUG: CDVDVideoCodecAndroidMediaCodec::AddData dts:2502000.00 pts:2544000.00 sz:1728 indexBuffer:-1 current state (3)
2020-03-12 13:30:52.727 T:17976   DEBUG: Previous line repeats 10 times.
2020-03-12 13:30:52.728 T:17976   DEBUG: PrepareNextRender: frameOnScreen: 2192350.808406 renderPts: 2239747.650648 nextFramePts: 2294000.000000 -> diff: -54252.349352  render: 0 forceNext: 0
2020-03-12 13:30:52.729 T:18058   DEBUG: CDVDVideoCodecAndroidMediaCodec::AddData dts:2502000.00 pts:2544000.00 sz:1728 indexBuffer:-1 current state (3)
2020-03-12 13:30:52.744 T:17976   DEBUG: Previous line repeats 13 times.
2020-03-12 13:30:52.744 T:17976   DEBUG: PrepareNextRender: frameOnScreen: 2192350.808406 renderPts: 2239807.298684 nextFramePts: 2294000.000000 -> diff: -54192.701316  render: 0 forceNext: 0
2020-03-12 13:30:52.744 T:18058   DEBUG: CDVDVideoCodecAndroidMediaCodec::AddData dts:2502000.00 pts:2544000.00 sz:1728 indexBuffer:-1 current state (3)
2020-03-12 13:30:52.761 T:17976   DEBUG: Previous line repeats 13 times.
2020-03-12 13:30:52.761 T:17976   DEBUG: PrepareNextRender: frameOnScreen: 2192350.808406 renderPts: 2239298.865581 nextFramePts: 2294000.000000 -> diff: -54701.134419  render: 0 forceNext: 0
2020-03-12 13:30:52.762 T:18058   DEBUG: CDVDVideoCodecAndroidMediaCodec::AddData dts:2502000.00 pts:2544000.00 sz:1728 indexBuffer:-1 current state (3)
2020-03-12 13:30:52.777 T:17976   DEBUG: Previous line repeats 13 times.
2020-03-12 13:30:52.777 T:17976   DEBUG: PrepareNextRender: frameOnScreen: 2192350.808406 renderPts: 2240260.946536 nextFramePts: 2294000.000000 -> diff: -53739.053464  render: 0 forceNext: 0
2020-03-12 13:30:52.778 T:18058   DEBUG: CDVDVideoCodecAndroidMediaCodec::AddData dts:2502000.00 pts:2544000.00 sz:1728 indexBuffer:-1 current state (3)
2020-03-12 13:30:52.795 T:17976   DEBUG: Previous line repeats 15 times.
2020-03-12 13:30:52.795 T:17976   DEBUG: PrepareNextRender: frameOnScreen: 2192350.808406 renderPts: 2238511.621499 nextFramePts: 2294000.000000 -> diff: -55488.378501  render: 0 forceNext: 0
2020-03-12 13:30:52.797 T:18058   DEBUG: CDVDVideoCodecAndroidMediaCodec::AddData dts:2502000.00 pts:2544000.00 sz:1728 indexBuffer:-1 current state (3)
2020-03-12 13:30:52.810 T:17976   DEBUG: Previous line repeats 10 times.
2020-03-12 13:30:52.810 T:17976   DEBUG: PrepareNextRender: frameOnScreen: 2192350.808406 renderPts: 2240726.528550 nextFramePts: 2294000.000000 -> diff: -53273.471450  render: 0 forceNext: 0
2020-03-12 13:30:52.810 T:18058   DEBUG: CDVDVideoCodecAndroidMediaCodec::AddData dts:2502000.00 pts:2544000.00 sz:1728 indexBuffer:-1 current state (3)
2020-03-12 13:30:52.829 T:17976   DEBUG: Previous line repeats 14 times.
2020-03-12 13:30:52.829 T:17976   DEBUG: PrepareNextRender: frameOnScreen: 2192350.808406 renderPts: 2238415.325666 nextFramePts: 2294000.000000 -> diff: -55584.674334  render: 0 forceNext: 0
2020-03-12 13:30:52.829 T:18058   DEBUG: CDVDVideoCodecAndroidMediaCodec::AddData dts:2502000.00 pts:2544000.00 sz:1728 indexBuffer:-1 current state (3)
2020-03-12 13:30:52.830 T:18048    INFO: CFileCache::Process - Source read didn't return any data! Hit eof(?)
2020-03-12 13:30:52.832 T:18058   DEBUG: CDVDVideoCodecAndroidMediaCodec::AddData dts:2502000.00 pts:2544000.00 sz:1728 indexBuffer:-1 current state (3)
2020-03-12 13:30:52.833 T:18048   ERROR: CFileCache::Process - Error 0 seeking. Seek returned -1
2020-03-12 13:30:52.833 T:18048    INFO: CFileCache::Process - Source read didn't return any data! Hit eof(?)
2020-03-12 13:30:52.833 T:18058   DEBUG: CDVDVideoCodecAndroidMediaCodec::AddData dts:2502000.00 pts:2544000.00 sz:1728 indexBuffer:-1 current state (3)
2020-03-12 13:30:52.834 T:18045   DEBUG: SeekTime - seek ended up on time 648857
2020-03-12 13:30:52.834 T:18045   DEBUG: CVideoPlayer::FlushBuffers - flushing buffers
2020-03-12 13:30:52.835 T:18058   DEBUG: CDVDVideoCodecAndroidMediaCodec::AddData dts:2502000.00 pts:2544000.00 sz:1728 indexBuffer:-1 current state (3)
2020-03-12 13:30:52.835 T:18058   DEBUG: CDVDVideoCodecAndroidMediaCodec::SignalEndOfStream: state: 3
2020-03-12 13:30:52.835 T:18058   DEBUG: CDVDVideoCodecAndroidMediaCodec::SignalEndOfStream: ReleaseMediaCodecBuffers
2020-03-12 13:30:52.835 T:18058   DEBUG: CMediaCodecVideoBuffer::ReleaseOutputBuffer index(0), render(0), time:0, offset:0
2020-03-12 13:30:52.835 T:18058   DEBUG: CMediaCodecVideoBuffer::ReleaseOutputBuffer index(6), render(0), time:0, offset:0
2020-03-12 13:30:52.836 T:17983   DEBUG: ffmpeg[64F33970]: [SWR] Using fltp internally between filters
2020-03-12 13:30:52.836 T:17983   DEBUG: ffmpeg[64F33970]: [SWR] Matrix coefficients:
2020-03-12 13:30:52.836 T:17983   DEBUG: ffmpeg[64F33970]: [SWR] FL: FL:1.000000 FR:0.000000 FC:0.707107 LFE:0.000000 SL:0.707107 SR:0.000000
2020-03-12 13:30:52.836 T:17983   DEBUG: ffmpeg[64F33970]: [SWR] FR: FL:0.000000 FR:1.000000 FC:0.707107 LFE:0.000000 SL:0.000000 SR:0.707107
2020-03-12 13:30:52.836 T:18058   DEBUG: CMediaCodecVideoBuffer::ReleaseOutputBuffer index(5), render(0), time:0, offset:0
2020-03-12 13:30:52.836 T:18058   DEBUG: CDVDVideoCodecAndroidMediaCodec::SignalEndOfStream: BUFFER_FLAG_END_OF_STREAM send
2020-03-12 13:30:52.836 T:18058   DEBUG: CDVDVideoCodecAndroidMediaCodec::Reset Current state (3)
2020-03-12 13:30:52.838 T:18058   DEBUG: CDVDVideoCodecAndroidMediaCodec::InjectExtraData
2020-03-12 13:30:52.849 T:18059   DEBUG: CDVDAudio::Flush - flush audio stream
2020-03-12 13:30:52.849 T:18059   DEBUG: CDVDAudio::Pause - pausing audio stream
2020-03-12 13:30:52.850 T:18059   DEBUG: CVideoPlayerAudio - CDVDMsg::GENERAL_SYNCHRONIZE
2020-03-12 13:30:52.850 T:18058   DEBUG: CVideoPlayerVideo - CDVDMsg::GENERAL_SYNCHRONIZE
2020-03-12 13:30:52.850 T:18045   DEBUG: CVideoPlayer - CDVDMsg::GENERAL_SYNCHRONIZE
2020-03-12 13:30:52.852 T:18045   DEBUG: CVideoPlayer::SetCaching - caching state 0
2020-03-12 13:30:52.852 T:18045   DEBUG: CDVDClock::SetSpeedAdjust - adjusted:0.000000
2020-03-12 13:30:52.852 T:18045  NOTICE: CVideoPlayer::OnExit()
2020-03-12 13:30:52.852 T:18045  NOTICE: VideoPlayer: eof, waiting for queues to empty
2020-03-12 13:30:52.853 T:18045  NOTICE: Closing stream player 1
2020-03-12 13:30:52.853 T:18045  NOTICE: Waiting for audio thread to exit
2020-03-12 13:30:52.860 T:18059  NOTICE: thread end: CVideoPlayerAudio::OnExit()
2020-03-12 13:30:52.860 T:18059   DEBUG: Thread VideoPlayerAudio 18059 terminating
2020-03-12 13:30:52.860 T:18045  NOTICE: Closing audio device
2020-03-12 13:30:52.860 T:18045   DEBUG: CDVDAudio::Flush - flush audio stream

I have some tweaked cache settings on that device that may be triggering the CFileCache issue but I'll have to do some more testing. 

<cache>
  <memorysize>220200960</memorysize>
  <buffermode>1</buffermode>
  <readfactor>4.0</readfactor>
</cache>

Whatever the case is, it doesn't happen with 2.0.8 with the same cache settings so something is still broken with 2.2.1 on Nvidia Shield.

noybman commented 4 years ago

As I mentioned, for Windows 10 it does not work for me however 2.0.8 does.

In my test case, I do not need to fast forward, but I can. Regardless of what I do, it quits at the exact time every time. Which is why I doubted that 2.2.1 was revised after 3/8.

On March 12, 2020 6:43:14 PM EDT, Steve Morris notifications@github.com wrote:

@noybman I believe the (3/8/20) version of 2.2.1 was just a test/beta version and that AlwinEsch added a few more fixes to that branch/PR before releasing the final version of 2.2.1 (3/10/20) that is now live on the Kodi Add-on repo. You can manually get the final version of 2.2.1 here:

https://mirrors.kodi.tv/addons/leia/

@AlwinEsch I just re-tested 2.0.8/2.2.0/2.2.1 (armv7) from the above mirror URL on Nvidia Shield 2019 and made sure to quit and restart Kodi after installing/uninstalling every version of vfs.rar. I am still seeing the same failing results. Most videos in .rar archives start to play just fine but when I press up to fast-forward 10min it tries to cache the data and then playback stops. 2.2.1 actually has the same behavior as 2.2.0 on Nvidia Shield, when I downgrade back to 2.0.8 the problems are fixed. I also re-tested 2.2.1 on Windows 10 and it works fine with the same videos.

I do not have vfs.libarchive installed and the .rar archives that I'm testing with are not password protected.

For privacy reasons I won't share the whole kodi.log file but here is a snippet of it when trying to fast-forward 10min, this is right after Kodi/CRARControl parses through the 81 .rar files (chunks/volumes) .rar-.r81. 

DEBUG: AddOnLog: RAR archive support: CRARControl::VolumeChange: Next
volume is
smb://192.168.1.200/videos/Video.Test.2013.1080p.x264-KODI/test1080p-kodi.r81
2020-03-12 13:30:52.703 T:18058   DEBUG:
CDVDVideoCodecAndroidMediaCodec::AddData dts:2502000.00 pts:2544000.00
sz:1728 indexBuffer:-1 current state (3)
2020-03-12 13:30:52.703 T:18045   DEBUG: Seek - waiting for position
8202913469.
2020-03-12 13:30:52.704 T:18058   DEBUG:
CDVDVideoCodecAndroidMediaCodec::AddData dts:2502000.00 pts:2544000.00
sz:1728 indexBuffer:-1 current state (3)
2020-03-12 13:30:52.714 T:17976   DEBUG: Previous line repeats 7 times.
2020-03-12 13:30:52.714 T:17976   DEBUG: PrepareNextRender:
frameOnScreen: 2192350.808406 renderPts: 2236375.568653 nextFramePts:
2294000.000000 -> diff: -57624.431347  render: 0 forceNext: 0
2020-03-12 13:30:52.714 T:18058   DEBUG:
CDVDVideoCodecAndroidMediaCodec::AddData dts:2502000.00 pts:2544000.00
sz:1728 indexBuffer:-1 current state (3)
2020-03-12 13:30:52.727 T:17976   DEBUG: Previous line repeats 10
times.
2020-03-12 13:30:52.728 T:17976   DEBUG: PrepareNextRender:
frameOnScreen: 2192350.808406 renderPts: 2239747.650648 nextFramePts:
2294000.000000 -> diff: -54252.349352  render: 0 forceNext: 0
2020-03-12 13:30:52.729 T:18058   DEBUG:
CDVDVideoCodecAndroidMediaCodec::AddData dts:2502000.00 pts:2544000.00
sz:1728 indexBuffer:-1 current state (3)
2020-03-12 13:30:52.744 T:17976   DEBUG: Previous line repeats 13
times.
2020-03-12 13:30:52.744 T:17976   DEBUG: PrepareNextRender:
frameOnScreen: 2192350.808406 renderPts: 2239807.298684 nextFramePts:
2294000.000000 -> diff: -54192.701316  render: 0 forceNext: 0
2020-03-12 13:30:52.744 T:18058   DEBUG:
CDVDVideoCodecAndroidMediaCodec::AddData dts:2502000.00 pts:2544000.00
sz:1728 indexBuffer:-1 current state (3)
2020-03-12 13:30:52.761 T:17976   DEBUG: Previous line repeats 13
times.
2020-03-12 13:30:52.761 T:17976   DEBUG: PrepareNextRender:
frameOnScreen: 2192350.808406 renderPts: 2239298.865581 nextFramePts:
2294000.000000 -> diff: -54701.134419  render: 0 forceNext: 0
2020-03-12 13:30:52.762 T:18058   DEBUG:
CDVDVideoCodecAndroidMediaCodec::AddData dts:2502000.00 pts:2544000.00
sz:1728 indexBuffer:-1 current state (3)
2020-03-12 13:30:52.777 T:17976   DEBUG: Previous line repeats 13
times.
2020-03-12 13:30:52.777 T:17976   DEBUG: PrepareNextRender:
frameOnScreen: 2192350.808406 renderPts: 2240260.946536 nextFramePts:
2294000.000000 -> diff: -53739.053464  render: 0 forceNext: 0
2020-03-12 13:30:52.778 T:18058   DEBUG:
CDVDVideoCodecAndroidMediaCodec::AddData dts:2502000.00 pts:2544000.00
sz:1728 indexBuffer:-1 current state (3)
2020-03-12 13:30:52.795 T:17976   DEBUG: Previous line repeats 15
times.
2020-03-12 13:30:52.795 T:17976   DEBUG: PrepareNextRender:
frameOnScreen: 2192350.808406 renderPts: 2238511.621499 nextFramePts:
2294000.000000 -> diff: -55488.378501  render: 0 forceNext: 0
2020-03-12 13:30:52.797 T:18058   DEBUG:
CDVDVideoCodecAndroidMediaCodec::AddData dts:2502000.00 pts:2544000.00
sz:1728 indexBuffer:-1 current state (3)
2020-03-12 13:30:52.810 T:17976   DEBUG: Previous line repeats 10
times.
2020-03-12 13:30:52.810 T:17976   DEBUG: PrepareNextRender:
frameOnScreen: 2192350.808406 renderPts: 2240726.528550 nextFramePts:
2294000.000000 -> diff: -53273.471450  render: 0 forceNext: 0
2020-03-12 13:30:52.810 T:18058   DEBUG:
CDVDVideoCodecAndroidMediaCodec::AddData dts:2502000.00 pts:2544000.00
sz:1728 indexBuffer:-1 current state (3)
2020-03-12 13:30:52.829 T:17976   DEBUG: Previous line repeats 14
times.
2020-03-12 13:30:52.829 T:17976   DEBUG: PrepareNextRender:
frameOnScreen: 2192350.808406 renderPts: 2238415.325666 nextFramePts:
2294000.000000 -> diff: -55584.674334  render: 0 forceNext: 0
2020-03-12 13:30:52.829 T:18058   DEBUG:
CDVDVideoCodecAndroidMediaCodec::AddData dts:2502000.00 pts:2544000.00
sz:1728 indexBuffer:-1 current state (3)
2020-03-12 13:30:52.830 T:18048    INFO: CFileCache::Process - Source
read didn't return any data! Hit eof(?)
2020-03-12 13:30:52.832 T:18058   DEBUG:
CDVDVideoCodecAndroidMediaCodec::AddData dts:2502000.00 pts:2544000.00
sz:1728 indexBuffer:-1 current state (3)
2020-03-12 13:30:52.833 T:18048   ERROR: CFileCache::Process - Error 0
seeking. Seek returned -1
2020-03-12 13:30:52.833 T:18048    INFO: CFileCache::Process - Source
read didn't return any data! Hit eof(?)
2020-03-12 13:30:52.833 T:18058   DEBUG:
CDVDVideoCodecAndroidMediaCodec::AddData dts:2502000.00 pts:2544000.00
sz:1728 indexBuffer:-1 current state (3)
2020-03-12 13:30:52.834 T:18045   DEBUG: SeekTime - seek ended up on
time 648857
2020-03-12 13:30:52.834 T:18045   DEBUG: CVideoPlayer::FlushBuffers -
flushing buffers
2020-03-12 13:30:52.835 T:18058   DEBUG:
CDVDVideoCodecAndroidMediaCodec::AddData dts:2502000.00 pts:2544000.00
sz:1728 indexBuffer:-1 current state (3)
2020-03-12 13:30:52.835 T:18058   DEBUG:
CDVDVideoCodecAndroidMediaCodec::SignalEndOfStream: state: 3
2020-03-12 13:30:52.835 T:18058   DEBUG:
CDVDVideoCodecAndroidMediaCodec::SignalEndOfStream:
ReleaseMediaCodecBuffers
2020-03-12 13:30:52.835 T:18058   DEBUG:
CMediaCodecVideoBuffer::ReleaseOutputBuffer index(0), render(0),
time:0, offset:0
2020-03-12 13:30:52.835 T:18058   DEBUG:
CMediaCodecVideoBuffer::ReleaseOutputBuffer index(6), render(0),
time:0, offset:0
2020-03-12 13:30:52.836 T:17983   DEBUG: ffmpeg[64F33970]: [SWR] Using
fltp internally between filters
2020-03-12 13:30:52.836 T:17983   DEBUG: ffmpeg[64F33970]: [SWR] Matrix
coefficients:
2020-03-12 13:30:52.836 T:17983   DEBUG: ffmpeg[64F33970]: [SWR] FL:
FL:1.000000 FR:0.000000 FC:0.707107 LFE:0.000000 SL:0.707107
SR:0.000000
2020-03-12 13:30:52.836 T:17983   DEBUG: ffmpeg[64F33970]: [SWR] FR:
FL:0.000000 FR:1.000000 FC:0.707107 LFE:0.000000 SL:0.000000
SR:0.707107
2020-03-12 13:30:52.836 T:18058   DEBUG:
CMediaCodecVideoBuffer::ReleaseOutputBuffer index(5), render(0),
time:0, offset:0
2020-03-12 13:30:52.836 T:18058   DEBUG:
CDVDVideoCodecAndroidMediaCodec::SignalEndOfStream:
BUFFER_FLAG_END_OF_STREAM send
2020-03-12 13:30:52.836 T:18058   DEBUG:
CDVDVideoCodecAndroidMediaCodec::Reset Current state (3)
2020-03-12 13:30:52.838 T:18058   DEBUG:
CDVDVideoCodecAndroidMediaCodec::InjectExtraData
2020-03-12 13:30:52.849 T:18059   DEBUG: CDVDAudio::Flush - flush audio
stream
2020-03-12 13:30:52.849 T:18059   DEBUG: CDVDAudio::Pause - pausing
audio stream
2020-03-12 13:30:52.850 T:18059   DEBUG: CVideoPlayerAudio -
CDVDMsg::GENERAL_SYNCHRONIZE
2020-03-12 13:30:52.850 T:18058   DEBUG: CVideoPlayerVideo -
CDVDMsg::GENERAL_SYNCHRONIZE
2020-03-12 13:30:52.850 T:18045   DEBUG: CVideoPlayer -
CDVDMsg::GENERAL_SYNCHRONIZE
2020-03-12 13:30:52.852 T:18045   DEBUG: CVideoPlayer::SetCaching -
caching state 0
2020-03-12 13:30:52.852 T:18045   DEBUG: CDVDClock::SetSpeedAdjust -
adjusted:0.000000
2020-03-12 13:30:52.852 T:18045  NOTICE: CVideoPlayer::OnExit()
2020-03-12 13:30:52.852 T:18045  NOTICE: VideoPlayer: eof, waiting for
queues to empty
2020-03-12 13:30:52.853 T:18045  NOTICE: Closing stream player 1
2020-03-12 13:30:52.853 T:18045  NOTICE: Waiting for audio thread to
exit
2020-03-12 13:30:52.860 T:18059  NOTICE: thread end:
CVideoPlayerAudio::OnExit()
2020-03-12 13:30:52.860 T:18059   DEBUG: Thread VideoPlayerAudio 18059
terminating
2020-03-12 13:30:52.860 T:18045  NOTICE: Closing audio device
2020-03-12 13:30:52.860 T:18045   DEBUG: CDVDAudio::Flush - flush audio
stream

I have some tweaked cache settings on that device that may be triggering the CFileCache issue but I'll have to do some more testing. 

<cache>
 <memorysize>220200960</memorysize>
 <buffermode>1</buffermode>
 <readfactor>4.0</readfactor>
</cache>

Whatever the case is, it doesn't happen with 2.0.8 with the same cache settings so something is still broken with 2.2.1 on Nvidia Shield.

-- You are receiving this because you were mentioned. Reply to this email directly or view it on GitHub: https://github.com/xbmc/vfs.rar/issues/60#issuecomment-598464343

-- Sent from my Android device with K-9 Mail. Please excuse my brevity.

AlwinEsch commented 4 years ago

@sleeve I start to look and to find why it not works there.

Was a small seek on begin working and OK and still stop on same position? How is his file size shown in "Kodi Main Windows"->"Videos"->"His source" (if needed use temporary Skin Estuary) and compare them with your Kodi on Windows and by Hand with Explorer and WinRAR?

Bildschirmfoto von 2020-03-13 01-58-13

sleeve commented 4 years ago

@AlwinEsch On the configuration that is currently failing for me (Android TV/2.2.1-armv7), the file size and video time/length are displayed correctly. The file size looks the same on (Android TV/2.0.8-armv7, Windows 10/2.2.1-x86_64, Windows 10 Explorer and WinRAR.

I tried small seeks on various videos in .rar archives and it also causes the playback to stop the same way as the long seeks. The videos will mostly all start playing fine but the second I fast-forward/seek (short 10sec or long 10min) the video just stops. This has just been the easiest and quickest way for me to run an acceptance test on the various versions of vfs.rar.

I guess I can run some longer tests and see if the videos stop at the same point without fast-forwarding/seeking, but this will take more time. Let me know if you have any more ideas or tests you'd like me to run.

AlwinEsch commented 4 years ago

Then unfortunately I have to ask again for an example RAR package with this error where you give me the link to alwinus@kodi.tv.

I have now tested the following available systems with my RARs:

Where it with my test RAR's has worked. Only bad currently about seek in password protected RAR's.

Definitely want to fix it for you.

EDIT: At first I thought that it had to do with big endian vs little endian, but since the size is displayed correctly, it is probably something else, so the question before because of the sizes.

noybman commented 4 years ago

The file I tested on 3/8/2020 at the link AlwinEsch provided is the same exact official file located here: https://mirrors.kodi.tv/addons/leia/vfs.rar+windows-x86_64/

Then on March 10, 2020 Elwin replied stating the fix was figured out, and replied to @Beet4 planning to update it again on ~3/10:

If nothing goes wrong today.

So where is the fix version that I should be testing after the one that was created on 3/8/2020 @ 11:03PM?

2.2.1 does not work on Windows 8.1 Pro but 2.0.8 does.

Found the bug and easy to fix. RAR lib gives this:

  unsigned int UnpSize; // 32 bit size of them and limited then to 4GByte
  unsigned int UnpSizeHigh; // This then needed if higher

to give the size, but Kodi/I'm has taken only the UnpSize.

it should (UnpSizeHigh<<32)|UnpSize to have correct.

So to speak, it always worked with videos smaller than 4GByte, but if more was missing something.

AlwinEsch commented 4 years ago

About this was added on 2.2.1 (https://github.com/xbmc/vfs.rar/commit/4ecb3b57b20fbf7e5a9671077eeabb017acc5f65)

Thats also why I asked about exapmle RAR Link, there is somethink else where can't reproduce by my RAR packages.

sleeve commented 4 years ago

@noybman I don't think the test build artifacts from 2.2.1-3/8/2020 are still on that jenkins page (https://jenkins.kodi.tv/blue/organizations/jenkins/xbmc%2Fvfs.rar/detail/PR-61/3/artifacts) so I can't be 100% certain, but when I made my previous comment that they were not the same as the final 2.2.1-3/10/2020 I ran a quick file compare for the android-arm7 files and they had different SHA1 file hashes along with different file dates.

android-armv7-2.2.1-3/8/2020 libvfs.rar.so= e3cd8360b811f8690e13acb89a14bc8515dcdc3f android-armv7-2.2.1-3/10/2020 libvfs.rar.so= bb1603e44a0f19436f7681a5e72783c0c7fb91c6

Like @AlwinEsch said, the last commit after that 3/8/2020 test build only fixed the file size bug that hopefully would have solved all the issues but I think there are still a few with 2.2.1. I've ran some more tests but I'll write my findings up on my issue #59 as I think we're dealing with slightly different bugs and I don't want to hijack this one with multiple issues.

AlwinEsch commented 4 years ago

This was then related to wrong RAR file size where was fixed by 2.2.1.

About other problems the 2.2.2 now available, thats why this now closed.

noybman commented 4 years ago

I can confirm that 2.2.2 is working for me on the content that failed with 2.2.0 and 2,2,1. Thank you for the fix.