SONAR-6194 SONAR-5009 profiling api + unique property sonar.log.level

8 files changed, 362 insertions, 36 deletions

diff --git a/sonar-plugin-api/src/test/java/org/sonar/api/utils/TimeProfilerTest.java b/sonar-plugin-api/src/test/java/org/sonar/api/utils/TimeProfilerTest.java
index 3d7e3ac6177..713b4677abf 100644
--- a/sonar-plugin-api/src/test/java/org/sonar/api/utils/TimeProfilerTest.java
+++ b/sonar-plugin-api/src/test/java/org/sonar/api/utils/TimeProfilerTest.java
@@ -21,7 +21,7 @@ package org.sonar.api.utils;
 
 import org.junit.Before;
 import org.junit.Test;
-import org.sonar.api.utils.log.Logger;
+import org.slf4j.Logger;
 
 import static org.mockito.Matchers.anyInt;
 import static org.mockito.Matchers.anyString;
diff --git a/sonar-plugin-api/src/test/java/org/sonar/api/utils/log/ConsoleLoggerTest.java b/sonar-plugin-api/src/test/java/org/sonar/api/utils/log/ConsoleLoggerTest.java
index 3f59d8d87e5..56d5f242dab 100644
--- a/sonar-plugin-api/src/test/java/org/sonar/api/utils/log/ConsoleLoggerTest.java
+++ b/sonar-plugin-api/src/test/java/org/sonar/api/utils/log/ConsoleLoggerTest.java
@@ -38,8 +38,9 @@ public class ConsoleLoggerTest {
 
   @Test
   public void debug_enabled() throws Exception {
-    tester.enableDebug(true);
+    tester.setLevel(LoggerLevel.DEBUG);
     assertThat(sut.isDebugEnabled()).isTrue();
+    assertThat(sut.isTraceEnabled()).isFalse();
     sut.debug("message");
     sut.debug("message {}", "foo");
     sut.debug("message {} {}", "foo", "bar");
@@ -49,8 +50,9 @@ public class ConsoleLoggerTest {
 
   @Test
   public void debug_disabled() throws Exception {
-    tester.enableDebug(false);
+    tester.setLevel(LoggerLevel.INFO);
     assertThat(sut.isDebugEnabled()).isFalse();
+    assertThat(sut.isTraceEnabled()).isFalse();
     sut.debug("message");
     sut.debug("message {}", "foo");
     sut.debug("message {} {}", "foo", "bar");
@@ -59,6 +61,29 @@ public class ConsoleLoggerTest {
   }
 
   @Test
+  public void trace_enabled() throws Exception {
+    tester.setLevel(LoggerLevel.TRACE);
+    assertThat(sut.isDebugEnabled()).isTrue();
+    assertThat(sut.isTraceEnabled()).isTrue();
+    sut.trace("message");
+    sut.trace("message {}", "foo");
+    sut.trace("message {} {}", "foo", "bar");
+    sut.trace("message {} {} {}", "foo", "bar", "baz");
+    verify(stream, times(4)).println(anyString());
+  }
+
+  @Test
+  public void trace_disabled() throws Exception {
+    tester.setLevel(LoggerLevel.DEBUG);
+    assertThat(sut.isTraceEnabled()).isFalse();
+    sut.trace("message");
+    sut.trace("message {}", "foo");
+    sut.trace("message {} {}", "foo", "bar");
+    sut.trace("message {} {} {}", "foo", "bar", "baz");
+    verifyZeroInteractions(stream);
+  }
+
+  @Test
   public void log() throws Exception {
     sut.info("message");
     sut.info("message {}", "foo");
diff --git a/sonar-plugin-api/src/test/java/org/sonar/api/utils/log/ConsoleLoggersTest.java b/sonar-plugin-api/src/test/java/org/sonar/api/utils/log/ConsoleLoggersTest.java
index 64fa4cc7b96..a77cd98a18a 100644
--- a/sonar-plugin-api/src/test/java/org/sonar/api/utils/log/ConsoleLoggersTest.java
+++ b/sonar-plugin-api/src/test/java/org/sonar/api/utils/log/ConsoleLoggersTest.java
@@ -34,14 +34,11 @@ public class ConsoleLoggersTest {
   }
 
   @Test
-  public void debugMode() throws Exception {
-    // disabled by default
-    assertThat(sut.isDebugEnabled()).isFalse();
+  public void level() throws Exception {
+    // INFO by default
+    assertThat(sut.getLevel()).isEqualTo(LoggerLevel.INFO);
 
-    sut.enableDebug(true);
-    assertThat(sut.isDebugEnabled()).isTrue();
-
-    sut.enableDebug(false);
-    assertThat(sut.isDebugEnabled()).isFalse();
+    sut.setLevel(LoggerLevel.DEBUG);
+    assertThat(sut.getLevel()).isEqualTo(LoggerLevel.DEBUG);
   }
 }
diff --git a/sonar-plugin-api/src/test/java/org/sonar/api/utils/log/DefaultProfilerTest.java b/sonar-plugin-api/src/test/java/org/sonar/api/utils/log/DefaultProfilerTest.java
new file mode 100644
index 00000000000..3bf72652db7
--- /dev/null
+++ b/sonar-plugin-api/src/test/java/org/sonar/api/utils/log/DefaultProfilerTest.java
@@ -0,0 +1,183 @@
+/*
+ * SonarQube, open source software quality management tool.
+ * Copyright (C) 2008-2014 SonarSource
+ * mailto:contact AT sonarsource DOT com
+ *
+ * SonarQube is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU Lesser General Public
+ * License as published by the Free Software Foundation; either
+ * version 3 of the License, or (at your option) any later version.
+ *
+ * SonarQube is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+ * Lesser General Public License for more details.
+ *
+ * You should have received a copy of the GNU Lesser General Public License
+ * along with this program; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin Street, Fifth Floor, Boston, MA  02110-1301, USA.
+ */
+package org.sonar.api.utils.log;
+
+import org.junit.Rule;
+import org.junit.Test;
+
+import static org.assertj.core.api.Assertions.assertThat;
+import static org.junit.Assert.fail;
+
+public class DefaultProfilerTest {
+
+  @Rule
+  public LogTester tester = new LogTester();
+
+  Profiler sut = Profiler.create(Loggers.get("DefaultProfilerTest"));
+
+  @Test
+  public void test_levels() throws Exception {
+    // trace by default
+    assertThat(sut.isDebugEnabled()).isTrue();
+    assertThat(sut.isTraceEnabled()).isTrue();
+
+    tester.setLevel(LoggerLevel.DEBUG);
+    assertThat(sut.isDebugEnabled()).isTrue();
+    assertThat(sut.isTraceEnabled()).isFalse();
+
+    tester.setLevel(LoggerLevel.INFO);
+    assertThat(sut.isDebugEnabled()).isFalse();
+    assertThat(sut.isTraceEnabled()).isFalse();
+  }
+
+  @Test
+  public void stop_reuses_start_message() throws Exception {
+    tester.setLevel(LoggerLevel.TRACE);
+
+    // trace
+    sut.startTrace("Register rules");
+    assertThat(tester.logs()).containsOnly("Register rules");
+    sut.stopTrace();
+    assertThat(tester.logs()).hasSize(2);
+    assertThat(tester.logs().get(1)).startsWith("Register rules (done) | time=");
+    tester.clear();
+
+    // debug
+    sut.startDebug("Register rules");
+    assertThat(tester.logs()).containsOnly("Register rules");
+    sut.stopTrace();
+    assertThat(tester.logs()).hasSize(2);
+    assertThat(tester.logs().get(1)).startsWith("Register rules (done) | time=");
+    tester.clear();
+
+    // info
+    sut.startInfo("Register rules");
+    assertThat(tester.logs()).containsOnly("Register rules");
+    sut.stopTrace();
+    assertThat(tester.logs()).hasSize(2);
+    assertThat(tester.logs().get(1)).startsWith("Register rules (done) | time=");
+  }
+
+  @Test
+  public void different_start_and_stop_messages() throws Exception {
+    tester.setLevel(LoggerLevel.TRACE);
+
+    // start TRACE and stop DEBUG
+    sut.startTrace("Register rules");
+    sut.stopDebug("Rules registered");
+    assertThat(tester.logs()).hasSize(2);
+    assertThat(tester.logs().get(0)).contains("Register rules");
+    assertThat(tester.logs().get(1)).startsWith("Rules registered | time=");
+    tester.clear();
+
+    // start DEBUG and stop INFO
+    sut.startDebug("Register rules");
+    sut.stopInfo("Rules registered");
+    assertThat(tester.logs()).hasSize(2);
+    assertThat(tester.logs().get(0)).contains("Register rules");
+    assertThat(tester.logs().get(1)).startsWith("Rules registered | time=");
+    tester.clear();
+
+    // start INFO and stop TRACE
+    sut.startInfo("Register rules");
+    sut.stopTrace("Rules registered");
+    assertThat(tester.logs()).hasSize(2);
+    assertThat(tester.logs().get(0)).contains("Register rules");
+    assertThat(tester.logs().get(1)).startsWith("Rules registered | time=");
+  }
+
+  @Test
+  public void log_on_at_stop() throws Exception {
+    tester.setLevel(LoggerLevel.TRACE);
+
+    // trace
+    sut.start();
+    sut.stopTrace("Rules registered");
+    assertThat(tester.logs()).hasSize(1);
+    assertThat(tester.logs().get(0)).startsWith("Rules registered | time=");
+    tester.clear();
+
+    // debug
+    sut.start();
+    sut.stopDebug("Rules registered");
+    assertThat(tester.logs()).hasSize(1);
+    assertThat(tester.logs().get(0)).startsWith("Rules registered | time=");
+    tester.clear();
+
+    // info
+    sut.start();
+    sut.stopInfo("Rules registered");
+    assertThat(tester.logs()).hasSize(1);
+    assertThat(tester.logs().get(0)).startsWith("Rules registered | time=");
+  }
+
+  @Test
+  public void add_context() throws Exception {
+    Profiler profiler = Profiler.create(Loggers.get("DefaultProfilerTest"));
+    profiler.addContext("a_string", "bar");
+    profiler.addContext("null_value", null);
+    profiler.addContext("an_int", 42);
+    profiler.start();
+    // do not write context as there's no message
+    assertThat(tester.logs()).isEmpty();
+
+    profiler.addContext("after_start", true);
+    profiler.stopInfo("Rules registered");
+    assertThat(tester.logs()).hasSize(1);
+    assertThat(tester.logs().get(0))
+      .startsWith("Rules registered | time=")
+      .endsWith("ms | a_string=bar | an_int=42 | after_start=true");
+  }
+
+  @Test
+  public void empty_message() throws Exception {
+    sut.addContext("foo", "bar");
+    sut.startInfo("");
+    assertThat(tester.logs()).containsOnly("foo=bar");
+
+    sut.addContext("after_start", true);
+    sut.stopInfo("");
+    assertThat(tester.logs()).hasSize(2);
+    assertThat(tester.logs().get(1))
+      .startsWith("time=")
+      .endsWith("ms | foo=bar | after_start=true");
+  }
+
+  @Test
+  public void fail_if_stop_without_message() throws Exception {
+    sut.start();
+    try {
+      sut.stopInfo();
+      fail();
+    } catch (IllegalStateException e) {
+      assertThat(e).hasMessage("Profiler#stopXXX() can't be called without any message defined in start methods");
+    }
+  }
+
+  @Test
+  public void fail_if_stop_without_start() throws Exception {
+    try {
+      sut.stopDebug("foo");
+      fail();
+    } catch (IllegalStateException e) {
+      assertThat(e).hasMessage("Profiler must be started before being stopped");
+    }
+  }
+}
diff --git a/sonar-plugin-api/src/test/java/org/sonar/api/utils/log/LogTesterTest.java b/sonar-plugin-api/src/test/java/org/sonar/api/utils/log/LogTesterTest.java
index 32bb1000bd6..8b10230815b 100644
--- a/sonar-plugin-api/src/test/java/org/sonar/api/utils/log/LogTesterTest.java
+++ b/sonar-plugin-api/src/test/java/org/sonar/api/utils/log/LogTesterTest.java
@@ -29,22 +29,22 @@ public class LogTesterTest {
 
   @Test
   public void debugLevel() throws Throwable {
-    boolean initial = sut.isDebugEnabled();
+    LoggerLevel initial = sut.getLevel();
 
     // when LogTester is used, then debug logs are enabled by default
     sut.before();
-    assertThat(sut.isDebugEnabled()).isTrue();
-    assertThat(Loggers.getFactory().isDebugEnabled()).isTrue();
+    assertThat(sut.getLevel()).isEqualTo(LoggerLevel.TRACE);
+    assertThat(Loggers.getFactory().getLevel()).isEqualTo(LoggerLevel.TRACE);
 
     // change
-    sut.enableDebug(false);
-    assertThat(sut.isDebugEnabled()).isFalse();
-    assertThat(Loggers.getFactory().isDebugEnabled()).isFalse();
+    sut.setLevel(LoggerLevel.INFO);
+    assertThat(sut.getLevel()).isEqualTo(LoggerLevel.INFO);
+    assertThat(Loggers.getFactory().getLevel()).isEqualTo(LoggerLevel.INFO);
 
-    // reset to initial level
+    // reset to initial level after execution of test
     sut.after();
-    assertThat(sut.isDebugEnabled()).isEqualTo(initial);
-    assertThat(Loggers.getFactory().isDebugEnabled()).isEqualTo(initial);
+    assertThat(sut.getLevel()).isEqualTo(initial);
+    assertThat(Loggers.getFactory().getLevel()).isEqualTo(initial);
   }
 
   @Test
@@ -55,7 +55,10 @@ public class LogTesterTest {
 
     assertThat(sut.logs()).containsExactly("an information", "warning: 42");
 
+    sut.clear();
+    assertThat(sut.logs()).isEmpty();
+
     sut.after();
-    assertThat(LogInterceptor.instance).isSameAs(NullInterceptor.NULL_INSTANCE);
+    assertThat(LogInterceptor.instance()).isSameAs(NullInterceptor.NULL_INSTANCE);
   }
 }
diff --git a/sonar-plugin-api/src/test/java/org/sonar/api/utils/log/LogbackLoggerTest.java b/sonar-plugin-api/src/test/java/org/sonar/api/utils/log/LogbackLoggerTest.java
index 7bb3ff87068..f17cb9f799f 100644
--- a/sonar-plugin-api/src/test/java/org/sonar/api/utils/log/LogbackLoggerTest.java
+++ b/sonar-plugin-api/src/test/java/org/sonar/api/utils/log/LogbackLoggerTest.java
@@ -25,6 +25,7 @@ import org.junit.Test;
 import org.slf4j.LoggerFactory;
 
 import static org.assertj.core.api.Assertions.assertThat;
+import static org.junit.Assert.fail;
 
 public class LogbackLoggerTest {
 
@@ -34,17 +35,13 @@ public class LogbackLoggerTest {
   public LogTester tester = new LogTester();
 
   @Test
-  public void debug_enabling() throws Exception {
-    tester.enableDebug(true);
-    assertThat(sut.isDebugEnabled()).isTrue();
-
-    tester.enableDebug(false);
-    assertThat(sut.isDebugEnabled()).isFalse();
-  }
-
-  @Test
   public void log() throws Exception {
     // no assertions. Simply verify that calls do not fail.
+    sut.trace("message");
+    sut.trace("message {}", "foo");
+    sut.trace("message {} {}", "foo", "bar");
+    sut.trace("message {} {} {}", "foo", "bar", "baz");
+
     sut.debug("message");
     sut.debug("message {}", "foo");
     sut.debug("message {} {}", "foo", "bar");
@@ -69,17 +66,32 @@ public class LogbackLoggerTest {
 
   @Test
   public void change_level() throws Exception {
-    assertThat(sut.setLevel(LoggerLevel.ERROR)).isTrue();
-    assertThat(sut.logbackLogger().getLevel()).isEqualTo(Level.ERROR);
-
-    assertThat(sut.setLevel(LoggerLevel.WARN)).isTrue();
-    assertThat(sut.logbackLogger().getLevel()).isEqualTo(Level.WARN);
-
     assertThat(sut.setLevel(LoggerLevel.INFO)).isTrue();
     assertThat(sut.logbackLogger().getLevel()).isEqualTo(Level.INFO);
+    assertThat(sut.isDebugEnabled()).isFalse();
+    assertThat(sut.isTraceEnabled()).isFalse();
 
     assertThat(sut.setLevel(LoggerLevel.DEBUG)).isTrue();
+    assertThat(sut.isDebugEnabled()).isTrue();
+    assertThat(sut.isTraceEnabled()).isFalse();
     assertThat(sut.logbackLogger().getLevel()).isEqualTo(Level.DEBUG);
+
+    assertThat(sut.setLevel(LoggerLevel.TRACE)).isTrue();
     assertThat(sut.isDebugEnabled()).isTrue();
+    assertThat(sut.isTraceEnabled()).isTrue();
+    assertThat(sut.logbackLogger().getLevel()).isEqualTo(Level.TRACE);
+  }
+
+  @Test
+  public void info_level_can_not_be_disabled() throws Exception {
+    try {
+      sut.setLevel(LoggerLevel.ERROR);
+      fail();
+
+    } catch (IllegalArgumentException e) {
+      assertThat(e).hasMessage("Only TRACE, DEBUG and INFO logging levels are supported. Got: ERROR");
+    }
+
+
   }
 }
diff --git a/sonar-plugin-api/src/test/java/org/sonar/api/utils/log/NullProfilerTest.java b/sonar-plugin-api/src/test/java/org/sonar/api/utils/log/NullProfilerTest.java
new file mode 100644
index 00000000000..a094ebb368e
--- /dev/null
+++ b/sonar-plugin-api/src/test/java/org/sonar/api/utils/log/NullProfilerTest.java
@@ -0,0 +1,48 @@
+/*
+ * SonarQube, open source software quality management tool.
+ * Copyright (C) 2008-2014 SonarSource
+ * mailto:contact AT sonarsource DOT com
+ *
+ * SonarQube is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU Lesser General Public
+ * License as published by the Free Software Foundation; either
+ * version 3 of the License, or (at your option) any later version.
+ *
+ * SonarQube is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+ * Lesser General Public License for more details.
+ *
+ * You should have received a copy of the GNU Lesser General Public License
+ * along with this program; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin Street, Fifth Floor, Boston, MA  02110-1301, USA.
+ */
+package org.sonar.api.utils.log;
+
+import org.junit.Test;
+
+import static org.assertj.core.api.Assertions.assertThat;
+
+public class NullProfilerTest {
+
+  NullProfiler sut = NullProfiler.NULL_INSTANCE;
+
+  @Test
+  public void do_not_fail() throws Exception {
+    assertThat(sut.start()).isSameAs(sut);
+    assertThat(sut.startTrace("")).isSameAs(sut);
+    assertThat(sut.startDebug("")).isSameAs(sut);
+    assertThat(sut.startInfo("")).isSameAs(sut);
+
+    assertThat(sut.stopTrace()).isSameAs(sut);
+    assertThat(sut.stopTrace("")).isSameAs(sut);
+    assertThat(sut.stopDebug("")).isSameAs(sut);
+    assertThat(sut.stopDebug()).isSameAs(sut);
+    assertThat(sut.stopInfo()).isSameAs(sut);
+    assertThat(sut.stopInfo("")).isSameAs(sut);
+
+    assertThat(sut.isDebugEnabled()).isFalse();
+    assertThat(sut.isTraceEnabled()).isFalse();
+    assertThat(sut.addContext("foo", "bar")).isSameAs(sut);
+  }
+}
diff --git a/sonar-plugin-api/src/test/java/org/sonar/api/utils/log/ProfilerTest.java b/sonar-plugin-api/src/test/java/org/sonar/api/utils/log/ProfilerTest.java
new file mode 100644
index 00000000000..6a9e0b9c36d
--- /dev/null
+++ b/sonar-plugin-api/src/test/java/org/sonar/api/utils/log/ProfilerTest.java
@@ -0,0 +1,58 @@
+/*
+ * SonarQube, open source software quality management tool.
+ * Copyright (C) 2008-2014 SonarSource
+ * mailto:contact AT sonarsource DOT com
+ *
+ * SonarQube is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU Lesser General Public
+ * License as published by the Free Software Foundation; either
+ * version 3 of the License, or (at your option) any later version.
+ *
+ * SonarQube is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+ * Lesser General Public License for more details.
+ *
+ * You should have received a copy of the GNU Lesser General Public License
+ * along with this program; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin Street, Fifth Floor, Boston, MA  02110-1301, USA.
+ */
+package org.sonar.api.utils.log;
+
+import org.junit.Rule;
+import org.junit.Test;
+
+import static org.assertj.core.api.Assertions.assertThat;
+
+public class ProfilerTest {
+  @Rule
+  public LogTester tester = new LogTester();
+
+  @Test
+  public void create() throws Exception {
+    Profiler profiler = Profiler.create(Loggers.get("foo"));
+    assertThat(profiler).isInstanceOf(DefaultProfiler.class);
+  }
+
+  @Test
+  public void create_null_profiler_if_trace_level_is_disabled() throws Exception {
+    tester.setLevel(LoggerLevel.TRACE);
+    Profiler profiler = Profiler.createIfTrace(Loggers.get("foo"));
+    assertThat(profiler).isInstanceOf(DefaultProfiler.class);
+
+    tester.setLevel(LoggerLevel.DEBUG);
+    profiler = Profiler.createIfTrace(Loggers.get("foo"));
+    assertThat(profiler).isInstanceOf(NullProfiler.class);
+  }
+
+  @Test
+  public void create_null_profiler_if_debug_level_is_disabled() throws Exception {
+    tester.setLevel(LoggerLevel.TRACE);
+    Profiler profiler = Profiler.createIfDebug(Loggers.get("foo"));
+    assertThat(profiler).isInstanceOf(DefaultProfiler.class);
+
+    tester.setLevel(LoggerLevel.INFO);
+    profiler = Profiler.createIfDebug(Loggers.get("foo"));
+    assertThat(profiler).isInstanceOf(NullProfiler.class);
+  }
+}