diff --git a/src/filter/http_context.rs b/src/filter/http_context.rs index 62259b67..ac9cbb9c 100644 --- a/src/filter/http_context.rs +++ b/src/filter/http_context.rs @@ -8,7 +8,7 @@ use crate::envoy::{ }; use crate::filter::http_context::TracingHeader::{Baggage, Traceparent, Tracestate}; use crate::utils::tokenize_with_escaping; -use log::{debug, info, warn}; +use log::{debug, warn}; use protobuf::Message; use proxy_wasm::traits::{Context, HttpContext}; use proxy_wasm::types::{Action, Bytes}; @@ -63,7 +63,10 @@ impl Filter { fn process_rate_limit_policy(&self, rlp: &RateLimitPolicy) -> Action { let descriptors = self.build_descriptors(rlp); if descriptors.is_empty() { - debug!("[context_id: {}] empty descriptors", self.context_id); + debug!( + "process_rate_limit_policy: empty descriptors #{}", + self.context_id + ); return Action::Continue; } @@ -89,7 +92,10 @@ impl Filter { Duration::from_secs(5), ) { Ok(call_id) => { - info!("Initiated gRPC call (id# {}) to Limitador", call_id); + debug!( + "Initiated gRPC call (id# {}) to Limitador #{}", + call_id, self.context_id + ); Action::Pause } Err(e) => { @@ -137,28 +143,29 @@ impl Filter { let attribute_path = tokenize_with_escaping(&p_e.selector, '.', '\\'); // convert a Vec to Vec<&str> // attribute_path.iter().map(AsRef::as_ref).collect() - let attribute_value = - match self.get_property(attribute_path.iter().map(AsRef::as_ref).collect()) { - None => { + let attribute_value = match self + .get_property(attribute_path.iter().map(AsRef::as_ref).collect()) + { + None => { + debug!( + "pattern_expression_applies: selector not found: {}, defaulting to `` #{}", + p_e.selector, self.context_id + ); + "".to_string() + } + // TODO(eastizle): not all fields are strings + // https://www.envoyproxy.io/docs/envoy/latest/intro/arch_overview/advanced/attributes + Some(attribute_bytes) => match String::from_utf8(attribute_bytes) { + Err(e) => { debug!( - "[context_id: {}]: selector not found: {}, defaulting to ``", - self.context_id, p_e.selector - ); - "".to_string() - } - // TODO(eastizle): not all fields are strings - // https://www.envoyproxy.io/docs/envoy/latest/intro/arch_overview/advanced/attributes - Some(attribute_bytes) => match String::from_utf8(attribute_bytes) { - Err(e) => { - debug!( - "[context_id: {}]: failed to parse selector value: {}, error: {}", - self.context_id, p_e.selector, e + "pattern_expression_applies: failed to parse selector value: {}, error: {} #{}", + p_e.selector, e, self.context_id, ); - return false; - } - Ok(attribute_value) => attribute_value, - }, - }; + return false; + } + Ok(attribute_value) => attribute_value, + }, + }; p_e.operator .eval(p_e.value.as_str(), attribute_value.as_str()) } @@ -189,8 +196,8 @@ impl Filter { { None => { debug!( - "[context_id: {}]: selector not found: {}", - self.context_id, selector_item.selector + "build_single_descriptor: selector not found: {} #{}", + selector_item.selector, self.context_id, ); match &selector_item.default { None => return None, // skipping the entire descriptor @@ -202,8 +209,9 @@ impl Filter { Some(attribute_bytes) => match String::from_utf8(attribute_bytes) { Err(e) => { debug!( - "[context_id: {}]: failed to parse selector value: {}, error: {}", - self.context_id, selector_item.selector, e); + "build_single_descriptor: failed to parse selector value: {}, error: {} #{}", + selector_item.selector, e, self.context_id + ); return None; } Ok(attribute_value) => attribute_value, @@ -234,7 +242,7 @@ impl Filter { impl HttpContext for Filter { fn on_http_request_headers(&mut self, _: usize, _: bool) -> Action { - info!("on_http_request_headers #{}", self.context_id); + debug!("on_http_request_headers #{}", self.context_id); for header in TracingHeader::all() { if let Some(value) = self.get_http_request_header_bytes(header.as_str()) { @@ -248,13 +256,16 @@ impl HttpContext for Filter { .get_longest_match_policy(self.request_authority().as_str()) { None => { - info!( - "context #{}: Allowing request to pass because zero descriptors generated", + debug!( + "Allowing request to pass because zero descriptors generated #{}", self.context_id ); Action::Continue } - Some(rlp) => self.process_rate_limit_policy(rlp), + Some(rlp) => { + debug!("ratelimitpolicy selected {} #{}", rlp.name, self.context_id); + self.process_rate_limit_policy(rlp) + } } } @@ -269,8 +280,8 @@ impl HttpContext for Filter { impl Context for Filter { fn on_grpc_call_response(&mut self, token_id: u32, status_code: u32, resp_size: usize) { - info!( - "on_grpc_call_response #{}: received gRPC call response: token: {token_id}, status: {status_code}", + debug!( + "on_grpc_call_response: received gRPC call response: token: {token_id}, status: {status_code} #{}", self.context_id ); diff --git a/src/filter/root_context.rs b/src/filter/root_context.rs index ac43c8b1..73598701 100644 --- a/src/filter/root_context.rs +++ b/src/filter/root_context.rs @@ -1,7 +1,7 @@ use crate::configuration::{FilterConfig, PluginConfiguration}; use crate::filter::http_context::Filter; use const_format::formatcp; -use log::{info, warn}; +use log::{debug, info, warn}; use proxy_wasm::traits::{Context, HttpContext, RootContext}; use proxy_wasm::types::ContextType; use std::rc::Rc; @@ -35,7 +35,7 @@ impl RootContext for FilterRoot { } fn create_http_context(&self, context_id: u32) -> Option> { - info!("create_http_context #{}", context_id); + debug!("create_http_context #{}", context_id); Some(Box::new(Filter { context_id, config: Rc::clone(&self.config), diff --git a/tests/rate_limited.rs b/tests/rate_limited.rs index 53c7675e..2ee70eb7 100644 --- a/tests/rate_limited.rs +++ b/tests/rate_limited.rs @@ -50,13 +50,13 @@ fn it_loads() { let http_context = 2; module .call_proxy_on_context_create(http_context, root_context) - .expect_log(Some(LogLevel::Info), Some("create_http_context #2")) + .expect_log(Some(LogLevel::Debug), Some("create_http_context #2")) .execute_and_expect(ReturnType::None) .unwrap(); module .call_proxy_on_request_headers(http_context, 0, false) - .expect_log(Some(LogLevel::Info), Some("on_http_request_headers #2")) + .expect_log(Some(LogLevel::Debug), Some("on_http_request_headers #2")) .expect_get_header_map_value(Some(MapType::HttpRequestHeaders), Some("traceparent")) .returning(None) .expect_get_header_map_value(Some(MapType::HttpRequestHeaders), Some("tracestate")) @@ -66,8 +66,8 @@ fn it_loads() { .expect_get_header_map_value(Some(MapType::HttpRequestHeaders), Some(":authority")) .returning(Some("cars.toystore.com")) .expect_log( - Some(LogLevel::Info), - Some("context #2: Allowing request to pass because zero descriptors generated"), + Some(LogLevel::Debug), + Some("Allowing request to pass because zero descriptors generated #2"), ) .execute_and_expect(ReturnType::Action(Action::Continue)) .unwrap(); @@ -154,13 +154,13 @@ fn it_limits() { let http_context = 2; module .call_proxy_on_context_create(http_context, root_context) - .expect_log(Some(LogLevel::Info), Some("create_http_context #2")) + .expect_log(Some(LogLevel::Debug), Some("create_http_context #2")) .execute_and_expect(ReturnType::None) .unwrap(); module .call_proxy_on_request_headers(http_context, 0, false) - .expect_log(Some(LogLevel::Info), Some("on_http_request_headers #2")) + .expect_log(Some(LogLevel::Debug), Some("on_http_request_headers #2")) .expect_get_header_map_value(Some(MapType::HttpRequestHeaders), Some("traceparent")) .returning(None) .expect_get_header_map_value(Some(MapType::HttpRequestHeaders), Some("tracestate")) @@ -175,6 +175,10 @@ fn it_limits() { .returning(Some("cars.toystore.com".as_bytes())) .expect_get_property(Some(vec!["request", "method"])) .returning(Some("POST".as_bytes())) + .expect_log( + Some(LogLevel::Debug), + Some("ratelimitpolicy selected some-name #2"), + ) .expect_grpc_call( Some("limitador-cluster"), Some("envoy.service.ratelimit.v3.RateLimitService"), @@ -188,8 +192,8 @@ fn it_limits() { ) .returning(Some(42)) .expect_log( - Some(LogLevel::Info), - Some("Initiated gRPC call (id# 42) to Limitador"), + Some(LogLevel::Debug), + Some("Initiated gRPC call (id# 42) to Limitador #2"), ) .execute_and_expect(ReturnType::Action(Action::Pause)) .unwrap(); @@ -198,8 +202,8 @@ fn it_limits() { module .call_proxy_on_grpc_receive(http_context, 42, grpc_response.len() as i32) .expect_log( - Some(LogLevel::Info), - Some("on_grpc_call_response #2: received gRPC call response: token: 42, status: 0"), + Some(LogLevel::Debug), + Some("on_grpc_call_response: received gRPC call response: token: 42, status: 0 #2"), ) .expect_get_buffer_bytes(Some(BufferType::GrpcReceiveBuffer)) .returning(Some(&grpc_response)) @@ -288,13 +292,13 @@ fn it_passes_additional_headers() { let http_context = 2; module .call_proxy_on_context_create(http_context, root_context) - .expect_log(Some(LogLevel::Info), Some("create_http_context #2")) + .expect_log(Some(LogLevel::Debug), Some("create_http_context #2")) .execute_and_expect(ReturnType::None) .unwrap(); module .call_proxy_on_request_headers(http_context, 0, false) - .expect_log(Some(LogLevel::Info), Some("on_http_request_headers #2")) + .expect_log(Some(LogLevel::Debug), Some("on_http_request_headers #2")) .expect_get_header_map_value(Some(MapType::HttpRequestHeaders), Some("traceparent")) .returning(None) .expect_get_header_map_value(Some(MapType::HttpRequestHeaders), Some("tracestate")) @@ -309,6 +313,10 @@ fn it_passes_additional_headers() { .returning(Some("cars.toystore.com".as_bytes())) .expect_get_property(Some(vec!["request", "method"])) .returning(Some("POST".as_bytes())) + .expect_log( + Some(LogLevel::Debug), + Some("ratelimitpolicy selected some-name #2"), + ) .expect_grpc_call( Some("limitador-cluster"), Some("envoy.service.ratelimit.v3.RateLimitService"), @@ -322,8 +330,8 @@ fn it_passes_additional_headers() { ) .returning(Some(42)) .expect_log( - Some(LogLevel::Info), - Some("Initiated gRPC call (id# 42) to Limitador"), + Some(LogLevel::Debug), + Some("Initiated gRPC call (id# 42) to Limitador #2"), ) .execute_and_expect(ReturnType::Action(Action::Pause)) .unwrap(); @@ -336,8 +344,8 @@ fn it_passes_additional_headers() { module .call_proxy_on_grpc_receive(http_context, 42, grpc_response.len() as i32) .expect_log( - Some(LogLevel::Info), - Some("on_grpc_call_response #2: received gRPC call response: token: 42, status: 0"), + Some(LogLevel::Debug), + Some("on_grpc_call_response: received gRPC call response: token: 42, status: 0 #2"), ) .expect_get_buffer_bytes(Some(BufferType::GrpcReceiveBuffer)) .returning(Some(&grpc_response)) @@ -416,13 +424,13 @@ fn it_rate_limits_with_empty_conditions() { let http_context = 2; module .call_proxy_on_context_create(http_context, root_context) - .expect_log(Some(LogLevel::Info), Some("create_http_context #2")) + .expect_log(Some(LogLevel::Debug), Some("create_http_context #2")) .execute_and_expect(ReturnType::None) .unwrap(); module .call_proxy_on_request_headers(http_context, 0, false) - .expect_log(Some(LogLevel::Info), Some("on_http_request_headers #2")) + .expect_log(Some(LogLevel::Debug), Some("on_http_request_headers #2")) .expect_get_header_map_value(Some(MapType::HttpRequestHeaders), Some("traceparent")) .returning(None) .expect_get_header_map_value(Some(MapType::HttpRequestHeaders), Some("tracestate")) @@ -431,6 +439,10 @@ fn it_rate_limits_with_empty_conditions() { .returning(None) .expect_get_header_map_value(Some(MapType::HttpRequestHeaders), Some(":authority")) .returning(Some("a.com")) + .expect_log( + Some(LogLevel::Debug), + Some("ratelimitpolicy selected some-name #2"), + ) .expect_grpc_call( Some("limitador-cluster"), Some("envoy.service.ratelimit.v3.RateLimitService"), @@ -444,8 +456,8 @@ fn it_rate_limits_with_empty_conditions() { ) .returning(Some(42)) .expect_log( - Some(LogLevel::Info), - Some("Initiated gRPC call (id# 42) to Limitador"), + Some(LogLevel::Debug), + Some("Initiated gRPC call (id# 42) to Limitador #2"), ) .execute_and_expect(ReturnType::Action(Action::Pause)) .unwrap(); @@ -454,8 +466,8 @@ fn it_rate_limits_with_empty_conditions() { module .call_proxy_on_grpc_receive(http_context, 42, grpc_response.len() as i32) .expect_log( - Some(LogLevel::Info), - Some("on_grpc_call_response #2: received gRPC call response: token: 42, status: 0"), + Some(LogLevel::Debug), + Some("on_grpc_call_response: received gRPC call response: token: 42, status: 0 #2"), ) .expect_get_buffer_bytes(Some(BufferType::GrpcReceiveBuffer)) .returning(Some(&grpc_response)) @@ -523,13 +535,13 @@ fn it_does_not_rate_limits_when_selector_does_not_exist_and_misses_default_value let http_context = 2; module .call_proxy_on_context_create(http_context, root_context) - .expect_log(Some(LogLevel::Info), Some("create_http_context #2")) + .expect_log(Some(LogLevel::Debug), Some("create_http_context #2")) .execute_and_expect(ReturnType::None) .unwrap(); module .call_proxy_on_request_headers(http_context, 0, false) - .expect_log(Some(LogLevel::Info), Some("on_http_request_headers #2")) + .expect_log(Some(LogLevel::Debug), Some("on_http_request_headers #2")) .expect_get_header_map_value(Some(MapType::HttpRequestHeaders), Some("traceparent")) .returning(None) .expect_get_header_map_value(Some(MapType::HttpRequestHeaders), Some("tracestate")) @@ -542,11 +554,15 @@ fn it_does_not_rate_limits_when_selector_does_not_exist_and_misses_default_value .returning(None) .expect_log( Some(LogLevel::Debug), - Some("[context_id: 2]: selector not found: unknown.path"), + Some("ratelimitpolicy selected some-name #2"), + ) + .expect_log( + Some(LogLevel::Debug), + Some("build_single_descriptor: selector not found: unknown.path #2"), ) .expect_log( Some(LogLevel::Debug), - Some("[context_id: 2] empty descriptors"), + Some("process_rate_limit_policy: empty descriptors #2"), ) .execute_and_expect(ReturnType::Action(Action::Continue)) .unwrap();