diff --git a/.changeset/pink-nails-warn.md b/.changeset/pink-nails-warn.md new file mode 100644 index 0000000000..6bdbf465b0 --- /dev/null +++ b/.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. diff --git a/packages/backend-app-api/src/wiring/BackendInitializer.ts b/packages/backend-app-api/src/wiring/BackendInitializer.ts index fe949c2e33..1bf38a8c40 100644 --- a/packages/backend-app-api/src/wiring/BackendInitializer.ts +++ b/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; @@ -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') { diff --git a/packages/backend-app-api/src/wiring/createInitializationLogger.ts b/packages/backend-app-api/src/wiring/createInitializationLogger.ts new file mode 100644 index 0000000000..566b5507ec --- /dev/null +++ b/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 { + 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(); + + 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; + } + }, + }; +}