Add check for gRPC status in access log filter (envoyproxy#2685)

* Add root and vm id for access log filter Signed-off-by: gargnupur <gargnupur@google.com> * Check gRPC status too Signed-off-by: gargnupur <gargnupur@google.com> * Fix test Signed-off-by: gargnupur <gargnupur@google.com> * Fix test Signed-off-by: gargnupur <gargnupur@google.com> * Fix test Signed-off-by: gargnupur <gargnupur@google.com> * Fixed based on feedback Signed-off-by: gargnupur <gargnupur@google.com> * Fixed based on feedback Signed-off-by: gargnupur <gargnupur@google.com>
Shikugawa · Mar 13, 2020 · c0b5350 · c0b5350
1 parent cf701d9
commit c0b5350
Show file tree

Hide file tree

Showing 5 changed files with 47 additions and 7 deletions.
diff --git a/extensions/access_log_policy/plugin.cc b/extensions/access_log_policy/plugin.cc
@@ -66,6 +66,9 @@ constexpr StringView kSource = "source";
 constexpr StringView kAddress = "address";
 constexpr StringView kConnection = "connection";
 constexpr StringView kUriSanPeerCertificate = "uri_san_peer_certificate";
+constexpr StringView kResponse = "response";
+constexpr StringView kCode = "code";
+constexpr StringView kGrpcStatus = "grpc_status";
 
 static RegisterContextFactory register_AccessLogPolicy(
     CONTEXT_FACTORY(PluginContext), ROOT_FACTORY(PluginRootContext));
@@ -114,11 +117,8 @@ void PluginRootContext::updateLastLogTimeNanos(const IstioDimensions& key,
 
 void PluginContext::onLog() {
   // Check if request is a failure.
-  int64_t response_code = 0;
-  // TODO(gargnupur): Add check for gRPC status too.
-  getValue({"response", "code"}, &response_code);
-  // If request is a failure, log it.
-  if (response_code != 200) {
+  if (isRequestFailed()) {
+    LOG_TRACE("Setting logging to true as we got error log");
     setFilterStateValue(true);
     return;
   }
@@ -135,6 +135,10 @@ void PluginContext::onLog() {
   long long last_log_time_nanos = lastLogTimeNanos();
   auto cur = static_cast<long long>(getCurrentTimeNanoseconds());
   if ((cur - last_log_time_nanos) > logTimeDurationNanos()) {
+    LOG_TRACE(absl::StrCat(
+        "Setting logging to true as its outside of log windown. SourceIp: ",
+        source_ip, " SourcePrincipal: ", source_principal,
+        " Window: ", logTimeDurationNanos()));
     if (setFilterStateValue(true)) {
       updateLastLogTimeNanos(cur);
     }
@@ -144,6 +148,28 @@ void PluginContext::onLog() {
   setFilterStateValue(false);
 }
 
+bool PluginContext::isRequestFailed() {
+  // Check if HTTP request is a failure.
+  int64_t http_response_code = 0;
+  if (getValue({kResponse, kCode}, &http_response_code) &&
+      http_response_code != 200) {
+    return true;
+  }
+
+  // Check if gRPC request is a failure.
+  int64_t grpc_response_code = 0;
+  if (::Wasm::Common::kGrpcContentTypes.count(
+          getHeaderMapValue(Common::Wasm::HeaderMapType::RequestHeaders,
+                            ::Wasm::Common::kContentTypeHeaderKey)
+              ->toString()) != 0 &&
+      getValue({kResponse, kGrpcStatus}, &grpc_response_code) &&
+      grpc_response_code != 0) {
+    return true;
+  }
+
+  return false;
+}
+
 #ifdef NULL_PLUGIN
 }  // namespace Plugin
 }  // namespace AccessLogPolicy

diff --git a/extensions/access_log_policy/plugin.h b/extensions/access_log_policy/plugin.h
@@ -102,6 +102,7 @@ class PluginContext : public Context {
   inline long long logTimeDurationNanos() {
     return rootContext()->logTimeDurationNanos();
   };
+  bool isRequestFailed();
 
   IstioDimensions istio_dimensions_;
 };

diff --git a/src/envoy/tcp/metadata_exchange/metadata_exchange.cc b/src/envoy/tcp/metadata_exchange/metadata_exchange.cc
@@ -88,6 +88,9 @@ Network::FilterStatus MetadataExchangeFilter::onData(Buffer::Instance& data,
       // If Alpn protocol is not the expected one, then return.
       // Else find and write node metadata.
       if (read_callbacks_->connection().nextProtocol() != config_->protocol_) {
+        ENVOY_LOG(trace, "Alpn Protocol Not Found. Expected {}, Got {}",
+                  config_->protocol_,
+                  read_callbacks_->connection().nextProtocol());
         setMetadataNotFoundFilterState();
         conn_state_ = Invalid;
         config_->stats().alpn_protocol_not_found_.inc();
@@ -147,6 +150,9 @@ Network::FilterStatus MetadataExchangeFilter::onWrite(Buffer::Instance&, bool) {
       return Network::FilterStatus::Continue;
     case ConnProtocolNotRead: {
       if (read_callbacks_->connection().nextProtocol() != config_->protocol_) {
+        ENVOY_LOG(trace, "Alpn Protocol Not Found. Expected {}, Got {}",
+                  config_->protocol_,
+                  read_callbacks_->connection().nextProtocol());
         setMetadataNotFoundFilterState();
         conn_state_ = Invalid;
         config_->stats().alpn_protocol_not_found_.inc();
@@ -212,6 +218,8 @@ void MetadataExchangeFilter::tryReadInitialProxyHeader(Buffer::Instance& data) {
   if (data.length() < initial_header_length) {
     config_->stats().initial_header_not_found_.inc();
     // Not enough data to read. Wait for it to come.
+    ENVOY_LOG(trace,
+              "Alpn Protocol matched. Waiting to read more initial header.");
     conn_state_ = NeedMoreDataInitialHeader;
     return;
   }
@@ -221,6 +229,7 @@ void MetadataExchangeFilter::tryReadInitialProxyHeader(Buffer::Instance& data) {
       MetadataExchangeInitialHeader::magic_number) {
     config_->stats().initial_header_not_found_.inc();
     setMetadataNotFoundFilterState();
+    ENVOY_LOG(trace, "Alpn Protocol Matched. Magic not matched.");
     conn_state_ = Invalid;
     return;
   }
@@ -237,6 +246,7 @@ void MetadataExchangeFilter::tryReadProxyData(Buffer::Instance& data) {
   }
   if (data.length() < proxy_data_length_) {
     // Not enough data to read. Wait for it to come.
+    ENVOY_LOG(trace, "Alpn Protocol matched. Waiting to read more metadata.");
     conn_state_ = NeedMoreDataProxyHeader;
     return;
   }
@@ -247,6 +257,8 @@ void MetadataExchangeFilter::tryReadProxyData(Buffer::Instance& data) {
   if (!proxy_data.ParseFromString(proxy_data_buf)) {
     config_->stats().header_not_found_.inc();
     setMetadataNotFoundFilterState();
+    ENVOY_LOG(trace,
+              "Alpn protocol matched. Magic matched. Metadata Not found.");
     conn_state_ = Invalid;
     return;
   }

diff --git a/src/envoy/tcp/metadata_exchange/metadata_exchange.h b/src/envoy/tcp/metadata_exchange/metadata_exchange.h
@@ -89,7 +89,8 @@ using MetadataExchangeConfigSharedPtr = std::shared_ptr<MetadataExchangeConfig>;
 /**
  * A MetadataExchange filter instance. One per connection.
  */
-class MetadataExchangeFilter : public Network::Filter {
+class MetadataExchangeFilter : public Network::Filter,
+                               protected Logger::Loggable<Logger::Id::filter> {
  public:
   MetadataExchangeFilter(MetadataExchangeConfigSharedPtr config,
                          const LocalInfo::LocalInfo& local_info)

diff --git a/test/envoye2e/stackdriver_plugin/stackdriver_plugin_test.go b/test/envoye2e/stackdriver_plugin/stackdriver_plugin_test.go
@@ -344,7 +344,7 @@ func verifyNumberOfAccessLogs(fsdl *driver.LoggingServer, t *testing.T, expected
 		select {
 		case req := <-fsdl.RcvLoggingReq:
 			if len(req.Entries) != expectedEntries {
-				t.Errorf("WriteLogEntries verification failed. Number of entries expected: %v, got: %v, gotEntry: %v", 1, len(req.Entries), req)
+				t.Errorf("WriteLogEntries verification failed. Number of entries expected: %v, got: %v, gotEntry: %v", expectedEntries, len(req.Entries), req)
 			}
 			logRcv = true
 		case <-to.C: