Merge pull request #7 from tomtom-international/1.0.9-SNAPSHOT

Added logCaller to `@TraceLogLevel` annotation

README.md

@@ -144,15 +144,27 @@ setLogger()
 ### Using the `@TraceLogLevel` annotation
 
 Trace events in a `TraceEventListener` can be annotated with the `@TraceLogLevel` annotation.
-This annotation allows you to specify a log level, using parameter `logLevel` that will 
+
+#### `@TraceLoglevel(logLevel=...)`
+
+`@TraceLoglevel` allows you to specify a log level, using parameter `logLevel` that will 
 be used to output the trace event to a standard logger using a specific log level, 
 such as `INFO`, `DEBUG`, `ERROR`, etc.
 
-It also offers the option to specify logging a full stack trace of a logged exception, using
+#### `@TraceLoglevel(logStackTrace=true|false)`
+
+`@TraceLoglevel` also offers the option to specify logging a full stack trace of a logged exception, using
 the optional parameter `logStackTrace`. This applies to the last argument of an event (if it 
 is a `Throwable` object). By default, the stack trace is included.
 
-Finally, it offers the option, using `includeOwnerClass` to add the class owning the event
+#### `@TraceLoglevel(logCaller=true|false)`
+
+`@TraceLoglevel` also offers the option to specify logging the filename and line number of
+the caller of an event. By default, the caller is not provided.
+
+#### `@TraceLoglevel(logOwnerClass=true|false)`
+
+`@TraceLoglevel` offers the option, using `logOwnerClass` to add the class owning the event
 interface to the log message, or omit that. By default, the owner class is not included.
 
 Example:
@@ -419,6 +431,10 @@ Contributors: Timon Kanters, Jeroen Erik Jensen
 
 ## Release notes
 
+### 1.0.9
+
+* Added `logCaller` to `@TraceLoglevel` add the caller filename and line number to the logger.
+
 ### 1.0.8
 
 * Added `logStackTrace` to annotation `@TraceLogLevel`.

pom.xml

@@ -21,7 +21,7 @@
 
     <groupId>com.tomtom.kotlin</groupId>
     <artifactId>kotlin-tools</artifactId>
-    <version>1.0.8</version>
+    <version>1.0.9</version>
     <packaging>pom</packaging>
 
     <name>Kotlin Tools</name>

traceevents/pom.xml

@@ -24,7 +24,7 @@
     <parent>
         <groupId>com.tomtom.kotlin</groupId>
         <artifactId>kotlin-tools</artifactId>
-        <version>1.0.8</version>
+        <version>1.0.9</version>
     </parent>
 
     <artifactId>traceevents</artifactId>

traceevents/src/main/java/com/tomtom/kotlin/traceevents/TraceLogLevel.kt

@@ -26,11 +26,20 @@ import com.tomtom.kotlin.traceevents.TraceLog.LogLevel
  * @param logStackTrace Specifies whether a stack trace should be included if the last parameter
  * of the event is derived from [Throwable]. If false, only the exception message is shown.
  * Default value is true.
+ *
+ * @param logCaller Specifies whether the filename and line number of the caller
+ * should be logged or not.
+ * Default is false.
+ *
+ * @param logOwnerClass Specifies whether owner class of the event definition should be logged
+ * or not.
+ * Default is false.
  */
 @Retention(AnnotationRetention.RUNTIME)
 @Target(AnnotationTarget.FUNCTION)
 annotation class TraceLogLevel(
     val logLevel: LogLevel,
     val logStackTrace: Boolean = true,
-    val includeOwnerClass: Boolean = false
+    val logCaller: Boolean = false,
+    val logOwnerClass: Boolean = false
 )

traceevents/src/main/java/com/tomtom/kotlin/traceevents/Tracer.kt

@@ -32,6 +32,7 @@ import java.time.format.DateTimeFormatter
 import kotlin.reflect.KClass
 import kotlin.reflect.full.isSubclassOf
 
