[SOLVED] Reactor Error After Room Left (u44) Message Received

[sean]

Hi there guys,

I have an application where rooms are created and shut down on demand and a client can enter and leave rooms as they please. For some reason, at odd times there is an error within the Reactor framework code and I can't seem to emulate it definitely each time. The conditions don't appear to be uniform at this time.

The error is a Null pointer error so I was hoping you could give me some insight into which objects are being referenced at this particular line of code in hopes that this may help me to understand what is happening? Here is the error stack trace:

Code: Select all

TypeError: Error #1009: Cannot access a property or method of a null object reference.
at net.user1.reactor::Room/purgeRoomData()[/Users/colin/build/working/src/net/user1/reactor/Room.as:2099]
at net.user1.reactor::Room/doLeave()[/Users/colin/build/working/src/net/user1/reactor/Room.as:534]
at CoreMessageListener/u44()[/Users/colin/build/working/src/net/user1/reactor/CoreMessageListener.as:619]
at Function/http://adobe.com/AS3/2006/builtin::apply()
at net.user1.reactor::MessageManager/notifyMessageListeners()[/Users/colin/build/working/src/net/user1/reactor/MessageManager.as:720]
at net.user1.reactor::MessageManager/upcReceivedListener()[/Users/colin/build/working/src/net/user1/reactor/MessageManager.as:293]
at flash.events::EventDispatcher/dispatchEventFunction()
at flash.events::EventDispatcher/dispatchEvent()
at net.user1.reactor::XMLSocketConnection/dataListener()[/Users/colin/build/working/src/net/user1/reactor/XMLSocketConnection.as:219]
at flash.events::EventDispatcher/dispatchEventFunction()
at flash.events::EventDispatcher/dispatchEvent()
at flash.net::XMLSocket/scanAndSendEvent()


This error doesn't seem to crash the client app but it does pop up often so I'm wondering if I am doing something wrong in terms of room management? This one seems to be out of my control...

Thanks in advance for your time,
Sean T.

[colin]

hi sean,
thanks for another high-quality bug report. the error you reported was caused by an attempt to dispose of a room that had already been disposed. theoretically that could only happen at disconnection time or if you are calling disposeCachedRooms() manually. do you have a call to disposeCachedRooms() in your code?

i have uploaded a new build with a fix here:
http://www.unionplatform.com/staging/re ... or/latest/

the bug report is here:
http://factory.user1.net/issues/show/568

but i am still interested in knowing exactly how this bug is triggered. if it occurs again, could you please post your client log (on DEBUG)? also, if your codebase is small enough, could you post the relevant sections here or point me to a repository if it is public? i'd need to see anything to do with room creation, removal, leaving, and watching). let me know if you'd rather send me a zip privately.

thanks,
colin

[sean]

Hey there Colin,

Thanks for getting back to me and I'm glad that my feedback is able to contribute to the Union platform.

This Error is one that is so weird and it seems to happen at odd times so I will definitely help you to diagnose it if it still persists after the rebuild. If it boils down to it, I will privately send you applicable source code. Currently I am not calling disposeCachedRooms() manually but I do start and stop the observation process when rooms are added and removed so maybe something in my room management process can be triggering it. Anyway, if this helps, I noticed I get another form of the error after receipt of the STOPPED_OBSERVING_ROOM message, here is the stack trace:

Code: Select all

TypeError: Error #1009: Cannot access a property or method of a null object reference.
   at net.user1.reactor::Room/purgeRoomData()[/Users/colin/build/working/src/net/user1/reactor/Room.as:2099]
   at net.user1.reactor::Room/doStopObserving()[/Users/colin/build/working/src/net/user1/reactor/Room.as:1002]
   at CoreMessageListener/u62()[/Users/colin/build/working/src/net/user1/reactor/CoreMessageListener.as:769]
   at Function/http://adobe.com/AS3/2006/builtin::apply()
   at net.user1.reactor::MessageManager/notifyMessageListeners()[/Users/colin/build/working/src/net/user1/reactor/MessageManager.as:720]
   at net.user1.reactor::MessageManager/upcReceivedListener()[/Users/colin/build/working/src/net/user1/reactor/MessageManager.as:293]
   at flash.events::EventDispatcher/dispatchEventFunction()
   at flash.events::EventDispatcher/dispatchEvent()
   at net.user1.reactor::XMLSocketConnection/dataListener()[/Users/colin/build/working/src/net/user1/reactor/XMLSocketConnection.as:219]
   at flash.events::EventDispatcher/dispatchEventFunction()
   at flash.events::EventDispatcher/dispatchEvent()
   at flash.net::XMLSocket/scanAndSendEvent()


It seems to reference the same line of Code at line 2099 so I assume that it is the same bug but in this case just triggered by the Stop Observing Event as opposed to Room Left event.

