DEBUG Commit

.env

@@ -48,7 +48,7 @@ TEST_EVM_QUERY_SERVICE_URL=http://kava:8545
 ##### Kava Proxy Config
 # What port the proxy service listens on
 PROXY_SERVICE_PORT=7777
-LOG_LEVEL=TRACE
+LOG_LEVEL=ERROR
 HTTP_READ_TIMEOUT_SECONDS=30
 HTTP_WRITE_TIMEOUT_SECONDS=60
 # Address of the origin server to proxy all requests to

Makefile

@@ -27,7 +27,7 @@ install: lint
 .PHONY: build
 # build a development version docker image of the service
 build: lint
-	docker build ./ -f local.Dockerfile -t ${IMAGE_NAME}:${LOCAL_IMAGE_TAG}
+	docker build --no-cache ./ -f local.Dockerfile -t ${IMAGE_NAME}:${LOCAL_IMAGE_TAG}
 
 .PHONY: publish
 # build a production version docker image of the service
@@ -42,7 +42,7 @@ unit-test:
 .PHONY: e2e-test
 # run tests that execute against a local or remote instance of the API
 e2e-test:
-	go test -count=1 -v -cover -coverprofile cover.out --race ./... -run "^TestE2ETest*"
+	go test -count=1 -v -cover -coverprofile cover.out --race ./... -run "^TestE2ETestProxyCachesMethodsWithBlockNumberParam*"
 
 .PHONY: it
 # run any test matching the provided pattern, can pass a regex or a string

main_test.go

@@ -2,6 +2,7 @@ package main_test
 
 import (
 	"context"
+	"fmt"
 	"os"
 	"testing"
 	"time"
@@ -469,3 +470,130 @@ func TestE2ETestProxyTracksBlockNumberForMethodsWithBlockHashParam(t *testing.T)
 		assert.Equal(t, *requestMetricDuringRequestWindow.BlockNumber, requestBlockNumber)
 	}
 }
