🔊 back: use sub loggers for platform and message queue logging

This commit is contained in:
Eric Doughty-Papassideris
2024-12-05 17:37:20 +01:00
parent 4c05cf9dee
commit b59fc33cc9
8 changed files with 73 additions and 60 deletions
@@ -3,7 +3,7 @@ import { TdriveService } from "./service";
import { TdriveServiceProvider } from "./service-provider"; import { TdriveServiceProvider } from "./service-provider";
import { ServiceDefinition } from "./service-definition"; import { ServiceDefinition } from "./service-definition";
import { TdriveServiceState } from "./service-state"; import { TdriveServiceState } from "./service-state";
import { logger } from "../logger"; import { platformLogger } from "../logger";
export class TdriveComponent { export class TdriveComponent {
instance: TdriveService<TdriveServiceProvider>; instance: TdriveService<TdriveServiceProvider>;
@@ -38,7 +38,7 @@ export class TdriveComponent {
recursionDepth?: number, recursionDepth?: number,
): Promise<void> { ): Promise<void> {
if (recursionDepth > 10) { if (recursionDepth > 10) {
logger.error("Maximum recursion depth exceeded (will exit process)"); platformLogger.error("Maximum recursion depth exceeded (will exit process)");
process.exit(1); process.exit(1);
} }
@@ -50,10 +50,10 @@ export class TdriveComponent {
for (const component of this.components) { for (const component of this.components) {
await component.switchToState(state, (recursionDepth || 0) + 1); await component.switchToState(state, (recursionDepth || 0) + 1);
} }
logger.info(`Children of ${this.name} are all in ${state} state`); platformLogger.info(`Children of ${this.name} are all in ${state} state`);
logger.info(this.getStateTree()); platformLogger.info(this.getStateTree());
} else { } else {
logger.info(`${this.name} does not have children`); platformLogger.info(`${this.name} does not have children`);
} }
// eslint-disable-next-line @typescript-eslint/no-explicit-any // eslint-disable-next-line @typescript-eslint/no-explicit-any
@@ -6,7 +6,7 @@ import { TdriveServiceConfiguration } from "./service-configuration";
import { TdriveContext } from "./context"; import { TdriveContext } from "./context";
import { TdriveServiceOptions } from "./service-options"; import { TdriveServiceOptions } from "./service-options";
import { CONSUMES_METADATA, PREFIX_METADATA } from "./constants"; import { CONSUMES_METADATA, PREFIX_METADATA } from "./constants";
import { getLogger, logger } from "../logger"; import { getLogger, platformLogger } from "../logger";
import { TdriveLogger } from ".."; import { TdriveLogger } from "..";
const pendingServices: any = {}; const pendingServices: any = {};
@@ -39,23 +39,23 @@ export abstract class TdriveService<T extends TdriveServiceProvider>
async init(): Promise<this> { async init(): Promise<this> {
if (this.state.value !== TdriveServiceState.Ready) { if (this.state.value !== TdriveServiceState.Ready) {
logger.info("Service %s is already initialized", this.name); platformLogger.info("Service %s is already initialized", this.name);
return this; return this;
} }
try { try {
logger.info("Initializing service %s", this.name); platformLogger.info("Initializing service %s", this.name);
pendingServices[this.name] = true; pendingServices[this.name] = true;
this.state.next(TdriveServiceState.Initializing); this.state.next(TdriveServiceState.Initializing);
await this.doInit(); await this.doInit();
this.state.next(TdriveServiceState.Initialized); this.state.next(TdriveServiceState.Initialized);
logger.info("Service %s is initialized", this.name); platformLogger.info("Service %s is initialized", this.name);
delete pendingServices[this.name]; delete pendingServices[this.name];
logger.info("Pending services: %s", JSON.stringify(Object.keys(pendingServices))); platformLogger.info("Pending services: %s", JSON.stringify(Object.keys(pendingServices)));
return this; return this;
} catch (err) { } catch (err) {
logger.error("Error while initializing service %s", this.name); platformLogger.error("Error while initializing service %s", this.name);
logger.error(err); platformLogger.error(err);
this.state.error(new Error(`Error while initializing service ${this.name}`)); this.state.error(new Error(`Error while initializing service ${this.name}`));
throw err; throw err;
@@ -75,21 +75,21 @@ export abstract class TdriveService<T extends TdriveServiceProvider>
this.state.value === TdriveServiceState.Starting || this.state.value === TdriveServiceState.Starting ||
this.state.value === TdriveServiceState.Started this.state.value === TdriveServiceState.Started
) { ) {
logger.info("Service %s is already started", this.name); platformLogger.info("Service %s is already started", this.name);
return this; return this;
} }
try { try {
logger.info("Starting service %s", this.name); platformLogger.info("Starting service %s", this.name);
this.state.next(TdriveServiceState.Starting); this.state.next(TdriveServiceState.Starting);
await this.doStart(); await this.doStart();
this.state.next(TdriveServiceState.Started); this.state.next(TdriveServiceState.Started);
logger.info("Service %s is started", this.name); platformLogger.info("Service %s is started", this.name);
return this; return this;
} catch (err) { } catch (err) {
logger.error("Error while starting service %s", this.name, err); platformLogger.error("Error while starting service %s", this.name, err);
logger.error(err); platformLogger.error(err);
this.state.error(new Error(`Error while starting service ${this.name}`)); this.state.error(new Error(`Error while starting service ${this.name}`));
throw err; throw err;
@@ -101,26 +101,26 @@ export abstract class TdriveService<T extends TdriveServiceProvider>
this.state.value === TdriveServiceState.Stopping || this.state.value === TdriveServiceState.Stopping ||
this.state.value === TdriveServiceState.Stopped this.state.value === TdriveServiceState.Stopped
) { ) {
logger.info("Service %s is already stopped", this.name); platformLogger.info("Service %s is already stopped", this.name);
return this; return this;
} }
if (this.state.value !== TdriveServiceState.Started) { if (this.state.value !== TdriveServiceState.Started) {
logger.info("Service %s can not be stopped until started", this.name); platformLogger.info("Service %s can not be stopped until started", this.name);
return this; return this;
} }
try { try {
logger.info("Stopping service %s", this.name); platformLogger.info("Stopping service %s", this.name);
this.state.next(TdriveServiceState.Stopping); this.state.next(TdriveServiceState.Stopping);
await this.doStop(); await this.doStop();
this.state.next(TdriveServiceState.Stopped); this.state.next(TdriveServiceState.Stopped);
logger.info("Service %s is stopped", this.name); platformLogger.info("Service %s is stopped", this.name);
return this; return this;
} catch (err) { } catch (err) {
logger.error("Error while stopping service %s", this.name, err); platformLogger.error("Error while stopping service %s", this.name, err);
logger.error(err); platformLogger.error(err);
this.state.error(new Error(`Error while stopping service ${this.name}`)); this.state.error(new Error(`Error while stopping service ${this.name}`));
throw err; throw err;
@@ -23,3 +23,7 @@ export const logger = pino({
export const getLogger = (name?: string): TdriveLogger => export const getLogger = (name?: string): TdriveLogger =>
logger.child({ name: `tdrive${name ? "." + name : ""}` }); logger.child({ name: `tdrive${name ? "." + name : ""}` });
export const platformLogger = getLogger("platform");
export const messageQueueLogger = getLogger("message-queue");
@@ -1,6 +1,6 @@
/* eslint-disable @typescript-eslint/no-explicit-any, @typescript-eslint/explicit-module-boundary-types */ /* eslint-disable @typescript-eslint/no-explicit-any, @typescript-eslint/explicit-module-boundary-types */
import { import {
logger, platformLogger,
TdriveComponent, TdriveComponent,
TdriveContext, TdriveContext,
TdriveServiceFactory, TdriveServiceFactory,
@@ -28,7 +28,7 @@ export async function buildDependenciesTree(
`The component dependency ${dependencyName} has not been found for component ${name}`, `The component dependency ${dependencyName} has not been found for component ${name}`,
); );
} else { } else {
logger.warn( platformLogger.warn(
`(warning) The component dependency ${dependencyName} has not been found for component ${name} it will be imported asynchronously`, `(warning) The component dependency ${dependencyName} has not been found for component ${name} it will be imported asynchronously`,
); );
@@ -99,10 +99,10 @@ export async function switchComponentsToState(
const states = []; const states = [];
for (const [name, component] of components) { for (const [name, component] of components) {
logger.info(`Asking for ${state} on ${name} dependencies`); platformLogger.info(`Asking for ${state} on ${name} dependencies`);
states.push(component.getServiceInstance().state); states.push(component.getServiceInstance().state);
await component.switchToState(state); await component.switchToState(state);
} }
logger.info(`All components are now in ${state} state`); platformLogger.info(`All components are now in ${state} state`);
} }
@@ -1,4 +1,4 @@
import { logger } from "../logger"; import { platformLogger } from "../logger";
import fs from "fs"; import fs from "fs";
export class Loader { export class Loader {
@@ -14,7 +14,7 @@ export class Loader {
try { try {
return await import(modulePath); return await import(modulePath);
} catch (err) { } catch (err) {
logger.debug( platformLogger.debug(
{ err }, { err },
`${modulePath} can not be loaded (file was found but we were unable to import the module)`, `${modulePath} can not be loaded (file was found but we were unable to import the module)`,
); );
@@ -28,7 +28,9 @@ export class Loader {
if (!classes || !classes.length) { if (!classes || !classes.length) {
modulesPaths.map(modulePath => { modulesPaths.map(modulePath => {
if (fs.existsSync(modulePath)) { if (fs.existsSync(modulePath)) {
logger.debug(`${modulePath} content was: [${fs.readdirSync(modulePath).join(", ")}]`); platformLogger.debug(
`${modulePath} content was: [${fs.readdirSync(modulePath).join(", ")}]`,
);
} }
}); });
throw new Error( throw new Error(
@@ -38,7 +40,7 @@ export class Loader {
); );
} }
logger.debug(`Loaded ${componentName}`); platformLogger.debug(`Loaded ${componentName}`);
return classes[0].default; return classes[0].default;
} }
@@ -1,6 +1,6 @@
import { Subject } from "rxjs"; import { Subject } from "rxjs";
import { v4 as uuidv4 } from "uuid"; import { v4 as uuidv4 } from "uuid";
import { Initializable, logger, TdriveServiceProvider } from "../../framework"; import { Initializable, messageQueueLogger, TdriveServiceProvider } from "../../framework";
import { Processor } from "./processor"; import { Processor } from "./processor";
import { ExecutionContext } from "../../framework/api/crud-service"; import { ExecutionContext } from "../../framework/api/crud-service";
@@ -187,7 +187,7 @@ export class MessageQueueServiceProcessor<In, Out>
try { try {
await this.subscribe(this.messageQueue); await this.subscribe(this.messageQueue);
} catch (err) { } catch (err) {
logger.warn( messageQueueLogger.warn(
{ err }, { err },
`MessageQueueServiceProcessor.handler.${this.handler.name} - Not able to start handler`, `MessageQueueServiceProcessor.handler.${this.handler.name} - Not able to start handler`,
); );
@@ -202,7 +202,7 @@ export class MessageQueueServiceProcessor<In, Out>
} }
async process(message: IncomingMessageQueueMessage<In>): Promise<Out> { async process(message: IncomingMessageQueueMessage<In>): Promise<Out> {
logger.info( messageQueueLogger.info(
`MessageQueueServiceProcessor.handler.${this.handler.name}:${message.id} - Processing message`, `MessageQueueServiceProcessor.handler.${this.handler.name}:${message.id} - Processing message`,
); );
return this.handler.process(message.data); return this.handler.process(message.data);
@@ -212,7 +212,7 @@ export class MessageQueueServiceProcessor<In, Out>
//TODO this is where we do not receive the call //TODO this is where we do not receive the call
if (this.handler.topics && this.handler.topics.in) { if (this.handler.topics && this.handler.topics.in) {
logger.info( messageQueueLogger.info(
`MessageQueueServiceProcessor.handler.${this.handler.name} - Subscribing to topic ${this.handler?.topics?.in} with options %o`, `MessageQueueServiceProcessor.handler.${this.handler.name} - Subscribing to topic ${this.handler?.topics?.in} with options %o`,
this.handler.options, this.handler.options,
); );
@@ -233,7 +233,7 @@ export class MessageQueueServiceProcessor<In, Out>
const isValid = this.handler.validate(message.data); const isValid = this.handler.validate(message.data);
if (!isValid) { if (!isValid) {
logger.error( messageQueueLogger.error(
`MessageQueueServiceProcessor.handler.${this.handler.name}:${message.id} - Message is invalid`, `MessageQueueServiceProcessor.handler.${this.handler.name}:${message.id} - Message is invalid`,
); );
@@ -246,7 +246,7 @@ export class MessageQueueServiceProcessor<In, Out>
try { try {
const result = await this.process(message); const result = await this.process(message);
if (this.handler?.options?.ack && message?.ack) { if (this.handler?.options?.ack && message?.ack) {
logger.debug( messageQueueLogger.debug(
`MessageQueueServiceProcessor.handler.${this.handler.name}:${message.id} - Acknowledging message %o`, `MessageQueueServiceProcessor.handler.${this.handler.name}:${message.id} - Acknowledging message %o`,
message, message,
); );
@@ -266,13 +266,13 @@ export class MessageQueueServiceProcessor<In, Out>
private async sendResult(message: IncomingMessageQueueMessage<In>, result: Out): Promise<void> { private async sendResult(message: IncomingMessageQueueMessage<In>, result: Out): Promise<void> {
if (!this.handler.topics.out) { if (!this.handler.topics.out) {
logger.info( messageQueueLogger.info(
`MessageQueueServiceProcessor.handler.${this.handler.name}:${message.id} - Message processing result is skipped`, `MessageQueueServiceProcessor.handler.${this.handler.name}:${message.id} - Message processing result is skipped`,
); );
return; return;
} }
logger.info( messageQueueLogger.info(
`MessageQueueServiceProcessor.handler.${this.handler.name}:${message.id} - Sending processing result to ${this.handler.topics.out}`, `MessageQueueServiceProcessor.handler.${this.handler.name}:${message.id} - Sending processing result to ${this.handler.topics.out}`,
); );
@@ -284,7 +284,7 @@ export class MessageQueueServiceProcessor<In, Out>
// eslint-disable-next-line @typescript-eslint/no-explicit-any // eslint-disable-next-line @typescript-eslint/no-explicit-any
private async handleError(message: IncomingMessageQueueMessage<In>, err: any) { private async handleError(message: IncomingMessageQueueMessage<In>, err: any) {
logger.error( messageQueueLogger.error(
{ err }, { err },
`MessageQueueServiceProcessor.handler.${this.handler.name}:${message.id} - Error while processing message`, `MessageQueueServiceProcessor.handler.${this.handler.name}:${message.id} - Error while processing message`,
); );
@@ -1,4 +1,4 @@
import { logger } from "../../framework"; import { messageQueueLogger } from "../../framework";
import { MessageQueueHandler, MessageQueueServiceAPI, MessageQueueServiceProcessor } from "./api"; import { MessageQueueHandler, MessageQueueServiceAPI, MessageQueueServiceProcessor } from "./api";
const LOG_PREFIX = "service.message-queue.Processor"; const LOG_PREFIX = "service.message-queue.Processor";
@@ -20,9 +20,9 @@ export class Processor {
this.started = true; this.started = true;
await Promise.all( await Promise.all(
Array.from(this.registry.processors.keys()).map(async name => { Array.from(this.registry.processors.keys()).map(async name => {
logger.info(`${LOG_PREFIX} - Starting notification processor ${name}`); messageQueueLogger.info(`${LOG_PREFIX} - Starting notification processor ${name}`);
await this.registry.processors.get(name)?.init(); await this.registry.processors.get(name)?.init();
logger.info(`${LOG_PREFIX} - notification processor ${name} is started`); messageQueueLogger.info(`${LOG_PREFIX} - notification processor ${name} is started`);
}), }),
); );
} }
@@ -41,7 +41,7 @@ export class Processor {
throw new Error(`${LOG_PREFIX} - Can not add null handler`); throw new Error(`${LOG_PREFIX} - Can not add null handler`);
} }
logger.info(`${LOG_PREFIX} - Adding message-queue handler ${handler.name}`); messageQueueLogger.info(`${LOG_PREFIX} - Adding message-queue handler ${handler.name}`);
this.registry.register(handler); this.registry.register(handler);
if (this.started) { if (this.started) {
@@ -50,17 +50,17 @@ export class Processor {
} }
async startHandler(name: string): Promise<void> { async startHandler(name: string): Promise<void> {
logger.info(`${LOG_PREFIX} - Starting message-queue handler ${name}`); messageQueueLogger.info(`${LOG_PREFIX} - Starting message-queue handler ${name}`);
await this.registry.processors.get(name)?.init(); await this.registry.processors.get(name)?.init();
} }
stopHandler(name: string): void { stopHandler(name: string): void {
logger.info(`${LOG_PREFIX} - Stopping message-queue handler ${name}`); messageQueueLogger.info(`${LOG_PREFIX} - Stopping message-queue handler ${name}`);
this.registry.processors.get(name)?.stop(); this.registry.processors.get(name)?.stop();
} }
removeHandler(name: string): void { removeHandler(name: string): void {
logger.info(`${LOG_PREFIX} - Removing message-queue handler ${name}`); messageQueueLogger.info(`${LOG_PREFIX} - Removing message-queue handler ${name}`);
this.stopHandler(name); this.stopHandler(name);
this.registry.processors.delete(name); this.registry.processors.delete(name);
} }
@@ -1,5 +1,5 @@
import { isEqual } from "lodash"; import { isEqual } from "lodash";
import { logger } from "../../framework"; import { messageQueueLogger } from "../../framework";
import { import {
MessageQueueClient, MessageQueueClient,
MessageQueueListener, MessageQueueListener,
@@ -40,7 +40,7 @@ export default class MessageQueueProxyService implements MessageQueueProxy {
constructor(private client?: MessageQueueClient) {} constructor(private client?: MessageQueueClient) {}
async setClient(client: MessageQueueClient): Promise<void> { async setClient(client: MessageQueueClient): Promise<void> {
logger.info(`${LOG_PREFIX} Setting new message-queue client`); messageQueueLogger.info(`${LOG_PREFIX} Setting new message-queue client`);
// TODO: The client can be removed or replaced while we are looping here // TODO: The client can be removed or replaced while we are looping here
// We may wait until things are done, or discard some... // We may wait until things are done, or discard some...
if (!client) { if (!client) {
@@ -48,7 +48,7 @@ export default class MessageQueueProxyService implements MessageQueueProxy {
} }
if (this.client) { if (this.client) {
logger.info(`${LOG_PREFIX} MessageQueue client already set. Overriding`); messageQueueLogger.info(`${LOG_PREFIX} MessageQueue client already set. Overriding`);
} }
this.client = client; this.client = client;
@@ -59,11 +59,11 @@ export default class MessageQueueProxyService implements MessageQueueProxy {
const listeners = entries[1]; const listeners = entries[1];
return Array.from(listeners).map(async listener => { return Array.from(listeners).map(async listener => {
logger.debug(`${LOG_PREFIX} Subscribing to topic ${topic} from cache`); messageQueueLogger.debug(`${LOG_PREFIX} Subscribing to topic ${topic} from cache`);
try { try {
await this.subscribe(topic, listener.listener, listener.options); await this.subscribe(topic, listener.listener, listener.options);
} catch (err) { } catch (err) {
logger.warn( messageQueueLogger.warn(
{ err }, { err },
`${LOG_PREFIX} Error while subscribing with cached subscription to topic ${topic}`, `${LOG_PREFIX} Error while subscribing with cached subscription to topic ${topic}`,
); );
@@ -75,10 +75,12 @@ export default class MessageQueueProxyService implements MessageQueueProxy {
await Promise.all( await Promise.all(
this.publicationsBuffer.map(async publication => { this.publicationsBuffer.map(async publication => {
try { try {
logger.debug(`${LOG_PREFIX} Publishing to topic ${publication.topic} from cache`); messageQueueLogger.debug(
`${LOG_PREFIX} Publishing to topic ${publication.topic} from cache`,
);
await this.publish(publication.topic, publication.message); await this.publish(publication.topic, publication.message);
} catch (err) { } catch (err) {
logger.warn( messageQueueLogger.warn(
{ err }, { err },
`${LOG_PREFIX} Error while publishing cached data on topic ${publication.topic}`, `${LOG_PREFIX} Error while publishing cached data on topic ${publication.topic}`,
); );
@@ -101,7 +103,7 @@ export default class MessageQueueProxyService implements MessageQueueProxy {
try { try {
await this.client?.close?.(); await this.client?.close?.();
} catch (err) { } catch (err) {
logger.debug({ err }, `${LOG_PREFIX} Error on closing the message-queue layer`); messageQueueLogger.debug({ err }, `${LOG_PREFIX} Error on closing the message-queue layer`);
} }
} }
@@ -139,7 +141,9 @@ export default class MessageQueueProxyService implements MessageQueueProxy {
} }
const subscriptions = this.subscriptionsCache.get(topic); const subscriptions = this.subscriptionsCache.get(topic);
logger.debug(`${LOG_PREFIX} Subscriptions for topic ${topic}: ${subscriptions.size}`); messageQueueLogger.debug(
`${LOG_PREFIX} Subscriptions for topic ${topic}: ${subscriptions.size}`,
);
const values = [...subscriptions]; const values = [...subscriptions];
const cachedListener = values.find( const cachedListener = values.find(
@@ -147,16 +151,16 @@ export default class MessageQueueProxyService implements MessageQueueProxy {
); );
if (!cachedListener) { if (!cachedListener) {
logger.debug(`${LOG_PREFIX} Caching subscription to ${topic} topic: Yes`); messageQueueLogger.debug(`${LOG_PREFIX} Caching subscription to ${topic} topic: Yes`);
this.subscriptionsCache.get(topic).add({ listener, options }); this.subscriptionsCache.get(topic).add({ listener, options });
} else { } else {
logger.debug(`${LOG_PREFIX} Caching subscription to ${topic} topic: No`); messageQueueLogger.debug(`${LOG_PREFIX} Caching subscription to ${topic} topic: No`);
} }
} }
// eslint-disable-next-line @typescript-eslint/no-explicit-any // eslint-disable-next-line @typescript-eslint/no-explicit-any
private addPublishCache(topic: string, message: any): void { private addPublishCache(topic: string, message: any): void {
logger.debug(`${LOG_PREFIX} Caching publication to ${topic} topic`); messageQueueLogger.debug(`${LOG_PREFIX} Caching publication to ${topic} topic`);
this.publicationsBuffer.push({ topic, message }); this.publicationsBuffer.push({ topic, message });
} }
@@ -166,7 +170,10 @@ export default class MessageQueueProxyService implements MessageQueueProxy {
listener: MessageQueueListener<any>, listener: MessageQueueListener<any>,
options?: MessageQueueSubscriptionOptions, options?: MessageQueueSubscriptionOptions,
): Promise<void> { ): Promise<void> {
logger.debug(`${LOG_PREFIX} Trying to subscribe to ${topic} topic with options %o`, options); messageQueueLogger.debug(
`${LOG_PREFIX} Trying to subscribe to ${topic} topic with options %o`,
options,
);
return this.client?.subscribe(topic, listener, options); return this.client?.subscribe(topic, listener, options);
} }
} }