Add quick and dirty (and nasty) Chrome debug logger

ingenerator · Sep 15, 2022 · f950bda · f950bda
1 parent c8bf848
commit f950bda
Show file tree

Hide file tree

Showing 3 changed files with 118 additions and 6 deletions.
diff --git a/src/ChromeDriverDebugLogger.php b/src/ChromeDriverDebugLogger.php
@@ -0,0 +1,103 @@
+<?php
+
+namespace DMore\ChromeDriver;
+
+use Ingenerator\PHPUtils\DateTime\DateTimeDiff;
+use Ingenerator\PHPUtils\StringEncoding\JSON;
+use WebSocket\ConnectionException;
+
+class ChromeDriverDebugLogger
+{
+
+    public function __construct()
+    {
+
+    }
+
+    public function logCommandSent(DevToolsConnection $connection, array $payload): void
+    {
+        $this->writeLog(
+            [
+                'client'  => $this->nameConnection($connection),
+                'action'  => 'send',
+                'payload' => $payload,
+            ]
+        );
+    }
+
+    public function logChromeResponse(DevToolsConnection $connection, array $response, string $wait_reason): void
+    {
+        $this->writeLog(
+            [
+                'client'   => $this->nameConnection($connection),
+                'action'   => 'receive',
+                'waiting'  => $wait_reason,
+                'response' => $response,
+            ]
+        );
+    }
+
+    public function logNullResponse(DevToolsConnection $connection, string $wait_reason): void
+    {
+        $this->writeLog(
+            [
+                'client'  => $this->nameConnection($connection),
+                'action'  => 'receiveEmpty',
+                'waiting' => $wait_reason,
+            ]
+        );
+    }
+
+    public function logConnectionException(
+        DevToolsConnection  $connection,
+        ConnectionException $exception,
+        string              $wait_reason
+    ): void {
+        $this->writeLog(
+            [
+                'client'  => $this->nameConnection($connection),
+                'action'  => 'connectionException',
+                'waiting' => $wait_reason,
+                'message' => $exception->getMessage(),
+                'data'    => $exception->getData(),
+                'trace'   => $exception->getTraceAsString(),
+            ]
+        );
+    }
+
+    private function writeLog(array $vars)
+    {
+        static $last_logged;
+        if ($last_logged === NULL) {
+            $last_logged = new \DateTimeImmutable;
+        }
+        $now = new \DateTimeImmutable;
+
+        $vars        = array_merge(
+            [
+                '@'   => ($now)->format('H:i:s.u'),
+                '+ms' => round(DateTimeDiff::microsBetween($last_logged, $now) / 1000, 3),
+            ],
+            $vars
+        );
+
+        $last_logged = $now;
+
+        \file_put_contents(
+            PROJECT_BASE_DIR.'/build/logs/chromedriver-debug.log.jsonl',
+            JSON::encode($vars, FALSE)."\n",
+            FILE_APPEND
+        );
+    }
+
+    private function nameConnection(DevToolsConnection $connection)
+    {
+        if ($connection instanceof ChromePage) {
+            return 'page:'.\spl_object_id($connection);
+        } elseif ($connection instanceof ChromeBrowser) {
+            return 'browser:'.\spl_object_id($connection);
+        } else {
+            return \get_class($connection).':'.\spl_object_id($connection);
+        }
+    }
+}
diff --git a/src/ChromePage.php b/src/ChromePage.php
@@ -39,7 +39,7 @@ public function visit($url)
         if (count($this->pending_requests) > 0) {
             $this->waitFor(function () {
                 return count($this->pending_requests) == 0;
-            });
+            }, 'before-visit');
         }
         $this->response = null;
         $this->page_ready = false;
@@ -58,7 +58,7 @@ public function waitForLoad()
             try {
                 $this->waitFor(function () {
                     return $this->page_ready;
-                });
+                }, 'wait-for-load');
             } catch (StreamReadException $exception) {
                 if ($exception->isTimedOut() && false === $this->canDevToolsConnectionBeEstablished()) {
                     throw new \RuntimeException(
@@ -130,8 +130,8 @@ private function waitForHttpResponse()
             }
 
             $this->waitFor(function () {
-                return null !== $this->response && count($this->pending_requests) == 0;
-            });
+                return NULL !== $this->response && count($this->pending_requests) == 0;
+            }, 'wait-for-http-response');
         }
     }
 

diff --git a/src/DevToolsConnection.php b/src/DevToolsConnection.php
@@ -16,10 +16,13 @@ abstract class DevToolsConnection
     /** @var int|null */
     private $socket_timeout;
 
+    protected ChromeDriverDebugLogger $logger;
+
     public function __construct($url, $socket_timeout = null)
     {
         $this->url = $url;
         $this->socket_timeout = $socket_timeout;
+        $this->logger = new ChromeDriverDebugLogger;
     }
 
     public function canDevToolsConnectionBeEstablished()
@@ -68,11 +71,12 @@ public function send($command, array $parameters = [])
             $payload['params'] = $parameters;
         }
 
+        $this->logger->logCommandSent($this, $payload);
         $this->client->send(json_encode($payload));
 
         $data = $this->waitFor(function ($data) use ($payload) {
             return array_key_exists('id', $data) && $data['id'] == $payload['id'];
-        });
+        }, 'send-'.$payload['id']);
 
         if (isset($data['result'])) {
             return $data['result'];
@@ -81,13 +85,14 @@ public function send($command, array $parameters = [])
         return ['result' => ['type' => 'undefined']];
     }
 
-    protected function waitFor(callable $is_ready)
+    protected function waitFor(callable $is_ready, string $debug_reason)
     {
         $data = [];
         while (true) {
             try {
                 $response = $this->client->receive();
             } catch (ConnectionException $exception) {
+                $this->logger->logConnectionException($this, $exception, $debug_reason);
                 $message = $exception->getMessage();
                 if (false !== strpos($message, 'Empty read; connection dead?')) {
                     throw $exception;
@@ -97,11 +102,15 @@ protected function waitFor(callable $is_ready)
 
                 throw new StreamReadException($state['eof'], $state['timed_out'], $state['blocked']);
             }
+
+            $this->logger->logNullResponse($this, $debug_reason);
             if (is_null($response)) {
                 return null;
             }
             $data = json_decode($response, true);
 
+            $this->logger->logChromeResponse($this, $data, $debug_reason);
+
             if (array_key_exists('error', $data)) {
                 $message = isset($data['error']['data']) ? $data['error']['message'] . '. ' . $data['error']['data'] : $data['error']['message'];
                 throw new DriverException($message , $data['error']['code']);