feat: improve rate-limiter (#10338)

.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
 

.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

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

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

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

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

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;

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 ();

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;

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,21 +644,30 @@ 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,
 				api_action => $api_action,
 				user_requests => $request_ref->{rate_limiter_user_requests},
 				limit => $limit
 			}
-		) if $log->is_info();
+		) if $ratelimiter_log->is_info();
 	}
 	return;
 }