[malte]

Since some releases I have an annoying issue in Rom Collection Browser: every 10 minutes some background process seems to do some UI updates that clears the gamelist in RCB.

This is what the list looks like before:


This is what it looks like every 10 minutes:


I can't say when this started. I went back to beta 1 and still could reproduce this issue. Other users are reporting it too, so it is not anything specific to my system.

The complete log can be seen here: http://xbmclogs.com/show.php?id=26458

I guess that these are the interesting lines (as this is what is coming up every 10 minutes):

Code:

12:21:17 T:6192   DEBUG: Checking repositories for updates (triggered by XBMC.org PVR Add-ons)
12:21:24 T:6192   DEBUG: CGUIMediaWindow::GetDirectory ()
12:21:24 T:6192   DEBUG:   ParentPath = []
...
12:31:17 T:6192   DEBUG: Checking repositories for updates (triggered by XBMC.org PVR Add-ons)
12:31:28 T:6192   DEBUG: CGUIMediaWindow::GetDirectory ()
12:31:28 T:6192   DEBUG:   ParentPath = []

If it matters this is the code that builds the list in RCB. But I don't think there is anything specific:

Code:

item = xbmcgui.ListItem(gameRow[util.ROW_NAME], str(gameRow[util.ROW_ID]), imageGameList, imageGameListSelected)            
item.setProperty('gameId', str(gameRow[util.ROW_ID]))
...
self.addItem(item)

If anybody has a hint what may cause this issue and how it could be solved I would be very glad to hear.

Thanks,
malte

[e2zippo]

I can chip in with my log right after it happens maybe that'll help

Code:

14:22:45 T:4908  NOTICE: RCB_INFO: onAction: 107
14:22:46 T:4908  NOTICE: RCB_INFO: onAction: 107
14:22:47 T:4908  NOTICE: RCB_INFO: onAction: 107
14:22:48 T:4908  NOTICE: RCB_INFO: onAction: 107
14:23:06 T:3480  NOTICE: Thread Jobworker start, auto delete: true
14:23:06 T:4496  NOTICE: Thread CFileCache start, auto delete: false
14:23:06 T:3480 WARNING: XFILE::CCurlFile::CReadState::FillBuffer: curl failed with code 22
14:23:06 T:3480   ERROR: CCurlFile::CReadState::Open, didn't get any data from stream.
14:23:06 T:3480   ERROR: XFILE::CFileCache::Open - failed to open source <http://mirrors.xbmc.org/addons/frodo/pvr/win32/addons.xml.md5>
14:23:06 T:3480 WARNING: XFILE::CCurlFile::CReadState::FillBuffer: curl failed with code 22
14:23:06 T:3480   ERROR: CCurlFile::CReadState::Open, didn't get any data from stream.
14:23:06 T:3480   ERROR: Repository XBMC.org PVR Add-ons returned no add-ons, listing may have failed
14:23:07 T:2700  NOTICE: Thread CFileCache start, auto delete: false

Seems to have something do with a repository refreshes.

[negge]

I had this issue as well. It appeared around the time I started testing the PVR functionality so it could very well be related somehow like e2zippo said. I haven't been able to reproduce this bug at all lately though.

[divingmule]

I experience this as well, while working on an add-on with a script error. I had the add-on open to a directory in xbmc setting idle, while working on some code in notepad, ever so often the add-on would run and reproduce the script error.

[MasterPhW]

This problem is still persistent in the released beta1 and happens every then and now while using a launcher addon (RCB, AL or even Chrome launcher).
Any comment on this problem by one of the team members?

[Angelscry]

This problem also happen with Advanced Launcher. This is an old problem that randomly occurs since last Eden versions of XBMC. With most of the add-on, that load content/data it's is not a big problem. If the items list become empty, the add-on just reload the content/data. But with add-ons that generate their proper content/data, like RCB and Advanced Launcher, it is a really annoying problem... because is the problem occurs when the add-on are saving data... they become corrupted or simply lost.

I have try to found what could be the problem, since a long time, but the problem occurs randomly, not really often and when it occurs the XBMC debug log file did not show anything. So... it is really hard to know what happen and what could be the cause.

[MasterPhW]

Yeah, I also tried to look for some special messages in the log but couldn't find anything.

The problem seems to happen more often since the beta on my HTPC, so I hoped for a solution, but only found this thread.

So there's probably nothing we could do...

[sennerz]

I'm getting this problem now, was there ever a solution found to this?

[MasterPhW]

No team member tried to fix it in the last 9 months, so probably not

[geopgin]

I hit this issue as discussed here. I wanted to share here, so that maybe we can dig into a bit more.

In my instance, it looks like "Pulsar Unofficial Repo" was triggering repo updates every time I was hitting this issue.

Code:

13:06:28 T:1661813128  NOTICE: RCB_DEBUG: onFocus: 52
13:09:16 T:1529454192   DEBUG: Checking repositories for updates (triggered by Pulsar Unofficial Repo)
13:09:35 T:1661813128  NOTICE: RCB_DEBUG: onFocus: 50

So I looked at all the events triggered by that batch and started disabling/removing all the repos that presented errors like..

Code:

