Redundant u8 Messages (S2C_CLIENT_ATTR_UPDATE)

All Union Platform questions, comments, feature requests, and bug reports.

Redundant u8 Messages (S2C_CLIENT_ATTR_UPDATE)

Postby toby » Tue 07 Aug 2012 02:40

To indicate that a client has undergone some state change,
I update one of his attributes to a new value in a Room Module
(which is not the lobby Module by the way).

I have everyone join a lobby room when they log in, and also every client does
lobby.addEventListener(net.user1.orbiter.RoomEvent.UPDATE_CLIENT_ATTRIBUTE, cliAttChanged);
to be notified when those values change.

It works ok, but in viewing the log to debug my code, I noticed something strange.

In my test, I have just two clients logged in.

Whenever I update a client attribute, the client who the attribute belongs to gets a single u8 message,
S2C_CLIENT_ATTR_UPDATE, with the new value.
So far, so good.

Here's the strange part:
Also on every occurrence, the OTHER client (whose attribute is not being set)
gets either 3 or 4 identical u8 messages in quick succession, all with the same new value.
I can tell from my own debugging entries in the log that these all come from the same
setAttribute() call.

When I added a third client to the mix,
he gets the multiple messages too - alternating with the second client.

The sequence is:
1: attribute changed for client 1
2: client 1 gets a single u8 message
then there are 3 (sometimes 4) pairs of
u8 messages directed, alternately, to client 2 and client 3,
that is the messages are
(To client 2, To client 3) (To client 2, To client 3) ... etc.
with all members of all the pairs identical.
toby
 
Posts: 162
Joined: Sun 24 Jun 2012 14:18

Re: Redundant u8 Messages (S2C_CLIENT_ATTR_UPDATE)

Postby colin » Tue 07 Aug 2012 10:21

hi toby,
sounds like a coding error. try to create the minimal possible test case to reproduce the behaviour. if you can't spot the problem in that test, feel free to post the test code here for others to examine.

colin
colin
 
Posts: 232
Joined: Mon 17 Oct 2011 18:47

Re: Redundant u8 Messages (S2C_CLIENT_ATTR_UPDATE)

Postby toby » Tue 07 Aug 2012 16:03

Solved??

So far, I have not succeeded in making a minimal test case.
I will submit this however:

Here's my code from my Room Module.
It is within a function which is invoked by a "left the room" event.

Code: Select all
log.debug("Unseating " + name);
cl.setAttribute("seated", "", Attribute.SCOPE_GLOBAL,
         Attribute.FLAG_SHARED | Attribute.FLAG_SERVER_ONLY);
log.debug("Unseat " + name + " completed");


Here's what I see in the log (blank lines added here for readability)

Code: Select all
2012-08-07 13:08:16,721 DEBUG - Server sending to client [2] message [<U><M>S2C_CLIENT_REMOVED(u37)</M><L><A><![CDATA[Challenge.001]]></A><A>2</A></L></U>]
2012-08-07 13:08:16,721 DEBUG - Server sending to client [1] message [<U><M>S2C_CLIENT_REMOVED(u37)</M><L><A><![CDATA[Challenge.001]]></A><A>2</A></L></U>]

--> These messages are from code just before the code above:
2012-08-07 13:08:16,721 DEBUG - kmart left room
2012-08-07 13:08:16,721 DEBUG - Player in seat 1 = null
2012-08-07 13:08:16,721 DEBUG - Player in seat 2 = kmart

--> Above code snippet starts here
2012-08-07 13:08:16,721 DEBUG - Unseating kmart