Oh...if this helps...what I do frequently in the app is stopWatchingForRooms and restart the process again. So the context of the app is a Main area, where a user is able to pick a lounge to enter. Once they choose a lounge, they can sit on a particular game table. Once the required amount of players join a game table, then they are all "brought into the game room screen" and at this point the RoomManager stops watching for rooms since the information about who is sitting where is no longer needed. The errors tend to pop up after being in the game room area or sometimes right after leaving the game room back to the lobby. Once back in the Lobby where the list of tables are populated with information about who is sitting where, then the RoomManager restarts watching for rooms.

So I'm not sure if frequently calling the stop and starting of room watching could be the trigger of this?

[colin]

ah, that makes some sense. sounds like you're getting a u44 (LEFT_ROOM) followed by a u33 (REMOVE_ROOM_RESULT), which would indirectly trigger dispose() on the room twice.

it would be nice to confirm that sequence of events though. if you see the error again (before you upgrade), please post your client log. if your client log is not handy, the server log will do.

thanks,
colin

[sean]

Okay, I think it's starting to make sense to me now...I will try to catch the error in action before upgrading so I can send you a copy of the client log.

[sean]

Good news Colin...I was able to capture client log output while the Error took place and based on the output, I have further insight into the problem :)

Below is a snippet that I believe is enough to sum up the issue:

Code: Select all

11/24/11 16:22:48.713 UTC-5 INFO:  [ROOM id: CUT4-C] New occupant count: 0
11/24/11 16:22:48.882 UTC-5 INFO:  [ROOM_MANAGER] Room removed: [ROOM id: CUT4-C].
11/24/11 16:22:48.883 UTC-5 INFO:  [ROOM_MANAGER] New room count: 9.
11/24/11 16:22:48.883 UTC-5 INFO:  [ROOM id: CUT4-C] Current client is observing the room. Forcing the client to stop observing...
11/24/11 16:22:48.883 UTC-5 INFO:  [ROOM id: CUT4-C] Observation stopped.
11/24/11 16:22:48.884 UTC-5 INFO:  [ROOM id: CUT4-C] Dereferencing resources.
11/24/11 16:22:48.884 UTC-5 INFO:  [ROOM id: CUT4-C] Shutdown complete.


So the room in question is the room with id "CUT4-C". Based on the Room ID I know that this is one of the main lounges (lobby) before someone picks a particular game table within X lounge. Because the error popped up while I was seated at the game table, it provides further insight into better optimizing my room management code.

Whenever a main lounge is added to the room manager's list, the current code, starts observing that room for updates of how many occupants are in that room. However, while seated at a game table, this information is no longer needed. The current code stops observing all lounges upon Joining a lounge but let's say a lounge is added after a user joins a lounge, it is still starting the observation process on that lounge. I guess this is where watching for rooms by a particular qualifier ID will come in handy. So I will need to adjust my code to only start the observation process if the user is at the main screen BEFORE choosing a lounge to enter.

Anyway, back to Union, so based on the output above, it seems what happens is since the rooms are set to DIE ON EMPTY, all the other occupants had left the lounge that was being observed so this triggered the room shutdown event but when the client got the message, we have a line that says: "Current client is observing the room. Forcing the client to stop observing..." So I assume that's the reason for the double dispose() being called on the room? But then again, it should be doing that gracefully anyway? Because you may have code that doesn't necessarily get a chance to stop observing before the room is shut down.

In my particular app, I believe I can get rid of the bug by simply NOT observing any of the main lounges if they are added while joining one of the particular lounges (before filling up a game table within that lounge). Once required # of players is reached on a game table, then the room manager stops watching for rooms so the problem area is in the time before this happens.

Anyway, sorry for the rant, just found the experience enlightening since it also gave me the chance to further optimize my room management which was the goal of my most recent code overhaul.

Let me know if this information satisfies your theory..

[colin]

hi sean,
i've added protective code, but i haven't been able to reproduce the error you're reporting in an isolated test yet. could you please set your log level to DEBUG and when you see the error, post your entire log (not just a short snippet)? here is how to change your log level:

Code: Select all

reactor.getLog().setLevel(Logger.DEBUG);

thanks,
colin

[sean]

Hey Colin, is the log level set to DEBUG by default?

I do have more statements prior to that point but Flash player crashed while hanging in the debugger so the lines I posted were at the end before the crash.

If it's set to DEBUG by default, then I can show you the rest of activity before...

[sean]

Found it in the API Reference, INFO is default, so I will retry with level set to DEBUG.

[colin]

if you can't reproduce the error with a full DEBUG log, explicit steps (or sample code) to reproduce the error would be welcome too. i tried re-creating your scenario, but have not been able to reproduce the error.

colin