13:09:21 T:1795745176   DEBUG: CFileCache::Open - opening <pulsarunofficialrepo/trunk/addons.xml.md5> using cache
13:09:21 T:1795745176   DEBUG: CurlFile::Open(0x6947d648) https://icanuckxbmcrepo.svn.cloudforge.com/pulsarunofficialrepo/trunk/addons.xml.md5
13:09:21 T:1795745176    INFO: void XCURL::DllLibCurlGlobal::easy_aquire(const char*, const char*, XCURL::CURL_HANDLE**, XCURL::CURLM**) - Created session to https://icanuckxbmcrepo.svn.cloudforge.com
13:09:22 T:1795745176   ERROR: CCurlFile::FillBuffer - Failed: SSL connect error(35)
13:09:22 T:1795745176   ERROR: CCurlFile::CReadState::Connect, didn't get any data from stream.
13:09:22 T:1795745176   ERROR: virtual bool XFILE::CFileCache::Open(const CURL&) - failed to open source <https://icanuckxbmcrepo.svn.cloudforge.com/pulsarunofficialrepo/trunk/addons.xml.md5>
13:09:22 T:1795745176   DEBUG: CFileCache::Open - opening <pulsarunofficialrepo/trunk/addons.xml> using cache
13:09:22 T:1795745176   DEBUG: CurlFile::Open(0x6947d648) https://icanuckxbmcrepo.svn.cloudforge.com/pulsarunofficialrepo/trunk/addons.xml
13:09:22 T:1795745176   ERROR: CCurlFile::FillBuffer - Failed: SSL connect error(35)
13:09:22 T:1795745176   ERROR: CCurlFile::CReadState::Connect, didn't get any data from stream.
13:09:22 T:1795745176   ERROR: virtual bool XFILE::CFileCache::Open(const CURL&) - failed to open source <https://icanuckxbmcrepo.svn.cloudforge.com/pulsarunofficialrepo/trunk/addons.xml>
13:09:22 T:1795745176   ERROR: Repository Pulsar Unofficial Repo returned no add-ons, listing may have failed

And..

Code:

13:09:23 T:1795745176   DEBUG: CFileCache::Open - opening <HIGHWAY99/repository.thehighway.bb/raw/master/addons.bb.xml.md5> using cache
13:09:23 T:1795745176   DEBUG: CurlFile::Open(0x69c9ca68) http://bitbucket.org/HIGHWAY99/repository.thehighway.bb/raw/master/addons.bb.xml.md5
13:09:23 T:1795745176    INFO: void XCURL::DllLibCurlGlobal::easy_aquire(const char*, const char*, XCURL::CURL_HANDLE**, XCURL::CURLM**) - Created session to http://bitbucket.org
13:09:23 T:1795745176   ERROR: CCurlFile::FillBuffer - Failed: HTTP returned error 429
13:09:23 T:1795745176  NOTICE: CCurlFile::FillBuffer - Reconnect, (re)try 1
13:09:24 T:1795745176   ERROR: CCurlFile::FillBuffer - Failed: HTTP returned error 429
13:09:24 T:1795745176   ERROR: CCurlFile::CReadState::Connect, didn't get any data from stream.
13:09:24 T:1795745176   ERROR: virtual bool XFILE::CFileCache::Open(const CURL&) - failed to open source <http://bitbucket.org/HIGHWAY99/repository.thehighway.bb/raw/master/addons.bb.xml.md5>
13:09:24 T:1795745176   DEBUG: CFileCache::Open - opening <HIGHWAY99/repository.thehighway/master/addons.xml.md5> using cache
13:09:24 T:1795745176   DEBUG: CurlFile::Open(0x69c9ca68) http://raw.github.com/HIGHWAY99/repository.thehighway/master/addons.xml.md5
13:09:24 T:1795745176   DEBUG: CCurlFile::Open - effective URL: <https://raw.githubusercontent.com/HIGHWAY99/repository.thehighway/master/addons.xml.md5>
13:09:24 T:1693644504  NOTICE: Thread FileCache start, auto delete: false
13:09:24 T:1693644504    INFO: CFileCache::Process - Hit eof.
13:09:24 T:1693644504   DEBUG: Thread FileCache 1693644504 terminating

I'm not sure if it was the repo that triggered the batch that was the problem or simply the catalyst. Since removing the repo's I have yet to experience the issue and not seen the repo update triggered.

What I still don't know is if/when another repo check occurs, will the issue present itself again. Also is it dependent on a failure within the batch or simply the check itself?

Couple of questions

1. What events cause kodi to check repo's, is it the repo or a addons responsibility
2. When a failure occurs checking a repo, is the check redispatched on a timer
3. If I were to re-enable the repos, is there any additional kodi logging I should enable?

It be pretty cool to find the actual cause of this, it seems like a pretty significant bug. 1 or more addons/repos shouldn't be able to affect the experience of another....if in fact that's whats happening

Let me know if there is anything I can provide that will help.

[geopgin]

Poking around the logs, and was hoping for some clarification. The T: (e.g. T:1568191160) in the logging represents a id for a thread correct? Also assuming my previous assumption is correct, is it normal to see 2 or more threads printed on a single line?

Example:

Code:

13:09:32 T:18446744071703793384  NOTICE: Thread FileCache start, auto delete: false
13:09:32 T:18446744071703793384    INFO: CFileCache::Process - Hit eof.
13:09:32 T:18446744071703793384   DEBUG: Thread FileCache 18446744071703793384 terminating

Was just looking at what all threads were doing around the timeframe of the issue and found that.

EDIT: Found Kodi Logging information. So yes it is thread ID, but is it normal to see one so large or 2 ids combined?

EDIT2: I posted the question here as it seemed more appropriate.