[pve-devel] [PATCH http-server v2 0/5] improve error handling in accept_connections

[pve-devel] [PATCH http-server v2 0/5] improve error handling in accept_connections

[Stoiko Ivanov]

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 (5):
  add debug print helper
  accept-phase: fix conn_count "leak"
  accept-phase: shutdown socket on early error
  add debug log for problems during accept
  debug: uniformly use dprint

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

-- 
2.20.1

[pve-devel] [PATCH http-server v2 1/5] add debug print helper

[Stoiko Ivanov]

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

diff --git a/PVE/APIServer/AnyEvent.pm b/PVE/APIServer/AnyEvent.pm
index c55da7f..7916bdd 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/^.+::([^:]+)$/\1/;
+    print "worker[$$]: $pkg +$line: $sub: $message\n";
+}
+
 sub log_request {
     my ($self, $reqstate) = @_;
 
-- 
2.20.1

Re: [pve-devel] [PATCH http-server v2 1/5] add debug print helper

[Thomas Lamprecht]

On 04.12.20 18:56, Stoiko Ivanov wrote:
> Suggested-by: Thomas Lamprecht <t.lamprecht@proxmox.com>
> Signed-off-by: Stoiko Ivanov <s.ivanov@proxmox.com>
> ---
>  PVE/APIServer/AnyEvent.pm | 10 ++++++++++
>  1 file changed, 10 insertions(+)
> 
> diff --git a/PVE/APIServer/AnyEvent.pm b/PVE/APIServer/AnyEvent.pm
> index c55da7f..7916bdd 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/^.+::([^:]+)$/\1/;

Could be a bit simpler, avoiding capturing group and back reference:
    $sub =~ s/^(?:.+::)+//;

(note did not actually test it)

> +    print "worker[$$]: $pkg +$line: $sub: $message\n";
> +}
> +
>  sub log_request {
>      my ($self, $reqstate) = @_;
>  
> 

please merge 5/5 into this one, makes no sense to have that split and the
use part ordered last.

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

[Stoiko Ivanov]

When handling new connections in 'accept_connections' the number of
active connections got increased before the AnyEvent::Handle
registered the callback which would decrement it on error/eof.

Any error/die beforehand 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.

Should the connection count become negative a warning is logged in both
places where we decrement it, in case of a failed AnyEvent::Handle->new(),
the count is not decremented if this would happen.

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 | 22 +++++++++++++++++++---
 1 file changed, 19 insertions(+), 3 deletions(-)

diff --git a/PVE/APIServer/AnyEvent.pm b/PVE/APIServer/AnyEvent.pm
index 7916bdd..af2fde8 100644
--- a/PVE/APIServer/AnyEvent.pm
+++ b/PVE/APIServer/AnyEvent.pm
@@ -157,6 +157,11 @@ sub client_do_disconnect {
 
     &$shutdown_hdl($hdl);
 
+    if ($self->{conn_count} <= 0) {
+	my $msg = "connection count <= 0!\n";
+	syslog('warn', $msg);
+	$self->dprint("warn: $msg");
+    }
     $self->{conn_count}--;
 
     print "$$: CLOSE FH" .  $hdl->{fh}->fileno() . " CONN$self->{conn_count}\n" if $self->{debug};
@@ -1489,8 +1494,6 @@ sub accept {
 
     fh_nonblocking $clientfh, 1;
 
-    $self->{conn_count}++;
-
     return $clientfh;
 }
 
@@ -1564,6 +1567,7 @@ sub check_host_access {
 sub accept_connections {
     my ($self) = @_;
 
+    my $hdl_err;
     eval {
 
 	while (my $clientfh = $self->accept()) {
@@ -1571,7 +1575,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 +1591,8 @@ sub accept_connections {
 		next;
 	    }
 
+	    $hdl_err = 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}) : ()));
+	    $hdl_err = 0;
 
 	    print "$$: ACCEPT FH" .  $clientfh->fileno() . " CONN$self->{conn_count}\n" if $self->{debug};
 
@@ -1618,6 +1625,15 @@ sub accept_connections {
 
     if (my $err = $@) {
 	syslog('err', $err);
+	if ($hdl_err) {
+	    if ($self->{conn_count} <= 0) {
+		my $msg = "connection count <= 0 not decrementing!\n";
+		syslog('warn', $msg);
+		$self->dprint("warn: $msg");
+	    } else {
+		$self->{conn_count}--;
+	    }
+	}
 	$self->{end_loop} = 1;
     }
 
-- 
2.20.1

Re: [pve-devel] [PATCH http-server v2 2/5] accept-phase: fix conn_count "leak"

[Thomas Lamprecht]

On 04.12.20 18:56, Stoiko Ivanov wrote:
> When handling new connections in 'accept_connections' the number of
> active connections got increased before the AnyEvent::Handle
> registered the callback which would decrement it on error/eof.
> 
> Any error/die beforehand 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.
> 
> Should the connection count become negative a warning is logged in both
> places where we decrement it, in case of a failed AnyEvent::Handle->new(),
> the count is not decremented if this would happen.
> 
> 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 | 22 +++++++++++++++++++---
>  1 file changed, 19 insertions(+), 3 deletions(-)
> 
> diff --git a/PVE/APIServer/AnyEvent.pm b/PVE/APIServer/AnyEvent.pm
> index 7916bdd..af2fde8 100644
> --- a/PVE/APIServer/AnyEvent.pm
> +++ b/PVE/APIServer/AnyEvent.pm
> @@ -157,6 +157,11 @@ sub client_do_disconnect {
>  
>      &$shutdown_hdl($hdl);
>  
> +    if ($self->{conn_count} <= 0) {
> +	my $msg = "connection count <= 0!\n";
> +	syslog('warn', $msg);
> +	$self->dprint("warn: $msg");

see below, at the end, for a comment about doing both, debug print and syslog.

> +    }
>      $self->{conn_count}--;
>  
>      print "$$: CLOSE FH" .  $hdl->{fh}->fileno() . " CONN$self->{conn_count}\n" if $self->{debug};
> @@ -1489,8 +1494,6 @@ sub accept {
>  
>      fh_nonblocking $clientfh, 1;
>  
> -    $self->{conn_count}++;
> -
>      return $clientfh;
>  }
>  
> @@ -1564,6 +1567,7 @@ sub check_host_access {
>  sub accept_connections {
>      my ($self) = @_;
>  
> +    my $hdl_err;

can we please avoid adding to that mess of arbitrary shortened variable names, at
least for new ones?

Also, this suggest a bit like it would denote if there's an handle error, but what
it actually tells is, if handle creation point got reached - naming should not be bound
to much to one use case.

Maybe:
my $handle_creation = 0;

or rather, just reuse $early_err (which has similar naming issues, but is pre-existing),
the $self->push_request_header is doing everything in a eval + warn only scope anyway.

>      eval {
>  
>  	while (my $clientfh = $self->accept()) {
> @@ -1571,7 +1575,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 +1591,8 @@ sub accept_connections {
>  		next;
>  	    }
>  
> +	    $hdl_err = 1;
> +	    $self->{conn_count}++;

still no comment whatsoever, that is unacceptable to me for such subtle thing, especially
paired with the commit message, which still mentions that increasing the count before
registering the callback handle (which we still do, for good reasons), makes it
confusing.

Please note that we explicitly increment here, not after calling ->new, because creating the
handle below starts off reading from the fh immediately and can trigger at least an on_error
(and possible other) callback.

>  	    $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}) : ()));
> +	    $hdl_err = 0;
>  
>  	    print "$$: ACCEPT FH" .  $clientfh->fileno() . " CONN$self->{conn_count}\n" if $self->{debug};
>  
> @@ -1618,6 +1625,15 @@ sub accept_connections {
>  
>      if (my $err = $@) {
>  	syslog('err', $err);
> +	if ($hdl_err) {
> +	    if ($self->{conn_count} <= 0) {
> +		my $msg = "connection count <= 0 not decrementing!\n";
> +		syslog('warn', $msg);
> +		$self->dprint("warn: $msg");

If we already log to syslog, isn't that enough to have it visible?

Or could a single `warn` call do the "correct thing", i.e., stderr so to
syslog if running as systemd service and to console if running in foreground?

Not too hard feelings here though.

> +	    } else {
> +		$self->{conn_count}--;
> +	    }
> +	}
>  	$self->{end_loop} = 1;
>      }
>  
> 

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

[Stoiko Ivanov]

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

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

diff --git a/PVE/APIServer/AnyEvent.pm b/PVE/APIServer/AnyEvent.pm
index af2fde8..a679006 100644
--- a/PVE/APIServer/AnyEvent.pm
+++ b/PVE/APIServer/AnyEvent.pm
@@ -1535,6 +1535,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;
 
@@ -1567,10 +1572,13 @@ sub check_host_access {
 sub accept_connections {
     my ($self) = @_;
 
-    my $hdl_err;
+    my ($clientfh, $early_err, $hdl_err);
     eval {
 
-	while (my $clientfh = $self->accept()) {
+	while (1) {
+	    $early_err = 1;
+	    $clientfh = $self->accept();
+	    last if !$clientfh;
 
 	    my $reqstate = { keep_alive => $self->{keep_alive} };
 
@@ -1582,14 +1590,19 @@ 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 {
+		shutdown($clientfh, 1);
+		next;
 	    }
 
 	    if (!$self->{trusted_env} && !$self->check_host_access($reqstate->{peer_host})) {
 		print "$$: ABORT request from $reqstate->{peer_host} - access denied\n" if $self->{debug};
 		$reqstate->{log}->{code} = 403;
 		$self->log_request($reqstate);
+		shutdown($clientfh, 1);
 		next;
 	    }
+	    $early_err = 0;
 
 	    $hdl_err = 1;
 	    $self->{conn_count}++;
@@ -1625,6 +1638,7 @@ sub accept_connections {
 
     if (my $err = $@) {
 	syslog('err', $err);
+	shutdown($clientfh, 1) if $early_err || $hdl_err;
 	if ($hdl_err) {
 	    if ($self->{conn_count} <= 0) {
 		my $msg = "connection count <= 0 not decrementing!\n";
-- 
2.20.1

Re: [pve-devel] [PATCH http-server v2 3/5] accept-phase: shutdown socket on early error

[Thomas Lamprecht]

On 04.12.20 18:56, Stoiko Ivanov wrote:
> if an error happens before AnyEvent::Handle registers the cleanup
> callback, we should shutdown the socket, when handling it.
> 
> Co-Authored-by: Dominik Csapak <d.csapak@proxmox.com>
> Signed-off-by: Stoiko Ivanov <s.ivanov@proxmox.com>
> ---
>  PVE/APIServer/AnyEvent.pm | 18 ++++++++++++++++--
>  1 file changed, 16 insertions(+), 2 deletions(-)
> 
> diff --git a/PVE/APIServer/AnyEvent.pm b/PVE/APIServer/AnyEvent.pm
> index af2fde8..a679006 100644
> --- a/PVE/APIServer/AnyEvent.pm
> +++ b/PVE/APIServer/AnyEvent.pm
> @@ -1535,6 +1535,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;
>  
> @@ -1567,10 +1572,13 @@ sub check_host_access {
>  sub accept_connections {
>      my ($self) = @_;
>  
> -    my $hdl_err;
> +    my ($clientfh, $early_err, $hdl_err);

ah OK, ignore my regards to "$early_err" in the previous comment, I thought it was pre-exsiting...

>      eval {
>  
> -	while (my $clientfh = $self->accept()) {
> +	while (1) {
> +	    $early_err = 1;
> +	    $clientfh = $self->accept();
> +	    last if !$clientfh;

what use has above change? Why not keeping it as is, you can still declare $clientfh
earlier to extend it's scope:

> +	while ($clientfh = $self->accept()) {


>  
>  	    my $reqstate = { keep_alive => $self->{keep_alive} };
>  
> @@ -1582,14 +1590,19 @@ 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 {
> +		shutdown($clientfh, 1);

Do we still plan to send anything? I.e., was `1` (SHUT_RD) used because of caution or
are there more explicit reasons for not using `2` (SHUT_RDWR)? Can be fine, but would
be good to know.

> +		next;
>  	    }
>  
>  	    if (!$self->{trusted_env} && !$self->check_host_access($reqstate->{peer_host})) {
>  		print "$$: ABORT request from $reqstate->{peer_host} - access denied\n" if $self->{debug};
>  		$reqstate->{log}->{code} = 403;
>  		$self->log_request($reqstate);
> +		shutdown($clientfh, 1);

same as above

>  		next;
>  	    }
> +	    $early_err = 0;
>  
>  	    $hdl_err = 1;
>  	    $self->{conn_count}++;
> @@ -1625,6 +1638,7 @@ sub accept_connections {
>  
>      if (my $err = $@) {
>  	syslog('err', $err);
> +	shutdown($clientfh, 1) if $early_err || $hdl_err;

same as above, and maybe we could do with just one such flag variables, reducing the combination
matrix a bit.

>  	if ($hdl_err) {
>  	    if ($self->{conn_count} <= 0) {
>  		my $msg = "connection count <= 0 not decrementing!\n";
> 

[pve-devel] [PATCH http-server v2 4/5] 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 a679006..0165264 100644
--- a/PVE/APIServer/AnyEvent.pm
+++ b/PVE/APIServer/AnyEvent.pm
@@ -1547,6 +1547,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;
 	    }
 	}
@@ -1555,6 +1556,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;
 	    }
@@ -1591,6 +1593,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: $!");
 		shutdown($clientfh, 1);
 		next;
 	    }
@@ -1638,6 +1641,7 @@ sub accept_connections {
 
     if (my $err = $@) {
 	syslog('err', $err);
+	self->dprint("connection accept error: $err");
 	shutdown($clientfh, 1) if $early_err || $hdl_err;
 	if ($hdl_err) {
 	    if ($self->{conn_count} <= 0) {
-- 
2.20.1

Re: [pve-devel] [PATCH http-server v2 4/5] add debug log for problems during accept

[Thomas Lamprecht]

On 04.12.20 18:56, Stoiko Ivanov wrote:
> 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 a679006..0165264 100644
> --- a/PVE/APIServer/AnyEvent.pm
> +++ b/PVE/APIServer/AnyEvent.pm
> @@ -1547,6 +1547,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;
>  	    }
>  	}
> @@ -1555,6 +1556,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;
>  	    }
> @@ -1591,6 +1593,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: $!");
>  		shutdown($clientfh, 1);
>  		next;
>  	    }
> @@ -1638,6 +1641,7 @@ sub accept_connections {
>  
>      if (my $err = $@) {
>  	syslog('err', $err);
> +	self->dprint("connection accept error: $err");

this cannot work, missing the dollar signe: `self` vs. `$self`

>  	shutdown($clientfh, 1) if $early_err || $hdl_err;
>  	if ($hdl_err) {
>  	    if ($self->{conn_count} <= 0) {
> 

[pve-devel] [PATCH http-server v2 5/5] debug: uniformly use dprint

[Stoiko Ivanov]

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

diff --git a/PVE/APIServer/AnyEvent.pm b/PVE/APIServer/AnyEvent.pm
index 0165264..9a4b7e7 100644
--- a/PVE/APIServer/AnyEvent.pm
+++ b/PVE/APIServer/AnyEvent.pm
@@ -153,7 +153,7 @@ sub client_do_disconnect {
 	return;
     }
 
-    print "close connection $hdl\n" if $self->{debug};
+    $self->dprint("close connection $hdl");
 
     &$shutdown_hdl($hdl);
 
@@ -164,7 +164,7 @@ sub client_do_disconnect {
     }
     $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 {
@@ -427,7 +427,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,
@@ -522,7 +522,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();
 			}
@@ -553,7 +553,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);
 
@@ -855,9 +855,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')) {
@@ -875,7 +875,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,
@@ -1348,7 +1348,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) ||
@@ -1599,7 +1599,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);
 		shutdown($clientfh, 1);
@@ -1633,7 +1633,7 @@ sub accept_connections {
 		($self->{tls_ctx} ? (tls => "accept", tls_ctx => $self->{tls_ctx}) : ()));
 	    $hdl_err = 0;
 
-	    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