Empty jetty.start file

[ferreira-alexandre]

I am experiencing a intemitent problem when a start a jetty container: Instead of keep server running the container exits with code 0.

Docker logs shows this message:

2018-06-29 22:42:57.000:INFO:docker-entrypoint:jetty start from /var/lib/jetty/jetty.start

Investigating the docker-entrypoint.sh I've discovery that the only point where this message is displayed is inside a if block that checks the existence of the jetty.start file, and in that case, execute the contents of it. But the problem is that there is no coding creating this file.

I'am using a Ubuntu 16.04 virtualbox machine, the problem only occours in the fist time docker is called in that VM. The container that is created with this error condition will never start again, but if I try "docker run" again the new container created works perfectly. If I destroy the VM and recreate it (I am using Vagrant and Puppet to recreate the machine and install docker every time) the problem may occour again. I've destroyed the VM 10 times, in 6 times the container did not start, because of this problem: A empty jetty.start file and the message above in the docker logs.

I've encounter this problem with a Docker file I've build from the "jetty:9.4-jre8" and with the "jetty:9.4-jre8" image itself.

I've found the empty jetty.start file because I've copied the /var/lib/jetty folder from the container that did not started to a folder, and check it's contents.

Anyone has any idea of how this could happen? I've checked the docker-entrypoint,sh several times, and does not make any sense, this is the part when it checks the existance of the file and log the message thai is appearing to me in docker logs:

if [ -f $JETTY_START ] ; then
    if [ $JETTY_BASE/start.d -nt $JETTY_START ] ; then
      cat >&2 <<- EOWARN
      ********************************************************************
      WARNING: The $JETTY_BASE/start.d directory has been modified since
               the $JETTY_START files was generated. Either delete
               the $JETTY_START file or re-run
                   /generate-jetty.start.sh
               from a Dockerfile
      ********************************************************************
      EOWARN
    fi
    echo $(date +'%Y-%m-%d %H:%M:%S.000'):INFO:docker-entrypoint:jetty start from $JETTY_START
    set -- $(cat $JETTY_START)
  else

Any help would be appreciated. Thanks!

More Details:

Output of "docker logs" after trying "docker start" 3 times:

2018-06-29 15:54:02.000:INFO:docker-entrypoint:jetty start from /var/lib/jetty/jetty.start
2018-06-29 17:47:01.000:INFO:docker-entrypoint:jetty start from /var/lib/jetty/jetty.start
2018-06-29 22:42:57.000:INFO:docker-entrypoint:jetty start from /var/lib/jetty/jetty.start

Checking the "/var/lib/docker/aufs/diff" I could find the layer where the empty file was introcuced with the command:

root@puppet-PC57-120:/var/lib/docker/aufs/diff# find -name jetty.start`
Output: 
./8df891c9347e500e9c48a7228dc538633210e759746a5f22eb8172921652111d/var/lib/jetty/jetty.start

Listing the contents of this layer:

root@puppet-PC57-120:/var/lib/docker/aufs/diff/8df891c9347e500e9c48a7228dc538633210e759746a5f22eb8172921652111d# tree
.
├── tmp
│   └── hsperfdata_jetty
│       └── 9
└── var
    └── lib
        └── jetty
            ├── jetty.start
            └── logs

6 directories, 2 files 

Docker history of the image:

