proxy_protocol listener with deny_unauthorized dies on first connection

[candlerb]

Describe the bug
When you have a secondary listener configured with proxy_protocol, with proxy_protocol_behavior = "deny_unauthorized", the listener dies silently on first connection.

To Reproduce
Start vault using vault server -config=vault-test.hcl -log-level=debug, where the configuration file is given below. This has a regular listener on port 1111 and a proxy_protocol listener on port 2222.

Check both ports are listening:

# ss -natp | egrep ':(1111|2222)'
LISTEN 0      128                           *:2222                            *:*              users:(("vault",pid=458,fd=9))
LISTEN 0      128                           *:1111                            *:*              users:(("vault",pid=458,fd=8))

Connect to 127.0.0.1 port 2222, then disconnect.

# telnet 127.0.0.1 2222
Trying 127.0.0.1...
Connected to 127.0.0.1.
Escape character is '^]'.
^]close

telnet> close
Connection closed.

Check socket status again (note no listener on 2222):

# ss -natp | egrep ':(1111|2222)'
FIN-WAIT-2      0           0                               127.0.0.1:55606                                              127.0.0.1:2222
LISTEN          0           128                                     *:1111                                                       *:*                             users:(("vault",pid=458,fd=8))
CLOSE-WAIT      1           0                      [::ffff:127.0.0.1]:2222                                      [::ffff:127.0.0.1]:55606                         users:(("vault",pid=458,fd=10))

Confirm that no further connections are accepted:

# telnet 127.0.0.1 2222
Trying 127.0.0.1...
telnet: Unable to connect to remote host: Connection refused

Expected behavior

1. Vault should handle proxy_protocol messages on port 2222.
2. If there is a protocol error, it should still continue to listen for new connections.
3. If there is a problem, it should be logged (nothing is seen, not even with -log-level=debug)

Environment:

• Vault Server Version: Vault v1.6.3 (b540be4b7ec48d0dd7512c8d8df9399d6bf84d76)
• Vault CLI Version: N/A
• Server Operating System/Architecture: Ubuntu 20.04 amd64 in lxd container; underlying host is 18.04.5 with kernel 4.15.0-128-generic

Vault server configuration file(s):

storage "file" {
  path = "/var/tmp/vault"
}

listener "tcp" {
  address = "[::]:1111"
  tls_disable = "true"
}

listener "tcp" {
  address = "[::]:2222"
  proxy_protocol_authorized_address = "127.0.0.1"
  proxy_protocol_behavior = "deny_unauthorized"
  tls_disable = "true"
}

disable_mlock = "true"
ui = "true"

Additional context
When running with the problematic config under strace, it shows the listening socket (fd 9) accepting a connection (fd 10), and then the listening socket (9) being closed.

