From 2e9fe9288be25f6d81aacfb6e34281a96e2175ff Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?St=C3=A9phane=20Lesimple?= Date: Thu, 3 Jun 2021 14:26:06 +0000 Subject: [PATCH] enh: httpproxy: add options to fine-tune logging Added the `log_request_response` and `log_request_response_max_size` options to osh-http-proxy.conf. By default, requests are logged, including their body, up to a size of 64K per request response. Before, there was no size limit to the logged body response. --- bin/proxy/osh-http-proxy-daemon | 20 +++++---- bin/proxy/osh-http-proxy-worker | 61 +++++++++++++++++----------- etc/bastion/osh-http-proxy.conf.dist | 14 ++++++- lib/perl/OVH/Bastion/ProxyHTTP.pm | 31 +++++++------- 4 files changed, 80 insertions(+), 46 deletions(-) diff --git a/bin/proxy/osh-http-proxy-daemon b/bin/proxy/osh-http-proxy-daemon index cbaf986..4c5b991 100755 --- a/bin/proxy/osh-http-proxy-daemon +++ b/bin/proxy/osh-http-proxy-daemon @@ -47,11 +47,12 @@ my $_normalize_config_integer = sub { $config->{$param} = $default; } }; -$_normalize_config_integer->('timeout', 1, 3600, 120); -$_normalize_config_integer->('min_servers', 1, 512, 8); -$_normalize_config_integer->('max_servers', 1, 512, 32); -$_normalize_config_integer->('min_spare_servers', 1, 512, 8); -$_normalize_config_integer->('max_spare_servers', 1, 512, 16); +$_normalize_config_integer->('timeout', 1, 3600, 120); +$_normalize_config_integer->('min_servers', 1, 512, 8); +$_normalize_config_integer->('max_servers', 1, 512, 32); +$_normalize_config_integer->('min_spare_servers', 1, 512, 8); +$_normalize_config_integer->('max_spare_servers', 1, 512, 16); +$_normalize_config_integer->('log_request_response_max_size', 0, 1024 * 1024 * 1024, 65536); foreach my $file ($config->{'ssl_key'}, $config->{'ssl_certificate'}) { if (!(-r -f $file)) { @@ -60,6 +61,9 @@ foreach my $file ($config->{'ssl_key'}, $config->{'ssl_certificate'}) { } } +# this option is enabled by default if omitted +$config->{'log_request_response'} //= 1; + OVH::Bastion::ProxyHTTP->new()->run( %options, port => $config->{'port'} . '/ssl', @@ -81,8 +85,10 @@ OVH::Bastion::ProxyHTTP->new()->run( # which is also the max allowed value of the 'timeout' config param (see above). timeout_idle => 3600, proxy_config => { - insecure => $config->{'insecure'} ? 1 : 0, - timeout => $config->{'timeout'}, # our worker will wait for up to this amount of time for the egress connection to complete + insecure => $config->{'insecure'} ? 1 : 0, + timeout => $config->{'timeout'}, # our worker will wait for up to this amount of time for the egress connection to complete + log_request_response => $config->{'log_request_response'} ? 1 : 0, + log_request_response_max_size => $config->{'log_request_response_max_size'}, }, ) or die "Proxy launch failed!"; diff --git a/bin/proxy/osh-http-proxy-worker b/bin/proxy/osh-http-proxy-worker index d662eed..59fc692 100755 --- a/bin/proxy/osh-http-proxy-worker +++ b/bin/proxy/osh-http-proxy-worker @@ -64,21 +64,23 @@ my $pass = delete $ENV{'PROXY_ACCOUNT_PASSWORD'}; my $content; GetOptions( - "account=s" => \my $account, - "user=s" => \my $user, - "group=s" => \my $group, - "context=s" => \my $context, - "host=s" => \my $remotemachine, - "port=i" => \my $remoteport, - "method=s" => \my $method, - "path=s" => \my $path, - "header=s" => \my @client_headers, - "timeout=i" => \my $timeout, - "insecure" => \my $insecure, - "uniqid=s" => \$uniqid, - "post-data-stdin" => \my $postDataStdin, - "allow-downgrade" => \my $allow_downgrade, - "monitoring" => \my $monitoring, + "account=s" => \my $account, + "user=s" => \my $user, + "group=s" => \my $group, + "context=s" => \my $context, + "host=s" => \my $remotemachine, + "port=i" => \my $remoteport, + "method=s" => \my $method, + "path=s" => \my $path, + "header=s" => \my @client_headers, + "timeout=i" => \my $timeout, + "insecure" => \my $insecure, + "uniqid=s" => \$uniqid, + "post-data-stdin" => \my $postDataStdin, + "allow-downgrade" => \my $allow_downgrade, + "monitoring" => \my $monitoring, + "log-request-response" => \my $log_request_response, + "log-request-response-max-size=i" => \my $log_request_response_max_size, ); push @headers, ["X-Bastion-Remote-IP" => $remotemachine]; @@ -394,20 +396,31 @@ my $basedir = "/home/$account/ttyrec"; my $finaldir = "$basedir/$remotemachine"; -d $finaldir || mkdir $finaldir; -my @now = Time::HiRes::gettimeofday(); -my @t = localtime($now[0]); +# depending on whether we must log the body or not, and whether there is a max size specified, +# prepare the log line about the body +my $body_to_log = "(BODY OMITTED)"; +if ($res && $log_request_response) { + $log_request_response_max_size //= 65536; + if ($log_request_response_max_size && length($res->decoded_content) > $log_request_response_max_size) { + $body_to_log = substr($res->decoded_content, 0, $log_request_response_max_size / 2) . '[...snip...]' . substr($res->decoded_content, -$log_request_response_max_size / 2); + } + else { + $body_to_log = $res->decoded_content; + } +} +my @now = Time::HiRes::gettimeofday(); +my @t = localtime($now[0]); +my @headerlog = ($uniqid, $now[0], $now[1], POSIX::strftime("%Y/%m/%d.%H:%M:%S", @t)); my $headers_as_string = $res ? join("", $res->{'_headers'}->as_string("\n")) : ''; my $logfile = sprintf("%s/%s.txt", $finaldir, POSIX::strftime("%F", @t)); -my $logline = sprintf( - "--- BASTION_REQUEST UNIQID=%s TIMESTAMP=%d.%06d DATE=%s ---\n%s\n" +my $logline = + sprintf("" + . "--- BASTION_REQUEST UNIQID=%s TIMESTAMP=%d.%06d DATE=%s ---\n%s\n" . "--- DEVICE_ANSWER UNIQID=%s TIMESTAMP=%d.%06d DATE=%s ---\n%s\n" . "--- END UNIQID=%s TIMESTAMP=%d.%06d DATE=%s ---\n\n", - $uniqid, $now[0], $now[1], POSIX::strftime("%Y/%m/%d.%H:%M:%S", @t), $req->as_string(), - $uniqid, $now[0], $now[1], POSIX::strftime("%Y/%m/%d.%H:%M:%S", @t), - ($res ? sprintf("%s %s\n%s\n%s", $res->protocol, $res->status_line, $headers_as_string, $res->decoded_content) : '(DEVICE TIMEOUT)'), - $uniqid, $now[0], $now[1], POSIX::strftime("%Y/%m/%d.%H:%M:%S", @t), -); + @headerlog, $req->as_string(), @headerlog, $res ? sprintf("%s %s\n%s\n%s", $res->protocol, $res->status_line, $headers_as_string, $body_to_log) : '(DEVICE TIMEOUT)', + @headerlog,); $logline =~ s/^(Authorization:).+/$1 (removed)/mgi; if (open(my $log, '>>', $logfile)) { diff --git a/etc/bastion/osh-http-proxy.conf.dist b/etc/bastion/osh-http-proxy.conf.dist index a6dc1ee..2729ced 100644 --- a/etc/bastion/osh-http-proxy.conf.dist +++ b/etc/bastion/osh-http-proxy.conf.dist @@ -74,5 +74,17 @@ # VALUE: 1 to 3600 # DESC: timeout delay (in seconds) for the connection between the bastion and the devices # DEFAULT: 120 -"timeout": 120 +"timeout": 120, +# +# log_request_response (bool) +# VALUE: true or false +# DESC: when enabled, the complete response of the device to the request we forwarded will be logged, otherwise we'll only log the response headers +# DEFAULT: true +"log_request_response": true, +# +# log_request_response_max_size (int) +# VALUE: 0 to 2^30 (1 GiB) +# DESC: this option only applies when `log_request_response` is true (see above). When set to zero, the complete response will be logged in the account's home log directory, including the body, regardless of its size. If set to a positive integer, the query response will only be partially logged, with full status and headers but the body only up to the specified size. This is a way to avoid turning off request response logging completely on very busy bastions, by ensuring logs growth don't get out of hand, as some responses to queries can take megabytes, with possibly limited added value to traceability. +# DEFAULT: 65536 +"log_request_response_max_size": 65536 } diff --git a/lib/perl/OVH/Bastion/ProxyHTTP.pm b/lib/perl/OVH/Bastion/ProxyHTTP.pm index f8455e8..f59b14d 100644 --- a/lib/perl/OVH/Bastion/ProxyHTTP.pm +++ b/lib/perl/OVH/Bastion/ProxyHTTP.pm @@ -134,18 +134,20 @@ sub log_and_exit { push @request_lines, delete $self->{'_log'}{'post_content'}; } - my $logfile = sprintf("%s/%s.txt", $finaldir, POSIX::strftime("%F", @t)); - my $logline = sprintf( - "--- CLIENT_REQUEST UNIQID=%s TIMESTAMP=%d.%06d DATE=%s ---\n%s\n" + my $bastion_answer_log = "HTTP/1.0 $code $msg\n"; + foreach my $row (@{$self->http_base_headers()}) { + $bastion_answer_log .= $row->[0] . ": " . $row->[1] . "\n"; + } + $bastion_answer_log .= "\n(BODY OMITTED, " . length($body) . " bytes)\n"; + my @headerlog = ($ENV{'UNIQID'}, $now[0], $now[1], POSIX::strftime("%Y/%m/%d.%H:%M:%S", @t)); + my $logfile = sprintf("%s/%s.txt", $finaldir, POSIX::strftime("%F", @t)); + my $logline = sprintf( + "" + . "--- CLIENT_REQUEST UNIQID=%s TIMESTAMP=%d.%06d DATE=%s ---\n%s\n" . "--- BASTION_ANSWER UNIQID=%s TIMESTAMP=%d.%06d DATE=%s ---\n%s\n" . "--- END UNIQID=%s TIMESTAMP=%d.%06d DATE=%s ---\n\n", - $ENV{'UNIQID'}, $now[0], $now[1], - POSIX::strftime("%Y/%m/%d.%H:%M:%S", @t), - join("\n", @request_lines), - $ENV{'UNIQID'}, $now[0], $now[1], - POSIX::strftime("%Y/%m/%d.%H:%M:%S", @t), - "HTTP/1.0 $code $msg\n\n$body", - $ENV{'UNIQID'}, $now[0], $now[1], POSIX::strftime("%Y/%m/%d.%H:%M:%S", @t), + @headerlog, join("\n", @request_lines), + @headerlog, $bastion_answer_log, @headerlog, ); $logline =~ s/^(Authorization:).+/$1 (removed)/mgi; @@ -164,7 +166,7 @@ sub log_and_exit { push @{$self->{'_supplementary_headers'}}, ['WWW-Authenticate', 'Basic realm="bastion"']; } - # and send status (will also fills access_log) + # and send status (will also fill access_log) return $self->send_status($code, $msg, $body . "\n"); } @@ -433,8 +435,10 @@ sub process_http_request { push @cmd, "--port", $remoteport; push @cmd, "--group", $group if $group; push @cmd, "--timeout", $timeout if $timeout; - push @cmd, "--allow-downgrade" if $allow_downgrade; - push @cmd, "--insecure" if ($self->{'proxy_config'}{'insecure'} && !$enforce_secure); + push @cmd, "--allow-downgrade" if $allow_downgrade; + push @cmd, "--insecure" if ($self->{'proxy_config'}{'insecure'} && !$enforce_secure); + push @cmd, "--log-request-response" if ($self->{'proxy_config'}{'log_request_response'}); + push @cmd, "--log-request-response-max-size", $self->{'proxy_config'}{'log_request_response_max_size'} if ($self->{'proxy_config'}{'log_request_response'}); # X-Test-* is only used for functional tests, and has to be passed to the remote foreach my $pattern (qw{ accept content-type content-length content-encoding x-test-[a-z-]+ }) { @@ -499,7 +503,6 @@ sub http_base_headers { $keyname = 'X-Bastion-Remote-' . $keyname if ($keyname =~ /^(client-ssl-)/i); push @headers, [$keyname, $keyval->[1]]; } - delete $self->{'_supplementary_headers'}; return \@headers; }