Some Listeners Failed to Start - How to Debug?

Help!
1

I am working on upgrading our HAProxy deployment from 1.6 to 1.8 while also putting it into containers that are running in Kubernetes (used to run on host). I’ve gotten it all working from what I can tell, but I keep getting this error when reloading/starting HAProxy with an updated config:

[ALERT] 172/125245 (1) : [haproxy.main()] Some protocols failed to start their listeners! Exiting.
[ALERT] 172/125245 (1) : [haproxy.main()] .

I’ve narrowed it down to my peers and stick-table config. When I disable stick-table, everything runs as expected, but once it’s enabled that listener fails to start–or well I assume it’s that listener since that is the only change when it happens. My thinking is that it is a problem with my peers config since when I make that change things fail. I’m not sure how to further debug this, though, as I cannot find any logs that explain the issue from stdout/stderr or from syslog.

Here is a config that is succcessful:

global
  log 127.0.0.1:9515 local0 debug
  log 127.0.0.1:9514 local1 debug
  log-send-hostname
  tune.bufsize  65536
  maxconn 8000
  stats socket /var/run/haproxy.sock mode 0600 level admin expose-fd listeners
  stats timeout 2m

defaults
  log global
  option dontlognull
  mode http
  maxconn 8000

  option redispatch
  retries 3
  timeout connect 5000
  timeout client 400000
  timeout server 400000
  timeout tarpit 2s

  errorfile 400 /etc/haproxy/static/errors/400.http
  errorfile 403 /etc/haproxy/static/errors/403.http
  errorfile 408 /etc/haproxy/static/errors/408.http
  errorfile 500 /etc/haproxy/static/errors/500.http
  errorfile 502 /etc/haproxy/static/errors/502.http
  errorfile 503 /etc/haproxy/static/errors/503.http
  errorfile 504 /etc/haproxy/static/errors/504.http

listen stats
  # bind :8000
  bind :35000
  stats uri /
  stats enable
  
frontend http
  description poop1
  bind :35001

  stick-table type ip size 500k expire 5m store http_req_rate(30s)
  tcp-request inspect-delay 2s
  tcp-request content track-sc1 src

  redirect scheme https code 301

Here is a config that fails to start some listeners:

global
  log 127.0.0.1:9515 local0 debug
  log 127.0.0.1:9514 local1 debug
  log-send-hostname
  tune.bufsize  65536
  maxconn 8000
  stats socket /var/run/haproxy.sock mode 0600 level admin expose-fd listeners
  stats timeout 2m

defaults
  log global
  option dontlognull
  mode http
  maxconn 8000

  # if a request to a backend fails, redispatch it to another backend.
  # the number of times to attempt this is controlled by the retries property below
  option redispatch
  # if sending a request to one server fails, try to send it
  # to another at most n times before aborting the request
  retries 3
  timeout connect 5000
  timeout client 400000
  timeout server 400000
  timeout tarpit 2s

  errorfile 400 /etc/haproxy/static/errors/400.http
  errorfile 403 /etc/haproxy/static/errors/403.http
  errorfile 408 /etc/haproxy/static/errors/408.http
  errorfile 500 /etc/haproxy/static/errors/500.http
  errorfile 502 /etc/haproxy/static/errors/502.http
  errorfile 503 /etc/haproxy/static/errors/503.http
  errorfile 504 /etc/haproxy/static/errors/504.http

listen stats
  # bind :8000
  bind :35000
  stats uri /
  stats enable

peers haproxy_peers
  peer <node_name> <node_ip>:34999 # this ip is actually the node this is running on, so it's a cluster of 1

frontend http
  description poop2
  bind :35001
  
  stick-table type ip size 500k expire 5m store http_req_rate(30s) peers haproxy_peers
  tcp-request inspect-delay 2s
  tcp-request content track-sc1 src

  redirect scheme https code 301

How else can I debug this? Any other thoughts? I’m not very fluent at C, so when I look at the source code I don’t see anything that looks problematic–it’s only trying to start the listeners and then it fails. ¯_(ツ)_/¯

2

Probably some other application listening on the <node_ip>:34999.

What happens if you run (with the same privileges as haproxy) netcat and make it listen to the same port:
nc -l 127.0.0.1 8080

Do you get Address already in use?
What does netstat say?
sudo netstat -tulpen | grep 34999

If that is all working correctly and port 34999 is free, try running haproxy through strace (this will show all system errors returned to haproxy):
strace -tt haproxy -f /etc/haproxy.cfg -d

Also please share the output of haproxy -vv and your OS/kernel release.

3

I tried the nc and netstat commands. No error with nc. netstat returns nothing.

/ # nc -l 127.0.0.1 34999
^Cpunt!

