Posted on Nov 11, 2011

A PHP proxy script for logging Magento API SOAP calls

We’ve struck the need to debug client’s calls to the Magento API during product import and update processes on a couple of sites.  Magento’s API isn’t the fastest, but various factors could be contributing to performance issues and errors being returned.  In a couple of cases recently, we’ve needed to check:

  • Our client’s import / sync routines are definitely calling the API correctly, and synchronously
  • Is there a performance problem?  Client-side or application-side?
  • What does the raw request look like, are similar calls similarly slow?

If we can establish some of the above we are better equipped to pinpoint the problem and fix, so on the suggestion of a good mate I decided to write a proxy script to run all requests through, log things and see what was going on.

API Versions

First you need to get your versions right.  Magento has two versions of its API, with different URLs.  For this to work we’ll need to make sure our proxy is inline with the right version, as we discovered when a client was calling V2 and the proxy calling V1.  Not surprisingly that didn’t work, so we’ll configure the proxy script to an api on a per-site basis.

The Test Script

Here’s a basic script, which will call the Magento API first to create a session then to request a customer record or other API calls.  Note that we point the SoapClient at our proxy script, not the Magento API URl.  There are calls to both V1 and V2 APIs in here.  There are also calls to a logger class which is bespoke for this purpose (see below).

proxytest.php

function soapTest($logger)
{
	$mage_proxy_url = 'http://domain.com/proxy/proxy.php?wsdl';
	$mage_user = 'api_user'; 
	$mage_api_key = 'password'; 

	// Initialize the SOAP client 
	$logger->Log("***Starting SoapClient");
	$soap = new SoapClient( $mage_proxy_url, array('trace' => 1, 'cache_wsdl'=>0) ); 
	// Login to Magento 
	$logger->Log("***New client established: ");
	try{
		// Login call is cross version
		$session_id = $soap->login( $mage_user, $mage_api_key );
		$logger->Log("SessionID: ".$session_id);
		
		// Version 1 API calls
		$result = $soap->call( $session_id, 'customer.info', 1);
		$result = $soap->call( $session_id, 'customer.info', 2);
		$result = $soap->call( $session_id,'catalog_product.info','MDCOM01'); 
		
		// Version 2 API calls
		//$result = $soap->customerCustomerInfo($session_id, 1);
		//$result = $soap->catalogCategoryAttributeList($session_id);
		
	}
	catch (Exception $e) {
		echo ('Caught exception: '.  $e);
	}

}


$logger = new ProxyLogger();
$logger->FileFolder = "/usr/share/nginx/debug/";
$logger->FileName = "proxylog-client";
$logger->Open();

soapTest($logger);

$logger->Close();

All we need to do is call this via a browser and it’ll run some SOAP requests via the API.  Then we check logs to see what happened, or monitor using tail -F to view in realtime.

The Logger Class

This is pretty simple but capable of producing some nice easy to read logs.  It’s instantiated as shown above and takes some optional parameters of sessionID and requestID so we can easily trace each session, and each call:

@ini_set('display_errors', 'Off');

class ProxyLogger{
	
	var $FH;
	var $FileFolder;
	var $FileName;
	
	function Open() {
		$filePath = $this->FileFolder.$this->FileName."_".date("Ymd",time()).".log";
		$this->FH = fopen($filePath, 'a') or die("can't open file: ".$filePath);
	}
	
	function Log($strMessage, $sessionId=false, $requestId = false){
		
		// Get timestamp
		list($totalSeconds, $extraMilliseconds) = $this->TimeAndMilliseconds();
		$tStamp = date("d-m-Y H:i:s", $totalSeconds) . " ".$extraMilliseconds;
			
		// Build message
		$strLog = $tStamp;
		if($sessionId) $strLog.="       ".$sessionId;
		if($requestId) $strLog.="	".$requestId;
		$strLog.= "	".$strMessage."\n";
		
		// Write log
		fwrite($this->FH, $strLog);
		
	}
	
	function Close(){
		fclose($this->FH);
	}
		
	
	function TimeAndMilliseconds(){
	    $m = explode(' ',microtime());
	    return array($m[1], (int)round($m[0]*1000,3));
	} 
	
}

See the display_errors Off at the top?  We need to ensure nothing spurious gets written out as it’ll mess up the SOAP response and cause bigger errors on the client.  I might examine the SOAP error response Magento uses and wrap exceptions in that, but ultimately a failure is a failure…

The proxy script – proxy.php

While it’s a bit big to post in full here, it’s available as part of the download

Still, to give some explanation, the first 4 variables in the class are configurable.  The last (api_url) is not required as we can derive the (actual Magento) URL from environmental variables providing this is a standard installation:

var $Debug = 2; // 0=no logging, 1=basic logging, 2=basic + raw data
var $LogPath;
var $ApiVersion = 1;
var $ApiUrl;

