Merge pull request #1104 from tpolecat/issue/1062

hook up quill logging
typelevel · Dec 20, 2019 · b54acb3 · b54acb3
2 parents facc6ab + 7ec618e
commit b54acb3
Show file tree

Hide file tree

Showing 3 changed files with 34 additions and 14 deletions.
diff --git a/build.sbt b/build.sbt
@@ -432,7 +432,7 @@ lazy val quill = project
     name := "doobie-quill",
     description := "Quill support for doobie.",
     libraryDependencies ++= Seq(
-      "io.getquill" %% "quill-jdbc" % quillVersion,
-      "org.slf4j"   %  "slf4j-nop"  % slf4jVersion % "test"
+      "io.getquill" %% "quill-jdbc"   % quillVersion,
+      "org.slf4j"   %  "slf4j-simple" % slf4jVersion % "test"
     ),
   )
diff --git a/modules/quill/src/main/scala/doobie/quill/DoobieContextBase.scala b/modules/quill/src/main/scala/doobie/quill/DoobieContextBase.scala
@@ -18,6 +18,7 @@ import doobie.enum.AutoGeneratedKeys
 import io.getquill.ReturnAction.{ ReturnColumns, ReturnNothing, ReturnRecord }
 import io.getquill.ReturnAction
 import io.getquill.context.jdbc.JdbcContextBase
+import io.getquill.util.ContextLogger
 
 /** Base trait from which vendor-specific variants are derived. */
 trait DoobieContextBase[Dialect <: SqlIdiom, Naming <: NamingStrategy]
@@ -33,13 +34,23 @@ trait DoobieContextBase[Dialect <: SqlIdiom, Naming <: NamingStrategy]
   type RunBatchActionResult             = List[Long]
   type RunBatchActionReturningResult[A] = List[A]
 
+  // Logging behavior should be identical to JdbcContextBase.scala, which includes a couple calls
+  // to log.underlying below.
+  private val log: ContextLogger =
+    new ContextLogger("DoobieContext")
+
+  private def prepareAndLog(sql: String, p: Prepare): PreparedStatementIO[Unit] =
+    FPS.raw(p).flatMap { case (params, _) =>
+      FPS.delay(log.logQuery(sql, params))
+    }
+
   override def executeQuery[A](
     sql:       String,
     prepare:   Prepare      = identityPrepare,
     extractor: Extractor[A] = identityExtractor
   ): ConnectionIO[List[A]] =
     HC.prepareStatement(sql) {
-      FPS.raw(prepare) *>
+      prepareAndLog(sql, prepare) *>
       HPS.executeQuery {
         HRS.list(extractor)
       }
@@ -51,7 +62,7 @@ trait DoobieContextBase[Dialect <: SqlIdiom, Naming <: NamingStrategy]
     extractor: Extractor[A] = identityExtractor
   ): ConnectionIO[A] =
     HC.prepareStatement(sql) {
-      FPS.raw(prepare) *>
+      prepareAndLog(sql, prepare) *>
       HPS.executeQuery {
         HRS.getUnique(extractor)
       }
@@ -65,7 +76,7 @@ trait DoobieContextBase[Dialect <: SqlIdiom, Naming <: NamingStrategy]
   ): Stream[ConnectionIO, A] =
     HC.stream(
       sql,
-      FPS.raw(prepare).void,
+      prepareAndLog(sql, prepare),
       fetchSize.getOrElse(DefaultChunkSize)
     )(extractor)
 
@@ -74,7 +85,7 @@ trait DoobieContextBase[Dialect <: SqlIdiom, Naming <: NamingStrategy]
     prepare: Prepare = identityPrepare
   ): ConnectionIO[Long] =
     HC.prepareStatement(sql) {
-      FPS.raw(prepare) *>
+      prepareAndLog(sql, prepare) *>
       HPS.executeUpdate.map(_.toLong)
     }
 
@@ -95,17 +106,23 @@ trait DoobieContextBase[Dialect <: SqlIdiom, Naming <: NamingStrategy]
     returningBehavior: ReturnAction
   ): ConnectionIO[A] =
     prepareConnections[A](returningBehavior)(sql) {
-      FPS.raw(prepare)  *>
-        FPS.executeUpdate *>
-        HPS.getGeneratedKeys(HRS.getUnique(extractor))
+      prepareAndLog(sql, prepare) *>
+      FPS.executeUpdate *>
+      HPS.getGeneratedKeys(HRS.getUnique(extractor))
+    }
+
+  private def prepareBatchAndLog(sql: String, p: Prepare): PreparedStatementIO[Unit] =
+    FPS.raw(p) flatMap { case (params, _) =>
+      FPS.delay(log.logBatchItem(sql, params))
     }
 
   override def executeBatchAction(
     groups: List[BatchGroup]
   ): ConnectionIO[List[Long]] =
     groups.flatTraverse { case BatchGroup(sql, preps) =>
       HC.prepareStatement(sql) {
-        preps.traverse(FPS.raw(_) *> FPS.addBatch) *>
+        FPS.delay(log.underlying.debug("Batch: {}", sql)) *>
+        preps.traverse(prepareBatchAndLog(sql, _) *> FPS.addBatch) *>
         Nested(HPS.executeBatch).map(_.toLong).value
       }
     }
@@ -116,9 +133,10 @@ trait DoobieContextBase[Dialect <: SqlIdiom, Naming <: NamingStrategy]
   ): ConnectionIO[List[A]] =
     groups.flatTraverse { case BatchGroupReturning(sql, returningBehavior, preps) =>
       prepareConnections(returningBehavior)(sql) {
-        preps.traverse(FPS.raw(_) *> FPS.addBatch) *>
-          HPS.executeBatch *>
-          HPS.getGeneratedKeys(HRS.list(extractor))
+        FPS.delay(log.underlying.debug("Batch: {}", sql)) *>
+        preps.traverse(prepareBatchAndLog(sql, _) *> FPS.addBatch) *>
+        HPS.executeBatch *>
+        HPS.getGeneratedKeys(HRS.list(extractor))
       }
     }
 

diff --git a/modules/quill/src/test/scala/doobie/quill/PostgresDoobieContextSpec.scala b/modules/quill/src/test/scala/doobie/quill/PostgresDoobieContextSpec.scala
@@ -15,7 +15,9 @@ import scala.concurrent.ExecutionContext
 
 class PostgresDoobieContextSpec extends Specification {
 
-  sys.props.put("Dquill.binds.log", "true")
+  // Logging should appear in test output
+  sys.props.put("quill.binds.log", "true")
+  sys.props.put("org.slf4j.simpleLogger.defaultLogLevel", "debug")
 
   implicit def contextShift: ContextShift[IO] =
     IO.contextShift(ExecutionContext.global)