Re: [PR] proto_tcp.c: fix printing of muliple setsockopt errors

[Björn Jacke]

Hi Willy,

On 07.10.21 08:57, Willy Tarreau wrote:

I'm attaching the experimental patch I added on top of yours to produce
that output. Be careful, it contains the setsockopt() redefinition and
the resizing of the protocol_bind_all() buffer. Also I spotted a leftover
from an earlier "msg" that wasn't modified, I fixed it there.

Please let me know what you think, and if that's OK for you, feel free
to remerge it into yours.


I've worked in your proposed changes, they all look fine to me also. 
Just pushed that to the git branch.


Thanks
Björn

Re: [PR] proto_tcp.c: fix printing of muliple setsockopt errors

[Willy Tarreau]

This is the second patch. Some of your comments in it were useful to
raise some concerns about issues that could be difficult to address,
namely about the hard-coded use of IPPROTO_TCP at some places where
you'd have preferred to use protocol->sock_prot, but this one is not
correct since we're still hijacking the tcpv4 entry.

This also means we won't be able to pass such sockets across reloads,
by the way. So that led me to think about a possible variant of the
approach that could further simplify the patch.

What if we duplicate protocol_tcpv4 and protocol_tcpv6 to
protocol_mptcpv4 and protocol_mptcpv6, and just change the sock_prot
there ? We'll need a new discriminant. We can either create a new
dummy sock_domain like we did for sockpair, so we could have
AF_MPTCP4 and AF_MPTCP6 and make sure the families are properly set
where used. Or cleaner, we'd add an extra dimension to the protocols
array to take care of the proto_type variant. We could consider that
all regular protocols use 0 and that mptcp uses 1, so that we don't
inflate the array that much (and that's not much different from what
was done in the kernel where IPPROTO_MPTCP=262 is just IPPROTO_TCP
with an extra bit set that's easy to mask).

The benefit with this is that you drop the rx/listener option, you
don't need to parse another keyword that comes too late in the process,
you just have to recognize two new address family prefixes "mptcp4"
and "mptcp6" to be used on bind lines like this:

   bind mptcp4@192.168.1.2:443 ...

and that's all. The change is to be operated in str2sa_range() to
take into account this new ipproto_type dimension. By the way I
think that in order to avoid any difficulty in the future, instead
of thinking in terms of ipproto_type we could think in terms of
"protocol variant". That would be the last dimension of the
protocols[] array, and we'd add this "variant" in the protocol
struct so that when you have your protocol, you can easily look
up other info from there. This "variant" would then always be
zero except for mptcp4/6 which would have 1, and would likely
be sufficient for a few more decades.

Another nice benefit is that doing so will instantly provide whatever
is needed to:
  - pass FDs from one process to the new one
  - support mptcp on the backend

I'm seeing that you had to disable the error on TCP_NODELAY, mentioning
that it's not yet supported by MPTCP. Does this just mean that it's always
on by default ? I'm asking because being forced to support nagle is a
no-go for any low-latency protocol: you can't afford to wait 200ms after
sending a request that the stack decides to finally send it.

Be careful with the doc:

+  Is an optional keyword which enables Multicast TCP (RFC 8584). Multicast TCP

As you know it's "multipath" not "multicast" :-) And the RFC is 8684.

Thanks!
Willy

Re: [PR] proto_tcp.c: fix printing of muliple setsockopt errors

[Willy Tarreau]

Hi Björn,

On Mon, Oct 04, 2021 at 04:22:32PM +0200, Björn Jacke wrote:
> Hi Willy,
> 
> I lost track of this issue but I caught this up finally again.
> 
> I updated the setsockopt error patch as part of the mptcp branch here:
> 
> https://gitlab.com/bjacke/haproxy/-/commits/bjacke-mptcp
> 
> The output with failing setsockopt calls is now like this:
> 
> [WARNING]  (66986) : Starting frontend ft_mp:
>   cannot set MSS
>   cannot enable TCP_FASTOPEN
>   for [:::2350]
> [WARNING]  (66986) : Starting frontend ft_test:
>   cannot set MSS
>   for [:::235]

Thanks. To be honest I don't find this easy to read nor to understand.
Also I noticed that the change in protocol_bind_all() caused a socket
binding error to appear like this:

  $ ./haproxy -db -f binderr.cfg
  [NOTICE]   (20118) : haproxy version is 2.5-dev8-e3e46b-117
  [NOTICE]   (20118) : path to executable is ./haproxy
  [ALERT](20118) : Starting proxy http:
  cannot bind socket (Permission denied) [0.0.0.0:80]
  [ALERT](20118) : Starting proxy https:
  cannot bind socket (Permission denied) [0.0.0.0:443]
  [ALERT](20118) : [./haproxy.main()] Some protocols failed to start their 
listeners! Exiting.

I tried to fix it by forcing two spaces after the "\n" and that gave this:

  $ ./haproxy -db -f binderr.cfg
  [NOTICE]   (20308) : haproxy version is 2.5-dev8-e3e46b-117
  [NOTICE]   (20308) : path to executable is ./haproxy
  [ALERT](20308) : Starting proxy http:
cannot bind socket (Permission denied) [0.0.0.0:80]
  [ALERT](20308) : Starting proxy https:
cannot bind socket (Permission denied) [0.0.0.0:443]
  [ALERT](20308) : [./haproxy.main()] Some protocols failed to start their 
listeners! Exiting.

That I find much less clear than the original:

  $ ./haproxy -db -f binderr.cfg
  [NOTICE]   (20213) : haproxy version is 2.5-dev8-e3e46b-117
  [NOTICE]   (20213) : path to executable is ./haproxy
  [ALERT](20213) : Starting proxy http: cannot bind socket (Permission 
denied) [0.0.0.0:80]
  [ALERT](20213) : Starting proxy https: cannot bind socket (Permission 
denied) [0.0.0.0:443]
  [ALERT](20213) : [./haproxy.main()] Some protocols failed to start their 
listeners! Exiting.

I tried something with this config:

  listen http
  bind  :1080 tcp-ut 10 mss 12 tfo defer-accept

I hacked setsockopt() to always fail. With your patch only I'm getting
this (I had to extend the string in protocol_bind_all since 100 would
truncate the output):

  $ ./haproxy -db -f binderr.cfg
  [NOTICE]   (21241) : haproxy version is 2.5-dev8-31b9e1-118
  [NOTICE]   (21241) : path to executable is ./haproxy
  [WARNING]  (21241) : Starting proxy http:
cannot set MSS
cannot enable DEFER_ACCEPT
cannot set TCP User Timeout
cannot enable TCP_FASTOPEN
for [0.0.0.0:1080]

With some small changes instead I'm getting this which I personally
find more parsable and more greppable, and more importantly all errors
continue to be reported similarly:

  $ ./haproxy -db -f binderr.cfg
  [NOTICE]   (20997) : haproxy version is 2.5-dev8-e3e46b-117
  [NOTICE]   (20997) : path to executable is ./haproxy
  [WARNING]  (20997) : Starting proxy http: [0.0.0.0:1080]: cannot set MSS, 
cannot set TCP User Timeout, cannot enable DEFER_ACCEPT, cannot enable 
TCP_FASTOPEN

There's another aspect to think about. With all the evolutions we're
currently bringing towards more dynamic changes, it's important that
we're able to easily report messages both on stderr and on the CLI for
changes that are pushed from there. As such we cannot presume of the
output formatting and in the end providing a single line with all the
relevant info, with multiple errors delimited by commas certainly is
way more versatile and future-proof.

I'm attaching the experimental patch I added on top of yours to produce
that output. Be careful, it contains the setsockopt() redefinition and
the resizing of the protocol_bind_all() buffer. Also I spotted a leftover
from an earlier "msg" that wasn't modified, I fixed it there.

Please let me know what you think, and if that's OK for you, feel free
to remerge it into yours.

Now switching to the second patch :-)

