XBMC shutdown error [not the same as recently closed bug]

  Thread Rating:
  • 0 Votes - 0 Average
  • 1
  • 2
  • 3
  • 4
  • 5
Post Reply
defender013 Offline
Member
Posts: 53
Joined: Sep 2010
Reputation: 0
Post: #1
hi all,

just wondering if i could get some suggestions where to look next... from what i've been able to to gather from the forums, shut down crashes seem to happen for a great variety of reasons, and not always re-produceable by all parties..

with that being said...

I am running dharma 10.0 on xp sp2. Ocassionally, when i issue a shut down command to xbmc, the whole thing freezes up. and I mean it REALLY freezes up, ctrl+alt+del doesn't even get me out of it.

I checked into the logs, it basically looks like it's stuck on trying to terminate the event server thread, so I'm really not sure what else i can do here..

any suggestion is welcome! I do wait around to see if it'll eventually figure itself out after enough time...but that doesn't seem to work either.

I"ve attached part of my logs here.

....
21:29:06 T:2068 M:987885568 NOTICE: ES: Starting UDP Event server on 0.0.0.0:9777
21:29:06 T:2068 M:987820032 NOTICE: UDP: Listening on port 9777

...
23:54:19 T:2016 M:971448320 DEBUG: CNetwork::NetworkMessage - Signaling network services to stop
23:54:19 T:2016 M:971448320 NOTICE: ES: Stopping event server
23:54:19 T:2016 M:971448320 DEBUG: CNetwork::NetworkMessage - Waiting for network services to stop
23:54:19 T:2016 M:971448320 NOTICE: Webserver: Stopping...
23:54:19 T:2016 M:971657216 NOTICE: WebServer: Stopped the webserver
23:54:19 T:2016 M:971657216 NOTICE: Webserver: Stopped...
23:54:20 T:980 M:971628544 DEBUG: Thread 980 terminating
23:54:20 T:2068 M:971665408 NOTICE: ES: UDP Event server stopped
23:54:20 T:2068 M:971657216 DEBUG: Thread 2068 terminating
find quote
jhsrennie Offline
Team-XBMC Developer
Posts: 7,248
Joined: Nov 2008
Reputation: 119
Location: Chester, UK
Post: #2
It may seem an odd suggestion, but next time you get a hang can you try pulling out the network cable (either at the PC or at the switch) and see if that unfreezes XBMC.

As you've worked out, there are at least two quite separate causes of the hang. On Vista/Win7 it's mostly the known problem with Aero but on XP it seems to be something network related. I've seen one post reporting that pulling the network cable released the hang.

JR
find quote
defender013 Offline
Member
Posts: 53
Joined: Sep 2010
Reputation: 0
Post: #3
hi JR,

thanks for the suggestion, I will definitely try that out.

unfortunately, since this problem is somewhat sporatic, i may not be able to try this suggestion for some time.

do you have any other suggestions? or what other information i can gather?

one more thing, this is just a guess, but is the UDP event server only started if i enable other computers to control xbmc as well? I'm asking this because it was only yesterday that i enabled this feature. However, the same setup has had similar crashes in the past when the option wasnt enabled (although i do not currently have logs of those instances)
find quote
defender013 Offline
Member
Posts: 53
Joined: Sep 2010
Reputation: 0
Post: #4
hi,

just wanted to give an update, in my case, pulling the network cable did not help.

and it still looks like during the shutdown process, xbmc just gets stuck at the event server....

anyone have any recommendations? im open to all suggestions?

22:28:50 T:3548 M:967286784 NOTICE: Saving settings
22:28:50 T:3548 M:967110656 NOTICE: stop all
22:28:50 T:3548 M:967106560 NOTICE: ES: Stopping event server
22:28:50 T:3548 M:967098368 NOTICE: Webserver: Stopping...
22:28:50 T:3548 M:967290880 NOTICE: WebServer: Stopped the webserver
22:28:50 T:3548 M:967290880 NOTICE: Webserver: Stopped...
22:28:51 T:2204 M:967319552 NOTICE: ES: UDP Event server stopped

just stops here after that...
find quote
jhsrennie Offline
Team-XBMC Developer
Posts: 7,248
Joined: Nov 2008
Reputation: 119
Location: Chester, UK
Post: #5
OK, thanks. Another user has also reported that pulling the network cable made no difference, so it looks as though I was barking up the wrong tree.

If I build a version of Dharma with extra debugging info would you be willing to try that?

Later: I've put a debug version of XBMC.exe on http://swarchive.ratsauce.co.uk/XBMC/default.asp. Download XBMC-Debug.zip. The zip contains a build of XBMC.exe with extra logging around the Eventserver shutdown code.

