A day's worth of debugging enhancements. Back to square one.
authorChristos KK Loverdos <loverdos@gmail.com>
Fri, 2 Mar 2012 16:08:04 +0000 (18:08 +0200)
committerChristos KK Loverdos <loverdos@gmail.com>
Fri, 2 Mar 2012 16:08:04 +0000 (18:08 +0200)
src/main/scala/gr/grnet/aquarium/logic/accounting/Accounting.scala
src/main/scala/gr/grnet/aquarium/user/UserStateComputations.scala
src/test/scala/gr/grnet/aquarium/user/UserStateComputationsTest.scala

index c628015..9db163d 100644 (file)
@@ -40,9 +40,9 @@ import dsl._
 import gr.grnet.aquarium.logic.events.{WalletEntry, ResourceEvent}
 import collection.immutable.SortedMap
 import java.util.Date
-import gr.grnet.aquarium.util.{CryptoUtils, Loggable}
 import com.ckkloverdos.maybe.{NoVal, Maybe, Failed, Just}
 import gr.grnet.aquarium.util.date.MutableDateCalc
+import gr.grnet.aquarium.util.{ContextualLogger, CryptoUtils, Loggable}
 
 /**
  * A timeslot together with the algorithm and unit price that apply for this particular timeslot.
@@ -98,11 +98,25 @@ trait Accounting extends DSLUtils with Loggable {
   def computeInitialChargeslots(referenceTimeslot: Timeslot,
                                 dslResource: DSLResource,
                                 policiesByTimeslot: Map[Timeslot, DSLPolicy],
-                                agreementNamesByTimeslot: Map[Timeslot, String]): Maybe[List[Chargeslot]] = Maybe {
+                                agreementNamesByTimeslot: Map[Timeslot, String],
+                                contextualLogger: Maybe[ContextualLogger] = NoVal): Maybe[List[Chargeslot]] = Maybe {
+
+    val clog = ContextualLogger.fromOther(contextualLogger, logger, "computeInitialChargeslots()")
 
     val policyTimeslots = policiesByTimeslot.keySet
     val agreementTimeslots = agreementNamesByTimeslot.keySet
 
+    clog.begin()
+
+    clog.debug("policiesByTimeslot:")
+    clog.withIndent {
+      policyTimeslots.foreach(pt ⇒ clog.debug("%s: %s", pt,  policyTimeslots(pt)))
+    }
+    clog.debug("agreementNamesByTimeslot:")
+    clog.withIndent {
+      agreementTimeslots.foreach(at ⇒ clog.debug("%s: %s", at, agreementNamesByTimeslot(at)))
+    }
+
     def getPolicy(ts: Timeslot): DSLPolicy = {
       policiesByTimeslot.find(_._1.contains(ts)).get._2
     }
@@ -112,10 +126,16 @@ trait Accounting extends DSLUtils with Loggable {
 
     // 1. Round ONE: split time according to overlapping policies and agreements.
     val alignedTimeslots = splitTimeslotByPoliciesAndAgreements(referenceTimeslot, policyTimeslots.toList, agreementTimeslots.toList)
+    clog.debug("ROUND 1: alignedTimeslots:")
+    clog.withIndent {
+      alignedTimeslots.foreach(ts ⇒ clog.debug("%s", ts))
+    }
 
     // 2. Round TWO: Use the aligned timeslots of Round ONE to produce even more
     //    fine-grained timeslots according to applicable algorithms.
     //    Then pack the info into charge slots.
+    clog.debug("ROUND 2")
+    clog.begin()
     val allChargeslots = for {
       alignedTimeslot <- alignedTimeslots
     } yield {
@@ -125,7 +145,9 @@ trait Accounting extends DSLUtils with Loggable {
 
       agreementOpt match {
         case None ⇒
-          throw new Exception("Unknown agreement %s during %s".format(agreementName, alignedTimeslot))
+          val errMsg = "Unknown agreement %s during %s".format(agreementName, alignedTimeslot)
+          clog.error("%s", errMsg)
+          throw new Exception(errMsg)
 
         case Some(agreement) ⇒
           // TODO: Factor this out, just like we did with:
@@ -147,6 +169,15 @@ trait Accounting extends DSLUtils with Loggable {
             val dslPricelist = pricelistByTimeslot(finegrainedTimeslot) // TODO: is this correct?
             val algorithmDefOpt = dslAlgorithm.algorithms.get(dslResource)
             val priceUnitOpt = dslPricelist.prices.get(dslResource)
+
+            clog.debug("%s:", finegrainedTimeslot)
+            clog.withIndent {
+              clog.debug("dslAlgorithm = %s", dslAlgorithm)
+              clog.debug("dslPricelist = %s", dslPricelist)
+              clog.debug("algorithmDefOpt = %s", algorithmDefOpt)
+              clog.debug("priceUnitOpt = %s", priceUnitOpt)
+            }
+
             (algorithmDefOpt, priceUnitOpt) match {
               case (None, None) ⇒
                 throw new Exception(
@@ -169,6 +200,9 @@ trait Accounting extends DSLUtils with Loggable {
       }
     }
 
+    clog.end()
+    clog.end()
+
     allChargeslots.flatten
   }
 
@@ -184,7 +218,11 @@ trait Accounting extends DSLUtils with Loggable {
                              dslResource: DSLResource,
                              defaultResourceMap: DSLResourcesMap,
                              agreementNamesByTimeslot: Map[Timeslot, String],
-                             algorithmCompiler: CostPolicyAlgorithmCompiler): Maybe[List[Chargeslot]] = Maybe {
+                             algorithmCompiler: CostPolicyAlgorithmCompiler,
+                             contextualLogger: Maybe[ContextualLogger] = NoVal): Maybe[List[Chargeslot]] = Maybe {
+
+    val clog = ContextualLogger.fromOther(contextualLogger, logger, "computeFullChargeslots()")
+    clog.begin()
 
     val occurredDate = currentResourceEvent.occurredDate
     val costPolicy = dslResource.costPolicy
@@ -195,8 +233,9 @@ trait Accounting extends DSLUtils with Loggable {
         previousResourceEventM match {
           // We have a previous event
           case Just(previousResourceEvent) ⇒
+            clog.debug("Have previous event")
             val referenceTimeslot = Timeslot(previousResourceEvent.occurredDate, occurredDate)
-            println("referenceTimeslot = %s".format(referenceTimeslot.toISODateString))
+
             // all policies within the interval from previous to current resource event
             val relevantPolicies = Policy.policies(referenceTimeslot)
 
@@ -219,18 +258,23 @@ trait Accounting extends DSLUtils with Loggable {
       case false ⇒
         // ... so we cannot compute timedelta from a previous event, there is just one chargeslot
         // referring to (almost) an instant in time
+        clog.debug("DO NOT have previous event")
         val referenceTimeslot = Timeslot(new MutableDateCalc(occurredDate).goPreviousMilli.toDate, occurredDate)
         val relevantPolicy = Policy.policy(occurredDate)
         val relevantPolicies = Map(referenceTimeslot -> relevantPolicy)
 
         (referenceTimeslot, relevantPolicies, costPolicy.getResourceInstanceUndefinedAmount)
     }
+    clog.debug("referenceTimeslot = %s".format(referenceTimeslot))
+    clog.debug("relevantPolicies = %s".format(relevantPolicies))
+    clog.debug("previousValue = %s".format(previousValue))
 
     val initialChargeslotsM = computeInitialChargeslots(
       referenceTimeslot,
       dslResource,
       relevantPolicies,
-      agreementNamesByTimeslot
+      agreementNamesByTimeslot,
+      Just(clog)
     )
     
     val fullChargeslotsM = initialChargeslotsM.map { chargeslots ⇒
@@ -275,6 +319,8 @@ trait Accounting extends DSLUtils with Loggable {
       }
     }
 
+    clog.end()
+
     fullChargeslotsM match {
       case Just(fullChargeslots) ⇒
         fullChargeslots
index 9fee278..56d7888 100644 (file)
@@ -132,7 +132,8 @@ class UserStateComputations extends Loggable {
 
     if(billingMonthStopMillis < userCreationMillis) {
       // If the user did not exist for this billing month, piece of cake
-      clog.debug("User did not exist before %s. Returning %s", userCreationDateCalc, zeroUserState)
+      clog.debug("User did not exist before %s", userCreationDateCalc)
+      clog.debug("Returning %s".format(zeroUserState))
       clog.endWith(Just(zeroUserState))
     } else {
       // Ask DB cache for the latest known user state for this billing period
@@ -207,6 +208,10 @@ class UserStateComputations extends Loggable {
                            accounting: Accounting,
                            contextualLogger: Maybe[ContextualLogger] = NoVal): Maybe[UserState] = Maybe {
 
+    def rcDebugInfo(rcEvent: ResourceEvent) = {
+      rcEvent.toDebugString(defaultResourcesMap, false)
+    }
+
     val clog = ContextualLogger.fromOther(
       contextualLogger,
       logger,
@@ -252,7 +257,12 @@ class UserStateComputations extends Loggable {
 
         // Prepare the implicitly terminated resource events from previous billing period
         val implicitlyTerminatedResourceEvents = _workingUserState.implicitlyTerminatedSnapshot.toMutableWorker
-        clog.debug("implicitlyTerminatedResourceEvents = %s", implicitlyTerminatedResourceEvents)
+        if(implicitlyTerminatedResourceEvents.size > 0) {
+          clog.debug("%s implicitlyTerminatedResourceEvents", implicitlyTerminatedResourceEvents.size)
+          clog.withIndent {
+            implicitlyTerminatedResourceEvents.foreach(ev ⇒ clog.debug("%s", rcDebugInfo(ev)))
+          }
+        }
 
         // Keep the resource events from this period that were first (and unused) of their kind
         val ignoredFirstResourceEvents = IgnoredFirstResourceEventsWorker.Empty
@@ -287,10 +297,6 @@ class UserStateComputations extends Loggable {
           }
         }
 
-        def rcDebugInfo(rcEvent: ResourceEvent) = {
-          rcEvent.toDebugString(defaultResourcesMap, false)
-        }
-
         // Find the actual resource events from DB
         val allResourceEventsForMonth = resourceEventStore.findAllRelevantResourceEventsForBillingPeriod(
           userId,
@@ -375,7 +381,7 @@ class UserStateComputations extends Loggable {
                     // A. Compute new resource instance accumulating amount
                     val newAmount = costPolicy.computeNewAccumulatingAmount(oldAmount, theValue)
                     
-                    clog.debug("oldAmount = %s, newAmount = %s, oldCredits = %s", oldAmount, newAmount, oldCredits)
+                    clog.debug("theValue = %s, oldAmount = %s, newAmount = %s, oldCredits = %s", theValue, oldAmount, newAmount, oldCredits)
 
                     // B. Compute new wallet entries
                     val alltimeAgreements = _workingUserState.agreementsSnapshot.agreementsByTimeslot
@@ -389,7 +395,8 @@ class UserStateComputations extends Loggable {
                       resourceDef,
                       defaultResourcesMap,
                       alltimeAgreements,
-                      SimpleCostPolicyAlgorithmCompiler
+                      SimpleCostPolicyAlgorithmCompiler,
+                      Just(clog)
                     )
 
                     // We have the chargeslots, let's associate them with the current event
index 0927a86..0254815 100644 (file)
@@ -6,71 +6,118 @@ import gr.grnet.aquarium.store.memory.MemStore
 import gr.grnet.aquarium.util.date.MutableDateCalc
 import gr.grnet.aquarium.logic.accounting.dsl._
 import java.util.Date
-import gr.grnet.aquarium.logic.accounting.Accounting
-import com.ckkloverdos.maybe.NoVal
 import simulation.{ConcurrentVMLocalUIDGenerator, ClientServiceSim, UserSim}
+import gr.grnet.aquarium.logic.accounting.{Policy, Accounting}
+import gr.grnet.aquarium.util.{Loggable, ContextualLogger}
+import com.ckkloverdos.maybe.{Just, NoVal}
 
 
 /**
  *
  * @author Christos KK Loverdos <loverdos@gmail.com>
  */
