Merge pull request #95 from pajavyskocil/responseTime

Fix logging request params

Author: vyskocilpavel

CHANGELOG.md

@@ -2,6 +2,11 @@
 All notable changes to this project will be documented in this file.
 
 ## [Unreleased]
+#### Added
+- Added logging response time for each request into RPC/LDAP
+
+#### Fixed
+- Fix logging request params
 
 ## [v3.7.3]
 #### Fixed

lib/LdapConnector.php

@@ -116,7 +116,11 @@ protected function search($base, $filter, $attributes = null)
         Logger::debug('sspmod_perun_LdapConnector.search - Connection to Perun LDAP established. ' .
             'Ready to perform search query. host: ' . $this->hostname . ', user: ' . $this->user);
 
+        $startTime = microtime(true);
         $result = ldap_search($conn, $base, $filter, $attributes);
+        $endTime = microtime(true);
+
+        $responseTime = round(($endTime - $startTime) * 1000, 3);
 
         // no such entity
         if (ldap_errno($conn) === 2) {
@@ -127,8 +131,8 @@ protected function search($base, $filter, $attributes = null)
 
         ldap_close($conn);
 
-        Logger::debug('sspmod_perun_LdapConnector.search - search query proceeded. ' .
-            'query base: ' . $base . ', filter: ' . $filter . ', response: ' . var_export($entries, true));
+        Logger::debug('sspmod_perun_LdapConnector.search - search query proceeded in ' . $responseTime . 'ms. ' .
+            'Query base: ' . $base . ', filter: ' . $filter . ', response: ' . var_export($entries, true));
 
         return $entries;
     }

lib/RpcConnector.php

@@ -66,16 +66,21 @@ public function get($manager, $method, $params = [])
         curl_setopt($ch, CURLOPT_CONNECTTIMEOUT, self::CONNECT_TIMEOUT);
         curl_setopt($ch, CURLOPT_TIMEOUT, self::TIMEOUT);
 
+        $startTime = microtime(true);
         $json = curl_exec($ch);
+        $endTime = microtime(true);
         curl_close($ch);
 
-        Logger::debug('perun.RPC: GET call $uri with params: ' . $paramsQuery . ', response: ' . $json);
+        $responseTime = round($endTime - $startTime, 3);
+        Logger::debug('perun.RPC: GET call ' . $uri . ' with params: ' . $paramsQuery . ', response : ' .
+            $json . ' in: ' . $responseTime . 's.');
 
         $result = json_decode($json, true);
 
         if (json_last_error() !== JSON_ERROR_NONE) {
             throw new Exception(
-                'Cant\'t decode response from Perun. Call: $uri, Params: $paramsQuery, Response: $json'
+                'Cant\'t decode response from Perun. Call: ' . $uri . ', Params: ' . $paramsQuery .
+                ', Response: ' . $json
             );
         }
         if (isset($result['errorId'])) {
@@ -107,17 +112,22 @@ public function post($manager, $method, $params = [])
         curl_setopt($ch, CURLOPT_CONNECTTIMEOUT, self::CONNECT_TIMEOUT);
         curl_setopt($ch, CURLOPT_TIMEOUT, self::TIMEOUT);
 
+        $startTime = microtime(true);
         $json = curl_exec($ch);
+        $endTime = microtime(true);
         curl_close($ch);
 
-        Logger::debug('perun.RPC: POST call $uri with params: ' . $paramsJson . ', response: ' . $json);
+        $responseTime = round($endTime - $startTime, 3);
+        Logger::debug('perun.RPC: POST call ' . $uri . ' with params: ' . $paramsJson . ', response : ' .
+            $json . ' in: ' . $responseTime . 's.');
 
         $result = json_decode($json, true);
 
 
         if (json_last_error() !== JSON_ERROR_NONE) {
             throw new Exception(
-                'Cant\'t decode response from Perun. Call: $uri, Params: $paramsJson, Response: $json'
+                'Cant\'t decode response from Perun. Call: ' . $uri . ', Params: ' . $paramsJson .
+                ', Response: ' . $json
             );
         }
         if (isset($result['errorId'])) {