2012-08-07 13:08:16,721 DEBUG - Server sending to client [2] message [<U><M>S2C_CLIENT_ATTR_UPDATE(u8)</M><L><A><![CDATA[]]></A><A>2</A><A><![CDATA[kmart]]></A><A><![CDATA[seated]]></A><A><![CDATA[]]></A><A>68</A></L></U>]
2012-08-07 13:08:16,721 DEBUG - Server sending to client [1] message [<U><M>S2C_CLIENT_ATTR_UPDATE(u8)</M><L><A><![CDATA[]]></A><A>2</A><A><![CDATA[kmart]]></A><A><![CDATA[seated]]></A><A><![CDATA[]]></A><A>68</A></L></U>]
2012-08-07 13:08:16,721 DEBUG - Server sending to client [1] message [<U><M>S2C_CLIENT_ATTR_UPDATE(u8)</M><L><A><![CDATA[]]></A><A>2</A><A><![CDATA[kmart]]></A><A><![CDATA[seated]]></A><A><![CDATA[]]></A><A>68</A></L></U>]
2012-08-07 13:08:16,721 DEBUG - Server sending to client [1] message [<U><M>S2C_CLIENT_ATTR_UPDATE(u8)</M><L><A><![CDATA[]]></A><A>2</A><A><![CDATA[kmart]]></A><A><![CDATA[seated]]></A><A><![CDATA[]]></A><A>68</A></L></U>]

2012-08-07 13:08:16,721 DEBUG - Unseat kmart completed

2012-08-07 13:08:16,737 DEBUG - Client [2] has left room [Challenge.001].
2012-08-07 13:08:16,737 DEBUG - Server sending to client [2] message [<U><M>S2C_LEAVE_ROOM_RESULT(u76)</M><L><A>Challenge.001</A><A>SUCCESS</A></L></U>]


NOTE:
It could be a logging problem ...
the listeners for the event only receive it once.
toby
 
Posts: 162
Joined: Sun 24 Jun 2012 14:18

Re: Redundant u8 Messages (S2C_CLIENT_ATTR_UPDATE)

Postby colin » Wed 08 Aug 2012 00:26

solved until you are able to reduce the issue to a minimal test sample that demonstrates/reproduces the issue.

colin
colin
 
Posts: 232
Joined: Mon 17 Oct 2011 18:47

Re: Redundant u8 Messages (S2C_CLIENT_ATTR_UPDATE)

Postby toby » Wed 08 Aug 2012 02:58

The critical thing appears to be that clients join two rooms simultaneously.

Then if there are two clients active, one gets a single u8
(the one who sent the u70). Everyone else gets multiple u8's all identical,
at least in the log.

I'm not sure how to get it to do more than two, but it will.
I've seen 3 and 4 repetitions.
Perhaps if you join and leave a few more rooms.

Here's a test case: [ see end of message for a note about making it even simpler ]

Start with Orbiter Chat Room example: http://www.unionplatform.com/?page_id=3318

- join a second room (any other room)

- Instead of sending a chat message, send a room module message.
The name of that message is used to update a client attribute for the client who sent it.

Here's the client side code:

Code: Select all
29a30
> var UPC = net.user1.orbiter.UPC;
54c55,56
<   orbiter.connect("tryunion.com", 80);
---
>   //orbiter.connect("tryunion.com", 80);
>   orbiter.connect("localhost", 9100);
69a72
>  chatRoom.addEventListener(net.user1.orbiter.RoomEvent.UPDATE_CLIENT_ATTRIBUTE, cliAttChanged);
75a79,80
>   orbiter.getRoomManager().joinRoom("SOME_OTHER_ROOM"); // Can be any other existing room
>
91a97,103
> function cliAttChanged(e)
> {
>  var att = e.getChangedAttr();
>  if (att.name == "_PING") return;
>  displayChatMessage("Client Attr Changed " + att.name);
> }
>
110a123
>
113c126,127
<     chatRoom.sendMessage("CHAT_MESSAGE", "true", null, outgoing.value);
---
>  orbiter.getMessageManager().sendUPC(UPC.SEND_ROOMMODULE_MESSAGE, "chatRoom", outgoing.value);
>     //chatRoom.sendMessage("CHAT_MESSAGE", "true", null, outgoing.value);



Here's the room module: chat_mod.js

