public void execute() { Profiler stepProfiler = Profiler.create(LOGGER).logTimeLast(true); boolean allStepsExecuted = false; try { executeSteps(stepProfiler); allStepsExecuted = true; } finally { if (listener != null) { executeListener(allStepsExecuted); } } }
private static Profiler startLogProfiler(CeTask task) { Profiler profiler = Profiler.create(LOG) .logTimeLast(true) .addContext("project", task.getMainComponent().flatMap(CeTask.Component::getKey).orElse(null)) .addContext("type", task.getType()); for (Map.Entry<String, String> characteristic : task.getCharacteristics().entrySet()) { profiler.addContext(characteristic.getKey(), characteristic.getValue()); } return profiler .addContext("id", task.getUuid()) .addContext("submitter", submitterOf(task)) .startInfo("Execute task"); }
@Test public void stopInfo_adds_context_before_time_if_logTimeLast_is_true() { addSomeContext(underTest); underTest.logTimeLast(true); underTest.start().stopInfo("Rules registered"); assertThat(tester.logs()).hasSize(1); assertThat(tester.logs(LoggerLevel.INFO).get(0)) .startsWith("Rules registered | a_string=bar | an_int=42 | after_start=true | time=") .endsWith("ms"); }
@Test public void stopTrace_adds_context_before_time_if_logTimeLast_is_true() { tester.setLevel(LoggerLevel.TRACE); addSomeContext(underTest); underTest.logTimeLast(true); underTest.start().stopTrace("Rules registered"); assertThat(tester.logs()).hasSize(1); assertThat(tester.logs(LoggerLevel.TRACE).get(0)) .startsWith("Rules registered | a_string=bar | an_int=42 | after_start=true | time=") .endsWith("ms"); }
@Test public void stopError_adds_context_before_time_if_logTimeLast_is_true() { addSomeContext(underTest); underTest.logTimeLast(true); underTest.start().stopError("Rules registered"); assertThat(tester.logs()).hasSize(1); assertThat(tester.logs(LoggerLevel.ERROR).get(0)) .startsWith("Rules registered | a_string=bar | an_int=42 | after_start=true | time=") .endsWith("ms"); }
@Test public void stopInfo_clears_context() { addSomeContext(underTest); underTest.logTimeLast(true); underTest.start().stopInfo("Foo"); underTest.start().stopInfo("Bar"); assertThat(tester.logs()).hasSize(2); List<String> logs = tester.logs(LoggerLevel.INFO); assertThat(logs.get(0)) .startsWith("Foo | a_string=bar | an_int=42 | after_start=true | time=") .endsWith("ms"); assertThat(logs.get(1)) .startsWith("Bar | time=") .endsWith("ms"); }
@Test @UseDataProvider("logTimeLastValues") public void different_start_and_stop_messages(boolean logTimeLast) { underTest.logTimeLast(logTimeLast); tester.setLevel(LoggerLevel.TRACE); // start TRACE and stop DEBUG underTest.startTrace("Register rules"); underTest.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 underTest.startDebug("Register rules {}", 10); underTest.stopInfo("Rules registered"); assertThat(tester.logs()).hasSize(2); assertThat(tester.logs().get(0)).contains("Register rules 10"); assertThat(tester.logs().get(1)).startsWith("Rules registered | time="); tester.clear(); // start INFO and stop TRACE underTest.startInfo("Register rules"); underTest.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 stopDebug_clears_context() { tester.setLevel(LoggerLevel.DEBUG); addSomeContext(underTest); underTest.logTimeLast(true); underTest.start().stopDebug("Foo"); underTest.start().stopDebug("Bar"); assertThat(tester.logs()).hasSize(2); List<String> logs = tester.logs(LoggerLevel.DEBUG); assertThat(logs.get(0)) .startsWith("Foo | a_string=bar | an_int=42 | after_start=true | time=") .endsWith("ms"); assertThat(logs.get(1)) .startsWith("Bar | time=") .endsWith("ms"); }
@Test public void stopTrace_clears_context() { tester.setLevel(LoggerLevel.TRACE); addSomeContext(underTest); underTest.logTimeLast(true); underTest.start().stopTrace("Foo"); underTest.start().stopTrace("Bar"); assertThat(tester.logs()).hasSize(2); List<String> logs = tester.logs(LoggerLevel.TRACE); assertThat(logs.get(0)) .startsWith("Foo | a_string=bar | an_int=42 | after_start=true | time=") .endsWith("ms"); assertThat(logs.get(1)) .startsWith("Bar | time=") .endsWith("ms"); }
@Test @UseDataProvider("logTimeLastValues") public void log_on_at_stop(boolean logTimeLast) { underTest.logTimeLast(logTimeLast); tester.setLevel(LoggerLevel.TRACE); // trace underTest.start(); underTest.stopTrace("Rules registered"); assertThat(tester.logs()).hasSize(1); assertThat(tester.logs().get(0)).startsWith("Rules registered | time="); tester.clear(); // debug underTest.start(); underTest.stopDebug("Rules registered {} on {}", 6, 10); assertThat(tester.logs()).hasSize(1); assertThat(tester.logs().get(0)).startsWith("Rules registered 6 on 10 | time="); tester.clear(); // info underTest.start(); underTest.stopInfo("Rules registered"); assertThat(tester.logs()).hasSize(1); assertThat(tester.logs().get(0)).startsWith("Rules registered | time="); }
@Test @UseDataProvider("logTimeLastValues") public void stop_reuses_start_message(boolean logTimeLast) throws InterruptedException { underTest.logTimeLast(logTimeLast); tester.setLevel(LoggerLevel.TRACE);
private static void addContext(Profiler profiler, CeTask task) { profiler .logTimeLast(true) .addContext("project", task.getComponentKey()) .addContext("type", task.getType()) .addContext("id", task.getUuid()); String submitterLogin = task.getSubmitterLogin(); if (submitterLogin != null) { profiler.addContext("submitter", submitterLogin); } } }