User variable update race condition

[abush]

I've come across a situation with appears to be a race condition in the SFS2X client.

Setup:

Code: Select all

smartFox.AddLogListener(LogLevel.INFO, onInfoMessage);
smartFox.AddEventListener(SFSEvent.USER_VARIABLES_UPDATE, onUserVariableUpdate);

private void onInfoMessage(Sfs2X.Core.BaseEvent evt)
{
    string message = (string)evt.Params["message"];
    UnityEngine.Debug.LogFormat("[SFS INFO] {0}", message);
}

private void onUserVariableUpdate(Sfs2X.Core.BaseEvent evt)
{
    User user = (User)evt.Params[ "user"];
    ArrayList changedVars = (ArrayList)evt.Params["changedVars"];
    foreach(string var in changedVars)
    {
        UnityEngine.Debug.Log("Changed " + var + " to " + user.GetVariable(var));
    }
}


Working example log from setting a user variable:

Code: Select all

[SFS INFO] Message: SetUserVariables { Message id: 12 }
{ Dump: }

    (int) u: 9
    (sfs_array) vl:
        (sfs_array)
            (utf_string) con_prop
            (byte) 4
            (utf_string)
                "actionCount":1

UnityEngine.Debug:Internal_Log(Int32, String, Object)
UnityEngine.Debug:Log(Object)
SmartFoxGameServerClient:onInfoMessage(BaseEvent) (at Assets\SmartFoxGameServerClient.cs:1328)
Sfs2X.Core.EventDispatcher:DispatchEvent(BaseEvent)
Sfs2X.SmartFox:ProcessEvents()


Changed con_prop to [UVar: con_prop, type: STRING, value: {"actionCount":1}]
UnityEngine.Debug:Internal_Log(Int32, String, Object)
UnityEngine.Debug:Log(Object)
SmartFoxGameServerClient:onUserVariableUpdate(BaseEvent) (at Assets\SmartFoxGameServerClient.cs:279)
Sfs2X.Core.EventDispatcher:DispatchEvent(BaseEvent)
Sfs2X.SmartFox:ProcessEvents()


Now the log from the race condition situation:

Code: Select all

[SFS INFO] Message: SetUserVariables { Message id: 12 }
{ Dump: }

    (int) u: 9
    (sfs_array) vl:
        (sfs_array)
            (utf_string) con_prop
            (byte) 4
            (utf_string)
                "actionCount":0

UnityEngine.Debug:Internal_Log(Int32, String, Object)
UnityEngine.Debug:Log(Object)
SmartFoxGameServerClient:onInfoMessage(BaseEvent) (at Assets\SmartFoxGameServerClient.cs:1328)
Sfs2X.Core.EventDispatcher:DispatchEvent(BaseEvent)
Sfs2X.SmartFox:ProcessEvents()

Changed con_prop to
UnityEngine.Debug:Internal_Log(Int32, String, Object)
UnityEngine.Debug:Log(Object)
SmartFoxGameServerClient:onUserVariableUpdate(BaseEvent) (at Assets\SmartFoxGameServerClient.cs:279)
Sfs2X.Core.EventDispatcher:DispatchEvent(BaseEvent)
Sfs2X.SmartFox:ProcessEvents()

[SFS INFO] Message: SetUserVariables { Message id: 12 }
{ Dump: }

    (int) u: 9
    (sfs_array) vl:
        (sfs_array)
            (utf_string) con
            (byte) 0
            (null) NULL

        (sfs_array)
            (utf_string) con_prop
            (byte) 0
            (null) NULL

UnityEngine.Debug:Internal_Log(Int32, String, Object)
UnityEngine.Debug:Log(Object)
SmartFoxGameServerClient:onInfoMessage(BaseEvent) (at Assets\SmartFoxGameServerClient.cs:1328)
Sfs2X.Core.EventDispatcher:DispatchEvent(BaseEvent)
Sfs2X.SmartFox:ProcessEvents()

Changed con to
UnityEngine.Debug:Internal_Log(Int32, String, Object)
UnityEngine.Debug:Log(Object)
SmartFoxGameServerClient:onUserVariableUpdate(BaseEvent) (at Assets\SmartFoxGameServerClient.cs:279)
Sfs2X.Core.EventDispatcher:DispatchEvent(BaseEvent)
Sfs2X.SmartFox:ProcessEvents()

Changed con_prop to
UnityEngine.Debug:Internal_Log(Int32, String, Object)
UnityEngine.Debug:Log(Object)
SmartFoxGameServerClient:onUserVariableUpdate(BaseEvent) (at Assets\SmartFoxGameServerClient.cs:279)
Sfs2X.Core.EventDispatcher:DispatchEvent(BaseEvent)
Sfs2X.SmartFox:ProcessEvents()


