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.
This commit is contained in:
Stéphane Lesimple 2021-06-03 14:26:06 +00:00 committed by Stéphane Lesimple
parent 850c8cabd4
commit 2e9fe9288b
4 changed files with 80 additions and 46 deletions

View file

@ -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!";

View file

@ -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)) {

View file

@ -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
}

View file

@ -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;
}