Permalink
Browse files

Improve logging:

- Upgrade to latest logback 1.1.3 and remove ending “$” from all logger
  names. Parsing these names is currently broken in logback (see
  http://jira.qos.ch/browse/LOGBACK-978) and might also cause problems
  with other frameworks.

- Add `mark` methods to GenericTest to put a debug ID into the MDC (and
  also use it as the action name when marking a DBIOAction).

- Update logback configs accordingly to print this debug ID.
  • Loading branch information...
szeiger committed Jun 15, 2015
1 parent e9ab330 commit ae7e4d8a6e49d6f9d534b980b399bb036b5c47fc
@@ -1,7 +1,7 @@
<configuration>
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>*** \(%logger{30}\) %msg%n</pattern>
<pattern>*** \(%logger{30}\)%green(%X{debugId}) %msg%n</pattern>
</encoder>
</appender>
<root level="${log.root:-info}">
@@ -38,9 +38,9 @@
<logger name="slick.jdbc.JdbcBackend.benchmark" level="${log.jdbc.bench:-info}" />
<logger name="slick.jdbc.StatementInvoker.result" level="${log.jdbc.result:-info}" />
<logger name="slick.jdbcJdbcModelBuilder" level="${log.createModel:-info}" />
<logger name="slick.ast.Node$" level="${log.qcomp.assignTypes:-inherited}" />
<logger name="slick.memory.HeapBackend$" level="${log.heap:-inherited}" />
<logger name="slick.ast.Node" level="${log.qcomp.assignTypes:-inherited}" />
<logger name="slick.memory.HeapBackend" level="${log.heap:-inherited}" />
<logger name="slick.memory.QueryInterpreter" level="${log.interpreter:-inherited}" />
<logger name="slick.relational.ResultConverterCompiler" level="${log.resultConverter:-inherited}" />
<logger name="slick.util.AsyncExecutor$" level="${log.asyncExecutor:-inherited}" />
<logger name="slick.util.AsyncExecutor" level="${log.asyncExecutor:-inherited}" />
</configuration>
View
@@ -27,7 +27,7 @@ object SlickBuild extends Build {
"com.google.inject" % "guice" % "2.0"
)
val slf4j = "org.slf4j" % "slf4j-api" % "1.6.4"
val logback = "ch.qos.logback" % "logback-classic" % "0.9.28"
val logback = "ch.qos.logback" % "logback-classic" % "1.1.3"
val typesafeConfig = "com.typesafe" % "config" % "1.2.1"
val reactiveStreamsVersion = "1.0.0.RC4"
val reactiveStreams = "org.reactivestreams" % "reactive-streams" % reactiveStreamsVersion
@@ -1,7 +1,7 @@
<configuration>
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>*** \(%logger{30}\) %msg%n</pattern>
<pattern>*** \(%logger{30}\)%green(%X{debugId}) %msg%n</pattern>
</encoder>
</appender>
<root level="${log.root:-info}">
@@ -1,7 +1,7 @@
<configuration>
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>*** \(%logger{30}\) %msg%n</pattern>
<pattern>*** \(%logger{30}\)%green(%X{debugId}) %msg%n</pattern>
</encoder>
</appender>
<root level="${log.root:-info}">
@@ -37,10 +37,10 @@
<logger name="slick.jdbc.JdbcBackend.statement" level="${log.jdbc.statement:-info}" />
<logger name="slick.jdbc.JdbcBackend.benchmark" level="${log.jdbc.bench:-info}" />
<logger name="slick.jdbc.StatementInvoker.result" level="${log.jdbc.result:-info}" />
<logger name="slick.jdbc.meta" level="${log.createModel:-info}" />
<logger name="slick.ast.Node$" level="${log.qcomp.assignTypes:-inherited}" />
<logger name="slick.memory.HeapBackend$" level="${log.heap:-inherited}" />
<logger name="slick.jdbcJdbcModelBuilder" level="${log.createModel:-info}" />
<logger name="slick.ast.Node" level="${log.qcomp.assignTypes:-inherited}" />
<logger name="slick.memory.HeapBackend" level="${log.heap:-inherited}" />
<logger name="slick.memory.QueryInterpreter" level="${log.interpreter:-inherited}" />
<logger name="slick.relational.ResultConverterCompiler" level="${log.resultConverter:-inherited}" />
<logger name="slick.util.AsyncExecutor$" level="${log.asyncExecutor:-inherited}" />
<logger name="slick.util.AsyncExecutor" level="${log.asyncExecutor:-inherited}" />
</configuration>
@@ -246,27 +246,27 @@ class JoinTest extends AsyncTest[RelationalTestDB] {
q1 = for {
(c, i) <- categories.sortBy(_.id).zipWithIndex
} yield (c.id, i)
_ <- q1.result.map(_ shouldBe List((1,0), (2,1), (3,2), (4,3)))
_ <- mark("q1", q1.result).map(_ shouldBe List((1,0), (2,1), (3,2), (4,3)))
q2 = for {
(c, p) <- categories.sortBy(_.id) zip posts.sortBy(_.category)
} yield (c.id, p.category)
_ <- q2.result.map(_ shouldBe List((1,-1), (2,1), (3,2), (4,2)))
_ <- mark("q2", q2.result).map(_ shouldBe List((1,-1), (2,1), (3,2), (4,2)))
q3 = for {
(c, p) <- categories zip posts
} yield (c.id, p.category)
_ <- q3.result.map(_ shouldBe List((1, -1), (3, 1), (2, 2), (4, 3)))
_ <- mark("q3", q3.result).map(_ shouldBe List((1, -1), (3, 1), (2, 2), (4, 3)))
q4 = for {
res <- categories.zipWith(posts, (c: Categories, p: Posts) => (c.id, p.category))
} yield res
_ <- q4.result.map(_ shouldBe List((1, -1), (3, 1), (2, 2), (4, 3)))
_ <- mark("q4", q4.result).map(_ shouldBe List((1, -1), (3, 1), (2, 2), (4, 3)))
q5 = for {
(c, i) <- categories.zipWithIndex
} yield (c.id, i)
_ <- q5.result.map(_ shouldBe List((1,0), (3,1), (2,2), (4,3)))
_ <- mark("q5", q5.result).map(_ shouldBe List((1,0), (3,1), (2,2), (4,3)))
q6 = for {
((c, p), i) <- (categories zip posts).zipWithIndex
} yield (c.id, p.category, i)
_ <- q6.result.map(_ shouldBe List((1, -1, 0), (3, 1, 1), (2, 2, 2), (4, 3, 3)))
_ <- mark("q6", q6.result).map(_ shouldBe List((1, -1, 0), (3, 1, 1), (2, 2, 2), (4, 3, 3)))
} yield ()
}
@@ -1,5 +1,7 @@
package com.typesafe.slick.testkit.util
import org.slf4j.MDC
import scala.language.existentials
import scala.concurrent.{Promise, ExecutionContext, Await, Future, blocking}
@@ -143,6 +145,20 @@ sealed abstract class GenericTest[TDB >: Null <: TestDB](implicit TdbClass: Clas
def u(args: Any*) = s.standardInterpolator(identity, args) + "_" + unique.incrementAndGet()
}
final def mark[T](id: String, f: => T): T = {
def set(id: String): Unit =
if(id eq null) MDC.remove("debugId")
else MDC.put("debugId", id)
val old = MDC.get("debugId")
try {
set(if(id eq null) id else s" [$id]")
f
} finally set(old)
}
final def mark[R, S <: NoStream, E <: Effect](id: String, f: => DBIOAction[R, S, E]): DBIOAction[R, S, E] =
mark[DBIOAction[R, S, E]](id, f.named(id))
def rcap = RelationalProfile.capabilities
def scap = SqlProfile.capabilities
def jcap = JdbcProfile.capabilities
@@ -2,6 +2,8 @@ package slick.util
import org.slf4j.{ Logger => Slf4jLogger, LoggerFactory }
import scala.reflect.ClassTag
final class SlickLogger(val slf4jLogger: Slf4jLogger) {
@inline
def debug(msg: => String, n: => Dumpable): Unit =
@@ -41,6 +43,15 @@ final class SlickLogger(val slf4jLogger: Slf4jLogger) {
def trace(msg: => String, t: Throwable) { if (slf4jLogger.isTraceEnabled) slf4jLogger.trace(msg, t) }
}
object SlickLogger {
def apply[T](implicit ct: ClassTag[T]): SlickLogger =
new SlickLogger(LoggerFactory.getLogger(ct.runtimeClass))
}
trait Logging {
protected[this] lazy val logger = new SlickLogger(LoggerFactory.getLogger(getClass))
protected[this] lazy val logger = {
val n = getClass.getName
val cln = if(n endsWith "$") n.substring(0, n.length-1) else n
new SlickLogger(LoggerFactory.getLogger(cln))
}
}

0 comments on commit ae7e4d8

Please sign in to comment.