What's going on here is on the server I'm setting the user variable to a value and then immediately afterwards removing it. The network messages are as I'd expect (variable with a value, followed by variable set to null). And 2 events are dispatched to the USER_VARIABLES_UPDATE listener as expected. However when the first of the 2 events is dispatched the User object variables are already set as I'm expecting them to be during second dispatch.

I'm at a bit of a loss in finding a way around this behaviour, I could delay the user variable clearing on the server side, but presumably this client behaviour would still occur under certain network conditions.

[Lapo]

Thanks for reporting.
I need to see the server side code that you're using for the 2nd test and it would also help to know the API version in use and Unity Editor version.

Thanks

[abush]

Certainly, the relevant server side code looks like this:

Code: Select all

UserVariable propertiesVariable = new SFSUserVariable("con_prop", "{\"actionCount\":0}");
SmartFoxServer.getInstance().getAPIManager().getSFSApi().setUserVariables(user, Arrays.asList(propertiesVariable));
...
List<UserVariable> vars = new ArrayList<UserVariable>(2);
vars.add(new SFSUserVariable("con", null));
if (user.containsVariable("con_prop") && !user.getVariable("con_prop").isNull()) {
    vars.add(new SFSUserVariable("con_prop", null));
}
SmartFoxServer.getInstance().getAPIManager().getSFSApi().setUserVariables(user, vars);


Running SFS 2.10.0 on the server and 1.6.2.1 on the client with Unity version 5.2.2p2.

[Lapo]

Thanks.

What happens is that you do get two events but while you're handling the first one the 2nd one is also processed and the variables for the User are updated concurrently. Your event handler ends up up seeing the 2nd state while technically still in the previous event.

This is mainly because the event refers you to the user's UVars instead of passing a copy of the changes before they are applied.

While this can be fixed with synchronizing the two threads, in general I would suggest to avoid sending multiple updates of the same value in a row. It is more efficient to simply calculate the final value in your server logic and then transmit it to the client, otherwise you're doubling the packet count for each response.

In any case we'll look into this more closely. Thanks for reporting.

[Lapo]

EXTRA NOTE:
the problem seem to show up only in Unity while it doesn't running the same code in .NET/Mono.

I think this has to do with the ThreadSafe vs non ThreadSafe modalities of the API and the possibly "slower" event queue processing done by the main Unity thread.

cheers

[abush]

Thanks Lapo,

That's what I expected was causing the behaviour.

I guess I'll have to rethink my approach here, originally I was consolidating the network events as you suggest, however the client triggers logic on the state transitions, so it's imperative that they receive both network events. For this case I can probably rework things to have a special command I fire off instead of doing this double state change (ie: command + clear user var instead of set user var + clear user var) since the server code path for this is isolated (and there's no concern with late arriving users missing the intermediate state).

I do fear there's still a general race condition here given the multi threaded nature of the game server and the potential for inconsistent network packet delivery times, however I suppose the take away is to never have the client depend on transitional behaviour between states for user (and room) variables.

[abush]

Alternatively it looks like if I disable ThreadSafeMode, wrap all events from the SmartFox class, and put the processed events back onto the main unity thread (after I've extracted the relevant user data myself) everything behaves as I'd expect (matching .NET/Mono).

I know disabling thread safe mode is not recommended in Unity, however does the SmartFox lib itself have known threading issues in this scenario? or is it just a recommendation to prevent all the potential issues with handling the smarfox events in a different thread?

[Lapo]

I do fear there's still a general race condition here given the multi threaded nature of the game server and the potential for inconsistent network packet delivery times, however I suppose the take away is to never have the client depend on transitional behaviour between states for user (and room) variables.

This is correct.
With Unity + ThreadSafeMode events are no longer executed sequentially in the SFS API thread, instead they are generated by the SFS thread and then handed to Unity's main thread which runs in parallel.
I don't even think it's possible to use some form of thread synchronization as this would ultimately result in stopping Unity's main thread, which I don't think it's allowed (..and if it was allowed, it could interfere by slowing it down), but I am not an expert in Unity's inner working.

On the bright side, this is the first time we encounter the problem and besides this very specific use case it doesn't seem to cause any other issue.

Alternatively it looks like if I disable ThreadSafeMode, wrap all events from the SmartFox class, and put the processed events back onto the main unity thread (after I've extracted the relevant user data myself) everything behaves as I'd expect (matching .NET/Mono).

I know disabling thread safe mode is not recommended in Unity, however does the SmartFox lib itself have known threading issues in this scenario? or is it just a recommendation to prevent all the potential issues with handling the smarfox events in a different thread?

I don't think there should be any problem, as long as you don't try to invoke Unity Engine's methods from an SFS thread.

thanks

[abush]

Everything is looking good far, I'll let you know if any issues arise.