test: Refactor Existing k6 Tests to Measure Accurately

.github/workflows/k6-tests.yml

@@ -70,6 +70,21 @@ jobs:
           trap "popd" EXIT
           npm run test
 
+      - name: Display Test Logs
+        run: |
+          pushd ${K6_ROOT} || exit 1
+          trap "popd" EXIT
+          npm run print-logs
+
       - name: Stop Containers
         if: ${{ always() }}
         run: ${GRADLE_EXEC} stopDockerContainer
+
+      - name: Upload Log Directory
+        if: always()
+        uses: actions/upload-artifact@b7c566a772e6b6bfb58ed0dc250532a479d7789f # v6.0.0
+        with:
+          name: all-out-logs
+          path: ${{ env.K6_ROOT }}/k6-out/ # This uploads everything inside the logs folder
+          if-no-files-found: "warn" # This will not fail the step if there are no files in the logs folder, but will warn us
+          retention-days: 5 # retain the logs for a period

.gitignore

@@ -66,4 +66,4 @@ protobuf-sources/hiero-consensus-node/
 
 node_modules/
 k6-proto/
-k6-out.txt
+k6-out/

tools-and-tests/k6/average-load/bn-server-status.js

@@ -1,13 +1,15 @@
-import { Client, StatusOK } from 'k6/net/grpc';
+import {Client, StatusDeadlineExceeded, StatusOK} from 'k6/net/grpc';
 import { check, sleep } from 'k6';
 import { SharedArray } from 'k6/data';
 import {ServerStatusRequest} from "../lib/grpc.js";