JR
(This post was last modified: 2011-02-25 19:45 by jhsrennie.)
find quote
defender013 Offline
Member
Posts: 53
Joined: Sep 2010
Reputation: 0
Post: #6
hi jhsrennie,

of course, i will try this out.

thank you for making a special build for this purpose.

i will get this going tonight and hopefully i'll have some new info for you soon.

thanks!
find quote
defender013 Offline
Member
Posts: 53
Joined: Sep 2010
Reputation: 0
Post: #7
hi jhsrennie,

so i tried your debug exe... and the strange thing is.. i cannot reproduce the error now.

this leads me to think.. that somehow the extra logging is resolving some race condition, or that it takes more than a power on/power off loop to reproduce the problem.

I will test this some more and hopefully get back to you with more useful information.

i think off the top of my head... there are a few things i want to try.

1. revert back to original *.exe and put that into a power on/off loop and see if the error pops up
2. if it does not pop up, i guess this means i need more real life use cases and not just an on/off loop
3. if it does pop up, this would somehow mean the extra logging is beneficial...

let me know what you think.

thanks
find quote
jhsrennie Offline
Team-XBMC Developer
Posts: 7,248
Joined: Nov 2008
Reputation: 119
Location: Chester, UK
Post: #8
I would just carry on using the debug build for the next few days and see if the problem recurs. You said it didn't happen every time anyway. The debug build is a genuine Dharma build, just with a bit of extra logging added, so it will work just as well as Dharma does.

JR
find quote
defender013 Offline
Member
Posts: 53
Joined: Sep 2010
Reputation: 0
Post: #9
hi jhsrennie,

so the good news is that i have reproduced the error with the extra debug logs, the bad news is that i don't think they are useful... see below..

21:52:50 T:2620 M:965177344 NOTICE: Storing total System Uptime
21:52:50 T:2620 M:965275648 NOTICE: Saving settings
21:52:50 T:2620 M:965177344 NOTICE: stop all
21:52:50 T:2620 M:965177344 NOTICE: ES: Stopping event server
21:52:50 T:2620 M:965177344 NOTICE: Webserver: Stopping...
21:52:50 T:2620 M:965361664 NOTICE: WebServer: Stopped the webserver
21:52:50 T:2620 M:965365760 NOTICE: Webserver: Stopped...
21:52:51 T:2456 M:965369856 NOTICE: ES: UDP Event server stopped
21:52:51 T:2456 M:965378048 NOTICE: CEventServer::Run: About to call Cleanup
21:52:51 T:2456 M:965378048 NOTICE: CEventServer::Cleanup: About to call m_pSocket->Close()
21:52:51 T:2456 M:965378048 NOTICE: CEventServer::Cleanup: m_pSocket->Close() finished
21:52:51 T:2456 M:965378048 NOTICE: CEventServer::Cleanup: About to lock
21:52:51 T:2456 M:965369856 NOTICE: CEventServer::Cleanup: Lock finished
21:52:51 T:2456 M:965369856 NOTICE: CEventServer::Cleanup: About to start client loop
21:52:51 T:2456 M:965369856 NOTICE: CEventServer::Cleanup: Client loop finished
21:52:51 T:2456 M:965378048 NOTICE: CEventServer::Run: Cleanup returned
21:52:51 T:2456 M:965378048 NOTICE: CEventServer::Process: Finished

all the extra debugging logs you added actually terminated gracefully, it looks like it is still stuck somewhere else...
find quote
jhsrennie Offline
Team-XBMC Developer
Posts: 7,248
Joined: Nov 2008
Reputation: 119
Location: Chester, UK
Post: #10
The normal debug log should contain:

Code:
NOTICE: ES: UDP Event server stopped
DEBUG: Thread 1076 terminating

The "Thread 1076 terminating" message (the number will vary) is the thread that runs the event server announcing that it has stopped. If you got the "CEventServer::Process: Finished" message but no "Thread nnn terminating" then that pins down the hang. Can you check if you got the thread terminating message in the log.

JR
find quote
defender013 Offline
Member
Posts: 53
Joined: Sep 2010
Reputation: 0
Post: #11
hi JR,

sorry i think i forgot to enable the debugging log in my settings. That particular line you're looking for only shows up when i have that enabled correct?

i'll turn that on again and re-test.
find quote
jhsrennie Offline
Team-XBMC Developer
Posts: 7,248
Joined: Nov 2008
Reputation: 119
Location: Chester, UK
Post: #12
defender013 Wrote:hi JR,

