backend-app-api: add initialization logger

Signed-off-by: Patrik Oldsberg <poldsberg@gmail.com>

.changeset/pink-nails-warn.md

@@ -0,0 +1,5 @@
+---
+'@backstage/backend-app-api': patch
+---
+
+Added logging of all plugins being initialized, periodic status, and completion.

packages/backend-app-api/src/wiring/BackendInitializer.ts

@@ -31,6 +31,7 @@ import { ForwardedError, ConflictError } from '@backstage/errors';
 import { featureDiscoveryServiceRef } from '@backstage/backend-plugin-api/alpha';
 import { DependencyGraph } from '../lib/DependencyGraph';
 import { ServiceRegistry } from './ServiceRegistry';
+import { createInitializationLogger } from './createInitializationLogger';
 
 export interface BackendRegisterInit {
   consumes: Set<ServiceOrExtensionPoint>;
@@ -226,6 +227,11 @@ export class BackendInitializer {
 
     const allPluginIds = [...pluginInits.keys()];
 
+    const initLogger = createInitializationLogger(
+      allPluginIds,
+      await this.#serviceRegistry.get(coreServices.rootLogger, 'root'),
+    );
+
     // All plugins are initialized in parallel
     await Promise.all(
       allPluginIds.map(async pluginId => {
@@ -289,6 +295,8 @@ export class BackendInitializer {
           });
         }
 
+        initLogger.onPluginStarted(pluginId);
+
         // Once the plugin and all modules have been initialized, we can signal that the plugin has stared up successfully
         const lifecycleService = await this.#getPluginLifecycleImpl(pluginId);
         await lifecycleService.startup();
@@ -299,6 +307,8 @@ export class BackendInitializer {
     const lifecycleService = await this.#getRootLifecycleImpl();
     await lifecycleService.startup();
 
+    initLogger.onAllStarted();
+
     // Once the backend is started, any uncaught errors or unhandled rejections are caught
     // and logged, in order to avoid crashing the entire backend on local failures.
     if (process.env.NODE_ENV !== 'test') {

packages/backend-app-api/src/wiring/createInitializationLogger.ts

@@ -0,0 +1,79 @@
+/*
+ * Copyright 2024 The Backstage Authors
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+import { RootLoggerService } from '@backstage/backend-plugin-api';
+
+const LOGGER_INTERVAL_MAX = 60_000;
+
+function joinIds(ids: Iterable<string>): string {
+  return [...ids].map(id => `'${id}'`).join(', ');
+}
+
+export function createInitializationLogger(
+  pluginIds: string[],
+  rootLogger?: RootLoggerService,
+): {
+  onPluginStarted(pluginId: string): void;
+  onAllStarted(): void;
+} {
+  const logger = rootLogger?.child({ type: 'initialization' });
+  const starting = new Set(pluginIds);
+  const started = new Set<string>();
+
+  logger?.info(`Plugin initialization started: ${joinIds(pluginIds)}`);
+
+  const getInitStatus = () => {
+    let status = '';
+    if (started.size > 0) {
+      status = `, newly initialized: ${joinIds(started)}`;
+      started.clear();
+    }
+    if (starting.size > 0) {
+      status += `, still initializing: ${joinIds(starting)}`;
+    }
+    return status;
+  };
+
+  // Periodically log the initialization status with a fibonacci backoff
+  let interval = 1000;
+  let prevInterval = 0;
+  let timeout: NodeJS.Timeout | undefined;
+  const onTimeout = () => {
+    logger?.info(`Plugin initialization in progress${getInitStatus()}`);
+
+    const nextInterval = Math.min(interval + prevInterval, LOGGER_INTERVAL_MAX);
+    prevInterval = interval;
+    interval = nextInterval;
+
+    timeout = setTimeout(onTimeout, nextInterval);
+  };
+  timeout = setTimeout(onTimeout, interval);
+
+  return {
+    onPluginStarted(pluginId: string) {
+      starting.delete(pluginId);
+      started.add(pluginId);
+    },
+    onAllStarted() {
+      logger?.info(`Plugin initialization complete${getInitStatus()}`);
+
+      if (timeout) {
+        clearTimeout(timeout);
+        timeout = undefined;
+      }
+    },
+  };
+}