+import {scenario, vu} from 'k6/execution';
+
 
 // Configure k6 VUs scheduling and iterations & thresholds
 export const options = {
     stages: [
-        { duration: '2m', target: 40 }, // traffic ramp-up from 1 to 40 users (all CNs and a shadow MN) over 5 minutes.
-        { duration: '3m', target: 100 }, // stay at 100 users for 3 minutes
+        { duration: '1m', target: 20 }, // traffic ramp-up from 1 to 40 users (all CNs and a shadow MN) over 5 minutes.
+        { duration: '1m', target: 40 }, // stay at 100 users for 3 minutes
         { duration: '1m', target: 0 }, // ramp-down to 0 users
     ],
     thresholds: { // todo make these good defaults, we need these to display tags in the result, but also to ping us if they go over
@@ -24,18 +26,48 @@ const data = new SharedArray('BN Test Configs', function () {
 const client = new Client();
 client.load([data.protobufPath], 'block-node/api/node_service.proto');
 
+// export function setup() {
+//     console.log(`Running setup for: vuIterationInScenario=${vu.iterationInScenario}, vuIterationInInstance=${vu.iterationInInstance} vuIdInTest=${vu.idInTest}, vuIdInInstance=${vu.idInInstance}`)
+//     if (vu.iterationInScenario === 0) {
+//         client.connect(data.blockNodeUrl, {
+//             plaintext: true
+//         });
+//         console.log(`Connection established: vuIterationInScenario=${vu.iterationInScenario}, vuIterationInInstance=${vu.iterationInInstance} vuIdInTest=${vu.idInTest}, vuIdInInstance=${vu.idInInstance}`)
+//     } else {
+//         console.log(`Connection is presumably established: vuIterationInScenario=${vu.iterationInScenario}, vuIterationInInstance=${vu.iterationInInstance} vuIdInTest=${vu.idInTest}, vuIdInInstance=${vu.idInInstance}`)
+//     }
+//     // return { data: res.json() };
+// }
+
 // run test
 export default () => {
-    client.connect(data.blockNodeUrl, {
-        plaintext: true
-    });
+    if (vu.iterationInScenario === 0) {
+        client.connect(data.blockNodeUrl, {
+            plaintext: true
+        });
+        console.log(`Connection established: scenarioIterationInTest=${scenario.iterationInTest}, vuIterationInScenario=${vu.iterationInScenario}, vuIterationInInstance=${vu.iterationInInstance} vuIdInTest=${vu.idInTest}, vuIdInInstance=${vu.idInInstance}`)
+    } else {
+        console.log(`Connection is presumably established: scenarioIterationInTest=${scenario.iterationInTest}, vuIterationInScenario=${vu.iterationInScenario}, vuIterationInInstance=${vu.iterationInInstance} vuIdInTest=${vu.idInTest}, vuIdInInstance=${vu.idInInstance}`)
+    }
     const params = {
         tags: {name: 'block_node_server_status'}
     };
-    const response = new ServerStatusRequest(client).invoke(params);
+    let response = new ServerStatusRequest(client).invoke(params);
+    if (response.status === StatusDeadlineExceeded) {
+        console.warn(`VU ${vu.idInTest} detected a stale connection (Code 4). Repairing...:  scenarioIterationInTest=${scenario.iterationInTest}, vuIterationInScenario=${vu.iterationInScenario}, vuIterationInInstance=${vu.iterationInInstance} vuIdInTest=${vu.idInTest}, vuIdInInstance=${vu.idInInstance}`);
+
+        client.close(); // Force kill the bad handle
+        client.connect(data.blockNodeUrl, { plaintext: true });
+
+        // Re-try immediately on the new connection
+        response = new ServerStatusRequest(client).invoke(params);
+    }
+    if (response.status !== StatusOK) {
+        console.log(`gRPC Error Code: ${response.status} (Message: ${response.error.message})`);
+        console.log(`gRPC error happened for: scenarioIterationInTest=${scenario.iterationInTest}, vuIterationInScenario=${vu.iterationInScenario}, vuIterationInInstance=${vu.iterationInInstance} vuIdInTest=${vu.idInTest}, vuIdInInstance=${vu.idInInstance}`)
+    }
     check(response, {
         'status is OK': (r) => r && r.status === StatusOK,
     });
-    client.close();
     sleep(1);
 };

tools-and-tests/k6/package.json

@@ -2,7 +2,8 @@
   "name": "@hiero-ledger/block-node-k6",
   "version": "0.0.1",
   "scripts": {
-    "test": "./run-k6-tests.sh"
+    "test": "./run-k6-tests.sh",
+    "print-logs": "./print-logs.sh"
   },
   "devDependencies": {
     "@types/k6": "^1.4.0"

tools-and-tests/k6/print-logs.sh

@@ -0,0 +1,13 @@
+#!/usr/bin/env bash
+
+print_logs() {
+    local k6_out_dir="k6-out"
+    # for each log file in the k6_out_dir, cat to console
+    for log_file in "${k6_out_dir}"/*.log; do
+        echo "===== Contents of ${log_file} ====="
+        cat "${log_file}"
+        echo "===================================="
+    done
+}
+
+print_logs

tools-and-tests/k6/run-k6-tests.sh

@@ -65,39 +65,45 @@ cleanup() {
 # todo add more tests here and also make sure to reset BN
 
 run_server_status_test() {
-    run_bn
-    run_simulator 0 10
     echo "Running server status test..."
-    k6 run ./average-load/bn-server-status.js >> "${k6_out_file}" 2>&1
+    local out_file=${k6_out_dir}/server_status_test.log
+    k6 run ./average-load/bn-server-status.js >> "${out_file}" 2>&1
     echo "Server status test completed."
 }
 
 run_query_validation_test() {
-    run_bn
-    run_simulator 0 10
     echo "Running query validation test..."
-    k6 run ./smoke/bn-query-validation.js >> "${k6_out_file}" 2>&1
+    local out_file=${k6_out_dir}/query_validation_test.log
+    k6 run ./smoke/bn-query-validation.js >> "${out_file}" 2>&1
     echo "Query validation test completed."
 }
 
 run_stream_validation_test() {
-    run_bn
-    run_simulator 0 10
     echo "Running stream validation test..."
-    k6 run ./smoke/bn-stream-validation.js >> "${k6_out_file}" 2>&1
+    local out_file=${k6_out_dir}/stream_validation_test.log
+    k6 run ./smoke/bn-stream-validation.js >> "${out_file}" 2>&1
     echo "Stream validation test completed."
 }
 
-run_tests() {
-    trap cleanup EXIT
-    local k6_out_file="k6-out.txt"
-    rm -f "${k6_out_file}" # remove old output file if exists before running tests
-    setup_proto_defs
+run_shared_node_tests() {
+    # These tests can run on a shared node setup as they only read data
+    run_bn
+    run_simulator 0 100
+    echo "Running shared node tests..."
     run_server_status_test
     run_query_validation_test
     run_stream_validation_test
-    echo "K6 tests completed. Output written to ${k6_out_file}"
-    cat "${k6_out_file}"
+    echo "Shared node tests completed."
+}
+
+run_tests() {
+    trap cleanup EXIT
+    local k6_out_dir="k6-out"
+    rm -rf "${k6_out_dir}" # remove old output dir if exists before running tests
+    mkdir -p "${k6_out_dir}"
+    setup_proto_defs
+    run_shared_node_tests
+    echo "K6 tests completed. Output available at: ${k6_out_dir}"
 }
 
 run_tests

tools-and-tests/k6/smoke/bn-query-validation.js

@@ -7,12 +7,10 @@
 export const options = {
     thresholds: { // todo make these good defaults, we need these to display tags in the result, but also to ping us if they go over
         'grpc_req_duration{name:block_node_server_status}': ['p(95)<300'],
-        'grpc_req_duration{name:get_first_block}': ['p(95)<300'],
-        'grpc_req_duration{name:get_last_block}': ['p(95)<300'],
+        'grpc_req_duration{name:get_block}': ['p(95)<300'],
     },
 };
 
-
 // load test configuration data
 const data = new SharedArray('BN Test Configs', function () {
     return JSON.parse(open('./../data.json')).configs;
@@ -26,7 +24,7 @@
     'block-node/api/block_stream_subscribe_service.proto');
 
 // run test
-export default () => {
+export default async () => {
     client.connect(data.blockNodeUrl, {
         plaintext: true
     });
@@ -44,24 +42,24 @@
     if (firstAvailableBlock === '18446744073709551615') {
         console.log(`No blocks to fetch, exiting test.`);
     } else {
-        const getFirstBlockRequestParams = {
-            tags: {name: 'get_first_block'},
-        };
-        const firstAvailableBlockResponse = new GetBlockRequest(client).invoke(firstAvailableBlock, getFirstBlockRequestParams);
-        check(firstAvailableBlockResponse, {
-            'block fetch status is OK': (r) => r && r.status === StatusOK,
-            'fetched block number is correct': (r) => r && r.message.block.items[0].blockHeader.number === firstAvailableBlock,
-        });
-        console.log(`Fetched Block '${firstAvailableBlock}' with size '${firstAvailableBlockResponse.message.block.items.length}' items`);
-        const getLastBlockRequestParams = {
-            tags: {name: 'get_last_block'},
+        for (let i = parseInt(firstAvailableBlock); i <= parseInt(lastAvailableBlock); i++) {
+            const getBlockRequestParams = {
+                tags: {name: 'get_block'},
+            }
+            const blockResponse = new GetBlockRequest(client).invoke(i, getBlockRequestParams);
+            try {
+                check(blockResponse, {
+                    'block fetch status is OK': (r) => r && r.status === StatusOK,
+                    'fetched block number is correct': (r) => r && parseInt(r.message.block.items[0].blockHeader.number) === i,
+                });
+            } catch (e) {
+                console.log(`error fetching block: ${i}\nresponse: ${JSON.stringify(blockResponse)}`)
+            }
+            // Sleep just for a tiny bit, it seems networking with k6 is not always fast enough and we do see
+            // some errors when fetching blocks, sometimes no data is received at all.
+            await new Promise(r => setTimeout(r, 50));
         }
-        const lastAvailableBlockResponse = new GetBlockRequest(client).invoke(lastAvailableBlock, getLastBlockRequestParams);
-        check(lastAvailableBlockResponse, {
-            'block fetch status is OK': (r) => r && r.status === StatusOK,
-            'fetched block number is correct': (r) => r && r.message.block.items[0].blockHeader.number === lastAvailableBlock,
-        });
-        console.log(`Fetched Block '${lastAvailableBlock}' with size '${lastAvailableBlockResponse.message.block.items.length}' items`);
+        sleep(1)
     }
     client.close();
     sleep(1);