Add grpc_status to the logs

examples/custom-log-format/README.md

@@ -9,13 +9,14 @@ metadata:
   name: nginx-config
   namespace: nginx-ingress
 data:
-  log-format:  '$remote_addr - $remote_user [$time_local] "$request" $status $body_bytes_sent "$http_referer"  "$http_user_agent" "$http_x_forwarded_for" "$resource_name" "$resource_type" "$resource_namespace" "$service"'
+  log-format:  '$remote_addr - $remote_user [$time_local] "$request" $status $grpc_status $body_bytes_sent "$http_referer"  "$http_user_agent" "$http_x_forwarded_for" "$resource_name" "$resource_type" "$resource_namespace" "$service"'
 ```
 
 In addition to the [built-in NGINX variables](https://nginx.org/en/docs/varindex.html), you can also use the variables that the Ingress Controller configures:
 - $resource_type - The type of kubernetes resource that handled the client request.
 - $resource_name - The name of the resource
 - $resource_namespace - The namespace the resource exists in.
 - $service - The name of the service the client request was sent to.
+- $grpc_status - the gRPC status code, which is constructed either from the HTTP/2 trailer (grpc_status) returned from the backend for normal conditions, or from the HTTP/2 header (grpc_status) set either by the backend or by NGINX itself for some error conditions.
 
 **note** These variables are only available for Ingress, VirtualServer and VirtualServerRoute resources.

internal/configs/version1/nginx-plus.tmpl

@@ -51,6 +51,11 @@ http {
                       '"$http_user_agent" "$http_x_forwarded_for"';
     {{- end}}
 
+    map $upstream_trailer_grpc_status $grpc_status {
+        default $upstream_trailer_grpc_status;
+        '' $sent_http_grpc_status;
+    }
+
     {{if .AccessLogOff}}
     access_log off;
     {{else}}

internal/configs/version1/nginx.tmpl

@@ -44,6 +44,11 @@ http {
                       '"$http_user_agent" "$http_x_forwarded_for"';
     {{- end}}
 
+    map $upstream_trailer_grpc_status $grpc_status {
+        default $upstream_trailer_grpc_status;
+        '' $sent_http_grpc_status;
+    }
+
     {{if .AccessLogOff}}
     access_log off;
     {{else}}

tests/data/virtual-server-grpc/nginx-config.yaml

@@ -4,4 +4,5 @@ metadata:
   name: nginx-config
   namespace: nginx-ingress
 data:
-  http2: "true"
+  http2: "true"
+  log-format: '$remote_addr - $remote_user [$time_local] "$request" $status $grpc_status $body_bytes_sent "$http_referer" "$http_user_agent" "$http_x_forwarded_for"'

tests/suite/resources_utils.py

@@ -1400,3 +1400,15 @@ def write_to_json(fname, data) -> None:
 
     with open(f"json_files/{fname}", "w+") as f:
         json.dump(data, f, ensure_ascii=False, indent=4)
+
+
+def get_last_log_entry(kube_apis, pod_name, namespace) -> str:
+    """
+    :param kube_apis: kube apis
+    :param pod_name: the name of the pod
+    :param namespace: the namespace
+    """
+    logs = kube_apis.read_namespaced_pod_log(pod_name, namespace)
+    # Our log entries end in '\n' which means the final entry when we split on a new line
+    # is an empty string. Return the second to last entry instead.
+    return logs.split('\n')[-2]

tests/suite/test_virtual_server_grpc.py

@@ -1,7 +1,5 @@
 import grpc
 import pytest
-import time
-from kubernetes.client.rest import ApiException
 
 from settings import TEST_DATA, DEPLOYMENTS
 from suite.custom_assertions import assert_event_starts_with_text_and_contains_errors, \
@@ -10,7 +8,8 @@
 from suite.grpc.helloworld_pb2_grpc import GreeterStub
 from suite.resources_utils import create_example_app, wait_until_all_pods_are_ready, \
     delete_common_app, create_secret_from_yaml, replace_configmap_from_yaml, \
-    delete_items_from_yaml, get_first_pod_name, get_events, wait_before_test, scale_deployment
+    delete_items_from_yaml, get_first_pod_name, get_events, wait_before_test, \
+    scale_deployment, get_last_log_entry
 from suite.ssl_utils import get_certificate
 from suite.vs_vsr_resources_utils import get_vs_nginx_template_conf, \
     patch_virtual_server_from_yaml
@@ -155,10 +154,14 @@ def test_grpc_error_intercept(self, kube_apis, ingress_controller_prerequisites,
             except grpc.RpcError as e:
                 print(e.details())
                 pytest.fail("RPC error was not expected during call, exiting...")
+        # Assert grpc_status is in the logs. The gRPC response in a successful call is 0.
+        ic_pod_name = get_first_pod_name(kube_apis.v1, ingress_controller_prerequisites.namespace)
+        last_log = get_last_log_entry(kube_apis.v1, ic_pod_name, ingress_controller_prerequisites.namespace)
+        assert '"POST /helloworld.Greeter/SayHello HTTP/2.0" 200 0' in last_log
 
         scale_deployment(kube_apis.v1, kube_apis.apps_v1_api, "grpc1", virtual_server_setup.namespace, 0)
         scale_deployment(kube_apis.v1, kube_apis.apps_v1_api, "grpc2", virtual_server_setup.namespace, 0)
-        time.sleep(1)
+        wait_before_test()
 
         with grpc.secure_channel(target, credentials, options) as channel:
             stub = GreeterStub(channel)
@@ -169,6 +172,11 @@ def test_grpc_error_intercept(self, kube_apis, ingress_controller_prerequisites,
                 pytest.fail("RPC error was expected during call, exiting...")
             except grpc.RpcError as e:
                 print(e)
+        # Assert the grpc_status is also in the logs.
+        ic_pod_name = get_first_pod_name(kube_apis.v1, ingress_controller_prerequisites.namespace)
+        wait_before_test()
+        last_log = get_last_log_entry(kube_apis.v1, ic_pod_name, ingress_controller_prerequisites.namespace)
+        assert '"POST /helloworld.Greeter/SayHello HTTP/2.0" 204 14' in last_log
 
     @pytest.mark.parametrize("backend_setup", [{"app_type": "grpc-vs"}], indirect=True)
     def test_config_after_enable_tls(self, kube_apis, ingress_controller_prerequisites,
@@ -229,7 +237,6 @@ def test_grpc_healthcheck_validation(self, kube_apis, ingress_controller_prerequ
         wait_before_test(2)
         ic_pod_name = get_first_pod_name(kube_apis.v1, ingress_controller_prerequisites.namespace)        
         vs_events = get_events(kube_apis.v1, virtual_server_setup.namespace)
-        print(vs_events)
         assert_event_starts_with_text_and_contains_errors(vs_event_text, vs_events, invalid_fields)
         assert_vs_conf_not_exists(kube_apis, ic_pod_name, ingress_controller_prerequisites.namespace,
                                   virtual_server_setup)