diff --git a/app/controllers/api/console.php b/app/controllers/api/console.php index 5abcd0fa23..d436ee7041 100644 --- a/app/controllers/api/console.php +++ b/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))); }); diff --git a/app/controllers/api/databases.php b/app/controllers/api/databases.php index 7542b24d35..586d59168b 100644 --- a/app/controllers/api/databases.php +++ b/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') diff --git a/app/controllers/api/graphql.php b/app/controllers/api/graphql.php index 830aecbe0c..712b479fd0 100644 --- a/app/controllers/api/graphql.php +++ b/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))); }); diff --git a/app/controllers/api/projects.php b/app/controllers/api/projects.php index 9e08c3774a..e2f6867904 100644 --- a/app/controllers/api/projects.php +++ b/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') diff --git a/app/controllers/general.php b/app/controllers/general.php index 86ad0a8d8e..7735c28bed 100644 --- a/app/controllers/general.php +++ b/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() diff --git a/app/controllers/mock.php b/app/controllers/mock.php index fc168ead26..0c8d52e45e 100644 --- a/app/controllers/mock.php +++ b/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); }); diff --git a/app/controllers/shared/api.php b/app/controllers/shared/api.php index df6ec002cb..3b1382f8f7 100644 --- a/app/controllers/shared/api.php +++ b/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))); }); diff --git a/app/controllers/shared/api/auth.php b/app/controllers/shared/api/auth.php index c381d9662a..8385c3824f 100644 --- a/app/controllers/shared/api/auth.php +++ b/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))); }); diff --git a/app/controllers/web/console.php b/app/controllers/web/console.php index dcf9c80a51..a5f08d39a2 100644 --- a/app/controllers/web/console.php +++ b/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/*') diff --git a/app/init.php b/app/init.php index 9696b08f6c..f50d622ebf 100644 --- a/app/init.php +++ b/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')));