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, Just, Maybe}
  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] 2012-02-13 12:54:53,653 main -                 doFullMonthlyBilling(2012-01) BEGIN
  50  [DEBUG] 2012-02-13 12:54:53,653 main -     findUserStateAtEndOfBillingMonth(2011-12)   BEGIN
  51  [DEBUG] 2012-02-13 12:54:53,661 main -     findUserStateAtEndOfBillingMonth(2011-12)     Found 0 out of sync events, will have to (re)compute user state
  52  [DEBUG] 2012-02-13 12:54:53,661 main -     findUserStateAtEndOfBillingMonth(2011-12)     Computing full month billing
  53  [DEBUG] 2012-02-13 12:54:53,662 main -                 doFullMonthlyBilling(2011-12)     BEGIN
  54  [DEBUG] 2012-02-13 12:54:53,662 main -     findUserStateAtEndOfBillingMonth(2011-11)       BEGIN
  55  [DEBUG] 2012-02-13 12:54:53,663 main -     findUserStateAtEndOfBillingMonth(2011-11)         Found 0 out of sync events, will have to (re)compute user state
  56  [DEBUG] 2012-02-13 12:54:53,663 main -     findUserStateAtEndOfBillingMonth(2011-11)         Computing full month billing
  57  [DEBUG] 2012-02-13 12:54:53,664 main -                 doFullMonthlyBilling(2011-11)         BEGIN
  58  [DEBUG] 2012-02-13 12:54:53,664 main -     findUserStateAtEndOfBillingMonth(2011-10)           BEGIN
  59  [DEBUG] 2012-02-13 12:54:53,667 main -     findUserStateAtEndOfBillingMonth(2011-10)             User did not exist before 2011-11-01 00:00:00.000. Returning UserState(Christos,0,0,false,null,ImplicitlyIssuedResourceEventsSnapshot(Map(),0),List(),List(),LatestResourceEventsSnapshot(Map(),0),0,ActiveStateSnapshot(false,0),CreditSnapshot(0.0,0),AgreementSnapshot(List(Agreement(default,0,-1)),0),RolesSnapshot(List(),0),OwnedResourcesSnapshot(List(),0))
  60  [DEBUG] 2012-02-13 12:54:53,668 main -     findUserStateAtEndOfBillingMonth(2011-10)           END
  61  [DEBUG] 2012-02-13 12:54:53,672 main -                 doFullMonthlyBilling(2011-11)           previousResourceEvents = LatestResourceEventsWorker(Map())
  62  [DEBUG] 2012-02-13 12:54:53,673 main -                 doFullMonthlyBilling(2011-11)           theImplicitOFFs = ImplicitlyIssuedResourceEventsWorker(Map())
  63  [DEBUG] 2012-02-13 12:54:53,680 main -                 doFullMonthlyBilling(2011-11)           resourceEventStore = MemStore(Map(UserState -> 0, WalletEntry -> 0, ResourceEvent -> 5, PolicyEntry -> 0, UserEvent -> 0))
  64  [DEBUG] 2012-02-13 12:54:53,681 main -                 doFullMonthlyBilling(2011-11)           Found 0 resource events, starting processing...
  65  [DEBUG] 2012-02-13 12:54:53,683 main -                 doFullMonthlyBilling(2011-11)         END
  66  [DEBUG] 2012-02-13 12:54:53,683 main -     findUserStateAtEndOfBillingMonth(2011-11)       END
  67  [DEBUG] 2012-02-13 12:54:53,684 main -                 doFullMonthlyBilling(2011-12)       previousResourceEvents = LatestResourceEventsWorker(Map())
  68  [DEBUG] 2012-02-13 12:54:53,684 main -                 doFullMonthlyBilling(2011-12)       theImplicitOFFs = ImplicitlyIssuedResourceEventsWorker(Map())
  69  [DEBUG] 2012-02-13 12:54:53,685 main -                 doFullMonthlyBilling(2011-12)       resourceEventStore = MemStore(Map(UserState -> 0, WalletEntry -> 0, ResourceEvent -> 5, PolicyEntry -> 0, UserEvent -> 0))
  70  [DEBUG] 2012-02-13 12:54:53,686 main -                 doFullMonthlyBilling(2011-12)       Found 0 resource events, starting processing...
  71  [DEBUG] 2012-02-13 12:54:53,686 main -                 doFullMonthlyBilling(2011-12)     END
  72  [DEBUG] 2012-02-13 12:54:53,687 main -     findUserStateAtEndOfBillingMonth(2011-12)   END
  73  [DEBUG] 2012-02-13 12:54:53,687 main -                 doFullMonthlyBilling(2012-01)   previousResourceEvents = LatestResourceEventsWorker(Map())
  74  [DEBUG] 2012-02-13 12:54:53,688 main -                 doFullMonthlyBilling(2012-01)   theImplicitOFFs = ImplicitlyIssuedResourceEventsWorker(Map())
  75  [DEBUG] 2012-02-13 12:54:53,688 main -                 doFullMonthlyBilling(2012-01)   resourceEventStore = MemStore(Map(UserState -> 0, WalletEntry -> 0, ResourceEvent -> 5, PolicyEntry -> 0, UserEvent -> 0))
  76  [DEBUG] 2012-02-13 12:54:53,689 main -                 doFullMonthlyBilling(2012-01)   Found 4 resource events, starting processing...
  77  [DEBUG] 2012-02-13 12:54:53,690 main -                 doFullMonthlyBilling(2012-01)     Processing EVENT(2, [2012-01-01 03:00:00.000], 99.0 [MB/Hr], diskspace::pithos/diskspace/DISK.1, Map(), Christos, pithos)
  78  [DEBUG] 2012-02-13 12:54:53,691 main -                 doFullMonthlyBilling(2012-01)       0 previousResourceEvents
  79  [DEBUG] 2012-02-13 12:54:53,691 main -                 doFullMonthlyBilling(2012-01)       0 theImplicitOFFs
  80  [DEBUG] 2012-02-13 12:54:53,694 main -                 doFullMonthlyBilling(2012-01)       Processing: ResourceEvent(2,1325379600000,1325379600000,Christos,pithos,diskspace,pithos/diskspace/DISK.1,1.0,99.0,Map())
  81  [DEBUG] 2012-02-13 12:54:53,704 main -                 doFullMonthlyBilling(2012-01)     Processing EVENT(0, [2012-01-02 01:00:00.000], ON, vmtime::synnefo/vmtime/VM.1, Map(), Christos, synnefo)
  82  [DEBUG] 2012-02-13 12:54:53,705 main -                 doFullMonthlyBilling(2012-01)       1 previousResourceEvents
  83  [DEBUG] 2012-02-13 12:54:53,708 main -                 doFullMonthlyBilling(2012-01)         EVENT(2, [2012-01-01 03:00:00.000], 99.0 [MB/Hr], diskspace::pithos/diskspace/DISK.1, Map(), Christos, pithos)
  84  [DEBUG] 2012-02-13 12:54:53,709 main -                 doFullMonthlyBilling(2012-01)       0 theImplicitOFFs
  85  [DEBUG] 2012-02-13 12:54:53,709 main -                 doFullMonthlyBilling(2012-01)       Ignoring not billable EVENT(0, [2012-01-02 01:00:00.000], ON, vmtime::synnefo/vmtime/VM.1, Map(), Christos, synnefo)
  86  [DEBUG] 2012-02-13 12:54:53,711 main -                 doFullMonthlyBilling(2012-01)     Processing EVENT(3, [2012-01-02 04:00:00.000], 23.0 [MB/Hr], diskspace::pithos/diskspace/DISK.1, Map(), Christos, pithos)
  87  [DEBUG] 2012-02-13 12:54:53,712 main -                 doFullMonthlyBilling(2012-01)       2 previousResourceEvents
  88  [DEBUG] 2012-02-13 12:54:53,713 main -                 doFullMonthlyBilling(2012-01)         EVENT(0, [2012-01-02 01:00:00.000], ON, vmtime::synnefo/vmtime/VM.1, Map(), Christos, synnefo)
  89  [DEBUG] 2012-02-13 12:54:53,714 main -                 doFullMonthlyBilling(2012-01)         EVENT(2, [2012-01-01 03:00:00.000], 99.0 [MB/Hr], diskspace::pithos/diskspace/DISK.1, Map(), Christos, pithos)
  90  [DEBUG] 2012-02-13 12:54:53,714 main -                 doFullMonthlyBilling(2012-01)       0 theImplicitOFFs
  91  [DEBUG] 2012-02-13 12:54:53,715 main -                 doFullMonthlyBilling(2012-01)       Processing: ResourceEvent(3,1325469600000,1325469600000,Christos,pithos,diskspace,pithos/diskspace/DISK.1,1.0,23.0,Map())
  92  [DEBUG] 2012-02-13 12:54:53,716 main -                 doFullMonthlyBilling(2012-01)       Previous  : ResourceEvent(2,1325379600000,1325379600000,Christos,pithos,diskspace,pithos/diskspace/DISK.1,1.0,99.0,Map())
  93  [DEBUG] 2012-02-13 12:54:53,718 main -                 doFullMonthlyBilling(2012-01)     Processing EVENT(1, [2012-01-02 10:00:00.000], OFF, vmtime::synnefo/vmtime/VM.1, Map(), Christos, synnefo)
  94  [DEBUG] 2012-02-13 12:54:53,719 main -                 doFullMonthlyBilling(2012-01)       2 previousResourceEvents
  95  [DEBUG] 2012-02-13 12:54:53,719 main -                 doFullMonthlyBilling(2012-01)         EVENT(0, [2012-01-02 01:00:00.000], ON, vmtime::synnefo/vmtime/VM.1, Map(), Christos, synnefo)
  96  [DEBUG] 2012-02-13 12:54:53,721 main -                 doFullMonthlyBilling(2012-01)         EVENT(3, [2012-01-02 04:00:00.000], 23.0 [MB/Hr], diskspace::pithos/diskspace/DISK.1, Map(), Christos, pithos)
  97  [DEBUG] 2012-02-13 12:54:53,721 main -                 doFullMonthlyBilling(2012-01)       0 theImplicitOFFs
  98  [DEBUG] 2012-02-13 12:54:53,722 main -                 doFullMonthlyBilling(2012-01)       Processing: ResourceEvent(1,1325491200000,1325491200000,Christos,synnefo,vmtime,synnefo/vmtime/VM.1,1.0,0.0,Map())
  99  [DEBUG] 2012-02-13 12:54:53,735 main -                 doFullMonthlyBilling(2012-01)       Previous  : ResourceEvent(0,1325458800000,1325458800000,Christos,synnefo,vmtime,synnefo/vmtime/VM.1,1.0,1.0,Map())
 100  [DEBUG] 2012-02-13 12:54:53,736 main -                 doFullMonthlyBilling(2012-01) END
 101  * }}}
 102  *
 103  * @author Christos KK Loverdos <loverdos@gmail.com>
 104  */
 105 final class ContextualLogger(val logger: Logger, fmt: String, args: Any*) {
 106   val ctx = ContextualLogger.fixCtx(fmt.format(args:_*))
 107
 108   private[this] var _nesting = 0
 109
 110   private def nestMsg(fmt: String, args: Any*) = {
 111     val msg = fmt.format(args: _*)
 112     _nesting match {
 113       case 0 ⇒
 114         msg
 115       case n ⇒
 116         val buffer = new java.lang.StringBuilder(n + msg.size)
 117         var _i = 0
 118         while(_i < (n * 2)) {
 119           buffer.append(' ')
 120           _i = _i + 1
 121         }
 122         buffer.append(msg)
 123         buffer.toString
 124     }
 125   }
 126
 127   def isDebugEnabled = logger.isDebugEnabled
 128
 129   def nesting = _nesting
 130
 131   def indentAs(other: ContextualLogger): this.type = {
 132     _nesting = other.nesting
 133     this
 134   }
 135
 136   def indent(): this.type   = {
 137     _nesting = _nesting + 1
 138     this
 139   }
 140
 141   def unindent(): this.type = {
 142     _nesting = _nesting - 1
 143     this
 144   }
 145
 146   def withIndent[A](f: => A): Unit = {
 147     import com.ckkloverdos.maybe.effect
 148     this.indent()
 149     effect(f){}{unindent()}
 150   }
 151
 152   def debug(fmt: String, args: Any*): Unit = {
 153     if(logger.isDebugEnabled) {
 154       val msg = ctx + " " + nestMsg(fmt, args:_*)
 155       logger.debug(msg)
 156     }
 157   }
 158
 159   def info(fmt: String, args: Any*): Unit = {
 160     if(logger.isInfoEnabled) {
 161       val msg = ctx + " " + nestMsg(fmt, args:_*)
 162       logger.info(msg)
 163     }
 164   }
 165
 166   def warn(fmt: String, args: Any*): Unit = {
 167     if(logger.isWarnEnabled) {
 168       val msg = ctx + " " + nestMsg(fmt, args:_*)
 169       logger.warn(msg)
 170     }
 171   }
 172
 173   def error(fmt: String, args: Any*): Unit = {
 174     if(logger.isErrorEnabled) {
 175       val msg = ctx + " " + nestMsg(fmt, args:_*)
 176       logger.error(msg)
 177     }
 178   }
 179
 180   def error(t: Throwable, fmt: String, args: Any*): Unit = {
 181     if(logger.isErrorEnabled) {
 182       val msg = ctx + " " + nestMsg(fmt, args:_*)
 183       logger.error(msg, t)
 184     }
 185   }
 186
 187   def error(failed: Failed): Unit = {
 188     this.error(failed.exception, "")
 189   }
 190
 191   def begin(message: String = ""): Unit = {
 192     if(message == "") debug("BEGIN") else debug("+++ [%s] +++", message)
 193     indent()
 194   }
 195
 196   def end(message: String = ""): Unit = {
 197     unindent()
 198     if(message == "") debug("END") else debug("--- [%s] ---", message)
 199   }
 200
 201   def debugMap[K, V](name: String, map: scala.collection.Map[K, V], oneLineLimit: Int = 3): Unit = {
 202     if(this.isDebugEnabled) {
 203       val mapSize = map.size
 204       if(mapSize <= oneLineLimit) {
 205         this.debug("%s [#=%s] = %s", name, mapSize, map)
 206       } else {
 207         this.debug("%s [#=%s]:", name, mapSize)
 208         val maxKeySize = maxStringSize(map.keySet)
 209         this.withIndent {
 210           for((k, v) <- map) {
 211             this.debug("%s -> %s", rpad(k.toString, maxKeySize), v)
 212           }
 213         }
 214       }
 215     }
 216   }
 217
 218   def debugSeq[T](name: String, seq: scala.collection.Seq[T], oneLineLimit: Int = 3): Unit = {
 219     if(this.isDebugEnabled) {
 220       val seqSize = seq.size
 221       if(seqSize <= oneLineLimit) {
 222         this.debug("%s [#=%s] = %s", name, seqSize, seq)
 223       } else {
 224         this.debug("%s [#=%s]: ", name, seqSize)
 225         this.withIndent(seq.foreach(this.debug("%s", _)))
 226       }
 227     }
 228   }
 229
 230   def debugSet[T](name: String, set: scala.collection.Set[T], oneLineLimit: Int = 3): Unit = {
 231     if(this.isDebugEnabled) {
 232       val setSize = set.size
 233       if(setSize <= oneLineLimit) {
 234         this.debug("%s [#=%s] = %s", name, setSize, set)
 235       } else {
 236         this.debug("%s [#=%s]: ", name, setSize)
 237         this.withIndent(set.foreach(this.debug("%s", _)))
 238       }
 239     }
 240   }
 241 }
 242
 243 /**
 244  * Companion object of [[gr.grnet.aquarium.util.ContextualLogger]].
 245  *
 246  * @author Christos KK Loverdos <loverdos@gmail.com>
 247  */
 248 object ContextualLogger {
 249   final val MaxCtxLength = 40
 250   final val ELLIPSIS = "…" // U+2026
 251
 252   def fixCtx(ctx: String): String = {
 253     val ctxLen = ctx.length()
 254     if(ctxLen == MaxCtxLength) {
 255       ctx
 256     } else if(ctxLen > MaxCtxLength) {
 257       ELLIPSIS + ctx.substring(ctxLen - MaxCtxLength + 1, ctxLen)
 258     } else {
 259       val buffer = new java.lang.StringBuilder(MaxCtxLength)
 260       val prefixLen = MaxCtxLength - ctxLen
 261       var _i = 0
 262       while(_i < prefixLen) {
 263         buffer.append(' ')
 264         _i = _i + 1
 265       }
 266       buffer.append(ctx)
 267       buffer.toString
 268     }
 269   }
 270
 271   def fromOther(clogM: Maybe[ContextualLogger], logger: Logger,  fmt: String, args: Any*): ContextualLogger = {
 272     clogM match {
 273       case Just(clog) ⇒
 274         new ContextualLogger(clog.logger, fmt, args:_*).indentAs(clog)
 275       case _ ⇒
 276         new ContextualLogger(logger, fmt, args:_*)
 277     }
 278   }
 279 }