spotify/docker-client

[2.7.6] Logs w/ follow hangs, or finalizer error

Open

#125 aperta il 18 feb 2015

Vedi su GitHub
 (11 commenti) (0 reazioni) (0 assegnatari)Java (551 fork)batch import
bughelp wantedpinned

Metriche repository

Star
 (1430 star)
Metriche merge PR
 (Nessuna PR mergiata in 30 g)

Descrizione

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))))))

Guida contributor