Wrong XML Received

dnunes · Post by **dnunes** » 17 Jan 2010, 20:36

Lapo wrote:
Whenever I get an error in the debug-versioin of the flashplayer, all (or most) server XML messages cause more error-popups complaining about the XML markup.
If you can provide a simple example that reproduces the issue it would be great

. . Sorry for the huge console log below. It is important to ilustrate the problem.

. . This is not a bug, guys. The problem is simple, take a look:

### ### Console output start ### ###
(...)
[Sending]: <msg t='sys'><body action='setUvars' r='25'><vars><var n='ty' t='n'><![CDATA[-543.7623611403974]]></var><var n='tx' t='n'><![CDATA[2432.5730520628235]]></var></vars></body></msg>
[Sending]: <msg t='sys'><body action='setUvars' r='25'><vars><var n='ty' t='n'><![CDATA[-543.7623611403973]]></var><var n='tx' t='n'><![CDATA[2392.573052062823]]></var></vars></body></msg>
[ RECEIVED ]: <msg t='sys'><body action='pubMsg' r='25'><user id='33' /><txt><![CDATA[!]]></txt></body></msg>, (len: 95)

DEBUG: PUBLIC message from "guest_33" says: "!"

[Fault] exception, information=TypeError: Error #1010: A term is undefined and has no properties.
Fault, gameover() at Amigo.as:128
[ RECEIVED ]: <msg t='sys'><body action='pubMsg' r='25'><user id='33' /><txt><![CDATA[!]]></txt></body></msg><msg t='sys'><body action='userGone' r='25'><user id='33' /></body></msg>, (len: 168)
[Fault] exception, information=TypeError: Error #1088: The markup in the document following the root element must be well-formed.
Fault, xmlReceived() at SmartFoxClient.as:2557
[ RECEIVED ]: <msg t='sys'><body action='pubMsg' r='25'><user id='33' /><txt><![CDATA[!]]></txt></body></msg><msg t='sys'><body action='userGone' r='25'><user id='33' /></body></msg><msg t='sys'><body action='uVarsUpdate' r='25'><user id='32' /><vars><var n='ty' t='n'><![CDATA[282.7493500861668]]></var><var n='tx' t='n'><![CDATA[1543.3304448274073]]></var></vars></body></msg>, (len: 364)
[Fault] exception, information=TypeError: Error #1088: The markup in the document following the root element must be well-formed.
Fault, xmlReceived() at SmartFoxClient.as:2557
[ RECEIVED ]: <msg t='sys'><body action='pubMsg' r='25'><user id='33' /><txt><![CDATA[!]]></txt></body></msg><msg t='sys'><body action='userGone' r='25'><user id='33' /></body></msg><msg t='sys'><body action='uVarsUpdate' r='25'><user id='32' /><vars><var n='ty' t='n'><![CDATA[282.7493500861668]]></var><var n='tx' t='n'><![CDATA[1543.3304448274073]]></var></vars></body></msg><msg t='sys'><body action='uVarsUpdate' r='25'><user id='32' /><vars><var n='ty' t='n'><![CDATA[96.7685879726334]]></var><var n='tx' t='n'><![CDATA[1720.6509529030927]]></var></vars></body></msg>, (len: 559)
[Fault] exception, information=TypeError: Error #1088: The markup in the document following the root element must be well-formed.
Fault, xmlReceived() at SmartFoxClient.as:2557
[ RECEIVED ]: <msg t='sys'><body action='pubMsg' r='25'><user id='33' /><txt><![CDATA[!]]></txt></body></msg><msg t='sys'><body action='userGone' r='25'><user id='33' /></body></msg><msg t='sys'><body action='uVarsUpdate' r='25'><user id='32' /><vars><var n='ty' t='n'><![CDATA[282.7493500861668]]></var><var n='tx' t='n'><![CDATA[1543.3304448274073]]></var></vars></body></msg><msg t='sys'><body action='uVarsUpdate' r='25'><user id='32' /><vars><var n='ty' t='n'><![CDATA[96.7685879726334]]></var><var n='tx' t='n'><![CDATA[1720.6509529030927]]></var></vars></body></msg><msg t='sys'><body action='uVarsUpdate' r='25'><user id='32' /><vars><var n='ty' t='n'><![CDATA[196.76858797263313]]></var><var n='tx' t='n'><![CDATA[1760.6509529030916]]></var></vars></body></msg>, (len: 756)
[Fault] exception, information=TypeError: Error #1088: The markup in the document following the root element must be well-formed.
Fault, xmlReceived() at SmartFoxClient.as:2557
[ RECEIVED ]: <msg t='sys'><body action='pubMsg' r='25'><user id='33' /><txt><![CDATA[!]]></txt></body></msg><msg t='sys'><body action='userGone' r='25'><user id='33' /></body></msg><msg t='sys'><body action='uVarsUpdate' r='25'><user id='32' /><vars><var n='ty' t='n'><![CDATA[282.7493500861668]]></var><var n='tx' t='n'><![CDATA[1543.3304448274073]]></var></vars></body></msg><msg t='sys'><body action='uVarsUpdate' r='25'><user id='32' /><vars><var n='ty' t='n'><![CDATA[96.7685879726334]]></var><var n='tx' t='n'><![CDATA[1720.6509529030927]]></var></vars></body></msg><msg t='sys'><body action='uVarsUpdate' r='25'><user id='32' /><vars><var n='ty' t='n'><![CDATA[196.76858797263313]]></var><var n='tx' t='n'><![CDATA[1760.6509529030916]]></var></vars></body></msg><msg t='sys'><body action='uVarsUpdate' r='25'><user id='32' /><vars><var n='ty' t='n'><![CDATA[116.76858797263309]]></var><var n='tx' t='n'><![CDATA[1760.650952903091]]></var></vars></body></msg>, (len: 952)
[Fault] exception, information=TypeError: Error #1088: The markup in the document following the root element must be well-formed.
Fault, xmlReceived() at SmartFoxClient.as:2557

