views:

383

answers:

3

I'm seeing something very very strange happening in a Flex app I'm maintaining.

I've been going through it removing all calls to trace() and replacing it with calls into the logging framework (using the built in mx.logging stuff). After doing so some XML parsing code suddenly broke, and I can't for the life of me figure out why.

here's the code:

private var loader:URLLoader; // created elsewhere

private function handleComplete(event:Event):void {    
  default xml namespace = com;
  xml = XML(loader.data);
  var response:XML = new XML(xml..raniResponse);
  //now handles a null response object
  if(xml && response.children().length() > 0) {
    LOG.debug("Got response.");
    var cityXML:XML = new XML(xml..city);
    var stateXML:XML = new XML(xml..stateProv);
    /* Some extra processing is done here */
  }
}

With the code like this, with that LOG.debug() call in place, I get the following error on the line cityXML is defined:

TypeError: Error #1088: The markup in the document following the root element must be well-formed.

If I comment out the LOG.debug() call it works fine.

I thought there might be some weirdness with the custom log target I created, so I removed that. Currently the only target being used is the built-in trace target.

Does anyone know what's going on? Why would a logging call break the XML parsing? I can't think of anything it could be doing that would break it.

EDIT:

I did some more tests, and it's just getting weirder.

I changed the code based on David's comment to use xml..city[0] instead of new XML(xml..city) for both assignments. This caused the exception to happen a bit later (in some code not shown above where it's referencing cityXML). So I tried stepping through in the debugger and noticed something odd.

cityXML was being set to null, while stateXML was getting the proper value. Looking at the xml object in the debugger showed all the correct data, so it should have been fine. As a random test I rearranged the code so that stateXML was being loaded first. After doing that, stateXML is null, while cityXML is correct.

So, whichever assignment happens immediately after the log is failing, but whatever happens after that worked fine.

Here's the (somewhat sanitized) XML that's being parsed:

<?xml version="1.0" encoding="utf-8"?>
<soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/"&gt;
  <soapenv:Body>
    <com:MyCompanyRANIv.01 xmlns:com="com:myc:rani:1:0:message" xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/"&gt;
      <com:raniResponse>
        <com:telephonyInfo>
          <com:countryCode>1</com:countryCode>
          <com:telephoneNumber>14121234567</com:telephoneNumber>
        </com:telephonyInfo>
        <com:geoInfo>
          <com:coordinates>
            <com:latLon>
              <com:lat>40.49</com:lat>
              <com:lon>-79.92</com:lon>
            </com:latLon>
          </com:coordinates>
          <com:countryInfo>
            <com:country>
              <com:featureName>United States</com:featureName>
              <com:featureTypeDescription>United States of America</com:featureTypeDescription>
              <com:featureCode value="US" system="ISO 3166" family="Country Code" systemVer="1-alpha-2" />
            </com:country>
          </com:countryInfo>
          <com:stateProvInfo>
            <com:stateProv>
              <com:featureName>PENNSYLVANIA</com:featureName>
              <com:featureTypeDescription xsi:nil="true" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" />
              <com:featureCode family="US State Code" system="FIPS State Alpha Code" systemVer="" value="PA" />
            </com:stateProv>
          </com:stateProvInfo>
          <com:regionInfo>
            <com:region>
              <com:featureName xsi:nil="true" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" />
              <com:featureTypeDescription xsi:nil="true" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" />
              <com:featureCode family="" system="" systemVer="" value="" />
            </com:region>
          </com:regionInfo>
          <com:countyParishInfo>
            <com:countyParish>
              <com:featureName>ALLEGHENY</com:featureName>
              <com:featureTypeDescription xsi:nil="true" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" />
              <com:featureCode family="" system="" systemVer="" value="" />
            </com:countyParish>
          </com:countyParishInfo>
          <com:cityInfo>
            <com:city>
              <com:featureName>PITTSBURGH</com:featureName>
              <com:featureTypeDescription xsi:nil="true" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" />
              <com:featureCode family="" system="" systemVer="" value="" />
            </com:city>
          </com:cityInfo>
          <com:buildingInfo>
            <com:building>
              <com:featureName xsi:nil="true" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" />
              <com:featureTypeDescription xsi:nil="true" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" />
            </com:building>
          </com:buildingInfo>
          <com:streetAddress address="" />
        </com:geoInfo>
        <com:services host="false" wireless="false" other="false" />
      </com:raniResponse>
      <com:raniRequest>
        <com:fullyQualifiedTelephoneNumber>14121234567</com:fullyQualifiedTelephoneNumber>
      </com:raniRequest>
    </com:MyCompanyRANIv.01>
  </soapenv:Body>
