diff --git a/src/filter.rs b/src/filter.rs index 371fb95f..c87e086f 100644 --- a/src/filter.rs +++ b/src/filter.rs @@ -31,7 +31,7 @@ extern "C" fn start() { proxy_wasm::hostcalls::log(LogLevel::Critical, &panic_info.to_string()).unwrap(); })); proxy_wasm::set_root_context(|context_id| -> Box { - info!("set_root_context #{}", context_id); + info!("#{} set_root_context", context_id); Box::new(FilterRoot { context_id, config: Rc::new(FilterConfig::new()), diff --git a/src/filter/http_context.rs b/src/filter/http_context.rs index 62259b67..a8491770 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", + self.context_id, call_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 ``", + 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: {}]: 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: {}", + "#{} pattern_expression_applies: failed to parse selector value: {}, error: {}", self.context_id, p_e.selector, e ); - 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,7 +196,7 @@ impl Filter { { None => { debug!( - "[context_id: {}]: selector not found: {}", + "#{} build_single_descriptor: selector not found: {}", self.context_id, selector_item.selector ); match &selector_item.default { @@ -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: {}", + self.context_id, selector_item.selector, e + ); 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,29 +256,36 @@ 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 {}", self.context_id, rlp.name); + self.process_rate_limit_policy(rlp) + } } } fn on_http_response_headers(&mut self, _num_headers: usize, _end_of_stream: bool) -> Action { - debug!("on_http_response_headers #{}", self.context_id); + debug!("#{} on_http_response_headers", self.context_id); for (name, value) in &self.response_headers_to_add { self.add_http_response_header(name, value); } Action::Continue } + + fn on_log(&mut self) { + debug!("#{} completed.", self.context_id); + } } 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..d15ea1ce 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; @@ -28,14 +28,14 @@ impl RootContext for FilterRoot { ); info!( - "{} {} root-context #{}: VM started", - WASM_SHIM_HEADER, full_version, self.context_id + "#{} {} {}: VM started", + self.context_id, WASM_SHIM_HEADER, full_version ); true } 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), @@ -45,7 +45,7 @@ impl RootContext for FilterRoot { } fn on_configure(&mut self, _config_size: usize) -> bool { - info!("on_configure #{}", self.context_id); + info!("#{} on_configure", self.context_id); let configuration: Vec = match self.get_plugin_configuration() { Some(c) => c, None => return false, diff --git a/tests/rate_limited.rs b/tests/rate_limited.rs index 53c7675e..1578afa7 100644 --- a/tests/rate_limited.rs +++ b/tests/rate_limited.rs @@ -35,12 +35,12 @@ fn it_loads() { module .call_proxy_on_context_create(root_context, 0) - .expect_log(Some(LogLevel::Info), Some("set_root_context #1")) + .expect_log(Some(LogLevel::Info), Some("#1 set_root_context")) .execute_and_expect(ReturnType::None) .unwrap(); module .call_proxy_on_configure(root_context, 0) - .expect_log(Some(LogLevel::Info), Some("on_configure #1")) + .expect_log(Some(LogLevel::Info), Some("#1 on_configure")) .expect_get_buffer_bytes(Some(BufferType::PluginConfiguration)) .returning(Some(cfg.as_bytes())) .expect_log(Some(LogLevel::Info), None) @@ -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("#2 create_http_context")) .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("#2 on_http_request_headers")) .expect_get_header_map_value(Some(MapType::HttpRequestHeaders), Some("traceparent")) .returning(None) .expect_get_header_map_value(Some(MapType::HttpRequestHeaders), Some("tracestate")) @@ -66,15 +66,15 @@ 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("#2 allowing request to pass because zero descriptors generated"), ) .execute_and_expect(ReturnType::Action(Action::Continue)) .unwrap(); module .call_proxy_on_response_headers(http_context, 0, false) - .expect_log(Some(LogLevel::Debug), Some("on_http_response_headers #2")) + .expect_log(Some(LogLevel::Debug), Some("#2 on_http_response_headers")) .execute_and_expect(ReturnType::Action(Action::Continue)) .unwrap(); } @@ -139,12 +139,12 @@ fn it_limits() { module .call_proxy_on_context_create(root_context, 0) - .expect_log(Some(LogLevel::Info), Some("set_root_context #1")) + .expect_log(Some(LogLevel::Info), Some("#1 set_root_context")) .execute_and_expect(ReturnType::None) .unwrap(); module .call_proxy_on_configure(root_context, 0) - .expect_log(Some(LogLevel::Info), Some("on_configure #1")) + .expect_log(Some(LogLevel::Info), Some("#1 on_configure")) .expect_get_buffer_bytes(Some(BufferType::PluginConfiguration)) .returning(Some(cfg.as_bytes())) .expect_log(Some(LogLevel::Info), None) @@ -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("#2 create_http_context")) .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("#2 on_http_request_headers")) .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("#2 ratelimitpolicy selected some-name"), + ) .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("#2 initiated gRPC call (id# 42) to Limitador"), ) .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("#2 on_grpc_call_response: received gRPC call response: token: 42, status: 0"), ) .expect_get_buffer_bytes(Some(BufferType::GrpcReceiveBuffer)) .returning(Some(&grpc_response)) @@ -208,7 +212,7 @@ fn it_limits() { module .call_proxy_on_response_headers(http_context, 0, false) - .expect_log(Some(LogLevel::Debug), Some("on_http_response_headers #2")) + .expect_log(Some(LogLevel::Debug), Some("#2 on_http_response_headers")) .execute_and_expect(ReturnType::Action(Action::Continue)) .unwrap(); } @@ -273,12 +277,12 @@ fn it_passes_additional_headers() { module .call_proxy_on_context_create(root_context, 0) - .expect_log(Some(LogLevel::Info), Some("set_root_context #1")) + .expect_log(Some(LogLevel::Info), Some("#1 set_root_context")) .execute_and_expect(ReturnType::None) .unwrap(); module .call_proxy_on_configure(root_context, 0) - .expect_log(Some(LogLevel::Info), Some("on_configure #1")) + .expect_log(Some(LogLevel::Info), Some("#1 on_configure")) .expect_get_buffer_bytes(Some(BufferType::PluginConfiguration)) .returning(Some(cfg.as_bytes())) .expect_log(Some(LogLevel::Info), None) @@ -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("#2 create_http_context")) .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("#2 on_http_request_headers")) .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("#2 ratelimitpolicy selected some-name"), + ) .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("#2 initiated gRPC call (id# 42) to Limitador"), ) .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("#2 on_grpc_call_response: received gRPC call response: token: 42, status: 0"), ) .expect_get_buffer_bytes(Some(BufferType::GrpcReceiveBuffer)) .returning(Some(&grpc_response)) @@ -346,7 +354,7 @@ fn it_passes_additional_headers() { module .call_proxy_on_response_headers(http_context, 0, false) - .expect_log(Some(LogLevel::Debug), Some("on_http_response_headers #2")) + .expect_log(Some(LogLevel::Debug), Some("#2 on_http_response_headers")) .expect_add_header_map_value( Some(MapType::HttpResponseHeaders), Some("test"), @@ -401,12 +409,12 @@ fn it_rate_limits_with_empty_conditions() { module .call_proxy_on_context_create(root_context, 0) - .expect_log(Some(LogLevel::Info), Some("set_root_context #1")) + .expect_log(Some(LogLevel::Info), Some("#1 set_root_context")) .execute_and_expect(ReturnType::None) .unwrap(); module .call_proxy_on_configure(root_context, 0) - .expect_log(Some(LogLevel::Info), Some("on_configure #1")) + .expect_log(Some(LogLevel::Info), Some("#1 on_configure")) .expect_get_buffer_bytes(Some(BufferType::PluginConfiguration)) .returning(Some(cfg.as_bytes())) .expect_log(Some(LogLevel::Info), None) @@ -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("#2 create_http_context")) .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("#2 on_http_request_headers")) .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("#2 ratelimitpolicy selected some-name"), + ) .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("#2 initiated gRPC call (id# 42) to Limitador"), ) .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("#2 on_grpc_call_response: received gRPC call response: token: 42, status: 0"), ) .expect_get_buffer_bytes(Some(BufferType::GrpcReceiveBuffer)) .returning(Some(&grpc_response)) @@ -464,7 +476,7 @@ fn it_rate_limits_with_empty_conditions() { module .call_proxy_on_response_headers(http_context, 0, false) - .expect_log(Some(LogLevel::Debug), Some("on_http_response_headers #2")) + .expect_log(Some(LogLevel::Debug), Some("#2 on_http_response_headers")) .execute_and_expect(ReturnType::Action(Action::Continue)) .unwrap(); } @@ -508,12 +520,12 @@ fn it_does_not_rate_limits_when_selector_does_not_exist_and_misses_default_value module .call_proxy_on_context_create(root_context, 0) - .expect_log(Some(LogLevel::Info), Some("set_root_context #1")) + .expect_log(Some(LogLevel::Info), Some("#1 set_root_context")) .execute_and_expect(ReturnType::None) .unwrap(); module .call_proxy_on_configure(root_context, 0) - .expect_log(Some(LogLevel::Info), Some("on_configure #1")) + .expect_log(Some(LogLevel::Info), Some("#1 on_configure")) .expect_get_buffer_bytes(Some(BufferType::PluginConfiguration)) .returning(Some(cfg.as_bytes())) .expect_log(Some(LogLevel::Info), None) @@ -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("#2 create_http_context")) .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("#2 on_http_request_headers")) .expect_get_header_map_value(Some(MapType::HttpRequestHeaders), Some("traceparent")) .returning(None) .expect_get_header_map_value(Some(MapType::HttpRequestHeaders), Some("tracestate")) @@ -542,18 +554,22 @@ 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("#2 ratelimitpolicy selected some-name"), + ) + .expect_log( + Some(LogLevel::Debug), + Some("#2 build_single_descriptor: selector not found: unknown.path"), ) .expect_log( Some(LogLevel::Debug), - Some("[context_id: 2] empty descriptors"), + Some("#2 process_rate_limit_policy: empty descriptors"), ) .execute_and_expect(ReturnType::Action(Action::Continue)) .unwrap(); module .call_proxy_on_response_headers(http_context, 0, false) - .expect_log(Some(LogLevel::Debug), Some("on_http_response_headers #2")) + .expect_log(Some(LogLevel::Debug), Some("#2 on_http_response_headers")) .execute_and_expect(ReturnType::Action(Action::Continue)) .unwrap(); }