On initialisation, the proxy will create two log files (if not already created).  Depending on debug level above it’ll create proxylog_YYYYMMDD.log and proxylog_raw_YYYYMMDD.log.  It’ll then set about constructing the API URL we want to hit, it’s own URL, and an md5 request ID.

Next it checks for raw POST data from the client.  Note a SOAP request won’t turn up using $_POST as it’s not assigned to a variable in that array.  We use:

$this->PostData = file_get_contents('php://input');

Initialisation done, we run the request.

If there’s no POST data, but there is a ?wsdl in the URL we simply need to deliver the WSDL so that PHP can create a SoapClient object.  We do this with a simple file_get_contents, replace the actual API url with our own proxy URL and return to the client:

function GetWsdl()
{
    $strOut = file_get_contents($this->ApiUrl."?wsdl");
    $strOut = str_replace($this->ApiUrl, $this->ProxyUrl, $strOut);

    return $strOut;
}

If we do have some POST data, we assume this is a SOAP request and process it.  If we can parse out a node of sessionId from the XML we store it for logging.  If it’s not there we assume it’s a new session request and log that.  We’ll then extract the sessionID from the response once we’ve received it back.

If we have a sessionID within the call then this is a main API request to do something more serious. Depending on the API version we extract the call handle from the XML and log that the request has arrived in.  We log this to both logs and add the raw post to the raw log. These are each tied together by the request ID.

Next we start a millisecond timer, send the raw POST data on to the actual API, and get the response back:

$this->Log("REQUEST IN - ".$this->CallName, 1);
$this->Log("REQUEST IN - ".$this->CallName, 2);
$this->Log($this->PostData, 2);

// time the request
$stTime = $this->GetMilliseconds();
// Send the request
$this->ResponseData = $this->SendPost();

$duration = $this->GetMilliseconds()-$stTime;

The method to send the POST request to the API uses CURL:

function SendPost()
{
	$headers = array(             
		"Content-type: application/xml;charset=\"utf-8\"", 
		"Accept: text/xml", 
		"Cache-Control: no-cache", 
		"Pragma: no-cache", 
		"SOAPAction: \"run\"", 
		"Content-length: ".strlen($this->PostData),
	); 

	$ch = curl_init();
	curl_setopt($ch, CURLOPT_URL, $this->ApiUrl);
	curl_setopt($ch, CURLOPT_POST, 1);
	curl_setopt($ch, CURLOPT_POSTFIELDS, $this->PostData);
	curl_setopt($ch, CURLOPT_RETURNTRANSFER , 1);
	curl_setopt($ch, CURLOPT_HTTPHEADER,  $headers);

	
	$result = curl_exec($ch);
	$err = curl_error($ch);  
	
	return $result;
			
}

We don’t need to worry too much about what comes back, other than to log it, including the duration of the response, and send it back to the client.  This is just a case of setting headers and echoing the result out:

header("Content Type: text/xml; Charset=\"UTF-8\"");
echo $this->ResponseData;
die();

So that’s about it.  All going well we get a blank page when we run our request on the test page, and a nice log like this, with a companion log containing the raw soapy xml goodness:

31-10-2011 20:40:54 965 ***Starting SoapClient
31-10-2011 20:40:54 967 -------------------------------- 15ef1f6df83caefca246fa567d40db41 REQUEST IN (WSDL)
31-10-2011 20:40:55 312 ***New client established:
31-10-2011 20:40:55 314 -------------------------------- 916d6778021593e17c2068aa06b37927 REQUEST MADE: Login or other method
31-10-2011 20:40:56 61 9a4232a68c0fe75e8b9ec818e88f3d77 916d6778021593e17c2068aa06b37927 RESPONSE RECEIVED - Time: 0.74644708633423
31-10-2011 20:40:56 62 9a4232a68c0fe75e8b9ec818e88f3d77 d8ee29078f8027ef52add2a09324fa39 REQUEST MADE: customer.info
31-10-2011 20:40:57 16 9a4232a68c0fe75e8b9ec818e88f3d77 d8ee29078f8027ef52add2a09324fa39 RESPONSE RECEIVED - Time: 0.9537661075592
31-10-2011 20:40:57 18 9a4232a68c0fe75e8b9ec818e88f3d77 d63448aeb18dfa43fbe269a9d5083942 REQUEST MADE: customer.info
31-10-2011 20:40:58 344 9a4232a68c0fe75e8b9ec818e88f3d77 d63448aeb18dfa43fbe269a9d5083942 RESPONSE RECEIVED - Time: 1.3248529434204

My good friend Steve prompted me to write this over a pint one night when discussing these problems.  He also (rather profoundly) stated “Log files give you power” and he’s dead right.  So far this script has given us the ability to prove what’s actually going on inside the hidden world of web service requests, and I can see us applying it far beyond the Magento API.

Feedback / suggestions / bug reports as always appreciated!