-class UserStateComputationsTest {
+class UserStateComputationsTest extends Loggable {
+  val PolicyYAML = """
+aquariumpolicy:
+  resources:
+    - resource:
+      name: bandwidth
+      unit: MB/hr
+      complex: false
+      costpolicy: discrete
+    - resource:
+      name: vmtime
+      unit: Hour
+      complex: true
+      costpolicy: onoff
+      descriminatorfield: vmid
+    - resource:
+      name: diskspace
+      unit: MB/hr
+      complex: false
+      costpolicy: continuous
+
+  implicitvars:
+    - price
+    - volume
+
+  algorithms:
+    - algorithm:
+      name: default
+      bandwidth: $price times $volume
+      vmtime: $price times $volume
+      diskspace: $price times $volume
+      effective:
+        from: 0
+
+  pricelists:
+    - pricelist:
+      name: default
+      bandwidth: 1.0
+      vmtime: 1.0
+      diskspace: 1.0
+      effective:
+        from: 0
+
+  creditplans:
+    - creditplan:
+      name: default
+      credits: 100
+      at: "00 00 1 * *"
+      effective:
+        from: 0
+
+  agreements:
+    - agreement:
+      name: default
+      algorithm: default
+      pricelist: default
+      creditplan: default
+  """
+
+  val DefaultPolicy = new DSL{}.parse(PolicyYAML)
+
+  // TODO: integrate this with the rest of the simulation stuff
+  // TODO: since, right now, the resource strings have to be given twice
+  val VMTimeResource    = DSLComplexResource("vmtime",    "Hr",    OnOffCostPolicy,      "")
+  val DiskspaceResource = DSLComplexResource("diskspace", "MB/Hr", ContinuousCostPolicy, "")
+  val BandwidthResource = DSLComplexResource("bandwidth", "MB/Hr", DiscreteCostPolicy,   "")
+  val DefaultResourcesMap = new DSLResourcesMap(VMTimeResource :: DiskspaceResource :: BandwidthResource :: Nil)
+
+  // There are two client services, synnefo and pithos.
+  val TheUIDGenerator = new ConcurrentVMLocalUIDGenerator
+  val Synnefo = ClientServiceSim("synnefo")(TheUIDGenerator)
+  val Pithos  = ClientServiceSim("pithos")(TheUIDGenerator)
+
   @Test
   def testOne: Unit = {
+    val clog = ContextualLogger.fromOther(NoVal, logger, "testOne()")
     val StartOfBillingYearDateCalc = new MutableDateCalc(2012, 1, 1)
 //    println("StartOfBillingYearDateCalc = %s".format(StartOfBillingYearDateCalc))
     val UserCreationDateCalc = StartOfBillingYearDateCalc.copy.goMinusMonths(2)
 //    println("UserCreationDateCalc = %s".format(UserCreationDateCalc))
 
-    // TODO: integrate this with the rest of the simulation stuff
-    // TODO: since, right now, the resource strings have to be given twice
-    val VMTIME_RESOURCE    = DSLComplexResource("vmtime",    "Hr",    OnOffCostPolicy,      "")
-    val DISKSPACE_RESOURCE = DSLComplexResource("diskspace", "MB/Hr", ContinuousCostPolicy, "")
-    val BANDWIDTH_RESOURCE = DSLComplexResource("bandwidth", "MB/Hr", DiscreteCostPolicy,   "")
-
-    val DEFAULT_RESOURCES_MAP = new DSLResourcesMap(VMTIME_RESOURCE :: DISKSPACE_RESOURCE :: BANDWIDTH_RESOURCE :: Nil)
-
-    val FOR_EVER = DSLTimeFrame(new Date(0), None, Nil)
-    val THE_PRICES_MAP: Map[DSLResource, Double] = Map(VMTIME_RESOURCE -> 1.0, DISKSPACE_RESOURCE -> 1.0)
-
-    val THE_PRICE_LIST  = DSLPriceList("default", None, THE_PRICES_MAP, FOR_EVER)
-    val THE_CREDIT_PLAN = DSLCreditPlan("default", None, 100, Nil, "", FOR_EVER)
-    val THE_ALGORITHM   = DSLAlgorithm("default", None, Map(), FOR_EVER)
-    val THE_AGREEMENT   = DSLAgreement("default", None, THE_ALGORITHM, THE_PRICE_LIST, THE_CREDIT_PLAN)
-
-    val THE_RESOURCES = DEFAULT_RESOURCES_MAP.toResourcesList
-
-    val DEFAULT_POLICY = DSLPolicy(
-      Nil,
-      THE_PRICE_LIST :: Nil,
-      THE_RESOURCES,
-      THE_CREDIT_PLAN :: Nil,
-      THE_AGREEMENT :: Nil
-    )
-
     val computer = new UserStateComputations
 
     val mc = Configurator.MasterConfigurator.withStoreProviderClass(classOf[MemStore])
+    Policy.withConfigurator(mc)
+
     val storeProvider = mc.storeProvider
     val userStateStore = storeProvider.userStateStore
     val resourceEventStore = storeProvider.resourceEventStore
     val policyStore = storeProvider.policyStore
 
-    // A new user is created on 2012-01-15 00:00:00.000
-    val christos  = UserSim("Christos", UserCreationDateCalc.toDate, storeProvider.resourceEventStore)
+    policyStore.storePolicyEntry(DefaultPolicy.toPolicyEntry)
 
-    // There are two client services, synnefo and pithos.
-    val uidGenerator = new ConcurrentVMLocalUIDGenerator
-    val synnefo = ClientServiceSim("synnefo")(uidGenerator)
-    val pithos  = ClientServiceSim("pithos")(uidGenerator)
+    // A new user is created on 2012-01-15 00:00:00.000
+    val UserCKKL  = UserSim("CKKL", UserCreationDateCalc.toDate, storeProvider.resourceEventStore)
 
     // By convention
     // - synnefo is for VMTime and Bandwidth
     // - pithos is for Diskspace
-    val vm        = synnefo.newVMTime   (christos, "VM.1")
-    val bandwidth = synnefo.newBandwidth(christos, "3G.1")
-    val disk      = pithos .newDiskspace(christos, "DISK.1")
+    val VMTimeInstance    = Synnefo.newVMTime   (UserCKKL, "VM.1")
+    val BandwidthInstance = Synnefo.newBandwidth(UserCKKL, "3G.1")
+    val DiskInstance      = Pithos .newDiskspace(UserCKKL, "DISK.1")
 
     // Let's create our dates of interest
     val vmStartDateCalc = StartOfBillingYearDateCalc.copy.goPlusDays(1).goPlusHours(1)
@@ -79,7 +126,7 @@ class UserStateComputationsTest {
     val vmStartDate = vmStartDateCalc.toDate
 
     // Within January, create one VM ON-OFF ...
-    val onOff1_M = vm.newONOFF(vmStartDate, 9)
+    val onOff1_M = VMTimeInstance.newONOFF(vmStartDate, 9)
 
     val diskConsumptionDateCalc = StartOfBillingYearDateCalc.copy.goPlusHours(3)
     // 2012-01-16 04:00:00.000
@@ -89,16 +136,16 @@ class UserStateComputationsTest {
     val diskConsumptionDate2 = diskConsumptionDateCalc2.toDate
 
     // ... and two diskspace changes
-    val consume1_M = disk.consumeMB(diskConsumptionDate1, 99)
-    val consume2_M = disk.consumeMB(diskConsumptionDate2, 23)
+    val consume1_M = DiskInstance.consumeMB(diskConsumptionDate1, 99)
+    val consume2_M = DiskInstance.consumeMB(diskConsumptionDate2, 23)
 
     // 100MB 3G bandwidth
     val bwDateCalc = diskConsumptionDateCalc2.copy.goPlusDays(1)
-    bandwidth.useBandwidth(bwDateCalc.toDate, 100.0)
+    BandwidthInstance.useBandwidth(bwDateCalc.toDate, 100.0)
 
     // ... and one "future" event
     // 2012-02-07 07:07:07.007
-    disk.consumeMB(
+    DiskInstance.consumeMB(
       StartOfBillingYearDateCalc.copy.
         goNextMonth.goPlusDays(6).
         goPlusHours(7).
@@ -107,34 +154,36 @@ class UserStateComputationsTest {
         goPlusMillis(7).toDate,
       777)
 
-    println("")
-    println("============================= Events by OccurredMillis =============================")
-    for {
-      event <- christos.myResourceEventsByOccurredDate
-    } {
-      println(event.toDebugString(DEFAULT_RESOURCES_MAP, false))
+    clog.debug("")
+    clog.debug("=== Events by OccurredMillis ===")
+    clog.withIndent {
+      for(event <- UserCKKL.myResourceEventsByOccurredDate) {
+        clog.debug(event.toDebugString(DefaultResourcesMap))
+      }
     }
-    println("============================= Events by OccurredMillis =============================")
-    println("")
+    clog.debug("=== Events by OccurredMillis ===")
+    clog.debug("")
 
     val billingMonthInfo = BillingMonthInfo.fromDateCalc(StartOfBillingYearDateCalc)
 
     val userStateM = computer.doFullMonthlyBilling(
-      christos.userId,
+      UserCKKL.userId,
       billingMonthInfo,
       userStateStore,
       resourceEventStore,
       policyStore,
-      christos.userCreationDate.getTime,
-      computer.createFirstUserState(christos.userId),
-      computer.createFirstUserState(christos.userId),
-      DEFAULT_POLICY,
-      DEFAULT_RESOURCES_MAP,
-      new Accounting{}
+      UserCKKL.userCreationDate.getTime,
+      computer.createFirstUserState(UserCKKL.userId),
+      computer.createFirstUserState(UserCKKL.userId),
+      DefaultPolicy,
+      DefaultResourcesMap,
+      new Accounting{},
+      Just(clog)
     )
     
-    println("!! userStateM = %s".format(userStateM))
+    clog.debug("userStateM = %s".format(userStateM))
     userStateM.forFailed { failed ⇒
+      clog.error(failed)
       failed.exception.printStackTrace()
       NoVal
     }