search

im85288 / service.upnext

GNU General Public License v2.0
81 stars 42 forks source link

"Watch now" causes weird colorful screen, but plays in the background #263

Closed theuema closed 3 years ago

theuema commented 3 years ago

Kodi: 19.1.0 nVidia Shield with Android 9 UpNext Version 1.1.5matrix.1

Video sources for Kodi are all added via NFS share.

UpNext window shows up perfectly and selecting "Watch now" successfully plays the correct episode, verified by its audio. The screen just shows a messy colored video image that changes colors periodically.

E.g.: signal-2021-08-04-153134_002 signal-2021-08-04-153134_001

theuema commented 3 years ago

Error logs regarding this issue (interesting ones marked with an arrow): 


2021-08-04 16:01:39.621 T:25415   DEBUG <general>: [service.upnext] UpNextMonitor -> Up Next style autoplay succeeded
2021-08-04 16:01:39.623 T:25424   DEBUG <general>: DoWork - Marking video item nfs://192.123.456.30/path/episode1.mkv as watched
2021-08-04 16:01:39.633 T:25433   DEBUG <general>: OnPlayBackStarted: CApplication::OnPlayBackStarted
2021-08-04 16:01:39.640 T:24789   DEBUG <general>: CVideoGUIInfo::InitCurrentItem( nfs://192.123.456.30/path/episode2.mkv)
2021-08-04 16:01:39.665 T:24789   DEBUG <general>: CPlayerGUIInfo::InitCurrentItem( nfs://192.123.456.30/path/episode2.mkv)
2021-08-04 16:01:39.683 T:25458   DEBUG <general>: CDVDAudio::Flush - flush audio stream
2021-08-04 16:01:39.683 T:25458   DEBUG <general>: CDVDAudio::Pause - pausing audio stream
2021-08-04 16:01:39.714 T:24792   DEBUG <general>: void CXBMCApp::OnPlayBackStarted()
...
-> 2021-08-04 16:01:39.776 T:24789   ERROR <general>: CMediaCodecVideoBuffer::ReleaseOutputBuffer error in render(1)
2021-08-04 16:01:39.778 T:25445   DEBUG <general>: Thread FileCache -1820862096 terminating
2021-08-04 16:01:39.778 T:25443   DEBUG <general>: CNFSFile::Close closing file path/episode1.mkv
2021-08-04 16:01:39.778 T:24789   DEBUG <general>: Flush - flushing renderer
2021-08-04 16:01:39.779 T:25443    INFO <general>: Creating InputStream
2021-08-04 16:01:39.783 T:25432   DEBUG <general>: Loading settings for  nfs://192.123.456.30/path/episode2.mkv
2021-08-04 16:01:39.787 T:25458   DEBUG <general>: CDVDAudio::Pause - pausing audio stream
2021-08-04 16:01:39.801 T:25443   DEBUG <general>: CFileCache::Open - < nfs://192.123.456.30/path/episode2.mkv> opening
2021-08-04 16:01:39.804 T:25443   DEBUG <general>: CNFSFile::Open - opened path/episode2.mkv
2021-08-04 16:01:39.808 T:25466   DEBUG <general>: Thread FileCache start, auto delete: false
...
2021-08-04 16:01:39.824 T:25443    INFO <general>: Creating Demuxer
2021-08-04 16:01:39.825 T:25443   DEBUG <general>: Open - probing detected format [matroska,webm]
...
2021-08-04 16:01:39.836 T:25443   DEBUG <general>: Open - avformat_find_stream_info starting
2021-08-04 16:01:39.856 T:25443   DEBUG <general>: Open - av_find_stream_info finished
2021-08-04 16:01:39.856 T:25443    INFO <general>: ffmpeg[0x68426820X]: Input #0, matroska,webm, from 'nfs://192.123.456.30/path/episode2.mkv':
2021-08-04 16:01:39.856 T:25443    INFO <general>: ffmpeg[0x68426820X]:   Metadata:
2021-08-04 16:01:39.856 T:25443    INFO <general>: ffmpeg[0x68426820X]:     encoder         : libebml v1.3.6 + libmatroska v1.4.9
2021-08-04 16:01:39.856 T:25443    INFO <general>: ffmpeg[0x68426820X]:   Duration: 00:21:29.86, start: 0.000000, bitrate: 10107 kb/s
2021-08-04 16:01:39.857 T:25443    INFO <general>: ffmpeg[0x68426820X]:     Stream #0:0: Video: h264 (High), yuv420p(tv, bt709, progressive), 1920x1080 [SAR 1:1 DAR 16:9], 23.98 fps, 23.98 tbr, 1k tbn, 47.95 tbc (default)
...
2021-08-04 16:01:39.861 T:25443   DEBUG <general>: CDVDDemuxFFmpeg::AddStream ID: 0
2021-08-04 16:01:39.861 T:25443   DEBUG <general>: CDVDDemuxFFmpeg::AddStream ID: 1
2021-08-04 16:01:39.861 T:25443   DEBUG <general>: CDVDDemuxFFmpeg::AddStream ID: 2
2021-08-04 16:01:39.861 T:25443   DEBUG <general>: CDVDDemuxFFmpeg::AddStream ID: 3
2021-08-04 16:01:39.861 T:25443    INFO <general>: Opening stream: 0 source: 256
2021-08-04 16:01:39.861 T:25443    INFO <general>: Creating video codec with codec id: 27
-> 2021-08-04 16:01:39.861 T:25443   ERROR <general>: CDVDVideoCodecAndroidMediaCodec::Open - InstanceGuard locked
-> 2021-08-04 16:01:39.861 T:25443    INFO <general>: CVideoPlayerVideo::OpenStream - could not open video codec
2021-08-04 16:01:39.864 T:25443   DEBUG <general>: ReadEditDecisionLists - Checking for edit decision lists (EDL) on local drive or remote share for: nfs://192.123.456.30/path/episode2.mkv
2021-08-04 16:01:39.865 T:25443    INFO <general>: Opening stream: 1 source: 256
2021-08-04 16:01:39.865 T:25443    INFO <general>: Finding audio codec for: 86056
2021-08-04 16:01:39.865 T:25443   DEBUG <general>: CDVDAudioCodecAndroidMediaCodec::Open codec(86056), profile(-99), tag(0), extrasize(0)
2021-08-04 16:01:39.865 T:25443    INFO <general>: CDVDAudioCodecAndroidMediaCodec::Open() Use default handling for non encrypted stream
2021-08-04 16:01:39.866 T:25443    INFO <general>: CDVDAudioCodecFFmpeg::Open() Successful opened audio decoder eac3
2021-08-04 16:01:39.866 T:25443    INFO <general>: Closing stream player 3
2021-08-04 16:01:39.866 T:25443    INFO <general>: Opening stream: 2 source: 256
2021-08-04 16:01:39.868 T:25443   DEBUG <general>: CVideoPlayer::SetCaching - caching state 1
2021-08-04 16:01:39.868 T:25443   DEBUG <general>: CDVDClock::SetSpeedAdjust - adjusted:0.000000

Some logs that might be of interest in a more general way: 

2021-08-04 16:02:13.203 T:24789    INFO <general>: Disabled debug logging due to GUI setting. Level 0.
2021-08-04 16:02:13.203 T:24789    INFO <general>: Log level changed to "INFO"
2021-08-04 16:02:29.435 T:24789    INFO <general>: Loading skin file: MyPrograms.xml, load type: KEEP_IN_MEMORY
-> 2021-08-04 16:03:02.674 T:25415   ERROR <general>: EXCEPTION: Unknown addon id 'service.upnext'.
2021-08-04 16:03:02.674 T:25415    INFO <general>: [service.upnext] UpNextMonitor -> Service stopped
2021-08-04 16:03:02.675 T:25415    INFO <general>: CPythonInvoker(12, /storage/emulated/0/Android/data/org.xbmc.kodi/files/.kodi/addons/service.upnext/resources/lib/service_entry.py): script successfully run
-> 2021-08-04 16:03:02.761 T:25415 WARNING <general>: CPythonInvoker(12, /storage/emulated/0/Android/data/org.xbmc.kodi/files/.kodi/addons/service.upnext/resources/lib/service_entry.py): the python script "/storage/emulated/0/Android/data/org.xbmc.kodi/files/.kodi/addons/service.upnext/resources/lib/service_entry.py" has left several classes in memory that we couldn't clean up. The classes include: N9XBMCAddon7xbmcgui6WindowE,N9XBMCAddon9xbmcaddon5AddonE,N9XBMCAddon4xbmc6PlayerE,N9XBMCAddon4xbmc6PlayerE
2021-08-04 16:03:02.761 T:25415    INFO <general>: Python interpreter interrupted by user
theuema commented 3 years ago

Update: Waiting for the default action when nothing is selected, "play next" successfully plays the next episode!

Reasoning from the logs and the working default action, it seems that "watch now" doesn't stop the stream correctly. The old instance of the video codec holds a lock that prevents the new video codec to open. Hope there is some investigation on this matter.

MoojMidge commented 3 years ago

This is not really caused by UpNext - the actions that take place when the "Watch now" button is selected are directly handled by Kodi, including the handling of the currently playing video.

Came across something similar but thought it was an AMLogic/CoreElec specific issue, guess it also happens on Android. One thing that is different in CoreElec is that the instance guard lock does get cleared, so the next video can play properly. I think the reason why this happens is that the m_opened flag gets set to false AFTER the instance guard check on AMLogic platforms, but BEFORE on Android. Once m_opened is set to false the situation can never be resolved on Android, until playback stops. Might be worthwhile creating a Kodi bug report about that.

In my instance, the issue is not that significant because of the AMLogic specific change mentioned above, but one thing that appeared to help the situation anyway was using the Player.Open JSONRPC method rather than the xbmc.Player().playnext() Python method. Don't really know why that works since both methods do pretty much the same thing, but the JSONRPC way is slightly slower, which may give Kodi enough time to properly close the previous decoder instance.

Created a test branch here: https://github.com/MoojMidge/service.upnext/tree/test-jsonplaynext, you can see if that improves things on Android.

theuema commented 3 years ago

Created a test branch here: https://github.com/MoojMidge/service.upnext/tree/test-jsonplaynext, you can see if that improves things on Android.

Thanks for coming up with a potential fix that fast. Unfortunately the situation has not changed. Seems that JSONRPC method still is fast enough to run into that problem you described.

Came across something similar but thought it was an AMLogic/CoreElec specific issue, guess it also happens on Android. One thing that is different in CoreElec is that the instance guard lock does get cleared, so the next video can play properly. I think the reason why this happens is that the m_opened flag gets set to false AFTER the instance guard check on AMLogic platforms, but BEFORE on Android. Once m_opened is set to false the situation can never be resolved on Android, until playback stops. Might be worthwhile creating a Kodi bug report about that.

Sure, I did that with communicating your information! Hope you don't mind, otherwise please let me know. Same if you have suggestions of improvement for the issue.

MoojMidge commented 3 years ago

No problem.

For reference, this is the commit for CoreELEC: https://github.com/CoreELEC/xbmc/commit/c63342329f31d0071a8e1d8d1a0d8c0cbad1e513#diff-3d80072e3ef4d59fed8025f1e11d31439b0847b59777d80d9e43b89fcbf3148b

I don't know that it is a real fix, but it does appear to work around the problem in CoreELEC. Might also be worthwhile seeing if disabling hardware acceleration (if possible) prevents the problem from occurring on your Shield.

theuema commented 3 years ago

I added the CoreELEC commit to the open issue, thanks.

Might also be worthwhile seeing if disabling hardware acceleration (if possible) prevents the problem from occurring on your Shield.

Great thinking that turns out to fix this particular problem. When deactivating ...

... in Kodi Settings/Player/Videos/Processing, "Watch now" works!

From both, the official Upnext Repo as well as your test branch. Not a real fix, since without HW acceleration no ultra high resolution stuff or HDR is possible, but might be of interest for the investigation. Generally worked for 1080p x264 stuff..