Improve start/end lifecycle logging, fixes #195

cspray · Aug 11, 2022 · f09323d · f09323d
1 parent 913e1d9
commit f09323d
Show file tree

Hide file tree

Showing 7 changed files with 48 additions and 10 deletions.
diff --git a/src/AnnotatedTargetContainerDefinitionCompiler.php b/src/AnnotatedTargetContainerDefinitionCompiler.php
@@ -108,8 +108,9 @@ private function parse(
             ->filterAttributes(...$attributeTypes)
             ->build();
 
+        $logger->info('Annotated Container compiling started.');
         $logger->info(
-            sprintf('Annotated Container compiling started. Scanning directories: %s', implode(' ', $dirs)),
+            sprintf('Scanning directories for Attributes: %s.', implode(' ', $dirs)),
             ['sourcePaths' => $dirs]
         );
 

diff --git a/src/ContainerFactory/AbstractContainerFactory.php b/src/ContainerFactory/AbstractContainerFactory.php
@@ -83,7 +83,7 @@ public function isActive(string $profile) : bool {
     final protected function logCreatingContainer(ObjectType $backingImplementation, array $activeProfiles) : void {
         $this->logger->info(
             sprintf(
-                'Creating AnnotatedContainer with %s backing implementation and "%s" active profiles.',
+                'Started wiring AnnotatedContainer with %s backing implementation and "%s" active profiles.',
                 $backingImplementation->getName(),
                 implode(', ', $activeProfiles)
             ),
@@ -94,6 +94,16 @@ final protected function logCreatingContainer(ObjectType $backingImplementation,
         );
     }
 
+    final protected function logFinishedCreatingContainer(ObjectType $backingImplementation, array $activeProfiles) : void {
+        $this->logger->info(
+            'Finished wiring AnnotatedContainer.',
+            [
+                'backingImplementation' => $backingImplementation->getName(),
+                'activeProfiles' => $activeProfiles
+            ]
+        );
+    }
+
     final protected function logServiceShared(ServiceDefinition $service) : void {
         $this->logger->info(
             sprintf('Shared service %s.', $service->getType()->getName()),

diff --git a/src/ContainerFactory/AurynContainerFactory.php b/src/ContainerFactory/AurynContainerFactory.php
@@ -63,6 +63,7 @@ public function createContainer(ContainerDefinition $containerDefinition, Contai
                 new ProfilesAwareContainerDefinition($containerDefinition, $activeProfiles),
                 $nameTypeMap
             );
+            $this->logFinishedCreatingContainer(objectType(Injector::class), $activeProfiles);
             return $this->getAnnotatedContainer($injector, $nameTypeMap, $this->getActiveProfilesService($activeProfiles));
         } catch (InvalidDefinitionException $exception) {
             throw new ContainerException($exception->getMessage(), previous: $exception);

diff --git a/src/ContainerFactory/PhpDiContainerFactory.php b/src/ContainerFactory/PhpDiContainerFactory.php
@@ -49,7 +49,9 @@ public function createContainer(ContainerDefinition $containerDefinition, Contai
         try {
             $this->logCreatingContainer(objectType(Container::class), $activeProfiles);
             $this->logServicesNotMatchingProfiles($containerDefinition, $activeProfiles);
-            return $this->createDiContainer($containerDefinition, $activeProfiles);
+            $container =  $this->createDiContainer($containerDefinition, $activeProfiles);
+            $this->logFinishedCreatingContainer(objectType(Container::class), $activeProfiles);
+            return $container;
         } catch (InvalidDefinitionException $exception) {
             throw new ContainerException($exception->getMessage(), previous: $exception);
         }

diff --git a/test/AnnotatedTargetContainerDefinitionCompilerTest.php b/test/AnnotatedTargetContainerDefinitionCompilerTest.php
@@ -220,20 +220,26 @@ public function testLogImplicitServiceDelegateHasUnionReturnType() {
         }
     }
 
-    public function testLoggingScannedDirs() : void {
+    public function testLoggingCompileLifecycleStarted() : void {
         $this->runCompileDirectory([
             $path1 = Fixtures::singleConcreteService()->getPath(),
             $path2 = Fixtures::ambiguousAliasedServices()->getPath()
         ]);
 
-        $expected = [
-            'message' => sprintf('Annotated Container compiling started. Scanning directories: %s %s', $path1, $path2),
+        $expected1 = [
+            'message' => sprintf('Annotated Container compiling started.'),
+            'context' => []
+        ];
+        $expected2 = [
+            'message' => sprintf('Scanning directories for Attributes: %s %s.', $path1, $path2),
             'context' => [
                 'sourcePaths' => [$path1, $path2]
             ]
         ];
 
-        self::assertContains($expected, $this->logger->getLogsForLevel(LogLevel::INFO));
+        $logs = $this->logger->getLogsForLevel(LogLevel::INFO);
+        self::assertSame($expected1, $logs[0]);
+        self::assertSame($expected2, $logs[1]);
     }
 
     public function testLoggingServiceDefinition() : void {

diff --git a/test/BootstrapTest.php b/test/BootstrapTest.php
@@ -216,7 +216,7 @@ public function testBootstrapWithLogging() : void {
         self::assertStringContainsString('Annotated Container compiling started.', $logContents);
         self::assertStringContainsString(
             sprintf(
-                'Creating AnnotatedContainer with %s backing implementation and "default" active profiles.',
+                'Started wiring AnnotatedContainer with %s backing implementation and "default" active profiles.',
                 $container->getBackingContainer()::class,
             ),
             $logContents

diff --git a/test/ContainerFactoryTestCase.php b/test/ContainerFactoryTestCase.php
@@ -494,15 +494,33 @@ public function testLoggingCreatingContainerWithActiveProfiles() : void {
 
         $expected = [
             'message' => sprintf(
-                'Creating AnnotatedContainer with %s backing implementation and "default, foo, bar" active profiles.',
+                'Started wiring AnnotatedContainer with %s backing implementation and "default, foo, bar" active profiles.',
                 $container->getBackingContainer()::class
             ),
             'context' => [
                 'backingImplementation' => $container->getBackingContainer()::class,
                 'activeProfiles' => ['default', 'foo', 'bar']
             ]
         ];
-        self::assertContains($expected, $logger->getLogsForLevel(LogLevel::INFO));
+
+        $logs = $logger->getLogsForLevel(LogLevel::INFO);
+        self::assertSame($expected, $logs[0]);
+    }
+
+    public function testLoggingCreatingContainerFinished() : void {
+        $logger = new TestLogger();
+        $container = $this->getContainer(Fixtures::singleConcreteService()->getPath(), profiles: ['default', 'foo', 'bar'], logger: $logger);
+
+        $expected = [
+            'message' => 'Finished wiring AnnotatedContainer.',
+            'context' => [
+                'backingImplementation' => $container->getBackingContainer()::class,
+                'activeProfiles' => ['default', 'foo', 'bar']
+            ]
+        ];
+
+        $logs = $logger->getLogsForLevel(LogLevel::INFO);
+        self::assertSame($expected, $logs[count($logs) - 1]);
     }
 
     public function testLoggingServiceShared() : void {