sorry i think i forgot to enable the debugging log in my settings. That particular line you're looking for only shows up when i have that enabled correct?

i'll turn that on again and re-test.

Yes, you need debugging on. However I've added a few more debug statements and put the new version of XBMC-debug.zip on http://swarchive.ratsauce.co.uk/XBMC/default.asp. Please will you grab this updated version.

Also you can turn debug logging on without the annoying text at the top of the screen. Create an advancedsettings.xml file in %appdata%\xbmc\userdata containing:

Code:
<advancedsettings>
  <loglevel>1</loglevel>
</advancedsettings>

JR
find quote
defender013 Offline
Member
Posts: 53
Joined: Sep 2010
Reputation: 0
Post: #13
hi JR,

will do. i'll try it now.. hopefully i'll have a brand new shiny log for you tomorrow.

thanks
find quote
defender013 Offline
Member
Posts: 53
Joined: Sep 2010
Reputation: 0
Post: #14
hi JR,

so i do have a failure log now, but honestly, at the moment, i'm not completely certain the failure logs are always the same. I will continue to post them as necessary.

FYI, there is a bunch of stuff at the end of the working log that looks like it has to do with uninstalling plugins. It seems like some of them didn't go all the way through, could this be the problem?

//failed log
23:05:51 T:3308 M:856481792 NOTICE: Storing total System Uptime
23:05:51 T:3308 M:856481792 NOTICE: Saving settings
23:05:51 T:3308 M:856289280 NOTICE: stop all
23:05:51 T:3308 M:856289280 DEBUG: CNetwork::NetworkMessage - Signaling network services to stop
23:05:51 T:3308 M:856289280 NOTICE: ES: Stopping event server
23:05:51 T:3308 M:856289280 DEBUG: CNetwork::NetworkMessage - Waiting for network services to stop
23:05:51 T:3308 M:856289280 NOTICE: Webserver: Stopping...
23:05:51 T:3308 M:856477696 NOTICE: WebServer: Stopped the webserver
23:05:51 T:3308 M:856477696 NOTICE: Webserver: Stopped...
23:05:51 T:672 M:856457216 NOTICE: CThread::staticThread: pThread->Process() finished
23:05:51 T:3760 M:856473600 NOTICE: ES: UDP Event server stopped
23:05:51 T:672 M:856473600 NOTICE: CThread::staticThread: Calling pThread->OnExit()
23:05:51 T:3760 M:856473600 NOTICE: CEventServer::Run: About to call Cleanup
23:05:51 T:672 M:856473600 NOTICE: CThread::staticThread: pThread->OnExit() finished
23:05:51 T:3760 M:856473600 NOTICE: CEventServer::Cleanup: About to call m_pSocket->Close()
23:05:51 T:672 M:856473600 NOTICE: CThread::staticThread: Calling pThread->IsAutoDelete()
23:05:51 T:672 M:856473600 DEBUG: Thread 672 terminating
23:05:51 T:672 M:856473600 NOTICE: CThread::staticThread: Calling _endthreadex(123)
23:05:51 T:3760 M:856473600 NOTICE: CEventServer::Cleanup: m_pSocket->Close() finished
23:05:51 T:3760 M:856473600 NOTICE: CEventServer::Cleanup: About to lock
23:05:51 T:3760 M:856469504 NOTICE: CEventServer::Cleanup: Lock finished
23:05:51 T:3760 M:856469504 NOTICE: CEventServer::Cleanup: About to start client loop
23:05:51 T:3760 M:856465408 NOTICE: CEventServer::Cleanup: Client loop finished
23:05:51 T:3760 M:856465408 NOTICE: CEventServer::Run: Cleanup returned
23:05:51 T:3760 M:856465408 NOTICE: CEventServer::Process: Finished
23:05:51 T:3760 M:856465408 NOTICE: CThread::staticThread: pThread->Process() finished
23:05:51 T:3760 M:856465408 NOTICE: CThread::staticThread: Calling pThread->OnExit()
23:05:51 T:3760 M:856465408 NOTICE: CThread::staticThread: pThread->OnExit() finished
23:05:51 T:3760 M:856465408 NOTICE: CThread::staticThread: Calling pThread->IsAutoDelete()
23:05:51 T:3760 M:856465408 DEBUG: Thread 3760 terminating
23:05:51 T:3760 M:856465408 NOTICE: CThread::staticThread: Calling _endthreadex(123)
23:05:51 T:3308 M:856539136 NOTICE: stop sap announcement listener
23:05:51 T:3308 M:856539136 NOTICE: clean cached files!
23:05:51 T:3308 M:856539136 NOTICE: unload skin
23:05:51 T:3308 M:856539136 DEBUG: ------ Window Deinit (Home.xml) ------
23:05:51 T:3308 M:856551424 DEBUG: ------ Window Deinit (Pointer.xml) ------
23:05:51 T:3308 M:856551424 DEBUG: ------ Window Deinit (DialogMuteBug.xml) ------
23:05:51 T:3308 M:870481920 NOTICE: stop python

