Last week I had an interesting adventure following up on a nondescript exception. It was being thrown by a Perl application currently in development at my workplace that will bridge a 3rd party SOAP API to our billing system while adding some magic in the middle. The application uses XML::Compile::WSDL11 to load a WSDL and two XSDs and this backs onto XML::Compile::Soap and LibXML::Simple for its XML handling. Triggering the error was straight forward and could be caused by compiling a specific group of calls and sending a query that would result in valid data being returned.

'report_opts' => {
	'location' => [
		'XML::Compile::Translate::Reader',
		'/home/edward/perl5/lib/perl5/XML/Compile/Translate/Reader.pm',
		609,
		'Log::Report::error',
		1,
		undef,
		undef,
		undef,
		1794,
		'TUUEEUUUUUUUUU^E',
		undef
	],
	'stack' => []
},
'reason' => 'ERROR',
	'message' => bless( {
		'_prepend' => 'decode error: ',
		'name' => '{services}product',
		'path' => '{services}searchResponse/devices/values/model',
		'_msgid' => 'element `{name}\' not processed at {path}',
		'_expand' => 1,
		'_domain' => 'xml-compile',
		'_class' => 'misfit',
		'_join' => ' '
	'Log::Report::Message' )
}, 'Log::Report::Exception' )

Initial troubleshooting

This exact error had come up earlier in development and had been traced back to the use of Log::Report. While not at fault itself, we found that the use of complex types in the XSDs by the 3rd party was triggering a warning in the LibXML::Simple included in XML::Compile. I was using Log::Report in ‘DEBUG’ mode to follow various bits of XML information during execution and this was causing the lower warning to become an exception by the time it reached my code. For the original case of the exception no problems were found in the code, or the XSDs, and the library clearly hadn’t intended for the warning to kill the program so commenting out Log::Report in my module resolved the issue.

So seeing this exception again after Log::Report had been removed from the equation was cause for concern. After breaking out the offending code and replicating the issue the next step was to jump once again into Reader.pm and its dependents to look for a fault. This wasn’t as easy as it should have been as XML::Compile is a mess of anonymous subroutines and this made debugging a real pain. However, after some time I was able to satisfy myself that our code, the libraries, and the third party XML were correct and fault must lay elsewhere. Along the way I learnt an entire volume of how Perl worked under the hood and brushed up on debuggers and XML encoding/decoding.

Identifying the offender

During my debugging of the XML libraries I had identified the scope of the elements causing the warning, which the libraries internal use of Log::Report was escalating to an exception. This was the natural starting point once I had finished reviewing libraries and my code. I sent through various request versions to gather all of the failure cases and compare those to the working returns. This quickly isolated one complex type element that worked normally but failed when its enclosing element included an xsi:type=” attribute. This led me back to a paragraph of documentation I’d seen around for handling XSI:Type which unfortunately assumed you were aware of the problem and equally aware of how to fix it. I neither knew of the problem nor how to fix it, plus all of the information available via Google searches added at best a sentence or two to my understanding.

So while I had this new information it was not clear how my exception and this handling were related nor how to try and fix one with the other. Working on the assumption that they were the same, though being very careful not to get focused and miss the obvious signs that it was time to move onto a new theory, I worked to bridge the gap between the two. I started by distilling the XSDs, my code, and a SOAP query that would reliably trigger a response that would cause an exception into a little package to test with. Just as I finished this task the unix tool socat was introduced to our team and an afternoon was lost to manipulating the returning packet which, as expected, failed to be productive but was awesome fun. I shall write a future blog post on socat so I’ll leave that story for another day.

At the very least this packet manipulation confirmed that the XML being returned wasn’t at fault either. If you haven’t been keeping score this left me with a functional XML parser, a working application, valid XSDs, valid SOAP packets, and an exception thrown from a legitimate warning. The warning itself was being triggered by the decoding of the element in the error because the parser couldn’t find a match for the type in its understanding of the XML tree generated by the XSDs. At this point the problem had became that obvious, though in hindsight it’s only because via the process of elimination every other possibility had been exhausted!

Examination of the XML

Our team has a strong ethos of understanding a problem before resolving it to ensure the right problem has been solved correctly. This meant finding out why the parser was having trouble matching the type of the element to the valid types tree as well as figuring out why the developers had decided that this case should not be resolved automatically, as my tests of the same call in PHP showed it could have been. Below is a cut down version of the two XSDs with the relevant type structure and an example of the response structure as well as an example of the return.

service1.xsd namespace=”types”

<?xml version="1.0" encoding="UTF-8"?>
<xs:schema xmlns:tns="types" xmlns:xs="http://www.w3.org/2001/XMLSchema" elementFormDefault="qualified" version="1.0" targetNamespace="types">

<xs:complexType name="commonRecordData">
	<xs:sequence>
		<xs:element name="name" type="xs:string" minOccurs="0"></xs:element>
		<xs:element name="creationTime" type="xs:dateTime" minOccurs="0"></xs:element>
		<xs:element name="id" type="xs:string" minOccurs="0"></xs:element>
	</xs:sequence>
</xs:complexType>

service2.xsd namespace=”services”

