Docker-maven-plugin: waiting on log randomly doesn't work

Created on 1 May 2017  路  31Comments  路  Source: fabric8io/docker-maven-plugin

Description

The wait on logging will often fail even though the logging statement is plainly visible in the logs. This is most often observed when running in Jenkins. There doesn't appear to be any pattern as running the build manually afterwards will usually fix it, but not always. Sometimes we have to rerun it two or three times in a row until it decides to see the logging.

Info

  • d-m-p version : 0.20.1
  • Maven version (mvn -v) : 3.3.9
  • Docker version : Docker version 1.13.1, build 092cba3
  • Simply running the build will fail about half of the time. We have a dockerized DropWizard service starting up and then we wait for the service to come up using the following setting:
                                    <wait>
                                        <log>(.*)(org\.eclipse\.jetty\.server\.Server: Started)(.*)</log>
                                        <time>60000</time>
                                    </wait>

We've tried various permutations from simply looking for "Started" to the regex noted above. The issue is never resolved. As often as not the following failed build output can be observed:

omitted> INFO  [2017-05-01 19:16:45,229] org.eclipse.jetty.server.AbstractConnector: Started admin@3804a9a8{HTTP/1.1,[http/1.1]}{0.0.0.0:8081}
omitted> INFO  [2017-05-01 19:16:45,229] org.eclipse.jetty.server.Server: Started @7161ms
[ERROR] DOCKER> [omitted] "omitted": Timeout after 120039 ms while waiting on log out '(.*)(org\.eclipse\.jetty\.server\.Server: Started)(.*)'
[ERROR] DOCKER> Error occurred during container startup, shutting down...
bug prio1
Source
picture redijedi
👍3

Most helpful comment

I'm still having this issue, with version 0.29.0.

picture riccardomarotti on 15 Apr 2019
👍6

All 31 comments

@redijedi Could you please try the following pattern: 

(?s)org\.eclipse\.jetty\.server\.Server:\s+Started

Does this help ?

rhuss picture rhuss on 2 May 2017

@rhuss

Thanks for the prompt reply! Unfortunately it's more of the same:

omitted> INFO  [2017-05-02 17:35:21,668] org.eclipse.jetty.server.handler.ContextHandler: Started i.d.j.MutableServletContextHandler@9687f55{/,null,AVAILABLE}
omitted> INFO  [2017-05-02 17:35:21,674] org.eclipse.jetty.server.Server: Started @6974ms
[ERROR] DOCKER> [omitted] "omitted": Timeout after 120040 ms while waiting on log out '(?s)org\.eclipse\.jetty\.server\.Server:\s+Started'
[ERROR] DOCKER> Error occurred during container startup, shutting down...
redijedi picture redijedi on 2 May 2017

You mean that is sporadically fails ? Or does it always fail ?

Could you please run it with mvn -X ... to get some more output (but please be aware it can get quite large) ? Please grep for "LogWaitChecker" and paste the result here.

rhuss picture rhuss on 2 May 2017

This is a VERY large file. Here is the output:

Log output

