Merge pull request #94 from php-twinfield/add-logging-to-api-connectors

Add psr/log and have `BaseApiConnector` log info, debug and error logs
php-twinfield · Mar 16, 2018 · 2666430 · 2666430
2 parents 45eb149 + 18adc95
commit 2666430
Show file tree

Hide file tree

Showing 4 changed files with 242 additions and 2 deletions.
diff --git a/composer.json b/composer.json
@@ -33,6 +33,7 @@
     "ext-soap": "*",
     "moneyphp/money": "^3.0",
     "myclabs/php-enum": "^1.5",
+    "psr/log": "^1.0",
     "webmozart/assert": "^1.2"
   },
   "suggest": {

diff --git a/src/ApiConnectors/BaseApiConnector.php b/src/ApiConnectors/BaseApiConnector.php
@@ -4,12 +4,18 @@
 
 use PhpTwinfield\Enums\Services;
 use PhpTwinfield\Exception;
+use PhpTwinfield\Response\Response;
 use PhpTwinfield\Secure\AuthenticatedConnection;
 use PhpTwinfield\Services\FinderService;
 use PhpTwinfield\Services\ProcessXmlService;
+use PhpTwinfield\Util;
+use Psr\Log\LoggerAwareInterface;
+use Psr\Log\LoggerAwareTrait;
 
-abstract class BaseApiConnector
+abstract class BaseApiConnector implements LoggerAwareInterface
 {
+    use LoggerAwareTrait;
+
     /**
      * Make sure to only add error messages for failure cases that caused the server not to accept / receive the
      * request. Else the automatic retry will cause the request to be understood by the server twice.
@@ -60,10 +66,14 @@ protected function getProcessXmlService(): ProcessXmlService
      * @throws Exception
      */
     public function sendXmlDocument(\DOMDocument $document) {
+        $this->logSendingDocument($document);
+
         try {
             $response = $this->getProcessXmlService()->sendDocument($document);
             $this->numRetries = 0;
 
+            $this->logResponse($response);
+
             return $response;
         } catch (\SoapFault | \ErrorException $exception) {
             /*
@@ -82,14 +92,68 @@ public function sendXmlDocument(\DOMDocument $document) {
                 if ($this->numRetries > self::MAX_RETRIES) {
                     break;
                 }
+
+                $this->logRetry($exception);
                 return $this->sendXmlDocument($document);
             }
 
             $this->numRetries = 0;
+            $this->logFailedRequest($exception);
             throw new Exception($exception->getMessage(), 0, $exception);
         }
     }
 
+    private function logSendingDocument(\DOMDocument $document): void
+    {
+        if (!$this->logger) {
+            return;
+        }
+
+        $message = "Sending request to Twinfield.";
+        if ($this->numRetries > 0) {
+            $message .= ' (attempt ' . ($this->numRetries + 1) . ')';
+        }
+
+        $this->logger->debug(
+            $message,
+            [
+                'document_xml' => Util::getPrettyXml($document),
+            ]
+        );
+    }
+
+    private function logResponse(Response $response): void
+    {
+        if (!$this->logger) {
+            return;
+        }
+
+        $this->logger->debug(
+            "Received response from Twinfield.",
+            [
+                'document_xml' => Util::getPrettyXml($response->getResponseDocument()),
+            ]
+        );
+    }
+
+    private function logRetry(\Throwable $e): void
+    {
+        if (!$this->logger) {
+            return;
+        }
+
+        $this->logger->info("Retrying request. Reason for initial failure: {$e->getMessage()}");
+    }
+
+    private function logFailedRequest(\Throwable $e): void
+    {
+        if (!$this->logger) {
+            return;
+        }
+
+        $this->logger->error("Request to Twinfield failed: {$e->getMessage()}");
+    }
+
     /**
      * @throws Exception
      */

diff --git a/src/Util.php b/src/Util.php
@@ -100,4 +100,20 @@ class_uses(get_class($object))
 
         return in_array($trait, $traits);
     }
+
+    public static function getPrettyXml(\DOMDocument $document): string
+    {
+        $oldPreserveWhiteSpace = $document->preserveWhiteSpace;
+        $oldFormatOutput = $document->formatOutput;
+
+        $document->preserveWhiteSpace = false;
+        $document->formatOutput = true;
+
+        $xml_string = $document->saveXML();
+
+        $document->preserveWhiteSpace = $oldPreserveWhiteSpace;
+        $document->formatOutput = $oldFormatOutput;
+
+        return $xml_string ?: '';
+    }
 }
diff --git a/tests/UnitTests/ApiConnectors/BaseApiConnectorTest.php b/tests/UnitTests/ApiConnectors/BaseApiConnectorTest.php
@@ -9,9 +9,14 @@
 use PhpTwinfield\Secure\AuthenticatedConnection;
 use PhpTwinfield\Services\ProcessXmlService;
 use PHPUnit\Framework\TestCase;
+use Psr\Log\LoggerInterface;
+use Psr\Log\LoggerTrait;
+use Psr\Log\LogLevel;
 
-class BaseApiConnectorTest extends TestCase
+class BaseApiConnectorTest extends TestCase implements LoggerInterface
 {
+    use LoggerTrait;
+
     /**
      * @var AuthenticatedConnection|\PHPUnit_Framework_MockObject_MockObject
      */
@@ -27,6 +32,11 @@ class BaseApiConnectorTest extends TestCase
      */
     private $client;
 
+    /**
+     * @var mixed[][]
+     */
+    private $logs;
+
     protected function setUp()
     {
         parent::setUp();
@@ -73,6 +83,155 @@ private function getMaxNumRetries(): int
         return $reflectionConstant->getValue();
     }
 
+    public function testSendDocumentLogsRequestAndResponse()
+    {
+        $request_document = new \DOMDocument();
+        $request_document->loadXML('<dimension>value</dimension>');
+
+        $response = Response::fromString('<dimension result="1">value</dimension>');
+
+        $this->connection->expects($this->any())
+            ->method("getAuthenticatedClient")
+            ->with(Services::PROCESSXML())
+            ->willReturn($this->client);
+
+        $this->client->expects($this->any())
+            ->method("sendDocument")
+            ->willReturn($response);
+
+        $this->service->setLogger($this);
+        $this->service->sendXmlDocument($request_document);
+
+        self::assertCount(2, $this->logs);
+
+        [$level, $message, $context] = $this->logs[0];
+        self::assertSame(LogLevel::DEBUG, $level);
+        self::assertSame('Sending request to Twinfield.', $message);
+        self::assertSame($this->completeXml('<dimension>value</dimension>'), $context['document_xml']);
+
+        [$level, $message, $context] = $this->logs[1];
+        self::assertSame(LogLevel::DEBUG, $level);
+        self::assertSame('Received response from Twinfield.', $message);
+        self::assertSame($this->completeXml('<dimension result="1">value</dimension>'), $context['document_xml']);
+    }
+
+    private function completeXml(string $xml): string
+    {
+        return sprintf(
+            '<?xml version="1.0"?>%s%s%s',
+            \PHP_EOL,
+            $xml,
+            \PHP_EOL
+        );
+    }
+
+    /**
+     * Used to keep track of the logs created by the API connector
+     *
+     * @inheritdoc
+     */
+    public function log($level, $message, array $context = array())
+    {
+        $this->logs[] = [$level, $message, $context];
+    }
+
+    /**
+     * @dataProvider soapFaultProvider
+     * @dataProvider errorExceptionProvider
+     */
+    public function testSendDocumentLogsRetries(\Throwable $e)
+    {
+        $request_document = new \DOMDocument();
+        $request_document->loadXML('<dimension>value</dimension>');
+
+        $response = Response::fromString('<dimension result="1">value</dimension>');
+
+        $this->connection->expects($this->any())
+            ->method("getAuthenticatedClient")
+            ->with(Services::PROCESSXML())
+            ->willReturn($this->client);
+
+        $this->client->expects($this->any())
+            ->method("sendDocument")
+            ->will($this->onConsecutiveCalls(
+                $this->throwException($e),
+                $this->throwException($e),
+                $this->returnValue($response)
+            ));
+
+        $this->service->setLogger($this);
+        $this->service->sendXmlDocument($request_document);
+
+
+        self::assertCount(6, $this->logs);
+
+        [$level, $message, $context] = $this->logs[0];
+        self::assertSame(LogLevel::DEBUG, $level);
+        self::assertSame('Sending request to Twinfield.', $message);
+        self::assertSame($this->completeXml('<dimension>value</dimension>'), $context['document_xml']);
+
+        [$level, $message, $context] = $this->logs[1];
+        self::assertSame(LogLevel::INFO, $level);
+        self::assertSame("Retrying request. Reason for initial failure: {$e->getMessage()}", $message);
+        self::assertEmpty($context);
+
+        [$level, $message, $context] = $this->logs[2];
+        self::assertSame(LogLevel::DEBUG, $level);
+        self::assertSame('Sending request to Twinfield. (attempt 2)', $message);
+        self::assertSame($this->completeXml('<dimension>value</dimension>'), $context['document_xml']);
+
+        [$level, $message, $context] = $this->logs[3];
+        self::assertSame(LogLevel::INFO, $level);
+        self::assertSame("Retrying request. Reason for initial failure: {$e->getMessage()}", $message);
+        self::assertEmpty($context);
+        self::assertEmpty($context);
+
+        [$level, $message, $context] = $this->logs[4];
+        self::assertSame(LogLevel::DEBUG, $level);
+        self::assertSame('Sending request to Twinfield. (attempt 3)', $message);
+        self::assertSame($this->completeXml('<dimension>value</dimension>'), $context['document_xml']);
+
+        [$level, $message, $context] = $this->logs[5];
+        self::assertSame(LogLevel::DEBUG, $level);
+        self::assertSame('Received response from Twinfield.', $message);
+        self::assertSame($this->completeXml('<dimension result="1">value</dimension>'), $context['document_xml']);
+    }
+
+    public function testSendDocumentLogsFailures()
+    {
+        $request_document = new \DOMDocument();
+        $request_document->loadXML('<dimension>value</dimension>');
+
+        $this->connection->expects($this->any())
+            ->method("getAuthenticatedClient")
+            ->with(Services::PROCESSXML())
+            ->willReturn($this->client);
+
+        $this->client->expects($this->any())
+            ->method("sendDocument")
+            ->will($this->onConsecutiveCalls(
+                $this->throwException(new \SoapFault('Server', 'Internal server error'))
+            ));
+
+        $this->service->setLogger($this);
+        try {
+            $this->service->sendXmlDocument($request_document);
+        } catch (\PhpTwinfield\Exception $e) {
+        }
+
+        self::assertCount(2, $this->logs);
+
+        [$level, $message, $context] = $this->logs[0];
+        self::assertSame(LogLevel::DEBUG, $level);
+        self::assertSame('Sending request to Twinfield.', $message);
+        self::assertSame($this->completeXml('<dimension>value</dimension>'), $context['document_xml']);
+
+        [$level, $message, $context] = $this->logs[1];
+        self::assertSame(LogLevel::ERROR, $level);
+        self::assertSame("Request to Twinfield failed: Internal server error", $message);
+        self::assertEmpty($context);
+    }
+
     /**
      * @dataProvider soapFaultProvider
      * @dataProvider errorExceptionProvider