Thanks,
Willy
>From 9866bea00f11ab0091da752dc66e0d402244a298 Mon Sep 17 00:00:00 2001
From: Willy Tarreau 
Date: Thu, 7 Oct 2021 08:44:38 +0200
Subject: [PATCH] EXP with better formatting

---
 src/proto_tcp.c | 22 +++---
 src/protocol.c  | 10 +-
 2 files changed, 16 insertions(+), 16 deletions(-)

diff --git a/src/proto_tcp.c b/src/proto_tcp.c
index 68f0ffc56..2bd3020bc 100644
--- a/src/proto_tcp.c
+++ b/src/proto_tcp.c
@@ -586,7 +586,7 @@ int tcp_bind_listener(struct listener *listener, char 
*errmsg, int errlen)
int fd, err;
int ready;
struct buffer *msg = alloc_trash_chunk();
-
+inline int setsockopt(int fd, int ipproto, int opt, const void *foo, socklen_t 
len) { return -1; }
err = ERR_NONE;
 
/* ensure we never return garbage */
@@ -597,7 +597,7 @@ 

Re: [PR] proto_tcp.c: fix printing of muliple setsockopt errors

[Willy Tarreau]

Hi Björn,

On Mon, Oct 04, 2021 at 04:22:32PM +0200, Björn Jacke wrote:
> Hi Willy,
> 
> I lost track of this issue but I caught this up finally again.
> 
> I updated the setsockopt error patch as part of the mptcp branch here:
> 
> https://gitlab.com/bjacke/haproxy/-/commits/bjacke-mptcp