[DEBUG] DOCKER> LogWaitChecker: Waiting on Ignite node started OK
[DEBUG] DOCKER> LogWaitChecker: Pattern to match 'Ignite node started OK'
[DEBUG] DOCKER> LogWaitChecker: Waiting on verbose:
[DEBUG] DOCKER> LogWaitChecker: Pattern to match 'verbose:'
[DEBUG] DOCKER> LogWaitChecker: Waiting on PostgreSQL init process complete; ready for start up.
[DEBUG] DOCKER> LogWaitChecker: Pattern to match 'PostgreSQL init process complete; ready for start up.'
[DEBUG] DOCKER> LogWaitChecker: Tying to match '/home/wiremock/' [Pattern: verbose:] [thread: 27]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'The files belonging to this database system will be owned by user "postgres".' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'This user must also own the server process.' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'The database cluster will be initialized with locale "en_US.utf8".' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'The default database encoding has accordingly been set to "UTF8".' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '??? __files' [Pattern: verbose:] [thread: 27]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'The default text search configuration will be set to "english".' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '??? ??? id.json' [Pattern: verbose:] [thread: 27]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'Data page checksums are disabled.' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '??? mappings' [Pattern: verbose:] [thread: 27]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '??? get-address.json' [Pattern: verbose:] [thread: 27]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '' [Pattern: verbose:] [thread: 27]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '2 directories, 2 files' [Pattern: verbose:] [thread: 27]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'fixing permissions on existing directory /var/lib/postgresql/data ... ok' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'creating subdirectories ... ok' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'selecting default max_connections ... 100' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'selecting default shared_buffers ... 128MB' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'selecting dynamic shared memory implementation ... posix' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'creating configuration files ... ok' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".' [Pattern: verbose:] [thread: 27]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'SLF4J: Defaulting to no-operation (NOP) logger implementation' [Pattern: verbose:] [thread: 27]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.' [Pattern: verbose:] [thread: 27]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'creating template1 database in /var/lib/postgresql/data/base/1 ... ok' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'initializing pg_authid ... ok' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '/$$      /$$ /$$                     /$$      /$$                     /$$' [Pattern: verbose:] [thread: 27]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '| $$  /$ | $$|__/                    | $$$    /$$$                    | $$' [Pattern: verbose:] [thread: 27]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '| $$ /$$$| $$ /$$  /$$$$$$   /$$$$$$ | $$$$  /$$$$  /$$$$$$   /$$$$$$$| $$   /$$' [Pattern: verbose:] [thread: 27]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '| $$/$$ $$ $$| $$ /$$__  $$ /$$__  $$| $$ $$/$$ $$ /$$__  $$ /$$_____/| $$  /$$/' [Pattern: verbose:] [thread: 27]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '| $$$$_  $$$$| $$| $$  \__/| $$$$$$$$| $$  $$$| $$| $$  \ $$| $$      | $$$$$$/' [Pattern: verbose:] [thread: 27]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '| $$$/ \  $$$| $$| $$      | $$_____/| $$\  $ | $$| $$  | $$| $$      | $$_  $$' [Pattern: verbose:] [thread: 27]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '| $$/   \  $$| $$| $$      |  $$$$$$$| $$ \/  | $$|  $$$$$$/|  $$$$$$$| $$ \  $$' [Pattern: verbose:] [thread: 27]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '|__/     \__/|__/|__/       \_______/|__/     |__/ \______/  \_______/|__/  \__/' [Pattern: verbose:] [thread: 27]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '' [Pattern: verbose:] [thread: 27]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'port:                         8080' [Pattern: verbose:] [thread: 27]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'enable-browser-proxying:      false' [Pattern: verbose:] [thread: 27]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'no-request-journal:           false' [Pattern: verbose:] [thread: 27]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'verbose:                      false' [Pattern: verbose:] [thread: 27]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'initializing dependencies ... ok' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'creating system views ... ok' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'loading system objects' descriptions ... ok' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'creating collations ... ok' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'creating conversions ... ok' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'creating dictionaries ... ok' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'setting privileges on built-in objects ... ok' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:56:59]    __________  ________________' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:56:59]   /  _/ ___/ |/ /  _/_  __/ __/' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:56:59]  _/ // (7 7    // /  / / / _/' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:56:59] /___/\___/_/|_/___/ /_/ /___/' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:56:59]' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:56:59] ver. 1.9.0#20170302-sha1:a8169d0a' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:56:59] 2017 Copyright(C) Apache Software Foundation' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:56:59]' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:56:59] Ignite documentation: http://ignite.apache.org' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:56:59]' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:56:59] Quiet mode.' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:56:59]   ^-- Logging to file '/opt/ignite/apache-ignite-fabric-1.9.0-bin/work/log/ignite-1a793dfc.0.log'' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:56:59]   ^-- To see **FULL** console log here add -DIGNITE_QUIET=false or "-v" to ignite.{sh|bat}' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:56:59]' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:56:59] OS: Linux 4.4.0-64-generic amd64' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:56:59] VM information: OpenJDK Runtime Environment 1.8.0_111-8u111-b14-2~bpo8+1-b14 Oracle Corporation OpenJDK 64-Bit Server VM 25.111-b14' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'creating information schema ... ok' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:56:59] Configured plugins:' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'loading PL/pgSQL server-side language ... ok' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:56:59]   ^-- None' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:56:59]' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:56:59] Message queue limit is set to 0 which may lead to potential OOMEs when running cache operations in FULL_ASYNC or PRIMARY_SYNC modes due to message queues growth on sender and receiver sides.' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:56:59] Security status [authentication=off, tls/ssl=off]' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'vacuuming database template1 ... ok' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'copying template1 to template0 ... ok' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'copying template1 to postgres ... ok' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'syncing data to disk ... ok' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'Success. You can now start the database server using:' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'postgres -D /var/lib/postgresql/data' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'or' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'pg_ctl -D /var/lib/postgresql/data -l logfile start' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'WARNING: enabling "trust" authentication for local connections' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'You can change this by editing pg_hba.conf or using the option -A, or' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '--auth-local and --auth-host, the next time you run initdb.' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '****************************************************' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'WARNING: No password has been set for the database.' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'This will allow anyone with access to the' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'Postgres port to access your database. In' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'Docker's default configuration, this is' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'effectively any other container on the same' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'system.' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'Use "-e POSTGRES_PASSWORD=password" to set' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'it in "docker run".' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '****************************************************' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'waiting for server to start....LOG:  database system was shut down at 2017-05-02 19:57:00 UTC' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'LOG:  MultiXact member wraparound protections are now enabled' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'LOG:  database system is ready to accept connections' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'LOG:  autovacuum launcher started' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'done' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'server started' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'ALTER ROLE' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '/usr/local/bin/docker-entrypoint.sh: running /docker-entrypoint-initdb.d/setup-conf.sh' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'Set wal_level=hot_standby' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'Set max_wal_senders=5' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'Set wal_keep_segments=32' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'Set archive_mode=off' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'Set archive_command=some command' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '/usr/local/bin/docker-entrypoint.sh: running /docker-entrypoint-initdb.d/setup-database.sh' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'Making sure user omitted exists...' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'CREATE ROLE' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'Making sure database omitted exists...' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'CREATE DATABASE' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'GRANT' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '/usr/local/bin/docker-entrypoint.sh: running /docker-entrypoint-initdb.d/setup-replication.sh' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'REPLICATION_USER is not set. Skipping replication setup...' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'LOG:  received fast shutdown request' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'LOG:  aborting any active transactions' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'waiting for server to shut down....LOG:  autovacuum launcher shutting down' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'LOG:  shutting down' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'LOG:  database system is shut down' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:01] Performance suggestions for grid  (fix if possible)' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:01] To disable, set -DIGNITE_PERFORMANCE_SUGGESTIONS_DISABLED=true' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:01]   ^-- Enable G1 Garbage Collector (add '-XX:+UseG1GC' to JVM options)' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:01]   ^-- Set max direct memory size if getting 'OOME: Direct buffer memory' (add '-XX:MaxDirectMemorySize=<size>[g|G|m|M|k|K]' to JVM options)' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:01]   ^-- Disable processing of calls to System.gc() (add '-XX:+DisableExplicitGC' to JVM options)' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:01] Refer to this page for more performance suggestions: https://apacheignite.readme.io/docs/jvm-and-system-tuning' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:01]' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:01] To start Console Management & Monitoring run ignitevisorcmd.{sh|bat}' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:01]' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:01] Ignite node started OK (id=1a793dfc)' [Pattern: Ignite node started OK] [thread: 28]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'done' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'server stopped' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'PostgreSQL init process complete; ready for start up.' [Pattern: PostgreSQL init process complete; ready for start up.] [thread: 30]
[DEBUG] DOCKER> LogWaitChecker: Waiting on (?s)org\.eclipse\.jetty\.server\.Server:\s+Started
[DEBUG] DOCKER> LogWaitChecker: Pattern to match '(?s)org\.eclipse\.jetty\.server\.Server:\s+Started'
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'INFO  [2017-05-02 19:57:04,524] omitted: DataSource name: omitted' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'INFO  [2017-05-02 19:57:04,526] omitted: DataSource user: omitted' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'INFO  [2017-05-02 19:57:04,526] omitted: Migrations resource: omitted' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'INFO  [2017-05-02 19:57:06,827] omitted: run(omitted{server=DefaultServerFactory{applicationConnectors=[io.dropwizard.jetty.HttpConnectorFactory@3700ec9c], adminConnectors=[io.dropwizard.jetty.HttpConnectorFactory@550a1967], adminMaxThreads=64, adminMinThreads=1, applicationContextPath=/, adminContextPath=/}, logging=DefaultLoggingFactory{level=WARN, loggers={omitted="INFO", org.eclipse.jetty.server="INFO"}, appenders=[io.dropwizard.logging.ConsoleAppenderFactory@30bcf3c1, com.tradier.raven.logging.RavenAppenderFactory@58ebfd03]}, metrics=MetricsFactory{frequency=1 minute, reporters=[]}},io.dropwizard.setup.Environment@56681eaf)' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'INFO  [2017-05-02 19:57:06,830] omitted: omitted' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:07]    __________  ________________' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:07]   /  _/ ___/ |/ /  _/_  __/ __/' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:07]  _/ // (7 7    // /  / / / _/' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:07] /___/\___/_/|_/___/ /_/ /___/' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:07]' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:07] ver. 1.9.0#20170302-sha1:a8169d0a' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:07] 2017 Copyright(C) Apache Software Foundation' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:07]' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:07] Ignite documentation: http://ignite.apache.org' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:07]' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:07] Quiet mode.' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:07]   ^-- To see **FULL** console log here add -DIGNITE_QUIET=false or "-v" to ignite.{sh|bat}' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:07]' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:07] OS: Linux 4.4.0-64-generic amd64' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:07] VM information: OpenJDK Runtime Environment 1.8.0_121-8u121-b13-0ubuntu1.16.04.2-b13 Oracle Corporation OpenJDK 64-Bit Server VM 25.121-b13' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'WARN  [2017-05-02 19:57:07,207] org.apache.ignite.internal.GridDiagnostic: Initial heap size is 252MB (should be no less than 512MB, use -Xms512m -Xmx512m).' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:07] Initial heap size is 252MB (should be no less than 512MB, use -Xms512m -Xmx512m).' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:07] Configured plugins:' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:07]   ^-- None' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:07]' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:07] Message queue limit is set to 0 which may lead to potential OOMEs when running cache operations in FULL_ASYNC or PRIMARY_SYNC modes due to message queues growth on sender and receiver sides.' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'WARN  [2017-05-02 19:57:07,304] org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi: Message queue limit is set to 0 which may lead to potential OOMEs when running cache operations in FULL_ASYNC or PRIMARY_SYNC modes due to message queues growth on sender and receiver sides.' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'WARN  [2017-05-02 19:57:07,317] org.apache.ignite.spi.checkpoint.noop.NoopCheckpointSpi: Checkpoints are disabled (to enable configure any GridCheckpointSpi implementation)' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'WARN  [2017-05-02 19:57:07,338] org.apache.ignite.internal.managers.collision.GridCollisionManager: Collision resolution is disabled (all jobs will be activated upon arrival).' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'WARN  [2017-05-02 19:57:07,341] org.apache.ignite.spi.swapspace.noop.NoopSwapSpaceSpi: Swap space is disabled. To enable use FileSwapSpaceSpi.' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:07] Security status [authentication=off, tls/ssl=off]' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:07] REST protocols do not start on client node. To start the protocols on client node set '-DIGNITE_REST_START_ON_CLIENT=true' system property.' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:09]   ^-- Set max direct memory size if getting 'OOME: Direct buffer memory' (add '-XX:MaxDirectMemorySize=<size>[g|G|m|M|k|K]' to JVM options)' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match '[19:57:09]   ^-- Disable processing of calls to System.gc() (add '-XX:+DisableExplicitGC' to JVM options)' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'INFO  [2017-05-02 19:57:09,881] omitted: Initialized broadcaster on cluster[NODE_TYPE=SCRIVENER] with timeout=0' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'INFO  [2017-05-02 19:57:09,884] omitted: Initialized SUBMITTED listener on cluster[NODE_TYPE=null]' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'INFO  [2017-05-02 19:57:09,885] omitted: Initialized COMMITTED listener on cluster[NODE_TYPE=null]' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'INFO  [2017-05-02 19:57:09,953] omitted: Registering omitted' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'INFO  [2017-05-02 19:57:09,958] omitted: Registering omitted' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'INFO  [2017-05-02 19:57:09,959] omitted: Registering health checks' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'INFO  [2017-05-02 19:57:09,959] omitted: Registering custom admin servlets' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'INFO  [2017-05-02 19:57:10,026] org.eclipse.jetty.server.Server: jetty-9.3.z-SNAPSHOT' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'INFO  [2017-05-02 19:57:10,519] org.eclipse.jetty.server.handler.ContextHandler: Started i.d.j.MutableServletContextHandler@9687f55{/,null,AVAILABLE}' [Pattern: (?s)org\.eclipse\.jetty\.server\.Server:\s+Started] [thread: 32]

