From: Christos KK Loverdos Date: Fri, 2 Mar 2012 16:08:04 +0000 (+0200) Subject: A day's worth of debugging enhancements. Back to square one. X-Git-Url: https://code.grnet.gr/git/aquarium/commitdiff_plain/d49ca08f91f91a9fd554dcd367a321016cee7d75 A day's worth of debugging enhancements. Back to square one. --- diff --git a/src/main/scala/gr/grnet/aquarium/logic/accounting/Accounting.scala b/src/main/scala/gr/grnet/aquarium/logic/accounting/Accounting.scala index c628015..9db163d 100644 --- a/src/main/scala/gr/grnet/aquarium/logic/accounting/Accounting.scala +++ b/src/main/scala/gr/grnet/aquarium/logic/accounting/Accounting.scala @@ -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 diff --git a/src/main/scala/gr/grnet/aquarium/user/UserStateComputations.scala b/src/main/scala/gr/grnet/aquarium/user/UserStateComputations.scala index 9fee278..56d7888 100644 --- a/src/main/scala/gr/grnet/aquarium/user/UserStateComputations.scala +++ b/src/main/scala/gr/grnet/aquarium/user/UserStateComputations.scala @@ -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 diff --git a/src/test/scala/gr/grnet/aquarium/user/UserStateComputationsTest.scala b/src/test/scala/gr/grnet/aquarium/user/UserStateComputationsTest.scala index 0927a86..0254815 100644 --- a/src/test/scala/gr/grnet/aquarium/user/UserStateComputationsTest.scala +++ b/src/test/scala/gr/grnet/aquarium/user/UserStateComputationsTest.scala @@ -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 */ -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 }