feature #10: log Query

.idea/postgres-json.iml

@@ -2,7 +2,9 @@
 <module type="JAVA_MODULE" version="4">
   <component name="NewModuleRootManager" inherit-compiler-output="true">
     <exclude-output />
-    <content url="file://$MODULE_DIR$" />
+    <content url="file://$MODULE_DIR$">
+      <excludeFolder url="file://$MODULE_DIR$/var" />
+    </content>
     <orderEntry type="inheritedJdk" />
     <orderEntry type="sourceFolder" forTests="false" />
   </component>

src/main/kotlin/fr/postgresjson/connexion/Connection.kt

@@ -20,8 +20,9 @@ interface Executable {
     fun <R: EntityI<*>> select(sql: String, typeReference: TypeReference<List<R>>, values: List<Any?> = emptyList()): List<R>
     fun <R: EntityI<*>> select(sql: String, typeReference: TypeReference<List<R>>, values: Map<String, Any?>): List<R>
     fun <R: EntityI<*>> select(sql: String, page: Int, limit: Int, typeReference: TypeReference<List<R>>, values: Map<String, Any?>): Paginated<R>
-    fun exec(sql: String, values: List<Any?> = emptyList()): CompletableFuture<QueryResult>
+    fun exec(sql: String, values: List<Any?> = emptyList()): QueryResult
-    fun exec(sql: String, values: Map<String, Any?>): CompletableFuture<QueryResult>
+    fun exec(sql: String, values: Map<String, Any?>): QueryResult
+    fun sendQuery(sql: String): QueryResult
 }
 
 class Connection(
@@ -35,7 +36,7 @@ class Connection(
     private val serializer = Serializer()
     private val logger: Logger? by LoggerDelegate()
 
-    fun connect(): ConnectionPool<PostgreSQLConnection> {
+    internal fun connect(): ConnectionPool<PostgreSQLConnection> {
         if (!::connection.isInitialized || !connection.isConnected()) {
             connection = PostgreSQLConnectionBuilder.createConnectionPool(
                 "jdbc:postgresql://$host:$port/$database?user=$username&password=$password"
@@ -47,8 +48,8 @@ class Connection(
     fun <A> inTransaction(f: (Connection) -> CompletableFuture<A>) = connect().inTransaction(f)
 
     override fun <R: EntityI<*>> select(sql: String, typeReference: TypeReference<R>, values: List<Any?>): R? {
-        val future = connect().sendPreparedStatement(sql, compileArgs(values))
+        val result = exec(sql, compileArgs(values))
-        val json = future.get().rows[0].getString(0)
+        val json = result.rows[0].getString(0)
         return if (json === null) {
             null
         } else {
@@ -69,8 +70,8 @@ class Connection(
         select(sql, object: TypeReference<R>() {}, values)
 
     override fun <R: EntityI<*>> select(sql: String, typeReference: TypeReference<List<R>>, values: List<Any?>): List<R> {
-        val future = connect().sendPreparedStatement(sql, compileArgs(values))
+        val result = exec(sql, compileArgs(values))
-        val json = future.get().rows[0].getString(0)
+        val json = result.rows[0].getString(0)
         return if (json === null) {
             listOf<EntityI<*>>() as List<R>
         } else {
@@ -94,7 +95,7 @@ class Connection(
             .plus("limit" to limit)
 
         val line = replaceArgs(sql, newValues) {
-            connect().sendPreparedStatement(this.sql, compileArgs(this.parameters)).get().rows[0]
+            exec(this.sql, compileArgs(this.parameters)).rows[0]
         }
 
         return line.run {
@@ -134,17 +135,24 @@ class Connection(
     inline fun <reified R: EntityI<*>> select(sql: String, values: Map<String, Any?>): List<R> =
         select(sql, object: TypeReference<List<R>>() {}, values)
 
-    override fun exec(sql: String, values: List<Any?>): CompletableFuture<QueryResult> {
+    override fun exec(sql: String, values: List<Any?>): QueryResult {
-        logger?.debug(sql, values)
+        return stopwatchQuery(sql, values) {
-        return connect().sendPreparedStatement(sql, compileArgs(values))
+            connect().sendPreparedStatement(sql, compileArgs(values)).join()
+        }
     }
 
-    override fun exec(sql: String, values: Map<String, Any?>): CompletableFuture<QueryResult> {
+    override fun exec(sql: String, values: Map<String, Any?>): QueryResult {
         return replaceArgs(sql, values) {
             exec(this.sql, this.parameters)
         }
     }
 
+    override fun sendQuery(sql: String): QueryResult {
+        return stopwatchQuery(sql) {
+            connect().sendQuery(sql).join()
+        }
+    }
+
     private fun compileArgs(values: List<Any?>): List<Any?> {
         return values.map {
             if (it is EntityI<*>) {
@@ -174,6 +182,21 @@ class Connection(
     }
 
     data class ParametersQuery(val sql: String, val parameters: List<Any?>)
+
+    private fun <T> stopwatchQuery(sql: String, values: List<Any?> = emptyList(), callback: () -> T): T {
+        val sqlForLog = "\n"+sql.prependIndent()
+        try {
+            val start = System.currentTimeMillis()
+            val result = callback()
+            val duration = (System.currentTimeMillis() - start)
+            logger?.debug("$duration ms for query: $sqlForLog", values)
+            return result
+        } catch (e: Throwable) {
+            logger?.info("Query Error: $sqlForLog", e)
+            throw e
+        }
+
+    }
 }
 
 data class Paginated<T: EntityI<*>>(

src/main/kotlin/fr/postgresjson/connexion/Requester.kt

@@ -4,7 +4,6 @@ import com.fasterxml.jackson.core.type.TypeReference
 import com.github.jasync.sql.db.QueryResult
 import fr.postgresjson.entity.EntityI
 import java.io.File
-import java.util.concurrent.CompletableFuture
 import fr.postgresjson.definition.Function as DefinitionFunction
 
 class Requester(
@@ -109,11 +108,11 @@ class Requester(
         inline fun <reified R: EntityI<*>> select(page: Int, limit: Int, values: Map<String, Any?> = emptyMap()): Paginated<R> =
             select(page, limit, object: TypeReference<List<R>>() {}, values)
 
-        override fun exec(values: List<Any?>): CompletableFuture<QueryResult> {
+        override fun exec(values: List<Any?>): QueryResult {
             return connection.exec(sql, values)
         }
 
-        override fun exec(values: Map<String, Any?>): CompletableFuture<QueryResult> {
+        override fun exec(values: Map<String, Any?>): QueryResult {
             return connection.exec(sql, values)
         }
     }
@@ -185,14 +184,14 @@ class Requester(
         inline fun <reified R: EntityI<*>> select(page: Int, limit: Int, values: Map<String, Any?> = emptyMap()): Paginated<R> =
             select(page, limit, object: TypeReference<List<R>>() {}, values)
 
-        override fun exec(values: List<Any?>): CompletableFuture<QueryResult> {
+        override fun exec(values: List<Any?>): QueryResult {
             val args = compileArgs(values)
             val sql = "SELECT * FROM ${definition.name} ($args)"
 
             return connection.exec(sql, values)
         }
 
-        override fun exec(values: Map<String, Any?>): CompletableFuture<QueryResult> {
+        override fun exec(values: Map<String, Any?>): QueryResult {
             val args = compileArgs(values)
             val sql = "SELECT * FROM ${definition.name} ($args)"
 
@@ -239,8 +238,8 @@ class Requester(
 
         fun <R: EntityI<*>> select(page: Int, limit: Int, typeReference: TypeReference<List<R>>, values: Map<String, Any?>): Paginated<R>
 
-        fun exec(values: List<Any?> = emptyList()): CompletableFuture<QueryResult>
+        fun exec(values: List<Any?> = emptyList()): QueryResult
-        fun exec(values: Map<String, Any?>): CompletableFuture<QueryResult>
+        fun exec(values: Map<String, Any?>): QueryResult
     }
 
     class RequesterFactory(

src/main/kotlin/fr/postgresjson/migration/Migrations.kt

@@ -154,10 +154,10 @@ data class Migrations private constructor(
     private fun initDB() {
         if (!initialized) {
             File(this::class.java.getResource("/sql/migration/createHistoryShema.sql").toURI()).let {
-                connection.connect().sendQuery(it.readText()).join()
+                connection.sendQuery(it.readText())
             }
             File(this::class.java.getResource("/sql/migration/createFunctionShema.sql").toURI()).let {
-                connection.connect().sendQuery(it.readText()).join()
+                connection.sendQuery(it.readText())
             }
             initialized = true
         }
@@ -165,7 +165,7 @@ data class Migrations private constructor(
 
     private fun lock() {
         File(this::class.java.getResource("/sql/migration/lockMigrationTables.sql").toURI()).let {
-            connection.connect().sendQuery(it.readText()).join()
+            connection.sendQuery(it.readText())
         }
     }
 
@@ -221,8 +221,8 @@ data class Migrations private constructor(
 
     fun run(): Map<Pair<String, Direction>, Status> {
         val list: MutableMap<Pair<String, Direction>, Status> = mutableMapOf()
-        connection.connect().apply {
+        connection.apply {
-            sendQuery("BEGIN").join()
+            sendQuery("BEGIN")
             lock()
             up().map {
                 list[Pair(it.key, Direction.UP)] = it.value
@@ -230,7 +230,7 @@ data class Migrations private constructor(
             down(true).map {
                 list[Pair(it.key, Direction.DOWN)] = it.value
             }
-            sendQuery("COMMIT").join()
+            sendQuery("COMMIT")
         }
 
         return list.toMap()
@@ -242,15 +242,15 @@ data class Migrations private constructor(
 
     private fun runTest(): Map<Pair<String, Direction>, Status> {
         val list: MutableMap<Pair<String, Direction>, Status> = mutableMapOf()
-        connection.connect().apply {
+        connection.apply {
-            sendQuery("BEGIN").join()
+            sendQuery("BEGIN")
             up().map {
                 list[Pair(it.key, Direction.UP)] = it.value
             }
             down(true).map {
                 list[Pair(it.key, Direction.DOWN)] = it.value
             }
-            sendQuery("ROLLBACK").join()
+            sendQuery("ROLLBACK")
         }
 
         return list.toMap()

src/main/kotlin/fr/postgresjson/migration/Query.kt

@@ -16,7 +16,7 @@ data class Query(
     override var doExecute: Action? = null
 
     override fun up(): Migration.Status {
-        connection.exec(up).join()
+        connection.exec(up)
 
         File(this::class.java.getResource("/sql/migration/insertHistory.sql").toURI()).let {
             connection.selectOne<MigrationEntity>(it.readText(), listOf(name, up, down))?.let { query ->
@@ -29,7 +29,7 @@ data class Query(
     }
 
     override fun down(): Migration.Status {
-        connection.exec(down).join()
+        connection.exec(down)
 
         File(this::class.java.getResource("/sql/migration/deleteHistory.sql").toURI()).let {
             connection.exec(it.readText(), listOf(name))

src/main/kotlin/fr/postgresjson/stopwatch/Stopwatch.kt

@@ -0,0 +1,8 @@
+package fr.postgresjson.stopwatch
+
+fun <T> elapse(callback: (start: Long) -> T, after: (elapse: Long) -> Unit): T {
+    val start = System.currentTimeMillis()
+    val result = callback(start)
+    after(System.currentTimeMillis() - start)
+    return result
+}

src/test/kotlin/fr/postgresjson/ConnectionTest.kt

@@ -1,10 +1,10 @@
 package fr.postgresjson
 
-import com.github.jasync.sql.db.util.isCompleted
 import fr.postgresjson.connexion.Connection
 import fr.postgresjson.connexion.Paginated
 import fr.postgresjson.entity.IdEntity
 import org.junit.Assert.*
+import org.junit.jupiter.api.Assertions
 import org.junit.jupiter.api.BeforeEach
 import org.junit.jupiter.api.Test
 import org.junit.jupiter.api.TestInstance
@@ -41,7 +41,7 @@ class ConnectionTest(): TestAbstract() {
             from test2 t
             JOIN test t2 ON t.test_id = t2.id
         ) j;
-        """
+        """.trimIndent()
         )
         assertNotNull(objs)
         assertTrue(objs is List<ObjTest2>)
@@ -71,9 +71,8 @@ class ConnectionTest(): TestAbstract() {
     @Test
     fun callExec() {
         val o = ObjTest("myName")
-        val future = connection.exec("select json_build_object('id', 1, 'name', ?::json->>'name')", listOf(o))
+        val result = connection.exec("select json_build_object('id', 1, 'name', ?::json->>'name')", listOf(o))
-        future.join()
+        Assertions.assertEquals(1, result.rowsAffected)
-        assertTrue(future.isCompleted)
     }
 
     @Test
@@ -107,9 +106,9 @@ class ConnectionTest(): TestAbstract() {
             """.trimIndent(),
             params
         )
-        assertEquals(result[0]!!.first, "ff")
+        assertEquals(result[0].first, "ff")
-        assertEquals(result[0]!!.seconde, "sec")
+        assertEquals(result[0].seconde, "sec")
-        assertEquals(result[0]!!.third, 123)
+        assertEquals(result[0].third, 123)
     }
 
     @Test

src/test/kotlin/fr/postgresjson/RequesterTest.kt

@@ -1,16 +1,12 @@
 package fr.postgresjson
 
-import com.github.jasync.sql.db.QueryResult
-import com.github.jasync.sql.db.util.isCompleted
 import fr.postgresjson.connexion.Paginated
 import fr.postgresjson.connexion.Requester
 import fr.postgresjson.entity.IdEntity
 import org.junit.Assert
-import org.junit.jupiter.api.Assertions
 import org.junit.jupiter.api.Assertions.assertEquals
 import org.junit.jupiter.api.Test
 import java.io.File
-import java.util.concurrent.CompletableFuture
 
 class RequesterTest: TestAbstract() {
     class ObjTest(var name:String): IdEntity(1)
@@ -42,25 +38,23 @@ class RequesterTest: TestAbstract() {
     @Test
     fun `call exec on query`() {
         val resources = File(this::class.java.getResource("/sql/query").toURI())
-        val future: CompletableFuture<QueryResult> = Requester(getConnextion())
+        val result = Requester(getConnextion())
             .addQuery(resources)
             .getQuery("Test/selectOne")
             .exec()
 
-        future.join()
+        assertEquals(1, result.rowsAffected)
-        Assertions.assertTrue(future.isCompleted)
     }
 
     @Test
     fun `call exec on function`() {
         val resources = File(this::class.java.getResource("/sql/function").toURI())
-        val future: CompletableFuture<QueryResult> = Requester(getConnextion())
+        val result = Requester(getConnextion())
             .addFunction(resources)
             .getFunction("test_function")
             .exec(listOf("test", "plip"))
 
-        future.join()
+        assertEquals(1, result.rowsAffected)
-        Assertions.assertTrue(future.isCompleted)
     }
 
     @Test

src/test/resources/logback.xml

@@ -4,23 +4,23 @@
             <pattern>%d{YYYY-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
         </encoder>
     </appender>
-    <property name="LOG_DIR" value="./postgresjson" />
+    <property name="LOG_DIR" value="./var/log" />
     <appender name="query" class="ch.qos.logback.core.FileAppender">
         <file>${LOG_DIR}/query.log</file>
         <append>true</append>
         <encoder>
-            <pattern>%d{YYYY-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{35} - %msg%n</pattern>
+            <pattern>%d{YYYY-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
         </encoder>
     </appender>
     <appender name="other" class="ch.qos.logback.core.FileAppender">
         <file>${LOG_DIR}/other.log</file>
         <append>true</append>
         <encoder>
-            <pattern>%d{YYYY-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{35} - %msg%n</pattern>
+            <pattern>%d{YYYY-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
         </encoder>
     </appender>
 
-    <root level="trace">
+    <root level="debug">
         <appender-ref ref="STDOUT"/>
         <appender-ref ref="other" />
     </root>
@@ -28,7 +28,7 @@
     <logger name="org.eclipse.jetty" level="INFO"/>
     <logger name="io.netty" level="INFO"/>
 
-    <logger name="fr.postgresjson.connexion" level="trace">
+    <logger name="fr.postgresjson.connexion" level="debug">
         <appender-ref ref="query" />
     </logger>
 </configuration>