Skip to content

Commit

Permalink
logging enhancements
Browse files Browse the repository at this point in the history
  • Loading branch information
@eguzki
eguzki committed Jun 14, 2024
1 parent 984d7fe commit f2138c8
Show file tree
Hide file tree
Showing 3 changed files with 88 additions and 61 deletions.
77 changes: 44 additions & 33 deletions src/filter/http_context.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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};
Expand Down Expand Up @@ -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;
}

Expand All @@ -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) => {
Expand Down Expand Up @@ -137,28 +143,29 @@ impl Filter {
let attribute_path = tokenize_with_escaping(&p_e.selector, '.', '\\');
// convert a Vec<String> 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())
}
Expand Down Expand Up @@ -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
Expand All @@ -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,
Expand Down Expand Up @@ -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()) {
Expand All @@ -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)
}
}
}

Expand All @@ -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
);

Expand Down
4 changes: 2 additions & 2 deletions src/filter/root_context.rs
View file
Original file line number Diff line number Diff line change
@@ -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;
Expand Down Expand Up @@ -35,7 +35,7 @@ impl RootContext for FilterRoot {
}

fn create_http_context(&self, context_id: u32) -> Option<Box<dyn HttpContext>> {
info!("create_http_context #{}", context_id);
debug!("create_http_context #{}", context_id);
Some(Box::new(Filter {
context_id,
config: Rc::clone(&self.config),
Expand Down
68 changes: 42 additions & 26 deletions tests/rate_limited.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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"))
Expand All @@ -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();
Expand Down Expand Up @@ -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"))
Expand All @@ -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"),
Expand All @@ -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();
Expand All @@ -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))
Expand Down Expand Up @@ -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"))
Expand All @@ -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"),
Expand All @@ -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();
Expand All @@ -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))
Expand Down Expand Up @@ -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"))
Expand All @@ -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"),
Expand All @@ -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();
Expand All @@ -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))
Expand Down Expand Up @@ -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"))
Expand All @@ -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();
Expand Down

0 comments on commit f2138c8

Please sign in to comment.