Merge pull request #104 from ydb-platform/ilyakharev-patch

Update logs in retry and iam

Author: ilyakharev

CHANGELOG.md

@@ -1,3 +1,4 @@
+* changed level of update token log record from info to debug
 * created refresh token ratio parameter
 
 ## 1.9.0

src/Auth/IamAuth.php

@@ -13,7 +13,8 @@ abstract class IamAuth extends Auth
      */
     public function requestToken($request_data)
     {
-        $this->logger()->info('YDB: Obtaining new IAM token...');
+        $this->logger()->debug('YDB: Request new IAM token...');
+        $startTime = microtime(true);
 
         $curl = curl_init(Iam::IAM_TOKEN_API_URL);
 
@@ -33,6 +34,8 @@ public function requestToken($request_data)
 
         $status = curl_getinfo($curl, CURLINFO_HTTP_CODE);
 
+        $this->logger->debug("YDB: Received IAM response in ".((microtime(true)-$startTime)*1000)." miliseconds");
+
         if ($status === 200) {
             $token = json_decode($result);
 

src/Iam.php

@@ -97,7 +97,7 @@ public function token($force = false)
      */
     public function newToken()
     {
-        $this->logger()->info('YDB: Obtaining new IAM token...');
+        $this->logger()->debug('YDB: Obtaining new token...');
 
         $tokenInfo = $this->config('credentials')->getTokenInfo();
         $this->iam_token = $tokenInfo->getToken();
@@ -394,7 +394,7 @@ protected function loadTokenFromFile()
                 $this->iam_token = $token->iamToken;
                 $this->expires_at = $token->expiresAt;
                 $this->refresh_at = $token->refreshAt ?? time();
-                $this->logger()->info('YDB: Reused IAM token [...' . substr($this->iam_token, -6) . '].');
+                $this->logger()->debug('YDB: Reused token [...' . substr($this->iam_token, -6) . '].');
                 return $token->iamToken;
             }
         }

src/Retry/Retry.php

@@ -77,23 +77,35 @@ public function retry(Closure $closure, bool $idempotent)
         $startTime = microtime(true);
         $retryCount = 0;
         $lastException = null;
-        while (microtime(true) < $startTime + $this->timeoutMs / 1000) {
-            $this->logger->debug("YDB: Run user function. Retry count: $retryCount. s: ".(microtime(true) - $startTime));
+        if (is_null($this->timeoutMs)) {
+            $deadline = PHP_INT_MAX;
+        } else {
+            $deadline = $startTime + $this->timeoutMs / 1000;
+        }
+        $this->logger->debug("YDB: begin retry function. Deadline: $deadline");
+        do {
+            $this->logger->debug("YDB: Run user function. Retry count: $retryCount. s: " . (microtime(true) - $startTime));
             try {
                 return $closure();
-            } catch (Exception $e) {
-                $this->logger->warning("YDB: Received exception: ".$e->getMessage());
-                if (!$this->canRetry($e, $idempotent)){
-                    $lastException = $e;
-                    break;
+            } catch (\Exception $e) {
+                $this->logger->debug("YDB: Received exception: " . $e->getMessage());
+                $lastException = $e;
+                if (!$this->canRetry($e, $idempotent)) {
+                    $this->logger->error("YDB: Received non-retryable exception in retry. ms: "
+                        . ((microtime(true) - $startTime) * 1000) . "Retry count: $retryCount");
+                    throw $lastException;
+                }
+                $delay = $this->retryDelay($retryCount, $this->backoffType(get_class($e))) * 1000;
+                if (microtime(true) + $delay / 1000000 > $deadline) {
+                    $this->logger->error("YDB: Timeout retry function. ms: "
+                        . ((microtime(true) - $startTime) * 1000) . "Retry count: $retryCount");
+                    throw $lastException;
                 }
                 $retryCount++;
-                $lastException = $e;
-                $delay = $this->retryDelay($retryCount, $this->backoffType(get_class($e)))*1000;
+                $this->logger->debug("YDB: Sleep $delay microseconds before retry");
                 usleep($delay);
             }
-        }
-        throw $lastException;
+        } while (true);
     }
 
     /**
@@ -111,7 +123,7 @@ protected function alwaysRetry(string $exception)
         return in_array($exception, self::$alwaysRetry);
     }
 
-    protected function canRetry(Exception $e, bool $idempotent)
+    protected function canRetry(\Exception $e, bool $idempotent)
     {
         return is_a($e, RetryableException::class) && ($this->alwaysRetry(get_class($e)) || $idempotent);
     }