debugging

Signed-off-by: Huabing (Robin) Zhao <zhaohuabing@gmail.com>

Author: zhaohuabing

test/e2e/tests/dynamic_resolver_original_host_accesslog.go

@@ -8,13 +8,19 @@
 package tests
 
 import (
+	"context"
+	"encoding/json"
 	"testing"
+	"time"
 
+	"github.com/stretchr/testify/require"
 	"k8s.io/apimachinery/pkg/types"
+	"k8s.io/apimachinery/pkg/util/wait"
 	gwapiv1 "sigs.k8s.io/gateway-api/apis/v1"
 	"sigs.k8s.io/gateway-api/conformance/utils/http"
 	"sigs.k8s.io/gateway-api/conformance/utils/kubernetes"
 	"sigs.k8s.io/gateway-api/conformance/utils/suite"
+	"sigs.k8s.io/gateway-api/conformance/utils/tlog"
 
 	"github.com/envoyproxy/gateway/internal/gatewayapi"
 	"github.com/envoyproxy/gateway/internal/gatewayapi/resource"
@@ -70,8 +76,37 @@ var DynamicResolverOriginalHostAccessLogTest = suite.ConformanceTest{
 		http.MakeRequestAndExpectEventuallyConsistentResponse(t, suite.RoundTripper, suite.TimeoutConfig, gwAddr, expectedResponse)
 
 		labels := getOTELLabels(ns)
-		match := `\"x-request-id\":\"` + requestID +
-			`\".*\"http.host\":\"test-service-foo.gateway-conformance-infra.svc.cluster.local\".*\"http.original_host\":\"www.example.com\"`
-		runLogTest(t, suite, gwAddr, &expectedResponse, labels, match, 1)
+		match := `\"x-request-id\":\"` + requestID + `\"`
+
+		var matchedLog string
+		err := wait.PollUntilContextTimeout(context.Background(), time.Second, time.Minute, true, func(_ context.Context) (bool, error) {
+			lines, err := QueryLogLinesFromLoki(t, suite.Client, labels, match)
+			if err != nil {
+				tlog.Logf(t, "failed to query log lines from loki: %v", err)
+				return false, nil
+			}
+
+			for _, line := range lines {
+				tlog.Logf(t, "candidate access log line: %s", line)
+				entry := map[string]any{}
+				if err := json.Unmarshal([]byte(line), &entry); err != nil {
+					tlog.Logf(t, "failed to unmarshal access log line: %v", err)
+					continue
+				}
+
+				if gotRequestID, ok := entry["x-request-id"].(string); ok && gotRequestID == requestID {
+					matchedLog = line
+					return true, nil
+				}
+			}
+
+			return false, nil
+		})
+		require.NoError(t, err, "timed out waiting for access log line for request id %s", requestID)
+
+		entry := map[string]string{}
+		require.NoError(t, json.Unmarshal([]byte(matchedLog), &entry))
+		require.Equal(t, "test-service-foo.gateway-conformance-infra.svc.cluster.local", entry["http.host"])
+		require.Equal(t, "www.example.com", entry["http.original_host"])
 	},
 }

test/e2e/tests/utils.go

@@ -629,14 +629,27 @@ func OverLimitCount(suite *suite.ConformanceTestSuite) (int, error) {
 	return total, nil
 }
 
-// QueryLogCountFromLoki queries log count from loki
-func QueryLogCountFromLoki(t *testing.T, c client.Client, keyValues map[string]string, match string) (int, error) {
+func buildLokiQuery(keyValues map[string]string, match string) string {
+	qParams := make([]string, 0, len(keyValues))
+	for k, v := range keyValues {
+		qParams = append(qParams, fmt.Sprintf("%s=\"%s\"", k, v))
+	}
+
+	q := "{" + strings.Join(qParams, ",") + "}"
+	if match != "" {
+		q = q + "|~\"" + match + "\""
+	}
+
+	return q
+}
+
+func queryLoki(t *testing.T, c client.Client, keyValues map[string]string, match string) (*LokiQueryResponse, string, error) {
 	svc := corev1.Service{}
 	if err := c.Get(context.Background(), types.NamespacedName{
 		Namespace: "monitoring",
 		Name:      "loki",
 	}, &svc); err != nil {
-		return -1, err
+		return nil, "", err
 	}
 	lokiHost := ""
 	for _, ing := range svc.Status.LoadBalancer.Ingress {
@@ -646,22 +659,14 @@ func QueryLogCountFromLoki(t *testing.T, c client.Client, keyValues map[string]s
 		}
 	}
 
-	qParams := make([]string, 0, len(keyValues))
-	for k, v := range keyValues {
-		qParams = append(qParams, fmt.Sprintf("%s=\"%s\"", k, v))
-	}
-
-	q := "{" + strings.Join(qParams, ",") + "}"
-	if match != "" {
-		q = q + "|~\"" + match + "\""
-	}
+	q := buildLokiQuery(keyValues, match)
 	params := url.Values{}
 	params.Add("query", q)
 	params.Add("start", fmt.Sprintf("%d", time.Now().Add(-10*time.Minute).Unix())) // query logs from last 10 minutes
 	lokiQueryURL := fmt.Sprintf("http://%s/loki/api/v1/query_range?%s", net.JoinHostPort(lokiHost, "3100"), params.Encode())
 	res, err := http.DefaultClient.Get(lokiQueryURL)
 	if err != nil {
-		return -1, err
+		return nil, q, err
 	}
 	defer func() {
 		_ = res.Body.Close()
@@ -670,11 +675,21 @@ func QueryLogCountFromLoki(t *testing.T, c client.Client, keyValues map[string]s
 
 	b, err := io.ReadAll(res.Body)
 	if err != nil {
-		return -1, err
+		return nil, q, err
 	}
 
 	lokiResponse := &LokiQueryResponse{}
 	if err := json.Unmarshal(b, lokiResponse); err != nil {
+		return nil, q, err
+	}
+
+	return lokiResponse, q, nil
+}
+
+// QueryLogCountFromLoki queries log count from loki
+func QueryLogCountFromLoki(t *testing.T, c client.Client, keyValues map[string]string, match string) (int, error) {
+	lokiResponse, q, err := queryLoki(t, c, keyValues, match)
+	if err != nil {
 		return -1, err
 	}
 
@@ -690,6 +705,32 @@ func QueryLogCountFromLoki(t *testing.T, c client.Client, keyValues map[string]s
 	return total, nil
 }
 
+// QueryLogLinesFromLoki queries matching log lines from loki.
+func QueryLogLinesFromLoki(t *testing.T, c client.Client, keyValues map[string]string, match string) ([]string, error) {
+	lokiResponse, _, err := queryLoki(t, c, keyValues, match)
+	if err != nil {
+		return nil, err
+	}
+
+	lines := make([]string, 0)
+	for _, res := range lokiResponse.Data.Result {
+		for _, value := range res.Values {
+			pair, ok := value.([]interface{})
+			if !ok || len(pair) < 2 {
+				continue
+			}
+
+			line, ok := pair[1].(string)
+			if !ok {
+				continue
+			}
+			lines = append(lines, line)
+		}
+	}
+
+	return lines, nil
+}
+
 type LokiQueryResponse struct {
 	Status string `json:"status"`
 	Data   struct {