This is the most confusing part, as haproxy logs don’t tell much:
2/24/2017 4:49:14 PMtime="2017-02-24T15:49:14Z" level=info msg="Starting Rancher LB service"
2/24/2017 4:49:14 PMtime="2017-02-24T15:49:14Z" level=info msg="LB controller: rancher"
2/24/2017 4:49:14 PMtime="2017-02-24T15:49:14Z" level=info msg="LB provider: haproxy"
2/24/2017 4:49:14 PMtime="2017-02-24T15:49:14Z" level=info msg="starting rancher controller"
2/24/2017 4:49:14 PMtime="2017-02-24T15:49:14Z" level=info msg="Healthcheck handler is listening on :10241"
2/24/2017 4:49:16 PMtime="2017-02-24T15:49:16Z" level=info msg=" -- starting haproxy\n[WARNING] 054/154915 (28) : config : 'option forwardfor' ignored for proxy 'default' as it requires HTTP mode.\n"
Metabase is being more helpful:
2/24/2017 3:50:00 PM at clojure.java.jdbc$db_query_with_resultset.invokeStatic(jdbc.clj:850)
2/24/2017 3:50:00 PM at clojure.java.jdbc$db_query_with_resultset.invoke(jdbc.clj:818)
2/24/2017 3:50:00 PM at clojure.java.jdbc$query.invokeStatic(jdbc.clj:874)
2/24/2017 3:50:00 PM at clojure.java.jdbc$query.invoke(jdbc.clj:854)
2/24/2017 3:50:00 PM at metabase.db$query.invokeStatic(db.clj:534)
2/24/2017 3:50:00 PM at metabase.db$query.doInvoke(db.clj:530)
2/24/2017 3:50:00 PM at clojure.lang.RestFn.invoke(RestFn.java:410)
2/24/2017 3:50:00 PM at metabase.db$simple_select.invokeStatic(db.clj:593)
2/24/2017 3:50:00 PM at metabase.db$simple_select.invoke(db.clj:585)
2/24/2017 3:50:00 PM at metabase.db$select.invokeStatic(db.clj:836)
2/24/2017 3:50:00 PM at metabase.db$select.doInvoke(db.clj:830)
2/24/2017 3:50:00 PM at clojure.lang.RestFn.invoke(RestFn.java:439)
2/24/2017 3:50:00 PM at metabase.task.sync_databases.SyncDatabases.execute(sync_databases.clj:21)
2/24/2017 3:50:00 PM at org.quartz.core.JobRunShell.run(JobRunShell.java:213)
2/24/2017 3:50:00 PM ... 1 more
2/24/2017 3:50:00 PMCaused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
2/24/2017 3:50:00 PM at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3004)
2/24/2017 3:50:00 PM at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3462)
2/24/2017 3:50:00 PM ... 24 more
2/24/2017 4:50:00 PM02-24 15:50:00 ERROR core.JobRunShell :: Job DEFAULT.metabase.task.sync-databases.job threw an unhandled Exception:
2/24/2017 4:50:00 PMcom.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
2/24/2017 4:50:00 PM
2/24/2017 4:50:00 PMThe last packet successfully received from the server was 2,999,993 milliseconds ago. The last packet sent successfully to the server was 1 milliseconds ago.
2/24/2017 4:50:00 PM at sun.reflect.GeneratedConstructorAccessor62.newInstance(Unknown Source)
2/24/2017 4:50:00 PM at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
2/24/2017 4:50:00 PM at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
2/24/2017 4:50:00 PM at com.mysql.jdbc.Util.handleNewInstance(Util.java:404)
2/24/2017 4:50:00 PM at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:988)
2/24/2017 4:50:00 PM at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3552)
2/24/2017 4:50:00 PM at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3452)
2/24/2017 4:50:00 PM at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3893)
2/24/2017 4:50:00 PM at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2526)
2/24/2017 4:50:00 PM at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2673)
2/24/2017 4:50:00 PM at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2549)
2/24/2017 4:50:00 PM at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1861)
2/24/2017 4:50:00 PM at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1962)
2/24/2017 4:50:00 PM at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:76)
2/24/2017 4:50:00 PM at clojure.java.jdbc$db_query_with_resultset$run_query_with_params__2997.invoke(jdbc.clj:831)
2/24/2017 4:50:00 PM at clojure.java.jdbc$db_query_with_resultset.invokeStatic(jdbc.clj:850)
2/24/2017 4:50:00 PM at clojure.java.jdbc$db_query_with_resultset.invoke(jdbc.clj:818)
2/24/2017 4:50:00 PM at clojure.java.jdbc$query.invokeStatic(jdbc.clj:874)
2/24/2017 4:50:00 PM at clojure.java.jdbc$query.invoke(jdbc.clj:854)
2/24/2017 4:50:00 PM at metabase.db$query.invokeStatic(db.clj:534)
2/24/2017 4:50:00 PM at metabase.db$query.doInvoke(db.clj:530)
2/24/2017 4:50:00 PM at clojure.lang.RestFn.invoke(RestFn.java:410)
2/24/2017 4:50:00 PM at metabase.db$simple_select.invokeStatic(db.clj:593)
2/24/2017 4:50:00 PM at metabase.db$simple_select.invoke(db.clj:585)
2/24/2017 4:50:00 PM at metabase.db$select.invokeStatic(db.clj:836)
2/24/2017 4:50:00 PM at metabase.db$select.doInvoke(db.clj:830)
2/24/2017 4:50:00 PM at clojure.lang.RestFn.invoke(RestFn.java:439)
2/24/2017 4:50:00 PM at metabase.task.sync_databases.SyncDatabases.execute(sync_databases.clj:21)
2/24/2017 4:50:00 PM at org.quartz.core.JobRunShell.run(JobRunShell.java:213)
2/24/2017 4:50:00 PM at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:557)
2/24/2017 4:50:00 PMCaused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
2/24/2017 4:50:00 PM at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3004)
2/24/2017 4:50:00 PM at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3462)
2/24/2017 4:50:00 PM ... 24 more
2/24/2017 4:50:00 PM02-24 15:50:00 ERROR core.ErrorLogger :: Job (DEFAULT.metabase.task.sync-databases.job threw an exception.
2/24/2017 4:50:00 PMorg.quartz.SchedulerException: Job threw an unhandled exception. [See nested exception: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
2/24/2017 4:50:00 PM
2/24/2017 4:50:00 PMThe last packet successfully received from the server was 2,999,993 milliseconds ago. The last packet sent successfully to the server was 1 milliseconds ago.]
2/24/2017 4:50:00 PM at org.quartz.core.JobRunShell.run(JobRunShell.java:224)
2/24/2017 4:50:00 PM at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:557)
2/24/2017 4:50:00 PMCaused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
2/24/2017 4:50:00 PM
2/24/2017 4:50:00 PMThe last packet successfully received from the server was 2,999,993 milliseconds ago. The last packet sent successfully to the server was 1 milliseconds ago.
2/24/2017 4:50:00 PM at sun.reflect.GeneratedConstructorAccessor62.newInstance(Unknown Source)
2/24/2017 4:50:00 PM at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
2/24/2017 4:50:00 PM at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
2/24/2017 4:50:00 PM at com.mysql.jdbc.Util.handleNewInstance(Util.java:404)
2/24/2017 4:50:00 PM at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:988)
2/24/2017 4:50:00 PM at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3552)
2/24/2017 4:50:00 PM at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3452)
2/24/2017 4:50:00 PM at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3893)
2/24/2017 4:50:00 PM at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2526)
2/24/2017 4:50:00 PM at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2673)
2/24/2017 4:50:00 PM at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2549)
2/24/2017 4:50:00 PM at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1861)
2/24/2017 4:50:00 PM at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1962)
2/24/2017 4:50:00 PM at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:76)
2/24/2017 4:50:00 PM at clojure.java.jdbc$db_query_with_resultset$run_query_with_params__2997.invoke(jdbc.clj:831)
2/24/2017 4:50:00 PM at clojure.java.jdbc$db_query_with_resultset.invokeStatic(jdbc.clj:850)
2/24/2017 4:50:00 PM at clojure.java.jdbc$db_query_with_resultset.invoke(jdbc.clj:818)
2/24/2017 4:50:00 PM at clojure.java.jdbc$query.invokeStatic(jdbc.clj:874)
2/24/2017 4:50:00 PM at clojure.java.jdbc$query.invoke(jdbc.clj:854)
2/24/2017 4:50:00 PM at metabase.db$query.invokeStatic(db.clj:534)
2/24/2017 4:50:00 PM at metabase.db$query.doInvoke(db.clj:530)
2/24/2017 4:50:00 PM at clojure.lang.RestFn.invoke(RestFn.java:410)
2/24/2017 4:50:00 PM at metabase.db$simple_select.invokeStatic(db.clj:593)
2/24/2017 4:50:00 PM at metabase.db$simple_select.invoke(db.clj:585)
2/24/2017 4:50:00 PM at metabase.db$select.invokeStatic(db.clj:836)
2/24/2017 4:50:00 PM at metabase.db$select.doInvoke(db.clj:830)
2/24/2017 4:50:00 PM at clojure.lang.RestFn.invoke(RestFn.java:439)
2/24/2017 4:50:00 PM at metabase.task.sync_databases.SyncDatabases.execute(sync_databases.clj:21)
2/24/2017 4:50:00 PM at org.quartz.core.JobRunShell.run(JobRunShell.java:213)
2/24/2017 4:50:00 PM ... 1 more
2/24/2017 4:50:00 PMCaused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
2/24/2017 4:50:00 PM at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3004)
2/24/2017 4:50:00 PM at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3462)
2/24/2017 4:50:00 PM ... 24 more
So far I’ve been able to only mitigate a lot the issue (not solve it) with this config for haproxy which I grabbed and tweaked from this thread.
default
timeout connect 1000
timeout check 1000
timeout client 10000
timeout server 10000
frontend http-frontend
bind *:80
mode http
redirect scheme https code 302 if !{ ssl_fc }
Here I found the TTL settings on the sql driver connection pools for metabase.
And the output of haproxy -vv
from inside the container:
HA-Proxy version 1.6.11-1ppa1~xenial 2016/12/27
Copyright 2000-2016 Willy Tarreau <willy@haproxy.org>
Build options :
TARGET = linux2628
CPU = generic
CC = gcc
CFLAGS = -g -O2 -fPIE -fstack-protector-strong -Wformat -Werror=format-securi
ty -Wdate-time -D_FORTIFY_SOURCE=2
OPTIONS = USE_ZLIB=1 USE_REGPARM=1 USE_OPENSSL=1 USE_LUA=1 USE_PCRE=1 USE_NS=1
Default settings :
maxconn = 2000, bufsize = 16384, maxrewrite = 1024, maxpollevents = 200
Encrypted password support via crypt(3): yes
Built with zlib version : 1.2.8
Running on zlib version : 1.2.8
Compression algorithms supported : identity("identity"), deflate("deflate"), raw
-deflate("deflate"), gzip("gzip")
Built with OpenSSL version : OpenSSL 1.0.2g 1 Mar 2016
Running on OpenSSL version : OpenSSL 1.0.2g 1 Mar 2016
OpenSSL library supports TLS extensions : yes
OpenSSL library supports SNI : yes
OpenSSL library supports prefer-server-ciphers : yes
Built with PCRE version : 8.38 2015-11-23
Running on PCRE version : 8.38 2015-11-23
PCRE library supports JIT : no (USE_PCRE_JIT not set)
Built with Lua version : Lua 5.3.1
Built with transparent proxy support using: IP_TRANSPARENT IPV6_TRANSPARENT IP_F
REEBIND
Built with network namespace support
Available polling systems :
epoll : pref=300, test result OK
poll : pref=200, test result OK
select : pref=150, test result OK
Total: 3 (3 usable), will use epoll.