Code: Select all
importClass(org.apache.log4j.Logger);
importClass(net.user1.union.core.attribute.Attribute);
importClass(net.user1.union.core.def.RoomDef);
importClass(net.user1.union.core.def.AttributeDef);
importClass(net.user1.union.core.def.ModuleDef);
importClass(net.user1.union.api.Room);
importClass(net.user1.union.core.event.RoomEvent);
importClass(net.user1.union.core.event.ServerEvent);

var moduleContext;
var wrapper;
var myRoom;
var server;
var log = Logger.getLogger("chat_mod");

function init(ctx, wrap)
{
  moduleContext = ctx;
  wrapper = wrap;
  myRoom = ctx.getRoom();
  server = ctx.getServer();
  wrapper.addRoomEventListener(RoomEvent.MODULE_MESSAGE, "onModuleMessage");
  wrapper.addRoomEventListener(RoomEvent.ADD_CLIENT, "newOcc");
}

function newOcc(e)
{
var cl = e.getClient();
cl.setAttribute("seated", "", Attribute.SCOPE_GLOBAL,
             Attribute.FLAG_SHARED | Attribute.FLAG_SERVER_ONLY);
}

function onModuleMessage(e)
{
var cl = e.getClient();
cl.setAttribute("seated", e.getMessage().getMessageName(), Attribute.SCOPE_GLOBAL,
             Attribute.FLAG_SHARED | Attribute.FLAG_SERVER_ONLY);
}


// This method must be implemented by every room module script.
function shutdown()
{
}


Add this to union.xml:
Code: Select all
<room>
       <id>chatRoom</id>
       <modules>
           <module>
              <id>chat_mod</id>
              <source type="script">chat_mod.js</source>
           </module>
       </modules>
</room>



For an even simpler test case, you don't need the Room Module.
Instead of sending a Room Module Message,
just do orbiter.self().setClientAttribute( .... ).

Then what you see in the log is:
u3 for the client setting the attribute and
double u8 for the other client, and no u8 for the first client,
and finally a u73, set_client_attribute_result.

Again, joining two rooms simultaneously seems to be the key factor.
toby
 
Posts: 162
Joined: Sun 24 Jun 2012 14:18

Re: Redundant u8 Messages (S2C_CLIENT_ATTR_UPDATE)

Postby toby » Fri 31 Aug 2012 18:40

It seems to me now there might be a real performance question here.
There appears to be a multiplier effect, whereby joining more rooms
(my clients might be in as many as 3), and having more clients,
generates lots of messages.

I question whether it will be feasible to use the attribute in the way
I am, where there will be frequent changes to it (not so many to any
one client, but overall to the set of clients). Or perhaps use it at all.

Here is what I get from 4 clients having joined (the same) three rooms,
and setting a single attribute for a single client:

Single message sent to the client who has the attribute change:
2012-08-31 15:38:10,727 DEBUG - Server to 5 S2C_CLIENT_ATTR_UPDATE(u8)

The other three clients all are notified FIVE times!

2012-08-31 15:38:10,727 DEBUG - Server to 7 S2C_CLIENT_ATTR_UPDATE(u8)
2012-08-31 15:38:10,727 DEBUG - Server to 6 S2C_CLIENT_ATTR_UPDATE(u8)
2012-08-31 15:38:10,728 DEBUG - Server to 8 S2C_CLIENT_ATTR_UPDATE(u8)

2012-08-31 15:38:10,729 DEBUG - Server to 7 S2C_CLIENT_ATTR_UPDATE(u8)
2012-08-31 15:38:10,729 DEBUG - Server to 6 S2C_CLIENT_ATTR_UPDATE(u8)
2012-08-31 15:38:10,729 DEBUG - Server to 8 S2C_CLIENT_ATTR_UPDATE(u8)

2012-08-31 15:38:10,729 DEBUG - Server to 7 S2C_CLIENT_ATTR_UPDATE(u8)
2012-08-31 15:38:10,729 DEBUG - Server to 6 S2C_CLIENT_ATTR_UPDATE(u8)
2012-08-31 15:38:10,730 DEBUG - Server to 8 S2C_CLIENT_ATTR_UPDATE(u8)

