XBMC shutdown error [not the same as recently closed bug] - Printable Version +- Kodi Community Forum (https://forum.kodi.tv) +-- Forum: Support (https://forum.kodi.tv/forumdisplay.php?fid=33) +--- Forum: General Support (https://forum.kodi.tv/forumdisplay.php?fid=111) +---- Forum: OS independent / Other (https://forum.kodi.tv/forumdisplay.php?fid=228) +---- Thread: XBMC shutdown error [not the same as recently closed bug] (/showthread.php?tid=94269) |
- defender013 - 2011-03-06 hi JR, so even the new log shows exactly the same thing.. 19:40:39 T:3836 M:1211912192 NOTICE: CThread:taticThread: Calling _endthreadex(123) 19:40:39 T:2856 M:1211912192 NOTICE: Saving settings 19:40:39 T:2856 M:1211465728 NOTICE: stop all 19:40:39 T:2856 M:1211465728 NOTICE: CApplication::Stop: About to call StopServices() 19:40:39 T:2856 M:1211465728 NOTICE: CNetwork::NetworkMessage - Signaling network services to stop 19:40:39 T:2856 M:1211465728 NOTICE: CNetwork::StopServices - Stopping Event Server, bWait = 0 19:40:39 T:2856 M:1211465728 NOTICE: ES: Stopping event server 19:40:39 T:2856 M:1211465728 NOTICE: CEventServer::StopServer: about to call StopThread(0) 19:40:39 T:2856 M:1211465728 NOTICE: CEventServer::StopServer: StopThread(0) returned 19:40:39 T:2856 M:1211465728 NOTICE: CNetwork::StopServices - Event Server stopped, bWait = 0 19:40:39 T:2856 M:1211465728 NOTICE: CNetwork::StopServices - Stopping JSONRPC Server, bWait = 0 19:40:39 T:2856 M:1211465728 NOTICE: CNetwork::StopServices - JSONRPC Server stopped, bWait = 0 19:40:39 T:2856 M:1211465728 NOTICE: CNetwork::NetworkMessage - Waiting for network services to stop 19:40:39 T:2856 M:1211465728 NOTICE: Webserver: Stopping... 19:40:39 T:2856 M:1211637760 NOTICE: WebServer: Stopped the webserver 19:40:39 T:2856 M:1211641856 NOTICE: Webserver: Stopped... 19:40:39 T:2856 M:1211641856 NOTICE: CThread::StopThread: about to call WaitForThreadExit(INFINITE) 19:40:39 T:2856 M:1211641856 NOTICE: CThread::WaitForThreadExit: about to call WaitForSingleObject(1028, -1) 19:40:40 T:2092 M:1213403136 NOTICE: ES: UDP Event server stopped 19:40:40 T:2852 M:1213403136 NOTICE: CThread:taticThread: pThread->Process() finished 19:40:40 T:2092 M:1213403136 NOTICE: CEventServer::Run: About to call Cleanup 19:40:40 T:2852 M:1213403136 NOTICE: CThread:taticThread: Calling pThread->OnExit() 19:40:40 T:2092 M:1213403136 NOTICE: CEventServer::Cleanup: About to call m_pSocket->Close() 19:40:40 T:2852 M:1213403136 NOTICE: CThread:taticThread: pThread->OnExit() finished 19:40:40 T:2852 M:1213403136 NOTICE: CThread:taticThread: Calling pThread->IsAutoDelete() 19:40:40 T:2852 M:1213403136 DEBUG: Thread 2852 terminating 19:40:40 T:2092 M:1213403136 NOTICE: CEventServer::Cleanup: m_pSocket->Close() finished 19:40:40 T:2852 M:1213403136 NOTICE: CThread:taticThread: Calling _endthreadex(123) 19:40:40 T:2092 M:1213403136 NOTICE: CEventServer::Cleanup: About to lock 19:40:40 T:2092 M:1213403136 NOTICE: CEventServer::Cleanup: Lock finished 19:40:40 T:2092 M:1213394944 NOTICE: CEventServer::Cleanup: About to start client loop 19:40:40 T:2092 M:1213403136 NOTICE: CEventServer::Cleanup: Client loop finished 19:40:40 T:2092 M:1213403136 NOTICE: CEventServer::Run: Cleanup returned 19:40:40 T:2092 M:1213399040 NOTICE: CEventServer:rocess: Finished 19:40:40 T:2092 M:1213399040 NOTICE: CThread:taticThread: pThread->Process() finished 19:40:40 T:2092 M:1213399040 NOTICE: CThread:taticThread: Calling pThread->OnExit() 19:40:40 T:2092 M:1213399040 NOTICE: CThread:taticThread: pThread->OnExit() finished 19:40:40 T:2092 M:1213399040 NOTICE: CThread:taticThread: Calling pThread->IsAutoDelete() 19:40:40 T:2092 M:1213399040 DEBUG: Thread 2092 terminating 19:40:40 T:2092 M:1213399040 NOTICE: CThread:taticThread: Calling _endthreadex(123) i'm pretty puzzled.. looks like this is the same thing i'll try to capture more logs and send them your way... - jhsrennie - 2011-03-06 Aha! Now we're making progress, even though it may not look like it to you! When XBMC wants to stop a thread it sends that thread a stop request, then waits for the thread to stop using the Windows function "WaitForSingleObject". If I look at my log I can see: Code: (I've left these three lines in as a reference point) but in your log: Code: NOTICE: Webserver: Stopping... the line NOTICE: CThread::WaitForThreadExit: WaitForSingleObject(1028, -1) != WAIT_TIMEOUT is missing. This means that XBMC is waiting for a thread to finish and it never does. Hence the hang. The main problem in working out what's going wrong is that XBMC is multi-threaded, which means that different bits of it run simultaneously and write to the log file simultaneously, so the order that lines appear in the log file isn't always the same, and it's not obvious which thread produced which log entry. Nevertheless, it's clear from your log that the call to WaitForSingleObject(1028, -1) never returned. The next step is to work out which thread is hanging. I might be able to do that without troubling you for yet more logging. Watch this space!! JR - jhsrennie - 2011-03-06 Bingo! It's the RSS reader! I've added some extra logging info around the RSS code. Please would you try it and see what your log shows when you get a hang. As usual it's on http://swarchive.ratsauce.co.uk/xbmc/xbmc-debug.zip. Can you pop the whole log on pastebin.com - because of all that threading log entries can be widely scattered through the log so it's not just the last few entries that I need. Anyhow, when I run XBMC I get: Code: NOTICE: Webserver: Stopping... I confidently predict that if you get a hang the last two lines of the above will be missing. Later: I've just updated XBMC-Debug.exe to add a few more lines of logging. If you sdownloaded it before 11:00 GMT please grab the updated copy. The updated copy has the build date set to 06/06/11 in the system info. The log entries should now look like: Code: Webserver: Stopping... Also, somewhere higher up in the log should be one or more lines looking like: NOTICE: CRssReader:rocess: finished and I'm particularly interested to check that all these lines are present in the log somewhere as i suspect the CRssReader:rocess() function may be hanging. Thanks, JR - defender013 - 2011-03-08 hi JR, will do, i will try this out tonight. this is odd though, i do remember reading the RSS reader was a problem, and i also remember this was suppose to have been fixed late last yr, hence my thread title of [not the same as recently closed bug]. i will check this out tonight and get back to you - defender013 - 2011-03-08 hi JR, indeed you are correct, here is the pastbin link http://pastebin.com/VsbqrbJi and i think the following here is what you are most interested in.. 22:10:39 T:2768 M:906182656 NOTICE: Webserver: Stopping... 22:10:39 T:2768 M:906358784 NOTICE: WebServer: Stopped the webserver 22:10:39 T:2768 M:906358784 NOTICE: Webserver: Stopped... 22:10:39 T:2768 M:906358784 NOTICE: CRssManager::Stop: no. readers = 1 22:10:39 T:2768 M:906358784 NOTICE: CRssManager::Stop: Deleting reader 1 22:10:39 T:2768 M:906358784 NOTICE: CRssReader::~CRssReader: testing handle 22:10:40 T:3724 M:908488704 NOTICE: ES: UDP Event server stopped 22:10:40 T:3600 M:908488704 NOTICE: CThread:taticThread: pThread->Process() finished 22:10:40 T:3724 M:908488704 NOTICE: CEventServer::Run: About to call Cleanup 22:10:40 T:3600 M:908488704 NOTICE: CThread:taticThread: Calling pThread->OnExit() 22:10:40 T:3724 M:908488704 NOTICE: CEventServer::Cleanup: About to call m_pSocket->Close() 22:10:40 T:3600 M:908488704 NOTICE: CThread:taticThread: pThread->OnExit() finished 22:10:40 T:3600 M:908488704 NOTICE: CThread:taticThread: Calling pThread->IsAutoDelete() 22:10:40 T:3600 M:908488704 DEBUG: Thread 3600 terminating 22:10:40 T:3724 M:908488704 NOTICE: CEventServer::Cleanup: m_pSocket->Close() finished 22:10:40 T:3600 M:908488704 NOTICE: CThread:taticThread: Calling _endthreadex(123) 22:10:40 T:3724 M:908488704 NOTICE: CEventServer::Cleanup: About to lock 22:10:40 T:3724 M:908488704 NOTICE: CEventServer::Cleanup: Lock finished 22:10:40 T:3724 M:908488704 NOTICE: CEventServer::Cleanup: About to start client loop 22:10:40 T:3724 M:908484608 NOTICE: CEventServer::Cleanup: Client loop finished 22:10:40 T:3724 M:908488704 NOTICE: CEventServer::Run: Cleanup returned 22:10:40 T:3724 M:908484608 NOTICE: CEventServer:rocess: Finished 22:10:40 T:3724 M:908484608 NOTICE: CThread:taticThread: pThread->Process() finished 22:10:40 T:3724 M:908484608 NOTICE: CThread:taticThread: Calling pThread->OnExit() 22:10:40 T:3724 M:908484608 NOTICE: CThread:taticThread: pThread->OnExit() finished 22:10:40 T:3724 M:908484608 NOTICE: CThread:taticThread: Calling pThread->IsAutoDelete() 22:10:40 T:3724 M:908484608 DEBUG: Thread 3724 terminating 22:10:40 T:3724 M:908484608 NOTICE: CThread:taticThread: Calling _endthreadex(123) 22:10:40 T:2768 M:908550144 NOTICE: CRssReader::~CRssReader: thread handle wait failed 22:10:40 T:2768 M:908550144 NOTICE: CRssReader::~CRssReader: About to call StopThread 22:10:40 T:2768 M:908550144 NOTICE: CThread::StopThread: 1012 - CRssReaderThread: about to call WaitForThreadExit(INFINITE) 22:10:40 T:2768 M:908546048 NOTICE: CThread::WaitForThreadExit: 1012 - CRssReaderThread: about to call WaitForSingleObject(1012, -1) CRssReader handle wait failed... just out of curiosity, how did you know it was the RSS? i mean you didnt have any actual failure logs pointing directly to it, how did you find out? - defender013 - 2011-03-08 i forgot to mention, you are also right, the CRss process did not finish, i didn't see such a line in the log... how did you figure this one out?? was there something obviously wrong in the code? - jhsrennie - 2011-03-08 defender013 Wrote:how did you figure this one out?? was there something obviously wrong in the code? Hours and hours of work! :-) I found every place in the source code where a new thread was created and I modified the code to add a name to the thread object so I could tell which thread was which. Then I ran it on my PC, which doesn't hang, compared my log to yours and spotted a pattern suggesting it was the RSSReader. Your log then proved it. There wasn't anything wrong with the code, and in fact it seems to be hanging in a completely unexpected bit of the code. The RSSReader is successfully reading the RSS feed data, but appears to be hanging when it attempts to save the data to internal storage. To try and confirm this I've made another new version of http://swarchive.ratsauce.co.uk/xbmc/xbmc-debug.zip to test. The key log entries for this are (from my system): Code: NOTICE: CRssReader::Process: 1304: calling UpdateObserver If I'm right, you should find that if there's a hang, some of the above lines will be missing. I have no idea where it will be hanging because I can't see any obvious reason why anything in the UpdateObserver() function should hang, so it will be very interesting to see what your log shows. JR - defender013 - 2011-03-09 hi JR, so it looks like CRss reader is not getting a graphics context lock? 23:43:07 T:1708 M:927412224 NOTICE: CRssReader:rocess: 1028: calling UpdateObserver 23:43:07 T:1708 M:927412224 NOTICE: CRssReader::UpdateObserver: entered UpdateObserver 23:43:07 T:1708 M:927412224 NOTICE: CRssReader::UpdateObserver: about to call getfeed 23:43:07 T:1708 M:927412224 NOTICE: CRssReader::UpdateObserver: feed.size = 461 23:43:07 T:1708 M:927412224 NOTICE: CRssReader::UpdateObserver: about to call g_graphicsContext.Lock this graphics context lock i think is the last thing being called for the CRssReader thread. could you be something related to my graphics driver or OS? just wondering if this in anyway would explain why aero on vista/7 is having a problem also the full log is here... http://pastebin.com/Hzzvug2Q - defender013 - 2011-03-09 hi JR, one more question..what exactly does this graphicContext.lock do? i just did a quick search and saw it mentioned back in 2009 in regards to external players... in my case, when xbmc freezes on shutdown, the entire system is pretty much screwed, mainly because the display freezes, and there is very little i can do (since i cant see anything else). I always suspected it might be some graphics related thing since I use an external player (and im always jumping in and out of focus). but for these logs, i never even start anything, so i don't really understand this problem is coming from... actually..do you think there is any chance this is happening because my external player never released a context lock (im going on really old forum posts here..) i should mention that my xbmc box rarely gets rebooted, it is almost always in s3 sleep. I'll try rebooting the machine tomorrow and see if i can still get similar failures without ever calling the external player thanks - jhsrennie - 2011-03-09 Ah, all that work and we're not much further forward. The g_graphicsContext.Lock() function is used to stop more than one thread modifying critical variables at the same time. When a thread needs to modify anything in these critical variables it calls g_graphicsContext.Lock(), and it's guaranteed exclusive access to the data until it calls g_graphicsContext.Unlock(). As soon as a thread has called g_graphicsContext.Lock() any other thread that calls g_graphicsContext.Lock() will freeze until the first thread calls g_graphicsContext.Unlock(). So what's happening is that some other thread is calling g_graphicsContext.Lock() but then not calling g_graphicsContext.Unlock(). That means that the RSSReader calls g_graphicsContext.Lock() and freezes waiting for the other thread. So it isn't a problem in the RSSReader after all. It's a problem in some other thread. JR - jhsrennie - 2011-03-09 I've found one place where an error might cause a call to g_graphicsContext.Unlock() to be missed. I've added some logging to check for this and put it on http://swarchive.ratsauce.co.uk/xbmc/xbmc-debug.zip as usual. Can you try this, and if you get a hang see if there's a line in the log: CApplication::Render: g_Windowing.BeginRender() returned FALSE - LOCK NOT RELEASED Thanks, JR - defender013 - 2011-03-09 hi JR, wow you're really good at this.. the line you were expecting to see is in fact there... i've also included some lines above it as i feel it might be helpful.. broken log: 08:30:54 T:188 M:1041518592 DEBUG: CWinEventsWin32::WndProcWindow is active 08:30:54 T:188 M:1041821696 DEBUG: CWinEventsWin32::WndProcWindow lost focus 08:30:54 T:188 M:1041018880 DEBUG: D3DERR_DEVICELOST 08:30:54 T:188 M:1040695296 NOTICE: CApplication::Render: g_Windowing.BeginRender() returned FALSE - LOCK NOT RELEASED working log: 08:30:45 T:2468 M:1070505984 DEBUG: CWinEventsWin32::WndProcWindow is active 08:30:45 T:2468 M:1070505984 DEBUG: CWinEventsWin32::WndProcWindow gained focus 08:30:45 T:2468 M:1070407680 DEBUG: CRenderSystemDX::CreateDevice on adapter 0 08:30:45 T:2468 M:1067925504 DEBUG: CRenderSystemDX::CreateDevice - adapter 0: ati2dvag.dll, ATI Radeon HD 4200, VendorId 4098, DeviceId 38672 08:30:45 T:2468 M:1067925504 DEBUG: CRenderSystemDX::CreateDevice - texture caps: 0x0001EC45 08:30:45 T:2468 M:1067921408 DEBUG: CRenderSystemDX::CreateDevice - RENDER_CAPS_DXT 08:30:45 T:2468 M:1067921408 DEBUG: CRenderSystemDX::CreateDevice - RENDER_CAPS_NPOT 08:30:45 T:2468 M:1067921408 DEBUG: CRenderSystemDX::CreateDevice - RENDER_CAPS_DXT_NPOT im wondering if there's something i'm doing with eventghots that's causing a problem... i'll take a look and get back to you. http://pastebin.com/LZmncUFC JR, one more piece of info. It looks like sometimes even when i CAN successfully shut down, the LOCK NOT RELEASED still shows up. It just happens to show up AFTER the Rss process itself has finished, thus allowing me to shut down gracefully... - defender013 - 2011-03-09 hi JR, sorry i'd like to get you a working log also so you can compare...but for some reason... now im almost always getting LOCK NOT RELEASED the one i posted for you earlier must be a complete stroke of luck. i will try again later tonight. is it just me? or does this just seem like a problem on my graphics card/driver? i recently did an update to the latest set of drivers, although i've been having this problem on/off for a few months now (dating back to the camelot days) thx - jhsrennie - 2011-03-09 OK, I think I have some good news for you. I think I've fixed the bug. Give my new version of http://swarchive.ratsauce.co.uk/xbmc/xbmc-debug.zip a try and see if it fixes the hangs. This is what I think is happening. The main thread in XBMC is calling the g_graphicsContext.Lock() function to allow it access to critical variables, then refreshing the screen, then calling g_graphicsContext.Unlock(). But if there's an error it abandons the screen refresh and fails to call g_graphicsContext.Unlock(). This means that the RSSReader hangs when it calls g_graphicsContext.Lock() to try and use the same memory. The error that's causing the problem is the D3DERR_DEVICELOST error that you've already noticed, and as you've also noticed whether the hang happens depends on whether the D3DERR_DEVICELOST error happens before or after the RSSReader has finished. This is going to vary depending on how long the RSSReader takes to read data from the Internet, so sometimes XBMC will hang and sometimes it won't. Ironically, the error itself is harmless. It's only because of the bug in XBMC that the D3DERR_DEVICELOST error is causing XBMC to hang. In my latest version of XBMC-Debug.exe I've left all the logging in, but I've changed the code so that if the D3DERR_DEVICELOST error occurs the code correctly calls the Unlock() function, and this should fix the problem. If this works I can strip out all the logging and build a shiny new version of Dharma with the bug fixed. There is a maintenance release, v10.1, out soon, and although in theory it's now closed to changes, my guess is that this bug is serious enough that the fix will be added to v10.1. JR - defender013 - 2011-03-09 hi JR, thank you for your detailed explanation, i am currently in corporate drone mode, so i won't be able to try this out until later tonight. quick question though, why is this particular error harmless? I mean just based on the log, it almost looks like xbmc is trying to control the graphics to do...something? So when it fails, how come its not a big deal? thanks |