-- Clicked on "ok" in the messages, no errors anymore --

[ RECEIVED ]: <msg t='sys'><body action='uVarsUpdate' r='25'><user id='32' /><vars><var n='ty' t='n'><![CDATA[116.76858797263309]]></var><var n='tx' t='n'><![CDATA[1800.6509529030907]]></var></vars></body></msg>, (len: 197)
[ RECEIVED ]: <msg t='sys'><body action='uVarsUpdate' r='25'><user id='32' /><vars><var n='ty' t='n'><![CDATA[-49.21217414090025]]></var><var n='tx' t='n'><![CDATA[2172.612477130153]]></var></vars></body></msg>, (len: 196)
[ RECEIVED ]: <msg t='sys'><body action='uVarsUpdate' r='25'><user id='32' /><vars><var n='ty' t='n'><![CDATA[-289.2121741409]]></var><var n='tx' t='n'><![CDATA[2532.6124771301497]]></var></vars></body></msg>, (len: 194)
[ RECEIVED ]: <msg t='sys'><body action='uVarsUpdate' r='25'><user id='32' /><vars><var n='ty' t='n'><![CDATA[-409.21217414089983]]></var><var n='tx' t='n'><![CDATA[2372.6124771301475]]></var></vars></body></msg>, (len: 198)
### ### Console output end ### ###

. . This is the relevant console content. The problem is that while the "an actionscript error has ocurred" box is showing, the script will stop working and it seems that the server repeat the messages it have sent to the client (take a look at how the messages are resent in the same packet right after the code error). It is likely that the server thinks that the client didn't receive the messages because it was unresponsive, so it kept resending everything again and again (probably making the "message out queue" goes up). After clicking "ok" on the boxes, everything goes back to normal, as you can see in the traces.
. . Although I know the code is supposed to deal with stacked messages, we have to bear with an unresponsive player.
. . If it helps, Lapo, it is very easy to reproduce: just open two players, connect to a server, make sure one of them throws an error and send default xml messages (user variables update, for example) from the other one while the "error ocurred" box is still showing.