It seems as though the output is different! This is strange since the build runs the same each time. I can execute the build manually ten times and a smattering will fail, guaranteed. However, it seems as though instead of printing org.eclipse.jetty.server.Server: Started, it printed org.eclipse.jetty.server.Server: jetty-9.3.z-SNAPSHOT, and I should look for org.eclipse.jetty.server.handler.ContextHandler: Started. What an odd thing.

redijedi picture redijedi on 3 May 2017

Nope! Spoke too soon. Those are expected. Here is yet another failure, but without the -X out:

omitted> INFO  [2017-05-03 01:21:53,106] org.eclipse.jetty.server.Server: jetty-9.3.z-SNAPSHOT
omitted> INFO  [2017-05-03 01:21:53,526] org.eclipse.jetty.server.handler.ContextHandler: Started i.d.j.MutableServletContextHandler@71179b6f{/,null,AVAILABLE}
omitted> INFO  [2017-05-03 01:21:53,533] org.eclipse.jetty.server.handler.ContextHandler: Started i.d.j.MutableServletContextHandler@9687f55{/,null,AVAILABLE}
omitted> INFO  [2017-05-03 01:21:53,536] org.eclipse.jetty.server.AbstractConnector: Started application@5460b754{HTTP/1.1,[http/1.1]}{0.0.0.0:8080}
omitted> INFO  [2017-05-03 01:21:53,537] org.eclipse.jetty.server.AbstractConnector: Started admin@a9f023e{HTTP/1.1,[http/1.1]}{0.0.0.0:8081}
omitted> INFO  [2017-05-03 01:21:53,537] org.eclipse.jetty.server.Server: Started @6975ms

