Improve logging

assembly/src/bin/ship

@@ -23,6 +23,7 @@ export SHIP_BIN=${SHIP_BIN:-$SHIP_HOME/bin}
 export SHIP_CONF=${SHIP_CONF:-$SHIP_HOME/conf}
 export SHIP_DOC=${SHIP_DOC:-$SHIP_HOME/doc}
 export SHIP_LIB=${SHIP_LIB:-$SHIP_HOME/lib}
+export SHIP_LOG=${SHIP_LOG:-$SHIP_HOME/log}
 
 JARS=$(find "$SHIP_LIB" -name 'bootstrap-*.jar')
 
@@ -34,6 +35,7 @@ java -cp "$JARS" \
 	"-Dlogging.config=$SHIP_CONF/ship-logger.xml" \
 	"-Dship.lib=$SHIP_LIB" \
 	"-Dship.conf=$SHIP_CONF" \
+	"-Dship.log=$SHIP_LOG" \
 	"-Dlogback.configurationFile=$SHIP_CONF/ship-logger.xml" ship.exec.LoaderLauncher $@
 
 # Add this to debug the ship.bootstrap mechanism for loading classes

assembly/src/conf/ship-logger.xml

@@ -9,9 +9,52 @@
       <Pattern>%d{HH:mm} %highlight(%-5level) %cyan(%logger{15}) - %msg%n</Pattern>
     </layout>
   </appender>
-  <root level="NONE">
-    <!--
-    <appender-ref ref="STDOUT" />
-    -->
-  </root>
+
+  <if condition='isDefined("SHIP_LOG")'>
+    <then>
+      <appender name="FILE-APPENDER" class="ch.qos.logback.core.FileAppender">
+        <file>${SHIP_LOG}/ship.log</file>
+        <append>true</append>
+        <!-- set immediateFlush to false for much higher logging throughput -->
+        <immediateFlush>true</immediateFlush>
+        <!-- encoders are assigned the type
+             ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->
+        <encoder>
+          <pattern>%-4relative [%thread] %-5level %logger{35}:%line - %msg%n</pattern>
+        </encoder>
+        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
+          <level>INFO</level>
+        </filter>
+      </appender>
+
+      <appender name="TRACE-APPENDER" class="ch.qos.logback.core.FileAppender">
+        <file>${SHIP_LOG}/trace.log</file>
+        <append>true</append>
+        <!-- set immediateFlush to false for much higher logging throughput -->
+        <immediateFlush>true</immediateFlush>
+        <!-- encoders are assigned the type
+             ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->
+        <encoder>
+          <pattern>%-4relative [%thread] %-5level %logger{35}:%line - %msg%n</pattern>
+        </encoder>
+      </appender>
+
+      <logger name="ship.util.AnsiMessagePrinter" level="INFO" />
+      <logger name="ship.util.FileWatcher" level="INFO" />
+      <logger name="ship.build.WebServer" level="DEBUG" />
+      <logger name="ship.build.web.service.BuildService" level="INFO" />
+
+      <root level="TRACE">
+        <appender-ref ref="TRACE-APPENDER" />
+        <appender-ref ref="FILE-APPENDER" />
+      </root>
+    </then>
+    <else>
+      <root level="NONE">
+        <!--
+            <appender-ref ref="STDOUT" />
+        -->
+      </root>
+    </else>
+  </if>
 </configuration>

build.gradle

@@ -84,6 +84,8 @@ configure(javaProjects) {
     implementation 'org.slf4j:slf4j-api:1.7.25'
 
     runtime 'ch.qos.logback:logback-classic:1.2.3'
+    runtime 'org.codehaus.janino:janino:3.0.6'
+    runtime 'org.codehaus.janino:commons-compiler:3.0.6'
     testImplementation 'org.projectlombok:lombok:1.18.2'
     testImplementation 'junit:junit:4.12'
     testImplementation('org.powermock:powermock-api-mockito2:2.0.0-beta.5') {

core/src/main/java/ship/build/web/service/BuildService.java

@@ -42,7 +42,7 @@ public void addListener(final DangerousConsumer<BuildSummary> listener) {
   public void save(final BuildDetails buildDetails) {
     buildDetails.setSequence(sequence.incrementAndGet());
     uuid2buildResult.put(buildDetails.getUuid(), buildDetails);
-    logger.info("New build detected: {}", buildDetails);
+    logger.debug("New build detected: {}", buildDetails);
     uuids.addFirst(buildDetails.getUuid());
     while (100 < uuids.size()) {
       final String uuid = uuids.removeLast();
@@ -81,4 +81,4 @@ public List<BuildSummary> list(final String from, final int requestSize) {
           .collect(toList());
     }
   }
-}
+}

core/src/main/java/ship/command/TestProject.java

@@ -87,7 +87,7 @@ protected void executeTest(final Builder builder, final String testPath) {
     final LuaSource executable = new LuaSource(buildDetails.getResult());
     testReporter.clear();
 
-    logger.trace("Executing test...");
+    logger.trace("Executing test {} ...", testPath);
     testReporter.start(testPath);
     final TestResult testResult = new LuaRunner().run(executable);
     final TestReportNode<LuaErrorInformation> testFile = testReporter.getCurrentTestFile();

core/src/main/java/ship/test/LuaSource.java

@@ -78,12 +78,12 @@ public String toString() {
    * @return formatted string
    */
   public String toString(final int from, final int to, final List<Integer> highlights) {
-    logger.debug("{} ~ {}", from, to);
+    logger.trace("toString({} ~ {})", from, to);
     final int digit = (int) (Math.log10(lines.length) + 1);
 
     assertTrue(from < to);
     final IntRange range = new IntRange(0, lines.length).select(new IntRange(from, to));
-    logger.trace("{}", range);
+    logger.trace("range: {}", range);
 
     final StringJoiner joiner = new StringJoiner("\n");
     IntStream.range(range.v1, range.v2)