/ # sudo netstat -tulpen | grep 34999
sh: sudo: not found
/ # netstat -tulpen | grep 34999
/ #help

HAProxy info:

/ # haproxy -vv
HA-Proxy version 1.8.9-83616ec 2018/05/18
Copyright 2000-2018 Willy Tarreau <willy@haproxy.org>

Build options :
  TARGET  = linux2628
  CPU     = generic
  CC      = gcc
  CFLAGS  = -O2 -g -fno-strict-aliasing -Wdeclaration-after-statement -fwrapv -fno-strict-overflow -Wno-null-dereference -Wno-unused-label
  OPTIONS = USE_ZLIB=1 USE_OPENSSL=1 USE_LUA=1 USE_PCRE=1

Default settings :
  maxconn = 2000, bufsize = 16384, maxrewrite = 1024, maxpollevents = 200

Built with OpenSSL version : OpenSSL 1.0.2o  27 Mar 2018
Running on OpenSSL version : OpenSSL 1.0.2o  27 Mar 2018
OpenSSL library supports TLS extensions : yes
OpenSSL library supports SNI : yes
OpenSSL library supports : SSLv3 TLSv1.0 TLSv1.1 TLSv1.2
Built with Lua version : Lua 5.3.4
Built with transparent proxy support using: IP_TRANSPARENT IPV6_TRANSPARENT IP_FREEBIND
Encrypted password support via crypt(3): yes
Built with multi-threading support.
Built with PCRE version : 8.41 2017-07-05
Running on PCRE version : 8.41 2017-07-05
PCRE library supports JIT : no (USE_PCRE_JIT not set)
Built with zlib version : 1.2.11
Running on zlib version : 1.2.11
Compression algorithms supported : identity("identity"), deflate("deflate"), raw-deflate("deflate"), gzip("gzip")
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.

Available filters :
	[SPOE] spoe
	[COMP] compression
	[TRACE] trace

strace output (which I used CTRL-C to get out of):

