From 52e0246b32f1bbda05d2af86f7c170129f685e63 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Rapha=C3=ABl=20Bournhonesque?= Date: Thu, 23 May 2024 11:23:16 +0200 Subject: [PATCH] feat: improve rate-limiter (#10338) --- .env | 1 + .github/workflows/container-deploy.yml | 1 + conf/apache-2.4/modperl.conf | 1 + conf/log.conf | 6 +++++ conf/off-log.conf | 7 +++++ docker-compose.yml | 1 + lib/ProductOpener/Config_off.pm | 5 ++++ lib/ProductOpener/Display.pm | 2 +- lib/ProductOpener/Redis.pm | 37 +++++++++++++++----------- lib/ProductOpener/Routing.pm | 18 ++++++++++--- 10 files changed, 59 insertions(+), 20 deletions(-) diff --git a/.env b/.env index 9cfd50dbb5e5c..d89e284d37354 100644 --- a/.env +++ b/.env @@ -63,6 +63,7 @@ GEOLITE2_ACCOUNT_ID= ELASTICSEARCH_HOSTS= LOG_LEVEL_ROOT=TRACE LOG_LEVEL_MONGODB=TRACE +LOG_LEVEL_RATE_LIMITER=TRACE BUILD_CACHE_REPO=openfoodfacts/openfoodfacts-build-cache diff --git a/.github/workflows/container-deploy.yml b/.github/workflows/container-deploy.yml index 08a2e0abdb346..e472877e4babf 100644 --- a/.github/workflows/container-deploy.yml +++ b/.github/workflows/container-deploy.yml @@ -158,6 +158,7 @@ jobs: echo "INFLUXDB_HOST=${{ env.INFLUXDB_HOST }}" >> .env echo "LOG_LEVEL_ROOT=ERROR" >> .env echo "LOG_LEVEL_MONGODB=ERROR" >> .env + echo "LOG_LEVEL_RATE_LIMITER=INFO" >> .env echo "BUILD_CACHE_REPO=openfoodfacts/openfoodfacts-build-cache" >> .env # Override domain name in nginx.conf diff --git a/conf/apache-2.4/modperl.conf b/conf/apache-2.4/modperl.conf index db23eca0eed25..1be3b16c6c5cf 100644 --- a/conf/apache-2.4/modperl.conf +++ b/conf/apache-2.4/modperl.conf @@ -23,6 +23,7 @@ PerlPassEnv POSTGRES_USER PerlPassEnv POSTGRES_PASSWORD PerlPassEnv LOG_LEVEL_ROOT PerlPassEnv LOG_LEVEL_MONGODB +PerlPassEnv LOG_LEVEL_RATE_LIMITER PerlPassEnv OFF_LOG_EMAILS PerlPassEnv BUILD_CACHE_REPO PerlPassEnv RATE_LIMITER_BLOCKING_ENABLED diff --git a/conf/log.conf b/conf/log.conf index 299e3195acafc..e0a023e0a9447 100644 --- a/conf/log.conf +++ b/conf/log.conf @@ -1,5 +1,6 @@ log4perl.rootLogger= sub {return ($ENV{LOG_LEVEL_ROOT} // "ERROR") . ", LOGFILE";} log4perl.logger.mongodb= sub {return ($ENV{LOG_LEVEL_MONGODB} // "INFO") . ", MONGODB_LOGFILE";} +log4perl.logger.ratelimiter = sub {return ($ENV{LOG_LEVEL_RATE_LIMITER} // "INFO") . ", RATELIMITER_LOGFILE";} log4perl.PatternLayout.cspec.S = sub { my $context = Log::Log4perl::MDC->get_context; use Data::Dumper (); local $Data::Dumper::Indent = 0; local $Data::Dumper::Terse = 1; local $Data::Dumper::Sortkeys = 1; local $Data::Dumper::Quotekeys = 0; local $Data::Dumper::Deparse= 1; my $str = Data::Dumper::Dumper($context); $str =~ s/[\n\r]/ /g; return $str; } log4perl.appender.LOGFILE=Log::Log4perl::Appender::File log4perl.appender.LOGFILE.filename=/mnt/podata/logs/log4perl.log @@ -11,3 +12,8 @@ log4perl.appender.MONGODB_LOGFILE.filename=/mnt/podata/logs/mongodb_log4perl.log log4perl.appender.MONGODB_LOGFILE.mode=append log4perl.appender.MONGODB_LOGFILE.layout=PatternLayout log4perl.appender.MONGODB_LOGFILE.layout.ConversionPattern=[%d] [%r] %F %L %c %S %m{chomp}%n +log4perl.appender.RATELIMITER_LOGFILE=Log::Log4perl::Appender::File +log4perl.appender.RATELIMITER_LOGFILE.filename=/mnt/podata/logs/ratelimiter_log4perl.log +log4perl.appender.RATELIMITER_LOGFILE.mode=append +log4perl.appender.RATELIMITER_LOGFILE.layout=PatternLayout +log4perl.appender.RATELIMITER_LOGFILE.layout.ConversionPattern=[%d] [%r] %F %L %c %S %m{chomp}%n diff --git a/conf/off-log.conf b/conf/off-log.conf index 7557465cd638d..05d57e27bcb7d 100644 --- a/conf/off-log.conf +++ b/conf/off-log.conf @@ -1,5 +1,6 @@ log4perl.rootLogger=ERROR, LOGFILE log4perl.logger.mongodb=INFO, MONGODB_LOGFILE +log4perl.logger.ratelimiter=INFO, RATELIMITER_LOGFILE log4perl.PatternLayout.cspec.S = sub { my $context = Log::Log4perl::MDC->get_context; use Data::Dumper (); local $Data::Dumper::Indent = 0; local $Data::Dumper::Terse = 1; local $Data::Dumper::Sortkeys = 1; local $Data::Dumper::Quotekeys = 0; local $Data::Dumper::Deparse = 1; my $str = Data::Dumper::Dumper($context); $str =~ s/[\n\r]/ /g; return $str; } @@ -17,3 +18,9 @@ log4perl.appender.MONGODB_LOGFILE.mode=append log4perl.appender.MONGODB_LOGFILE.layout=PatternLayout log4perl.appender.MONGODB_LOGFILE.layout.ConversionPattern=[%r] %F %L %c %S %m{chomp}%n +log4perl.appender.RATELIMITER_LOGFILE=Log::Log4perl::Appender::File +log4perl.appender.RATELIMITER_LOGFILE.filename=/srv/off/logs/ratelimiter_log4perl.log +log4perl.appender.RATELIMITER_LOGFILE.mode=append + +log4perl.appender.RATELIMITER_LOGFILE.layout=PatternLayout +log4perl.appender.RATELIMITER_LOGFILE.layout.ConversionPattern=[%r] %F %L %c %S %m{chomp}%n \ No newline at end of file diff --git a/docker-compose.yml b/docker-compose.yml index ab67c6322c31d..290e556cd8c70 100644 --- a/docker-compose.yml +++ b/docker-compose.yml @@ -27,6 +27,7 @@ x-backend-conf: &backend-conf - GEOLITE2_PATH - LOG_LEVEL_ROOT - LOG_LEVEL_MONGODB + - LOG_LEVEL_RATE_LIMITER - INFLUXDB_HOST - BUILD_CACHE_REPO - RATE_LIMITER_BLOCKING_ENABLED diff --git a/lib/ProductOpener/Config_off.pm b/lib/ProductOpener/Config_off.pm index 966362e4e1b19..d820b3cff8ef9 100644 --- a/lib/ProductOpener/Config_off.pm +++ b/lib/ProductOpener/Config_off.pm @@ -1624,4 +1624,9 @@ $options{rate_limit_search} = 10; # Number of requests per minutes for the product API $options{rate_limit_product} = 100; +# Rate limit allow list +$options{rate_limit_allow_list} = { + '51.210.154.203' => 1, # OVH2 +}; + 1; diff --git a/lib/ProductOpener/Display.pm b/lib/ProductOpener/Display.pm index 396ee8f3f5d13..e28344e75eee4 100644 --- a/lib/ProductOpener/Display.pm +++ b/lib/ProductOpener/Display.pm @@ -206,7 +206,7 @@ use Tie::IxHash; use Log::Any '$log', default_adapter => 'Stderr'; # special logger to make it easy to measure memcached hit and miss rates -our $mongodb_log = Log::Log4perl->get_logger('mongodb'); +our $mongodb_log = Log::Any->get_logger(category => 'mongodb'); $mongodb_log->info("start") if $mongodb_log->is_info(); use Apache2::RequestUtil (); diff --git a/lib/ProductOpener/Redis.pm b/lib/ProductOpener/Redis.pm index 07b11d4fb3e3a..02bec36b090d8 100644 --- a/lib/ProductOpener/Redis.pm +++ b/lib/ProductOpener/Redis.pm @@ -43,7 +43,10 @@ The connection to redis my $redis_client; # tracking if we already displayed a warning -my $sent_warning_about_missing_redis_url = 0; +our $sent_warning_about_missing_redis_url = 0; + +# Specific logger to track rate-limiter operations +our $ratelimiter_log = Log::Any->get_logger(category => 'ratelimiter'); =head2 init_redis($is_reconnect=0) @@ -176,7 +179,7 @@ sub get_rate_limit_user_requests ($ip, $api_action) { if (!$redis_url) { # No Redis URL provided, we can't get the remaining number of requests if (!$sent_warning_about_missing_redis_url) { - $log->warn("Redis URL not provided, rate-limiting is disabled") if $log->is_warn(); + $ratelimiter_log->warn("Redis URL not provided, rate-limiting is disabled") if $ratelimiter_log->is_warn(); $sent_warning_about_missing_redis_url = 1; } return; @@ -185,13 +188,13 @@ sub get_rate_limit_user_requests ($ip, $api_action) { my $error = ""; if (!defined $redis_client) { # we were disconnected, try again - $log->info("Trying to reconnect to Redis"); + $ratelimiter_log->info("Trying to reconnect to Redis"); init_redis(); } my $resp; if (defined $redis_client) { - $log->debug("Getting rate-limit remaining requests", {ip => $ip, api_action => $api_action}) - if $log->is_debug(); + $ratelimiter_log->debug("Getting rate-limit remaining requests", {ip => $ip, api_action => $api_action}) + if $ratelimiter_log->is_debug(); my $current_minute = int(time() / 60); eval {$resp = $redis_client->get("po-rate-limit:$ip:$api_action:$current_minute");}; $error = $@; @@ -200,8 +203,8 @@ sub get_rate_limit_user_requests ($ip, $api_action) { $error = "Can't connect to Redis"; } if (!($error eq "")) { - $log->error("Failed to get remaining number of requests from Redis rate-limiter", {error => $error}) - if $log->is_warn(); + $ratelimiter_log->error("Failed to get remaining number of requests from Redis rate-limiter", {error => $error}) + if $ratelimiter_log->is_warn(); # ask for eventual reconnection for next call $redis_client = undef; } @@ -212,8 +215,8 @@ sub get_rate_limit_user_requests ($ip, $api_action) { else { $resp = 0; } - $log->debug("Remaining number of requests from Redis rate-limiter", {remaining_requests => $resp}) - if $log->is_debug(); + $ratelimiter_log->debug("Remaining number of requests from Redis rate-limiter", {remaining_requests => $resp}) + if $ratelimiter_log->is_debug(); return $resp; } @@ -242,7 +245,7 @@ sub increment_rate_limit_requests ($ip, $api_action) { if (!$redis_url) { # No Redis URL provided, we can't increment the number of requests if (!$sent_warning_about_missing_redis_url) { - $log->warn("Redis URL not provided, rate-limiting is disabled") if $log->is_warn(); + $ratelimiter_log->warn("Redis URL not provided, rate-limiting is disabled") if $ratelimiter_log->is_warn(); $sent_warning_about_missing_redis_url = 1; } return; @@ -251,11 +254,12 @@ sub increment_rate_limit_requests ($ip, $api_action) { my $error = ""; if (!defined $redis_client) { # we were disconnected, try again - $log->info("Trying to reconnect to Redis"); + $ratelimiter_log->info("Trying to reconnect to Redis"); init_redis(); } if (defined $redis_client) { - $log->debug("Incrementing rate-limit requests", {ip => $ip, api_action => $api_action}) if $log->is_debug(); + $ratelimiter_log->debug("Incrementing rate-limit requests", {ip => $ip, api_action => $api_action}) + if $ratelimiter_log->is_debug(); my $current_minute = int(time() / 60); eval { # Use a MULTI/EXEC block to increment the counter and set the expiration atomically @@ -270,14 +274,15 @@ sub increment_rate_limit_requests ($ip, $api_action) { $error = "Can't connect to Redis"; } if (!($error eq "")) { - $log->error("Failed to increment number of requests from Redis rate-limiter", {error => $error}) - if $log->is_warn(); + $ratelimiter_log->error("Failed to increment number of requests from Redis rate-limiter", {error => $error}) + if $ratelimiter_log->is_error(); # ask for eventual reconnection for next call $redis_client = undef; } else { - $log->debug("Incremented number of requests from Redis rate-limiter", {ip => $ip, api_action => $api_action}) - if $log->is_debug(); + $ratelimiter_log->debug("Incremented number of requests from Redis rate-limiter", + {ip => $ip, api_action => $api_action}) + if $ratelimiter_log->is_debug(); } return; diff --git a/lib/ProductOpener/Routing.pm b/lib/ProductOpener/Routing.pm index aeff845c696c9..55a47619d9db8 100644 --- a/lib/ProductOpener/Routing.pm +++ b/lib/ProductOpener/Routing.pm @@ -61,6 +61,9 @@ use CGI qw/:cgi :form escapeHTML/; use URI::Escape::XS; use Log::Any qw($log); +# Specific logger to track rate-limiter operations +our $ratelimiter_log = Log::Any->get_logger(category => 'ratelimiter'); + =head2 sub extract_tagtype_and_tag_value_pairs_from_components($request_ref, $components_ref) Extract tag type / tag value pairs and store them in an array $request_ref->{tags} @@ -641,13 +644,22 @@ sub set_rate_limit_attributes ($request_ref, $ip) { my $block_message = "Rate-limiter blocking: the user has reached the rate-limit"; # Check if rate-limit blocking is enabled if ($rate_limiter_blocking_enabled) { - $request_ref->{rate_limiter_blocking} = 1; + # Check that the IP address is not in the allow list + if (not defined $options{rate_limit_allow_list}{$ip}) { + # The user has reached the rate-limit, we block the request + $request_ref->{rate_limiter_blocking} = 1; + } + else { + # The IP address is in the allow list, we don't block the request + $block_message + = "Rate-limiter blocking is disabled for the user, but the user has reached the rate-limit"; + } } else { # Rate-limit blocking is disabled, we just log a warning $block_message = "Rate-limiter blocking is disabled, but the user has reached the rate-limit"; } - $log->info( + $ratelimiter_log->info( $block_message, { ip => $ip, @@ -655,7 +667,7 @@ sub set_rate_limit_attributes ($request_ref, $ip) { user_requests => $request_ref->{rate_limiter_user_requests}, limit => $limit } - ) if $log->is_info(); + ) if $ratelimiter_log->is_info(); } return; }