From 69c9ac20bf030bb746810fad5f666b4cb1d2fff0 Mon Sep 17 00:00:00 2001 From: Piotr Chromiec Date: Wed, 17 Mar 2021 12:51:48 +0100 Subject: [PATCH] [pay] traces for `yagna freeze` bug hunt --- a | 0 core/payment/src/api/debit_notes.rs | 21 ++++++++++++++++++++- core/payment/src/api/invoices.rs | 16 ++++++++++++++++ core/payment/src/processor.rs | 9 +++++++++ core/payment/src/utils.rs | 2 ++ 5 files changed, 47 insertions(+), 1 deletion(-) create mode 100644 a diff --git a/a b/a new file mode 100644 index 0000000000..e69de29bb2 diff --git a/core/payment/src/api/debit_notes.rs b/core/payment/src/api/debit_notes.rs index 82669a3b16..a467add226 100644 --- a/core/payment/src/api/debit_notes.rs +++ b/core/payment/src/api/debit_notes.rs @@ -239,6 +239,7 @@ async fn accept_debit_note( let allocation_id = acceptance.allocation_id.clone(); let dao: DebitNoteDao = db.as_dao(); + log::trace!("Querying DB for Debit Note [{}]", debit_note_id); let debit_note: DebitNote = match dao.get(debit_note_id.clone(), node_id).await { Ok(Some(debit_note)) => debit_note, Ok(None) => return response::not_found(), @@ -260,6 +261,11 @@ async fn accept_debit_note( } let activity_id = debit_note.activity_id.clone(); + log::trace!( + "Querying DB for Activity [{}] for Debit Note [{}]", + activity_id, + debit_note_id + ); let activity = match db .as_dao::() .get(activity_id.clone(), node_id) @@ -271,6 +277,11 @@ async fn accept_debit_note( }; let amount_to_pay = &debit_note.total_amount_due - &activity.total_amount_scheduled.0; + log::trace!( + "Querying DB for Allocation [{}] for Debit Note [{}]", + allocation_id, + debit_note_id + ); let allocation = match db .as_dao::() .get(allocation_id.clone(), node_id) @@ -293,19 +304,27 @@ async fn accept_debit_note( let timeout = query.timeout.unwrap_or(params::DEFAULT_ACK_TIMEOUT); with_timeout(timeout, async move { let issuer_id = debit_note.issuer_id; - let accept_msg = AcceptDebitNote::new(debit_note_id.clone(), acceptance, issuer_id); + let accept_msg = ::new(debit_note_id.clone(), acceptance, issuer_id); let schedule_msg = SchedulePayment::from_debit_note(debit_note, allocation_id, amount_to_pay); match async move { + log::trace!( + "Sending AcceptDebitNote [{}] to [{}]", + debit_note_id, + issuer_id + ); ya_net::from(node_id) .to(issuer_id) .service(PUBLIC_SERVICE) .call(accept_msg) .await??; if let Some(msg) = schedule_msg { + log::trace!("Calling SchedulePayment [{}] locally", debit_note_id); bus::service(LOCAL_SERVICE).send(msg).await??; } + log::trace!("Accepting Debit Note [{}] in DB", debit_note_id); dao.accept(debit_note_id, node_id).await?; + log::trace!("Debit Note accepted successfully for [{}]", debit_note_id); counter!("payment.debit_notes.requestor.accepted", 1); Ok(()) diff --git a/core/payment/src/api/invoices.rs b/core/payment/src/api/invoices.rs index 7e25541196..3815e85349 100644 --- a/core/payment/src/api/invoices.rs +++ b/core/payment/src/api/invoices.rs @@ -282,6 +282,8 @@ async fn accept_invoice( let allocation_id = acceptance.allocation_id.clone(); let dao: InvoiceDao = db.as_dao(); + + log::trace!("Querying DB for Invoice [{}]", invoice_id); let invoice = match dao.get(invoice_id.clone(), node_id).await { Ok(Some(invoice)) => invoice, Ok(None) => return response::not_found(), @@ -303,6 +305,11 @@ async fn accept_invoice( } let agreement_id = invoice.agreement_id.clone(); + log::trace!( + "Querying DB for Agreement [{}] for Invoice [{}]", + agreement_id, + invoice_id + ); let agreement = match db .as_dao::() .get(agreement_id.clone(), node_id) @@ -316,6 +323,11 @@ async fn accept_invoice( }; let amount_to_pay = &invoice.amount - &agreement.total_amount_scheduled.0; + log::trace!( + "Querying DB for Allocation [{}] for Invoice [{}]", + allocation_id, + invoice_id + ); let allocation = match db .as_dao::() .get(allocation_id.clone(), node_id) @@ -341,15 +353,19 @@ async fn accept_invoice( let accept_msg = AcceptInvoice::new(invoice_id.clone(), acceptance, issuer_id); let schedule_msg = SchedulePayment::from_invoice(invoice, allocation_id, amount_to_pay); match async move { + log::trace!("Sending AcceptInvoice [{}] to [{}]", invoice_id, issuer_id); ya_net::from(node_id) .to(issuer_id) .service(PUBLIC_SERVICE) .call(accept_msg) .await??; if let Some(msg) = schedule_msg { + log::trace!("Calling SchedulePayment [{}] locally", invoice_id); bus::service(LOCAL_SERVICE).send(msg).await??; } + log::trace!("Accepting Invoice [{}] in DB", invoice_id); dao.accept(invoice_id, node_id).await?; + log::trace!("Invoice accepted successfully for [{}]", invoice_id); counter!("payment.invoices.requestor.accepted", 1); Ok(()) diff --git a/core/payment/src/processor.rs b/core/payment/src/processor.rs index 3e2139582b..05e881fd52 100644 --- a/core/payment/src/processor.rs +++ b/core/payment/src/processor.rs @@ -404,11 +404,17 @@ impl PaymentProcessor { pub async fn schedule_payment(&self, msg: SchedulePayment) -> Result<(), SchedulePaymentError> { let amount = msg.amount.clone(); + log::trace!("Getting driver for [{:?}]", msg.title); let driver = self.registry.lock().await.driver( &msg.payment_platform, &msg.payer_addr, AccountMode::SEND, )?; + log::trace!( + "Scheduling payment [{:?}] using driver [{}]", + msg.title, + driver + ); let order_id = driver_endpoint(&driver) .send(driver::SchedulePayment::new( amount, @@ -419,11 +425,14 @@ impl PaymentProcessor { )) .await??; + log::trace!("Creating payment order in DB for [{:?}]", msg.title); self.db_executor .as_dao::() .create(msg, order_id, driver) .await?; + log::trace!("Payment scheduled successfully for [{:?}]", msg.title); + Ok(()) } diff --git a/core/payment/src/utils.rs b/core/payment/src/utils.rs index ad8d34c6ae..48790fe40b 100644 --- a/core/payment/src/utils.rs +++ b/core/payment/src/utils.rs @@ -118,11 +118,13 @@ pub async fn with_timeout>( ) -> HttpResponse { let timeout_secs = timeout_secs.into(); if timeout_secs > 0.0 { + log::trace!("Starting timeout for: {}s", timeout_secs); match tokio::time::timeout(Duration::from_secs_f64(timeout_secs), work).await { Ok(v) => v, Err(_) => return HttpResponse::GatewayTimeout().finish(), } } else { + log::trace!("Executing /wo timeout."); work.await } }