+
+func TestE2ETestProxyCachesMethodsWithBlockNumberParam(t *testing.T) {
+	testEthMethodName := "eth_getBalance"
+	testRandomAddressHex := "0x6767114FFAA17C6439D7AEA480738B982CE63A02"
+	testAddress := common.HexToAddress(testRandomAddressHex)
+
+	// create api and database clients
+	client, err := ethclient.Dial(proxyServiceURL)
+
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	databaseClient, err := database.NewPostgresClient(databaseConfig)
+
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	// get the latest queryable block number
+	// need to do this dynamically since not all blocks
+	// are queryable for a given network
+	latestBlock, err := client.HeaderByNumber(testContext, nil)
+
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	requestBlockNumber := latestBlock.Number
+
+	// make requests to api and track start / end time of the request
+	// we don't check response errors because the proxy will create metrics
+	// for each request whether the kava node api returns an error or not
+	// and if it doesn't the test itself will fail due to missing metrics
+	startTime := time.Now()
+
+	// eth_getBalance - cache MISS
+	bal1, err := client.BalanceAt(testContext, testAddress, requestBlockNumber)
+	fmt.Printf("bal1: %v, err: %v", bal1, err)
+	require.NoError(t, err)
+
+	// eth_getBalance - cache HIT
+	bal2, err := client.BalanceAt(testContext, testAddress, requestBlockNumber)
+	require.NoError(t, err)
+
+	endTime := time.Now()
+	_ = testEthMethodName
+	_ = databaseClient
+	_ = startTime
+	_ = endTime
+
+	require.Equal(t, bal1, bal2, "balances should be the same")
+
+	//requestMetricsDuringRequestWindow := getRequestMetricsBetween(
+	//	t,
+	//	databaseClient,
+	//	[]string{testEthMethodName},
+	//	startTime,
+	//	endTime,
+	//)
+	//
+	//assert.Equal(t, len(requestMetricsDuringRequestWindow), 2)
+
+	//assert.NotEqual(
+	//	t,
+	//	requestMetricsDuringRequestWindow[0].CacheHit,
+	//	requestMetricsDuringRequestWindow[1].CacheHit,
+	//	"expected one cache hit and one cache miss",
+	//)
+}
+
+func getRequestMetricsBetween(
+	t *testing.T,
+	databaseClient database.PostgresClient,
+	testedMethods []string,
+	startTime, endTime time.Time,
+) []database.ProxiedRequestMetric {
+	t.Helper()
+
+	var nextCursor int64
+	var proxiedRequestMetrics []database.ProxiedRequestMetric
+
+	proxiedRequestMetricsPage, nextCursor, err := database.ListProxiedRequestMetricsWithPagination(
+		testContext,
+		databaseClient.DB,
+		nextCursor,
+		10000,
+	)
+
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	proxiedRequestMetrics = proxiedRequestMetricsPage
+
+	for nextCursor != 0 {
+		proxiedRequestMetricsPage, nextCursor, err = database.ListProxiedRequestMetricsWithPagination(
+			testContext,
+			databaseClient.DB,
+			nextCursor,
+			10000,
+		)
+
+		if err != nil {
+			t.Fatal(err)
+		}
+
+		proxiedRequestMetrics = append(proxiedRequestMetrics, proxiedRequestMetricsPage...)
+	}
+
+	// search for any request metrics during the test timespan
+	// with the same method used by the test
+	var requestMetricsDuringRequestWindow []database.ProxiedRequestMetric
+	// iterate in reverse order to start checking the most recent request metrics first
+	for i := len(proxiedRequestMetrics) - 1; i >= 0; i-- {
+		requestMetric := proxiedRequestMetrics[i]
+		if requestMetric.RequestTime.After(startTime) && requestMetric.RequestTime.Before(endTime) {
+			for _, testedMethod := range testedMethods {
+				if requestMetric.MethodName == testedMethod {
+					requestMetricsDuringRequestWindow = append(requestMetricsDuringRequestWindow, requestMetric)
+				}
+			}
+		}
+	}
+
+	return requestMetricsDuringRequestWindow
+}

rebuild.sh

@@ -0,0 +1,4 @@
+make down
+docker rmi kava-proxy-service-proxy
+make build
+make up

service/middleware.go

@@ -232,7 +232,22 @@ func createProxyRequestMiddleware(next http.Handler, config config.Config, servi
 			// Only proxy the request if it's not cached
 			isCached := cachemdw.IsRequestCached(r.Context())
 			if !isCached {
+				serviceLogger.Error().Msg("BEFORE ServeHTTP")
+				serviceLogger.Error().Msgf("%+v\n %+v\n", lrw, r)
+				serviceLogger.Error().Msgf("############################## REQUEST ############################################")
+				rawBody1, err := io.ReadAll(lrw.body)
+				serviceLogger.Error().Msgf("Host: %s\n", r.Host)
+				serviceLogger.Error().Msgf("Method: %s\n", r.Method)
+				serviceLogger.Error().Msgf("URL: %s\n", r.URL.String())
+				serviceLogger.Error().Msgf("rawBodyRequest: %s\n err: %v\n", rawBody1, err)
+				serviceLogger.Error().Msgf("##########################################################################")
 				proxy.ServeHTTP(lrw, r)
+				serviceLogger.Error().Msg("AFTER ServeHTTP")
+				serviceLogger.Error().Msgf("%+v\n %+v\n", lrw, r)
+				rawBody, err := io.ReadAll(lrw.body)
+				serviceLogger.Error().Msgf("############################### RESPONSE ###########################################")
+				serviceLogger.Error().Msgf("rawBody: %s\n err: %v\n", rawBody, err)
+				serviceLogger.Error().Msgf("##########################################################################")
 			}
 
 			serviceLogger.Trace().Msg(fmt.Sprintf("response %+v \nheaders %+v \nstatus %+v for request %+v", lrw.Status(), lrw.Header(), lrw.body, r))