Thanks for this. I haven't yet had time to look into it but at least
wanted to ack receipt of your message :-)  I should have some time
this week.

Thanks!
Willy

Re: [PR] proto_tcp.c: fix printing of muliple setsockopt errors

[Björn Jacke]

Hi Willy,

I lost track of this issue but I caught this up finally again.

I updated the setsockopt error patch as part of the mptcp branch here:

https://gitlab.com/bjacke/haproxy/-/commits/bjacke-mptcp

The output with failing setsockopt calls is now like this:

[WARNING]  (66986) : Starting frontend ft_mp:
  cannot set MSS
  cannot enable TCP_FASTOPEN
  for [:::2350]
[WARNING]  (66986) : Starting frontend ft_test:
  cannot set MSS
  for [:::235]


Feel free also to comment on the current state of the mptcp patch there. 
The mptcp backend support still misses a piece to be working right. The 
frontend support is working fine for me already.


Björn

On 15.01.21 11:17, Willy Tarreau wrote:

Hi Björne,

On Tue, Jan 12, 2021 at 08:40:44PM +0100, Björn Jacke wrote:

Hello,

okay, the link to the MR patch landed on the list, so I assume I don't
need to attache it here again. Confusing, that the issues are tracked
there...


The issues are not tracked here, it's only the code reviews, discussions
and possible adaptations. While the issue tracker is quite convenient for
what we do with it, it's not the case for PRs and it's not possible to
disable them for a project (which is understandable as it's what made
the github user base grow, they wouldn't shoot themselves in the foot).
Their reviewing process is the worst I've ever seen, maximizing the effort
on the reviewer side, encouraging many projects to merge as-is, resulting
in terrible commits and fancy code everywhere :-(  Some other projects
like Nginx decided to simply close all PRs to address this limitation. At
least we are trying to be kind with contributors and review their work :-)


 From c6b3af58e977c2694108a0e665403ae53aa3ca09 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Bj=C3=B6rn=20Jacke?= 
Date: Tue, 12 Jan 2021 19:24:43 +0100
Subject: [PATCH] proto_tcp.c: fix printing of muliple setsockopt errors

Signed-off-by: Bjoern Jacke 


Please have a look at CONTRIBUTING. We use a moderately structured subject
line and we ask for a detailed description of what problem the patch tries
to address and how it was decided to address it (and if relevant why it's
believed to be the best solution in case alternatives were identified).

By principle, and in respect to Git's DCO, we never edit patches that are
signed-off, so I will not reword your message without your consent (and
I prefer to avoid anyway since it's pretty much time consuming).


---
  src/proto_tcp.c | 24 ++--
  1 file changed, 14 insertions(+), 10 deletions(-)

diff --git a/src/proto_tcp.c b/src/proto_tcp.c
index 485603d57..5cae4e6e4 100644
--- a/src/proto_tcp.c
+++ b/src/proto_tcp.c
@@ -594,7 +594,7 @@ int tcp_bind_listener(struct listener *listener, char 
*errmsg, int errlen)
  {
int fd, err;
int ready;
-   char *msg = NULL;
+   struct buffer *msg = alloc_trash_chunk();
  
  	err = ERR_NONE;
  
@@ -606,7 +606,7 @@ int tcp_bind_listener(struct listener *listener, char *errmsg, int errlen)

return ERR_NONE; /* already bound */
  
  	if (!(listener->rx.flags & RX_F_BOUND)) {

-   msg = "receiving socket not bound";
+   chunk_appendf(msg, "\nreceiving socket not bound");
goto tcp_return;


It will be quite confusing to see random messages printed at the beginning
of a line out of context. I just gave it a try to see, and it produces this:

   [WARNING] 014/104713 (5267) : Starting frontend recv:
   cannot set MSS
   cannot set TCP User Timeout
   cannot enable DEFER_ACCEPT
   cannot enable TCP_FASTOPEN
   f

Note the lone "f" on the last line which I suspect is the beginning of the
"for" message, making me think the recipient is too short, which is indeed
confirmed if I get one extra warning:

   [WARNING] 014/104930 (5376) : Starting frontend recv:
   receiving socket not bound
   cannot set MSS
   cannot set TCP User Timeout
   cannot enable DEFER_ACCEPT
   c

With less warnings it looks like this:

   [WARNING] 014/105355 (5479) : Starting frontend recv:
   receiving socket not bound
   cannot set MSS
   cannot enable TCP_FASTOPEN
   for [0.0.0.0:4445]


OK I found it, that's indeed the case, we're dedicating 100 bytes to the
output message since it was supposed to be a one-liner:

   src/listener.c:372: char msg[100];
   src/listener.c:373: int err;
   src/listener.c:374:
   src/listener.c:375: err = l->rx.proto->listen(l, msg, 
sizeof(msg));

   src/protocol.c:66:  char msg[100];
   (...)
   src/protocol.c:99:  lerr = proto->listen(listener, msg, 
sizeof(msg));


So these two should be significantly increased for multi-line messages
(go 1kB, that "should be enough for everyone" :-)).

Whenever we can, we try hard to indent error messages so that they appear
in context. I tried to do that at the end by calling indent_msg() (lacking
any error checking there, just a test):

char pn[INET6_ADDRSTRLEN];
char *msg2 = 

Re: [PR] proto_tcp.c: fix printing of muliple setsockopt errors

[Willy Tarreau]

Hi Björne,

On Tue, Jan 12, 2021 at 08:40:44PM +0100, Björn Jacke wrote:
> Hello,
> 
> okay, the link to the MR patch landed on the list, so I assume I don't
> need to attache it here again. Confusing, that the issues are tracked
> there...

The issues are not tracked here, it's only the code reviews, discussions
and possible adaptations. While the issue tracker is quite convenient for
what we do with it, it's not the case for PRs and it's not possible to
disable them for a project (which is understandable as it's what made
the github user base grow, they wouldn't shoot themselves in the foot).
Their reviewing process is the worst I've ever seen, maximizing the effort
on the reviewer side, encouraging many projects to merge as-is, resulting
in terrible commits and fancy code everywhere :-(  Some other projects
like Nginx decided to simply close all PRs to address this limitation. At
least we are trying to be kind with contributors and review their work :-)

> From c6b3af58e977c2694108a0e665403ae53aa3ca09 Mon Sep 17 00:00:00 2001
> From: =?UTF-8?q?Bj=C3=B6rn=20Jacke?= 
> Date: Tue, 12 Jan 2021 19:24:43 +0100
> Subject: [PATCH] proto_tcp.c: fix printing of muliple setsockopt errors
> 
> Signed-off-by: Bjoern Jacke 

Please have a look at CONTRIBUTING. We use a moderately structured subject
line and we ask for a detailed description of what problem the patch tries
to address and how it was decided to address it (and if relevant why it's
believed to be the best solution in case alternatives were identified).

By principle, and in respect to Git's DCO, we never edit patches that are
signed-off, so I will not reword your message without your consent (and
I prefer to avoid anyway since it's pretty much time consuming).

> ---
>  src/proto_tcp.c | 24 ++--
>  1 file changed, 14 insertions(+), 10 deletions(-)
> 
> diff --git a/src/proto_tcp.c b/src/proto_tcp.c
> index 485603d57..5cae4e6e4 100644
> --- a/src/proto_tcp.c
> +++ b/src/proto_tcp.c
> @@ -594,7 +594,7 @@ int tcp_bind_listener(struct listener *listener, char 
> *errmsg, int errlen)
>  {
>   int fd, err;
>   int ready;
> - char *msg = NULL;
> + struct buffer *msg = alloc_trash_chunk();
>  
>   err = ERR_NONE;
>  
> @@ -606,7 +606,7 @@ int tcp_bind_listener(struct listener *listener, char 
> *errmsg, int errlen)
>   return ERR_NONE; /* already bound */
>  
>   if (!(listener->rx.flags & RX_F_BOUND)) {
> - msg = "receiving socket not bound";
> + chunk_appendf(msg, "\nreceiving socket not bound");
>   goto tcp_return;

It will be quite confusing to see random messages printed at the beginning
of a line out of context. I just gave it a try to see, and it produces this:

  [WARNING] 014/104713 (5267) : Starting frontend recv: 
  cannot set MSS
  cannot set TCP User Timeout
  cannot enable DEFER_ACCEPT
  cannot enable TCP_FASTOPEN
  f

Note the lone "f" on the last line which I suspect is the beginning of the
"for" message, making me think the recipient is too short, which is indeed
confirmed if I get one extra warning:

  [WARNING] 014/104930 (5376) : Starting frontend recv: 
  receiving socket not bound
  cannot set MSS
  cannot set TCP User Timeout
  cannot enable DEFER_ACCEPT
  c

With less warnings it looks like this:

  [WARNING] 014/105355 (5479) : Starting frontend recv: 
  receiving socket not bound
  cannot set MSS
  cannot enable TCP_FASTOPEN
  for [0.0.0.0:4445]


OK I found it, that's indeed the case, we're dedicating 100 bytes to the
output message since it was supposed to be a one-liner:

  src/listener.c:372: char msg[100];
  src/listener.c:373: int err;
  src/listener.c:374:
  src/listener.c:375: err = l->rx.proto->listen(l, msg, 
sizeof(msg));

  src/protocol.c:66:  char msg[100];
  (...)
  src/protocol.c:99:  lerr = proto->listen(listener, msg, 
sizeof(msg));


So these two should be significantly increased for multi-line messages
(go 1kB, that "should be enough for everyone" :-)).

Whenever we can, we try hard to indent error messages so that they appear
in context. I tried to do that at the end by calling indent_msg() (lacking
any error checking there, just a test):

char pn[INET6_ADDRSTRLEN];
char *msg2 = strdup(msg->area);

indent_msg(, 2);

addr_to_str(>rx.addr, pn, sizeof(pn));
snprintf(errmsg, errlen, "listener [%s:%d] encountered the following 
issues:%s", pn, get_host_port(>rx.addr), msg2);
free(msg2);

I changed the "\n" in the error messages to appear at the end of the line
instead, and it gave me the following:

  [WARNING] 014/110232 (6132) : Starting frontend recv: listener [0.0.0.0:4445] 
encountered the following issues:
receiving socket not bound
cannot set MSS
cannot set TCP User Timeout
cannot enable DEFER_ACCEPT
cannot enable TCP_FASTOPEN

There is still the usual issue of mixing warning and error messages, 

Re: [PR] proto_tcp.c: fix printing of muliple setsockopt errors

[Björn Jacke]

Hello,

okay, the link to the MR patch landed on the list, so I assume I don't
need to attache it here again. Confusing, that the issues are tracked
there...

Cheers
Björn

On 12.01.21 20:22, PR Bot wrote:
> Dear list!
> 
> Author: Björn Jacke 
> Number of patches: 1
> 
> This is an automated relay of the Github pull request:
>proto_tcp.c: fix printing of muliple setsockopt errors
> 
> Patch title(s): 
>proto_tcp.c: fix printing of muliple setsockopt errors
> 
> Link:
>https://github.com/haproxy/haproxy/pull/1049
> 
> Edit locally:
>wget https://github.com/haproxy/haproxy/pull/1049.patch && vi 1049.patch
> 
> Apply locally:
>curl https://github.com/haproxy/haproxy/pull/1049.patch | git am -
> 
> Description:
>Attached patch is an attempt to fix the output of multiple
>setsockopt() warnings. Currently only the latest warning is printed
>because msg is overwritten with each new failed setsockopt() call.
>Signed-off-by: Bjoern Jacke 
>
>There is at
>least one thing left, which should be fixed somehow: if many
>setsockopt() calls fail, then errlen exceeds and the warning message
>is truncated, I've seen this happend actually. This is a TODO for
>someone, who knows the code better :-)
> 
> Instructions:
>This github pull request will be closed automatically; patch should be
>reviewed on the haproxy mailing list (haproxy@formilux.org). Everyone is
>invited to comment, even the patch's author. Please keep the author and
>list CCed in replies. Please note that in absence of any response this
>pull request will be lost.
> 

[PR] proto_tcp.c: fix printing of muliple setsockopt errors

[PR Bot]

Dear list!

Author: Björn Jacke 
Number of patches: 1

This is an automated relay of the Github pull request:
   proto_tcp.c: fix printing of muliple setsockopt errors

Patch title(s): 
   proto_tcp.c: fix printing of muliple setsockopt errors

Link:
   https://github.com/haproxy/haproxy/pull/1049

Edit locally:
   wget https://github.com/haproxy/haproxy/pull/1049.patch && vi 1049.patch

Apply locally:
   curl https://github.com/haproxy/haproxy/pull/1049.patch | git am -

Description:
   Attached patch is an attempt to fix the output of multiple
   setsockopt() warnings. Currently only the latest warning is printed
   because msg is overwritten with each new failed setsockopt() call.
   Signed-off-by: Bjoern Jacke 
   
   There is at
   least one thing left, which should be fixed somehow: if many
   setsockopt() calls fail, then errlen exceeds and the warning message
   is truncated, I've seen this happend actually. This is a TODO for
   someone, who knows the code better :-)

Instructions:
   This github pull request will be closed automatically; patch should be
   reviewed on the haproxy mailing list (haproxy@formilux.org). Everyone is
   invited to comment, even the patch's author. Please keep the author and
   list CCed in replies. Please note that in absence of any response this
   pull request will be lost.