[pve-devel] [PATCH http-server v3 0/4] improve error handling in accept_connections

[pve-devel] [PATCH http-server v3 0/4] improve error handling in accept_connections

[Stoiko Ivanov]

v2->v3:
* incorporated Thomas patient and excellent feedback (Thanks!!):
* replaced the two error-flags by a single handle_creation flag,  based
  on the observation that the code after AnyEvent::Handle->new() does not die
  (and that we'd probably still shutdown the socket if it did)
* replaced the calls to shutdown($fh, SHUT_RD) with calls to close - in case
  accept() fails, we don't want to sent anything + it sents one tcp-packet less
  (only rst+ack, instead of fin+ack,rst+ack)
* replaced syslog+dprint by a single warn (in our AnyEvent daemons that results
  in the line being printed to STDERR+to syslog with level warning)
* squashed 1/5 (introduce dprint sub) and 5/5 (use it)

tested on my workstation (the cleanup by having an deny-acl in
/etc/default/pveproxy and connecting 1000 times with openssl s_client)

original cover-letter for v2:
v1->v2:
* increment of connection count now happens right before the AnyEvent::Handle
  is created
* the handle-creation is guarded by an error-flag, and if it fails the
  connection count is decremented (bounded to 0) again
* as suggested by Thomas - added a debug print sub which includes the
  package name, linenumber and function name where the printing happens
* refactored all active debug-prints to use it.

original cover-letter for v1:
This patchset is the result of investigating a report in our community forum:
https://forum.proxmox.com/threads/pveproxy-eats-available-ram.79617/

The first patch fixes an issue where pveproxy worker processes would never
exit (and eat quite a bit of ram+cpu) when 'getpeername' returned an error.

The second seemed to me like a sensible further cleanup, and the third patch
will hopefully provide the needed information when debugging such things in
the future.

Huge thanks to Dominik, who analyzed this issue with me!


Stoiko Ivanov (4):
  add debug print helper
  accept-phase: fix conn_count "leak"
  accept-phase: shutdown socket on early error
  add debug log for problems during accept

 PVE/APIServer/AnyEvent.pm | 68 ++++++++++++++++++++++++++++++---------
 1 file changed, 53 insertions(+), 15 deletions(-)

-- 
2.20.1

[pve-devel] [PATCH http-server v3 1/4] add debug print helper

[Stoiko Ivanov]

and uniformly use it

Suggested-by: Thomas Lamprecht <t.lamprecht@proxmox.com>
Signed-off-by: Stoiko Ivanov <s.ivanov@proxmox.com>
---
 PVE/APIServer/AnyEvent.pm | 32 +++++++++++++++++++++-----------
 1 file changed, 21 insertions(+), 11 deletions(-)

diff --git a/PVE/APIServer/AnyEvent.pm b/PVE/APIServer/AnyEvent.pm
index c55da7f..b8c28ce 100644
--- a/PVE/APIServer/AnyEvent.pm
+++ b/PVE/APIServer/AnyEvent.pm
@@ -66,6 +66,16 @@ my $split_abs_uri = sub {
     return wantarray ? ($rel_uri, $format) : $rel_uri;
 };
 
+sub dprint {
+    my ($self, $message) = @_;
+
+    return if !$self->{debug};
+
+    my ($pkg, $pkgfile, $line, $sub) = caller(1);
+    $sub =~ s/^(?:.+::)+//;
+    print "worker[$$]: $pkg +$line: $sub: $message\n";
+}
+
 sub log_request {
     my ($self, $reqstate) = @_;
 
@@ -143,13 +153,13 @@ sub client_do_disconnect {
 	return;
     }
 
-    print "close connection $hdl\n" if $self->{debug};
+    $self->dprint("close connection $hdl");
 
     &$shutdown_hdl($hdl);
 
     $self->{conn_count}--;
 
-    print "$$: CLOSE FH" .  $hdl->{fh}->fileno() . " CONN$self->{conn_count}\n" if $self->{debug};
+    $self->dprint("CLOSE FH" .  $hdl->{fh}->fileno() . " CONN$self->{conn_count}");
 }
 
 sub finish_response {
@@ -412,7 +422,7 @@ sub websocket_proxy {
 	    my ($fh) = @_
 		or die "connect to '$remhost:$remport' failed: $!";
 
-	    print "$$: CONNECTed to '$remhost:$remport'\n" if $self->{debug};
+	    $self->dprint("CONNECTed to '$remhost:$remport'");
 
 	    $reqstate->{proxyhdl} = AnyEvent::Handle->new(
 		fh => $fh,
@@ -507,7 +517,7 @@ sub websocket_proxy {
 			$reqstate->{proxyhdl}->push_write($payload) if $reqstate->{proxyhdl};
 		    } elsif ($opcode == 8) {
 			my $statuscode = unpack ("n", $payload);
-			print "websocket received close. status code: '$statuscode'\n" if $self->{debug};
+			$self->dprint("websocket received close. status code: '$statuscode'");
 			if ($reqstate->{proxyhdl}) {
 			    $reqstate->{proxyhdl}->push_shutdown();
 			}
@@ -538,7 +548,7 @@ sub websocket_proxy {
 		"Sec-WebSocket-Protocol: $wsproto\015\012" .
 		"\015\012";
 
-	    print $res if $self->{debug};
+	    $self->dprint($res);
 
 	    $reqstate->{hdl}->push_write($res);
 
@@ -840,9 +850,9 @@ sub handle_spice_proxy_request {
 
         if ($node ne 'localhost' && PVE::INotify::nodename() !~ m/^$node$/i) {
             $remip = $self->remote_node_ip($node);
-	    print "REMOTE CONNECT $vmid, $remip, $connect_str\n" if $self->{debug};
+	    $self->dprint("REMOTE CONNECT $vmid, $remip, $connect_str");
         } else {
-	    print "$$: CONNECT $vmid, $node, $spiceport\n" if $self->{debug};
+	    $self->dprint("CONNECT $vmid, $node, $spiceport");
 	}
 
 	if ($remip && $r->header('PVEDisableProxy')) {
@@ -860,7 +870,7 @@ sub handle_spice_proxy_request {
 	    my ($fh) = @_
 		or die "connect to '$remhost:$remport' failed: $!";
 
-	    print "$$: CONNECTed to '$remhost:$remport'\n" if $self->{debug};
+	    $self->dprint("CONNECTed to '$remhost:$remport'");
 	    $reqstate->{proxyhdl} = AnyEvent::Handle->new(
 		fh => $fh,
 		rbuf_max => 64*1024,
@@ -1333,7 +1343,7 @@ sub unshift_read_header {
 
 			die "upload without content length header not supported" if !$len;
 
-			print "start upload $path $ct $boundary\n" if $self->{debug};
+			$self->dprint("start upload $path $ct $boundary");
 
 			my $tmpfilename = get_upload_filename();
 			my $outfh = IO::File->new($tmpfilename, O_RDWR|O_CREAT|O_EXCL, 0600) ||
@@ -1571,7 +1581,7 @@ sub accept_connections {
 	    }
 
 	    if (!$self->{trusted_env} && !$self->check_host_access($reqstate->{peer_host})) {
-		print "$$: ABORT request from $reqstate->{peer_host} - access denied\n" if $self->{debug};
+		$self->dprint("ABORT request from $reqstate->{peer_host} - access denied");
 		$reqstate->{log}->{code} = 403;
 		$self->log_request($reqstate);
 		next;
@@ -1600,7 +1610,7 @@ sub accept_connections {
 		},
 		($self->{tls_ctx} ? (tls => "accept", tls_ctx => $self->{tls_ctx}) : ()));
 
-	    print "$$: ACCEPT FH" .  $clientfh->fileno() . " CONN$self->{conn_count}\n" if $self->{debug};
+	    $self->dprint("ACCEPT FH" .  $clientfh->fileno() . " CONN$self->{conn_count}");
 
 	    $self->push_request_header($reqstate);
 	}
-- 
2.20.1

[pve-devel] [PATCH http-server v3 2/4] accept-phase: fix conn_count "leak"

[Stoiko Ivanov]

When handling new connections in 'accept_connections' the number of
active connections (conn_count) got increased before the callback, which
would eventually decrease it got registered in AnyEvent::Handle->new.

Any error/die before registering the callback would skip the
decrement, and leave the process in an endless loop upon exiting in
wait_end_loop.

This can happen e.g. when the call to getpeername fails, or if the
connection is denied by the ALLOW_FROM/DENY_FROM settings in
'/etc/default/pveproxy' (which is also a simple reproducer for that).

Additionally it can cause a denial of service, by attempting to
connect from a denied ip until the connection count exeeds the maximum
connections of all child-processes.

This patch addresses the issue by incrementing the connection count
before attempting to create the handle, and decrementing it again, if
handle creation fails.

A warning is logged if 'conn_count' turns negative when decrementing
during cleanup on error/eof. In case creating a new handle during
initial accept_connection fails, a warning is logged as well, but
'conn_count' is not decremented.

Reported via our community-forum:
https://forum.proxmox.com/threads/pveproxy-eats-available-ram.79617/

Co-Authored-by: Dominik Csapak <d.csapak@proxmox.com>
Signed-off-by: Stoiko Ivanov <s.ivanov@proxmox.com>
---
 PVE/APIServer/AnyEvent.pm | 20 +++++++++++++++++---
 1 file changed, 17 insertions(+), 3 deletions(-)

diff --git a/PVE/APIServer/AnyEvent.pm b/PVE/APIServer/AnyEvent.pm
index b8c28ce..be60f2e 100644
--- a/PVE/APIServer/AnyEvent.pm
+++ b/PVE/APIServer/AnyEvent.pm
@@ -157,6 +157,8 @@ sub client_do_disconnect {
 
     &$shutdown_hdl($hdl);
 
+    warn "connection count <= 0!\n" if $self->{conn_count} <= 0;
+
     $self->{conn_count}--;
 
     $self->dprint("CLOSE FH" .  $hdl->{fh}->fileno() . " CONN$self->{conn_count}");
@@ -1489,8 +1491,6 @@ sub accept {
 
     fh_nonblocking $clientfh, 1;
 
-    $self->{conn_count}++;
-
     return $clientfh;
 }
 
@@ -1564,6 +1564,7 @@ sub check_host_access {
 sub accept_connections {
     my ($self) = @_;
 
+    my $handle_creation;
     eval {
 
 	while (my $clientfh = $self->accept()) {
@@ -1571,7 +1572,7 @@ sub accept_connections {
 	    my $reqstate = { keep_alive => $self->{keep_alive} };
 
 	    # stop keep-alive when there are many open connections
-	    if ($self->{conn_count} >= $self->{max_conn_soft_limit}) {
+	    if ($self->{conn_count} + 1 >= $self->{max_conn_soft_limit}) {
 		$reqstate->{keep_alive} = 0;
 	    }
 
@@ -1587,6 +1588,11 @@ sub accept_connections {
 		next;
 	    }
 
+	    # Increment conn_count before creating new handle, since creation
+	    # triggers callbacks, which can potentialy decrement (e.g.
+	    # on_error) conn_count before AnyEvent::Handle->new() returns.
+	    $handle_creation = 1;
+	    $self->{conn_count}++;
 	    $reqstate->{hdl} = AnyEvent::Handle->new(
 		fh => $clientfh,
 		rbuf_max => 64*1024,
@@ -1609,6 +1615,7 @@ sub accept_connections {
 		    if (my $err = $@) { syslog('err', "$err"); }
 		},
 		($self->{tls_ctx} ? (tls => "accept", tls_ctx => $self->{tls_ctx}) : ()));
+	    $handle_creation = 0;
 
 	    $self->dprint("ACCEPT FH" .  $clientfh->fileno() . " CONN$self->{conn_count}");
 
@@ -1618,6 +1625,13 @@ sub accept_connections {
 
     if (my $err = $@) {
 	syslog('err', $err);
+	if ($handle_creation) {
+	    if ($self->{conn_count} <= 0) {
+		warn "connection count <= 0 not decrementing!\n";
+	    } else {
+		$self->{conn_count}--;
+	    }
+	}
 	$self->{end_loop} = 1;
     }
 
-- 
2.20.1

[pve-devel] [PATCH http-server v3 3/4] accept-phase: shutdown socket on early error

[Stoiko Ivanov]

if an error happens before AnyEvent::Handle registers the cleanup
callback, we should shutdown/close the socket, when handling it.

Using close, instead of shutdown($sock, SHUT_WR) here, since we are in
an error-state, and would not read from the socket anyways.
(Additionally close sends just on packet (RST,ACK), vs shutdown
(FIN,ACK+RST,ACK) in its use here).

Co-Authored-by: Dominik Csapak <d.csapak@proxmox.com>
Signed-off-by: Stoiko Ivanov <s.ivanov@proxmox.com>
---
 PVE/APIServer/AnyEvent.pm | 14 ++++++++++++--
 1 file changed, 12 insertions(+), 2 deletions(-)

diff --git a/PVE/APIServer/AnyEvent.pm b/PVE/APIServer/AnyEvent.pm
index be60f2e..d3b48b7 100644
--- a/PVE/APIServer/AnyEvent.pm
+++ b/PVE/APIServer/AnyEvent.pm
@@ -1532,6 +1532,11 @@ sub check_host_access {
 
     my $cip = Net::IP->new($clientip);
 
+    if (!$cip) {
+	$self->dprint("client IP not parsable: $@");
+	return 0;
+    }
+
     my $match_allow = 0;
     my $match_deny = 0;
 
@@ -1564,10 +1569,10 @@ sub check_host_access {
 sub accept_connections {
     my ($self) = @_;
 
-    my $handle_creation;
+    my ($clientfh, $handle_creation);
     eval {
 
-	while (my $clientfh = $self->accept()) {
+	while ($clientfh = $self->accept()) {
 
 	    my $reqstate = { keep_alive => $self->{keep_alive} };
 
@@ -1579,12 +1584,16 @@ sub accept_connections {
 	    if (my $sin = getpeername($clientfh)) {
 		my ($pfamily, $pport, $phost) = PVE::Tools::unpack_sockaddr_in46($sin);
 		($reqstate->{peer_port}, $reqstate->{peer_host}) = ($pport,  Socket::inet_ntop($pfamily, $phost));
+	    } else {
+		close($clientfh);
+		next;
 	    }
 
 	    if (!$self->{trusted_env} && !$self->check_host_access($reqstate->{peer_host})) {
 		$self->dprint("ABORT request from $reqstate->{peer_host} - access denied");
 		$reqstate->{log}->{code} = 403;
 		$self->log_request($reqstate);
+		close($clientfh);
 		next;
 	    }
 
@@ -1625,6 +1634,7 @@ sub accept_connections {
 
     if (my $err = $@) {
 	syslog('err', $err);
+	close($clientfh);
 	if ($handle_creation) {
 	    if ($self->{conn_count} <= 0) {
 		warn "connection count <= 0 not decrementing!\n";
-- 
2.20.1

[pve-devel] [PATCH http-server v3 4/4] add debug log for problems during accept

[Stoiko Ivanov]

Signed-off-by: Stoiko Ivanov <s.ivanov@proxmox.com>
---
 PVE/APIServer/AnyEvent.pm | 4 ++++
 1 file changed, 4 insertions(+)

diff --git a/PVE/APIServer/AnyEvent.pm b/PVE/APIServer/AnyEvent.pm
index d3b48b7..8a1af54 100644
--- a/PVE/APIServer/AnyEvent.pm
+++ b/PVE/APIServer/AnyEvent.pm
@@ -1544,6 +1544,7 @@ sub check_host_access {
 	foreach my $t (@{$self->{allow_from}}) {
 	    if ($t->overlaps($cip)) {
 		$match_allow = 1;
+		$self->dprint("client IP allowed: ". $t->prefix());
 		last;
 	    }
 	}
@@ -1552,6 +1553,7 @@ sub check_host_access {
     if ($self->{deny_from}) {
 	foreach my $t (@{$self->{deny_from}}) {
 	    if ($t->overlaps($cip)) {
+		$self->dprint("client IP denied: ". $t->prefix());
 		$match_deny = 1;
 		last;
 	    }
@@ -1585,6 +1587,7 @@ sub accept_connections {
 		my ($pfamily, $pport, $phost) = PVE::Tools::unpack_sockaddr_in46($sin);
 		($reqstate->{peer_port}, $reqstate->{peer_host}) = ($pport,  Socket::inet_ntop($pfamily, $phost));
 	    } else {
+		$self->dprint("getpeername failed: $!");
 		close($clientfh);
 		next;
 	    }
@@ -1634,6 +1637,7 @@ sub accept_connections {
 
     if (my $err = $@) {
 	syslog('err', $err);
+	$self->dprint("connection accept error: $err");
 	close($clientfh);
 	if ($handle_creation) {
 	    if ($self->{conn_count} <= 0) {
-- 
2.20.1

[pve-devel] applied-series: [PATCH http-server v3 0/4] improve error handling in accept_connections

[Thomas Lamprecht]

On 10.12.20 15:02, Stoiko Ivanov wrote:
> v2->v3:
> * incorporated Thomas patient and excellent feedback (Thanks!!):
> * replaced the two error-flags by a single handle_creation flag,  based
>   on the observation that the code after AnyEvent::Handle->new() does not die
>   (and that we'd probably still shutdown the socket if it did)
> * replaced the calls to shutdown($fh, SHUT_RD) with calls to close - in case
>   accept() fails, we don't want to sent anything + it sents one tcp-packet less
>   (only rst+ack, instead of fin+ack,rst+ack)
> * replaced syslog+dprint by a single warn (in our AnyEvent daemons that results
>   in the line being printed to STDERR+to syslog with level warning)
> * squashed 1/5 (introduce dprint sub) and 5/5 (use it)
> 
> tested on my workstation (the cleanup by having an deny-acl in
> /etc/default/pveproxy and connecting 1000 times with openssl s_client)
> 
> original cover-letter for v2:
> v1->v2:
> * increment of connection count now happens right before the AnyEvent::Handle
>   is created
> * the handle-creation is guarded by an error-flag, and if it fails the
>   connection count is decremented (bounded to 0) again
> * as suggested by Thomas - added a debug print sub which includes the
>   package name, linenumber and function name where the printing happens
> * refactored all active debug-prints to use it.
> 
> original cover-letter for v1:
> This patchset is the result of investigating a report in our community forum:
> https://forum.proxmox.com/threads/pveproxy-eats-available-ram.79617/
> 
> The first patch fixes an issue where pveproxy worker processes would never
> exit (and eat quite a bit of ram+cpu) when 'getpeername' returned an error.
> 
> The second seemed to me like a sensible further cleanup, and the third patch
> will hopefully provide the needed information when debugging such things in
> the future.
> 
> Huge thanks to Dominik, who analyzed this issue with me!
> 
> 
> Stoiko Ivanov (4):
>   add debug print helper
>   accept-phase: fix conn_count "leak"
>   accept-phase: shutdown socket on early error
>   add debug log for problems during accept
> 
>  PVE/APIServer/AnyEvent.pm | 68 ++++++++++++++++++++++++++++++---------
>  1 file changed, 53 insertions(+), 15 deletions(-)
> 



applied series, much thanks!