<?xml version="1.0" encoding="UTF-8"?>
<xs:schema xmlns:tns="services" xmlns:ns1="types" xmlns:xs="http://www.w3.org/2001/XMLSchema" elementFormDefault="qualified" version="1.0" targetNamespace="services">

<xs:import namespace="types" schemaLocation="service1.xsd"></xs:import>

<xs:element name="searchResponse">
	<xs:complexType>
		<xs:all>
			<xs:element name="devices" type="tns:deviceList" minOccurs="0"></xs:element>
		</xs:all>
	</xs:complexType>
</xs:element>

<xs:complexType name="deviceList">
	<xs:sequence>
		<xs:element name="values" type="tns:device" nillable="true" minOccurs="0" maxOccurs="unbounded"></xs:element>
	</xs:sequence>
</xs:complexType>

<xs:complexType name="device">
	<xs:complexContent>
		<xs:extension base="ns1:commonRecordData">
			<xs:sequence>
				<xs:element name="models" type="ns1:commonRecordData" minOccurs="0"></xs:element>
			</xs:sequence>
		</xs:extension>
	</xs:complexContent>
</xs:complexType>

<xs:complexType name="models">
	<xs:complexContent>
		<xs:extension base="ns1:commonRecordData">
			<xs:sequence>
				<xs:element name="product" type="xs:string" minOccurs="0"></xs:element>
				<xs:element name="manufacturer" type="xs:string" minOccurs="0"></xs:element>
			</xs:sequence>
		</xs:extension>
	</xs:complexContent>
</xs:complexType>

searchResponse including XSI:Type attribute

<?xml version="1.0" ?>
<S:Envelope xmlns:S="http://schemas.xmlsoap.org/soap/envelope/">
<S:Body>
	<ns2:searchResponse xmlns="types" xmlns:ns2="services">
		<ns2:devices>
			<ns2:values>
				<ns2:models xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:type="ns2:models">
					<id>6af3cdde-830e-8205-2e2b-bab5ff2f3d08</id>
					<name>an example model</name>
					<creationTime>2012-10-24T05:27:10.000Z</creationTime>
					<ns2:product>device 1234</ns2:product>
					<ns2:manufacturer>vendor 1234</ns2:manufacturer>
				</ns2:models>
			</ns2:values>
		</ns2:devices>
	</ns2:searchResponse>
</S:Body>
</S:Envelope>

In the above examples you can see that there are two elements in the list and the first decodes while the second, as per the exception above, throws a warning. When the types are followed to the XSDs the chains of relations all appear to be completely fine. Some cheating with socat allowed me to rewrite element attributes (or remove them) and along with a few custom XSDs I was able to show that the parser was simply not aware of the complex type ‘models’ in the context of the response message. Until this point I had been working under the assumption that xsi:type was the cause of the issue and not the vendors attempt to resolve an issue. This was an important realisation and suddenly I understood the need to handle a mismatch in xsi:type and the context of the documentation.

Final resolution

XSI:Type Handling Documentation from XML::Compile::Schema

[1.10] The xsi:type is an old-fashioned mechanism, and should be avoided! In this case, the schema does tell you that a certain element has a certrain type, but at run-time(!) that is changed. When an XML element has a xsi:type attribute, it tells you simply to have an extension of the original type. This whole mechanism does bite the “compilation” idea of XML::Compile… however with some help, it will work.

To make xsi:type work at run-time, you have to pass a table of which types you expect at compile-time.

As you can see even once the problem is known interpreting the given solution isn’t that straight forward. After figuring out that the WSDL11 compiler would take an xsi:type mapping table when the object was being created I tried several attempts to follow the documentation using its example and the one other example I could find on the internet (which didn’t relate at all to my problem). As tends to happens with these problems I didn’t get anywhere with it until I was half way through explaining the problem to a co-worker. The mapping, in retrospect, is of course a rigid list of how to get from the absolute base class (in XSD1), through every intermediary class required, to the class eventually causing the issue.

Final XSI:Type Handling Solution

my $wsdl = new XML::Compile::WSDL11;
$wsdl->addWSDL($wsdl_services);
$wsdl->importDefinitions($services1);
$wsdl->importDefinitions($services2);

$wsdl->xsiType(
	"{types}commonRecordData" =>
		[ "{services}models" ]
);

However, if you had multiple classes between the base and several final classes it could look a lot more complex. The important thing to realise is this is a way for the compiler to build a valid path from the basic type to only the type(s) you’re trying to have it decode. The easiest way to figure out this mapping is to distil your XSD working from the final class backwards through all of the extends=” until you have a list of classes that depend on other classes. Reverse that list so you have the base class working towards the final class and use that as your xsi_type table.

Problem solved

Handling the XSI:Type mismatch in Perl allowed me to leave the third parties XSDs removing the risk of breaking future compatibility. It’s a good work around as well any fixed XSDs in future will cause the xsiType() to silently stop applying. It is possible that beyond creating new mapping tables no future maintainers of the software will have to change these tables. In terms of elegance it doesn’t get better than that when dealing with others broken software.

So while finding this solution took days to investigate and solve I found it was a nice personal demonstration that 1.00 FTE’s recent comic isn’t always true.