IMAGE               CREATED             CREATED BY                                      SIZE                COMMENT
d0a341de0d9e        8 weeks ago         /bin/sh -c #(nop)  CMD ["java" "-jar" "/us...   0B
<missing>           8 weeks ago         /bin/sh -c #(nop)  EXPOSE 8080/tcp              0B
<missing>           8 weeks ago         /bin/sh -c #(nop)  USER [jetty]                 0B
<missing>           8 weeks ago         /bin/sh -c #(nop) COPY file:d462f1618b7d60...   82.6MB
<missing>           8 weeks ago         rm -r /var/lib/jetty/webapps                    0B
<missing>           2 months ago        /bin/sh -c #(nop)  HEALTHCHECK &{["CMD-SHE...   0B
<missing>           2 months ago        /bin/sh -c #(nop)  MAINTAINER TI Quantum <...   0B
<missing>           3 months ago        /bin/sh -c #(nop)  CMD ["java" "-jar" "/us...   0B
<missing>           3 months ago        /bin/sh -c #(nop)  ENTRYPOINT ["/docker-en...   0B
<missing>           3 months ago        /bin/sh -c #(nop)  EXPOSE 8080/tcp              0B
<missing>           3 months ago        /bin/sh -c #(nop)  USER [jetty]                 0B
<missing>           3 months ago        /bin/sh -c #(nop) COPY multi:4510ce2f7fb95...   3.26kB
<missing>           3 months ago        /bin/sh -c set -xe  && mkdir -p "$TMPDIR" ...   0B
<missing>           3 months ago        /bin/sh -c #(nop)  ENV TMPDIR=/tmp/jetty        0B
<missing>           3 months ago        /bin/sh -c set -xe  && java -jar "$JETTY_H...   4.75kB
<missing>           3 months ago        /bin/sh -c #(nop) WORKDIR /var/lib/jetty        0B
<missing>           3 months ago        /bin/sh -c mkdir -p "$JETTY_BASE"               0B
<missing>           3 months ago        /bin/sh -c #(nop)  ENV JETTY_BASE=/var/lib...   0B
<missing>           3 months ago        /bin/sh -c set -xe  && curl -SL "$JETTY_TG...   9.69MB
<missing>           3 months ago        /bin/sh -c #(nop)  ENV JETTY_GPG_KEYS=AED5...   0B
<missing>           3 months ago        /bin/sh -c #(nop)  ENV JETTY_TGZ_URL=https...   0B
<missing>           3 months ago        /bin/sh -c #(nop)  ENV JETTY_VERSION=9.4.9...   0B
<missing>           3 months ago        /bin/sh -c #(nop) WORKDIR /usr/local/jetty      0B
<missing>           3 months ago        /bin/sh -c mkdir -p "$JETTY_HOME"               0B
<missing>           3 months ago        /bin/sh -c #(nop)  ENV PATH=/usr/local/jet...   0B
<missing>           3 months ago        /bin/sh -c #(nop)  ENV JETTY_HOME=/usr/loc...   0B
<missing>           3 months ago        /bin/sh -c groupadd -r jetty && useradd -r...   329kB
<missing>           3 months ago        /bin/sh -c /var/lib/dpkg/info/ca-certifica...   394kB
<missing>           3 months ago        /bin/sh -c set -ex;   if [ ! -d /usr/share...   393MB
<missing>           3 months ago        /bin/sh -c #(nop)  ENV CA_CERTIFICATES_JAV...   0B
<missing>           3 months ago        /bin/sh -c #(nop)  ENV JAVA_DEBIAN_VERSION...   0B
<missing>           3 months ago        /bin/sh -c #(nop)  ENV JAVA_VERSION=8u162       0B
<missing>           3 months ago        /bin/sh -c #(nop)  ENV JAVA_HOME=/docker-j...   0B
<missing>           3 months ago        /bin/sh -c ln -svT "/usr/lib/jvm/java-8-op...   33B
<missing>           3 months ago        /bin/sh -c {   echo '#!/bin/sh';   echo 's...   87B
<missing>           3 months ago        /bin/sh -c #(nop)  ENV LANG=C.UTF-8             0B
<missing>           3 months ago        /bin/sh -c apt-get update && apt-get insta...   2.05MB
<missing>           3 months ago        /bin/sh -c set -ex;  if ! command -v gpg >...   7.8MB
<missing>           3 months ago        /bin/sh -c apt-get update && apt-get insta...   23.8MB
<missing>           3 months ago        /bin/sh -c #(nop)  CMD ["bash"]                 0B
<missing>           3 months ago        /bin/sh -c #(nop) ADD file:b380df301ccb5ca...   100MB

Dockerfile beeing used:

FROM jetty:9.4-jre8

HEALTHCHECK --interval=30s --timeout=3s --start-period=10m \
    CMD curl -f http://localhost:8080/health

RUN ["rm","-r","/var/lib/jetty/webapps"]
COPY target/servico.calculo.war  /var/lib/jetty/webapps/ROOT.war

USER jetty
EXPOSE 8080
CMD ["java","-jar","/usr/local/jetty/start.jar"]

[gregw]

@ferreira-alexandre I'm a jetty expert, not a docker expert, so I'm struggling to make sense of this issue also - specially the variability of it!!!

So sometimes you create a container and it has an empty jetty.start file - which of course will not start anything. Sometimes when you create the container, it does work - do you know if this has no jetty.start file or jetty.start file with valid contents?

If an empty jetty.start file is in a layer, then surely it must have been created by the Dockerfile that created that image? Or is this layer from the container and not the image?? How can that be for the "jetty:9.4-jre8" image itself, which does not contain an empty jetty.start file?

Any chance of getting the history commands in full without the ... abbreviation?

[ferreira-alexandre]

Hi @gregw,

Sometimes when you create the container, it does work - do you know if this has no jetty.start file or jetty.start file with valid contents?

When everything works the jetty.start file has valid content, like this one:

ubuntu@puppet-PC57-226:~$ sudo docker cp b:/var/lib/jetty/jetty.start .
ubuntu@puppet-PC57-226:~$ cat jetty.start
/usr/lib/jvm/java-8-openjdk-amd64/jre/bin/java -Djava.io.tmpdir=/tmp -Djetty.home=/usr/local/jetty -Djetty.base=/var/lib/jetty -cp /usr/local/jetty/lib/mail/javax.mail.glassfish-1.4.1.v201005082020.jar:/var/lib/jetty/resources:/usr/local/jetty/lib/servlet-api-3.1.jar:/usr/local/jetty/lib/jetty-schemas-3.1.jar:/usr/local/jetty/lib/jetty-http-9.4.9.v20180320.jar:/usr/local/jetty/lib/jetty-server-9.4.9.v20180320.jar:/usr/local/jetty/lib/jetty-xml-9.4.9.v20180320.jar:/usr/local/jetty/lib/jetty-util-9.4.9.v20180320.jar:/usr/local/jetty/lib/jetty-io-9.4.9.v20180320.jar:/usr/local/jetty/lib/jetty-jndi-9.4.9.v20180320.jar:/usr/local/jetty/lib/jetty-security-9.4.9.v20180320.jar:/usr/local/jetty/lib/transactions/javax.transaction-api-1.2.jar:/usr/local/jetty/lib/jetty-servlet-9.4.9.v20180320.jar:/usr/local/jetty/lib/jetty-webapp-9.4.9.v20180320.jar:/usr/local/jetty/lib/jetty-plus-9.4.9.v20180320.jar:/usr/local/jetty/lib/jetty-annotations-9.4.9.v20180320.jar:/usr/local/jetty/lib/annotations/asm-6.0.jar:/usr/local/jetty/lib/annotations/asm-commons-6.0.jar:/usr/local/jetty/lib/annotations/javax.annotation-api-1.2.jar:/usr/local/jetty/lib/apache-jsp/org.eclipse.jdt.ecj-3.12.3.jar:/usr/local/jetty/lib/apache-jsp/org.eclipse.jetty.apache-jsp-9.4.9.v20180320.jar:/usr/local/jetty/lib/apache-jsp/org.mortbay.jasper.apache-el-8.5.24.2.jar:/usr/local/jetty/lib/apache-jsp/org.mortbay.jasper.apache-jsp-8.5.24.2.jar:/usr/local/jetty/lib/apache-jstl/org.apache.taglibs.taglibs-standard-impl-1.2.5.jar:/usr/local/jetty/lib/apache-jstl/org.apache.taglibs.taglibs-standard-spec-1.2.5.jar:/usr/local/jetty/lib/jetty-client-9.4.9.v20180320.jar:/usr/local/jetty/lib/jetty-deploy-9.4.9.v20180320.jar:/usr/local/jetty/lib/websocket/javax.websocket-api-1.0.jar:/usr/local/jetty/lib/websocket/javax-websocket-client-impl-9.4.9.v20180320.jar:/usr/local/jetty/lib/websocket/javax-websocket-server-impl-9.4.9.v20180320.jar:/usr/local/jetty/lib/websocket/websocket-api-9.4.9.v20180320.jar:/usr/local/jetty/lib/websocket/websocket-client-9.4.9.v20180320.jar:/usr/local/jetty/lib/websocket/websocket-common-9.4.9.v20180320.jar:/usr/local/jetty/lib/websocket/websocket-server-9.4.9.v20180320.jar:/usr/local/jetty/lib/websocket/websocket-servlet-9.4.9.v20180320.jar org.eclipse.jetty.xml.XmlConfiguration java.version=1.8.0_162 java.version.major=1 java.version.micro=0 java.version.minor=8 java.version.platform=8 jetty.base=/var/lib/jetty jetty.base.uri=file:///var/lib/jetty jetty.home=/usr/local/jetty jetty.home.uri=file:///usr/local/jetty /usr/local/jetty/etc/jetty-threadpool.xml /usr/local/jetty/etc/jetty.xml /usr/local/jetty/etc/jetty-webapp.xml /usr/local/jetty/etc/jetty-plus.xml /usr/local/jetty/etc/jetty-annotations.xml /usr/local/jetty/etc/jetty-deploy.xml /usr/local/jetty/etc/jetty-http.xml

If an empty jetty.start file is in a layer, then surely it must have been created by the Dockerfile that created that image? Or is this layer from the container and not the image?? How can that be for the "jetty:9.4-jre8" image itself, which does not contain an empty jetty.start file?

So, I did some research to understand this one (I am not a docker expert also) and found this two Stack Overflow's questions that complement each other:

https://stackoverflow.com/questions/43070640/how-to-link-docker-images-to-their-composing-layers-on-the-disk https://stackoverflow.com/questions/43070640/how-to-link-docker-images-to-their-composing-layers-on-the-disk

With the command suggested on the first one, I've confirmed that the layer containing the empty jetty.start file belongs to the container that did not started:

root@puppet-PC57-885:~# grep 8df891c9347e500e9c48a7228dc538633210e759746a5f22eb8172921652111d /var/lib/docker/image/aufs/layerdb/mounts/*/mount-id
/var/lib/docker/image/aufs/layerdb/mounts/ff5ca547360f5c7f895288483db4e7019c04cc4146926b5e757807c182a56d77/mount-id:8df891c9347e500e9c48a7228dc538633210e759746a5f22eb8172921652111d

root@puppet-PC57-885:~# docker ps -a --no-trunc
CONTAINER ID                                                       IMAGE                                    COMMAND                                                                                   CREATED             STATUS                   PORTS
NAMES
1e36085d02dc0116daf21e433556376f514f94267b367868124cff2118814851   quantum.azurecr.io/jmx_exporter:latest   "java -jar lib/jmx_prometheus_httpserver-0.9-jar-with-dependencies.jar 9000 config.yml"   5 days ago          Up 5 hours               0.0.0.0:9080->9000/tcp
seca_monitor_1
ff5ca547360f5c7f895288483db4e7019c04cc4146926b5e757807c182a56d77   quantum.azurecr.io/seca:3.0-RC6          "/docker-entrypoint.sh java -jar /usr/local/jetty/start.jar"                              5 days ago          Exited (0) 5 hours ago
seca_app_1

This brings me to conclusion that the empty jetty.start file could only be created from the execution of the entrypoint script (showed by the docker ps output above):

/docker-entrypoint.sh java -jar /usr/local/jetty/start.jar

Which brings me back to the original problem: how could the docker-entrypoint.sh script created this empty file? This script has a bit of complex shellscript, but as far I could understand, the script only refferences this file two times: When assing a variable:

: ${JETTY_START:=$JETTY_BASE/jetty.start}

And in this if-block:

if [ -f $JETTY_START ] ; then
    if [ $JETTY_BASE/start.d -nt $JETTY_START ] ; then
      cat >&2 <<- EOWARN
      ********************************************************************
      WARNING: The $JETTY_BASE/start.d directory has been modified since
               the $JETTY_START files was generated. Either delete
               the $JETTY_START file or re-run
                   /generate-jetty.start.sh
               from a Dockerfile
      ********************************************************************
      EOWARN
    fi
    echo $(date +'%Y-%m-%d %H:%M:%S.000'):INFO:docker-entrypoint:jetty start from $JETTY_START
    set -- $(cat $JETTY_START)
  else
    # Do a jetty dry run to set the final command
    "$@" --dry-run > $JETTY_START
    if [ $(egrep -v '\\$' $JETTY_START | wc -l ) -gt 1 ] ; then
      # command was more than a dry-run
      cat $JETTY_START \
      | awk '/\\$/ { printf "%s", substr($0, 1, length($0)-1); next } 1' \
      | egrep -v '[^ ]*java .* org\.eclipse\.jetty\.xml\.XmlConfiguration '
      exit
    fi
    set -- $(sed 's/\\$//' $JETTY_START)
  fi
fi

Is absolutelly strange that this if [ -f $JETTY_START ] returns true, since nothing happened before the execution of this script to create this file (since we noticed that there is nothing in "jetty:9.4-jre8" image that could create this file)

And there is nothing on our image also, as you can see with the (this time without the '...' abbreviation) docker history of the image:

docker_history.txt

As said before, the output of the docker logs shows that the execution of the docker-entrypoint.sh script entered in that if-block.

Thank you very much!

More info I've attached the docker-entrypoint.sh script extracted directly from the containter (replacing the "sh" extension for "txt"). docker-entrypoint.txt

[gregw]

@ferreira-alexandre So in summary:

• The base image and your extended image do not include a jetty.start file, nor do they call the generate-jetty-start.sh script (this suggests a work around - when you generate your image, run the generate-jetty-start.sh script so it contains known good contents)
• Working containers do have a valid jetty.start file, so this must have been generated by https://github.com/appropriate/docker-jetty/blob/master/docker-entrypoint.sh#L91
• Failing containers have an empty jetty.start file, which can only have been generated by that same line, failing in some way.
• Failing containers also have debug output that indicates that the jetty.start file existed at https://github.com/appropriate/docker-jetty/blob/master/docker-entrypoint.sh#L75 , which is before the generation step!?!?!? So this can only happen IFF the entrypoint script is being run twice??? perhaps even concurrently????

So there are a few steps of magic there that we are not seeing and something is going wrong in them. The work around suggested above may work, but it probably just avoiding the problem of the entrypoint script being run twice (which I think it must be?)

[ferreira-alexandre]

@gregw You where right, the script in fact did ran twice, (probably) concurrently!

I edited the docker-entrypoint.sh and put a echo STARTING docker-entrypoint.sh in the first line, rebuilded the image and executed the container until it fails. As expected, the log shows 2 of this messages:

ubuntu@puppet-PC57-944:/opt/seca$ sudo docker logs seca_app_1
STARTING docker-entrypoint.sh
STARTING docker-entrypoint.sh
2018-07-05 19:47:17.000:INFO:docker-entrypoint:jetty start from /var/lib/jetty/jetty.start

Thank you very much for this idea of concurrency, I did not think in this approach. Since I didn't know so much of Docker I was thinking that the problem was "some kind of Docker magic" that I couldn't undestand.

I did not say in the previous topics, but I am using Docker Compose to run this container, and in fact, there is opened issue in Docker Compose about the ENTRYPOINT be executed two times: https://github.com/docker/compose/issues/1280. Looking the dates of the last person who said that this still happening and the release date of the latest Docker Compose version, it seems that this issue was not fixed yet.

Now that I know what is causing the problem I can think in some workarounds.

The most relevant fact is that this is not a problem related to the Jetty container image or the Jetty itself.

Thank you again for helping me to find the cause! (this was bothering me for days) Best regards

[gregw]

Thanks for confirming the diagnosis!