From 95d005470d8f64a5f825769ef00aab9f8d469f8a Mon Sep 17 00:00:00 2001 From: Matthew Baggett Date: Tue, 15 Dec 2020 12:08:04 +0100 Subject: [PATCH] Improving monolog in the wake of trying to get Rollbar to work. --- src/App.php | 55 +++++++++++++--------- src/Controllers/AbstractController.php | 2 +- src/Controllers/AbstractHTMLController.php | 16 +++++-- src/Router/Route.php | 7 --- src/Router/Router.php | 10 ++-- 5 files changed, 53 insertions(+), 37 deletions(-) diff --git a/src/App.php b/src/App.php index baee6eb..6748820 100644 --- a/src/App.php +++ b/src/App.php @@ -30,6 +30,7 @@ use Faker\Provider; use Middlewares\TrailingSlash; use Monolog\Formatter\LineFormatter; use Monolog\Handler\ErrorLogHandler; +use Monolog\Handler\StreamHandler; use Monolog\Logger; use Monolog\Processor\PsrLogMessageProcessor; use Psr\Container\ContainerInterface; @@ -63,6 +64,7 @@ class App private array $supportedLanguages = ['en_US']; private static bool $isInitialised = false; + protected ?CachePoolChain $cachePoolChain = null; public function __construct() { @@ -134,6 +136,7 @@ class App // $container->enableCompilation($this->getCachePath()); // $container->writeProxiesToFile(true, "{$this->getCachePath()}/injection-proxies"); //} + $container = $container->build(); $container->set(Slim\Views\Twig::class, function ( @@ -254,23 +257,27 @@ class App return $faker; }); - $container->set(CachePoolChain::class, function (Redis $redis) { - $caches = []; + $container->set(CachePoolChain::class, function (Logger $logger, Redis $redis) { + if (!$this->cachePoolChain) { + $caches = []; + + // If apc/apcu present, add it to the pool + if (function_exists('apcu_add')) { + $caches[] = new ApcuCachePool(true); + } elseif (function_exists('apc_add')) { + $caches[] = new ApcCachePool(true); + } + + // If Redis is configured, add it to the pool. + if ($redis->isAvailable()) { + $caches[] = new RedisCachePool($redis->getUnderlyingRedis()); + } + $caches[] = new ArrayCachePool(); + + $this->cachePoolChain = new CachePoolChain($caches); - // If apc/apcu present, add it to the pool - if (function_exists('apcu_add')) { - $caches[] = new ApcuCachePool(); - } elseif (function_exists('apc_add')) { - $caches[] = new ApcCachePool(); } - - // If Redis is configured, add it to the pool. - if ($redis->isAvailable()) { - $caches[] = new RedisCachePool($redis->getUnderlyingRedis()); - } - $caches[] = new ArrayCachePool(); - - return new CachePoolChain($caches); + return $this->cachePoolChain; }); $container->set('MonologFormatter', function (EnvironmentService $environmentService) { @@ -281,8 +288,11 @@ class App ); }); - $container->set(Logger::class, function (ConfigurationService $configurationService) { - $monolog = new Logger($configurationService->get(ConfigurationService::KEY_APP_NAME)); + $container->set(Logger::class, function (ConfigurationService $configurationService, EnvironmentService $environmentService) { + $appName = $configurationService->get(ConfigurationService::KEY_APP_NAME); + $logName = $environmentService->has("REQUEST_URI") ? sprintf("%s(%s)", $appName, $environmentService->get("REQUEST_URI")) : $appName; + $monolog = new Logger($logName); + $monolog->pushHandler(new StreamHandler(sprintf("/var/log/%s.log", strtolower($appName)))); $monolog->pushHandler(new ErrorLogHandler(), Logger::DEBUG); $monolog->pushProcessor(new PsrLogMessageProcessor()); @@ -339,6 +349,7 @@ class App $this->router = $container->get(Router::class); + #!\Kint::dump($this->environmentService->all());exit; return $container; } @@ -482,7 +493,11 @@ class App $this->interrogateControllers(); $this->debugBar['time']->stopMeasure('interrogateControllers'); - $this->logger->debug(sprintf('Bootstrap complete in %sms', number_format((microtime(true) - $_SERVER['REQUEST_TIME_FLOAT']) * 1000, 2))); + $timeToBootstrapMs = (microtime(true) - $_SERVER['REQUEST_TIME_FLOAT']) * 1000; + $bootstrapTooLongThresholdMs = 300; + if($timeToBootstrapMs >= $bootstrapTooLongThresholdMs) { + $this->logger->warning(sprintf('Bootstrap complete in %sms which is more than the threshold of %sms', number_format($timeToBootstrapMs, 2), $bootstrapTooLongThresholdMs)); + } $this->router->populateRoutes($this->getApp(), $request); @@ -527,8 +542,6 @@ class App $this->router->cache(); - $this->logger->debug(sprintf( - 'ROUTE_CACHE miss. Perhaps enable ROUTE_CACHE envvar.' - )); + $this->logger->info('ROUTE_CACHE miss.'); } } diff --git a/src/Controllers/AbstractController.php b/src/Controllers/AbstractController.php index d29c528..9493f93 100644 --- a/src/Controllers/AbstractController.php +++ b/src/Controllers/AbstractController.php @@ -23,7 +23,7 @@ abstract class AbstractController public function __construct(Logger $logger, CacheProvider $cacheProvider) { $this->logger = $logger; - $this->logger->debug(sprintf('Entered Controller in %sms', number_format((microtime(true) - $_SERVER['REQUEST_TIME_FLOAT']) * 1000, 2))); + #$this->logger->debug(sprintf('Entered Controller in %sms', number_format((microtime(true) - $_SERVER['REQUEST_TIME_FLOAT']) * 1000, 2))); $this->cacheProvider = $cacheProvider; } diff --git a/src/Controllers/AbstractHTMLController.php b/src/Controllers/AbstractHTMLController.php index aded2f2..c0f0db0 100644 --- a/src/Controllers/AbstractHTMLController.php +++ b/src/Controllers/AbstractHTMLController.php @@ -51,11 +51,17 @@ abstract class AbstractHTMLController extends AbstractController $parameters )->withHeader('Content-Type', 'text/html'); - $this->logger->debug(sprintf( - 'Took %sms to render %s', - number_format((microtime(true) - $renderStart) * 1000, 2), - $template - )); + $renderTimeLimitMs = 500; + $renderTimeMs = (microtime(true) - $renderStart) * 1000; + + if($renderTimeMs >= $renderTimeLimitMs) { + $this->logger->debug(sprintf( + 'Took %sms to render %s, which is over %sms limit', + number_format($renderTimeMs, 2), + $template, + $renderTimeLimitMs + )); + } $this->debugBar['time']->stopMeasure('render'); return $response; diff --git a/src/Router/Route.php b/src/Router/Route.php index 35a74a3..1a753d0 100644 --- a/src/Router/Route.php +++ b/src/Router/Route.php @@ -34,13 +34,6 @@ class Route ]; protected array $validDomains = []; - private Logger $logger; - - public function __construct(Logger $logger) - { - $this->logger = $logger; - } - public function getCallbackProperties(): array { return $this->callbackProperties; diff --git a/src/Router/Router.php b/src/Router/Router.php index 94d24b2..12522ac 100644 --- a/src/Router/Router.php +++ b/src/Router/Router.php @@ -71,7 +71,7 @@ class Router } foreach ($routeAnnotation->methods as $httpMethod) { - $newRoute = new Route($this->logger); + $newRoute = new Route(); $newRoute ->setHttpMethod($httpMethod) @@ -141,7 +141,10 @@ class Router } $this->routes = $cacheItem->get(); - $this->logger->debug(sprintf('Loaded routes from Cache in %sms', number_format((microtime(true) - $time) * 1000, 2))); + $timeToLoadFromCacheMs = (microtime(true) - $time) * 1000; + if($timeToLoadFromCacheMs >= 500) { + $this->logger->warning(sprintf('Loaded routes from Cache in %sms, which is slower than 500ms', number_format($timeToLoadFromCacheMs, 2))); + } return true; } @@ -156,8 +159,9 @@ class Router try { $this->cachePoolChain->save($routeItem); + $this->logger->info("Cached router to cache pool"); } catch (CachePoolException $cachePoolException) { - $this->logger->critical($cachePoolException->getMessage()); + $this->logger->critical("Cache Pool Exception: " . $cachePoolException->getMessage()); } return $this;