</soapenv:Envelope>
+1  A: 

That's a tough one. I never used the logging classes, so I'm unsure of that part of the question, but converting an XMLList to XML like you do:

var cityXML:XML = new XML(xml..city);

works only if the XMLList contains a single item, otherwise you get the warning you quoted. Try the following form instead:

var cityXML:XML = xml..city[0];

This works for empty lists as well as for lists with many items. You could also check the number of children with xml..city.length() and log a warning message if it is not 1. Perhaps this will help to figure out the exact problem.

How this is effected by adding or removing logging calls, though, beats me.

(On a somewhat related note, I noticed that declaring and assigning value to an XML variable within a case block of a switch statement does not work as expected, i.e. the assignment is simply ignored, and the variable will not be assigned a value. Breaking the line in two helps. This also seemed like a bug to me, so perhaps not everything is right with the compilation of XML-related code in AS3.)

David Hanak
Looking at the XML being parsed there is only one "city" node. Same with the other things being pulled out of it. So theoretically the XML conversion should work fine.
Herms
Theoretically, yes. But there could be some bugs with XML handling, as I pointed out, that's why I suggested trying an alternative notation. There's no harm in trying. :-)
David Hanak
Yea, I tried it. It moved the error to somewhere else in the code. I updated the question with details.
Herms
+1  A: 

Posting this as an answer instead of an edit as it includes some workarounds.

I did a few more tests. Here's the relevant code from the first:

LOG.debug("Got response:");
var cityXML:XML = xml..city[0];
var stateXML:XML = xml..stateProv[0];

Stepping through with the debugger, cityXML is assigned to null, while stateXML gets the right value.

Next, I tried this:

LOG.debug("Got response:");
trace("foobar");
var cityXML:XML = xml..city[0];
var stateXML:XML = xml..stateProv[0];

It worked! (why?!). Both cityXML and stateXML got the right values.

Not satisfied with this, I tried another test. I thought maybe I just needed some other operation between the log and the first assignment (no idea WHY, but just experimenting here). So I tried this:

LOG.debug("Got response:");
var someDumbVariable:Number = 42;
var cityXML:XML = xml..city[0];
var stateXML:XML = xml..stateProv[0];

This didn't work. So, one more test:

LOG.debug("Got response:");
var cityXML:XML = xml..city[0];
cityXML = xml..city[0];
var stateXML:XML = xml..stateProv[0];

This worked! When stepping through with the debugger the first assignment ends with cityXML being set to null. However, the 2nd assignment to it gives the correct value. (I tried simply splitting the cityXML line into a declaration on one line and the assignment on another, but that didn't change the behavior. 2 assignments seemed necessary).

Another workaround:

LOG.debug("Got response:");
if(xml.length() == 0) { return; }
var cityXML:XML = xml..city[0];
var stateXML:XML = xml..stateProv[0];

I still have no idea why the log would cause this stuff to happen, but it seems that either throwing a trace in or attempting the assignment twice works around the issue. I'm going to keep investigating to see if I can figure out the root cause here, but at least I've now got a couple workarounds that don't involve removing the logging.

Herms
Since mine is the only answer so far that actually has working workarounds I'm going to accept it, but I'd love it if someone could find a better answer!
Herms
A: 

Hmm. This looks very similar to the problem I have mentioned. Try this: move the XML variable declarations to the head of the function:

private function handleComplete(event:Event):void {    
  var cityXML:XML;
  var stateXML:XML;

  default xml namespace = com;
  xml = XML(loader.data);
  var response:XML = new XML(xml..raniResponse);
  //now handles a null response object
  if(xml && response.children().length() > 0) {
    LOG.debug("Got response.");
    cityXML = new XML(xml..city);
    stateXML = new XML(xml..stateProv);
    /* Some extra processing is done here */
  }
}

(Posted as a separate answer because it is so much different from the previous one.)

David Hanak
Nope, no change in behavior. I think it has less to do with the variable and more to do with accessing the XML. For some reason that first time trying to access it isn't working properly.
Herms