Add extra logs

app/controllers/api/console.php

@@ -5,14 +5,19 @@ use Appwrite\Utopia\Response;
 use Utopia\App;
 use Utopia\Database\Document;
 use Utopia\Validator\Text;
+use Utopia\Logger\Log;
 
 App::init()
     ->groups(['console'])
     ->inject('project')
-    ->action(function (Document $project) {
+    ->inject('startTime')
+    ->inject('log')
+    ->action(function (Document $project, float $startTime, Log $log) {
+        $log->addExtra('consoleInitStart', \strval(\microtime(true)));
         if ($project->getId() !== 'console') {
             throw new Exception(Exception::GENERAL_ACCESS_FORBIDDEN);
         }
+        $log->addExtra('consoleInitEnd', \strval(\microtime(true)));
     });
 
 

app/controllers/api/databases.php

@@ -55,6 +55,7 @@ use Utopia\Validator\Range;
 use Utopia\Validator\Text;
 use Utopia\Validator\URL;
 use Utopia\Validator\WhiteList;
+use Utopia\Logger\Log;
 
 /**
  * * Create attribute of varying type
@@ -387,12 +388,16 @@ App::init()
     ->groups(['api', 'database'])
     ->inject('request')
     ->inject('dbForProject')
-    ->action(function (Request $request, Database $dbForProject) {
+    ->inject('startTime')
+    ->inject('log')
+    ->action(function (Request $request, Database $dbForProject, float $startTime, Log $log) {
+        $log->addExtra('databaseInitStart', \strval(\microtime(true)));
         $timeout = \intval($request->getHeader('x-appwrite-timeout'));
 
         if (!empty($timeout) && App::isDevelopment()) {
             $dbForProject->setTimeout($timeout);
         }
+        $log->addExtra('databaseInitEnd', \strval(\microtime(true)));
     });
 
 App::post('/v1/databases')

app/controllers/api/graphql.php

@@ -16,6 +16,7 @@ use Utopia\App;
 use Utopia\Database\Document;
 use Utopia\Validator\JSON;
 use Utopia\Validator\Text;
+use Utopia\Logger\Log;
 
 App::get('/v1/graphql')
     ->desc('GraphQL endpoint')
@@ -292,6 +293,10 @@ function processResult($result, $debugFlags): array
 App::shutdown()
     ->groups(['schema'])
     ->inject('project')
-    ->action(function (Document $project) {
+    ->inject('startTime')
+    ->inject('log')
+    ->action(function (Document $project, float $startTime, Log $log) {
+        $log->addExtra('GraphQLShutdownStart', \strval(\microtime(true)));
         Schema::setDirty($project->getId());
+        $log->addExtra('GraphQLShutdownEnd', \strval(\microtime(true)));
     });

app/controllers/api/projects.php

@@ -38,14 +38,19 @@ use Utopia\Validator\Range;
 use Utopia\Validator\Text;
 use Utopia\Validator\URL;
 use Utopia\Validator\WhiteList;
+use Utopia\Logger\Log;
 
 App::init()
     ->groups(['projects'])
     ->inject('project')
-    ->action(function (Document $project) {
+    ->inject('startTime')
+    ->inject('log')
+    ->action(function (Document $project, float $startTime, Log $log) {
+        $log->addExtra('projectInitStart', \strval(\microtime(true)));
         if ($project->getId() !== 'console') {
             throw new Exception(Exception::GENERAL_ACCESS_FORBIDDEN);
         }
+        $log->addExtra('projectInitEnd', \strval(\microtime(true)));
     });
 
 App::post('/v1/projects')

app/controllers/general.php

@@ -386,11 +386,13 @@ App::init()
     ->inject('queueForEvents')
     ->inject('queueForUsage')
     ->inject('geodb')
-    ->action(function (App $utopia, SwooleRequest $swooleRequest, Request $request, Response $response, Document $console, Document $project, Database $dbForConsole, callable $getProjectDB, Document $user, Locale $locale, array $localeCodes, array $clients, array $servers, Certificate $queueForCertificates, Event $queueForEvents, Usage $queueForUsage, Reader $geodb) {
+    ->inject('startTime')
+    ->inject('log')
+    ->action(function (App $utopia, SwooleRequest $swooleRequest, Request $request, Response $response, Document $console, Document $project, Database $dbForConsole, callable $getProjectDB, Document $user, Locale $locale, array $localeCodes, array $clients, array $servers, Certificate $queueForCertificates, Event $queueForEvents, Usage $queueForUsage, Reader $geodb, float $startTime, Log $log) {
         /*
         * Appwrite Router
         */
-
+        $log->addExtra('generalInitStart', \strval(\microtime(true)));
         $host = $request->getHostname() ?? '';
         $mainDomain = App::getEnv('_APP_DOMAIN', '');
         // Only run Router when external domain
@@ -738,6 +740,8 @@ App::init()
         if ($user->getAttribute('reset')) {
             throw new AppwriteException(AppwriteException::USER_PASSWORD_RESET_REQUIRED);
         }
+
+        $log->addExtra('generalInitEnd', \strval(\microtime(true)));
     });
 
 App::options()