Post by **Lapo** » 19 Jan 2010, 09:15

I am not able to reproduce the problem.
I have two clients running in the same Room, client A and B.
Client B is firing new UserVariables every second and Client A shows that it receives the events.
On Client A I can click a button that throws and Argument Error opening the infamous Error window of the debug player.
At this point Client A stops to respond to avents (apparently) but no other problems appear.
Finally I close the Error dialog box and all the "missing" events appear.

I also tried firing 10 variables update per second, no problem.

The problem is that while the "an actionscript error has ocurred" box is showing, the script will stop working and it seems that the server repeat the messages it have sent to the client

Those messages don't look like they are repeated, in fact they are different.

If you can provide a working examples that reproduces the issue it would be great.

dnunes · Post by **dnunes** » 19 Jan 2010, 23:23

Lapo wrote:Those messages don't look like they are repeated, in fact they are different.
If you can provide a working examples that reproduces the issue it would be great.

. . Just look at them. I mean... After the first error. The second message the server sends includes the first one and the third one includes the first and the second one. I'll make it clearer:

[Fault] exception, information=TypeError: Error #1010: A term is undefined and has no properties.
Fault, gameover() at Amigo.as:128
[ RECEIVED ]: <msg t='sys'><body action='pubMsg' r='25'><user id='33' /><txt><![CDATA[!]]></txt></body></msg><msg t='sys'><body action='userGone' r='25'><user id='33' /></body></msg>, (len: 168)
[Fault] exception, information=TypeError: Error #1088: The markup in the document following the root element must be well-formed.
Fault, xmlReceived() at SmartFoxClient.as:2557
[ RECEIVED ]: <msg t='sys'><body action='pubMsg' r='25'><user id='33' /><txt><![CDATA[!]]></txt></body></msg><msg t='sys'><body action='userGone' r='25'><user id='33' /></body></msg><msg t='sys'><body action='uVarsUpdate' r='25'><user id='32' /><vars><var n='ty' t='n'><![CDATA[282.7493500861668]]></var><var n='tx' t='n'><![CDATA[1543.3304448274073]]></var></vars></body></msg>, (len: 364)
[Fault] exception, information=TypeError: Error #1088: The markup in the document following the root element must be well-formed.
Fault, xmlReceived() at SmartFoxClient.as:2557
[ RECEIVED ]: <msg t='sys'><body action='pubMsg' r='25'><user id='33' /><txt><![CDATA[!]]></txt></body></msg><msg t='sys'><body action='userGone' r='25'><user id='33' /></body></msg><msg t='sys'><body action='uVarsUpdate' r='25'><user id='32' /><vars><var n='ty' t='n'><![CDATA[282.7493500861668]]></var><var n='tx' t='n'><![CDATA[1543.3304448274073]]></var></vars></body></msg><msg t='sys'><body action='uVarsUpdate' r='25'><user id='32' /><vars><var n='ty' t='n'><![CDATA[96.7685879726334]]></var><var n='tx' t='n'><![CDATA[1720.6509529030927]]></var></vars></body></msg>, (len: 559)

. . I can reproduce it very easily, but in a huge code. As soon as I have time I'll make a very small working example to send to you, ok?

Post by **Lapo** » 20 Jan 2010, 09:28

Yes, that would be useful.
Thanks

NateAustin · Post by **NateAustin** » 04 Feb 2010, 22:35

I figured out what's going on here. This issue had been plaguing us for a long time.

Inside SmartFoxClient.as, the function handleSocketData() is not written to be robust against errors that pop up during event dispatch. So when there's an error, it's possible for handleSocketData() to be called again before it gets a chance to clean up the socket buffer.

I have a patch that fixes this.