+
 /**
  * GENERAL DOCUMENTATION ON TRACE EVENTS
  * -------------------------------------
@@ -217,8 +218,10 @@ class Tracer private constructor(
             method.getDeclaredAnnotation(TraceLogLevel::class.java)?.logLevel ?: LogLevel.DEBUG
         val logStackTraceAnnotation =
             method.getDeclaredAnnotation(TraceLogLevel::class.java)?.logStackTrace ?: true
+        val logCaller =
+            method.getDeclaredAnnotation(TraceLogLevel::class.java)?.logCaller ?: false
         val includeOwnerClassAnnotation =
-            method.getDeclaredAnnotation(TraceLogLevel::class.java)?.includeOwnerClass ?: false
+            method.getDeclaredAnnotation(TraceLogLevel::class.java)?.logOwnerClass ?: false
 
         /**
          * Skip event when the method is a standard (possibly auto-generated) class method.
@@ -260,6 +263,7 @@ class Tracer private constructor(
                     "event=${createLogMessage(
                         event,
                         includeTime = false,
+                        logCaller = logCaller,
                         logStackTrace = logStackTraceAnnotation,
                         includeOwnerClass = includeOwnerClassAnnotation
                     )}"
@@ -301,6 +305,7 @@ class Tracer private constructor(
                         "Event lost, event=${createLogMessage(
                             event,
                             includeTime = true,
+                            logCaller = true,
                             logStackTrace = true,
                             includeOwnerClass = true
                         )}"
@@ -351,6 +356,7 @@ class Tracer private constructor(
 
     companion object {
         val TAG = Tracer::class.simpleName!!
+        const val STACK_TRACE_DEPTH = 5L
 
         /**
          * Names of simple, predefined log functions (from standard loggers).
@@ -616,6 +622,7 @@ class Tracer private constructor(
         internal fun createLogMessage(
             traceEvent: TraceEvent,
             includeTime: Boolean,
+            logCaller: Boolean,
             logStackTrace: Boolean,
             includeOwnerClass: Boolean
         ): String {
@@ -628,8 +635,11 @@ class Tracer private constructor(
                     convertToStringUsingRegistry(it)
                 }})"
             )
+            if (logCaller) {
+                sb.append(", caller=${getCaller()}")
+            }
             if (includeOwnerClass) {
-                sb.append(", from ${traceEvent.ownerClass}")
+                sb.append(", ownerClass=${traceEvent.ownerClass}")
             }
             if (logStackTrace && !traceEvent.args.isEmpty()) {
                 (traceEvent.args.last() as? Throwable)?.let {
@@ -654,6 +664,47 @@ class Tracer private constructor(
                 e.message
             }
 
+        private fun getCaller(): String {
+
+            /**
+             * For Java 9, we suggest the following optimization:
+             *
+             * Use the [StackWalker] instead of [Thread.getStackTrace], because it's much, much
+             * faster to not get all frames.
+             *
+             * Get the stack up to a maximum of [STACK_TRACE_DEPTH] levels deep. Our caller must be
+             * in those first calls. If it's not, the unit tests fails and informs the developer
+             * the reconsider the value of [STACK_TRACE_DEPTH].
+             *
+             * <pre>
+             *     val stack = StackWalker.getInstance().walk {
+             *         frames -> frames.limit(STACK_TRACE_DEPTH).collect(Collectors.toList())
+             * </pre>
+             *
+             * For now, use the slower Java 8 version:
+             */
+            val stack = Throwable().stackTrace
+
+            // Find our own 'invoke' function call on the stack that called this function.
+            var i = 0
+            while (i < stack.size &&
+                stack[i].className != "com.tomtom.kotlin.traceevents.Tracer" &&
+                stack[i].methodName != "invoke"
+            ) i++
+
+            // The function call 2 levels deeper is the actual caller function.
+            return if (i < stack.size - 2) {
+
+                // Skip the com.sun.proxy function call and get the info from the next item.
+                val item = stack[i + 2]
+                "${item.fileName}:${item.methodName}(${item.lineNumber})"
+            } else {
+
+                // This shouldn't happen, but we certainly shouldn't throw here.
+                "(error: can't find `invoke` function on stack)"
+            }
+        }
+
         init {
 
             // Always switch on synchronous logging by default.

traceevents/src/test/java/com/tomtom/kotlin/traceevents/LogTest.kt

@@ -16,7 +16,9 @@ package com.tomtom.kotlin.traceevents
 
 import com.tomtom.kotlin.traceevents.TraceLog.LogLevel
 import com.tomtom.kotlin.traceevents.TraceLog.Logger
+import org.junit.Before
 import org.junit.Test
+import kotlin.system.measureTimeMillis
 import kotlin.test.assertEquals
 import kotlin.test.assertFalse
 import kotlin.test.assertTrue
@@ -51,13 +53,21 @@ class LogTest {
         @TraceLogLevel(LogLevel.ERROR)
         fun allArgs(aInt: Int?, aString: String?, aArray: Array<Int?>?, aList: List<Int?>?)
 
-        @TraceLogLevel(LogLevel.DEBUG, logStackTrace = true, includeOwnerClass = true)
+        @TraceLogLevel(LogLevel.DEBUG, logCaller = true)
+        fun withCaller(message: String)
+
+        @TraceLogLevel(LogLevel.DEBUG, logStackTrace = true, logOwnerClass = true)
         fun withStackTrace(e: Throwable?)
 
-        @TraceLogLevel(LogLevel.DEBUG, logStackTrace = false, includeOwnerClass = false)
+        @TraceLogLevel(LogLevel.DEBUG, logStackTrace = false, logOwnerClass = false)
         fun withoutStackTrace(e: Throwable?)
     }
 
+    @Before
+    fun setUp() {
+        TraceLog.setLogger()
+    }
+
     @Test
     fun `specific consumer`() {
         val logger = LoggerCalled()
@@ -214,7 +224,7 @@ class LogTest {
             sut.withStackTrace(null)
         }
         val expected =
-            "$TIME: [DEBUG] LogTest: event=withStackTrace(null), from com.tomtom.kotlin.traceevents.LogTest\n"
+            "$TIME: [DEBUG] LogTest: event=withStackTrace(null), ownerClass=com.tomtom.kotlin.traceevents.LogTest\n"
         assertEquals(expected, actual)
     }
 
@@ -226,7 +236,7 @@ class LogTest {
 
         // Cut off just enough to NOT include line numbers of source code as they may change.
         val prefix =
-            "$TIME: [DEBUG] LogTest: event=withStackTrace(java.lang.IllegalStateException: error1), from com.tomtom.kotlin.traceevents.LogTest\n" +
+            "$TIME: [DEBUG] LogTest: event=withStackTrace(java.lang.IllegalStateException: error1), ownerClass=com.tomtom.kotlin.traceevents.LogTest\n" +
                 "java.lang.IllegalStateException: error1\n" +
                 "\tat com.tomtom.kotlin.traceevents.LogTest\$log event with exception to stdout with stacktrace\$actual\$1.invoke(LogTest.kt:"
         val suffix =
@@ -239,6 +249,20 @@ class LogTest {
         assertTrue(replaceNumber(actual, NUMBER).endsWith(suffix))
     }
 
+    @Test
+    fun `log event with caller`() {
+        val actual = captureStdoutReplaceTime(TIME) {
+            sut.withCaller("test")
+        }
+
+        println(actual)
+        // Cut off just enough to NOT include line numbers of source code as they may change.
+        val expected =
+            "$TIME: [DEBUG] LogTest: event=withCaller(test), caller=LogTest.kt:invoke($NUMBER)\n"
+        assertEquals(expected, replaceNumber(actual, NUMBER),
+            "Perhaps you should increase STACK_TRACE_DEPTH?")
+    }
+
     companion object {
         const val TIME = "[TIME]"
         const val NUMBER = "[NUMBER]"