This was after I added the other string into an or in the regex. So neither work.

redijedi picture redijedi on 3 May 2017

Thanks, looks interesting.

How do you access the Docker daemon ? Via TCP or via Unix socket ? I ask because unfortunately there tend to be concurrency issues within the unix socket library we are using (jnr-unixsocket) which are not yet fully resolved.

If you are using Unix sockets, could you try it with TCP, too ? Another experiment could be to disable the log output to the console as then there is then only one thread fetching the logs (the waiter thread).

rhuss picture rhuss on 3 May 2017

If you feel fancy (and you are using Unix sockets which I suspect), could you please try out dmp 0.20-SNAPSHOT which I just pushed? It contains an update of jrn-unixsocket and I'm curious whether this works for you.

rhuss picture rhuss on 3 May 2017

Unfortunately no, we're using TCP to access the daemon. The entire system is (basically) Jenkins running on EC2 using Docker to spin up Jenkins slaves. These slaves run the builds which, in this case, use the same daemon to spin up the containers configured in the mvn pom.

When you say disable the log output, do you mean at the app level? Currently logging dumps to sys out. What will the waiter thread read if we're not writing the logs?

redijedi picture redijedi on 4 May 2017

@redijedi thanks for the info.

It reads the log internally (not showing on the console). So when you log out to stdout, you fetch the logs twice: One for the output, one for the wait-thread. So my idea was to check whether it's a threading issue between those two threads.