[pid   660] 14:04:24.462396 futex(0x82cc038, FUTEX_WAKE_PRIVATE, 1) = 1
[pid   658] 14:04:24.462639 <... futex resumed>) = 0
[pid   660] 14:04:24.462748 accept4(9,  <unfinished ...>
[pid   658] 14:04:24.462845 nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid   660] 14:04:24.463004 <... accept4 resumed>{sa_family=AF_INET6, sin6_port=htons(56930), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "::ffff:127.0.0.1", &sin6_addr), sin6_scope_id=0}, [112->28], SOCK_CLOEXEC|SOCK_NONBLOCK) = 10
[pid   658] 14:04:24.463472 <... nanosleep resumed>NULL) = 0
[pid   660] 14:04:24.463674 epoll_ctl(4, EPOLL_CTL_ADD, 10, {EPOLLIN|EPOLLOUT|EPOLLRDHUP|EPOLLET, {u32=2227302312, u64=140499197489064}} <unfinished ...>
[pid   658] 14:04:24.463806 nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid   660] 14:04:24.463955 <... epoll_ctl resumed>) = 0
[pid   658] 14:04:24.464034 <... nanosleep resumed>NULL) = 0
[pid   660] 14:04:24.464139 getsockname(10,  <unfinished ...>
[pid   658] 14:04:24.464244 nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid   660] 14:04:24.464384 <... getsockname resumed>{sa_family=AF_INET6, sin6_port=htons(2222), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "::ffff:127.0.0.1", &sin6_addr), sin6_scope_id=0}, [112->28]) = 0
[pid   658] 14:04:24.464502 <... nanosleep resumed>NULL) = 0
[pid   660] 14:04:24.464633 setsockopt(10, SOL_TCP, TCP_NODELAY, [1], 4 <unfinished ...>
[pid   658] 14:04:24.464745 nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid   660] 14:04:24.464885 <... setsockopt resumed>) = 0
[pid   660] 14:04:24.464996 setsockopt(10, SOL_SOCKET, SO_KEEPALIVE, [1], 4 <unfinished ...>
[pid   658] 14:04:24.465105 <... nanosleep resumed>NULL) = 0
[pid   660] 14:04:24.465212 <... setsockopt resumed>) = 0
[pid   660] 14:04:24.465314 setsockopt(10, SOL_TCP, TCP_KEEPINTVL, [15], 4 <unfinished ...>
[pid   658] 14:04:24.465441 nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid   660] 14:04:24.465553 <... setsockopt resumed>) = 0
[pid   660] 14:04:24.465648 setsockopt(10, SOL_TCP, TCP_KEEPIDLE, [15], 4) = 0
[pid   658] 14:04:24.465818 <... nanosleep resumed>NULL) = 0
[pid   660] 14:04:24.465896 setsockopt(10, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0
[pid   658] 14:04:24.466062 nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid   660] 14:04:24.466164 setsockopt(10, SOL_TCP, TCP_KEEPINTVL, [180], 4) = 0
[pid   658] 14:04:24.466334 <... nanosleep resumed>NULL) = 0
[pid   660] 14:04:24.466415 setsockopt(10, SOL_TCP, TCP_KEEPIDLE, [180], 4) = 0
[pid   658] 14:04:24.466682 nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid   660] 14:04:24.466829 epoll_ctl(4, EPOLL_CTL_DEL, 9, 0xc00076dc8c) = 0
[pid   660] 14:04:24.466992 close(9 <unfinished ...>
[pid   658] 14:04:24.467130 <... nanosleep resumed>NULL) = 0
[pid   660] 14:04:24.467208 <... close resumed>) = 0
[pid   660] 14:04:24.467321 epoll_pwait(4,  <unfinished ...>
[pid   658] 14:04:24.467469 nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid   660] 14:04:24.467638 <... epoll_pwait resumed>[{EPOLLOUT, {u32=2227302312, u64=140499197489064}}], 128, 0, NULL, 824641511424) = 1
[pid   660] 14:04:24.467773 epoll_pwait(4,  <unfinished ...>
[pid   658] 14:04:24.467879 <... nanosleep resumed>NULL) = 0
[pid   658] 14:04:24.468050 futex(0x82cc038, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=390494490}) = -1 ETIMEDOUT (Connection timed out)

Workaround
The problem goes away if you set

proxy_protocol_behavior = "use_always"

[candlerb]

The problem appears to be fixed in v1.9.4: if I attempt to reproduce as above, the connection to 127.0.0.1:2222 is immediately dropped and the listener continues working.

# telnet 127.0.0.1 2222
Trying 127.0.0.1...
Connected to 127.0.0.1.
Escape character is '^]'.
Connection closed by foreign host.

# ss -natp | egrep ':(1111|2222)'
LISTEN         0           128                                     *:2222                                                        *:*                             users:(("vault",pid=508674,fd=9))
LISTEN         0           128                                     *:1111                                                        *:*                             users:(("vault",pid=508674,fd=8))
TIME-WAIT      0           0                      [::ffff:127.0.0.1]:2222                                       [::ffff:127.0.0.1]:45866

However, the vault server still does not log any message when denying a proxy_protocol request, even with -log-level=debug, and I think it would be helpful if it did.

(Aside: to get the connection accepted, you have to change proxy_protocol_authorized_address to proxy_protocol_authorized_addrs. Vault's HCL parser silently ignores unknown settings)

[aphorise]

Thanks for the update - I do recall this issue for a few versions around the time you'd reported it and it was actually resolved prior to 1.9.x IIRC. In any case if you tested on TRACE level logs and still dont see any additional events then I'd wait for future features around telemetry or other logging improvements; there's other Github issues already (on here) including another requesting the 3rd item you'd mentioned around HCL checking 😄

Hey @candlerb do you agree that your issue can now be closed?

[candlerb]

Yes, this can be closed.

I haven't tried with TRACE level logs.

Aside: the issue with unknown settings being silently ignored was fixed in #14752.