Improve logging

[balhoff]

Addresses #131. I added logback and tried to clean up the logging packages pulled in via various dependencies. I also turned on request logging within akka-http.

@rpgoldman you should now be able to provide your own logback.xml via the command line. I included one in src/main/resources/logback.xml that prints at the DEBUG level. You should see a lot of OWL API output.

[rpgoldman]

@balhoff Sorry to be dense, but this is not working for me yet.

Is there any chance that things are going wrong because of the Dockerfile? I just noticed that nothing was really rebuilt when I did the docker build command. The Dockerfile does not use the repo it is embedded in, as far as I can tell. Instead it pulls a tarball (if I am reading the comments right:

   # Download and unpack owlery from the latest release on Github
ADD get-tarball-url.sh /tmp/get-tarball-url.sh
RUN echo "Building $APPNAME from "$(sh /tmp/get-tarball-url.sh $REPO $TARGET) && \
    curl -L -o /tmp/$APPNAME.tar.gz \
         $(sh /tmp/get-tarball-url.sh $REPO $TARGET) && \
    mkdir /tmp/$APPNAME && \
    tar -z -x -v --strip-components 1 -C /tmp/$APPNAME -f /tmp/$APPNAME.tar.gz

What's disturbing is that when I add the TARGET argument to make sure I get the code on master, it does not trigger a rebuild:

$ docker build --build-arg TARGET=master -t owlery:latest .
[+] Building 0.9s (18/18) FINISHED
 => [internal] load build definition from Dockerfile                                                                                                                                                 0.0s
 => => transferring dockerfile: 37B                                                                                                                                                                  0.0s
 => [internal] load .dockerignore                                                                                                                                                                    0.0s
 => => transferring context: 2B                                                                                                                                                                      0.0s
 => [internal] load metadata for docker.io/library/openjdk:8-jdk                                                                                                                                     0.7s
 => [auth] library/openjdk:pull token for registry-1.docker.io                                                                                                                                       0.0s
 => [ 1/12] FROM docker.io/library/openjdk:8-jdk@sha256:75739abc3852736798b0f0f897c98d8f587368e8e6cf9a2580289e3390b6432b                                                                             0.0s
 => [internal] load build context                                                                                                                                                                    0.0s
 => => transferring context: 74B                                                                                                                                                                     0.0s
 => CACHED [ 2/12] ADD create-user.sh /usr/local/bin/create-service-user                                                                                                                             0.0s
 => CACHED [ 3/12] RUN chmod ug+x /usr/local/bin/create-service-user                                                                                                                                 0.0s
 => CACHED [ 4/12] RUN create-service-user owlery owlery                                                                                                                                             0.0s
 => CACHED [ 5/12] RUN apt-get update -y &&     apt-get install -y apt-utils &&     apt-get install -y             apt-transport-https             fakeroot                                          0.0s
 => CACHED [ 6/12] RUN echo "deb https://repo.scala-sbt.org/scalasbt/debian all main" > /etc/apt/sources.list.d/sbt.list &&     apt-key adv --keyserver hkp://keyserver.ubuntu.com:80 --recv 2EE0EA  0.0s
 => CACHED [ 7/12] RUN apt-get update -y &&     apt-get install -y               sbt                                                                                                                 0.0s
 => CACHED [ 8/12] ADD get-tarball-url.sh /tmp/get-tarball-url.sh                                                                                                                                    0.0s
 => CACHED [ 9/12] RUN echo "Building owlery from "$(sh /tmp/get-tarball-url.sh phenoscape/owlery master) &&     curl -L -o /tmp/owlery.tar.gz          $(sh /tmp/get-tarball-url.sh phenoscape/owl  0.0s
 => CACHED [10/12] RUN cd /tmp/owlery &&     sbt stage                                                                                                                                               0.0s
 => CACHED [11/12] RUN cd /tmp/owlery &&     mv target/universal/stage /usr/share/owlery &&     chmod a+x /usr/share/owlery/bin/owlery &&     ln -s /usr/share/owlery/bin/owlery /usr/local/bin/owl  0.0s
 => CACHED [12/12] RUN mkdir /srv/conf                                                                                                                                                               0.0s
 => exporting to image                                                                                                                                                                               0.0s
 => => exporting layers                                                                                                                                                                              0.0s
 => => writing image sha256:d53d10830c22203c49a1f131a9e2b6152ff68cd3689e86bd385b69f3d121baf7                                                                                                         0.0s
 => => naming to docker.io/library/owlery:latest

I would expect that step 9 would force a rebuild, but it does not -- instead it treats the tarball as if it is cached. Is that the expected behavior?

[rpgoldman]

@balhoff This was my original report, before I noticed the Dockerfile issue above:

I have done the following

• put a copy of logback.xml into /srv/conf on the docker image (checked with bash)
• run the docker image with these options:

  JAVA_ARGS := '-Dorg.slf4j.simpleLogger.defaultLogLevel=DEBUG -Dlogback.configurationFile=/srv/conf/logback.xml'
  docker run --rm --env JAVA_OPTS=$(JAVA_ARGS) -p $(HOST_PORT):8080 -v $(makeFileDir)/server-files:/srv/owl -v $(makeFileDir)owlery-conf:/srv/conf owlery:latest | tee server.log
  

But I am not seeing the logger output yet.

I slightly modified your config file as follows, but the only change was the filename used -- I put it into the docker container.

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="10 seconds">

    <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <Pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{0}    %msg%n</Pattern>
        </encoder>
    </appender>


    <appender name="files" class="ch.qos.logback.core.FileAppender">
        <file>/srv/conf/owlery.log</file>
        <append>true</append>
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <Pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{0}    %msg%n</Pattern>
        </encoder>
    </appender>


    <root level="DEBUG">
        <appender-ref ref="stdout" />
        <appender-ref ref="files"/>
    </root>


</configuration>

and I see that my command line configuration seems to work:

# system properties
"logback" : {
    # system properties
    "configurationFile" : "/srv/conf/logback.xml"
},

[balhoff]

I see! It may be that it's not being rebuilt. I don't use docker myself so I have not been running that way. I'll look at the docker build as soon as I am able.

[hlapp]

@rpgoldman Docker caches image layers locally when building (each command is a layer). If the commands didn't change it will use the cached layer(s). You would first need to remove the image you already have, or supply --no-cache instead to the docker build command (see manual).