chore(logging): purchases logging

codex/contracts/market.nim

@@ -12,7 +12,7 @@ import ./marketplace
 export market
 
 logScope:
-    topics = "marketplace onchain market"
+  topics = "marketplace onchain market"
 
 type
   OnChainMarket* = ref object of Market

codex/purchasing/states/cancelled.nim

@@ -1,10 +1,14 @@
 import pkg/metrics
+import pkg/chronicles
 import ../statemachine
 import ./errorhandling
 import ./error
 
 declareCounter(codexPurchasesCancelled, "codex purchases cancelled")
 
+logScope:
+  topics = "marketplace purchases cancelled"
+
 type PurchaseCancelled* = ref object of ErrorHandlingState
 
 method `$`*(state: PurchaseCancelled): string =
@@ -13,6 +17,9 @@ method `$`*(state: PurchaseCancelled): string =
 method run*(state: PurchaseCancelled, machine: Machine): Future[?State] {.async.} =
   codexPurchasesCancelled.inc()
   let purchase = Purchase(machine)
+
+  warn "Request cancelled, withdrawing remaining funds",  requestId = $purchase.requestId
   await purchase.market.withdrawFunds(purchase.requestId)
+
   let error = newException(Timeout, "Purchase cancelled due to timeout")
   return some State(PurchaseErrored(error: error))

codex/purchasing/states/error.nim

@@ -1,8 +1,13 @@
 import pkg/metrics
+import pkg/chronicles
 import ../statemachine
+import ../../utils/exceptions
 
 declareCounter(codexPurchasesError, "codex purchases error")
 
+logScope:
+  topics = "marketplace purchases errored"
+
 type PurchaseErrored* = ref object of PurchaseState
   error*: ref CatchableError
 
@@ -12,4 +17,7 @@ method `$`*(state: PurchaseErrored): string =
 method run*(state: PurchaseErrored, machine: Machine): Future[?State] {.async.} =
   codexPurchasesError.inc()
   let purchase = Purchase(machine)
+
+  error "Purchasing error", error=state.error.msgDetail, requestId = purchase.requestId
+
   purchase.future.fail(state.error)

codex/purchasing/states/finished.nim

@@ -1,8 +1,12 @@
 import pkg/metrics
+import pkg/chronicles
 import ../statemachine
 
 declareCounter(codexPurchasesFinished, "codex purchases finished")
 
+logScope:
+  topics = "marketplace purchases finished"
+
 type PurchaseFinished* = ref object of PurchaseState
 
 method `$`*(state: PurchaseFinished): string =
@@ -11,4 +15,5 @@ method `$`*(state: PurchaseFinished): string =
 method run*(state: PurchaseFinished, machine: Machine): Future[?State] {.async.} =
   codexPurchasesFinished.inc()
   let purchase = Purchase(machine)
+  info "Purchase finished", requestId = purchase.requestId
   purchase.future.complete()

codex/purchasing/states/started.nim

@@ -1,11 +1,15 @@
 import pkg/metrics
+import pkg/chronicles
 import ../statemachine
 import ./errorhandling
 import ./finished
 import ./failed
 
 declareCounter(codexPurchasesStarted, "codex purchases started")
 
+logScope:
+  topics = "marketplace purchases started"
+
 type PurchaseStarted* = ref object of ErrorHandlingState
 
 method `$`*(state: PurchaseStarted): string =
@@ -17,6 +21,7 @@ method run*(state: PurchaseStarted, machine: Machine): Future[?State] {.async.}
 
   let clock = purchase.clock
   let market = purchase.market
+  info "All required slots filled, purchase started", requestId = purchase.requestId
 
   let failed = newFuture[void]()
   proc callback(_: RequestId) =

codex/purchasing/states/submitted.nim

@@ -1,9 +1,13 @@
 import pkg/metrics
+import pkg/chronicles
 import ../statemachine
 import ./errorhandling
 import ./started
 import ./cancelled
 
+logScope:
+  topics = "marketplace purchases submitted"
+
 declareCounter(codexPurchasesSubmitted, "codex purchases submitted")
 
 type PurchaseSubmitted* = ref object of ErrorHandlingState