Download the files here
Please test in a dev environment and examine the code before you do. I’m not responsible for anything that may go wrong from their use.

6 Comments

  • Yang says:

    This is awesome. I can now get the actual error message when something goes wrong. Magento is a weird box to crack.

    • Bob says:

      Magento is such a pig. Why doesn’t it show the error message? WTF? What the f*** is the point in having an error message when there’s no way to get it without a hack? I f***ing hate Magento, it’s API is the dog worst thing in the universe. I’d rather work with Hitler than Magento.
      I spent all yesterday getting an auto-update with the magento API working, guess what! Magento’s API doesn’t maintain referential integrity! Deleting a parent category while it has children throws “Internal Error” and then corrupts the database so the backend wont run! What a heap of junk

  • Thomas Schonenberger says:

    Hi Colin – Many thanks for this post! It’s exactly what I need to try get to the bottom of why an OpenERP integration is not importing products.

    Just wondering if you can help though – The test is working fine but it fails on a version mismatch when I try call it from OpenERP. Any chance you could shed some light on this?

    Would be most appreciative
    Tom

    27-11-2013 02:35:35 452 913ba3049a521b057dd9785875c352eb RESPONSE RECEIVED:
    env:VersionMismatchWrong Version

    27-11-2013 02:49:30 988 ——————————– 4b85a1cb6c62029f444a4ff9150d59e1 REQUEST IN – Login or other method
    27-11-2013 02:49:30 988 ——————————– 4b85a1cb6c62029f444a4ff9150d59e1
    OpenERP??????

    27-11-2013 02:49:33 557 4c47d6459a66d4dbfaff534ac224d5bd 4b85a1cb6c62029f444a4ff9150d59e1 RESPONSE RECEIVED:
    4c47d6459a66d4dbfaff534ac224d5bd

    27-11-2013 02:49:33 560 4c47d6459a66d4dbfaff534ac224d5bd d0b77819745967be2305c6c31dd9e0d5 REQUEST IN – customerCustomerInfo
    27-11-2013 02:49:33 560 4c47d6459a66d4dbfaff534ac224d5bd d0b77819745967be2305c6c31dd9e0d5
    4c47d6459a66d4dbfaff534ac224d5bd1

    27-11-2013 02:49:36 270 4c47d6459a66d4dbfaff534ac224d5bd d0b77819745967be2305c6c31dd9e0d5 RESPONSE RECEIVED:
    12009-05-24 00:11:352013-09-11 14:33:4000000000111Default Store Viewzekeslp@gmail.comZekeMurphy2Mr1973-06-26 00:00:0075bc7c7de2aa224708f5c3e2291518fa:jQ

    27-11-2013 02:49:36 274 4c47d6459a66d4dbfaff534ac224d5bd c26f4e24a9a16b786efea214abf3a0b5 REQUEST IN – catalogCategoryAttributeList
    27-11-2013 02:49:36 274 4c47d6459a66d4dbfaff534ac224d5bd c26f4e24a9a16b786efea214abf3a0b5
    4c47d6459a66d4dbfaff534ac224d5bd
    //- CONTENT REMOVED -//

    27-11-2013 03:11:16 868 95f005284f797d0722f267513c7f9167 RESPONSE RECEIVED:
    env:VersionMismatchWrong Version

    • techcolin says:

      Yep – not sure why this would be different calling it from your ERP system to the test script, but that error is related to the version of SoapClient differing from the version the Soap Server (in this case, the proxy script itself).

      The line:
      $soap = new SoapClient( $mage_proxy_url, array(‘trace’ => 1, ‘cache_wsdl’=>0) );

      Can take another parameter to specify the soap_version, 1.1 or 1.2 (it should default to 1.1, which is what the proxy should output) as follows:
      $soap = new SoapClient( $mage_proxy_url, array(‘trace’ => 1, ‘cache_wsdl’=>0, ‘soap_version’ => SOAP_1_2) );

      It looks like version 1.2 uses application/soap+xml as the content type where 1.1 uses text/xml. I’m using “application/xml” which is probably the problem in the SendPost method.

      http://de1.php.net/manual/en/soapclient.soapclient.php
      http://www.w3.org/TR/soap12-part0/#L4697

      Let me know how you get on.

    • techcolin says:

      PS – just removed your log output as it had logins and passwords in it!

      • Thomas Schonenberger says:

        Hi Colin

        Thanks for the help so far. I’m back on this after a break in Dec. Unfortunately I’m not much of a programmer – I can see whats going on here to some degree, but just don’t quite know how to tackle it. :)

        The advice above refers to the proxytest file, which actually fires off OK – I get a “hello” response. http://staging.sustainable.co.za/proxytest.php
        When I try a request from OpenERP via the proxy.php though I get the error.

        It would be greatly appreciated if you could perhaps point me in a bit more specific direction? Feel free to email me on my registered email address… Thomas (at) mediavisioninteractive . com

        Thanks
        Tom