app/controllers/mock.php

@@ -16,6 +16,7 @@ use Utopia\Database\Validator\UID;
 use Utopia\VCS\Adapter\Git\GitHub;
 use Utopia\Database\Helpers\Permission;
 use Utopia\Database\Helpers\Role;
+use Utopia\Logger\Log;
 
 App::get('/v1/mock/tests/general/oauth2')
     ->desc('OAuth Login')
@@ -218,8 +219,11 @@ App::shutdown()
     ->inject('utopia')
     ->inject('response')
     ->inject('request')
-    ->action(function (App $utopia, Response $response, Request $request) {
+    ->inject('startTime')
+    ->inject('log')
+    ->action(function (App $utopia, Response $response, Request $request, float $startTime, Log $log) {
 
+        $log->addExtra('MockShutdownStart', \strval(\microtime(true)));
         $result = [];
         $route  = $utopia->getRoute();
         $path   = APP_STORAGE_CACHE . '/tests.json';
@@ -237,5 +241,7 @@ App::shutdown()
             throw new Exception(Exception::GENERAL_MOCK, 'Failed to save results', 500);
         }
 
+        $log->addExtra('MockShutdownEnd', \strval(\microtime(true)));
+
         $response->dynamic(new Document(['result' => $route->getMethod() . ':' . $route->getPath() . ':passed']), Response::MODEL_MOCK);
     });

app/controllers/shared/api.php

@@ -21,6 +21,7 @@ use Utopia\Database\Database;
 use Utopia\Database\DateTime;
 use Utopia\Database\Document;
 use Utopia\Database\Validator\Authorization;
+use Utopia\Logger\Log;
 
 $parseLabel = function (string $label, array $responsePayload, array $requestParams, Document $user) {
     preg_match_all('/{(.*?)}/', $label, $matches);
@@ -156,8 +157,11 @@ App::init()
     ->inject('mode')
     ->inject('queueForMails')
     ->inject('queueForUsage')
-    ->action(function (App $utopia, Request $request, Response $response, Document $project, Document $user, Event $queueForEvents, Audit $queueForAudits, Delete $queueForDeletes, EventDatabase $queueForDatabase, Database $dbForProject, string $mode, Mail $queueForMails, Usage $queueForUsage) use ($databaseListener) {
+    ->inject('startTime')
+    ->inject('log')
+    ->action(function (App $utopia, Request $request, Response $response, Document $project, Document $user, Event $queueForEvents, Audit $queueForAudits, Delete $queueForDeletes, EventDatabase $queueForDatabase, Database $dbForProject, string $mode, Mail $queueForMails, Usage $queueForUsage, float $startTime, Log $log) use ($databaseListener) {
 
+        $log->addExtra('apiInitStart', \strval(\microtime(true)));
         $route = $utopia->getRoute();
 
         if ($project->isEmpty() && $route->getLabel('abuse-limit', 0) > 0) { // Abuse limit requires an active project scope
@@ -309,6 +313,7 @@ App::init()
                 $response->addHeader('X-Appwrite-Cache', 'miss');
             }
         }
+        $log->addExtra('apiInitEnd', \strval(\microtime(true)));
     });
 
 App::init()
@@ -316,8 +321,10 @@ App::init()
     ->inject('utopia')
     ->inject('request')
     ->inject('project')
-    ->action(function (App $utopia, Request $request, Document $project) {
-
+    ->inject('startTime')
+    ->inject('log')
+    ->action(function (App $utopia, Request $request, Document $project, float $startTime, Log $log) {
+        $log->addExtra('APIInitStart2', \strval(\microtime(true)));
         $route = $utopia->getRoute();
 
         $isPrivilegedUser = Auth::isPrivilegedUser(Authorization::getRoles());
@@ -369,6 +376,7 @@ App::init()
                 throw new Exception(Exception::USER_AUTH_METHOD_UNSUPPORTED, 'Unsupported authentication type: ' . $route->getLabel('auth.type', ''));
                 break;
         }
+        $log->addExtra('APIInitEnd2', \strval(\microtime(true)));
     });
 
 /**
@@ -384,7 +392,10 @@ App::shutdown()
     ->inject('response')
     ->inject('project')
     ->inject('dbForProject')
-    ->action(function (App $utopia, Request $request, Response $response, Document $project, Database $dbForProject) {
+    ->inject('startTime')
+    ->inject('log')
+    ->action(function (App $utopia, Request $request, Response $response, Document $project, Database $dbForProject, float $startTime, Log $log) {
+        $log->addExtra('APIShutdownStart1', \strval(\microtime(true)));
         $sessionLimit = $project->getAttribute('auths', [])['maxSessions'] ?? APP_LIMIT_USER_SESSIONS_DEFAULT;
         $session = $response->getPayload();
         $userId = $session['userId'] ?? '';
@@ -408,6 +419,8 @@ App::shutdown()
             $dbForProject->deleteDocument('sessions', $session->getId());
         }
         $dbForProject->deleteCachedDocument('users', $userId);
+
+        $log->addExtra('APIShutdownStart2', \strval(\microtime(true)));
     });
 
 App::shutdown()
@@ -426,8 +439,11 @@ App::shutdown()
     ->inject('queueForFunctions')
     ->inject('mode')
     ->inject('dbForConsole')
-    ->action(function (App $utopia, Request $request, Response $response, Document $project, Document $user, Event $queueForEvents, Audit $queueForAudits, Usage $queueForUsage, Delete $queueForDeletes, EventDatabase $queueForDatabase, Database $dbForProject, Func $queueForFunctions, string $mode, Database $dbForConsole) use ($parseLabel) {
+    ->inject('startTime')
+    ->inject('log')
+    ->action(function (App $utopia, Request $request, Response $response, Document $project, Document $user, Event $queueForEvents, Audit $queueForAudits, Usage $queueForUsage, Delete $queueForDeletes, EventDatabase $queueForDatabase, Database $dbForProject, Func $queueForFunctions, string $mode, Database $dbForConsole, float $startTime, Log $log) use ($parseLabel) {
 
+        $log->addExtra('APIShutdownStart2', \strval(\microtime(true)));
         $responsePayload = $response->getPayload();
 
         if (!empty($queueForEvents->getEvent())) {
@@ -615,12 +631,17 @@ App::shutdown()
                 }
             }
         }
+        $log->addExtra('APIShutdownEnd2', \strval(\microtime(true)));
     });
 
 App::init()
     ->groups(['usage'])
-    ->action(function () {
+    ->inject('startTime')
+    ->inject('log')
+    ->action(function (float $startTime, Log $log) {
+        $log->addExtra('APIInitStart3', \strval(\microtime(true)));
         if (App::getEnv('_APP_USAGE_STATS', 'enabled') !== 'enabled') {
             throw new Exception(Exception::GENERAL_USAGE_DISABLED);
         }
+        $log->addExtra('APIInitEnd3', \strval(\microtime(true)));
     });

app/controllers/shared/api/auth.php

@@ -6,14 +6,17 @@ use Utopia\App;
 use Appwrite\Extend\Exception;
 use Utopia\Database\Document;
 use Utopia\Database\Validator\Authorization;
+use Utopia\Logger\Log;
 
 App::init()
     ->groups(['auth'])
     ->inject('utopia')
     ->inject('request')
     ->inject('project')
-    ->action(function (App $utopia, Request $request, Document $project) {
-
+    ->inject('startTime')
+    ->inject('log')
+    ->action(function (App $utopia, Request $request, Document $project, float $startTime, Log $log) {
+        $log->addExtra('AuthInitStart', \strval(\microtime(true)));
         $route = $utopia->match($request);
 
         $isPrivilegedUser = Auth::isPrivilegedUser(Authorization::getRoles());
@@ -65,4 +68,5 @@ App::init()
                 throw new Exception(Exception::USER_AUTH_METHOD_UNSUPPORTED, 'Unsupported authentication route');
                 break;
         }
+        $log->addExtra('AuthInitEnd', \strval(\microtime(true)));
     });

app/controllers/web/console.php

@@ -3,17 +3,22 @@
 use Appwrite\Utopia\Request;
 use Appwrite\Utopia\Response;
 use Utopia\App;
+use Utopia\Logger\Log;
 
 App::init()
     ->groups(['web'])
     ->inject('request')
     ->inject('response')
-    ->action(function (Request $request, Response $response) {
+    ->inject('startTime')
+    ->inject('log')
+    ->action(function (Request $request, Response $response, float $startTime, Log $log) {
+        $log->addExtra('ConsoleWebInitStart', \strval(\microtime(true)));
         $response
             ->addHeader('X-Frame-Options', 'SAMEORIGIN') // Avoid console and homepage from showing in iframes
             ->addHeader('X-XSS-Protection', '1; mode=block; report=/v1/xss?url=' . \urlencode($request->getURI()))
             ->addHeader('X-UA-Compatible', 'IE=Edge') // Deny IE browsers from going into quirks mode
         ;
+        $log->addExtra('ConsoleWebInitEnd', \strval(\microtime(true)));
     });
 
 App::get('/console/*')

app/http.php

@@ -2,6 +2,7 @@
 
 require_once __DIR__ . '/../vendor/autoload.php';
 
+use Appwrite\Extend\Exception;
 use Appwrite\Utopia\Response;
 use Swoole\Process;
 use Swoole\Http\Server;
@@ -26,6 +27,24 @@ use Utopia\Pools\Group;
 
 $http = new Server("0.0.0.0", App::getEnv('PORT', 80));
 
+App::setResource('startTime', function() {
+    return \microtime(true);
+});
+
+App::init()
+    ->inject('startTime')
+    ->inject('log')
+    ->inject('http')
+    ->action(function(float $startTime, Log $log, mixed $http) {
+        $stats = $http->stats();
+        $workersIdle = $stats['idle_worker_num'] ?? -1;
+        $workersTotal = $stats['worker_num'] ?? -1;
+
+        $log->addExtra('workersIdle', \strval($workersIdle));
+        $log->addExtra('workersTotal', \strval($workersTotal));
+        $log->addExtra('veryFirstInit', \strval(\microtime(true)));
+    });
+
 $payloadSize = 6 * (1024 * 1024); // 6MB
 $workerNumber = swoole_cpu_num() * intval(App::getEnv('_APP_WORKER_PER_CORE', 6));
 
@@ -222,9 +241,10 @@ $http->on('start', function (Server $http) use ($payloadSize, $register) {
     });
 });
 
-$http->on('request', function (SwooleRequest $swooleRequest, SwooleResponse $swooleResponse) use ($register) {
+$http->on('request', function (SwooleRequest $swooleRequest, SwooleResponse $swooleResponse) use ($register, $http) {
     App::setResource('swooleRequest', fn () => $swooleRequest);
     App::setResource('swooleResponse', fn () => $swooleResponse);
+    App::setResource('http', fn () => $http);
 
     $request = new Request($swooleRequest);
     $response = new Response($swooleResponse);
@@ -243,9 +263,23 @@ $http->on('request', function (SwooleRequest $swooleRequest, SwooleResponse $swo
 
     $app = new App('UTC');
 
+    $l = new Log();
+
+    $fd = $swooleRequest->fd;
+    $fd_info = $http->getClientInfo($fd);
+    $packetTimeStart = $fd_info['last_time'];
+    $l->addExtra('packetTimeStart', \strval($packetTimeStart));
+
+    App::setResource('log', fn() => $l);
+    App::setResource('swooleStartTime', fn() => \floatval($packetTimeStart));
+
+    $l->addExtra('GetPoolsStart', \strval(\microtime(true)));
+
     $pools = $register->get('pools');
     App::setResource('pools', fn () => $pools);
 
+    $l->addExtra('GetPoolsEnd', \strval(\microtime(true)));
+
     try {
         Authorization::cleanRoles();
         Authorization::setRole(Role::any()->toString());
@@ -327,4 +361,18 @@ $http->on('request', function (SwooleRequest $swooleRequest, SwooleResponse $swo
     }
 });
 
+App::shutdown()
+    ->inject('swooleStartTime')
+    ->inject('log')
+    ->action(function(float $swooleStartTime, Log $log) {
+        $endTime = \microtime(true);
+
+        $log->addExtra('veryLastShutdown', \strval(\microtime(true)));
+        $log->addExtra('durationSwoole', \strval($endTime - $swooleStartTime));
+
+        if($endTime - $swooleStartTime > 10) {
+            throw new Exception(Exception::GENERAL_SERVER_ERROR, 'Our amazing timeout.');
+        }
+    });
+
 $http->start();

app/init.php

@@ -866,7 +866,6 @@ foreach ($locales as $locale) {
 ]);
 
 // Runtime Execution
-App::setResource('log', fn() => new Log());
 App::setResource('logger', function ($register) {
     return $register->get('logger');
 }, ['register']);