Merge pull request #1001 from golemfactory/mgordel/JST-936/logging-in…

…mprovements

refactor: improved logging

src/activity/activity.module.ts

@@ -216,13 +216,18 @@ export class ActivityModuleImpl implements ActivityModule {
   }
 
   async createActivity(agreement: Agreement): Promise<Activity> {
-    this.logger.info("Creating activity", {
+    this.logger.debug("Creating activity", {
       agreementId: agreement.id,
       provider: agreement.provider,
     });
     try {
       const activity = await this.activityApi.createActivity(agreement);
       this.events.emit("activityCreated", activity);
+      this.logger.info("Created activity", {
+        activityId: activity.id,
+        agreementId: agreement.id,
+        provider: agreement.provider,
+      });
       return activity;
     } catch (error) {
       this.events.emit("errorCreatingActivity", error);
@@ -231,14 +236,15 @@ export class ActivityModuleImpl implements ActivityModule {
   }
 
   async destroyActivity(activity: Activity): Promise<Activity> {
-    this.logger.info("Destroying activity", {
-      activityId: activity.id,
-      agreementId: activity.agreement.id,
-      provider: activity.agreement.provider,
-    });
+    this.logger.debug("Destroying activity", activity);
     try {
       const updated = await this.activityApi.destroyActivity(activity);
       this.events.emit("activityDestroyed", updated);
+      this.logger.info("Destroyed activity", {
+        activityId: updated.id,
+        agreementId: updated.agreement.id,
+        provider: updated.agreement.provider,
+      });
       return updated;
     } catch (error) {
       this.events.emit("errorDestroyingActivity", activity, error);
@@ -275,7 +281,7 @@ export class ActivityModuleImpl implements ActivityModule {
   }
 
   async createExeUnit(activity: Activity, options?: ExeUnitOptions): Promise<ExeUnit> {
-    this.logger.info("Creating exe-unit for activity", { activityId: activity.id });
+    this.logger.debug("Creating exe-unit for activity", { activityId: activity.id });
     const exe = new ExeUnit(activity, this, {
       yagnaOptions: this.services.yagna.yagnaOptions,
       logger: this.logger.child("exe-unit"),
@@ -285,13 +291,15 @@ export class ActivityModuleImpl implements ActivityModule {
     this.logger.debug("Initializing the exe-unit for activity", { activityId: activity.id });
     try {
       await exe.setup();
-      this.events.emit(
-        "exeUnitInitialized",
-        await this.refreshActivity(activity).catch(() => {
-          this.logger.warn("Failed to refresh activity after work context initialization", { activityId: activity.id });
-          return activity;
-        }),
-      );
+      const refreshedActivity = await this.refreshActivity(activity).catch(() => {
+        this.logger.warn("Failed to refresh activity after work context initialization", { activityId: activity.id });
+        return activity;
+      });
+      this.events.emit("exeUnitInitialized", refreshedActivity);
+      this.logger.info("Initialized exe-unit", {
+        activityId: activity.id,
+        state: refreshedActivity.getState(),
+      });
       return exe;
     } catch (error) {
       this.events.emit(

src/market/market.module.ts

@@ -312,7 +312,8 @@ export class MarketModuleImpl implements MarketModule {
       const unsubscribeFromOfferProposals = async (demand: Demand) => {
         try {
           await this.deps.marketApi.unpublishDemand(demand);
-          this.logger.info("Demand unpublished from the market", { demand });
+          this.logger.info("Unpublished demand", { demandId: demand.id });
+          this.logger.debug("Unpublished demand", demand);
           this.events.emit("demandSubscriptionStopped", demand);
         } catch (err) {
           const golemMarketError = new GolemMarketError(

src/network/network.module.ts

@@ -100,7 +100,7 @@ export class NetworkModuleImpl implements NetworkModule {
       // add Requestor as network node
       const requestorId = await this.networkApi.getIdentity();
       await this.createNetworkNode(network, requestorId, options?.ownerIp);
-      this.logger.info(`Network created`, network.getNetworkInfo());
+      this.logger.info(`Created network`, network.getNetworkInfo());
       this.events.emit("networkCreated", network);
       return network;
     } catch (err) {
@@ -124,7 +124,7 @@ export class NetworkModuleImpl implements NetworkModule {
       try {
         await this.networkApi.removeNetwork(network);
         network.markAsRemoved();
-        this.logger.info(`Network removed`, network.getNetworkInfo());
+        this.logger.info(`Removed network`, network.getNetworkInfo());
         this.events.emit("networkRemoved", network);
       } catch (error) {
         this.events.emit("errorRemovingNetwork", network, error);
@@ -154,7 +154,7 @@ export class NetworkModuleImpl implements NetworkModule {
         const ipv4 = this.getFreeIpInNetwork(network, nodeIp);
         const node = await this.networkApi.createNetworkNode(network, nodeId, ipv4.toString());
         network.addNode(node);
-        this.logger.info(`Node has been added to the network.`, { id: nodeId, ip: ipv4.toString() });
+        this.logger.info(`Added network node`, { id: nodeId, ip: ipv4.toString() });
         this.events.emit("nodeCreated", network, node);
         return node;
       } catch (error) {
@@ -184,7 +184,7 @@ export class NetworkModuleImpl implements NetworkModule {
         }
         await this.networkApi.removeNetworkNode(network, node);
         network.removeNode(node);
-        this.logger.info(`Node has been removed from the network.`, {
+        this.logger.info(`Removed network node`, {
           network: network.getNetworkInfo().ip,
           nodeIp: node.ip,
         });

src/payment/agreement_payment_process.ts

@@ -252,12 +252,6 @@ export class AgreementPaymentProcess {
 
     try {
       await this.paymentModule.acceptInvoice(invoice, this.allocation, invoice.amount);
-      this.logger.info(`Invoice has been accepted`, {
-        invoiceId: invoice.id,
-        agreementId: invoice.agreementId,
-        amount: invoice.amount,
-        provider: this.agreement.provider,
-      });
     } catch (error) {
       const message = getMessageFromApiError(error);
       throw new GolemPaymentError(

src/payment/payment.module.ts

@@ -137,14 +137,20 @@ export class PaymentModuleImpl implements PaymentModule {
   }
 
   async createAllocation(params: CreateAllocationParams): Promise<Allocation> {
-    this.logger.info("Creating allocation", { params: params });
+    this.logger.debug("Creating allocation", { params: params });
 
     try {
       const allocation = await this.paymentApi.createAllocation({
         paymentPlatform: this.getPaymentPlatform(),
         ...params,
       });
       this.events.emit("allocationCreated", allocation);
+      this.logger.info("Created allocation", {
+        allocationId: allocation.id,
+        budget: allocation.totalAmount,
+        platform: this.getPaymentPlatform(),
+      });
+      this.logger.debug("Created allocation", allocation);
       return allocation;
     } catch (error) {
       this.events.emit("errorCreatingAllocation", error);
@@ -153,14 +159,19 @@ export class PaymentModuleImpl implements PaymentModule {
   }
 
   async releaseAllocation(allocation: Allocation): Promise<void> {
-    this.logger.info("Releasing allocation", { id: allocation.id });
+    this.logger.debug("Releasing allocation", allocation);
     try {
       const lastKnownAllocationState = await this.getAllocation(allocation.id).catch(() => {
         this.logger.warn("Failed to fetch allocation before releasing", { id: allocation.id });
         return allocation;
       });
       await this.paymentApi.releaseAllocation(allocation);
       this.events.emit("allocationReleased", lastKnownAllocationState);
+      this.logger.info("Released allocation", {
+        allocationId: lastKnownAllocationState.id,
+        totalAmount: lastKnownAllocationState.totalAmount,
+        spentAmount: lastKnownAllocationState.spentAmount,
+      });
     } catch (error) {
       this.events.emit(
         "errorReleasingAllocation",
@@ -186,37 +197,67 @@ export class PaymentModuleImpl implements PaymentModule {
   }
 
   async acceptInvoice(invoice: Invoice, allocation: Allocation, amount: string): Promise<Invoice> {
-    this.logger.info("Accepting invoice", { id: invoice.id, allocation: allocation.id, amount });
+    this.logger.debug("Accepting invoice", invoice);
     try {
       const acceptedInvoice = await this.paymentApi.acceptInvoice(invoice, allocation, amount);
       this.events.emit("invoiceAccepted", acceptedInvoice);
+      this.logger.info("Accepted invoice", {
+        id: invoice.id,
+        allocationId: allocation.id,
+        agreementId: invoice.agreementId,
+        provider: invoice.provider,
+        amount,
+      });
       return acceptedInvoice;
     } catch (error) {
       this.events.emit("errorAcceptingInvoice", invoice, error);
+      this.logger.error(`Failed to accept invoice. ${error}`, {
+        id: invoice.id,
+        allocationId: allocation.id,
+        agreementId: invoice.agreementId,
+        provider: invoice.provider,
+        amount,
+      });
       throw error;
     }
   }
 
   async rejectInvoice(invoice: Invoice, reason: string): Promise<Invoice> {
-    this.logger.info("Rejecting invoice", { id: invoice.id, reason });
+    this.logger.debug("Rejecting invoice", { id: invoice.id, reason });
     try {
       const rejectedInvoice = await this.paymentApi.rejectInvoice(invoice, reason);
       this.events.emit("invoiceRejected", rejectedInvoice);
+      this.logger.warn("Rejeced invoice", { id: invoice.id, reason });
       return rejectedInvoice;
     } catch (error) {
       this.events.emit("errorRejectingInvoice", invoice, error);
+      this.logger.error(`Failed to reject invoice. ${error}`, { id: invoice.id, reason });
       throw error;
     }
   }
 
   async acceptDebitNote(debitNote: DebitNote, allocation: Allocation, amount: string): Promise<DebitNote> {
-    this.logger.info("Accepting debit note", { id: debitNote.id, allocation: allocation.id, amount });
+    this.logger.debug("Accepting debit note", debitNote);
     try {
       const acceptedDebitNote = await this.paymentApi.acceptDebitNote(debitNote, allocation, amount);
       this.events.emit("debitNoteAccepted", acceptedDebitNote);
+      this.logger.debug("Accepted debit note", {
+        id: debitNote.id,
+        allocationId: allocation.id,
+        activityId: debitNote.activityId,
+        provider: debitNote.provider,
+        amount,
+      });
       return acceptedDebitNote;
     } catch (error) {
       this.events.emit("errorAcceptingDebitNote", debitNote, error);
+      this.logger.error(`Failed to accept debitNote. ${error}`, {
+        id: debitNote.id,
+        allocationId: allocation.id,
+        activityId: debitNote.activityId,
+        provider: debitNote.provider,
+        amount,
+      });
       throw error;
     }
   }

src/resource-rental/resource-rental.ts

@@ -90,9 +90,9 @@ export class ResourceRental {
             }
             throw new GolemAbortError("The finalization of payment process has been aborted", abortSignal.reason);
           });
-          this.logger.info("Payment process for agreement finalized", { agreementId: this.agreement.id });
+          this.logger.info("Finalized payment process", { agreementId: this.agreement.id });
         } catch (error) {
-          this.logger.error("Payment process finalization failed", { agreementId: this.agreement.id, error });
+          this.logger.error("Filed to finalize payment process", { agreementId: this.agreement.id, error });
           throw error;
         } finally {
           this.events.emit("finalized");

src/shared/yagna/adapters/market-api-adapter.ts

@@ -276,7 +276,7 @@ export class MarketApiAdapter implements IMarketApi {
       );
     }
 
-    this.logger.info("Established agreement", { agreementId: agreement.id, provider: agreement.provider });
+    this.logger.debug("Established agreement", agreement);
 
     return confirmed;
   }

src/shared/yagna/yagnaApi.ts

@@ -179,22 +179,24 @@ export class YagnaApi {
    * Effectively starts the Yagna API client including subscribing to events exposed via rxjs subjects
    */
   async connect() {
-    this.logger.info("Connecting to Yagna");
+    this.logger.debug("Connecting to Yagna");
 
-    await this.assertSupportedVersion();
+    const version = await this.assertSupportedVersion();
 
-    const identity = this.identity.getIdentity();
+    const identity = await this.identity.getIdentity();
 
     this.startPollingEvents();
 
+    this.logger.info("Connected to Yagna", { version, identity: identity.identity });
+
     return identity;
   }
 
   /**
    * Terminates the Yagna API related activities
    */
   async disconnect() {
-    this.logger.info("Disconnecting from Yagna");
+    this.logger.debug("Disconnecting from Yagna");
     await this.stopPollingEvents();
     this.logger.info("Disconnected from Yagna");
   }
@@ -209,7 +211,7 @@ export class YagnaApi {
   }
 
   private startPollingEvents() {
-    this.logger.info("Starting to poll for events from Yagna", { appSessionId: this.appSessionId });
+    this.logger.debug("Starting to poll for events from Yagna", { appSessionId: this.appSessionId });
 
     const pollIntervalSec = 5;
     const maxEvents = 100;
@@ -229,17 +231,17 @@ export class YagnaApi {
     // Run the readers and don't block execution
     this.reader
       .pollToSubject(this.agreementEventsPoll.pollValues(), this.agreementEvents$)
-      .then(() => this.logger.info("Finished polling agreement events from Yagna"))
+      .then(() => this.logger.debug("Finished polling agreement events from Yagna"))
       .catch((err) => this.logger.error("Error while polling agreement events from Yagna", err));
 
     this.reader
       .pollToSubject(this.debitNoteEventsPoll.pollValues(), this.debitNoteEvents$)
-      .then(() => this.logger.info("Finished polling debit note events from Yagna"))
+      .then(() => this.logger.debug("Finished polling debit note events from Yagna"))
       .catch((err) => this.logger.error("Error while polling debit note events from Yagna", err));
 
     this.reader
       .pollToSubject(this.invoiceEventPoll.pollValues(), this.invoiceEvents$)
-      .then(() => this.logger.info("Finished polling invoice events from Yagna"))
+      .then(() => this.logger.debug("Finished polling invoice events from Yagna"))
       .catch((err) => this.logger.error("Error while polling invoice events from Yagna", err));
   }