diff --git a/src/filter.rs b/src/filter.rs
index 371fb95..c87e086 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<dyn RootContext> {
-        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 62259b6..a849177 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<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 ``",
+                    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 ac43c8b..d15ea1c 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<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),
@@ -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<u8> = match self.get_plugin_configuration() {
             Some(c) => c,
             None => return false,
diff --git a/tests/rate_limited.rs b/tests/rate_limited.rs
index 53c7675..1578afa 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();
 }