Here's the original function:

Code: Select all

    private function handleSocketData(evt:Event):void
    {			
        var bytes:int = socketConnection.bytesAvailable
   
            while (--bytes >= 0)
            {
                var b:int = socketConnection.readByte()
           
                if (b != 0x00)
                {
                    byteBuffer.writeByte(b)
                }
                else
                {
                    handleMessage(byteBuffer.toString())
                    byteBuffer = new ByteArray()
                }
          }
    }

You can see that if handleMessage() errors out, the byteBuffer will never be reset. This causes double messages the next time you get a server message.

here is my patch - I've also hardened the function against re-entry, which is a related phenomenon, where it seems that when there's an error during event dispatching, then handleSocketData can be in the call stack twice. I don't know if the call stack is accurately portraying what's going on in this case, but I fixed it anyway.

So here is the patch:

Code: Select all

        private function handleSocketData(evt:Event):void
        {			
            var bytes:int = socketConnection.bytesAvailable
   
            while (--bytes >= 0)
            {
                var b:int = socketConnection.readByte()
           
                if (b != 0x00)
                {
                    byteBuffer.writeByte(b)
                }
                else
                {
                    //clear the buffer before we call out, 
                    //so that if there's an error during 
                    //event dispatching, we leave the buffer 
                    //in a good state.
                    var message:String = byteBuffer.toString();
                    byteBuffer = new ByteArray();
                    handleMessage(message);
                    
                    //now, reset the bytes available, in case this function 
                    //was called during the event dispatch. We have observed 
                    //stack traces that show this happening, but it's not 
                    //entirely clear how/why, or if it's true. 
                    //nevertheless, it's an easy fix if so:
                    bytes = socketConnection.bytesAvailable;
                }
            }
        }

Post by **Lapo** » 05 Feb 2010, 08:57

Hi,
thanks for your submission, you have some valid point.
While I do agree with you that there's a possible way for the execution to escape the proper flow leaving the byte array in a "dirty" state I was never able to see a stack trace that showed how this happened.

This seems quite a rare case, and we have not yet found a way to make it happen at will. Also the stack traces that show two messages in the buffer don't contain the previous exception which we would expect to be the cause of this second problem.
Have you been able to see anything like that?

At any rate hardening the code of that method looks like a very good idea.
I would prefer to use a try/catch/finally instead to take full control of the code flow. Although I haven't tested this yet I would suggest this version:

Code: Select all

private function handleSocketData(evt:Event):void
{			
	var bytes:int = socketConnection.bytesAvailable
   
	while (--bytes >= 0)
	{
		var b:int = socketConnection.readByte()
   	
		if (b != 0x00)
			byteBuffer.writeByte(b)
		
		else
		{	
			// Attempt to execute the handleMessage
   			try
			{
				handleMessage(byteBuffer.toString()) 	
			}
			
			/*
			* If any error occurs we make sure that it is trapped here
			* We then log it to the console and allow it to bubble up normally
			*/
			catch(err:Error)
			{
				trace("Error occured while handling the message: " + err)
				throw(err)
			}
			
			/*
			* Before we exit this method we make sure that the state of the buffer
			* is consistent.
			*/
			finally
			{
				byteBuffer = new ByteArray()
			}
   		}
   	}
}

Also at this point I would also make the byteBuffer variable not global but local to the function to make absolutely sure that it's scope is confined to handleSocketData. This way the finally block could be removed and if any error occurs the current state of the byte data reading is preserved.

We'll make some tests next week and release a new updated API soon with these fixes.

Post by **Lapo** » 10 Feb 2010, 17:47

Here is an update to the API which adds the fixes we have discussed here. It would be great if you could try and provide more feedback.

Download from here

p.s. = needless to say it is required to recompile your application with the new API before testing.

Post by **Lapo** » 19 Feb 2010, 11:42

Any updates on this?
Did you try the updated API with your code? Can you tell us if you are able to handle the problem now?

thank you