2012-08-31 15:38:10,730 DEBUG - Server to 7 S2C_CLIENT_ATTR_UPDATE(u8)
2012-08-31 15:38:10,730 DEBUG - Server to 6 S2C_CLIENT_ATTR_UPDATE(u8)
2012-08-31 15:38:10,730 DEBUG - Server to 8 S2C_CLIENT_ATTR_UPDATE(u8)

2012-08-31 15:38:10,730 DEBUG - Server to 7 S2C_CLIENT_ATTR_UPDATE(u8)
2012-08-31 15:38:10,731 DEBUG - Server to 6 S2C_CLIENT_ATTR_UPDATE(u8)
2012-08-31 15:38:10,731 DEBUG - Server to 8 S2C_CLIENT_ATTR_UPDATE(u8)

Now imagine the situation where there are 50-100 clients,
and several of them decide to change this attribute (or have it
changed on their behalf) ... the result, it seems, would be hundreds,
if not thousands, of redundant messages.
toby
 
Posts: 162
Joined: Sun 24 Jun 2012 14:18

Re: Redundant Messages add u89 (LOGGED_OFF) to the list

Postby toby » Thu 06 Sep 2012 19:07

I observe a similar phenomenon with u89 S2C_LOGGED_OFF messages.
I suspect there are others as well.

With client attributes, by jumping through a few hoops, I was able to
avoid using them, saving countless redundant messages.
There aren't any hoops or detours for logoff ... it's the only exit from the system.

Each room you observe or join generates a logoff message when someone (else) logs off.
For the client actually doing the logoff, there is only 1.

In this case there were 4 clients, who each observed or joined (the same) 3 rooms.
One logged off, which generated 3 useful messages, and 6 redundant ones.

If there were 100 clients logged in,
that would be 100 useful messages, and 200 redundant ones.
Every time someone logged off
(which will be quite often - people pop in and out quite a bit).


2012-09-06 16:49:59,663 DEBUG - from 27 C2S_LOGOFF(u86) USER-ID

2012-09-06 16:49:59,663 DEBUG - Server to 23 S2C_LOGGED_OFF(u89) 27 ! USER-ID
2012-09-06 16:49:59,663 DEBUG - Server to 25 S2C_LOGGED_OFF(u89) 27 ! USER-ID
2012-09-06 16:49:59,664 DEBUG - Server to 26 S2C_LOGGED_OFF(u89) 27 ! USER-ID

2012-09-06 16:49:59,664 DEBUG - Server to 23 S2C_LOGGED_OFF(u89) 27 ! USER-ID
2012-09-06 16:49:59,664 DEBUG - Server to 25 S2C_LOGGED_OFF(u89) 27 ! USER-ID
2012-09-06 16:49:59,664 DEBUG - Server to 26 S2C_LOGGED_OFF(u89) 27 ! USER-ID

2012-09-06 16:49:59,664 DEBUG - Server to 23 S2C_LOGGED_OFF(u89) 27 ! USER-ID
2012-09-06 16:49:59,664 DEBUG - Server to 25 S2C_LOGGED_OFF(u89) 27 ! USER-ID
2012-09-06 16:49:59,664 DEBUG - Server to 26 S2C_LOGGED_OFF(u89) 27 ! USER-ID

2012-09-06 16:49:59,664 DEBUG - Server to 27 S2C_LOGGED_OFF(u89) 27 ! USER-ID
toby
 
Posts: 162
Joined: Sun 24 Jun 2012 14:18

Re: Redundant u8 Messages (S2C_CLIENT_ATTR_UPDATE)

Postby toby » Sun 09 Jun 2013 23:40

Having recently added a new client attribute to my app,
I observed this problem anew, so I am wondering if it is
receiving any attention.

Fortunately, these new attributes will not change very often,
so I will be able to use them, but this does appear to be a bug,
and I think it should be resolved.
toby
 
Posts: 162
Joined: Sun 24 Jun 2012 14:18


Return to Union Platform

Online

Users browsing this forum: No registered users and 4 guests