Is there any chance that I can reproduce it? I will try it later today locally but until now I wasn't able to re-produce the error.

rhuss picture rhuss on 4 May 2017

I don't think this will be of any help, but I've hit this issue as well. Specifically over a year ago, with an old version of the plugin and against an old version of Docker (1.7.1). I was ultimately able to use an url/http based wait instead and ended up forgetting about this, but I just hit it again with a slightly newer version of the plugin (0.15.16). Both of these were on an ancient RHEL6 box, using the TCP socket. The log wait did work fine on a Win 7 and 10 box.

Vulcannis picture Vulcannis on 26 May 2017

We are also having this problem. Any news on resolving it? Are there any known workarounds?

We are seeing the problem with plugin version 0.21.0 on Centos with docker 17.05. When we run the same project on mac with Boot2docker with 17.04 we have no issues. In docker logs we can see the log message we are waiting for, but it is not picked up in the plugin and it times out. This happens randomly on our images.

robzet picture robzet on 29 May 2017

@robzet @Vulcannis I really tried hard to reproduce, but I still can't. The best thing would be to have a reproducible, minimal test case (even it happens only from time to time).

In order to narrow down the issue further and to collect some empiric data, could please answer the following questions within a comment (even if the information is already given)?

  • Docker version:
  • Hosts OS + version (or platform) :
  • docker-maven-plugin version:
  • Connect to Docker daemon via TCP or Unix socket [TCP / Unix] :
  • <log> enabled in the <run> section [yes / no]:

In order to check the connection mode, its best to check DOCKER_HOST variable. If its empty then its connected via Unix socket.

rhuss picture rhuss on 29 May 2017

@rhuss What we have tried so far is upgrading maven plugin and downgrading docker with no success. We are now moving to tcp waits.

Docker version: _17.05.0-ce / 17.04.0-ce_
Hosts OS + version (or platform) : _CentOS 7_
docker-maven-plugin version: _0.21.0 / 0.20.1_
Connect to Docker daemon via TCP or Unix socket [TCP / Unix] : _tcp_
<log> enabled in the <run> section [yes / no]: _yes_

Thank you!

robzet picture robzet on 29 May 2017

@rhuss I'm not surprised, on our dev boxes we've never had an issue, it's just our CI server that always chokes. Here's it's info (ancient!):

Docker version: 1.7.1, build 786b29d
Hosts OS + version (or platform): RHEL 6, 2.6.32-573.1.1.el6.x86_64
docker-maven-plugin version: 0.14.12 & 0.15.16
Connect to Docker daemon via TCP or Unix socket [TCP / Unix]: tcp
enabled in the section [yes / no]: yes (no results in a consistent failure, though again only on this box)

Vulcannis picture Vulcannis on 29 May 2017

I'm having the exact same issue, on Mac and Linux, it seem very random maybe 1/4th of the time the build fails because of this.

Using versions 0.22.1 and 0.23.0 of the maven docker plugin.

Configure under, <image><run><wait><log>

# docker version
Client:
 Version:      17.06.2-ce
 API version:  1.30
 Go version:   go1.8.3
 Git commit:   3dfb8343b139d6342acfd9975d7f1068b5b1c3d3
 Built:        Tue Oct 17 18:33:39 2017
 OS/Arch:      linux/amd64

Server:
 Version:      17.06.2-ce
 API version:  1.30 (minimum version 1.12)
 Go version:   go1.8.3
 Git commit:   402dd4a/17.06.2-ce
 Built:        Tue Oct 17 18:34:10 2017
 OS/Arch:      linux/amd64
 Experimental: false

# docker version
Client:
 Version:      17.09.0-ce
 API version:  1.32
 Go version:   go1.8.3
 Git commit:   afdb6d4
 Built:        Tue Sep 26 22:40:09 2017
 OS/Arch:      darwin/amd64

Server:
 Version:      17.09.0-ce
 API version:  1.32 (minimum version 1.12)
 Go version:   go1.8.3
 Git commit:   afdb6d4
 Built:        Tue Sep 26 22:45:38 2017
 OS/Arch:      linux/amd64
 Experimental: true

kafka> [2017-11-22 23:00:45,416] INFO [Controller-1-to-broker-1-send-thread]: Starting (kafka.controller.RequestSendThread)
kafka> [2017-11-22 23:00:45,418] INFO [Controller 1]: New broker startup callback for 1 (kafka.controller.KafkaController)
kafka> [2017-11-22 23:00:45,429] INFO [Controller-1-to-broker-1-send-thread]: Controller 1 connected to localhost:37339 (id: 1 rack: null) for sending state change requests (kafka.controller.RequestSendThread)
kafka> [2017-11-22 23:00:45,518] TRACE Controller 1 epoch 1 received response {error_code=0} for a request sent to broker localhost:37339 (id: 1 rack: null) (state.change.logger)
kafka> [2017-11-22 23:00:50,315] TRACE [Controller 1]: Checking need to trigger auto leader balancing (kafka.controller.KafkaController)
kafka> [2017-11-22 23:00:50,317] DEBUG [Controller 1]: Preferred replicas by broker Map() (kafka.controller.KafkaController)
[ERROR] DOCKER> [confluentinc/cp-kafka:3.3.0] "kafka": Timeout after 60194 ms while waiting on log out '.* Controller 1 connected to .* \(kafka\.controller\.RequestSendThread\)'
[ERROR] DOCKER> Error occurred during container startup, shutting down...