/ # strace -tt haproxy -f /etc/haproxy/dynamic/haproxy.cfg -d -L ip-10-10-44-9
18:30:05.997183 execve("/usr/local/sbin/haproxy", ["haproxy", "-f", "/etc/haproxy/dynamic/haproxy.cfg", "-d", "-L", "ip-10-10-44-9"], 0x7ffcbed72c10 /* 77 vars */) = 0
18:30:05.997599 arch_prctl(ARCH_SET_FS, 0x7f1481effb88) = 0
18:30:05.997631 set_tid_address(0x7f1481effbc0) = 35
18:30:05.997677 open("/etc/ld-musl-x86_64.path", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
18:30:05.997720 open("/lib/libz.so.1", O_RDONLY|O_CLOEXEC) = 3
18:30:05.997758 fcntl(3, F_SETFD, FD_CLOEXEC) = 0
18:30:05.997789 fstat(3, {st_mode=S_IFREG|0755, st_size=91952, ...}) = 0
18:30:05.997829 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260!\0\0\0\0\0\0"..., 960) = 960
18:30:05.997866 mmap(NULL, 2191360, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0x7f1481a5d000
18:30:05.997904 mmap(0x7f1481c72000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x15000) = 0x7f1481c72000
18:30:05.997953 close(3)                = 0
18:30:05.997983 open("/lib/libssl.so.1.0.0", O_RDONLY|O_CLOEXEC) = 3
18:30:05.998020 fcntl(3, F_SETFD, FD_CLOEXEC) = 0
18:30:05.998088 fstat(3, {st_mode=S_IFREG|0555, st_size=429112, ...}) = 0
18:30:05.998136 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\230\221\1\0\0\0\0\0"..., 960) = 960
18:30:05.998196 mmap(NULL, 2527232, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0x7f14817f4000
18:30:05.998245 mmap(0x7f1481a52000, 45056, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x5e000) = 0x7f1481a52000
18:30:05.998306 close(3)                = 0
18:30:05.998340 open("/lib/libcrypto.so.1.0.0", O_RDONLY|O_CLOEXEC) = 3
18:30:05.998496 fcntl(3, F_SETFD, FD_CLOEXEC) = 0
18:30:05.998559 fstat(3, {st_mode=S_IFREG|0555, st_size=2213448, ...}) = 0
18:30:05.998652 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\0z\6\0\0\0\0\0"..., 960) = 960
18:30:05.998715 mmap(NULL, 4325376, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0x7f14813d4000
18:30:05.998883 mmap(0x7f14817c9000, 176128, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x1f5000) = 0x7f14817c9000
18:30:05.998987 mmap(0x7f14817f0000, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f14817f0000
18:30:05.999126 close(3)                = 0
18:30:05.999229 open("/lib/liblua-5.3.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
18:30:05.999364 open("/usr/local/lib/liblua-5.3.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
18:30:05.999475 open("/usr/lib/liblua-5.3.so.0", O_RDONLY|O_CLOEXEC) = 3
18:30:05.999571 fcntl(3, F_SETFD, FD_CLOEXEC) = 0
18:30:05.999714 fstat(3, {st_mode=S_IFREG|0644, st_size=198288, ...}) = 0
18:30:05.999820 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0`s\0\0\0\0\0\0"..., 960) = 960
18:30:05.999913 mmap(NULL, 2297856, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0x7f14811a3000
18:30:06.000030 mmap(0x7f14813d1000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x2e000) = 0x7f14813d1000
18:30:06.000169 close(3)                = 0
18:30:06.000247 open("/lib/libpcre.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
18:30:06.000362 open("/usr/local/lib/libpcre.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
18:30:06.000443 open("/usr/lib/libpcre.so.1", O_RDONLY|O_CLOEXEC) = 3
18:30:06.000554 fcntl(3, F_SETFD, FD_CLOEXEC) = 0
18:30:06.000626 fstat(3, {st_mode=S_IFREG|0755, st_size=370360, ...}) = 0
18:30:06.000708 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0@\24\0\0\0\0\0\0"..., 960) = 960
18:30:06.000810 mmap(NULL, 2469888, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0x7f1480f48000
18:30:06.000886 mmap(0x7f14811a1000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x59000) = 0x7f14811a1000
18:30:06.001070 close(3)                = 0
18:30:06.001222 mprotect(0x7f1481c72000, 4096, PROT_READ) = 0
18:30:06.001519 mprotect(0x7f1481a52000, 20480, PROT_READ) = 0
18:30:06.001850 mprotect(0x7f14817c9000, 114688, PROT_READ) = 0
18:30:06.001975 mprotect(0x7f14813d1000, 8192, PROT_READ) = 0
18:30:06.002108 mprotect(0x7f14811a1000, 4096, PROT_READ) = 0
18:30:06.002191 mprotect(0x7f1481efc000, 4096, PROT_READ) = 0
18:30:06.002473 mprotect(0x5642c3fc7000, 16384, PROT_READ) = 0
18:30:06.002559 brk(NULL)               = 0x5642c5fdd000
18:30:06.002677 brk(0x5642c5fe0000)     = 0x5642c5fe0000
18:30:06.002747 arch_prctl(ARCH_SET_FS, 0x5642c5fdf2c0) = 0
18:30:06.002865 set_tid_address(0x5642c5fdf2f8) = 35
18:30:06.003293 brk(0x5642c5fe1000)     = 0x5642c5fe1000
18:30:06.003420 brk(0x5642c5fe2000)     = 0x5642c5fe2000
18:30:06.003530 brk(0x5642c5fe3000)     = 0x5642c5fe3000
18:30:06.003636 brk(0x5642c5fe4000)     = 0x5642c5fe4000
18:30:06.003771 brk(0x5642c5fe5000)     = 0x5642c5fe5000
18:30:06.003868 brk(0x5642c5fe6000)     = 0x5642c5fe6000
18:30:06.003968 brk(0x5642c5fe8000)     = 0x5642c5fe8000
18:30:06.004126 brk(0x5642c5fe9000)     = 0x5642c5fe9000
18:30:06.004232 brk(0x5642c5fea000)     = 0x5642c5fea000
18:30:06.004319 brk(0x5642c5feb000)     = 0x5642c5feb000
18:30:06.004470 brk(0x5642c5fec000)     = 0x5642c5fec000
18:30:06.004630 brk(0x5642c5ff1000)     = 0x5642c5ff1000
18:30:06.004757 brk(0x5642c5ff6000)     = 0x5642c5ff6000
18:30:06.004841 brk(0x5642c5ffb000)     = 0x5642c5ffb000
18:30:06.004945 uname({sysname="Linux", nodename="haproxy-router-64cfd4cf7c-f2pnj", ...}) = 0
18:30:06.005046 open("/etc/localtime", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = 3
18:30:06.005148 fstat(3, {st_mode=S_IFREG|0644, st_size=127, ...}) = 0
18:30:06.005271 mmap(NULL, 127, PROT_READ, MAP_SHARED, 3, 0) = 0x7f1481efb000
18:30:06.005416 close(3)                = 0
18:30:06.005503 clock_gettime(CLOCK_REALTIME, {tv_sec=1529692206, tv_nsec=5529198}) = 0
18:30:06.005598 getpid()                = 35
18:30:06.005678 rt_sigprocmask(SIG_SETMASK, [USR2], NULL, 8) = 0
18:30:06.005860 clock_gettime(CLOCK_REALTIME, {tv_sec=1529692206, tv_nsec=5901721}) = 0
18:30:06.006018 brk(0x5642c5ffc000)     = 0x5642c5ffc000
18:30:06.006127 brk(0x5642c5ffd000)     = 0x5642c5ffd000
18:30:06.006227 brk(0x5642c5ffe000)     = 0x5642c5ffe000
18:30:06.006353 brk(0x5642c5fff000)     = 0x5642c5fff000
18:30:06.006485 brk(0x5642c6000000)     = 0x5642c6000000
18:30:06.006605 brk(0x5642c6001000)     = 0x5642c6001000
18:30:06.006700 brk(0x5642c6003000)     = 0x5642c6003000
18:30:06.006839 brk(0x5642c6004000)     = 0x5642c6004000
18:30:06.006954 brk(0x5642c6005000)     = 0x5642c6005000
18:30:06.007052 brk(0x5642c6006000)     = 0x5642c6006000
18:30:06.007139 brk(0x5642c6007000)     = 0x5642c6007000
18:30:06.007200 brk(0x5642c6009000)     = 0x5642c6009000
18:30:06.007316 brk(0x5642c600c000)     = 0x5642c600c000
18:30:06.007449 brk(0x5642c600f000)     = 0x5642c600f000
18:30:06.007621 brk(0x5642c6014000)     = 0x5642c6014000
18:30:06.007830 brk(0x5642c6015000)     = 0x5642c6015000
18:30:06.007970 brk(0x5642c6016000)     = 0x5642c6016000
18:30:06.008084 getpid()                = 35
18:30:06.008148 getpid()                = 35
18:30:06.008233 open("/dev/urandom", O_RDONLY|O_NOCTTY|O_NONBLOCK) = 3
18:30:06.008325 fstat(3, {st_mode=S_IFCHR|0666, st_rdev=makedev(1, 9), ...}) = 0
18:30:06.008414 poll([{fd=3, events=POLLIN}], 1, 10) = 1 ([{fd=3, revents=POLLIN}])
18:30:06.008513 read(3, "\220K&\277\342gf\303\325\214\342\201\367\223\360\37\325h}\30\372\277cU\212\33\332\353%\205\346\36", 32) = 32
18:30:06.008579 close(3)                = 0
18:30:06.008670 getuid()                = 0
18:30:06.008778 clock_gettime(CLOCK_REALTIME, {tv_sec=1529692206, tv_nsec=8800714}) = 0
18:30:06.008904 brk(0x5642c6017000)     = 0x5642c6017000
18:30:06.009045 brk(0x5642c6019000)     = 0x5642c6019000
18:30:06.009186 getpid()                = 35
18:30:06.009255 getpid()                = 35
18:30:06.009316 getpid()                = 35
18:30:06.009369 getpid()                = 35
18:30:06.009479 stat("/etc/haproxy/dynamic/haproxy.cfg", {st_mode=S_IFREG|0644, st_size=1510, ...}) = 0
18:30:06.009594 open("/etc/haproxy/dynamic/haproxy.cfg", O_RDONLY) = 3
18:30:06.009674 readv(3, [{iov_base="", iov_len=0}, {iov_base="global\n  log 127.0.0.1:9515 loca"..., iov_len=1024}], 2) = 1024
18:30:06.009798 brk(0x5642c601b000)     = 0x5642c601b000
18:30:06.009941 open("/etc/haproxy/static/errors/400.http", O_RDONLY) = 4
18:30:06.010072 fstat(4, {st_mode=S_IFREG|0644, st_size=183, ...}) = 0
18:30:06.010177 read(4, "HTTP/1.0 400 Bad request\nCache-C"..., 183) = 183
18:30:06.010332 close(4)                = 0
18:30:06.010415 open("/etc/haproxy/static/errors/403.http", O_RDONLY) = 4
18:30:06.010552 fstat(4, {st_mode=S_IFREG|0644, st_size=184, ...}) = 0
18:30:06.010687 read(4, "HTTP/1.0 403 Forbidden\nCache-Con"..., 184) = 184
18:30:06.010792 close(4)                = 0
18:30:06.010869 open("/etc/haproxy/static/errors/408.http", O_RDONLY) = 4
18:30:06.010955 fstat(4, {st_mode=S_IFREG|0644, st_size=208, ...}) = 0
18:30:06.011094 read(4, "HTTP/1.0 408 Request Time-out\nCa"..., 208) = 208
18:30:06.011188 close(4)                = 0
18:30:06.011302 open("/etc/haproxy/static/errors/500.http", O_RDONLY) = 4
18:30:06.011414 fstat(4, {st_mode=S_IFREG|0644, st_size=181, ...}) = 0
18:30:06.011487 read(4, "HTTP/1.0 500 Server Error\nCache-"..., 181) = 181
18:30:06.011621 close(4)                = 0
18:30:06.011693 open("/etc/haproxy/static/errors/502.http", O_RDONLY) = 4
18:30:06.011784 fstat(4, {st_mode=S_IFREG|0644, st_size=200, ...}) = 0
18:30:06.011942 read(4, "HTTP/1.0 502 Bad Gateway\nCache-C"..., 200) = 200
18:30:06.012082 close(4)                = 0
18:30:06.012158 open("/etc/haproxy/static/errors/503.http", O_RDONLY) = 4
18:30:06.012242 fstat(4, {st_mode=S_IFREG|0644, st_size=208, ...}) = 0
18:30:06.012325 read(4, "HTTP/1.0 503 Service Unavailable"..., 208) = 208
18:30:06.012397 close(4)                = 0
18:30:06.012537 readv(3, [{iov_base="", iov_len=0}, {iov_base=" 504 /etc/haproxy/static/errors/"..., iov_len=1024}], 2) = 486
18:30:06.012629 open("/etc/haproxy/static/errors/504.http", O_RDONLY) = 4
18:30:06.012711 fstat(4, {st_mode=S_IFREG|0644, st_size=190, ...}) = 0
18:30:06.012855 read(4, "HTTP/1.0 504 Gateway Time-out\nCa"..., 190) = 190
18:30:06.012965 close(4)                = 0
18:30:06.013039 brk(0x5642c601d000)     = 0x5642c601d000
18:30:06.013129 brk(0x5642c601e000)     = 0x5642c601e000
18:30:06.013265 brk(0x5642c6020000)     = 0x5642c6020000
18:30:06.013349 brk(0x5642c6022000)     = 0x5642c6022000
18:30:06.013523 readv(3, [{iov_base="", iov_len=0}, {iov_base="", iov_len=1024}], 2) = 0
18:30:06.013692 close(3)                = 0
18:30:06.013770 clock_gettime(CLOCK_REALTIME, {tv_sec=1529692206, tv_nsec=13792909}) = 0
18:30:06.013907 brk(0x5642c6033000)     = 0x5642c6033000
18:30:06.013976 brk(0x5642c6044000)     = 0x5642c6044000
18:30:06.014059 brk(0x5642c6055000)     = 0x5642c6055000
18:30:06.014199 brk(0x5642c6066000)     = 0x5642c6066000
18:30:06.014285 brk(0x5642c6077000)     = 0x5642c6077000
18:30:06.014424 brk(0x5642c6088000)     = 0x5642c6088000
18:30:06.014523 writev(2, [{iov_base="", iov_len=0}, {iov_base="Available polling systems :\n", iov_len=28}], 2Available polling systems :
) = 28
18:30:06.014681 writev(2, [{iov_base="      epoll : ", iov_len=14}, {iov_base=NULL, iov_len=0}], 2      epoll : ) = 14
18:30:06.014858 writev(2, [{iov_base="pref=300, ", iov_len=10}, {iov_base=NULL, iov_len=0}], 2pref=300, ) = 10
18:30:06.014978 epoll_create1(0)        = 3
18:30:06.015096 close(3)                = 0
18:30:06.015163 writev(2, [{iov_base="", iov_len=0}, {iov_base=" test result OK", iov_len=15}], 2 test result OK) = 15
18:30:06.015303 writev(2, [{iov_base="", iov_len=0}, {iov_base="\n", iov_len=1}], 2
) = 1
18:30:06.015402 writev(2, [{iov_base="       poll : ", iov_len=14}, {iov_base=NULL, iov_len=0}], 2       poll : ) = 14
18:30:06.015490 writev(2, [{iov_base="pref=200, ", iov_len=10}, {iov_base=NULL, iov_len=0}], 2pref=200, ) = 10
18:30:06.015632 writev(2, [{iov_base="", iov_len=0}, {iov_base=" test result OK", iov_len=15}], 2 test result OK) = 15
18:30:06.015743 writev(2, [{iov_base="", iov_len=0}, {iov_base="\n", iov_len=1}], 2
) = 1
18:30:06.015923 writev(2, [{iov_base="     select : ", iov_len=14}, {iov_base=NULL, iov_len=0}], 2     select : ) = 14
18:30:06.016081 writev(2, [{iov_base="pref=150, ", iov_len=10}, {iov_base=NULL, iov_len=0}], 2pref=150, ) = 10
18:30:06.016188 writev(2, [{iov_base="", iov_len=0}, {iov_base=" test result FAILED", iov_len=19}], 2 test result FAILED) = 19
18:30:06.016281 writev(2, [{iov_base="", iov_len=0}, {iov_base="\n", iov_len=1}], 2
) = 1
18:30:06.016391 writev(2, [{iov_base="Total: 3 (2 usable), will use ep"..., iov_len=37}, {iov_base=NULL, iov_len=0}], 2Total: 3 (2 usable), will use epoll.
) = 37
18:30:06.016535 writev(2, [{iov_base="", iov_len=0}, {iov_base="\n", iov_len=1}], 2
) = 1
18:30:06.016678 writev(2, [{iov_base="", iov_len=0}, {iov_base="Available filters :\n", iov_len=20}], 2Available filters :
) = 20
18:30:06.016798 writev(2, [{iov_base="\t[SPOE] spoe\n", iov_len=13}, {iov_base=NULL, iov_len=0}], 2	[SPOE] spoe
) = 13
18:30:06.016896 writev(2, [{iov_base="\t[COMP] compression\n", iov_len=20}, {iov_base=NULL, iov_len=0}], 2	[COMP] compression
) = 20
18:30:06.017056 writev(2, [{iov_base="\t[TRACE] trace\n", iov_len=15}, {iov_base=NULL, iov_len=0}], 2	[TRACE] trace
) = 15
18:30:06.017161 mmap(NULL, 1028096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f1481e00000
18:30:06.017282 mmap(NULL, 258048, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f1481dc1000
18:30:06.017378 brk(0x5642c6098000)     = 0x5642c6098000
18:30:06.017976 epoll_create1(0)        = 3
18:30:06.018040 ioctl(1, TIOCGWINSZ, {ws_row=60, ws_col=135, ws_xpixel=0, ws_ypixel=0}) = 0
18:30:06.018117 writev(1, [{iov_base="Using epoll", iov_len=11}, {iov_base="() as the polling mechanism.\n", iov_len=29}], 2Using epoll() as the polling mechanism.
) = 40
18:30:06.018263 rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0
18:30:06.018359 rt_sigaction(SIGQUIT, {sa_handler=0x5642c3d7bcd0, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f1481cba0ea}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
18:30:06.018463 rt_sigaction(SIGUSR1, {sa_handler=0x5642c3d7bcd0, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f1481cba0ea}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
18:30:06.018565 rt_sigaction(SIGHUP, {sa_handler=0x5642c3d7bcd0, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f1481cba0ea}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
18:30:06.018779 rt_sigaction(SIGUSR2, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f1481cba0ea}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
18:30:06.018892 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f1481cba0ea}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
18:30:06.019021 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [USR2], 8) = 0
18:30:06.019154 rt_sigprocmask(SIG_BLOCK, ~[], NULL, 8) = 0
18:30:06.019253 prlimit64(0, RLIMIT_NOFILE, {rlim_cur=16035, rlim_max=16035}, NULL) = 0
18:30:06.019330 futex(0x7f1481f000a0, FUTEX_WAKE_PRIVATE, 2147483647) = 0
18:30:06.019430 rt_sigprocmask(SIG_SETMASK, [USR2], NULL, 8) = 0
18:30:06.019503 unlink("/var/run/haproxy.sock.35.tmp") = -1 ENOENT (No such file or directory)
18:30:06.019652 unlink("/var/run/haproxy.sock.35.bak") = -1 ENOENT (No such file or directory)
18:30:06.019742 link("/var/run/haproxy.sock", "/var/run/haproxy.sock.35.bak") = 0
18:30:06.019849 socket(AF_UNIX, SOCK_STREAM, 0) = 4
18:30:06.019992 fcntl(4, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
18:30:06.020081 bind(4, {sa_family=AF_UNIX, sun_path="/var/run/haproxy.sock.35.tmp"}, 110) = 0
18:30:06.020270 chmod("/var/run/haproxy.sock.35.tmp", 0600) = 0
18:30:06.020357 getsockopt(4, SOL_SOCKET, SO_ACCEPTCONN, [0], [4]) = 0
18:30:06.020440 listen(4, 10)           = 0
18:30:06.020560 rename("/var/run/haproxy.sock.35.tmp", "/var/run/haproxy.sock") = 0
18:30:06.020669 unlink("/var/run/haproxy.sock.35.bak") = 0
18:30:06.020848 socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 5
18:30:06.020963 getsockopt(5, SOL_TCP, TCP_MAXSEG, [536], [4]) = 0
18:30:06.021107 close(5)                = 0
18:30:06.021203 socket(AF_INET6, SOCK_STREAM, IPPROTO_TCP) = 5
18:30:06.021412 getsockopt(5, SOL_TCP, TCP_MAXSEG, [536], [4]) = 0
18:30:06.021512 close(5)                = 0
18:30:06.021577 socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 5
18:30:06.021722 fcntl(5, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
18:30:06.021797 setsockopt(5, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0
18:30:06.021950 getsockopt(5, SOL_SOCKET, SO_LINGER, {l_onoff=0, l_linger=0}, [8]) = 0
18:30:06.022044 setsockopt(5, SOL_SOCKET, SO_LINGER, {l_onoff=0, l_linger=0}, 8) = 0
18:30:06.022130 setsockopt(5, SOL_SOCKET, SO_REUSEPORT, [1], 4) = 0
18:30:06.022214 setsockopt(5, SOL_TCP, TCP_USER_TIMEOUT, [0], 4) = 0
18:30:06.022376 setsockopt(5, SOL_TCP, TCP_DEFER_ACCEPT, [0], 4) = 0
18:30:06.022511 getsockopt(5, SOL_TCP, TCP_FASTOPEN, [0], [4]) = 0
18:30:06.022604 bind(5, {sa_family=AF_INET, sin_port=htons(35000), sin_addr=inet_addr("0.0.0.0")}, 16) = 0
18:30:06.022745 getsockopt(5, SOL_SOCKET, SO_ACCEPTCONN, [0], [4]) = 0
18:30:06.022841 listen(5, 8000)         = 0
18:30:06.022960 setsockopt(5, SOL_TCP, TCP_QUICKACK, [0], 4) = 0
18:30:06.023046 getpid()                = 35
18:30:06.023175 getpid()                = 35
18:30:06.023235 socket(AF_INET, SOCK_DGRAM, IPPROTO_UDP) = 6
18:30:06.023362 setsockopt(6, SOL_SOCKET, SO_RCVBUF, [0], 4) = 0
18:30:06.023460 shutdown(6, SHUT_RD)    = -1 ENOTCONN (Socket not connected)
18:30:06.023531 fcntl(6, F_GETFD)       = 0
18:30:06.023660 fcntl(6, F_SETFD, FD_CLOEXEC) = 0
18:30:06.023729 sendmsg(6, {msg_name={sa_family=AF_INET, sin_port=htons(9515), sin_addr=inet_addr("127.0.0.1")}, msg_namelen=16, msg_iov=[{iov_base="<133>Jun 22 18:30:06 haproxy-rou"..., iov_len=53}, {iov_base="haproxy", iov_len=7}, {iov_base="[", iov_len=1}, {iov_base="35", iov_len=2}, {iov_base="]: ", iov_len=3}, {iov_base="", iov_len=0}, {iov_base="Proxy stats started.", iov_len=20}, {iov_base="\n", iov_len=1}], msg_iovlen=8, msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 87
18:30:06.028986 sendmsg(6, {msg_name={sa_family=AF_INET, sin_port=htons(9514), sin_addr=inet_addr("127.0.0.1")}, msg_namelen=16, msg_iov=[{iov_base="<141>Jun 22 18:30:06 haproxy-rou"..., iov_len=53}, {iov_base="haproxy", iov_len=7}, {iov_base="[", iov_len=1}, {iov_base="35", iov_len=2}, {iov_base="]: ", iov_len=3}, {iov_base="", iov_len=0}, {iov_base="Proxy stats started.", iov_len=20}, {iov_base="\n", iov_len=1}], msg_iovlen=8, msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 87
18:30:06.029861 socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 7
18:30:06.030191 fcntl(7, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
18:30:06.030289 setsockopt(7, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0
18:30:06.030423 getsockopt(7, SOL_SOCKET, SO_LINGER, {l_onoff=0, l_linger=0}, [8]) = 0
18:30:06.030574 setsockopt(7, SOL_SOCKET, SO_LINGER, {l_onoff=0, l_linger=0}, 8) = 0
18:30:06.030742 setsockopt(7, SOL_SOCKET, SO_REUSEPORT, [1], 4) = 0
18:30:06.030905 setsockopt(7, SOL_TCP, TCP_USER_TIMEOUT, [0], 4) = 0
18:30:06.031058 setsockopt(7, SOL_TCP, TCP_DEFER_ACCEPT, [0], 4) = 0
18:30:06.031268 getsockopt(7, SOL_TCP, TCP_FASTOPEN, [0], [4]) = 0
18:30:06.031442 bind(7, {sa_family=AF_INET, sin_port=htons(35001), sin_addr=inet_addr("0.0.0.0")}, 16) = 0
18:30:06.031596 getsockopt(7, SOL_SOCKET, SO_ACCEPTCONN, [0], [4]) = 0
18:30:06.031721 listen(7, 8000)         = 0
18:30:06.031885 setsockopt(7, SOL_TCP, TCP_QUICKACK, [0], 4) = 0
18:30:06.032033 getpid()                = 35
18:30:06.032155 sendmsg(6, {msg_name={sa_family=AF_INET, sin_port=htons(9515), sin_addr=inet_addr("127.0.0.1")}, msg_namelen=16, msg_iov=[{iov_base="<133>Jun 22 18:30:06 haproxy-rou"..., iov_len=53}, {iov_base="haproxy", iov_len=7}, {iov_base="[", iov_len=1}, {iov_base="35", iov_len=2}, {iov_base="]: ", iov_len=3}, {iov_base="", iov_len=0}, {iov_base="Proxy http started.", iov_len=19}, {iov_base="\n", iov_len=1}], msg_iovlen=8, msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 86
18:30:06.032758 sendmsg(6, {msg_name={sa_family=AF_INET, sin_port=htons(9514), sin_addr=inet_addr("127.0.0.1")}, msg_namelen=16, msg_iov=[{iov_base="<141>Jun 22 18:30:06 haproxy-rou"..., iov_len=53}, {iov_base="haproxy", iov_len=7}, {iov_base="[", iov_len=1}, {iov_base="35", iov_len=2}, {iov_base="]: ", iov_len=3}, {iov_base="", iov_len=0}, {iov_base="Proxy http started.", iov_len=19}, {iov_base="\n", iov_len=1}], msg_iovlen=8, msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 86
18:30:06.036063 socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 8
18:30:06.036214 fcntl(8, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
18:30:06.036348 setsockopt(8, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0
18:30:06.036568 getsockopt(8, SOL_SOCKET, SO_LINGER, {l_onoff=0, l_linger=0}, [8]) = 0
18:30:06.036702 setsockopt(8, SOL_SOCKET, SO_LINGER, {l_onoff=0, l_linger=0}, 8) = 0
18:30:06.036812 setsockopt(8, SOL_SOCKET, SO_REUSEPORT, [1], 4) = 0
18:30:06.036967 setsockopt(8, SOL_TCP, TCP_USER_TIMEOUT, [0], 4) = 0
18:30:06.037087 setsockopt(8, SOL_TCP, TCP_DEFER_ACCEPT, [0], 4) = 0
18:30:06.037276 getsockopt(8, SOL_TCP, TCP_FASTOPEN, [0], [4]) = 0
18:30:06.037438 bind(8, {sa_family=AF_INET, sin_port=htons(34999), sin_addr=inet_addr("10.10.44.9")}, 16) = -1 EADDRNOTAVAIL (Address not available)
18:30:06.037654 close(8)                = 0
18:30:06.037743 getpid()                = 35
18:30:06.037880 writev(2, [{iov_base="[ALERT] 172/183006 (35) : [hapro"..., iov_len=45}, {iov_base=NULL, iov_len=0}], 2[ALERT] 172/183006 (35) : [haproxy.main()] .
) = 45
18:30:06.038034 getpid()                = 35
18:30:06.038132 writev(2, [{iov_base="[ALERT] 172/183006 (35) : ", iov_len=26}, {iov_base="[haproxy.main()] Some protocols "..., iov_len=74}], 2[ALERT] 172/183006 (35) : [haproxy.main()] Some protocols failed to start their listeners! Exiting.
) = 100
18:30:06.038308 writev(2, [{iov_base="", iov_len=0}, {iov_base=NULL, iov_len=0}], 2) = 0
18:30:06.038485 close(5)                = 0
18:30:06.038556 close(7)                = 0
18:30:06.038726 close(4)                = 0
18:30:06.038912 exit_group(1)           = ?
18:30:06.039288 +++ exited with 1 +++

I should note that this is in an alpine-linux container running in Kubernetes on top of an Ubuntu 14.04 EC2 instance.

4

Are you sure you straced the non-working config? I can’t see any attempt to bind to port 34999 and there is also no error message in there (Some protocols failed to start their).

5

Yup, you were right. I should have figured that out when I had to CTRL-C. Derp. I updated my previous comment with the correct strace.

I see the error now is that the Address isn’t available. I’ve never run into that, but I imagine it’s some configuration on the kubernetes/docker side of things. I’ll investigate and report back.

6

I wonder if it has to do with the fact that the hostname or local IP is not actually 10.10.44.9, since it’s a docker container. I updated my config to use 0.0.0.0:34999 and it didn’t fail when running strace. I’m going to redeploy with that and all of my other config items to see if it all works together. Thank you for your help!

7

Yes, you cannot tell your kernel to bind a socket to 10.10.44.9 if that’s not a local IP. You’d need additional non-local options for this, but it doesn’t make sense in this case.