//working log
23:09:27 T:3444 M:962662400 DEBUG: ADDON: cpluff: 'Plug-in visualization.itunes has been uninstalled.'
23:09:27 T:3444 M:962662400 INFO: ADDON: cpluff: 'An unreleased information object was encountered at address 01C5B980 with reference count 1 when destroying the associated plug-in context. Not releasing the object.'
23:09:27 T:3444 M:962662400 INFO: ADDON: cpluff: 'An unreleased information object was encountered at address 01C3F710 with reference count 1 when destroying the associated plug-in context. Not releasing the object.'
23:09:27 T:3444 M:962662400 INFO: ADDON: cpluff: 'An unreleased information object was encountered at address 01C4C718 with reference count 1 when destroying the associated plug-in context. Not releasing the object.'
23:09:27 T:3444 M:962662400 INFO: ADDON: cpluff: 'An unreleased information object was encountered at address 01C5B7A0 with reference count 1 when destroying the associated plug-in context. Not releasing the object.'
23:09:27 T:3444 M:962662400 INFO: ADDON: cpluff: 'An unreleased information object was encountered at address 01C49A60 with reference count 1 when destroying the associated plug-in context. Not releasing the object.'
23:09:27 T:3444 M:962662400 INFO: ADDON: cpluff: 'An unreleased information object was encountered at address 01C41760 with reference count 1 when destroying the associated plug-in context. Not releasing the object.'
23:09:27 T:3444 M:962662400 INFO: ADDON: cpluff: 'An unreleased information object was encountered at address 01C4E6E8 with reference count 1 when destroying the associated plug-in context. Not releasing the object.'
23:09:27 T:3444 M:962662400 INFO: ADDON: cpluff: 'An unreleased information object was encountered at address 01C451B0 with reference count 1 when destroying the associated plug-in context. Not releasing the object.'
23:09:27 T:3444 M:962662400 INFO: ADDON: cpluff: 'An unreleased information object was encountered at address 01C4A0B8 with reference count 1 when destroying the associated plug-in context. Not releasing the object.'
23:09:27 T:3444 M:962658304 INFO: ADDON: cpluff: 'An unreleased information object was encountered at address 01C479B8 with reference count 1 when destroying the associated plug-in context. Not releasing the object.'
23:09:27 T:3444 M:962641920 NOTICE: unload sections
23:09:27 T:3444 M:962641920 DEBUG: SECTION:UnloadAll(DLL: special://xbmcbin/system/cpluff.dll)
23:09:27 T:3444 M:962641920 DEBUG: Win32DllLoader::Unload cpluff.dll
23:09:27 T:3444 M:962641920 DEBUG: FreeLibrary(libexpat.dll) -> 016D7B38
23:09:27 T:3444 M:962641920 DEBUG: Win32DllLoader::Unload libexpat.dll
23:09:27 T:3444 M:962695168 DEBUG: SECTION:UnloadAll(DLL: special://xbmcbin/system/ImageLib.dll)
23:09:27 T:3444 M:962695168 DEBUG: Win32DllLoader::Unload ImageLib.dll
find quote
jhsrennie Offline
Team-XBMC Developer
Posts: 7,248
Joined: Nov 2008
Reputation: 119
Location: Chester, UK
Post: #15
OK, it now looks as if it's hanging at a different place. Before the last line in the log was the "NOTICE: ES: UDP Event server stopped" line, and now it's the "NOTICE: stop python" line.

I'm beginning to wonder if this is a memory management issue and we're getting stack or heap corruption, although that usually just causes a crash. I don't think the cpluff errors are significant. I get those too and my XBMC never hangs on exit. I suspect those errors are coming from a smart pointer and are harmless. They just mean some developer forgot to release an object they had allocated.

I'm a bit stuck for ideas now. Usually when you see errors changing under your feet it's a memory management error, or for a multithreaded app like XBMC it could be a thread contention problem. In both cases apparently unrelated changes to the code can cause the problem to change or indeed disappear. Thanks for your help. I'm going to have to think about this. I might look for where the "stop python" message is and add extra logging around that.

JR
find quote
Post Reply