spotify/docker-client
View on GitHub[2.7.6] Logs w/ follow hangs, or finalizer error
Open
#125 opened on Feb 18, 2015
bughelp wantedpinned
Description
My code is starting a Docker container with a Postgres instance inside, and waiting for the output to include the text "database system is ready to accept connections".
My code works fine ... but after I see the target text things go wonky.
If I close the LogStream, my process hangs for a while, then gets an exception:
(start-container)
09:07:27.965 INFO no-correlation-id [nREPL-worker-3] c.s.d.c.DefaultDockerClient - Creating container with ContainerConfig: ContainerConfig{hostname=null, domainname=null, username=null, memory=null, memorySwap=null, cpuShares=null, cpuset=null, attachStdin=null, attachStdout=null, attachStderr=null, portSpecs=[62890:5432], exposedPorts=null, tty=null, openStdin=null, stdinOnce=null, env=null, cmd=null, image=quay.io/aviso/combined-db-migrated, volumes=null, workingDir=null, entrypoint=null, networkDisabled=null, onBuild=null}
09:07:28.096 INFO no-correlation-id [nREPL-worker-3] c.s.d.c.DefaultDockerClient - Starting container with HostConfig: HostConfig{binds=null, containerIDFile=null, lxcConf=null, privileged=null, portBindings=null, links=null, publishAllPorts=null, dns=null, dnsSearch=null, volumesFrom=null, networkMode=null}
2015-02-18 17:07:10 UTC LOG: database system was interrupted; last known up at 2015-02-12 21:40:56 UTC
2015-02-18 17:07:10 UTC LOG: database system was not properly shut down; automatic recovery in progress
2015-02-18 17:07:10 UTC LOG: redo starts at 0/1792078
2015-02-18 17:07:10 UTC LOG: record with zero length at 0/19DD660
2015-02-18 17:07:10 UTC LOG: redo done at 0/19DD620
2015-02-18 17:07:10 UTC LOG: last completed transaction was at log time 2015-02-12 21:41:06.015063+00
2015-02-18 17:07:11 UTC LOG: autovacuum launcher started
2015-02-18 17:07:11 UTC LOG: database system is ready to accept connections
up and running!
java.net.SocketTimeoutException: Read timed out
java.lang.RuntimeException: java.net.SocketTimeoutException: Read timed out
(pst)
clojure.core/eval core.clj: 3076
...
docker-utils/eval6732 form-init5456222565433859833.clj: 1
docker-utils/start-container docker_utils.clj: 151
docker-utils/launch-container docker_utils.clj: 128
docker-utils/wait-for-startup2 docker_utils.clj: 110
com.spotify.docker.client.LogStream.close LogStream.java: 74
com.spotify.docker.client.LogReader.close LogReader.java: 88
com.google.common.io.ByteStreams.copy ByteStreams.java: 175
org.glassfish.jersey.message.internal.ReaderInterceptorExecutor$UnCloseableInputStream.read ReaderInterceptorExecutor.java: 295
org.glassfish.jersey.message.internal.EntityInputStream.read EntityInputStream.java: 96
java.io.FilterInputStream.read FilterInputStream.java: 107
java.io.FilterInputStream.read FilterInputStream.java: 133
java.io.BufferedInputStream.read BufferedInputStream.java: 334
java.io.BufferedInputStream.read1 BufferedInputStream.java: 275
java.io.BufferedInputStream.fill BufferedInputStream.java: 235
org.apache.http.conn.EofSensorInputStream.read EofSensorInputStream.java: 137
org.apache.http.impl.io.ChunkedInputStream.read ChunkedInputStream.java: 169
org.apache.http.impl.io.ChunkedInputStream.nextChunk ChunkedInputStream.java: 206
org.apache.http.impl.io.ChunkedInputStream.getChunkSize ChunkedInputStream.java: 240
org.apache.http.impl.io.SessionInputBufferImpl.readLine SessionInputBufferImpl.java: 270
org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer SessionInputBufferImpl.java: 152
org.apache.http.impl.io.SessionInputBufferImpl.streamRead SessionInputBufferImpl.java: 136
java.net.SocketInputStream.read SocketInputStream.java: 121
java.net.SocketInputStream.read SocketInputStream.java: 150
java.net.SocketInputStream.socketRead0 SocketInputStream.java
java.net.SocketTimeoutException: Read timed out
java.lang.RuntimeException: java.net.SocketTimeoutException: Read timed out
(Obviously, I'm working in Clojure, but that should hopefully not be relevant).
On the other hand, if I skip the close step, things work fine ... but at some future point, I see this error in my console:
(System/gc)
=> nil
09:09:19.238 WARN no-correlation-id [Finalizer] c.s.d.c.LogStream - com.spotify.docker.client.LogStream@79220f71 not closed properly
If it helps, here's the code:
(defn- wait-for-startup2
"Waits for the container to startup. Returns nil or throws an exception."
[docker-client container-id container-name]
;; docker logs outputs to STDERR for some reason
(let [^LogStream logs (.. docker-client (logs container-id (into-array DockerClient$LogsParameter [DockerClient$LogsParameter/STDERR
DockerClient$LogsParameter/FOLLOW])))
utf-8 Charsets/UTF_8
;; A bit cumbersome to get the logs
cmd-fn (fn []
(if (.hasNext logs)
(->> logs .next .content (.decode utf-8) .toString)))
test-fn (fn [line]
(print line)
(and line
(re-find #"database system is ready to accept connections" line)))
wait-result (wait-until cmd-fn test-fn 5000)]
(println "up and running!")
; (.close logs)
(if (= ::timeout wait-result)
(throw (DockerException. (format "Docker container `%s' did not complete initialization before timeout." container-name))))))