You can clearly see the third log line is the matching one.

aaronjwhiteside picture aaronjwhiteside on 23 Nov 2017

I managed to reproduce something similar to what is reported here but I'm not 100% sure it's the same scenario.

To reproduce the issue the expected log line needs to be delayed for more that the configured timeout.

Here the timeout is 5000ms and each generated line has a 1000ms sleep following it:

$ mvn clean install
[INFO] Scanning for projects...
[INFO] 
[INFO] ------------------------------------------------------------------------
[INFO] Building none 1.0-SNAPSHOT
[INFO] ------------------------------------------------------------------------
[INFO] 
[INFO] --- maven-clean-plugin:2.5:clean (default-clean) @ none ---
[INFO] Deleting /Users/comp_/git/github.com/isavin/issues/github.com/fabric8io/docker-maven-plugin/767/target
[INFO] 
[INFO] --- maven-resources-plugin:3.0.2:resources (default-resources) @ none ---
[WARNING] Using platform encoding (UTF-8 actually) to copy filtered resources, i.e. build is platform dependent!
[INFO] skip non existing resourceDirectory /Users/comp_/git/github.com/isavin/issues/github.com/fabric8io/docker-maven-plugin/767/src/main/resources
[INFO] 
[INFO] --- maven-compiler-plugin:3.7.0:compile (default-compile) @ none ---
[INFO] No sources to compile
[INFO] 
[INFO] --- maven-resources-plugin:3.0.2:testResources (default-testResources) @ none ---
[WARNING] Using platform encoding (UTF-8 actually) to copy filtered resources, i.e. build is platform dependent!
[INFO] skip non existing resourceDirectory /Users/comp_/git/github.com/isavin/issues/github.com/fabric8io/docker-maven-plugin/767/src/test/resources
[INFO] 
[INFO] --- maven-compiler-plugin:3.7.0:testCompile (default-testCompile) @ none ---
[INFO] No sources to compile
[INFO] 
[INFO] --- maven-surefire-plugin:2.20.1:test (default-test) @ none ---
[INFO] No tests to run.
[INFO] 
[INFO] --- maven-jar-plugin:3.0.2:jar (default-jar) @ none ---
[WARNING] JAR will be empty - no content was marked for inclusion!
[INFO] Building jar: /Users/comp_/git/github.com/isavin/issues/github.com/fabric8io/docker-maven-plugin/767/target/none-1.0-SNAPSHOT.jar
[INFO] 
[INFO] --- docker-maven-plugin:0.24-SNAPSHOT:build (default-build) @ none ---
[INFO] 
[INFO] --- docker-maven-plugin:0.24-SNAPSHOT:start (default-start) @ none ---
[INFO] DOCKER> [alpine:latest]: Start container 8d6c90a5fb83
8d6c90> Log line 1
8d6c90> Log line 2
8d6c90> Log line 3
8d6c90> Log line 4
8d6c90> Log line 5
8d6c90> Log line 6
8d6c90> Log line 7
8d6c90> Log line 8
8d6c90> Log line 9
8d6c90> Log line 10
8d6c90> org.eclipse.jetty.server.Server: Started @6975ms
[INFO] DOCKER> Pattern '(.*)(org\.eclipse\.jetty\.server\.Server: Started)(.*)' matched for container 8d6c90a5fb83
[ERROR] DOCKER> [alpine:latest]: Timeout after 5102 ms while waiting on log out '(.*)(org\.eclipse\.jetty\.server\.Server: Started)(.*)'
[ERROR] DOCKER> Error occurred during container startup, shutting down...
[INFO] DOCKER> [alpine:latest]: Stop and removed container 8d6c90a5fb83 after 0 ms
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 13.632 s
[INFO] Finished at: 2018-02-08T23:10:33+02:00
[INFO] Final Memory: 22M/274M
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal io.fabric8:docker-maven-plugin:0.24-SNAPSHOT:start (default-start) on project none: Execution default-start of goal io.fabric8:docker-maven-plugin:0.24-SNAPSHOT:start failed: Start-Job failed with unexpected exception: [alpine:latest]: Timeout after 5102 ms while waiting on log out '(.*)(org\.eclipse\.jetty\.server\.Server: Started)(.*)' -> [Help 1]
[ERROR] 
[ERROR] To see the full stack trace of the errors, re-run Maven with the -e switch.
[ERROR] Re-run Maven using the -X switch to enable full debug logging.
[ERROR] 
[ERROR] For more information about the errors and possible solutions, please read the following articles:
[ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/PluginExecutionException

The sample project is available here.

@redijedi @Vulcannis @robzet @aaronjwhiteside are you still experiencing this? Could you provide a full mvn -X log?

It would help to verify if by the time the expected line is logged the container has already been running for more then the specified timeout.

ghost picture ghost on 8 Feb 2018

I have the same issue with a mysql image. The logs with -X didn't show anything the last info I got from log checker was that pattern was OK it's stuck.

danieljipa picture danieljipa on 3 Mar 2018

Still seeing this issue every now and then, the log line is produced well before the timeout is reached, so I don't think that is the issue.

It's hard to reproduce on demand and I'm hesitant about turning debug on in our CI environment.

aaronjwhiteside picture aaronjwhiteside on 3 Mar 2018

For me the issue is only reproducible on my MacOS. On Ubuntu it works OK. So I don't think this is a plugin problem.

danieljipa picture danieljipa on 5 Mar 2018

@aaronjwhiteside @danieljipa thanks for the feedback!

@danieljipa can you reproduce the issue on MacOS every time? Do you have a small sample project I can use to try to find the issue?

ghost picture ghost on 5 Mar 2018

@isavin It's something like 3 out of 4 times it fails. It hangs and not even the exec:postStart command is executed. I will try to create a small sample for this.

danieljipa picture danieljipa on 5 Mar 2018

As an update. It seems to fail only with 0.24.0. With 0.23.0 it always work.
docker -v Docker version 17.12.0-ce, build c97c6d6

MacOS Sierra 10.12.6 (16G1114)

java -version java version "9.0.4" Java(TM) SE Runtime Environment (build 9.0.4+11) Java HotSpot(TM) 64-Bit Server VM (build 9.0.4+11, mixed mode)

Minimal reproductible sample https://github.com/danjee/dockermavenplugin

danjee picture danjee on 5 Mar 2018

@danjee great! thank you! I'll have a look when I have time and let you know.

ghost picture ghost on 5 Mar 2018

Ty @isavin

danjee picture danjee on 5 Mar 2018

So this issue is still there, at least in 0.27.2 isn't it?

LorenzoBettini picture LorenzoBettini on 22 Jan 2019

0.28 also seems to still have this issue. I do use unix sockets and it fails randomly (about 3/4 times), although the log is always there.

ric2b picture ric2b on 7 Feb 2019

Next try: There's an update of the unix socket library in release 0.29.0, so it might be worth to check this out whether it fixes this issue.

rhuss picture rhuss on 8 Apr 2019
👎2

I'm still having this issue, with version 0.29.0.

riccardomarotti picture riccardomarotti on 15 Apr 2019
👍6

I am still having this issue when using 0.31.0. Interestingly, for a Spring boot project, it works fine when I use postgres:9.5.4 container with junit 4 but if I upgrade either the db to 10+ or junit to ver.5, then I get the same message as in the comment: " ghost commented on Feb 8, 2018"
I have two executions. The first starts the container (phase validate/start), then run Flyway and Jooq plugins in the phases in-between, then the second execution (phase install/stop).

MichalAdorno picture MichalAdorno on 29 Sep 2019

it turned out that the issue of timeout is triggered by a \n character in the tag. THe plugin simply is not able to create a container. \n got there because of autoformatting...

MichalAdorno picture MichalAdorno on 7 Oct 2019

@rhuss I am facing the same issue with version 0.31.0. Can you please provide a workaround for this

neerajjain92 picture neerajjain92 on 11 Oct 2019
Was this page helpful?
0 / 5 - 0 ratings

Related issues

ivanfryda picture ivanfryda  路  5Comments
jstrachan picture jstrachan  路  10Comments
mixaaaa picture mixaaaa  路  5Comments
ghilainm picture ghilainm  路  4Comments
svenhaag picture svenhaag  路  3Comments