Add 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/init.php

@@ -875,6 +875,10 @@ App::setResource('hooks', function ($register) {
     return $register->get('hooks');
 }, ['register']);
 
+App::setResource('startTime', function() {
+    return \microtime(true);
+});
+
 App::setResource('register', fn() => $register);
 App::setResource('locale', fn() => new Locale(App::getEnv('_APP_LOCALE', 'en')));