From 32f692cdbce948a0b7260265a8208a236a070db3 Mon Sep 17 00:00:00 2001 From: evgeniy-scherbina Date: Thu, 12 Oct 2023 12:27:36 -0400 Subject: [PATCH] DEBUG Commit --- .env | 2 +- Makefile | 4 +- main_test.go | 140 ++++++++++++++++++++++++++++++++++++++++++ rebuild.sh | 4 ++ service/middleware.go | 15 +++++ 5 files changed, 162 insertions(+), 3 deletions(-) create mode 100755 rebuild.sh diff --git a/.env b/.env index a54ad67..00d97e9 100644 --- a/.env +++ b/.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 diff --git a/Makefile b/Makefile index d63769d..6291a8f 100644 --- a/Makefile +++ b/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 diff --git a/main_test.go b/main_test.go index 3bd2cff..e58557e 100644 --- a/main_test.go +++ b/main_test.go @@ -2,6 +2,8 @@ package main_test import ( "context" + "fmt" + "math/big" "os" "testing" "time" @@ -469,3 +471,141 @@ 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("latestBlock: %v", latestBlock.Hash()) + bal1, err := client.NonceAt(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) + bal2, err := client.NonceAt(testContext, testAddress, requestBlockNumber) + require.NoError(t, err) + + block, err := client.BlockByNumber(testContext, big.NewInt(3)) + require.NoError(t, err) + fmt.Printf("BLOCK_NUMBER: %v\n", block.Number()) + + block, err = client.BlockByNumber(testContext, big.NewInt(3)) + require.NoError(t, err) + fmt.Printf("BLOCK_NUMBER: %v\n", block.Number()) + + 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 +} diff --git a/rebuild.sh b/rebuild.sh new file mode 100755 index 0000000..71603d8 --- /dev/null +++ b/rebuild.sh @@ -0,0 +1,4 @@ +make down +docker rmi kava-proxy-service-proxy +make build +make up \ No newline at end of file diff --git a/service/middleware.go b/service/middleware.go index df88d70..8478e20 100644 --- a/service/middleware.go +++ b/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))