+- 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-01
hi JR,
there's actually a few things i wanted to point out about my setup first..
i am using a fairly old version of eventGhost with dharma, and usually, when I "shut down" xbmc, it is done through eventGhost's xbmc plugin.
it had not occurred to update to a more recent version to see if the behavior would somehow be different.
also, the log i reproduced for you just now was not actually shutting down xbmc using the same plugin. It was done through the xbmc shutdown menu.
I've noticed this for some time in my setup; the probability of hanging is MUCH greater when i use the shutdown menu, vs the eventghost plugin.. not entirely sure why this is.
just thought you should know. Anyhow, i will be updating to the latest eventGhost and giving that a shot to see if there is any difference. Meanwhile, i will continue to capture logs as they come up.
- jhsrennie - 2011-03-01
Eventghost may be sending an alt-F4 keystroke ...
JR
- defender013 - 2011-03-01
i suspected that..
so i took out the eventGhost plug-in, and did emulated keystrokes of alt+f4 instead.
the behavior was ALSO different. xbmc would never hang on exit, HOWEVER, it would sometimes crash the next time i try to start.
I compared the logs, and quite honestly, nothing stood out.
- defender013 - 2011-03-01
sorry just wanted to summarize..
1. xbmc shutdown menu -> frequent hanging
2. eventGhost xbmc plugin shutdown command -> less frequent hanging, but still happens.
3. alt+f4 emulated keystrokes through eventGhost -> never hangs, but occassioanlly prevents xbmc from correctly starting up again (only fixed by manually terminating xbmc process or box reboot)
- jhsrennie - 2011-03-01
alt-F4 is handled by Windows and it's action is to destroy the window that receives the message. Normally an application will spot that it's main window has been destroyed and will terminate. What you're seeing is that the main window is destroyed, so it disappears from the display, and XBMC.exe attempts to terminate but sometimes hangs while shutting down. So you end up with a hidden XBMC.exe process that you have to kill manually. It's probably the same hang, it just appears different because of the different order the shutdown steps are taken.
However it's interesting that using the shutdown menu hangs more than pressing alt-F4.
JR
- defender013 - 2011-03-01
hi JR,
that's what i thought at first as well. however, there were a couple of things that convinced me otherwise at the time..
1. i had task manager open and made sure the xbmc process was indeed gone before the failed to start-up case (I'm not sure what you mean by hidden, does that mean it will not even be listed in the process list?)
2. i checked the debug log of the case RIGHT before the failure to boot up, and it looks identical to a complete/clean shut down case.
In fact, i collected a log of the cases that didn't boot up, and what happened was xbmc came up, and immediately decided to shut down again, THEN it hung.
so the sequence is as follows..
alt+f4 -> graceful shutdown according to logs -> various manual checking of xbmc processes -> attempt to restart -> xbmc boots up successfully according to logs -> immediately decides that it needs to shut down again and hangs at the event server location
in this last test case, i made sure to disable any xbmc start-up activity (library scanning what have you) to make sure nothing else would interfere. It's almost as if xbmc did not completely terminate the last time and decided to continue once it started up again.
sorry for spamming you with post after post...these are all just some interesting things i've noticed recently
- jhsrennie - 2011-03-01
defender013 Wrote:sorry for spamming you with post after post...these are all just some interesting things i've noticed recently
Please carry on. I suspect we're still a way from understanding what's going on, but I feel we're making progress.
You're correct that if xbmc.exe doesn't show in the process list it has definitely shut down. It's very odd that XBMC should start then immediately exit with no input from you. If you have a log of it doing that, preferably with my modified version of XBMC I'd be very interested to see that. If you can use the advancedsettings.xml setting to have the debug logging enabled by default that would be ideal. It won't have any significant effect on the XBMC performance.
Thanks again for all your help.
JR
- defender013 - 2011-03-01
will do.
i will collect a set of fresh logs tonight, all this alt+f4 testing i did was without your debug.exe.
hopefully i'll have something for you tonight (i've already added the debug level to my advancesettings.xml).
thanks
- defender013 - 2011-03-02
hi JR,
so actually you were right. the alt+f4 failing case is the same, xbmc.exe did not terminate, and it prevented xbmc from correctly starting up again.
the following is the log, and it just ends at trying to terminate the thread. hope this helps.
22:04:37 T:3328 M:1004994560 NOTICE: Storing total System Uptime
22:04:37 T:1804 M:1004994560 NOTICE: CThread:
taticThread: Calling pThread->OnExit()22:04:37 T:1804 M:1004994560 NOTICE: CThread:
taticThread: pThread->OnExit() finished22:04:37 T:1804 M:1004994560 NOTICE: CThread:
taticThread: Calling pThread->IsAutoDelete()22:04:37 T:1804 M:1004994560 DEBUG: Thread 1804 terminating (autodelete)
22:04:37 T:1804 M:1004994560 NOTICE: CThread:
taticThread: Calling _endthreadex(123)22:04:37 T:3328 M:1004990464 NOTICE: Saving settings
22:04:37 T:3328 M:1004662784 NOTICE: stop all
22:04:37 T:3328 M:1004654592 DEBUG: CNetwork::NetworkMessage - Signaling network services to stop
22:04:37 T:3328 M:1004654592 NOTICE: ES: Stopping event server
22:04:37 T:3328 M:1004654592 DEBUG: CNetwork::NetworkMessage - Waiting for network services to stop
22:04:37 T:3328 M:1004654592 NOTICE: Webserver: Stopping...
22:04:37 T:3328 M:1004843008 NOTICE: WebServer: Stopped the webserver
22:04:37 T:3328 M:1004843008 NOTICE: Webserver: Stopped...
22:04:37 T:4040 M:1006456832 NOTICE: ES: UDP Event server stopped
22:04:37 T:1268 M:1006456832 NOTICE: CThread:
taticThread: pThread->Process() finished22:04:37 T:4040 M:1006456832 NOTICE: CEventServer::Run: About to call Cleanup
22:04:37 T:1268 M:1006456832 NOTICE: CThread:
taticThread: Calling pThread->OnExit()22:04:37 T:4040 M:1006456832 NOTICE: CEventServer::Cleanup: About to call m_pSocket->Close()
22:04:37 T:1268 M:1006456832 NOTICE: CThread:
taticThread: pThread->OnExit() finished22:04:37 T:1268 M:1006456832 NOTICE: CThread:
taticThread: Calling pThread->IsAutoDelete()22:04:37 T:1268 M:1006456832 DEBUG: Thread 1268 terminating
22:04:37 T:4040 M:1006456832 NOTICE: CEventServer::Cleanup: m_pSocket->Close() finished
22:04:37 T:1268 M:1006456832 NOTICE: CThread:
taticThread: Calling _endthreadex(123)22:04:37 T:4040 M:1006456832 NOTICE: CEventServer::Cleanup: About to lock
22:04:37 T:4040 M:1006456832 NOTICE: CEventServer::Cleanup: Lock finished
22:04:37 T:4040 M:1006456832 NOTICE: CEventServer::Cleanup: About to start client loop
22:04:37 T:4040 M:1006456832 NOTICE: CEventServer::Cleanup: Client loop finished
22:04:37 T:4040 M:1006456832 NOTICE: CEventServer::Run: Cleanup returned
22:04:37 T:4040 M:1006452736 NOTICE: CEventServer:
rocess: Finished22:04:37 T:4040 M:1006452736 NOTICE: CThread:
taticThread: pThread->Process() finished22:04:37 T:4040 M:1006452736 NOTICE: CThread:
taticThread: Calling pThread->OnExit()22:04:37 T:4040 M:1006452736 NOTICE: CThread:
taticThread: pThread->OnExit() finished22:04:37 T:4040 M:1006452736 NOTICE: CThread:
taticThread: Calling pThread->IsAutoDelete()22:04:37 T:4040 M:1006452736 DEBUG: Thread 4040 terminating
22:04:37 T:4040 M:1006452736 NOTICE: CThread:
taticThread: Calling _endthreadex(123)
- jhsrennie - 2011-03-02
Hmm, the "Calling _endthreadex(123)" message is the last message you'd expect to see from the EventServer thread. _endthreadex causes the calling thread to terminate so it appears to be behaving as expected.
So it looks as if it wasn't the EventServer thread causing the problem. I'll do some more debugging to see what code follows the EventServer thread termination.
JR
- defender013 - 2011-03-02
hi JR,
yes i think you're right. in my original log,
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
it looked the ES might've been doing okay also...
sorry if i've led you on a wild goose chase....
- jhsrennie - 2011-03-03
OK, I've added a load more debug logging and put the new version on http://swarchive.ratsauce.co.uk/xbmc/xbmc-debug.zip
Can you give this one a try (with debugging enabled) and see if you can trap a shutdown hang. Given that the Event Server seems OK, the next suspect is the JSON RPC server. Actually, since JSON is new in Dharma this is an obvious target.
Thanks again for helping with this.
JR
- defender013 - 2011-03-04
hi JR,
even with all the extra debug logs, the hang case is still ending at the same place...
22:17:43 T:2668 M:911048704 NOTICE: Saving settings
22:17:44 T:2668 M:910802944 NOTICE: stop all
22:17:44 T:2668 M:910794752 NOTICE: CApplication::Stop: About to call StopServices()
22:17:44 T:2668 M:910794752 NOTICE: CNetwork::NetworkMessage - Signaling network services to stop
22:17:44 T:2668 M:910794752 NOTICE: CNetwork::StopServices - Stopping Event Server
22:17:44 T:2668 M:910794752 NOTICE: ES: Stopping event server
22:17:44 T:2668 M:910794752 NOTICE: CNetwork::StopServices - Event Server stopped
22:17:44 T:2668 M:910794752 NOTICE: CNetwork::StopServices - Stopping JSONRPC Server
22:17:44 T:2668 M:910794752 NOTICE: CNetwork::StopServices - JSONRPC Server stopped
22:17:44 T:2668 M:910794752 NOTICE: CNetwork::NetworkMessage - Waiting for network services to stop
22:17:44 T:2668 M:910794752 NOTICE: Webserver: Stopping...
22:17:44 T:2668 M:910995456 NOTICE: WebServer: Stopped the webserver
22:17:44 T:2668 M:910995456 NOTICE: Webserver: Stopped...
22:17:44 T:3884 M:912732160 NOTICE: ES: UDP Event server stopped
22:17:44 T:2420 M:912732160 NOTICE: CThread:
taticThread: pThread->Process() finished22:17:44 T:3884 M:912732160 NOTICE: CEventServer::Run: About to call Cleanup
22:17:44 T:2420 M:912732160 NOTICE: CThread:
taticThread: Calling pThread->OnExit()22:17:44 T:3884 M:912732160 NOTICE: CEventServer::Cleanup: About to call m_pSocket->Close()
22:17:44 T:2420 M:912732160 NOTICE: CThread:
taticThread: pThread->OnExit() finished22:17:44 T:3884 M:912732160 NOTICE: CEventServer::Cleanup: m_pSocket->Close() finished
22:17:44 T:2420 M:912732160 NOTICE: CThread:
taticThread: Calling pThread->IsAutoDelete()22:17:44 T:3884 M:912732160 NOTICE: CEventServer::Cleanup: About to lock
22:17:44 T:2420 M:912732160 DEBUG: Thread 2420 terminating
22:17:44 T:3884 M:912732160 NOTICE: CEventServer::Cleanup: Lock finished
22:17:44 T:2420 M:912732160 NOTICE: CThread:
taticThread: Calling _endthreadex(123)22:17:44 T:3884 M:912732160 NOTICE: CEventServer::Cleanup: About to start client loop
22:17:44 T:3884 M:912732160 NOTICE: CEventServer::Cleanup: Client loop finished
22:17:44 T:3884 M:912732160 NOTICE: CEventServer::Run: Cleanup returned
22:17:44 T:3884 M:912732160 NOTICE: CEventServer:
rocess: Finished22:17:44 T:3884 M:912728064 NOTICE: CThread:
taticThread: pThread->Process() finished22:17:44 T:3884 M:912728064 NOTICE: CThread:
taticThread: Calling pThread->OnExit()22:17:44 T:3884 M:912728064 NOTICE: CThread:
taticThread: pThread->OnExit() finished22:17:44 T:3884 M:912728064 NOTICE: CThread:
taticThread: Calling pThread->IsAutoDelete()22:17:44 T:3884 M:912728064 DEBUG: Thread 3884 terminating
22:17:44 T:3884 M:912728064 NOTICE: CThread:
taticThread: Calling _endthreadex(123)i noticed in the working case, you have the following,
22:17:36 T:600 M:913293312 NOTICE: CNetwork::StopServices - Event Server stopped
22:17:36 T:600 M:913297408 NOTICE: CNetwork::StopServices - Stopping JSONRPC Server
22:17:36 T:600 M:913297408 NOTICE: CNetwork::StopServices - JSONRPC Server stopped
22:17:36 T:600 M:913297408 NOTICE: CNetwork::NetworkMessage - Network services to stopped
22:17:36 T:600 M:913297408 NOTICE: CApplication::Stop: StopServices() returned
none of those showed up in this case...
hope this helps
do you think this could just be a windows xp problem or some kind?
- defender013 - 2011-03-04
hi JR,
one more thing, the following is a working log,
22:17:35 T:600 M:910864384 NOTICE: ES: Stopping event server
22:17:35 T:600 M:910864384 NOTICE: CNetwork::StopServices - Event Server stopped
22:17:35 T:600 M:910864384 NOTICE: CNetwork::StopServices - Stopping JSONRPC Server
22:17:35 T:600 M:910864384 NOTICE: CNetwork::StopServices - JSONRPC Server stopped
22:17:35 T:600 M:910864384 NOTICE: CNetwork::NetworkMessage - Waiting for network services to stop
22:17:35 T:600 M:910864384 NOTICE: Webserver: Stopping...
22:17:35 T:600 M:911065088 NOTICE: WebServer: Stopped the webserver
22:17:35 T:600 M:911065088 NOTICE: Webserver: Stopped...
22:17:35 T:600 M:911077376 NOTICE: CNetwork::StopServices - Stopping Event Server
22:17:36 T:2132 M:913231872 NOTICE: ES: UDP Event server stopped
22:17:36 T:2540 M:913231872 NOTICE: CThread:
taticThread: pThread->Process() finished22:17:36 T:2132 M:913231872 NOTICE: CEventServer::Run: About to call Cleanup
22:17:36 T:2540 M:913231872 NOTICE: CThread:
taticThread: Calling pThread->OnExit()22:17:36 T:2132 M:913231872 NOTICE: CEventServer::Cleanup: About to call m_pSocket->Close()
22:17:36 T:2540 M:913231872 NOTICE: CThread:
taticThread: pThread->OnExit() finished22:17:36 T:2540 M:913231872 NOTICE: CThread:
taticThread: Calling pThread->IsAutoDelete()22:17:36 T:2540 M:913231872 DEBUG: Thread 2540 terminating
22:17:36 T:2132 M:913231872 NOTICE: CEventServer::Cleanup: m_pSocket->Close() finished
22:17:36 T:2540 M:913231872 NOTICE: CThread:
taticThread: Calling _endthreadex(123)22:17:36 T:2132 M:913231872 NOTICE: CEventServer::Cleanup: About to lock
22:17:36 T:2132 M:913231872 NOTICE: CEventServer::Cleanup: Lock finished
22:17:36 T:2132 M:913231872 NOTICE: CEventServer::Cleanup: About to start client loop
22:17:36 T:2132 M:913231872 NOTICE: CEventServer::Cleanup: Client loop finished
22:17:36 T:2132 M:913231872 NOTICE: CEventServer::Run: Cleanup returned
22:17:36 T:2132 M:913227776 NOTICE: CEventServer:
rocess: Finished22:17:36 T:2132 M:913227776 NOTICE: CThread:
taticThread: pThread->Process() finished22:17:36 T:2132 M:913227776 NOTICE: CThread:
taticThread: Calling pThread->OnExit()22:17:36 T:2132 M:913227776 NOTICE: CThread:
taticThread: pThread->OnExit() finished22:17:36 T:2132 M:913227776 NOTICE: CThread:
taticThread: Calling pThread->IsAutoDelete()22:17:36 T:2132 M:913227776 DEBUG: Thread 2132 terminating
22:17:36 T:2132 M:913227776 NOTICE: CThread:
taticThread: Calling _endthreadex(123)22:17:36 T:600 M:913293312 NOTICE: CNetwork::StopServices - Event Server stopped
22:17:36 T:600 M:913297408 NOTICE: CNetwork::StopServices - Stopping JSONRPC Server
22:17:36 T:600 M:913297408 NOTICE: CNetwork::StopServices - JSONRPC Server stopped
22:17:36 T:600 M:913297408 NOTICE: CNetwork::NetworkMessage - Network services to stopped
22:17:36 T:600 M:913297408 NOTICE: CApplication::Stop: StopServices() returned
22:17:36 T:600 M:913297408 NOTICE: stop sap announcement listener
but if you see, the following printout shows up twice,
22:17:35 T:600 M:910864384 NOTICE: CNetwork::StopServices - Event Server stopped
22:17:35 T:600 M:910864384 NOTICE: CNetwork::StopServices - Stopping JSONRPC Server
22:17:35 T:600 M:910864384 NOTICE: CNetwork::StopServices - JSONRPC Server stopped
- jhsrennie - 2011-03-04
The CNetwork::StopServices is called twice with a different argument, so the fact it appears twice in the log is expected.
If the log stops at:
22:17:44 T:3884 M:912728064 NOTICE: CThread:
taticThread: Calling _endthreadex(123)then that's a definite clue. My guess is that XBMC is waiting for the EventServer thread to exit and it never does. I've added even more logging around the code where XBMC waits for the thread, and I've put the modified version on http://swarchive.ratsauce.co.uk/xbmc/xbmc-debug.zip
again.
Incidentally, if you're ever confused about which version you're running, on the home page arrow down to System, press the right arrow and from the submenu select System Info. This latest version will show "Compiled Mar 4 2011".
Thanks,
JR