@@ -18,6 +22,8 @@ method run*(state: PurchaseSubmitted, machine: Machine): Future[?State] {.async.
   let market = purchase.market
   let clock = purchase.clock
 
+  info "Request submitted, waiting for slots to be filled", requestId = purchase.requestId
+
   proc wait {.async.} =
     let done = newFuture[void]()
     proc callback(_: RequestId) =
@@ -27,7 +33,7 @@ method run*(state: PurchaseSubmitted, machine: Machine): Future[?State] {.async.
     await subscription.unsubscribe()
 
   proc withTimeout(future: Future[void]) {.async.} =
-    let expiry = request.expiry.truncate(int64)
+    let expiry = request.expiry.truncate(int64) + 1
     await future.withTimeout(clock, expiry)
 
   try:

codex/sales/states/cancelled.nim

@@ -4,7 +4,7 @@ import ./errorhandling
 import ./errored
 
 logScope:
-    topics = "marketplace sales cancelled"
+  topics = "marketplace sales cancelled"
 
 type
   SaleCancelled* = ref object of ErrorHandlingState

codex/sales/states/errored.nim

@@ -7,7 +7,7 @@ import ../salesagent
 import ../../utils/exceptions
 
 logScope:
-    topics = "marketplace sales errored"
+  topics = "marketplace sales errored"
 
 type SaleErrored* = ref object of SaleState
   error*: ref CatchableError

codex/sales/states/failed.nim

@@ -4,7 +4,7 @@ import ./errorhandling
 import ./errored
 
 logScope:
-    topics = "marketplace sales failed"
+  topics = "marketplace sales failed"
 
 type
   SaleFailed* = ref object of ErrorHandlingState

codex/sales/states/filled.nim

@@ -11,7 +11,7 @@ import ./proving
 import ./provingsimulated
 
 logScope:
-    topics = "marketplace sales filled"
+  topics = "marketplace sales filled"
 
 type
   SaleFilled* = ref object of ErrorHandlingState

codex/sales/states/filling.nim

@@ -8,7 +8,7 @@ import ./cancelled
 import ./failed
 
 logScope:
-    topics = "marketplace sales filling"
+  topics = "marketplace sales filling"
 
 type
   SaleFilling* = ref object of ErrorHandlingState

codex/sales/states/finished.nim

@@ -7,7 +7,7 @@ import ./cancelled
 import ./failed
 
 logScope:
-    topics = "marketplace sales finished"
+  topics = "marketplace sales finished"
 
 type
   SaleFinished* = ref object of ErrorHandlingState

codex/sales/states/ignored.nim

@@ -5,7 +5,7 @@ import ../salesagent
 import ./errorhandling
 
 logScope:
-    topics = "marketplace sales ignored"
+  topics = "marketplace sales ignored"
 
 type
   SaleIgnored* = ref object of ErrorHandlingState

codex/sales/states/initialproving.nim

@@ -7,7 +7,7 @@ import ./cancelled
 import ./failed
 
 logScope:
-    topics = "marketplace sales initial-proving"
+  topics = "marketplace sales initial-proving"
 
 type
   SaleInitialProving* = ref object of ErrorHandlingState

codex/sales/states/payout.nim

@@ -8,7 +8,7 @@ import ./failed
 import ./finished
 
 logScope:
-    topics = "marketplace sales payout"
+  topics = "marketplace sales payout"
 
 type
   SalePayout* = ref object of ErrorHandlingState

codex/sales/states/preparing.nim

@@ -16,7 +16,7 @@ type
   SalePreparing* = ref object of ErrorHandlingState
 
 logScope:
-    topics = "marketplace sales preparing"
+  topics = "marketplace sales preparing"
 
 method `$`*(state: SalePreparing): string = "SalePreparing"
 

codex/sales/states/proving.nim

@@ -11,7 +11,7 @@ import ./errored
 import ./payout
 
 logScope:
-    topics = "marketplace sales proving"
+  topics = "marketplace sales proving"
 
 type
   SlotNotFilledError* = object of CatchableError

codex/sales/states/unknown.nim

@@ -9,7 +9,7 @@ import ./cancelled
 import ./payout
 
 logScope:
-    topics = "marketplace sales unknown"
+  topics = "marketplace sales unknown"
 
 type
   SaleUnknown* = ref object of SaleState

tests/codex/testpurchasing.nim

@@ -105,15 +105,15 @@ asyncchecksuite "Purchasing":
     let purchase = await purchasing.purchase(request)
     check eventually market.requested.len > 0
     let request = market.requested[0]
-    clock.set(request.expiry.truncate(int64))
+    clock.set(request.expiry.truncate(int64)+1)
     expect PurchaseTimeout:
       await purchase.wait()
 
   test "checks that funds were withdrawn when purchase times out":
     let purchase = await purchasing.purchase(request)
     check eventually market.requested.len > 0
     let request = market.requested[0]
-    clock.set(request.expiry.truncate(int64))
+    clock.set(request.expiry.truncate(int64)+1)
     expect PurchaseTimeout:
       await purchase.wait()
     check market.withdrawn == @[request.id]