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

   1 /*
   2  * Copyright 2011 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, "%s", failed.explanation)
 189   }
 190
 191   def begin(): Unit = {
 192     debug("BEGIN")
 193     indent()
 194   }
 195
 196   def end(): Unit = {
 197     unindent()
 198     debug("END")
 199   }
 200
 201   def endWith[A : Manifest](f: ⇒A): A = {
 202     try f
 203     catch {
 204       case e: Exception ⇒
 205         this.error(e, "")
 206         throw e
 207     } finally end()
 208   }
 209
 210   def debugMap[K, V](name: String, map: scala.collection.Map[K, V], limit: Int = 3): Unit = {
 211     val clog = this
 212     if(clog.isDebugEnabled) {
 213       if(map.size < limit) {
 214         clog.debug("%s = %s", name, map)
 215       } else {
 216         clog.debug("%s:", name)
 217         clog.withIndent {
 218           for((k, v) <- map) {
 219             clog.debug("%s: %s", k, v)
 220           }
 221         }
 222       }
 223     }
 224   }
 225
 226   def debugSeq[T](name: String, seq: scala.collection.Seq[T], limit: Int = 3): Unit = {
 227     if(this.isDebugEnabled) {
 228       if(seq.lengthCompare(limit) <= 0) {
 229         this.debug("%s = %s", name, seq)
 230       } else {
 231         this.debug("%s: ", name)
 232         this.withIndent(seq.foreach(this.debug("%s", _)))
 233       }
 234     }
 235   }
 236
 237   def debugSet[T](name: String, set: scala.collection.Set[T], limit: Int = 3): Unit = {
 238     if(this.isDebugEnabled) {
 239       if(set.size <= limit) {
 240         this.debug("%s = %s", name, set)
 241       } else {
 242         this.debug("%s: ", name)
 243         this.withIndent(set.foreach(this.debug("%s", _)))
 244       }
 245     }
 246   }
 247 }
 248
 249 /**
 250  * Companion object of [[gr.grnet.aquarium.util.ContextualLogger]].
 251  *
 252  * @author Christos KK Loverdos <loverdos@gmail.com>
 253  */
 254 object ContextualLogger {
 255   final val MaxCtxLength = 40
 256   final val ELLIPSIS = "…" // U+2026
 257
 258   def fixCtx(ctx: String): String = {
 259     val ctxLen = ctx.length()
 260     if(ctxLen == MaxCtxLength) {
 261       ctx
 262     } else if(ctxLen > MaxCtxLength) {
 263       ELLIPSIS + ctx.substring(ctxLen - MaxCtxLength + 1, ctxLen)
 264     } else {
 265       val buffer = new java.lang.StringBuilder(MaxCtxLength)
 266       val prefixLen = MaxCtxLength - ctxLen
 267       var _i = 0
 268       while(_i < prefixLen) {
 269         buffer.append(' ')
 270         _i = _i + 1
 271       }
 272       buffer.append(ctx)
 273       buffer.toString
 274     }
 275   }
 276
 277   def fromOther(clogM: Maybe[ContextualLogger], logger: Logger,  fmt: String, args: Any*): ContextualLogger = {
 278     clogM match {
 279       case Just(clog) ⇒
 280         new ContextualLogger(clog.logger, fmt, args:_*).indentAs(clog)
 281       case _ ⇒
 282         new ContextualLogger(logger, fmt, args:_*)
 283     }
 284   }
 285 }