2010-11-24, 09:48
Hey
I don't know if this is the right place to post this but as I think the problem is related to JSON RPC and XBMCs webserver I thought I'd post it here first and if it's not the right place someone can point me to where to post this best.
When I'm running my "XBMC on iMON Display" application using JSON RPC to retrieve all the information from XBMC it often happens that XBMC crashes on shutdown. I did it a few times with debug logging enabled and compared the log files and they always look the same after a crash.
This is how the end of the log file looks when the shutdown doesn't crash:
and this is how it looks when it crashes:
Of course the terminated thread numbers vary but I noticed that it never gets to
I also have an idea why this might be happening: In my application I have an option to enable polling XBMCs CurrentControl info label every 500 ms. This allows to display the label of the current control on the LCD display and therefore it is possible to use XBMC without turning on the TV. BUT on shutdown it might happen that a GetInfoLabels() call is sent right before/after the ApplicationStop announcement arrived. Now XBMC is already shutting down its webserver but receives another request and might not know what to do.
I want to emphasize that this is only an idea I had because I noticed that everytime XBMC crashes on shutdown I get errors in the log of my application and when it doesn't crash there are no errors either.
I'll see if I can get rid of the calls causing the problem but if it is really as I suspect XBMC shouldn't really crash just because there is some stupid application (which might not listen to the announcements) calls another JSON RPC method when XBMC doesn't expect it.
I don't know if this is the right place to post this but as I think the problem is related to JSON RPC and XBMCs webserver I thought I'd post it here first and if it's not the right place someone can point me to where to post this best.
When I'm running my "XBMC on iMON Display" application using JSON RPC to retrieve all the information from XBMC it often happens that XBMC crashes on shutdown. I did it a few times with debug logging enabled and compared the log files and they always look the same after a crash.
This is how the end of the log file looks when the shutdown doesn't crash:
Code:
08:31:23 T:5212 M:1053921280 DEBUG: CAnnouncementManager - Announcement: ApplicationStop from xbmc
08:31:23 T:5212 M:1053913088 NOTICE: Storing total System Uptime
08:31:23 T:5212 M:1053917184 NOTICE: Saving settings
08:31:23 T:5212 M:1053954048 NOTICE: stop all
08:31:23 T:5212 M:1053954048 DEBUG: CNetwork::NetworkMessage - Signaling network services to stop
08:31:23 T:5212 M:1053949952 NOTICE: ES: Stopping event server
08:31:23 T:5212 M:1053945856 DEBUG: CNetwork::NetworkMessage - Waiting for network services to stop
08:31:23 T:5212 M:1053945856 NOTICE: Webserver: Stopping...
08:31:23 T:5212 M:1053958144 NOTICE: WebServer: Stopped the webserver
08:31:23 T:5212 M:1053958144 NOTICE: Webserver: Stopped...
08:31:23 T:3976 M:1053999104 INFO: JSONRPC Server: Disconnection detected
08:31:23 T:3976 M:1053999104 DEBUG: Thread 3976 terminating
08:31:23 T:1724 M:1053757440 NOTICE: ES: UDP Event server stopped
08:31:23 T:1724 M:1053757440 DEBUG: Thread 1724 terminating
08:31:23 T:5212 M:1053790208 NOTICE: stop player
08:31:23 T:5132 M:1053790208 INFO: PAPlayer: End of playback reached
08:31:23 T:5132 M:1053790208 DEBUG: CAnnouncementManager - Announcement: PlaybackStopped from xbmc
08:31:23 T:5132 M:1053790208 DEBUG: PAPlayer: Thread end
08:31:23 T:5132 M:1053790208 DEBUG: Thread 5132 terminating
08:31:23 T:4632 M:1054523392 DEBUG: Thread 4632 terminating
08:31:23 T:5212 M:1060118528 DEBUG: CWin32DirectSound::Deinitialize: Cleaning up
08:31:23 T:5212 M:1060163584 NOTICE: stop sap announcement listener
08:31:23 T:5212 M:1060163584 NOTICE: clean cached files!
08:31:23 T:5212 M:1060319232 NOTICE: unload skin
08:31:23 T:5212 M:1060319232 DEBUG: ------ Window Deinit (Home.xml) ------
08:31:23 T:5212 M:1060319232 DEBUG: ------ Window Deinit (MusicOverlay.xml) ------
08:31:23 T:5212 M:1060319232 DEBUG: ------ Window Deinit (Pointer.xml) ------
08:31:23 T:5212 M:1060319232 DEBUG: ------ Window Deinit (DialogMuteBug.xml) ------
08:31:23 T:5212 M:1084399616 NOTICE: stop python
08:31:24 T:5212 M:1111687168 NOTICE: stopped
08:31:24 T:5212 M:1111683072 NOTICE: destroy
08:31:24 T:5212 M:1111715840 INFO: ADDON: cpluff: 'An unreleased information object was encountered at address 02CC3C40 with reference count 1 when destroying the associated plug-in context. Not releasing the object.'
08:31:24 T:5212 M:1111715840 INFO: ADDON: cpluff: 'An unreleased information object was encountered at address 02CC37C0 with reference count 1 when destroying the associated plug-in context. Not releasing the object.'
08:31:24 T:5212 M:1111715840 INFO: ADDON: cpluff: 'An unreleased information object was encountered at address 02CC3C88 with reference count 1 when destroying the associated plug-in context. Not releasing the object.'
08:31:24 T:5212 M:1111715840 INFO: ADDON: cpluff: 'An unreleased information object was encountered at address 02CE0110 with reference count 1 when destroying the associated plug-in context. Not releasing the object.'
08:31:24 T:5212 M:1111715840 INFO: ADDON: cpluff: 'An unreleased information object was encountered at address 02CC3898 with reference count 1 when destroying the associated plug-in context. Not releasing the object.'
08:31:24 T:5212 M:1111715840 INFO: ADDON: cpluff: 'An unreleased information object was encountered at address 02CE0860 with reference count 1 when destroying the associated plug-in context. Not releasing the object.'
08:31:24 T:5212 M:1111715840 INFO: ADDON: cpluff: 'An unreleased information object was encountered at address 02CE01E8 with reference count 1 when destroying the associated plug-in context. Not releasing the object.'
08:31:24 T:5212 M:1111715840 INFO: ADDON: cpluff: 'An unreleased information object was encountered at address 02CDFFA8 with reference count 1 when destroying the associated plug-in context. Not releasing the object.'
08:31:24 T:5212 M:1111715840 INFO: ADDON: cpluff: 'An unreleased information object was encountered at address 02CC3B68 with reference count 1 when destroying the associated plug-in context. Not releasing the object.'
08:31:24 T:5212 M:1111715840 INFO: ADDON: cpluff: 'An unreleased information object was encountered at address 02CC36E8 with reference count 1 when destroying the associated plug-in context. Not releasing the object.'
08:31:24 T:5212 M:1111715840 INFO: ADDON: cpluff: 'An unreleased information object was encountered at address 02CC39B8 with reference count 1 when destroying the associated plug-in context. Not releasing the object.'
08:31:24 T:5212 M:1111715840 INFO: ADDON: cpluff: 'An unreleased information object was encountered at address 02CC3778 with reference count 1 when destroying the associated plug-in context. Not releasing the object.'
08:31:24 T:5212 M:1111715840 NOTICE: unload sections
08:31:24 T:5212 M:1111715840 DEBUG: SECTION:UnloadAll(SECTION: LIBHTTP)
08:31:24 T:5212 M:1111715840 DEBUG: SECTION:UnloadAll(DLL: special://xbmcbin/system/cpluff.dll)
08:31:24 T:5212 M:1111715840 DEBUG: Win32DllLoader::Unload cpluff.dll
08:31:24 T:5212 M:1111715840 DEBUG: FreeLibrary(libexpat.dll) -> 022B8950
08:31:24 T:5212 M:1111715840 DEBUG: Win32DllLoader::Unload libexpat.dll
08:31:24 T:5212 M:1111896064 DEBUG: SECTION:UnloadAll(DLL: special://xbmcbin/system/ImageLib.dll)
08:31:24 T:5212 M:1111896064 DEBUG: Win32DllLoader::Unload ImageLib.dll
08:31:24 T:5212 M:1112223744 DEBUG: SECTION:UnloadAll(DLL: special://xbmcbin/system/players/dvdplayer/libmad.dll)
08:31:24 T:5212 M:1112223744 DEBUG: Win32DllLoader::Unload libmad.dll
08:31:24 T:5212 M:1112297472 DEBUG: SECTION:UnloadAll(DLL: special://xbmcbin/system/libid3tag.dll)
08:31:24 T:5212 M:1112297472 DEBUG: Win32DllLoader::Unload libid3tag.dll
08:31:24 T:5212 M:1112453120 INFO: lastfm destroyed
and this is how it looks when it crashes:
Code:
08:32:03 T:4660 M:1068199936 DEBUG: CAnnouncementManager - Announcement: ApplicationStop from xbmc
08:32:03 T:4660 M:1068199936 NOTICE: Storing total System Uptime
08:32:03 T:4660 M:1068199936 NOTICE: Saving settings
08:32:03 T:5532 M:1068199936 INFO: JSONRPC Server: Disconnection detected
08:32:03 T:4660 M:1068011520 NOTICE: stop all
08:32:03 T:4660 M:1068011520 DEBUG: CNetwork::NetworkMessage - Signaling network services to stop
08:32:03 T:4660 M:1068011520 NOTICE: ES: Stopping event server
08:32:03 T:4660 M:1068007424 DEBUG: CNetwork::NetworkMessage - Waiting for network services to stop
08:32:03 T:4660 M:1068007424 NOTICE: Webserver: Stopping...
08:32:03 T:336 M:1068007424 NOTICE: ES: UDP Event server stopped
08:32:03 T:336 M:1068007424 DEBUG: Thread 336 terminating
08:32:04 T:5532 M:1068019712 DEBUG: Thread 5532 terminating
Of course the terminated thread numbers vary but I noticed that it never gets to
Code:
08:31:23 T:5212 M:1053958144 NOTICE: WebServer: Stopped the webserver
08:31:23 T:5212 M:1053958144 NOTICE: Webserver: Stopped...
I also have an idea why this might be happening: In my application I have an option to enable polling XBMCs CurrentControl info label every 500 ms. This allows to display the label of the current control on the LCD display and therefore it is possible to use XBMC without turning on the TV. BUT on shutdown it might happen that a GetInfoLabels() call is sent right before/after the ApplicationStop announcement arrived. Now XBMC is already shutting down its webserver but receives another request and might not know what to do.
I want to emphasize that this is only an idea I had because I noticed that everytime XBMC crashes on shutdown I get errors in the log of my application and when it doesn't crash there are no errors either.
I'll see if I can get rid of the calls causing the problem but if it is really as I suspect XBMC shouldn't really crash just because there is some stupid application (which might not listen to the announcements) calls another JSON RPC method when XBMC doesn't expect it.