code.grnet.gr Git - aquarium/blob - src/main/scala/gr/grnet/aquarium/util/ContextualLogger.scala

   1 /*
   2  * Copyright 2011-2012 GRNET S.A. All rights reserved.
   3  *
   4  * Redistribution and use in source and binary forms, with or
   5  * without modification, are permitted provided that the following
   6  * conditions are met:
   7  *
   8  *   1. Redistributions of source code must retain the above
   9  *      copyright notice, this list of conditions and the following
  10  *      disclaimer.
  11  *
  12  *   2. Redistributions in binary form must reproduce the above
  13  *      copyright notice, this list of conditions and the following
  14  *      disclaimer in the documentation and/or other materials
  15  *      provided with the distribution.
  16  *
  17  * THIS SOFTWARE IS PROVIDED BY GRNET S.A. ``AS IS'' AND ANY EXPRESS
  18  * OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED
  19  * WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR
  20  * PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL GRNET S.A OR
  21  * CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
  22  * SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
  23  * LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF
  24  * USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED
  25  * AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
  26  * LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN
  27  * ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE
  28  * POSSIBILITY OF SUCH DAMAGE.
  29  *
  30  * The views and conclusions contained in the software and
  31  * documentation are those of the authors and should not be
  32  * interpreted as representing official policies, either expressed
  33  * or implied, of GRNET S.A.
  34  */
  35
  36 package gr.grnet.aquarium.util
  37
  38 import org.slf4j.Logger
  39 import com.ckkloverdos.maybe.Failed
  40
  41 /**
  42  * A logger that keeps track of working context and indentation level.
  43  *
  44  * This is mostly useful in single-threaded debugging sessions.
  45   *
  46   * A sample output follows:
  47   *
  48   * {{{
  49 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -                          testOrphanOFF() BEGIN
  50 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -                          testOrphanOFF()
  51 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -                          testOrphanOFF()   +++ [Events by OccurredMillis] +++
  52 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -                          testOrphanOFF()       EVENT(0, [2012-01-01 00:00:00], 0.0, vmtime::VM.1, Map(), CKKL, synnefo)
  53 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -                          testOrphanOFF()   --- [Events by OccurredMillis] ---
  54 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -                          testOrphanOFF()
  55 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -            doFullMonthBilling(2012-01)   BEGIN
  56 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest - …ndUserStateAtEndOfBillingMonth(2011-12)     BEGIN
  57 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest - …ndUserStateAtEndOfBillingMonth(2011-12)       No user state found from cache, will have to (re)compute
  58 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -            doFullMonthBilling(2011-12)       BEGIN
  59 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest - …ndUserStateAtEndOfBillingMonth(2011-11)         BEGIN
  60 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest - …ndUserStateAtEndOfBillingMonth(2011-11)           No user state found from cache, will have to (re)compute
  61 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -            doFullMonthBilling(2011-11)           BEGIN
  62 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest - …ndUserStateAtEndOfBillingMonth(2011-10)             BEGIN
  63 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest - …ndUserStateAtEndOfBillingMonth(2011-10)               User did not exist before 2011-11-01 00:00:00.000
  64 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest - …ndUserStateAtEndOfBillingMonth(2011-10)               Returning INITIAL state [_id=4fa7e12ba0eee3db73fbe8d0] UserState(true,CKKL,1320098400000,0,false,null,ImplicitlyIssuedResourceEventsSnapshot(List()),List(),List(),LatestResourceEventsSnapshot(List()),0,0,IMStateSnapshot(StdIMEvent(,1320098400000,1320098400000,CKKL,,true,user,1.0,create,Map())),CreditSnapshot(0.0),AgreementHistory(List(AgreementHistoryItem(default, 2011-11-01 00:00:00.000, 292278994-08-17 07:12:55.807))),OwnedResourcesSnapshot(List()),List(),1320098400000,InitialUserStateSetup,0,None,4fa7e12ba0eee3db73fbe8d0)
  65 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest - …ndUserStateAtEndOfBillingMonth(2011-10)             END
  66 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -            doFullMonthBilling(2011-11)             calculationReason = MonthlyBillingCalculation(2011-11)
  67 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -            doFullMonthBilling(2011-11)             Saved [_id=4fa7e12ba0eee3db73fbe8d0] UserState(true,CKKL,1320098400000,1,false,null,ImplicitlyIssuedResourceEventsSnapshot(List()),List(),List(),LatestResourceEventsSnapshot(List()),0,0,IMStateSnapshot(StdIMEvent(,1320098400000,1320098400000,CKKL,,true,user,1.0,create,Map())),CreditSnapshot(0.0),AgreementHistory(List(AgreementHistoryItem(default, 2011-11-01 00:00:00.000, 292278994-08-17 07:12:55.807))),OwnedResourcesSnapshot(List()),List(),1320098400000,MonthlyBillingCalculation(2011-11),0,Some(4fa7e12ba0eee3db73fbe8d0),4fa7e12ba0eee3db73fbe8d0)
  68 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -            doFullMonthBilling(2011-11)             RETURN UserState(true,CKKL,1320098400000,1,false,null,ImplicitlyIssuedResourceEventsSnapshot(List()),List(),List(),LatestResourceEventsSnapshot(List()),0,0,IMStateSnapshot(StdIMEvent(,1320098400000,1320098400000,CKKL,,true,user,1.0,create,Map())),CreditSnapshot(0.0),AgreementHistory(List(AgreementHistoryItem(default, 2011-11-01 00:00:00.000, 292278994-08-17 07:12:55.807))),OwnedResourcesSnapshot(List()),List(),1320098400000,MonthlyBillingCalculation(2011-11),0,Some(4fa7e12ba0eee3db73fbe8d0),4fa7e12ba0eee3db73fbe8d0)
  69 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -            doFullMonthBilling(2011-11)           END
  70 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest - …ndUserStateAtEndOfBillingMonth(2011-11)         END
  71 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -            doFullMonthBilling(2011-12)         calculationReason = MonthlyBillingCalculation(2011-12)
  72 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -            doFullMonthBilling(2011-12)         Saved [_id=4fa7e12ba0eee3db73fbe8d0] UserState(true,CKKL,1320098400000,2,false,null,ImplicitlyIssuedResourceEventsSnapshot(List()),List(),List(),LatestResourceEventsSnapshot(List()),0,0,IMStateSnapshot(StdIMEvent(,1320098400000,1320098400000,CKKL,,true,user,1.0,create,Map())),CreditSnapshot(0.0),AgreementHistory(List(AgreementHistoryItem(default, 2011-11-01 00:00:00.000, 292278994-08-17 07:12:55.807))),OwnedResourcesSnapshot(List()),List(),1320098400000,MonthlyBillingCalculation(2011-12),0,Some(4fa7e12ba0eee3db73fbe8d0),4fa7e12ba0eee3db73fbe8d0)
  73 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -            doFullMonthBilling(2011-12)         RETURN UserState(true,CKKL,1320098400000,2,false,null,ImplicitlyIssuedResourceEventsSnapshot(List()),List(),List(),LatestResourceEventsSnapshot(List()),0,0,IMStateSnapshot(StdIMEvent(,1320098400000,1320098400000,CKKL,,true,user,1.0,create,Map())),CreditSnapshot(0.0),AgreementHistory(List(AgreementHistoryItem(default, 2011-11-01 00:00:00.000, 292278994-08-17 07:12:55.807))),OwnedResourcesSnapshot(List()),List(),1320098400000,MonthlyBillingCalculation(2011-12),0,Some(4fa7e12ba0eee3db73fbe8d0),4fa7e12ba0eee3db73fbe8d0)
  74 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -            doFullMonthBilling(2011-12)       END
  75 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest - …ndUserStateAtEndOfBillingMonth(2011-12)     END
  76 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -         walletEntriesForResourceEvent(0)     +++ [EVENT(0, [2012-01-01 00:00:00], 0.0, vmtime::VM.1, Map(), CKKL, synnefo)] +++
  77 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -         walletEntriesForResourceEvent(0)       Cost policy OnOffCostPolicy for DSLResource(vmtime,Hr,OnOffCostPolicy,true,instanceId)
  78 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -         walletEntriesForResourceEvent(0)       PreviousM None
  79 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -         walletEntriesForResourceEvent(0)       Ignoring first event of its kind EVENT(0, [2012-01-01 00:00:00], 0.0, vmtime::VM.1, Map(), CKKL, synnefo)
  80 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -         walletEntriesForResourceEvent(0)     --- [EVENT(0, [2012-01-01 00:00:00], 0.0, vmtime::VM.1, Map(), CKKL, synnefo)] ---
  81 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -            doFullMonthBilling(2012-01)     calculationReason = MonthlyBillingCalculation(2012-01)
  82 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -            doFullMonthBilling(2012-01)     Saved [_id=4fa7e12ba0eee3db73fbe8d0] UserState(true,CKKL,1320098400000,3,false,null,ImplicitlyIssuedResourceEventsSnapshot(List()),List(),List(),LatestResourceEventsSnapshot(List(StdResourceEvent(0,1325368800000,1325368800000,CKKL,synnefo,vmtime,VM.1,0.0,1.0,Map()))),0,0,IMStateSnapshot(StdIMEvent(,1320098400000,1320098400000,CKKL,,true,user,1.0,create,Map())),CreditSnapshot(0.0),AgreementHistory(List(AgreementHistoryItem(default, 2011-11-01 00:00:00.000, 292278994-08-17 07:12:55.807))),OwnedResourcesSnapshot(List()),List(),1320098400000,MonthlyBillingCalculation(2012-01),0,Some(4fa7e12ba0eee3db73fbe8d0),4fa7e12ba0eee3db73fbe8d0)
  83 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -            doFullMonthBilling(2012-01)     RETURN UserState(true,CKKL,1320098400000,3,false,null,ImplicitlyIssuedResourceEventsSnapshot(List()),List(),List(),LatestResourceEventsSnapshot(List(StdResourceEvent(0,1325368800000,1325368800000,CKKL,synnefo,vmtime,VM.1,0.0,1.0,Map()))),0,0,IMStateSnapshot(StdIMEvent(,1320098400000,1320098400000,CKKL,,true,user,1.0,create,Map())),CreditSnapshot(0.0),AgreementHistory(List(AgreementHistoryItem(default, 2011-11-01 00:00:00.000, 292278994-08-17 07:12:55.807))),OwnedResourcesSnapshot(List()),List(),1320098400000,MonthlyBillingCalculation(2012-01),0,Some(4fa7e12ba0eee3db73fbe8d0),4fa7e12ba0eee3db73fbe8d0)
  84 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -            doFullMonthBilling(2012-01)   END
  85 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -                          testOrphanOFF()   _id = 4fa7e12ba0eee3db73fbe8d0
  86 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -                          testOrphanOFF()   parentId = Some(4fa7e12ba0eee3db73fbe8d0)
  87 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -                          testOrphanOFF()   credits = 0.0
  88 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -                          testOrphanOFF()   changeReason = MonthlyBillingCalculation(2012-01)
  89 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -                          testOrphanOFF()   implicitlyIssued [#=0] = List()
  90 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -                          testOrphanOFF()   latestResourceEvents [#=1]:
  91 DEBUG 17:50:19 g.g.a.user.UserStateComputationsTest -                          testOrphanOFF()     EVENT(0, [2012-01-01 00:00:00], 0.0, vmtime::VM.1, Map(), CKKL, synnefo)
  92 DEBUG 17:50:20 g.g.a.user.UserStateComputationsTest -                          testOrphanOFF()   newWalletEntries [#=0] = List()
  93  * }}}
  94  *
  95  * @author Christos KK Loverdos <loverdos@gmail.com>
  96  */
  97 final class ContextualLogger(val logger: Logger, fmt: String, args: Any*) {
  98   val ctx = ContextualLogger.fixCtx(fmt.format(args:_*))
  99
 100   private[this] var _nesting = 0
 101
 102   private def nestMsg(fmt: String, args: Any*) = {
 103     val msg = fmt.format(args: _*)
 104     _nesting match {
 105       case 0 ⇒
 106         msg
 107       case n ⇒
 108         val buffer = new java.lang.StringBuilder(n + msg.size)
 109         var _i = 0
 110         while(_i < (n * 2)) {
 111           buffer.append(' ')
 112           _i = _i + 1
 113         }
 114         buffer.append(msg)
 115         buffer.toString
 116     }
 117   }
 118
 119   def isDebugEnabled = logger.isDebugEnabled
 120
 121   def nesting = _nesting
 122
 123   def indentAs(other: ContextualLogger): this.type = {
 124     _nesting = other.nesting
 125     this
 126   }
 127
 128   def indent(): this.type   = {
 129     _nesting = _nesting + 1
 130     this
 131   }
 132
 133   def unindent(): this.type = {
 134     _nesting = _nesting - 1
 135     this
 136   }
 137
 138   def withIndent[A](f: => A): Unit = {
 139     import com.ckkloverdos.maybe.effect
 140     this.indent()
 141     effect(f){}{unindent()}
 142   }
 143
 144   def debug(fmt: String, args: Any*): Unit = {
 145     if(logger.isDebugEnabled) {
 146       val msg = ctx + " " + nestMsg(fmt, args:_*)
 147       logger.debug(msg)
 148     }
 149   }
 150
 151   def info(fmt: String, args: Any*): Unit = {
 152     if(logger.isInfoEnabled) {
 153       val msg = ctx + " " + nestMsg(fmt, args:_*)
 154       logger.info(msg)
 155     }
 156   }
 157
 158   def warn(fmt: String, args: Any*): Unit = {
 159     if(logger.isWarnEnabled) {
 160       val msg = ctx + " " + nestMsg(fmt, args:_*)
 161       logger.warn(msg)
 162     }
 163   }
 164
 165   def error(fmt: String, args: Any*): Unit = {
 166     if(logger.isErrorEnabled) {
 167       val msg = ctx + " " + nestMsg(fmt, args:_*)
 168       logger.error(msg)
 169     }
 170   }
 171
 172   def error(t: Throwable, fmt: String, args: Any*): Unit = {
 173     if(logger.isErrorEnabled) {
 174       val msg = ctx + " " + nestMsg(fmt, args:_*)
 175       logger.error(msg, t)
 176     }
 177   }
 178
 179   def error(failed: Failed): Unit = {
 180     this.error(failed.exception, "")
 181   }
 182
 183   def begin(message: String = ""): Unit = {
 184     if(message == "") debug("BEGIN") else debug("+++ [%s] +++", message)
 185     indent()
 186   }
 187
 188   def end(message: String = ""): Unit = {
 189     unindent()
 190     if(message == "") debug("END") else debug("--- [%s] ---", message)
 191   }
 192
 193   def debugMap[K, V](name: String, map: scala.collection.Map[K, V], oneLineLimit: Int = 3): Unit = {
 194     if(this.isDebugEnabled) {
 195       val mapSize = map.size
 196       if(mapSize <= oneLineLimit) {
 197         this.debug("%s [#=%s] = %s", name, mapSize, map)
 198       } else {
 199         this.debug("%s [#=%s]:", name, mapSize)
 200         val maxKeySize = maxStringSize(map.keySet)
 201         this.withIndent {
 202           for((k, v) <- map) {
 203             this.debug("%s -> %s", rpad(k.toString, maxKeySize), v)
 204           }
 205         }
 206       }
 207     }
 208   }
 209
 210   def debugSeq[T](name: String, seq: scala.collection.Seq[T], oneLineLimit: Int = 3): Unit = {
 211     if(this.isDebugEnabled) {
 212       val seqSize = seq.size
 213       if(seqSize <= oneLineLimit) {
 214         this.debug("%s [#=%s] = %s", name, seqSize, seq)
 215       } else {
 216         this.debug("%s [#=%s]: ", name, seqSize)
 217         this.withIndent(seq.foreach(this.debug("%s", _)))
 218       }
 219     }
 220   }
 221
 222   def debugSet[T](name: String, set: scala.collection.Set[T], oneLineLimit: Int = 3): Unit = {
 223     if(this.isDebugEnabled) {
 224       val setSize = set.size
 225       if(setSize <= oneLineLimit) {
 226         this.debug("%s [#=%s] = %s", name, setSize, set)
 227       } else {
 228         this.debug("%s [#=%s]: ", name, setSize)
 229         this.withIndent(set.foreach(this.debug("%s", _)))
 230       }
 231     }
 232   }
 233 }
 234
 235 /**
 236  * Companion object of [[gr.grnet.aquarium.util.ContextualLogger]].
 237  *
 238  * @author Christos KK Loverdos <loverdos@gmail.com>
 239  */
 240 object ContextualLogger {
 241   final val MaxCtxLength = 40
 242   final val ELLIPSIS = "…" // U+2026
 243
 244   def fixCtx(ctx: String): String = {
 245     val ctxLen = ctx.length()
 246     if(ctxLen == MaxCtxLength) {
 247       ctx
 248     } else if(ctxLen > MaxCtxLength) {
 249       ELLIPSIS + ctx.substring(ctxLen - MaxCtxLength + 1, ctxLen)
 250     } else {
 251       val buffer = new java.lang.StringBuilder(MaxCtxLength)
 252       val prefixLen = MaxCtxLength - ctxLen
 253       var _i = 0
 254       while(_i < prefixLen) {
 255         buffer.append(' ')
 256         _i = _i + 1
 257       }
 258       buffer.append(ctx)
 259       buffer.toString
 260     }
 261   }
 262
 263   def fromOther(clogOpt: Option[ContextualLogger], logger: Logger,  fmt: String, args: Any*): ContextualLogger = {
 264     clogOpt match {
 265       case Some(clog) ⇒
 266         new ContextualLogger(clog.logger, fmt, args:_*).indentAs(clog)
 267
 268       case None ⇒
 269         new ContextualLogger(logger, fmt, args:_*)
 270     }
 271   }
 272 }