From 9d42348937f2f0a44a15078e0a5be205ea69eed6 Mon Sep 17 00:00:00 2001 From: Maru Newby Date: Sat, 12 Oct 2024 12:10:15 -0700 Subject: [PATCH 01/22] [testing] Switch to logging with zap --- tests/antithesis/init_db.go | 3 +- tests/e2e/banff/suites.go | 22 +- tests/e2e/c/dynamic_fees.go | 15 +- tests/e2e/etna/suites.go | 11 +- tests/e2e/p/l1.go | 7 +- tests/e2e/p/staking_rewards.go | 17 +- tests/e2e/p/validator_sets.go | 5 +- tests/e2e/p/workflow.go | 25 +- tests/e2e/vms/xsvm.go | 25 +- tests/e2e/x/transfer/virtuous.go | 56 ++--- .../fixture/bootstrapmonitor/e2e/e2e_test.go | 43 ++-- tests/fixture/e2e/env.go | 24 +- tests/fixture/e2e/ginkgo_test_context.go | 47 ++-- tests/fixture/e2e/helpers.go | 69 ++++-- tests/fixture/e2e/metrics_link.go | 5 +- tests/fixture/tmpnet/cmd/main.go | 28 ++- tests/fixture/tmpnet/kube.go | 8 +- tests/fixture/tmpnet/network.go | 227 +++++++++--------- tests/fixture/tmpnet/network_test.go | 4 +- tests/fixture/tmpnet/node.go | 7 +- tests/fixture/tmpnet/node_process.go | 38 ++- tests/fixture/tmpnet/subnet.go | 52 ++-- tests/lib/utils.go | 19 ++ tests/log.go | 39 +++ tests/simple_test_context.go | 15 +- tests/test_context.go | 9 +- tests/upgrade/upgrade_test.go | 2 +- 27 files changed, 489 insertions(+), 333 deletions(-) create mode 100644 tests/lib/utils.go create mode 100644 tests/log.go diff --git a/tests/antithesis/init_db.go b/tests/antithesis/init_db.go index 3d6cf5f58992..7da69082d805 100644 --- a/tests/antithesis/init_db.go +++ b/tests/antithesis/init_db.go @@ -11,6 +11,7 @@ import ( "path/filepath" "time" + "github.com/ava-labs/avalanchego/tests" "github.com/ava-labs/avalanchego/tests/fixture/tmpnet" "github.com/ava-labs/avalanchego/utils/perms" ) @@ -32,7 +33,7 @@ func initBootstrapDB(network *tmpnet.Network, avalancheGoPath string, pluginDir defer cancel() if err := tmpnet.BootstrapNewNetwork( ctx, - os.Stdout, + tests.NewDefaultTestLogger(), network, "", avalancheGoPath, diff --git a/tests/e2e/banff/suites.go b/tests/e2e/banff/suites.go index cb68ca877c28..4cc3700cfc4f 100644 --- a/tests/e2e/banff/suites.go +++ b/tests/e2e/banff/suites.go @@ -44,7 +44,7 @@ var _ = ginkgo.Describe("[Banff]", func() { var assetID ids.ID tc.By("create new X-chain asset", func() { - assetTx, err := xWallet.IssueCreateAssetTx( + tx, err := xWallet.IssueCreateAssetTx( "RnM", "RNM", 9, @@ -59,13 +59,11 @@ var _ = ginkgo.Describe("[Banff]", func() { tc.WithDefaultContext(), ) require.NoError(err) - assetID = assetTx.ID() - - tc.Outf("{{green}}created new X-chain asset{{/}}: %s\n", assetID) + assetID = tx.ID() }) tc.By("export new X-chain asset to P-chain", func() { - tx, err := xWallet.IssueExportTx( + _, err := xWallet.IssueExportTx( constants.PlatformChainID, []*avax.TransferableOutput{ { @@ -81,23 +79,19 @@ var _ = ginkgo.Describe("[Banff]", func() { tc.WithDefaultContext(), ) require.NoError(err) - - tc.Outf("{{green}}issued X-chain export{{/}}: %s\n", tx.ID()) }) tc.By("import new asset from X-chain on the P-chain", func() { - tx, err := pWallet.IssueImportTx( + _, err := pWallet.IssueImportTx( xChainID, owner, tc.WithDefaultContext(), ) require.NoError(err) - - tc.Outf("{{green}}issued P-chain import{{/}}: %s\n", tx.ID()) }) tc.By("export asset from P-chain to the X-chain", func() { - tx, err := pWallet.IssueExportTx( + _, err := pWallet.IssueExportTx( xChainID, []*avax.TransferableOutput{ { @@ -113,19 +107,15 @@ var _ = ginkgo.Describe("[Banff]", func() { tc.WithDefaultContext(), ) require.NoError(err) - - tc.Outf("{{green}}issued P-chain export{{/}}: %s\n", tx.ID()) }) tc.By("import asset from P-chain on the X-chain", func() { - tx, err := xWallet.IssueImportTx( + _, err := xWallet.IssueImportTx( constants.PlatformChainID, owner, tc.WithDefaultContext(), ) require.NoError(err) - - tc.Outf("{{green}}issued X-chain import{{/}}: %s\n", tx.ID()) }) _ = e2e.CheckBootstrapIsPossible(tc, env.GetNetwork()) diff --git a/tests/e2e/c/dynamic_fees.go b/tests/e2e/c/dynamic_fees.go index 873b76f9a684..eede13eac7e0 100644 --- a/tests/e2e/c/dynamic_fees.go +++ b/tests/e2e/c/dynamic_fees.go @@ -14,6 +14,7 @@ import ( "github.com/ethereum/go-ethereum/common" "github.com/onsi/ginkgo/v2" "github.com/stretchr/testify/require" + "go.uber.org/zap" "github.com/ava-labs/avalanchego/tests/fixture/e2e" "github.com/ava-labs/avalanchego/tests/fixture/tmpnet" @@ -105,10 +106,13 @@ var _ = e2e.DescribeCChain("[Dynamic Fees]", func() { require.NoError(err) if initialGasPrice == nil { initialGasPrice = gasPrice - tc.Outf("{{blue}}initial gas price is %v{{/}}\n", initialGasPrice) + tc.Log().Info("initial gas price", + zap.Uint64("price", initialGasPrice.Uint64()), + ) } else if gasPrice.Cmp(initialGasPrice) > 0 { - // Gas price has increased - tc.Outf("{{blue}}gas price has increased to %v{{/}}\n", gasPrice) + tc.Log().Info("gas price has increased", + zap.Uint64("price", gasPrice.Uint64()), + ) return true } @@ -139,10 +143,11 @@ var _ = e2e.DescribeCChain("[Dynamic Fees]", func() { var err error gasPrice, err = ethClient.SuggestGasPrice(tc.DefaultContext()) require.NoError(err) - tc.Outf("{{blue}}.{{/}}") return initialGasPrice.Cmp(gasPrice) > 0 }, e2e.DefaultTimeout, e2e.DefaultPollingInterval, "failed to see gas price decrease before timeout") - tc.Outf("\n{{blue}}gas price has decreased to %v{{/}}\n", gasPrice) + tc.Log().Info("gas price has decreased", + zap.Uint64("price", gasPrice.Uint64()), + ) }) tc.By("sending funds at the current gas price", func() { diff --git a/tests/e2e/etna/suites.go b/tests/e2e/etna/suites.go index 60ecd0ff6252..703249e0abdd 100644 --- a/tests/e2e/etna/suites.go +++ b/tests/e2e/etna/suites.go @@ -9,6 +9,7 @@ import ( "github.com/onsi/ginkgo/v2" "github.com/stretchr/testify/require" + "go.uber.org/zap" "github.com/ava-labs/avalanchego/api/info" "github.com/ava-labs/avalanchego/tests/fixture/e2e" @@ -28,11 +29,13 @@ var _ = ginkgo.Describe("[Etna]", func() { require.NoError(err) now := time.Now() + msg := "etna is activated" if !upgrades.IsEtnaActivated(now) { - tc.Outf("{{green}}Etna is not activated{{/}}: %s (now) < %s (EtnaTime)\n", now, upgrades.EtnaTime) - return + msg = "etna is not activated" } - - tc.Outf("{{green}}Etna is activated{{/}}: %s (now) >= %s (EtnaTime)\n", now, upgrades.EtnaTime) + tc.Log().Info(msg, + zap.Time("now", now), + zap.Time("etnaTime", upgrades.EtnaTime), + ) }) }) diff --git a/tests/e2e/p/l1.go b/tests/e2e/p/l1.go index 5a2783a0aef6..6bc5ec079857 100644 --- a/tests/e2e/p/l1.go +++ b/tests/e2e/p/l1.go @@ -13,6 +13,7 @@ import ( "github.com/onsi/ginkgo/v2" "github.com/prometheus/client_golang/prometheus" "github.com/stretchr/testify/require" + "go.uber.org/zap" "google.golang.org/protobuf/proto" "github.com/ava-labs/avalanchego/api/info" @@ -203,7 +204,11 @@ var _ = e2e.DescribePChain("[L1]", func() { subnetGenesisNode.StakingAddress, networkID, router.InboundHandlerFunc(func(_ context.Context, m p2pmessage.InboundMessage) { - tc.Outf("received %s %s from %s\n", m.Op(), m.Message(), m.NodeID()) + tc.Log().Info("received a message", + zap.Stringer("op", m.Op()), + zap.Stringer("message", m.Message()), + zap.Stringer("from", m.NodeID()), + ) genesisPeerMessages.PushRight(m) }), ) diff --git a/tests/e2e/p/staking_rewards.go b/tests/e2e/p/staking_rewards.go index 29545450ddbc..4837a6f46306 100644 --- a/tests/e2e/p/staking_rewards.go +++ b/tests/e2e/p/staking_rewards.go @@ -10,6 +10,7 @@ import ( "github.com/onsi/ginkgo/v2" "github.com/spf13/cast" "github.com/stretchr/testify/require" + "go.uber.org/zap" "github.com/ava-labs/avalanchego/api/admin" "github.com/ava-labs/avalanchego/api/info" @@ -114,7 +115,9 @@ var _ = ginkgo.Describe("[Staking Rewards]", func() { e2e.OutputWalletBalances(tc, baseWallet) endTime := time.Now().Add(targetValidationPeriod) - tc.Outf("validation period ending at: %v\n", endTime) + tc.Log().Info("determined alpha node validation end time", + zap.Time("time", endTime), + ) _, err := pWallet.IssueAddPermissionlessValidatorTx( &txs.SubnetValidator{ @@ -142,7 +145,9 @@ var _ = ginkgo.Describe("[Staking Rewards]", func() { }) betaValidatorEndTime := time.Now().Add(targetValidationPeriod) - tc.Outf("beta node validation period ending at: %v\n", betaValidatorEndTime) + tc.Log().Info("determined beta node validation end time", + zap.Time("time", betaValidatorEndTime), + ) tc.By("adding beta node as a validator", func() { e2e.OutputWalletBalances(tc, baseWallet) @@ -180,7 +185,9 @@ var _ = ginkgo.Describe("[Staking Rewards]", func() { e2e.OutputWalletBalances(tc, baseWallet) endTime := time.Now().Add(targetDelegationPeriod) - tc.Outf("delegation period ending at: %v\n", endTime) + tc.Log().Info("determined gamma delegator validation end", + zap.Time("time", endTime), + ) _, err := pWallet.IssueAddPermissionlessDelegatorTx( &txs.SubnetValidator{ @@ -205,7 +212,9 @@ var _ = ginkgo.Describe("[Staking Rewards]", func() { e2e.OutputWalletBalances(tc, baseWallet) endTime := time.Now().Add(targetDelegationPeriod) - tc.Outf("delegation period ending at: %v\n", endTime) + tc.Log().Info("determined delta delegator delegation period end time", + zap.Time("time", endTime), + ) _, err := pWallet.IssueAddPermissionlessDelegatorTx( &txs.SubnetValidator{ diff --git a/tests/e2e/p/validator_sets.go b/tests/e2e/p/validator_sets.go index 7be620cc8716..ee81dda8fda4 100644 --- a/tests/e2e/p/validator_sets.go +++ b/tests/e2e/p/validator_sets.go @@ -9,6 +9,7 @@ import ( "github.com/onsi/ginkgo/v2" "github.com/stretchr/testify/require" + "go.uber.org/zap" "github.com/ava-labs/avalanchego/genesis" "github.com/ava-labs/avalanchego/ids" @@ -97,7 +98,9 @@ var _ = e2e.DescribePChain("[Validator Sets]", func() { } for height := uint64(0); height <= currentPChainHeight; height++ { - tc.Outf(" checked validator sets for height %d\n", height) + tc.Log().Info("checked validator sets", + zap.Uint64("height", height), + ) var observedValidatorSet map[ids.NodeID]*validators.GetValidatorOutput for _, pvmClient := range pvmClients { validatorSet, err := pvmClient.GetValidatorsAt( diff --git a/tests/e2e/p/workflow.go b/tests/e2e/p/workflow.go index ae21bae227dc..38f109e1fa98 100644 --- a/tests/e2e/p/workflow.go +++ b/tests/e2e/p/workflow.go @@ -8,6 +8,7 @@ import ( "github.com/onsi/ginkgo/v2" "github.com/stretchr/testify/require" + "go.uber.org/zap" "github.com/ava-labs/avalanchego/ids" "github.com/ava-labs/avalanchego/tests/fixture/e2e" @@ -87,15 +88,17 @@ var _ = e2e.DescribePChain("[Workflow]", func() { avaxAssetID = pContext.AVAXAssetID ) - tc.Outf("{{blue}} fetching minimal stake amounts {{/}}\n") + tc.Log().Info("fetching minimal stake amounts") pChainClient := platformvm.NewClient(nodeURI.URI) minValStake, minDelStake, err := pChainClient.GetMinStake( tc.DefaultContext(), constants.PlatformChainID, ) require.NoError(err) - tc.Outf("{{green}} minimal validator stake: %d {{/}}\n", minValStake) - tc.Outf("{{green}} minimal delegator stake: %d {{/}}\n", minDelStake) + tc.Log().Info("fetched minimal stake amounts", + zap.Uint64("minValidatorStake", minValStake), + zap.Uint64("minDelegatorStake", minDelStake), + ) // Use a random node ID to ensure that repeated test runs will succeed // against a network that persists across runs. @@ -145,7 +148,9 @@ var _ = e2e.DescribePChain("[Workflow]", func() { require.NoError(err) initialAVAXBalance := balances[avaxAssetID] - tc.Outf("{{blue}} P-chain balance before P->X export: %d {{/}}\n", initialAVAXBalance) + tc.Log().Info("retrieved P-chain balance before P->X export", + zap.Uint64("balance", initialAVAXBalance), + ) exportTx, err := pWallet.IssueExportTx( xContext.BlockchainID, @@ -172,7 +177,9 @@ var _ = e2e.DescribePChain("[Workflow]", func() { require.NoError(err) finalAVAXBalance := balances[avaxAssetID] - tc.Outf("{{blue}} P-chain balance after P->X export: %d {{/}}\n", finalAVAXBalance) + tc.Log().Info("retrieved P-chain balance after P->X export", + zap.Uint64("balance", finalAVAXBalance), + ) require.Equal(initialAVAXBalance-toTransfer-exportFee, finalAVAXBalance) }) @@ -182,7 +189,9 @@ var _ = e2e.DescribePChain("[Workflow]", func() { require.NoError(err) initialAVAXBalance := balances[avaxAssetID] - tc.Outf("{{blue}} X-chain balance before P->X import: %d {{/}}\n", initialAVAXBalance) + tc.Log().Info("retrieved X-chain balance before P->X import", + zap.Uint64("balance", initialAVAXBalance), + ) _, err = xWallet.IssueImportTx( constants.PlatformChainID, @@ -196,7 +205,9 @@ var _ = e2e.DescribePChain("[Workflow]", func() { require.NoError(err) finalAVAXBalance := balances[avaxAssetID] - tc.Outf("{{blue}} X-chain balance after P->X import: %d {{/}}\n", finalAVAXBalance) + tc.Log().Info("retrieved X-chain balance after P->X import", + zap.Uint64("balance", finalAVAXBalance), + ) require.Equal(initialAVAXBalance+toTransfer-xContext.BaseTxFee, finalAVAXBalance) }) diff --git a/tests/e2e/vms/xsvm.go b/tests/e2e/vms/xsvm.go index bb0e3d81809e..5f3b08fa2d90 100644 --- a/tests/e2e/vms/xsvm.go +++ b/tests/e2e/vms/xsvm.go @@ -9,6 +9,7 @@ import ( "github.com/onsi/ginkgo/v2" "github.com/stretchr/testify/require" + "go.uber.org/zap" "github.com/ava-labs/avalanchego/ids" "github.com/ava-labs/avalanchego/tests/fixture/e2e" @@ -66,12 +67,20 @@ var _ = ginkgo.Describe("[XSVM]", func() { sourceValidators := getNodesForIDs(network.Nodes, sourceSubnet.ValidatorIDs) require.NotEmpty(sourceValidators) sourceAPINode := sourceValidators[0] - tc.Outf(" issuing transactions for source subnet on %s (%s)\n", sourceAPINode.NodeID, sourceAPINode.URI) + tc.Log().Info("issuing transactions for source subnet", + zap.String("subnetName", subnetAName), + zap.Stringer("nodeID", sourceAPINode.NodeID), + zap.String("nodeURI", sourceAPINode.URI), + ) destinationValidators := getNodesForIDs(network.Nodes, destinationSubnet.ValidatorIDs) require.NotEmpty(destinationValidators) destinationAPINode := destinationValidators[0] - tc.Outf(" issuing transactions for destination subnet on %s (%s)\n", destinationAPINode.NodeID, destinationAPINode.URI) + tc.Log().Info("issuing transactions for destination subnet", + zap.String("subnetName", subnetBName), + zap.Stringer("nodeID", destinationAPINode.NodeID), + zap.String("nodeURI", destinationAPINode.URI), + ) destinationKey := e2e.NewPrivateKey(tc) @@ -98,7 +107,9 @@ var _ = ginkgo.Describe("[XSVM]", func() { }, ) require.NoError(err) - tc.Outf(" issued transaction with ID: %s\n", exportTxStatus.TxID) + tc.Log().Info("issued export transaction", + zap.Stringer("txID", exportTxStatus.TxID), + ) tc.By("checking that the export transaction has been accepted on all nodes") for _, node := range sourceValidators[1:] { @@ -126,7 +137,9 @@ var _ = ginkgo.Describe("[XSVM]", func() { }, ) require.NoError(err) - tc.Outf(" issued transaction with ID: %s\n", transferTxStatus.TxID) + tc.Log().Info("issued transfer", + zap.Stringer("txID", transferTxStatus.TxID), + ) tc.By(fmt.Sprintf("importing to blockchain %s on subnet %s", destinationChain.ChainID, destinationSubnet.SubnetID)) sourceURIs := make([]string, len(sourceValidators)) @@ -145,7 +158,9 @@ var _ = ginkgo.Describe("[XSVM]", func() { }, ) require.NoError(err) - tc.Outf(" issued transaction with ID: %s\n", importTxStatus.TxID) + tc.Log().Info("issued import transaction", + zap.Stringer("txID", importTxStatus.TxID), + ) tc.By("checking that the balance of the source key has decreased") sourceBalance, err := sourceClient.Balance(tc.DefaultContext(), sourceChain.PreFundedKey.Address(), sourceChain.ChainID) diff --git a/tests/e2e/x/transfer/virtuous.go b/tests/e2e/x/transfer/virtuous.go index 337e2aeed2f5..12e2c7ea4514 100644 --- a/tests/e2e/x/transfer/virtuous.go +++ b/tests/e2e/x/transfer/virtuous.go @@ -5,13 +5,13 @@ package transfer import ( - "fmt" "math/rand" "time" "github.com/onsi/ginkgo/v2" "github.com/prometheus/client_golang/prometheus" "github.com/stretchr/testify/require" + "go.uber.org/zap" "github.com/ava-labs/avalanchego/chains" "github.com/ava-labs/avalanchego/ids" @@ -116,7 +116,9 @@ var _ = e2e.DescribeXChainSerial("[Virtuous Transfer Tx AVAX]", func() { require.NoError(err) runFunc := func(round int) { - tc.Outf("{{green}}\n\n\n\n\n\n---\n[ROUND #%02d]:{{/}}\n", round) + tc.Log().Info("starting new round", + zap.Int("round", round), + ) needPermute := round > 3 if needPermute { @@ -153,7 +155,11 @@ var _ = e2e.DescribeXChainSerial("[Virtuous Transfer Tx AVAX]", func() { require.NoError(err) for _, uri := range rpcEps { for _, metric := range []string{blksProcessingMetric, blksAcceptedMetric} { - tc.Outf("{{green}}%s at %q:{{/}} %v\n", metric, uri, metricsBeforeTx[uri][metric]) + tc.Log().Info("metric before tx", + zap.String("metric", metric), + zap.String("uri", uri), + zap.Any("value", metricsBeforeTx[uri][metric]), + ) } } @@ -165,10 +171,9 @@ var _ = e2e.DescribeXChainSerial("[Virtuous Transfer Tx AVAX]", func() { bal := balances[avaxAssetID] testBalances = append(testBalances, bal) - fmt.Printf(`CURRENT BALANCE %21d AVAX (SHORT ADDRESS %q) -`, - bal, - testKeys[i].PublicKey().Address(), + tc.Log().Info("balance in AVAX", + zap.Uint64("balance", bal), + zap.Stringer("address", testKeys[i].PublicKey().Address()), ) } fromIdx := -1 @@ -218,27 +223,14 @@ var _ = e2e.DescribeXChainSerial("[Virtuous Transfer Tx AVAX]", func() { require.Contains(err.Error(), "insufficient funds") }) - fmt.Printf(`=== -TRANSFERRING - -FROM [%q] -SENDER CURRENT BALANCE : %21d AVAX -SENDER NEW BALANCE (AFTER) : %21d AVAX - -TRANSFER AMOUNT FROM SENDER : %21d AVAX - -TO [%q] -RECEIVER CURRENT BALANCE : %21d AVAX -RECEIVER NEW BALANCE (AFTER) : %21d AVAX -=== -`, - shortAddrs[fromIdx], - senderOrigBal, - senderNewBal, - amountToTransfer, - shortAddrs[toIdx], - receiverOrigBal, - receiverNewBal, + tc.Log().Info("transfering", + zap.Stringer("fromAddress", shortAddrs[fromIdx]), + zap.Uint64("senderOrigBal", senderOrigBal), + zap.Uint64("senderNewBal", senderNewBal), + zap.Uint64("amountToTransfer", amountToTransfer), + zap.Stringer("toAddress", shortAddrs[toIdx]), + zap.Uint64("receiverOrigBal", receiverOrigBal), + zap.Uint64("receiverNewBal", receiverNewBal), ) tx, err := wallets[fromIdx].X().IssueBaseTx( @@ -261,12 +253,16 @@ RECEIVER NEW BALANCE (AFTER) : %21d AVAX balances, err := wallets[fromIdx].X().Builder().GetFTBalance() require.NoError(err) senderCurBalX := balances[avaxAssetID] - tc.Outf("{{green}}first wallet balance:{{/}} %d\n", senderCurBalX) + tc.Log().Info("first wallet balance", + zap.Uint64("balance", senderCurBalX), + ) balances, err = wallets[toIdx].X().Builder().GetFTBalance() require.NoError(err) receiverCurBalX := balances[avaxAssetID] - tc.Outf("{{green}}second wallet balance:{{/}} %d\n", receiverCurBalX) + tc.Log().Info("second wallet balance", + zap.Uint64("balance", receiverCurBalX), + ) require.Equal(senderCurBalX, senderNewBal) require.Equal(receiverCurBalX, receiverNewBal) diff --git a/tests/fixture/bootstrapmonitor/e2e/e2e_test.go b/tests/fixture/bootstrapmonitor/e2e/e2e_test.go index 512dffbd3162..199046940339 100644 --- a/tests/fixture/bootstrapmonitor/e2e/e2e_test.go +++ b/tests/fixture/bootstrapmonitor/e2e/e2e_test.go @@ -15,6 +15,7 @@ import ( "github.com/onsi/ginkgo/v2" "github.com/stretchr/testify/require" + "go.uber.org/zap" "k8s.io/client-go/kubernetes" "k8s.io/client-go/tools/clientcmd" @@ -89,14 +90,14 @@ var _ = ginkgo.Describe("[Bootstrap Tester]", func() { require := require.New(tc) if skipAvalanchegoImageBuild { - tc.Outf("{{yellow}}skipping build of avalanchego image{{/}}\n") + tc.Log().Warn("skipping build of avalanchego image") } else { ginkgo.By("Building the avalanchego image") buildAvalanchegoImage(tc, avalanchegoImage, false /* forceNewHash */) } if skipMonitorImageBuild { - tc.Outf("{{yellow}}skipping build of bootstrap-monitor image{{/}}\n") + tc.Log().Info("skipping build of bootstrap-monitor image") } else { ginkgo.By("Building the bootstrap-monitor image") buildImage(tc, monitorImage, false /* forceNewHash */, "build_bootstrap_monitor_image.sh") @@ -142,7 +143,12 @@ var _ = ginkgo.Describe("[Bootstrap Tester]", func() { require.Eventually(func() bool { testConfig, err := bootstrapmonitor.GetBootstrapTestConfigFromPod(tc.DefaultContext(), clientset, namespace, bootstrapPodName, nodeContainerName) if err != nil { - tc.Outf("Error determining image used by the %q container of pod %s.%s: %v \n", nodeContainerName, namespace, bootstrapPodName, err) + tc.Log().Debug("failed to determine image used by the pod container", + zap.String("container", nodeContainerName), + zap.String("namespace", namespace), + zap.String("pod", bootstrapPodName), + zap.Error(err), + ) return false } if !strings.Contains(testConfig.Image, "sha256") { @@ -177,7 +183,11 @@ var _ = ginkgo.Describe("[Bootstrap Tester]", func() { return false } if err != nil { - tc.Outf("Error getting pod %s.%s: %v\n", namespace, bootstrapPodName, err) + tc.Log().Debug("failed to retrieve pod", + zap.String("namespace", namespace), + zap.String("pod", bootstrapPodName), + zap.Error(err), + ) return false } return pod.UID != podUID @@ -193,7 +203,12 @@ var _ = ginkgo.Describe("[Bootstrap Tester]", func() { require.Eventually(func() bool { testConfig, err := bootstrapmonitor.GetBootstrapTestConfigFromPod(tc.DefaultContext(), clientset, namespace, bootstrapPodName, nodeContainerName) if err != nil { - tc.Outf("Error determining image used by the %q container of pod %s.%s: %v \n", nodeContainerName, namespace, bootstrapPodName, err) + tc.Log().Debug("failed to determine image used by the pod container", + zap.String("container", nodeContainerName), + zap.String("namespace", namespace), + zap.String("pod", bootstrapPodName), + zap.Error(err), + ) return false } if testConfig.Image != containerImage { @@ -279,7 +294,7 @@ func waitForPodCondition(tc tests.TestContext, clientset *kubernetes.Clientset, func waitForNodeHealthy(tc tests.TestContext, kubeconfig *restclient.Config, namespace string, podName string) ids.NodeID { nodeID, err := tmpnet.WaitForNodeHealthy( tc.DefaultContext(), - tc.Outf, + tc.Log(), kubeconfig, namespace, podName, @@ -421,9 +436,12 @@ func grantMonitorPermissions(tc tests.TestContext, clientset *kubernetes.Clients func waitForLogOutput(tc tests.TestContext, clientset *kubernetes.Clientset, namespace string, podName string, containerName string, desiredOutput string) { // TODO(marun) Figure out why log output is randomly truncated (not flushed?) - outputLogLine(tc, fmt.Sprintf( - "Logs from: %q container of pod %s.%s (may not be complete)", containerName, namespace, podName)) - outputLogLine(tc, strings.Repeat("=", 80)) + tc.Log().Info("log output from container (may not be complete)", + zap.String("namespace", namespace), + zap.String("pod", podName), + zap.String("container", containerName), + ) + tc.Log().Info(strings.Repeat("=", 80)) req := clientset.CoreV1().Pods(namespace).GetLogs(podName, &corev1.PodLogOptions{ Container: containerName, @@ -437,14 +455,9 @@ func waitForLogOutput(tc tests.TestContext, clientset *kubernetes.Clientset, nam scanner := bufio.NewScanner(readCloser) for scanner.Scan() { line := scanner.Text() - outputLogLine(tc, line) + tc.Log().Info(line) if len(desiredOutput) > 0 && strings.Contains(line, desiredOutput) { return } } } - -// outputLogLine outputs logs in a consistent color -func outputLogLine(tc tests.TestContext, line string) { - tc.Outf("{{light-gray}}%s{{/}}\n", line) -} diff --git a/tests/fixture/e2e/env.go b/tests/fixture/e2e/env.go index 1dac79b8d29a..7fd99896199e 100644 --- a/tests/fixture/e2e/env.go +++ b/tests/fixture/e2e/env.go @@ -12,6 +12,7 @@ import ( "github.com/onsi/ginkgo/v2" "github.com/stretchr/testify/require" + "go.uber.org/zap" "github.com/ava-labs/avalanchego/api/info" "github.com/ava-labs/avalanchego/config" @@ -102,27 +103,31 @@ func NewTestEnvironment(tc tests.TestContext, flagVars *FlagVars, desiredNetwork var err error network, err = tmpnet.ReadNetwork(networkDir) require.NoError(err) - tc.Outf("{{yellow}}Loaded a network configured at %s{{/}}\n", network.Dir) + tc.Log().Info("loaded a network", + zap.String("networkDir", networkDir), + ) } if flagVars.StopNetwork() { if len(networkSymlink) > 0 { // Remove the symlink to avoid attempts to reuse the stopped network - tc.Outf("Removing symlink %s\n", networkSymlink) + tc.Log().Info("removing symlink", + zap.String("path", networkSymlink), + ) if err := os.Remove(networkSymlink); !errors.Is(err, os.ErrNotExist) { require.NoError(err) } } if network != nil { - tc.Outf("Stopping network\n") + tc.Log().Info("stopping network") require.NoError(network.Stop(tc.DefaultContext())) } else { - tc.Outf("No network to stop\n") + tc.Log().Info("no network to stop") } os.Exit(0) } else if network != nil && flagVars.RestartNetwork() { // A network is only restarted if it is already running and stop was not requested - require.NoError(network.Restart(tc.DefaultContext(), tc.GetWriter())) + require.NoError(network.Restart(tc.DefaultContext(), tc.Log())) } } @@ -172,7 +177,9 @@ func NewTestEnvironment(tc tests.TestContext, flagVars *FlagVars, desiredNetwork uris := network.GetNodeURIs() require.NotEmpty(uris, "network contains no nodes") - tc.Outf("{{green}}network URIs: {{/}} %+v\n", uris) + tc.Log().Info("network nodes are available", + zap.Any("uris", uris), + ) return &TestEnvironment{ NetworkDir: network.Dir, @@ -187,7 +194,10 @@ func NewTestEnvironment(tc tests.TestContext, flagVars *FlagVars, desiredNetwork func (te *TestEnvironment) GetRandomNodeURI() tmpnet.NodeURI { r := rand.New(rand.NewSource(time.Now().Unix())) //#nosec G404 nodeURI := te.URIs[r.Intn(len(te.URIs))] - te.testContext.Outf("{{blue}} targeting node %s with URI: %s{{/}}\n", nodeURI.NodeID, nodeURI.URI) + te.testContext.Log().Info("targeting random node", + zap.Stringer("nodeID", nodeURI.NodeID), + zap.String("uri", nodeURI.URI), + ) return nodeURI } diff --git a/tests/fixture/e2e/ginkgo_test_context.go b/tests/fixture/e2e/ginkgo_test_context.go index 912c144db3e1..eae87c1faca9 100644 --- a/tests/fixture/e2e/ginkgo_test_context.go +++ b/tests/fixture/e2e/ginkgo_test_context.go @@ -5,21 +5,36 @@ package e2e import ( "context" - "io" "time" "github.com/onsi/ginkgo/v2" - "github.com/onsi/ginkgo/v2/formatter" "github.com/stretchr/testify/require" "github.com/ava-labs/avalanchego/tests" + "github.com/ava-labs/avalanchego/utils/logging" "github.com/ava-labs/avalanchego/wallet/subnet/primary/common" ) -type GinkgoTestContext struct{} +type ginkgoWriteCloser struct{} + +func (*ginkgoWriteCloser) Write(p []byte) (n int, err error) { + // Add a leading space to better differentiate from other ginkgo output + _, _ = ginkgo.GinkgoWriter.Write([]byte(" ")) + return ginkgo.GinkgoWriter.Write(p) +} + +func (*ginkgoWriteCloser) Close() error { + return nil +} + +type GinkgoTestContext struct { + logger logging.Logger +} func NewTestContext() *GinkgoTestContext { - return &GinkgoTestContext{} + return &GinkgoTestContext{ + logger: tests.NewTestLogger(&ginkgoWriteCloser{}), + } } func (*GinkgoTestContext) Errorf(format string, args ...interface{}) { @@ -30,8 +45,8 @@ func (*GinkgoTestContext) FailNow() { ginkgo.GinkgoT().FailNow() } -func (*GinkgoTestContext) GetWriter() io.Writer { - return ginkgo.GinkgoWriter +func (tc *GinkgoTestContext) Log() logging.Logger { + return tc.logger } func (*GinkgoTestContext) Cleanup() { @@ -46,26 +61,6 @@ func (*GinkgoTestContext) By(text string, callback ...func()) { ginkgo.By(text, callback...) } -// Outputs to stdout. -// -// Examples: -// -// - Out("{{green}}{{bold}}hi there %q{{/}}", "aa") -// - Out("{{magenta}}{{bold}}hi therea{{/}} {{cyan}}{{underline}}b{{/}}") -// -// See https://github.com/onsi/ginkgo/blob/v2.0.0/formatter/formatter.go#L52-L73 -// for an exhaustive list of color options. -func (*GinkgoTestContext) Outf(format string, args ...interface{}) { - s := formatter.F(format, args...) - // Use GinkgoWriter to ensure that output from this function is - // printed sequentially within other test output produced with - // GinkgoWriter (e.g. `STEP:...`) when tests are run in - // parallel. ginkgo collects and writes stdout separately from - // GinkgoWriter during parallel execution and the resulting output - // can be confusing. - ginkgo.GinkgoWriter.Print(s) -} - // Helper simplifying use of a timed context by canceling the context on ginkgo teardown. func (tc *GinkgoTestContext) ContextWithTimeout(duration time.Duration) context.Context { return tests.ContextWithTimeout(tc, duration) diff --git a/tests/fixture/e2e/helpers.go b/tests/fixture/e2e/helpers.go index dcf68cb94657..02438633a267 100644 --- a/tests/fixture/e2e/helpers.go +++ b/tests/fixture/e2e/helpers.go @@ -16,6 +16,7 @@ import ( "github.com/ava-labs/coreth/ethclient" "github.com/ava-labs/coreth/interfaces" "github.com/stretchr/testify/require" + "go.uber.org/zap" "github.com/ava-labs/avalanchego/config" "github.com/ava-labs/avalanchego/ids" @@ -61,7 +62,10 @@ func NewPrivateKey(tc tests.TestContext) *secp256k1.PrivateKey { // Create a new wallet for the provided keychain against the specified node URI. func NewWallet(tc tests.TestContext, keychain *secp256k1fx.Keychain, nodeURI tmpnet.NodeURI) primary.Wallet { - tc.Outf("{{blue}} initializing a new wallet for node %s with URI: %s {{/}}\n", nodeURI.NodeID, nodeURI.URI) + tc.Log().Info("initializing a new wallet", + zap.Stringer("nodeID", nodeURI.NodeID), + zap.String("URI", nodeURI.URI), + ) baseWallet, err := primary.MakeWallet(tc.DefaultContext(), &primary.WalletConfig{ URI: nodeURI.URI, AVAXKeychain: keychain, @@ -72,19 +76,23 @@ func NewWallet(tc tests.TestContext, keychain *secp256k1fx.Keychain, nodeURI tmp baseWallet, common.WithPostIssuanceFunc( func(id ids.ID) { - tc.Outf(" issued transaction with ID: %s\n", id) + tc.Log().Info("issued transaction", + zap.Stringer("txID", id), + ) }, ), ) - xAVAX, pAVAX := GetWalletBalances(tc, wallet) - tc.Outf("{{blue}} wallet starting with %d X-chain nAVAX and %d P-chain nAVAX{{/}}\n", xAVAX, pAVAX) + OutputWalletBalances(tc, wallet) return wallet } // OutputWalletBalances outputs the X-Chain and P-Chain balances of the provided wallet. func OutputWalletBalances(tc tests.TestContext, wallet primary.Wallet) { xAVAX, pAVAX := GetWalletBalances(tc, wallet) - tc.Outf("{{blue}} wallet has %d X-chain nAVAX and %d P-chain nAVAX{{/}}\n", xAVAX, pAVAX) + tc.Log().Info("wallet balances in nAVAX", + zap.Uint64("xChain", xAVAX), + zap.Uint64("pChain", pAVAX), + ) } // GetWalletBalances retrieves the X-Chain and P-Chain balances of the provided wallet. @@ -111,7 +119,10 @@ func GetWalletBalances(tc tests.TestContext, wallet primary.Wallet) (uint64, uin // Create a new eth client targeting the specified node URI. func NewEthClient(tc tests.TestContext, nodeURI tmpnet.NodeURI) ethclient.Client { - tc.Outf("{{blue}} initializing a new eth client for node %s with URI: %s {{/}}\n", nodeURI.NodeID, nodeURI.URI) + tc.Log().Info("initializing a new eth client", + zap.Stringer("nodeID", nodeURI.NodeID), + zap.String("URI", nodeURI.URI), + ) nodeAddress := strings.Split(nodeURI.URI, "//")[1] uri := fmt.Sprintf("ws://%s/ext/bc/C/ws", nodeAddress) client, err := ethclient.Dial(uri) @@ -124,10 +135,12 @@ func AddEphemeralNode(tc tests.TestContext, network *tmpnet.Network, flags tmpne require := require.New(tc) node := tmpnet.NewEphemeralNode(flags) - require.NoError(network.StartNode(tc.DefaultContext(), tc.GetWriter(), node)) + require.NoError(network.StartNode(tc.DefaultContext(), tc.Log(), node)) tc.DeferCleanup(func() { - tc.Outf("shutting down ephemeral node %q\n", node.NodeID) + tc.Log().Info("shutting down ephemeral node", + zap.Stringer("nodeID", node.NodeID), + ) ctx, cancel := context.WithTimeout(context.Background(), DefaultTimeout) defer cancel() require.NoError(node.Stop(ctx)) @@ -149,7 +162,9 @@ func SendEthTransaction(tc tests.TestContext, ethClient ethclient.Client, signed require := require.New(tc) txID := signedTx.Hash() - tc.Outf(" sending eth transaction with ID: %s\n", txID) + tc.Log().Info("sending eth transaction", + zap.Stringer("txID", txID), + ) require.NoError(ethClient.SendTransaction(tc.DefaultContext(), signedTx)) @@ -193,7 +208,9 @@ func CheckBootstrapIsPossible(tc tests.TestContext, network *tmpnet.Network) *tm require := require.New(tc) if len(os.Getenv(SkipBootstrapChecksEnvName)) > 0 { - tc.Outf("{{yellow}}Skipping bootstrap check due to the %s env var being set", SkipBootstrapChecksEnvName) + tc.Log().Info("skipping bootstrap check due to env var being set", + zap.String("envVar", SkipBootstrapChecksEnvName), + ) return nil } tc.By("checking if bootstrap is possible with the current network state") @@ -208,7 +225,7 @@ func CheckBootstrapIsPossible(tc tests.TestContext, network *tmpnet.Network) *tm } node := tmpnet.NewEphemeralNode(flags) - require.NoError(network.StartNode(tc.DefaultContext(), tc.GetWriter(), node)) + require.NoError(network.StartNode(tc.DefaultContext(), tc.Log(), node)) // StartNode will initiate node stop if an error is encountered during start, // so no further cleanup effort is required if an error is seen here. @@ -249,7 +266,7 @@ func StartNetwork( err := tmpnet.BootstrapNewNetwork( tc.DefaultContext(), - tc.GetWriter(), + tc.Log(), network, DefaultNetworkDir, avalancheGoExecPath, @@ -258,13 +275,11 @@ func StartNetwork( if err != nil { // Ensure nodes are stopped if bootstrap fails. The network configuration // will remain on disk to enable troubleshooting. - if stopErr := network.Stop(tc.DefaultContext()); stopErr != nil { - tc.Outf("failed to stop network after bootstrap failure: %v", stopErr) - } - require.FailNowf("network bootstrapping failed", "network bootstrapping error: %s", err) + err := network.Stop(tc.DefaultContext()) + require.NoError(err, "network bootstrapping failed") } - tc.Outf("{{green}}Successfully started network{{/}}\n") + tc.Log().Info("network started successfully") symlinkPath, err := tmpnet.GetReusableNetworkPathForOwner(network.Owner) require.NoError(err) @@ -273,26 +288,36 @@ func StartNetwork( // Symlink the path of the created network to the default owner path (e.g. latest_avalanchego-e2e) // to enable easy discovery for reuse. require.NoError(os.Symlink(network.Dir, symlinkPath)) - tc.Outf("{{green}}Symlinked %s to %s to enable reuse{{/}}\n", network.Dir, symlinkPath) + tc.Log().Info("symlinked network dir for reuse", + zap.String("networkDir", network.Dir), + zap.String("symlinkPath", symlinkPath), + ) } tc.DeferCleanup(func() { if reuseNetwork { - tc.Outf("{{yellow}}Skipping shutdown for network %s (symlinked to %s) to enable reuse{{/}}\n", network.Dir, symlinkPath) + tc.Log().Info("skipping shutdown for network intended for reuse", + zap.String("networkDir", network.Dir), + zap.String("symlinkPath", symlinkPath), + ) return } if skipShutdown { - tc.Outf("{{yellow}}Skipping shutdown for network %s{{/}}\n", network.Dir) + tc.Log().Info("skipping shutdown for network", + zap.String("networkDir", network.Dir), + ) return } if shutdownDelay > 0 { - tc.Outf("Waiting %s before network shutdown to ensure final metrics scrape\n", shutdownDelay) + tc.Log().Info("delaying network shutdown to ensure final metrics scrape", + zap.Duration("delay", shutdownDelay), + ) time.Sleep(shutdownDelay) } - tc.Outf("Shutting down network\n") + tc.Log().Info("shutting down network") ctx, cancel := context.WithTimeout(context.Background(), DefaultTimeout) defer cancel() require.NoError(network.Stop(ctx)) diff --git a/tests/fixture/e2e/metrics_link.go b/tests/fixture/e2e/metrics_link.go index 5f20e3ff88c4..3fb796677404 100644 --- a/tests/fixture/e2e/metrics_link.go +++ b/tests/fixture/e2e/metrics_link.go @@ -8,6 +8,7 @@ import ( "time" "github.com/onsi/ginkgo/v2" + "go.uber.org/zap" "github.com/ava-labs/avalanchego/tests/fixture/tmpnet" ) @@ -54,5 +55,7 @@ var _ = ginkgo.AfterEach(func() { strconv.FormatInt(startTime, 10), strconv.FormatInt(endTime, 10), ) - tc.Outf("Test Metrics: %s\n", metricsLink) + tc.Log().Info("metrics and logs available via grafana (collectors must be running)", + zap.String("uri", metricsLink), + ) }) diff --git a/tests/fixture/tmpnet/cmd/main.go b/tests/fixture/tmpnet/cmd/main.go index d2b60682323b..11aaac263f38 100644 --- a/tests/fixture/tmpnet/cmd/main.go +++ b/tests/fixture/tmpnet/cmd/main.go @@ -13,9 +13,12 @@ import ( "time" "github.com/spf13/cobra" + "go.uber.org/zap" "github.com/ava-labs/avalanchego/tests/fixture/tmpnet" "github.com/ava-labs/avalanchego/version" + + testlib "github.com/ava-labs/avalanchego/tests/lib" ) const cliVersion = "0.0.1" @@ -26,12 +29,16 @@ var ( ) func main() { - var networkDir string + var ( + networkDir string + rawLogFormat string + ) rootCmd := &cobra.Command{ Use: "tmpnetctl", Short: "tmpnetctl commands", } rootCmd.PersistentFlags().StringVar(&networkDir, "network-dir", os.Getenv(tmpnet.NetworkDirEnvName), "The path to the configuration directory of a temporary network") + rootCmd.PersistentFlags().StringVar(&rawLogFormat, "log-format", "auto", "The structure of log format. Defaults to 'auto' which formats terminal-like logs, when the output is a terminal. Otherwise, should be one of {auto, plain, colors, json}") versionCmd := &cobra.Command{ Use: "version", @@ -62,6 +69,11 @@ func main() { return errAvalancheGoRequired } + log, err := testlib.LoggerForFormat(rawLogFormat) + if err != nil { + return err + } + // Root dir will be defaulted on start if not provided network := &tmpnet.Network{ @@ -74,15 +86,15 @@ func main() { ctx, cancel := context.WithTimeout(context.Background(), networkStartTimeout) defer cancel() - err := tmpnet.BootstrapNewNetwork( + if err := tmpnet.BootstrapNewNetwork( ctx, - os.Stdout, + log, network, rootDir, avalancheGoPath, pluginDir, - ) - if err != nil { + ); err != nil { + log.Error("failed to bootstrap network", zap.Error(err)) return err } @@ -137,9 +149,13 @@ func main() { if len(networkDir) == 0 { return errNetworkDirRequired } + log, err := testlib.LoggerForFormat(rawLogFormat) + if err != nil { + return err + } ctx, cancel := context.WithTimeout(context.Background(), tmpnet.DefaultNetworkTimeout) defer cancel() - return tmpnet.RestartNetwork(ctx, os.Stdout, networkDir) + return tmpnet.RestartNetwork(ctx, log, networkDir) }, } rootCmd.AddCommand(restartNetworkCmd) diff --git a/tests/fixture/tmpnet/kube.go b/tests/fixture/tmpnet/kube.go index 3bd93bc8bc92..244440ad6625 100644 --- a/tests/fixture/tmpnet/kube.go +++ b/tests/fixture/tmpnet/kube.go @@ -13,6 +13,7 @@ import ( "strings" "time" + "go.uber.org/zap" "k8s.io/apimachinery/pkg/api/resource" "k8s.io/apimachinery/pkg/util/intstr" "k8s.io/apimachinery/pkg/util/wait" @@ -147,8 +148,7 @@ func stringMapToEnvVarSlice(mapping map[string]string) []corev1.EnvVar { // WaitForNodeHealthy waits for the node running in the specified pod to report healthy. func WaitForNodeHealthy( ctx context.Context, - // TODO(marun) Use an actual logger - logFunc func(format string, args ...interface{}), + log logging.Logger, kubeconfig *restclient.Config, namespace string, podName string, @@ -183,7 +183,9 @@ func WaitForNodeHealthy( return false, err } else if err != nil { // Error is potentially recoverable - log and continue - logFunc("Error checking node health: %v", err) + log.Debug("failed to check node health", + zap.Error(err), + ) return false, nil } return healthReply.Healthy, nil diff --git a/tests/fixture/tmpnet/network.go b/tests/fixture/tmpnet/network.go index 2160c8ad072e..2e06c7281563 100644 --- a/tests/fixture/tmpnet/network.go +++ b/tests/fixture/tmpnet/network.go @@ -9,7 +9,6 @@ import ( "encoding/json" "errors" "fmt" - "io" "net/netip" "os" "os/exec" @@ -20,11 +19,13 @@ import ( "time" "github.com/google/uuid" + "go.uber.org/zap" "github.com/ava-labs/avalanchego/config" "github.com/ava-labs/avalanchego/genesis" "github.com/ava-labs/avalanchego/ids" "github.com/ava-labs/avalanchego/utils/crypto/secp256k1" + "github.com/ava-labs/avalanchego/utils/logging" "github.com/ava-labs/avalanchego/utils/perms" "github.com/ava-labs/avalanchego/utils/set" "github.com/ava-labs/avalanchego/vms/platformvm" @@ -135,7 +136,7 @@ func toCanonicalDir(dir string) (string, error) { func BootstrapNewNetwork( ctx context.Context, - w io.Writer, + log logging.Logger, network *Network, rootNetworkDir string, avalancheGoExecPath string, @@ -144,16 +145,16 @@ func BootstrapNewNetwork( if len(network.Nodes) == 0 { return errInsufficientNodes } - if err := checkVMBinaries(w, network.Subnets, avalancheGoExecPath, pluginDir); err != nil { + if err := checkVMBinaries(log, network.Subnets, avalancheGoExecPath, pluginDir); err != nil { return err } - if err := network.EnsureDefaultConfig(w, avalancheGoExecPath, pluginDir); err != nil { + if err := network.EnsureDefaultConfig(log, avalancheGoExecPath, pluginDir); err != nil { return err } if err := network.Create(rootNetworkDir); err != nil { return err } - return network.Bootstrap(ctx, w) + return network.Bootstrap(ctx, log) } // Stops the nodes of the network configured in the provided directory. @@ -166,12 +167,12 @@ func StopNetwork(ctx context.Context, dir string) error { } // Restarts the nodes of the network configured in the provided directory. -func RestartNetwork(ctx context.Context, w io.Writer, dir string) error { +func RestartNetwork(ctx context.Context, log logging.Logger, dir string) error { network, err := ReadNetwork(dir) if err != nil { return err } - return network.Restart(ctx, w) + return network.Restart(ctx, log) } // Reads a network from the provided directory. @@ -190,10 +191,10 @@ func ReadNetwork(dir string) (*Network, error) { } // Initializes a new network with default configuration. -func (n *Network) EnsureDefaultConfig(w io.Writer, avalancheGoPath string, pluginDir string) error { - if _, err := fmt.Fprintf(w, "Preparing configuration for new network with %s\n", avalancheGoPath); err != nil { - return err - } +func (n *Network) EnsureDefaultConfig(log logging.Logger, avalancheGoPath string, pluginDir string) error { + log.Info("preparing configuration for new network", + zap.String("avalanchegoPath", avalancheGoPath), + ) // A UUID supports centralized metrics collection if len(n.UUID) == 0 { @@ -336,7 +337,7 @@ func (n *Network) DefaultGenesis() (*genesis.UnparsedConfig, error) { } // Starts the specified nodes -func (n *Network) StartNodes(ctx context.Context, w io.Writer, nodesToStart ...*Node) error { +func (n *Network) StartNodes(ctx context.Context, log logging.Logger, nodesToStart ...*Node) error { if len(nodesToStart) == 0 { return errInsufficientNodes } @@ -349,9 +350,10 @@ func (n *Network) StartNodes(ctx context.Context, w io.Writer, nodesToStart ...* } else { // Simplify output by only logging network start when starting all nodes or when starting // the first node by itself to bootstrap subnet creation. - if _, err := fmt.Fprintf(w, "Starting network %s (UUID: %s)\n", n.Dir, n.UUID); err != nil { - return err - } + log.Info("starting network", + zap.String("networkDir", n.Dir), + zap.String("uuid", n.UUID), + ) } // Record the time before nodes are started to ensure visibility of subsequently collected metrics via the emitted link @@ -359,43 +361,43 @@ func (n *Network) StartNodes(ctx context.Context, w io.Writer, nodesToStart ...* // Configure the networking for each node and start for _, node := range nodesToStart { - if err := n.StartNode(ctx, w, node); err != nil { + if err := n.StartNode(ctx, log, node); err != nil { return err } } - if _, err := fmt.Fprint(w, "Waiting for nodes to report healthy...\n\n"); err != nil { - return err - } - if err := waitForHealthy(ctx, w, nodesToWaitFor); err != nil { + log.Info("waiting for nodes to report healthy") + if err := waitForHealthy(ctx, log, nodesToWaitFor); err != nil { return err } - if _, err := fmt.Fprintf(w, "\nStarted network %s (UUID: %s)\n", n.Dir, n.UUID); err != nil { - return err - } - - // Generate a link to the main dashboard filtered by the uuid and showing results from now till whenever the link is viewed + log.Info("started network", + zap.String("networkDir", n.Dir), + zap.String("uuid", n.UUID), + ) + // Provide a link to the main dashboard filtered by the uuid and showing results from now till whenever the link is viewed startTimeStr := strconv.FormatInt(startTime.UnixMilli(), 10) metricsURL := MetricsLinkForNetwork(n.UUID, startTimeStr, "") - // Write link to the network path and to stdout + // Write link to the network path metricsPath := filepath.Join(n.Dir, "metrics.txt") if err := os.WriteFile(metricsPath, []byte(metricsURL+"\n"), perms.ReadWrite); err != nil { return fmt.Errorf("failed to write metrics link to %s: %w", metricsPath, err) } - if _, err := fmt.Fprintf(w, "\nMetrics: %s\nLink also saved to %s\n", metricsURL, metricsPath); err != nil { - return err - } + + log.Info("metrics and logs available in grafana", + zap.String("url", metricsURL), + zap.String("linkPath", metricsPath), + ) return nil } // Start the network for the first time -func (n *Network) Bootstrap(ctx context.Context, w io.Writer) error { +func (n *Network) Bootstrap(ctx context.Context, log logging.Logger) error { if len(n.Subnets) == 0 { // Without the need to coordinate subnet configuration, // starting all nodes at once is the simplest option. - return n.StartNodes(ctx, w, n.Nodes...) + return n.StartNodes(ctx, log, n.Nodes...) } // The node that will be used to create subnets and bootstrap the network @@ -410,9 +412,7 @@ func (n *Network) Bootstrap(ctx context.Context, w io.Writer) error { // disabled. This allows the creation of initial subnet state without // requiring coordination between multiple nodes. - if _, err := fmt.Fprintln(w, "Starting a single-node network with sybil protection disabled for quicker subnet creation"); err != nil { - return err - } + log.Info("starting a single-node network with sybil protection disabled for quicker subnet creation") // If sybil protection is enabled, it should be re-enabled before the node is used to bootstrap the other nodes var err error @@ -425,29 +425,29 @@ func (n *Network) Bootstrap(ctx context.Context, w io.Writer) error { bootstrapNode.Flags[config.SybilProtectionEnabledKey] = false } - if err := n.StartNodes(ctx, w, bootstrapNode); err != nil { + if err := n.StartNodes(ctx, log, bootstrapNode); err != nil { return err } // Don't restart the node during subnet creation since it will always be restarted afterwards. - if err := n.CreateSubnets(ctx, w, bootstrapNode.URI, false /* restartRequired */); err != nil { + if err := n.CreateSubnets(ctx, log, bootstrapNode.URI, false /* restartRequired */); err != nil { return err } if reEnableSybilProtection { - if _, err := fmt.Fprintf(w, "Re-enabling sybil protection for %s\n", bootstrapNode.NodeID); err != nil { - return err - } + log.Info("re-enabling sybil protection", + zap.Stringer("nodeID", bootstrapNode.NodeID), + ) delete(bootstrapNode.Flags, config.SybilProtectionEnabledKey) } - if _, err := fmt.Fprintf(w, "Restarting bootstrap node %s\n", bootstrapNode.NodeID); err != nil { - return err - } + log.Info("restarting bootstrap node", + zap.Stringer("nodeID", bootstrapNode.NodeID), + ) if len(n.Nodes) == 1 { // Ensure the node is restarted to pick up subnet and chain configuration - return n.RestartNode(ctx, w, bootstrapNode) + return n.RestartNode(ctx, log, bootstrapNode) } // TODO(marun) This last restart of the bootstrap node might be unnecessary if: @@ -459,18 +459,16 @@ func (n *Network) Bootstrap(ctx context.Context, w io.Writer) error { if err := bootstrapNode.Stop(ctx); err != nil { return fmt.Errorf("failed to stop node %s: %w", bootstrapNode.NodeID, err) } - if err := n.StartNode(ctx, w, bootstrapNode); err != nil { + if err := n.StartNode(ctx, log, bootstrapNode); err != nil { return fmt.Errorf("failed to start node %s: %w", bootstrapNode.NodeID, err) } - if _, err := fmt.Fprintln(w, "Starting remaining nodes..."); err != nil { - return err - } - return n.StartNodes(ctx, w, n.Nodes[1:]...) + log.Info("starting remaining nodes") + return n.StartNodes(ctx, log, n.Nodes[1:]...) } // Starts the provided node after configuring it for the network. -func (n *Network) StartNode(ctx context.Context, w io.Writer, node *Node) error { +func (n *Network) StartNode(ctx context.Context, log logging.Logger, node *Node) error { // This check is duplicative for a network that is starting, but ensures // that individual node start/restart won't fail due to missing binaries. pluginDir, err := n.getPluginDir() @@ -483,7 +481,7 @@ func (n *Network) StartNode(ctx context.Context, w io.Writer, node *Node) error } // Check the VM binaries after EnsureNodeConfig to ensure node.RuntimeConfig is non-nil - if err := checkVMBinaries(w, n.Subnets, node.RuntimeConfig.AvalancheGoPath, pluginDir); err != nil { + if err := checkVMBinaries(log, n.Subnets, node.RuntimeConfig.AvalancheGoPath, pluginDir); err != nil { return err } @@ -497,7 +495,7 @@ func (n *Network) StartNode(ctx context.Context, w io.Writer, node *Node) error return err } - if err := node.Start(w); err != nil { + if err := node.Start(log); err != nil { // Attempt to stop an unhealthy node to provide some assurance to the caller // that an error condition will not result in a lingering process. err = errors.Join(err, node.Stop(ctx)) @@ -508,7 +506,7 @@ func (n *Network) StartNode(ctx context.Context, w io.Writer, node *Node) error } // Restart a single node. -func (n *Network) RestartNode(ctx context.Context, w io.Writer, node *Node) error { +func (n *Network) RestartNode(ctx context.Context, log logging.Logger, node *Node) error { // Ensure the node reuses the same API port across restarts to ensure // consistent labeling of metrics. Otherwise prometheus's automatic // addition of the `instance` label (host:port) results in @@ -529,12 +527,12 @@ func (n *Network) RestartNode(ctx context.Context, w io.Writer, node *Node) erro if err := node.Stop(ctx); err != nil { return fmt.Errorf("failed to stop node %s: %w", node.NodeID, err) } - if err := n.StartNode(ctx, w, node); err != nil { + if err := n.StartNode(ctx, log, node); err != nil { return fmt.Errorf("failed to start node %s: %w", node.NodeID, err) } - if _, err := fmt.Fprintf(w, " waiting for node %s to report healthy\n", node.NodeID); err != nil { - return err - } + log.Info("waiting for node to report healthy", + zap.Stringer("nodeID", node.NodeID), + ) return WaitForHealthy(ctx, node) } @@ -569,12 +567,10 @@ func (n *Network) Stop(ctx context.Context) error { } // Restarts all non-ephemeral nodes in the network. -func (n *Network) Restart(ctx context.Context, w io.Writer) error { - if _, err := fmt.Fprintln(w, " restarting network"); err != nil { - return err - } +func (n *Network) Restart(ctx context.Context, log logging.Logger) error { + log.Info("restarting network") for _, node := range n.Nodes { - if err := n.RestartNode(ctx, w, node); err != nil { + if err := n.RestartNode(ctx, log, node); err != nil { return err } } @@ -676,7 +672,7 @@ func (n *Network) GetSubnet(name string) *Subnet { // Ensure that each subnet on the network is created. If restartRequired is false, node restart // to pick up configuration changes becomes the responsibility of the caller. -func (n *Network) CreateSubnets(ctx context.Context, w io.Writer, apiURI string, restartRequired bool) error { +func (n *Network) CreateSubnets(ctx context.Context, log logging.Logger, apiURI string, restartRequired bool) error { createdSubnets := make([]*Subnet, 0, len(n.Subnets)) for _, subnet := range n.Subnets { if len(subnet.ValidatorIDs) == 0 { @@ -687,9 +683,9 @@ func (n *Network) CreateSubnets(ctx context.Context, w io.Writer, apiURI string, continue } - if _, err := fmt.Fprintf(w, "Creating subnet %q\n", subnet.Name); err != nil { - return err - } + log.Info("creating subnet", + zap.String("name", subnet.Name), + ) if subnet.OwningKey == nil { // Allocate a pre-funded key and remove it from the network so it won't be used for @@ -706,18 +702,19 @@ func (n *Network) CreateSubnets(ctx context.Context, w io.Writer, apiURI string, return err } - if _, err := fmt.Fprintf(w, " created subnet %q as %q\n", subnet.Name, subnet.SubnetID); err != nil { - return err - } + log.Info("created subnet", + zap.String("name", subnet.Name), + zap.Stringer("id", subnet.SubnetID), + ) // Persist the subnet configuration if err := subnet.Write(n.GetSubnetDir(), n.GetChainConfigDir()); err != nil { return err } - if _, err := fmt.Fprintf(w, " wrote configuration for subnet %q\n", subnet.Name); err != nil { - return err - } + log.Info("wrote subnet configuration", + zap.String("name", subnet.Name), + ) createdSubnets = append(createdSubnets, subnet) } @@ -746,16 +743,14 @@ func (n *Network) CreateSubnets(ctx context.Context, w io.Writer, apiURI string, } if restartRequired { - if _, err := fmt.Fprintln(w, "Restarting node(s) to enable them to track the new subnet(s)"); err != nil { - return err - } + log.Info("restarting node(s) to enable them to track the new subnet(s)") for _, node := range reconfiguredNodes { if len(node.URI) == 0 { // Only running nodes should be restarted continue } - if err := n.RestartNode(ctx, w, node); err != nil { + if err := n.RestartNode(ctx, log, node); err != nil { return err } } @@ -763,9 +758,9 @@ func (n *Network) CreateSubnets(ctx context.Context, w io.Writer, apiURI string, // Add validators for the subnet for _, subnet := range createdSubnets { - if _, err := fmt.Fprintf(w, "Adding validators for subnet %q\n", subnet.Name); err != nil { - return err - } + log.Info("adding validators for subnet", + zap.String("name", subnet.Name), + ) // Collect the nodes intended to validate the subnet validatorIDs := set.NewSet[ids.NodeID](len(subnet.ValidatorIDs)) @@ -778,7 +773,7 @@ func (n *Network) CreateSubnets(ctx context.Context, w io.Writer, apiURI string, validatorNodes = append(validatorNodes, node) } - if err := subnet.AddValidators(ctx, w, apiURI, validatorNodes...); err != nil { + if err := subnet.AddValidators(ctx, log, apiURI, validatorNodes...); err != nil { return err } } @@ -787,12 +782,12 @@ func (n *Network) CreateSubnets(ctx context.Context, w io.Writer, apiURI string, pChainClient := platformvm.NewClient(n.Nodes[0].URI) validatorsToRestart := set.Set[ids.NodeID]{} for _, subnet := range createdSubnets { - if err := WaitForActiveValidators(ctx, w, pChainClient, subnet); err != nil { + if err := WaitForActiveValidators(ctx, log, pChainClient, subnet); err != nil { return err } // It should now be safe to create chains for the subnet - if err := subnet.CreateChains(ctx, w, n.Nodes[0].URI); err != nil { + if err := subnet.CreateChains(ctx, log, n.Nodes[0].URI); err != nil { return err } @@ -800,9 +795,9 @@ func (n *Network) CreateSubnets(ctx context.Context, w io.Writer, apiURI string, if err := subnet.Write(n.GetSubnetDir(), n.GetChainConfigDir()); err != nil { return err } - if _, err := fmt.Fprintf(w, " wrote chain configuration for subnet %q\n", subnet.Name); err != nil { - return err - } + log.Info("wrote chain configuration for subnet", + zap.String("name", subnet.Name), + ) // If one or more of the subnets chains have explicit configuration, the // subnet's validator nodes will need to be restarted for those nodes to read @@ -816,16 +811,14 @@ func (n *Network) CreateSubnets(ctx context.Context, w io.Writer, apiURI string, return nil } - if _, err := fmt.Fprintln(w, "Restarting node(s) to pick up chain configuration"); err != nil { - return err - } + log.Info("restarting node(s) to pick up chain configuration") // Restart nodes to allow configuration for the new chains to take effect for _, node := range n.Nodes { if !validatorsToRestart.Contains(node.NodeID) { continue } - if err := n.RestartNode(ctx, w, node); err != nil { + if err := n.RestartNode(ctx, log, node); err != nil { return err } } @@ -892,7 +885,7 @@ func (n *Network) getPluginDir() (string, error) { } // Waits until the provided nodes are healthy. -func waitForHealthy(ctx context.Context, w io.Writer, nodes []*Node) error { +func waitForHealthy(ctx context.Context, log logging.Logger, nodes []*Node) error { ticker := time.NewTicker(networkHealthCheckInterval) defer ticker.Stop() @@ -908,9 +901,10 @@ func waitForHealthy(ctx context.Context, w io.Writer, nodes []*Node) error { } unhealthyNodes.Remove(node) - if _, err := fmt.Fprintf(w, "%s is healthy @ %s\n", node.NodeID, node.URI); err != nil { - return err - } + log.Info("node is healthy", + zap.Stringer("nodeID", node.NodeID), + zap.String("uri", node.URI), + ) } if unhealthyNodes.Len() == 0 { @@ -957,47 +951,60 @@ const invalidRPCVersion = 0 // checkVMBinaries checks that VM binaries for the given subnets exist and optionally checks that VM // binaries have the same rpcchainvm version as the indicated avalanchego binary. -func checkVMBinaries(w io.Writer, subnets []*Subnet, avalanchegoPath string, pluginDir string) error { +func checkVMBinaries(log logging.Logger, subnets []*Subnet, avalanchegoPath string, pluginDir string) error { if len(subnets) == 0 { return nil } - expectedRPCVersion, err := getRPCVersion(avalanchegoPath, "--version-json") + avalanchegoRPCVersion, err := getRPCVersion(avalanchegoPath, "--version-json") if err != nil { - // Only warn if the rpc version is not available to ensure backwards compatibility. - if _, err := fmt.Fprintf(w, "Warning: Unable to check rpcchainvm version for avalanchego: %v\n", err); err != nil { - return err - } + log.Warn("unable to check rpcchainvm version for avalanchego", zap.Error(err)) + return nil } - errs := []error{} + var incompatibleChains bool for _, subnet := range subnets { for _, chain := range subnet.Chains { - pluginPath := filepath.Join(pluginDir, chain.VMID.String()) + vmPath := filepath.Join(pluginDir, chain.VMID.String()) // Check that the path exists - if _, err := os.Stat(pluginPath); err != nil { - errs = append(errs, fmt.Errorf("failed to check VM binary for subnet %q: %w", subnet.Name, err)) + if _, err := os.Stat(vmPath); err != nil { + log.Warn("unable to check rpcchainvm version for VM", + zap.String("vmPath", vmPath), + zap.Error(err), + ) + continue } - if len(chain.VersionArgs) == 0 || expectedRPCVersion == invalidRPCVersion { + if len(chain.VersionArgs) == 0 || avalanchegoRPCVersion == invalidRPCVersion { // Not possible to check the rpcchainvm version continue } // Check that the VM's rpcchainvm version matches avalanchego's version - rpcVersion, err := getRPCVersion(pluginPath, chain.VersionArgs...) + vmRPCVersion, err := getRPCVersion(vmPath, chain.VersionArgs...) if err != nil { - if _, err := fmt.Fprintf(w, "Warning: Unable to check rpcchainvm version for VM Binary for subnet %q: %v\n", subnet.Name, err); err != nil { - return err - } - } else if expectedRPCVersion != rpcVersion { - errs = append(errs, fmt.Errorf("unexpected rpcchainvm version for VM binary of subnet %q: %q reports %d, but %q reports %d", subnet.Name, avalanchegoPath, expectedRPCVersion, pluginPath, rpcVersion)) + log.Warn("unable to check rpcchainvm version for VM Binary", + zap.String("subnet", subnet.Name), + zap.Error(err), + ) + } else if avalanchegoRPCVersion != vmRPCVersion { + log.Error("unexpected rpcchainvm version for VM binary", + zap.String("subnet", subnet.Name), + zap.String("avalanchegoPath", avalanchegoPath), + zap.Uint64("avalanchegoRPCVersion", avalanchegoRPCVersion), + zap.String("vmPath", vmPath), + zap.Uint64("vmRPCVersion", vmRPCVersion), + ) + incompatibleChains = true } } } - return errors.Join(errs...) + if incompatibleChains { + return errors.New("the rpcchainvm version of the VMs for one or more chains may not be compatible with the specified avalanchego binary") + } + return nil } type RPCChainVMVersion struct { diff --git a/tests/fixture/tmpnet/network_test.go b/tests/fixture/tmpnet/network_test.go index db8d1c404716..e5e12ec88ad2 100644 --- a/tests/fixture/tmpnet/network_test.go +++ b/tests/fixture/tmpnet/network_test.go @@ -4,9 +4,9 @@ package tmpnet import ( - "bytes" "testing" + "github.com/ava-labs/avalanchego/tests" "github.com/stretchr/testify/require" ) @@ -16,7 +16,7 @@ func TestNetworkSerialization(t *testing.T) { tmpDir := t.TempDir() network := NewDefaultNetwork("testnet") - require.NoError(network.EnsureDefaultConfig(&bytes.Buffer{}, "/path/to/avalanche/go", "")) + require.NoError(network.EnsureDefaultConfig(tests.NewDefaultTestLogger(), "/path/to/avalanche/go", "")) require.NoError(network.Create(tmpDir)) // Ensure node runtime is initialized require.NoError(network.readNodes()) diff --git a/tests/fixture/tmpnet/node.go b/tests/fixture/tmpnet/node.go index 3717fc45e32a..9cff10ca7f3a 100644 --- a/tests/fixture/tmpnet/node.go +++ b/tests/fixture/tmpnet/node.go @@ -23,6 +23,7 @@ import ( "github.com/ava-labs/avalanchego/ids" "github.com/ava-labs/avalanchego/staking" "github.com/ava-labs/avalanchego/utils/crypto/bls" + "github.com/ava-labs/avalanchego/utils/logging" "github.com/ava-labs/avalanchego/vms/platformvm/signer" ) @@ -42,7 +43,7 @@ var ( // NodeRuntime defines the methods required to support running a node. type NodeRuntime interface { readState() error - Start(w io.Writer) error + Start(log logging.Logger) error InitiateStop() error WaitForStopped(ctx context.Context) error IsHealthy(ctx context.Context) (bool, error) @@ -172,8 +173,8 @@ func (n *Node) IsHealthy(ctx context.Context) (bool, error) { return n.getRuntime().IsHealthy(ctx) } -func (n *Node) Start(w io.Writer) error { - return n.getRuntime().Start(w) +func (n *Node) Start(log logging.Logger) error { + return n.getRuntime().Start(log) } func (n *Node) InitiateStop(ctx context.Context) error { diff --git a/tests/fixture/tmpnet/node_process.go b/tests/fixture/tmpnet/node_process.go index 3036dfc118f2..d555757535d7 100644 --- a/tests/fixture/tmpnet/node_process.go +++ b/tests/fixture/tmpnet/node_process.go @@ -21,7 +21,9 @@ import ( "github.com/ava-labs/avalanchego/config" "github.com/ava-labs/avalanchego/node" + "github.com/ava-labs/avalanchego/utils/logging" "github.com/ava-labs/avalanchego/utils/perms" + "go.uber.org/zap" ) const ( @@ -74,7 +76,7 @@ func (p *NodeProcess) readState() error { // its staking port. The network will start faster with this // synchronization due to the avoidance of exponential backoff // if a node tries to connect to a beacon that is not ready. -func (p *NodeProcess) Start(w io.Writer) error { +func (p *NodeProcess) Start(log logging.Logger) error { // Avoid attempting to start an already running node. proc, err := p.getProcess() if err != nil { @@ -106,19 +108,7 @@ func (p *NodeProcess) Start(w io.Writer) error { ctx, cancelWithCause := context.WithCancelCause(context.Background()) defer cancelWithCause(nil) logPath := p.node.GetDataDir() + "/logs/main.log" - go watchLogFileForFatal(ctx, cancelWithCause, w, logPath) - - // Determine appropriate level of node description detail - dataDir := p.node.GetDataDir() - nodeDescription := fmt.Sprintf("node %q", p.node.NodeID) - if p.node.IsEphemeral { - nodeDescription = "ephemeral " + nodeDescription - } - nonDefaultNodeDir := filepath.Base(dataDir) != p.node.NodeID.String() - if nonDefaultNodeDir { - // Only include the data dir if its base is not the default (the node ID) - nodeDescription = fmt.Sprintf("%s with path: %s", nodeDescription, dataDir) - } + go watchLogFileForFatal(ctx, cancelWithCause, log, logPath) // A node writes a process context file on start. If the file is not // found in a reasonable amount of time, the node is unlikely to have @@ -127,9 +117,11 @@ func (p *NodeProcess) Start(w io.Writer) error { return fmt.Errorf("failed to start local node: %w", err) } - if _, err = fmt.Fprintf(w, "Started %s\n", nodeDescription); err != nil { - return err - } + log.Info("started local node", + zap.Stringer("nodeID", p.node.NodeID), + zap.String("dataDir", p.node.GetDataDir()), + zap.Bool("isEphemeral", p.node.IsEphemeral), + ) // Configure collection of metrics and logs return p.writeMonitoringConfig() @@ -350,7 +342,7 @@ func (p *NodeProcess) writeMonitoringConfigFile(tmpnetDir string, name string, c // Errors encountered while looking for FATAL log entries are considered potential rather // than positive indications of failure and are printed to the provided writer instead of // being provided to the cancelWithCause function. -func watchLogFileForFatal(ctx context.Context, cancelWithCause context.CancelCauseFunc, w io.Writer, path string) { +func watchLogFileForFatal(ctx context.Context, cancelWithCause context.CancelCauseFunc, log logging.Logger, path string) { waitInterval := 100 * time.Millisecond // Wait for the file to exist fileExists := false @@ -371,7 +363,10 @@ func watchLogFileForFatal(ctx context.Context, cancelWithCause context.CancelCau // Open the file file, err := os.Open(path) if err != nil { - _, _ = fmt.Fprintf(w, "failed to open %s: %v", path, err) + log.Error("failed to open log file", + zap.String("path", path), + zap.Error(err), + ) return } defer file.Close() @@ -391,7 +386,10 @@ func watchLogFileForFatal(ctx context.Context, cancelWithCause context.CancelCau time.Sleep(waitInterval) continue } else { - _, _ = fmt.Fprintf(w, "error reading %s: %v\n", path, err) + log.Error("failed to read log file", + zap.String("path", path), + zap.Error(err), + ) return } } diff --git a/tests/fixture/tmpnet/subnet.go b/tests/fixture/tmpnet/subnet.go index 1e1d3c749c7a..23b3cb8d9292 100644 --- a/tests/fixture/tmpnet/subnet.go +++ b/tests/fixture/tmpnet/subnet.go @@ -8,15 +8,17 @@ import ( "encoding/json" "errors" "fmt" - "io" "os" "path/filepath" "strings" "time" + "go.uber.org/zap" + "github.com/ava-labs/avalanchego/ids" "github.com/ava-labs/avalanchego/utils/constants" "github.com/ava-labs/avalanchego/utils/crypto/secp256k1" + "github.com/ava-labs/avalanchego/utils/logging" "github.com/ava-labs/avalanchego/utils/perms" "github.com/ava-labs/avalanchego/utils/set" "github.com/ava-labs/avalanchego/utils/units" @@ -133,16 +135,16 @@ func (s *Subnet) Create(ctx context.Context, uri string) error { return nil } -func (s *Subnet) CreateChains(ctx context.Context, w io.Writer, uri string) error { +func (s *Subnet) CreateChains(ctx context.Context, log logging.Logger, uri string) error { wallet, err := s.GetWallet(ctx, uri) if err != nil { return err } pWallet := wallet.P() - if _, err := fmt.Fprintf(w, "Creating chains for subnet %q\n", s.Name); err != nil { - return err - } + log.Info("creating chains for subnet", + zap.String("subnet", s.Name), + ) for _, chain := range s.Chains { createChainTx, err := pWallet.IssueCreateChainTx( @@ -158,15 +160,17 @@ func (s *Subnet) CreateChains(ctx context.Context, w io.Writer, uri string) erro } chain.ChainID = createChainTx.ID() - if _, err := fmt.Fprintf(w, " created chain %q for VM %q on subnet %q\n", chain.ChainID, chain.VMID, s.Name); err != nil { - return err - } + log.Info("created chain", + zap.Stringer("chain", chain.ChainID), + zap.String("subnet", s.Name), + zap.Stringer("vm", chain.VMID), + ) } return nil } // Add validators to the subnet -func (s *Subnet) AddValidators(ctx context.Context, w io.Writer, apiURI string, nodes ...*Node) error { +func (s *Subnet) AddValidators(ctx context.Context, log logging.Logger, apiURI string, nodes ...*Node) error { wallet, err := s.GetWallet(ctx, apiURI) if err != nil { return err @@ -207,9 +211,10 @@ func (s *Subnet) AddValidators(ctx context.Context, w io.Writer, apiURI string, return err } - if _, err := fmt.Fprintf(w, " added %s as validator for subnet `%s`\n", node.NodeID, s.Name); err != nil { - return err - } + log.Info("added validator to subnet", + zap.String("subnet", s.Name), + zap.Stringer("node", node.NodeID), + ) } return nil @@ -290,25 +295,18 @@ func (s *Subnet) HasChainConfig() bool { func WaitForActiveValidators( ctx context.Context, - w io.Writer, + log logging.Logger, pChainClient platformvm.Client, subnet *Subnet, ) error { ticker := time.NewTicker(DefaultPollingInterval) defer ticker.Stop() - if _, err := fmt.Fprintf(w, "Waiting for validators of subnet %q to become active\n", subnet.Name); err != nil { - return err - } - - if _, err := fmt.Fprint(w, " "); err != nil { - return err - } + log.Info("waiting for subnet validators to become active", + zap.String("subnet", subnet.Name), + ) for { - if _, err := fmt.Fprint(w, "."); err != nil { - return err - } validators, err := pChainClient.GetCurrentValidators(ctx, subnet.SubnetID, nil) if err != nil { return err @@ -324,15 +322,15 @@ func WaitForActiveValidators( } } if allActive { - if _, err := fmt.Fprintf(w, "\n saw the expected active validators of subnet %q\n", subnet.Name); err != nil { - return err - } + log.Info("saw the expected active validators of subnet", + zap.String("subnet", subnet.Name), + ) return nil } select { case <-ctx.Done(): - return fmt.Errorf("failed to see the expected active validators of subnet %q before timeout", subnet.Name) + return fmt.Errorf("failed to see the expected active validators of subnet %q before timeout: %w", subnet.Name, ctx.Err()) case <-ticker.C: } } diff --git a/tests/lib/utils.go b/tests/lib/utils.go new file mode 100644 index 000000000000..6c7f7dfba6b6 --- /dev/null +++ b/tests/lib/utils.go @@ -0,0 +1,19 @@ +// Copyright (C) 2019-2024, Ava Labs, Inc. All rights reserved. +// See the file LICENSE for licensing terms. + +package lib + +import ( + "os" + + "github.com/ava-labs/avalanchego/utils/logging" +) + +func LoggerForFormat(rawLogFormat string) (logging.Logger, error) { + writeCloser := os.Stdout + logFormat, err := logging.ToFormat(rawLogFormat, writeCloser.Fd()) + if err != nil { + return nil, err + } + return logging.NewLogger("", logging.NewWrappedCore(logging.Verbo, writeCloser, logFormat.ConsoleEncoder())), nil +} diff --git a/tests/log.go b/tests/log.go new file mode 100644 index 000000000000..7187af423e5a --- /dev/null +++ b/tests/log.go @@ -0,0 +1,39 @@ +// Copyright (C) 2019-2024, Ava Labs, Inc. All rights reserved. +// See the file LICENSE for licensing terms. + +package tests + +import ( + "io" + "os" + + "go.uber.org/zap/zapcore" + + "github.com/ava-labs/avalanchego/utils/logging" +) + +// Define a default encoder appropriate for testing +var defaultEncoderConfig = zapcore.EncoderConfig{ + TimeKey: "", + LevelKey: "level", + NameKey: "", + CallerKey: "", + MessageKey: "msg", + StacktraceKey: "stacktrace", + EncodeLevel: zapcore.LowercaseLevelEncoder, +} + +func NewDefaultTestLogger() logging.Logger { + return NewTestLogger(os.Stdout) +} + +func NewTestLogger(writeCloser io.WriteCloser) logging.Logger { + return logging.NewLogger( + "", + logging.NewWrappedCore( + logging.Verbo, + writeCloser, + zapcore.NewConsoleEncoder(defaultEncoderConfig), + ), + ) +} diff --git a/tests/simple_test_context.go b/tests/simple_test_context.go index 3be2c050f6e4..577b521f6b39 100644 --- a/tests/simple_test_context.go +++ b/tests/simple_test_context.go @@ -6,14 +6,13 @@ package tests import ( "context" "fmt" - "io" "log" "os" "time" - "github.com/onsi/ginkgo/v2/formatter" "github.com/stretchr/testify/require" + "github.com/ava-labs/avalanchego/utils/logging" "github.com/ava-labs/avalanchego/wallet/subnet/primary/common" ) @@ -36,10 +35,6 @@ func (*SimpleTestContext) FailNow() { panic(failNowMessage) } -func (*SimpleTestContext) GetWriter() io.Writer { - return os.Stdout -} - // Cleanup is intended to be deferred by the caller to ensure cleanup is performed even // in the event that a panic occurs. func (tc *SimpleTestContext) Cleanup() { @@ -92,10 +87,10 @@ func (tc *SimpleTestContext) By(_ string, _ ...func()) { tc.FailNow() } -// TODO(marun) Enable color output equivalent to GinkgoTestContext.Outf -func (*SimpleTestContext) Outf(format string, args ...interface{}) { - s := formatter.F(format, args...) - log.Print(s) +func (tc *SimpleTestContext) Log() logging.Logger { + tc.Errorf("SimpleTestContext.Log not yet implemented") + tc.FailNow() + return nil } // Helper simplifying use of a timed context by canceling the context on ginkgo teardown. diff --git a/tests/test_context.go b/tests/test_context.go index 54ed9120a414..2eff4adbbfcf 100644 --- a/tests/test_context.go +++ b/tests/test_context.go @@ -5,11 +5,11 @@ package tests import ( "context" - "io" "time" "github.com/stretchr/testify/require" + "github.com/ava-labs/avalanchego/utils/logging" "github.com/ava-labs/avalanchego/wallet/subnet/primary/common" ) @@ -23,11 +23,8 @@ type TestContext interface { // Provides a simple alternative to ginkgo.DeferCleanup DeferCleanup(cleanup func()) - // Enables color output to stdout - Outf(format string, args ...interface{}) - - // Ensures compatibility with ginkgo.GinkgoWriter - GetWriter() io.Writer + // Returns a logger that can be used to log test output + Log() logging.Logger // Context helpers requiring cleanup with DeferCleanup ContextWithTimeout(duration time.Duration) context.Context diff --git a/tests/upgrade/upgrade_test.go b/tests/upgrade/upgrade_test.go index d49684160509..2db31b983cfd 100644 --- a/tests/upgrade/upgrade_test.go +++ b/tests/upgrade/upgrade_test.go @@ -68,7 +68,7 @@ var _ = ginkgo.Describe("[Upgrade]", func() { node.RuntimeConfig.AvalancheGoPath = avalancheGoExecPathToUpgradeTo - require.NoError(network.StartNode(tc.DefaultContext(), tc.GetWriter(), node)) + require.NoError(network.StartNode(tc.DefaultContext(), tc.Log(), node)) tc.By(fmt.Sprintf("waiting for node %q to report healthy after restart", node.NodeID)) e2e.WaitForHealthy(tc, node) From 72d27a919ab990d859438768ee1947b766cede56 Mon Sep 17 00:00:00 2001 From: Maru Newby Date: Wed, 20 Nov 2024 21:19:10 +0100 Subject: [PATCH 02/22] fixup: Self-review --- tests/e2e/p/staking_rewards.go | 2 +- tests/e2e/vms/xsvm.go | 2 +- tests/e2e/x/transfer/virtuous.go | 2 +- .../fixture/bootstrapmonitor/e2e/e2e_test.go | 4 ++-- tests/fixture/e2e/env.go | 2 +- tests/fixture/e2e/helpers.go | 8 ++++---- tests/fixture/e2e/metrics_link.go | 2 +- tests/fixture/tmpnet/cmd/main.go | 16 ++++++++++++---- tests/fixture/tmpnet/network.go | 5 ++++- tests/fixture/tmpnet/subnet.go | 2 +- tests/lib/utils.go | 19 ------------------- tests/log.go | 5 ++++- 12 files changed, 32 insertions(+), 37 deletions(-) delete mode 100644 tests/lib/utils.go diff --git a/tests/e2e/p/staking_rewards.go b/tests/e2e/p/staking_rewards.go index 4837a6f46306..11f5d4dc0340 100644 --- a/tests/e2e/p/staking_rewards.go +++ b/tests/e2e/p/staking_rewards.go @@ -185,7 +185,7 @@ var _ = ginkgo.Describe("[Staking Rewards]", func() { e2e.OutputWalletBalances(tc, baseWallet) endTime := time.Now().Add(targetDelegationPeriod) - tc.Log().Info("determined gamma delegator validation end", + tc.Log().Info("determined gamma delegator validation end time", zap.Time("time", endTime), ) diff --git a/tests/e2e/vms/xsvm.go b/tests/e2e/vms/xsvm.go index 5f3b08fa2d90..161c8780f428 100644 --- a/tests/e2e/vms/xsvm.go +++ b/tests/e2e/vms/xsvm.go @@ -137,7 +137,7 @@ var _ = ginkgo.Describe("[XSVM]", func() { }, ) require.NoError(err) - tc.Log().Info("issued transfer", + tc.Log().Info("issued transfer transaction", zap.Stringer("txID", transferTxStatus.TxID), ) diff --git a/tests/e2e/x/transfer/virtuous.go b/tests/e2e/x/transfer/virtuous.go index 12e2c7ea4514..c77aec5b8285 100644 --- a/tests/e2e/x/transfer/virtuous.go +++ b/tests/e2e/x/transfer/virtuous.go @@ -223,7 +223,7 @@ var _ = e2e.DescribeXChainSerial("[Virtuous Transfer Tx AVAX]", func() { require.Contains(err.Error(), "insufficient funds") }) - tc.Log().Info("transfering", + tc.Log().Info("issuing transfer", zap.Stringer("fromAddress", shortAddrs[fromIdx]), zap.Uint64("senderOrigBal", senderOrigBal), zap.Uint64("senderNewBal", senderNewBal), diff --git a/tests/fixture/bootstrapmonitor/e2e/e2e_test.go b/tests/fixture/bootstrapmonitor/e2e/e2e_test.go index 199046940339..13508a7ec0d2 100644 --- a/tests/fixture/bootstrapmonitor/e2e/e2e_test.go +++ b/tests/fixture/bootstrapmonitor/e2e/e2e_test.go @@ -97,7 +97,7 @@ var _ = ginkgo.Describe("[Bootstrap Tester]", func() { } if skipMonitorImageBuild { - tc.Log().Info("skipping build of bootstrap-monitor image") + tc.Log().Warn("skipping build of bootstrap-monitor image") } else { ginkgo.By("Building the bootstrap-monitor image") buildImage(tc, monitorImage, false /* forceNewHash */, "build_bootstrap_monitor_image.sh") @@ -455,7 +455,7 @@ func waitForLogOutput(tc tests.TestContext, clientset *kubernetes.Clientset, nam scanner := bufio.NewScanner(readCloser) for scanner.Scan() { line := scanner.Text() - tc.Log().Info(line) + tc.Log().Info(" > " + line) if len(desiredOutput) > 0 && strings.Contains(line, desiredOutput) { return } diff --git a/tests/fixture/e2e/env.go b/tests/fixture/e2e/env.go index 7fd99896199e..789b6d267aab 100644 --- a/tests/fixture/e2e/env.go +++ b/tests/fixture/e2e/env.go @@ -122,7 +122,7 @@ func NewTestEnvironment(tc tests.TestContext, flagVars *FlagVars, desiredNetwork tc.Log().Info("stopping network") require.NoError(network.Stop(tc.DefaultContext())) } else { - tc.Log().Info("no network to stop") + tc.Log().Warn("no network to stop") } os.Exit(0) } else if network != nil && flagVars.RestartNetwork() { diff --git a/tests/fixture/e2e/helpers.go b/tests/fixture/e2e/helpers.go index 02438633a267..f1831f72a98c 100644 --- a/tests/fixture/e2e/helpers.go +++ b/tests/fixture/e2e/helpers.go @@ -276,7 +276,7 @@ func StartNetwork( // Ensure nodes are stopped if bootstrap fails. The network configuration // will remain on disk to enable troubleshooting. err := network.Stop(tc.DefaultContext()) - require.NoError(err, "network bootstrapping failed") + require.NoError(err, "failed to stop network after bootstrap failure") } tc.Log().Info("network started successfully") @@ -288,7 +288,7 @@ func StartNetwork( // Symlink the path of the created network to the default owner path (e.g. latest_avalanchego-e2e) // to enable easy discovery for reuse. require.NoError(os.Symlink(network.Dir, symlinkPath)) - tc.Log().Info("symlinked network dir for reuse", + tc.Log().Warn("symlinked network dir for reuse", zap.String("networkDir", network.Dir), zap.String("symlinkPath", symlinkPath), ) @@ -296,7 +296,7 @@ func StartNetwork( tc.DeferCleanup(func() { if reuseNetwork { - tc.Log().Info("skipping shutdown for network intended for reuse", + tc.Log().Warn("skipping shutdown for network intended for reuse", zap.String("networkDir", network.Dir), zap.String("symlinkPath", symlinkPath), ) @@ -304,7 +304,7 @@ func StartNetwork( } if skipShutdown { - tc.Log().Info("skipping shutdown for network", + tc.Log().Warn("skipping shutdown for network", zap.String("networkDir", network.Dir), ) return diff --git a/tests/fixture/e2e/metrics_link.go b/tests/fixture/e2e/metrics_link.go index 3fb796677404..716938520066 100644 --- a/tests/fixture/e2e/metrics_link.go +++ b/tests/fixture/e2e/metrics_link.go @@ -55,7 +55,7 @@ var _ = ginkgo.AfterEach(func() { strconv.FormatInt(startTime, 10), strconv.FormatInt(endTime, 10), ) - tc.Log().Info("metrics and logs available via grafana (collectors must be running)", + tc.Log().Info(tmpnet.MetricsAvailableMessage, zap.String("uri", metricsLink), ) }) diff --git a/tests/fixture/tmpnet/cmd/main.go b/tests/fixture/tmpnet/cmd/main.go index 11aaac263f38..2620e4f0ab87 100644 --- a/tests/fixture/tmpnet/cmd/main.go +++ b/tests/fixture/tmpnet/cmd/main.go @@ -16,9 +16,8 @@ import ( "go.uber.org/zap" "github.com/ava-labs/avalanchego/tests/fixture/tmpnet" + "github.com/ava-labs/avalanchego/utils/logging" "github.com/ava-labs/avalanchego/version" - - testlib "github.com/ava-labs/avalanchego/tests/lib" ) const cliVersion = "0.0.1" @@ -69,7 +68,7 @@ func main() { return errAvalancheGoRequired } - log, err := testlib.LoggerForFormat(rawLogFormat) + log, err := loggerForFormat(rawLogFormat) if err != nil { return err } @@ -149,7 +148,7 @@ func main() { if len(networkDir) == 0 { return errNetworkDirRequired } - log, err := testlib.LoggerForFormat(rawLogFormat) + log, err := loggerForFormat(rawLogFormat) if err != nil { return err } @@ -166,3 +165,12 @@ func main() { } os.Exit(0) } + +func loggerForFormat(rawLogFormat string) (logging.Logger, error) { + writeCloser := os.Stdout + logFormat, err := logging.ToFormat(rawLogFormat, writeCloser.Fd()) + if err != nil { + return nil, err + } + return logging.NewLogger("", logging.NewWrappedCore(logging.Verbo, writeCloser, logFormat.ConsoleEncoder())), nil +} diff --git a/tests/fixture/tmpnet/network.go b/tests/fixture/tmpnet/network.go index 2e06c7281563..63e2306eb200 100644 --- a/tests/fixture/tmpnet/network.go +++ b/tests/fixture/tmpnet/network.go @@ -40,6 +40,9 @@ const ( NetworkDirEnvName = "TMPNET_NETWORK_DIR" RootDirEnvName = "TMPNET_ROOT_DIR" + // Message to log indicating where to look for metrics and logs for network + MetricsAvailableMessage = "metrics and logs available via grafana (collectors must be running)" + // This interval was chosen to avoid spamming node APIs during // startup, as smaller intervals (e.g. 50ms) seemed to noticeably // increase the time for a network's nodes to be seen as healthy. @@ -384,7 +387,7 @@ func (n *Network) StartNodes(ctx context.Context, log logging.Logger, nodesToSta return fmt.Errorf("failed to write metrics link to %s: %w", metricsPath, err) } - log.Info("metrics and logs available in grafana", + log.Info(MetricsAvailableMessage, zap.String("url", metricsURL), zap.String("linkPath", metricsPath), ) diff --git a/tests/fixture/tmpnet/subnet.go b/tests/fixture/tmpnet/subnet.go index 23b3cb8d9292..6abd774845ec 100644 --- a/tests/fixture/tmpnet/subnet.go +++ b/tests/fixture/tmpnet/subnet.go @@ -322,7 +322,7 @@ func WaitForActiveValidators( } } if allActive { - log.Info("saw the expected active validators of subnet", + log.Info("saw the expected active validators of the subnet", zap.String("subnet", subnet.Name), ) return nil diff --git a/tests/lib/utils.go b/tests/lib/utils.go deleted file mode 100644 index 6c7f7dfba6b6..000000000000 --- a/tests/lib/utils.go +++ /dev/null @@ -1,19 +0,0 @@ -// Copyright (C) 2019-2024, Ava Labs, Inc. All rights reserved. -// See the file LICENSE for licensing terms. - -package lib - -import ( - "os" - - "github.com/ava-labs/avalanchego/utils/logging" -) - -func LoggerForFormat(rawLogFormat string) (logging.Logger, error) { - writeCloser := os.Stdout - logFormat, err := logging.ToFormat(rawLogFormat, writeCloser.Fd()) - if err != nil { - return nil, err - } - return logging.NewLogger("", logging.NewWrappedCore(logging.Verbo, writeCloser, logFormat.ConsoleEncoder())), nil -} diff --git a/tests/log.go b/tests/log.go index 7187af423e5a..77877369bba3 100644 --- a/tests/log.go +++ b/tests/log.go @@ -20,13 +20,16 @@ var defaultEncoderConfig = zapcore.EncoderConfig{ CallerKey: "", MessageKey: "msg", StacktraceKey: "stacktrace", - EncodeLevel: zapcore.LowercaseLevelEncoder, + // TODO(marun) Figure out why this is outputting e.g. `Level(-6)` instead of `INFO` + EncodeLevel: zapcore.LowercaseLevelEncoder, } +// NewDefaultTestLogger returns a logger that writes to stdout func NewDefaultTestLogger() logging.Logger { return NewTestLogger(os.Stdout) } +// NewDefaultTestLogger returns a logger for the specified WriteCloser func NewTestLogger(writeCloser io.WriteCloser) logging.Logger { return logging.NewLogger( "", From 1192c192630579c83aac4d41319ef5f288adc1c3 Mon Sep 17 00:00:00 2001 From: Maru Newby Date: Wed, 20 Nov 2024 21:37:00 +0100 Subject: [PATCH 03/22] fixup: s/node/nodeID/ in log output --- tests/fixture/tmpnet/subnet.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/fixture/tmpnet/subnet.go b/tests/fixture/tmpnet/subnet.go index 6abd774845ec..5221ea3e4c34 100644 --- a/tests/fixture/tmpnet/subnet.go +++ b/tests/fixture/tmpnet/subnet.go @@ -213,7 +213,7 @@ func (s *Subnet) AddValidators(ctx context.Context, log logging.Logger, apiURI s log.Info("added validator to subnet", zap.String("subnet", s.Name), - zap.Stringer("node", node.NodeID), + zap.Stringer("nodeID", node.NodeID), ) } From 53d0040cd9bbfb764f1700bea0d1d2d53362484c Mon Sep 17 00:00:00 2001 From: Maru Newby Date: Wed, 20 Nov 2024 21:40:52 +0100 Subject: [PATCH 04/22] fixup: Fix lint failures --- tests/fixture/tmpnet/network_test.go | 3 ++- tests/fixture/tmpnet/node_process.go | 3 ++- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/tests/fixture/tmpnet/network_test.go b/tests/fixture/tmpnet/network_test.go index e5e12ec88ad2..feba6f99225b 100644 --- a/tests/fixture/tmpnet/network_test.go +++ b/tests/fixture/tmpnet/network_test.go @@ -6,8 +6,9 @@ package tmpnet import ( "testing" - "github.com/ava-labs/avalanchego/tests" "github.com/stretchr/testify/require" + + "github.com/ava-labs/avalanchego/tests" ) func TestNetworkSerialization(t *testing.T) { diff --git a/tests/fixture/tmpnet/node_process.go b/tests/fixture/tmpnet/node_process.go index d555757535d7..68381ea00907 100644 --- a/tests/fixture/tmpnet/node_process.go +++ b/tests/fixture/tmpnet/node_process.go @@ -19,11 +19,12 @@ import ( "syscall" "time" + "go.uber.org/zap" + "github.com/ava-labs/avalanchego/config" "github.com/ava-labs/avalanchego/node" "github.com/ava-labs/avalanchego/utils/logging" "github.com/ava-labs/avalanchego/utils/perms" - "go.uber.org/zap" ) const ( From 5880edc3a5db9dc40f0134184a909379ffb5125e Mon Sep 17 00:00:00 2001 From: Maru Newby Date: Wed, 20 Nov 2024 21:58:39 +0100 Subject: [PATCH 05/22] fixup: Implement SimpleTestContext.Log --- tests/simple_test_context.go | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/tests/simple_test_context.go b/tests/simple_test_context.go index 577b521f6b39..b5597718da96 100644 --- a/tests/simple_test_context.go +++ b/tests/simple_test_context.go @@ -6,7 +6,6 @@ package tests import ( "context" "fmt" - "log" "os" "time" @@ -19,16 +18,19 @@ import ( const failNowMessage = "SimpleTestContext.FailNow called" type SimpleTestContext struct { + logger logging.Logger cleanupFuncs []func() cleanupCalled bool } func NewTestContext() *SimpleTestContext { - return &SimpleTestContext{} + return &SimpleTestContext{ + logger: logging.NewLogger("", logging.NewWrappedCore(logging.Verbo, os.Stdout, logging.Plain.ConsoleEncoder())), + } } -func (*SimpleTestContext) Errorf(format string, args ...interface{}) { - log.Printf("error: "+format, args...) +func (tc *SimpleTestContext) Errorf(format string, args ...interface{}) { + tc.logger.Error(fmt.Sprintf(format, args...)) } func (*SimpleTestContext) FailNow() { @@ -88,9 +90,7 @@ func (tc *SimpleTestContext) By(_ string, _ ...func()) { } func (tc *SimpleTestContext) Log() logging.Logger { - tc.Errorf("SimpleTestContext.Log not yet implemented") - tc.FailNow() - return nil + return tc.logger } // Helper simplifying use of a timed context by canceling the context on ginkgo teardown. From 4563083f5b9ef632e4f545ac3e78bc9af882e62a Mon Sep 17 00:00:00 2001 From: Maru Newby Date: Wed, 20 Nov 2024 23:08:57 +0100 Subject: [PATCH 06/22] fixup: Switch antithesis to zap --- .../avalanchego/gencomposeconfig/main.go | 7 +- tests/antithesis/avalanchego/main.go | 221 ++++++++++++++---- tests/antithesis/config.go | 2 +- tests/antithesis/init_db.go | 2 +- tests/antithesis/node_health.go | 29 ++- .../antithesis/xsvm/gencomposeconfig/main.go | 7 +- tests/antithesis/xsvm/main.go | 59 +++-- tests/fixture/e2e/ginkgo_test_context.go | 2 +- tests/fixture/e2e/helpers.go | 10 +- tests/fixture/tmpnet/cmd/main.go | 15 +- tests/fixture/tmpnet/network_test.go | 3 +- tests/log.go | 34 ++- tests/simple_test_context.go | 10 +- 13 files changed, 290 insertions(+), 111 deletions(-) diff --git a/tests/antithesis/avalanchego/gencomposeconfig/main.go b/tests/antithesis/avalanchego/gencomposeconfig/main.go index 7425a3df9bba..1681ad78e421 100644 --- a/tests/antithesis/avalanchego/gencomposeconfig/main.go +++ b/tests/antithesis/avalanchego/gencomposeconfig/main.go @@ -4,8 +4,9 @@ package main import ( - "log" + "go.uber.org/zap" + "github.com/ava-labs/avalanchego/tests" "github.com/ava-labs/avalanchego/tests/antithesis" "github.com/ava-labs/avalanchego/tests/fixture/tmpnet" ) @@ -16,6 +17,8 @@ const baseImageName = "antithesis-avalanchego" func main() { network := tmpnet.LocalNetworkOrPanic() if err := antithesis.GenerateComposeConfig(network, baseImageName, "" /* runtimePluginDir */); err != nil { - log.Fatalf("failed to generate compose config: %v", err) + tests.NewDefaultLogger("").Fatal("failed to generate compose config", + zap.Error(err), + ) } } diff --git a/tests/antithesis/avalanchego/main.go b/tests/antithesis/avalanchego/main.go index fa3afb7b6e64..e89c58cef5d9 100644 --- a/tests/antithesis/avalanchego/main.go +++ b/tests/antithesis/avalanchego/main.go @@ -6,13 +6,14 @@ package main import ( "context" "crypto/rand" - "log" + "fmt" "math/big" "time" "github.com/antithesishq/antithesis-sdk-go/assert" "github.com/antithesishq/antithesis-sdk-go/lifecycle" "github.com/stretchr/testify/require" + "go.uber.org/zap" "github.com/ava-labs/avalanchego/database" "github.com/ava-labs/avalanchego/genesis" @@ -23,6 +24,7 @@ import ( "github.com/ava-labs/avalanchego/tests/fixture/tmpnet" "github.com/ava-labs/avalanchego/utils/constants" "github.com/ava-labs/avalanchego/utils/crypto/secp256k1" + "github.com/ava-labs/avalanchego/utils/logging" "github.com/ava-labs/avalanchego/utils/set" "github.com/ava-labs/avalanchego/utils/units" "github.com/ava-labs/avalanchego/vms/avm" @@ -43,7 +45,8 @@ import ( const NumKeys = 5 func main() { - tc := tests.NewTestContext() + // TODO(marun) Support choosing the log format + tc := tests.NewTestContext(tests.NewDefaultLogger("")) defer tc.Cleanup() require := require.New(tc) @@ -63,10 +66,13 @@ func main() { EthKeychain: kc, }) require.NoError(err, "failed to initialize wallet") - log.Printf("synced wallet in %s", time.Since(walletSyncStartTime)) + tc.Log().Info("synced wallet", + zap.Duration("duration", time.Since(walletSyncStartTime)), + ) genesisWorkload := &workload{ id: 0, + log: tests.NewDefaultLogger(fmt.Sprintf("worker %d", 0)), wallet: wallet, addrs: set.Of(genesis.EWOQKey.Address()), uris: c.URIs, @@ -104,9 +110,11 @@ func main() { }, }}) require.NoError(err, "failed to issue initial funding X-chain baseTx") - log.Printf("issued initial funding X-chain baseTx %s in %s", baseTx.ID(), time.Since(baseStartTime)) + tc.Log().Info("issued initial funding X-chain baseTx", + zap.Stringer("txID", baseTx.ID()), + zap.Duration("duration", time.Since(baseStartTime)), + ) - // TODO(marun) Enable cleanup of these contexts genesisWorkload.confirmXChainTx(ctx, baseTx) uri := c.URIs[i%len(c.URIs)] @@ -118,10 +126,13 @@ func main() { EthKeychain: kc, }) require.NoError(err, "failed to initialize wallet") - log.Printf("synced wallet in %s", time.Since(walletSyncStartTime)) + tc.Log().Info("synced wallet", + zap.Duration("duration", time.Since(walletSyncStartTime)), + ) workloads[i] = &workload{ id: i, + log: tests.NewDefaultLogger(fmt.Sprintf("worker %d", i)), wallet: wallet, addrs: set.Of(addr), uris: c.URIs, @@ -141,6 +152,7 @@ func main() { type workload struct { id int + log logging.Logger wallet primary.Wallet addrs set.Set[ids.ShortID] uris []string @@ -149,12 +161,11 @@ type workload struct { func (w *workload) run(ctx context.Context) { timer := timerpkg.StoppedTimer() - tc := tests.NewTestContext() + tc := tests.NewTestContext(w.log) defer tc.Cleanup() require := require.New(tc) xAVAX, pAVAX := e2e.GetWalletBalances(tc, w.wallet) - log.Printf("wallet starting with %d X-chain nAVAX and %d P-chain nAVAX", xAVAX, pAVAX) assert.Reachable("wallet starting", map[string]any{ "worker": w.id, "xBalance": xAVAX, @@ -166,7 +177,10 @@ func (w *workload) run(ctx context.Context) { require.NoError(err, "failed to read randomness") flowID := val.Int64() - log.Printf("wallet %d executing flow %d", w.id, flowID) + w.log.Info("executing test", + zap.Int("workerID", w.id), + zap.Int64("flowID", flowID), + ) switch flowID { case 0: w.issueXChainBaseTx(ctx) @@ -199,7 +213,9 @@ func (w *workload) issueXChainBaseTx(ctx context.Context) { ) balances, err := xBuilder.GetFTBalance() if err != nil { - log.Printf("failed to fetch X-chain balances: %s", err) + w.log.Error("failed to fetch X-chain balances", + zap.Error(err), + ) assert.Unreachable("failed to fetch X-chain balances", map[string]any{ "worker": w.id, "err": err, @@ -215,7 +231,10 @@ func (w *workload) issueXChainBaseTx(ctx context.Context) { neededBalance = baseTxFee + units.Schmeckle ) if avaxBalance < neededBalance { - log.Printf("skipping X-chain tx issuance due to insufficient balance: %d < %d", avaxBalance, neededBalance) + w.log.Info("skipping X-chain tx issuance due to insufficient balance", + zap.Uint64("balance", avaxBalance), + zap.Uint64("neededBalance", neededBalance), + ) return } @@ -237,10 +256,15 @@ func (w *workload) issueXChainBaseTx(ctx context.Context) { }, ) if err != nil { - log.Printf("failed to issue X-chain baseTx: %s", err) + w.log.Warn("failed to issue X-chain baseTx", + zap.Error(err), + ) return } - log.Printf("issued new X-chain baseTx %s in %s", baseTx.ID(), time.Since(baseStartTime)) + w.log.Info("issued new X-chain baseTx", + zap.Stringer("txID", baseTx.ID()), + zap.Duration("duration", time.Since(baseStartTime)), + ) w.confirmXChainTx(ctx, baseTx) w.verifyXChainTxConsumedUTXOs(ctx, baseTx) @@ -253,7 +277,9 @@ func (w *workload) issueXChainCreateAssetTx(ctx context.Context) { ) balances, err := xBuilder.GetFTBalance() if err != nil { - log.Printf("failed to fetch X-chain balances: %s", err) + w.log.Error("failed to fetch X-chain balances", + zap.Error(err), + ) assert.Unreachable("failed to fetch X-chain balances", map[string]any{ "worker": w.id, "err": err, @@ -268,7 +294,10 @@ func (w *workload) issueXChainCreateAssetTx(ctx context.Context) { neededBalance = xContext.CreateAssetTxFee ) if avaxBalance < neededBalance { - log.Printf("skipping X-chain tx issuance due to insufficient balance: %d < %d", avaxBalance, neededBalance) + w.log.Info("skipping X-chain tx issuance due to insufficient balance", + zap.Uint64("balance", avaxBalance), + zap.Uint64("neededBalance", neededBalance), + ) return } @@ -290,10 +319,15 @@ func (w *workload) issueXChainCreateAssetTx(ctx context.Context) { }, ) if err != nil { - log.Printf("failed to issue X-chain create asset transaction: %s", err) + w.log.Warn("failed to issue X-chain create asset transaction", + zap.Error(err), + ) return } - log.Printf("created new X-chain asset %s in %s", createAssetTx.ID(), time.Since(createAssetStartTime)) + w.log.Info("created new X-chain asset", + zap.Stringer("txID", createAssetTx.ID()), + zap.Duration("duration", time.Since(createAssetStartTime)), + ) w.confirmXChainTx(ctx, createAssetTx) w.verifyXChainTxConsumedUTXOs(ctx, createAssetTx) @@ -306,7 +340,9 @@ func (w *workload) issueXChainOperationTx(ctx context.Context) { ) balances, err := xBuilder.GetFTBalance() if err != nil { - log.Printf("failed to fetch X-chain balances: %s", err) + w.log.Error("failed to fetch X-chain balances", + zap.Error(err), + ) assert.Unreachable("failed to fetch X-chain balances", map[string]any{ "worker": w.id, "err": err, @@ -323,7 +359,10 @@ func (w *workload) issueXChainOperationTx(ctx context.Context) { neededBalance = createAssetTxFee + baseTxFee ) if avaxBalance < neededBalance { - log.Printf("skipping X-chain tx issuance due to insufficient balance: %d < %d", avaxBalance, neededBalance) + w.log.Info("skipping X-chain tx issuance due to insufficient balance", + zap.Uint64("balance", avaxBalance), + zap.Uint64("neededBalance", neededBalance), + ) return } @@ -344,10 +383,15 @@ func (w *workload) issueXChainOperationTx(ctx context.Context) { }, ) if err != nil { - log.Printf("failed to issue X-chain create asset transaction: %s", err) + w.log.Warn("failed to issue X-chain create asset transaction", + zap.Error(err), + ) return } - log.Printf("created new X-chain asset %s in %s", createAssetTx.ID(), time.Since(createAssetStartTime)) + w.log.Info("created new X-chain asset", + zap.Stringer("txID", createAssetTx.ID()), + zap.Duration("duration", time.Since(createAssetStartTime)), + ) operationStartTime := time.Now() operationTx, err := xWallet.IssueOperationTxMintProperty( @@ -355,10 +399,15 @@ func (w *workload) issueXChainOperationTx(ctx context.Context) { &owner, ) if err != nil { - log.Printf("failed to issue X-chain operation transaction: %s", err) + w.log.Warn("failed to issue X-chain operation transaction", + zap.Error(err), + ) return } - log.Printf("issued X-chain operation tx %s in %s", operationTx.ID(), time.Since(operationStartTime)) + w.log.Info("issued X-chain operation transaction", + zap.Stringer("txID", operationTx.ID()), + zap.Duration("duration", time.Since(operationStartTime)), + ) w.confirmXChainTx(ctx, createAssetTx) w.verifyXChainTxConsumedUTXOs(ctx, createAssetTx) @@ -374,7 +423,9 @@ func (w *workload) issueXToPTransfer(ctx context.Context) { ) balances, err := xBuilder.GetFTBalance() if err != nil { - log.Printf("failed to fetch X-chain balances: %s", err) + w.log.Warn("failed to fetch X-chain balances", + zap.Error(err), + ) assert.Unreachable("failed to fetch X-chain balances", map[string]any{ "worker": w.id, "err": err, @@ -394,7 +445,10 @@ func (w *workload) issueXToPTransfer(ctx context.Context) { neededBalance = txFees + units.Avax ) if avaxBalance < neededBalance { - log.Printf("skipping X-chain tx issuance due to insufficient balance: %d < %d", avaxBalance, neededBalance) + w.log.Info("skipping X-chain tx issuance due to insufficient balance", + zap.Uint64("balance", avaxBalance), + zap.Uint64("neededBalance", neededBalance), + ) return } @@ -414,10 +468,15 @@ func (w *workload) issueXToPTransfer(ctx context.Context) { }}, ) if err != nil { - log.Printf("failed to issue X-chain export transaction: %s", err) + w.log.Warn("failed to issue X-chain export transaction", + zap.Error(err), + ) return } - log.Printf("created X-chain export transaction %s in %s", exportTx.ID(), time.Since(exportStartTime)) + w.log.Info("created X-chain export transaction", + zap.Stringer("txID", exportTx.ID()), + zap.Duration("duration", time.Since(exportStartTime)), + ) var ( xChainID = xContext.BlockchainID @@ -428,10 +487,15 @@ func (w *workload) issueXToPTransfer(ctx context.Context) { &owner, ) if err != nil { - log.Printf("failed to issue P-chain import transaction: %s", err) + w.log.Warn("failed to issue P-chain import transaction", + zap.Error(err), + ) return } - log.Printf("created P-chain import transaction %s in %s", importTx.ID(), time.Since(importStartTime)) + w.log.Info("created P-chain import transaction", + zap.Stringer("txID", importTx.ID()), + zap.Duration("duration", time.Since(importStartTime)), + ) w.confirmXChainTx(ctx, exportTx) w.verifyXChainTxConsumedUTXOs(ctx, exportTx) @@ -448,7 +512,9 @@ func (w *workload) issuePToXTransfer(ctx context.Context) { ) balances, err := pBuilder.GetBalance() if err != nil { - log.Printf("failed to fetch P-chain balances: %s", err) + w.log.Error("failed to fetch P-chain balances", + zap.Error(err), + ) assert.Unreachable("failed to fetch P-chain balances", map[string]any{ "worker": w.id, "err": err, @@ -467,7 +533,10 @@ func (w *workload) issuePToXTransfer(ctx context.Context) { neededBalance = txFees + units.Schmeckle ) if avaxBalance < neededBalance { - log.Printf("skipping P-chain tx issuance due to insufficient balance: %d < %d", avaxBalance, neededBalance) + w.log.Info("skipping P-chain tx issuance due to insufficient balance", + zap.Uint64("balance", avaxBalance), + zap.Uint64("neededBalance", neededBalance), + ) return } @@ -488,10 +557,15 @@ func (w *workload) issuePToXTransfer(ctx context.Context) { }}, ) if err != nil { - log.Printf("failed to issue P-chain export transaction: %s", err) + w.log.Warn("failed to issue P-chain export transaction", + zap.Error(err), + ) return } - log.Printf("created P-chain export transaction %s in %s", exportTx.ID(), time.Since(exportStartTime)) + w.log.Info("created P-chain export transaction", + zap.Stringer("txID", exportTx.ID()), + zap.Duration("duration", time.Since(exportStartTime)), + ) importStartTime := time.Now() importTx, err := xWallet.IssueImportTx( @@ -499,10 +573,15 @@ func (w *workload) issuePToXTransfer(ctx context.Context) { &owner, ) if err != nil { - log.Printf("failed to issue X-chain import transaction: %s", err) + w.log.Warn("failed to issue X-chain import transaction", + zap.Error(err), + ) return } - log.Printf("created X-chain import transaction %s in %s", importTx.ID(), time.Since(importStartTime)) + w.log.Info("created X-chain import transaction", + zap.Stringer("txID", importTx.ID()), + zap.Duration("duration", time.Since(importStartTime)), + ) w.confirmPChainTx(ctx, exportTx) w.verifyPChainTxConsumedUTXOs(ctx, exportTx) @@ -525,12 +604,21 @@ func (w *workload) confirmXChainTx(ctx context.Context, tx *xtxs.Tx) { for _, uri := range w.uris { client := avm.NewClient(uri, "X") if err := avm.AwaitTxAccepted(client, ctx, txID, 100*time.Millisecond); err != nil { - log.Printf("failed to confirm X-chain transaction %s on %s: %s", txID, uri, err) + w.log.Error("failed to confirm X-chain transaction", + zap.Stringer("txID", txID), + zap.String("uri", uri), + zap.Error(err), + ) return } - log.Printf("confirmed X-chain transaction %s on %s", txID, uri) + w.log.Info("confirmed X-chain transaction", + zap.Stringer("txID", txID), + zap.String("uri", uri), + ) } - log.Printf("confirmed X-chain transaction %s on all nodes", txID) + w.log.Info("confirmed X-chain transaction", + zap.Stringer("txID", txID), + ) } func (w *workload) confirmPChainTx(ctx context.Context, tx *ptxs.Tx) { @@ -538,12 +626,21 @@ func (w *workload) confirmPChainTx(ctx context.Context, tx *ptxs.Tx) { for _, uri := range w.uris { client := platformvm.NewClient(uri) if err := platformvm.AwaitTxAccepted(client, ctx, txID, 100*time.Millisecond); err != nil { - log.Printf("failed to determine the status of a P-chain transaction %s on %s: %s", txID, uri, err) + w.log.Error("failed to confirm P-chain transaction", + zap.Stringer("txID", txID), + zap.String("uri", uri), + zap.Error(err), + ) return } - log.Printf("confirmed P-chain transaction %s on %s", txID, uri) + w.log.Info("confirmed P-chain transaction", + zap.Stringer("txID", txID), + zap.String("uri", uri), + ) } - log.Printf("confirmed P-chain transaction %s on all nodes", txID) + w.log.Info("confirmed P-chain transaction", + zap.Stringer("txID", txID), + ) } func (w *workload) verifyXChainTxConsumedUTXOs(ctx context.Context, tx *xtxs.Tx) { @@ -563,7 +660,10 @@ func (w *workload) verifyXChainTxConsumedUTXOs(ctx context.Context, tx *xtxs.Tx) w.addrs.List(), ) if err != nil { - log.Printf("failed to fetch X-chain UTXOs on %s: %s", uri, err) + w.log.Warn("failed to fetch X-chain UTXOs", + zap.String("uri", uri), + zap.Error(err), + ) return } @@ -571,7 +671,12 @@ func (w *workload) verifyXChainTxConsumedUTXOs(ctx context.Context, tx *xtxs.Tx) for input := range inputs { _, err := utxos.GetUTXO(ctx, chainID, chainID, input) if err != database.ErrNotFound { - log.Printf("failed to verify that X-chain UTXO %s was deleted on %s after %s", input, uri, txID) + w.log.Error("failed to verify that X-chain UTXO was deleted", + zap.String("uri", uri), + zap.Stringer("txID", txID), + zap.Stringer("utxoID", input), + zap.Error(err), + ) assert.Unreachable("failed to verify that X-chain UTXO was deleted", map[string]any{ "worker": w.id, "uri": uri, @@ -582,9 +687,14 @@ func (w *workload) verifyXChainTxConsumedUTXOs(ctx context.Context, tx *xtxs.Tx) return } } - log.Printf("confirmed all X-chain UTXOs consumed by %s are not present on %s", txID, uri) + w.log.Info("confirmed all X-chain UTXOs consumed by tx are not present on node", + zap.Stringer("txID", txID), + zap.String("uri", uri), + ) } - log.Printf("confirmed all X-chain UTXOs consumed by %s are not present on all nodes", txID) + w.log.Info("confirmed all X-chain UTXOs consumed by tx are not present on all nodes", + zap.Stringer("txID", txID), + ) } func (w *workload) verifyPChainTxConsumedUTXOs(ctx context.Context, tx *ptxs.Tx) { @@ -603,7 +713,10 @@ func (w *workload) verifyPChainTxConsumedUTXOs(ctx context.Context, tx *ptxs.Tx) w.addrs.List(), ) if err != nil { - log.Printf("failed to fetch P-chain UTXOs on %s: %s", uri, err) + w.log.Warn("failed to fetch P-chain UTXOs", + zap.String("uri", uri), + zap.Error(err), + ) return } @@ -611,7 +724,12 @@ func (w *workload) verifyPChainTxConsumedUTXOs(ctx context.Context, tx *ptxs.Tx) for input := range inputs { _, err := utxos.GetUTXO(ctx, constants.PlatformChainID, constants.PlatformChainID, input) if err != database.ErrNotFound { - log.Printf("failed to verify that P-chain UTXO %s was deleted on %s after %s", input, uri, txID) + w.log.Error("failed to verify that P-chain UTXO was deleted", + zap.String("uri", uri), + zap.Stringer("txID", txID), + zap.Stringer("utxoID", input), + zap.Error(err), + ) assert.Unreachable("failed to verify that P-chain UTXO was deleted", map[string]any{ "worker": w.id, "uri": uri, @@ -622,7 +740,12 @@ func (w *workload) verifyPChainTxConsumedUTXOs(ctx context.Context, tx *ptxs.Tx) return } } - log.Printf("confirmed all P-chain UTXOs consumed by %s are not present on %s", txID, uri) + w.log.Info("confirmed all P-chain UTXOs consumed by tx are not present on node", + zap.Stringer("txID", txID), + zap.String("uri", uri), + ) } - log.Printf("confirmed all P-chain UTXOs consumed by %s are not present on all nodes", txID) + w.log.Info("confirmed all P-chain UTXOs consumed by tx are not present on all nodes", + zap.Stringer("txID", txID), + ) } diff --git a/tests/antithesis/config.go b/tests/antithesis/config.go index 751cbb33e731..14568fd1df10 100644 --- a/tests/antithesis/config.go +++ b/tests/antithesis/config.go @@ -68,7 +68,7 @@ func NewConfigWithSubnets(tc tests.TestContext, defaultNetwork *tmpnet.Network, // Use the network configuration provided if len(uris) != 0 { - require.NoError(tc, awaitHealthyNodes(tc.DefaultContext(), uris), "failed to see healthy nodes") + require.NoError(tc, awaitHealthyNodes(tc.DefaultContext(), tc.Log(), uris), "failed to see healthy nodes") return &Config{ URIs: uris, ChainIDs: chainIDs, diff --git a/tests/antithesis/init_db.go b/tests/antithesis/init_db.go index 7da69082d805..90a60307a6d1 100644 --- a/tests/antithesis/init_db.go +++ b/tests/antithesis/init_db.go @@ -33,7 +33,7 @@ func initBootstrapDB(network *tmpnet.Network, avalancheGoPath string, pluginDir defer cancel() if err := tmpnet.BootstrapNewNetwork( ctx, - tests.NewDefaultTestLogger(), + tests.NewDefaultLogger(""), network, "", avalancheGoPath, diff --git a/tests/antithesis/node_health.go b/tests/antithesis/node_health.go index 4015f3c9cf23..e5f524b65a67 100644 --- a/tests/antithesis/node_health.go +++ b/tests/antithesis/node_health.go @@ -6,39 +6,50 @@ package antithesis import ( "context" "fmt" - "log" "time" + "go.uber.org/zap" + "github.com/ava-labs/avalanchego/api/health" + "github.com/ava-labs/avalanchego/utils/logging" ) // Waits for the nodes at the provided URIs to report healthy. -func awaitHealthyNodes(ctx context.Context, uris []string) error { +func awaitHealthyNodes(ctx context.Context, log logging.Logger, uris []string) error { for _, uri := range uris { - if err := awaitHealthyNode(ctx, uri); err != nil { + if err := awaitHealthyNode(ctx, log, uri); err != nil { return err } } - log.Println("all nodes reported healthy") + log.Info("all nodes reported healthy") return nil } -func awaitHealthyNode(ctx context.Context, uri string) error { +func awaitHealthyNode(ctx context.Context, log logging.Logger, uri string) error { client := health.NewClient(uri) ticker := time.NewTicker(100 * time.Millisecond) defer ticker.Stop() - log.Printf("awaiting node health at %s", uri) + log.Info("awaiting node health", + zap.String("uri", uri), + ) for { res, err := client.Health(ctx, nil) switch { case err != nil: - log.Printf("node couldn't be reached at %s", uri) + log.Error("failed to reach node", + zap.String("uri", uri), + zap.Error(err), + ) case res.Healthy: - log.Printf("node reported healthy at %s", uri) + log.Info("node reported healthy", + zap.String("uri", uri), + ) return nil default: - log.Printf("node reported unhealthy at %s", uri) + log.Info("node reported unhealthy", + zap.String("uri", uri), + ) } select { diff --git a/tests/antithesis/xsvm/gencomposeconfig/main.go b/tests/antithesis/xsvm/gencomposeconfig/main.go index e038daac0893..8bed3a982133 100644 --- a/tests/antithesis/xsvm/gencomposeconfig/main.go +++ b/tests/antithesis/xsvm/gencomposeconfig/main.go @@ -4,9 +4,10 @@ package main import ( - "log" + "go.uber.org/zap" "github.com/ava-labs/avalanchego/genesis" + "github.com/ava-labs/avalanchego/tests" "github.com/ava-labs/avalanchego/tests/antithesis" "github.com/ava-labs/avalanchego/tests/fixture/subnet" "github.com/ava-labs/avalanchego/tests/fixture/tmpnet" @@ -21,6 +22,8 @@ func main() { subnet.NewXSVMOrPanic("xsvm", genesis.VMRQKey, network.Nodes...), } if err := antithesis.GenerateComposeConfig(network, baseImageName, "" /* runtimePluginDir */); err != nil { - log.Fatalf("failed to generate compose config: %v", err) + tests.NewDefaultLogger("").Fatal("failed to generate compose config", + zap.Error(err), + ) } } diff --git a/tests/antithesis/xsvm/main.go b/tests/antithesis/xsvm/main.go index a51a3e88f505..e9f735f8f5e4 100644 --- a/tests/antithesis/xsvm/main.go +++ b/tests/antithesis/xsvm/main.go @@ -6,13 +6,14 @@ package main import ( "context" "crypto/rand" - "log" + "fmt" "math/big" "time" "github.com/antithesishq/antithesis-sdk-go/assert" "github.com/antithesishq/antithesis-sdk-go/lifecycle" "github.com/stretchr/testify/require" + "go.uber.org/zap" "github.com/ava-labs/avalanchego/genesis" "github.com/ava-labs/avalanchego/ids" @@ -21,6 +22,7 @@ import ( "github.com/ava-labs/avalanchego/tests/fixture/subnet" "github.com/ava-labs/avalanchego/tests/fixture/tmpnet" "github.com/ava-labs/avalanchego/utils/crypto/secp256k1" + "github.com/ava-labs/avalanchego/utils/logging" "github.com/ava-labs/avalanchego/utils/set" "github.com/ava-labs/avalanchego/utils/units" "github.com/ava-labs/avalanchego/vms/example/xsvm/api" @@ -36,7 +38,8 @@ const ( ) func main() { - tc := tests.NewTestContext() + // TODO(marun) Support choosing the log format + tc := tests.NewTestContext(tests.NewDefaultLogger("")) defer tc.Cleanup() require := require.New(tc) @@ -54,14 +57,19 @@ func main() { ctx := tests.DefaultNotifyContext(c.Duration, tc.DeferCleanup) require.Len(c.ChainIDs, 1) - log.Printf("CHAIN IDS: %v", c.ChainIDs) + tc.Log().Debug("raw chain ID", + zap.String("chainID", c.ChainIDs[0]), + ) chainID, err := ids.FromString(c.ChainIDs[0]) require.NoError(err, "failed to parse chainID") - - log.Printf("Using uris %v and chainID %s", c.URIs, chainID) + tc.Log().Info("node and chain configuration", + zap.Stringer("chainID", chainID), + zap.Strings("uris", c.URIs), + ) genesisWorkload := &workload{ id: 0, + log: tests.NewDefaultLogger(fmt.Sprintf("worker %d", 0)), chainID: chainID, key: genesis.VMRQKey, addrs: set.Of(genesis.VMRQKey.Address()), @@ -92,12 +100,16 @@ func main() { }, ) require.NoError(err, "failed to issue initial funding transfer") - log.Printf("issued initial funding transfer %s in %s", transferTxStatus.TxID, time.Since(baseStartTime)) + tc.Log().Info("issued initial funding transfer", + zap.Stringer("txID", transferTxStatus.TxID), + zap.Duration("duration", time.Since(baseStartTime)), + ) genesisWorkload.confirmTransferTx(ctx, transferTxStatus) workloads[i] = &workload{ id: i, + log: tests.NewDefaultLogger(fmt.Sprintf("worker %d", i)), chainID: chainID, key: key, addrs: set.Of(addr), @@ -118,6 +130,7 @@ func main() { type workload struct { id int + log logging.Logger chainID ids.ID key *secp256k1.PrivateKey addrs set.Set[ids.ShortID] @@ -127,7 +140,7 @@ type workload struct { func (w *workload) run(ctx context.Context) { timer := timerpkg.StoppedTimer() - tc := tests.NewTestContext() + tc := tests.NewTestContext(w.log) defer tc.Cleanup() require := require.New(tc) @@ -136,14 +149,19 @@ func (w *workload) run(ctx context.Context) { client := api.NewClient(uri, w.chainID.String()) balance, err := client.Balance(ctx, w.key.Address(), w.chainID) require.NoError(err, "failed to fetch balance") - log.Printf("worker %d starting with a balance of %d", w.id, balance) + w.log.Info("worker starting", + zap.Int("worker", w.id), + zap.Uint64("balance", balance), + ) assert.Reachable("worker starting", map[string]any{ "worker": w.id, "balance": balance, }) for { - log.Printf("worker %d executing transfer", w.id) + w.log.Info("executing transfer", + zap.Int("worker", w.id), + ) destAddress, _ := w.addrs.Peek() txStatus, err := transfer.Transfer( ctx, @@ -157,9 +175,16 @@ func (w *workload) run(ctx context.Context) { }, ) if err != nil { - log.Printf("worker %d failed to issue transfer: %s", w.id, err) + w.log.Error("failed to issue transfer", + zap.Int("worker", w.id), + zap.Error(err), + ) } else { - log.Printf("worker %d issued transfer %s in %s", w.id, txStatus.TxID, time.Since(txStatus.StartTime)) + w.log.Info("issued transfer", + zap.Int("worker", w.id), + zap.Stringer("txID", txStatus.TxID), + zap.Duration("duration", time.Since(txStatus.StartTime)), + ) w.confirmTransferTx(ctx, txStatus) } @@ -179,9 +204,17 @@ func (w *workload) confirmTransferTx(ctx context.Context, tx *status.TxIssuance) for _, uri := range w.uris { client := api.NewClient(uri, w.chainID.String()) if err := api.AwaitTxAccepted(ctx, client, w.key.Address(), tx.Nonce, PollingInterval); err != nil { - log.Printf("worker %d failed to confirm transaction %s on %s: %s", w.id, tx.TxID, uri, err) + w.log.Error("failed to confirm transaction", + zap.Int("worker", w.id), + zap.Stringer("txID", tx.TxID), + zap.String("uri", uri), + zap.Error(err), + ) return } } - log.Printf("worker %d confirmed transaction %s on all nodes", w.id, tx.TxID) + w.log.Info("confirmed transaction on all nodes", + zap.Int("worker", w.id), + zap.Stringer("txID", tx.TxID), + ) } diff --git a/tests/fixture/e2e/ginkgo_test_context.go b/tests/fixture/e2e/ginkgo_test_context.go index eae87c1faca9..2f70fa9afcd1 100644 --- a/tests/fixture/e2e/ginkgo_test_context.go +++ b/tests/fixture/e2e/ginkgo_test_context.go @@ -33,7 +33,7 @@ type GinkgoTestContext struct { func NewTestContext() *GinkgoTestContext { return &GinkgoTestContext{ - logger: tests.NewTestLogger(&ginkgoWriteCloser{}), + logger: tests.NewSimpleLogger(&ginkgoWriteCloser{}), } } diff --git a/tests/fixture/e2e/helpers.go b/tests/fixture/e2e/helpers.go index f1831f72a98c..ffa1b88ab0a7 100644 --- a/tests/fixture/e2e/helpers.go +++ b/tests/fixture/e2e/helpers.go @@ -88,11 +88,7 @@ func NewWallet(tc tests.TestContext, keychain *secp256k1fx.Keychain, nodeURI tmp // OutputWalletBalances outputs the X-Chain and P-Chain balances of the provided wallet. func OutputWalletBalances(tc tests.TestContext, wallet primary.Wallet) { - xAVAX, pAVAX := GetWalletBalances(tc, wallet) - tc.Log().Info("wallet balances in nAVAX", - zap.Uint64("xChain", xAVAX), - zap.Uint64("pChain", pAVAX), - ) + _, _ = GetWalletBalances(tc, wallet) } // GetWalletBalances retrieves the X-Chain and P-Chain balances of the provided wallet. @@ -114,6 +110,10 @@ func GetWalletBalances(tc tests.TestContext, wallet primary.Wallet) (uint64, uin xAVAX = xBalances[avaxAssetID] pAVAX = pBalances[avaxAssetID] ) + tc.Log().Info("wallet balances in nAVAX", + zap.Uint64("xChain", xAVAX), + zap.Uint64("pChain", pAVAX), + ) return xAVAX, pAVAX } diff --git a/tests/fixture/tmpnet/cmd/main.go b/tests/fixture/tmpnet/cmd/main.go index 2620e4f0ab87..96859fba4d8f 100644 --- a/tests/fixture/tmpnet/cmd/main.go +++ b/tests/fixture/tmpnet/cmd/main.go @@ -15,8 +15,8 @@ import ( "github.com/spf13/cobra" "go.uber.org/zap" + "github.com/ava-labs/avalanchego/tests" "github.com/ava-labs/avalanchego/tests/fixture/tmpnet" - "github.com/ava-labs/avalanchego/utils/logging" "github.com/ava-labs/avalanchego/version" ) @@ -68,7 +68,7 @@ func main() { return errAvalancheGoRequired } - log, err := loggerForFormat(rawLogFormat) + log, err := tests.LoggerForFormat("", rawLogFormat) if err != nil { return err } @@ -148,7 +148,7 @@ func main() { if len(networkDir) == 0 { return errNetworkDirRequired } - log, err := loggerForFormat(rawLogFormat) + log, err := tests.LoggerForFormat("", rawLogFormat) if err != nil { return err } @@ -165,12 +165,3 @@ func main() { } os.Exit(0) } - -func loggerForFormat(rawLogFormat string) (logging.Logger, error) { - writeCloser := os.Stdout - logFormat, err := logging.ToFormat(rawLogFormat, writeCloser.Fd()) - if err != nil { - return nil, err - } - return logging.NewLogger("", logging.NewWrappedCore(logging.Verbo, writeCloser, logFormat.ConsoleEncoder())), nil -} diff --git a/tests/fixture/tmpnet/network_test.go b/tests/fixture/tmpnet/network_test.go index feba6f99225b..f13628b9d742 100644 --- a/tests/fixture/tmpnet/network_test.go +++ b/tests/fixture/tmpnet/network_test.go @@ -4,6 +4,7 @@ package tmpnet import ( + "os" "testing" "github.com/stretchr/testify/require" @@ -17,7 +18,7 @@ func TestNetworkSerialization(t *testing.T) { tmpDir := t.TempDir() network := NewDefaultNetwork("testnet") - require.NoError(network.EnsureDefaultConfig(tests.NewDefaultTestLogger(), "/path/to/avalanche/go", "")) + require.NoError(network.EnsureDefaultConfig(tests.NewSimpleLogger(os.Stdout), "/path/to/avalanche/go", "")) require.NoError(network.Create(tmpDir)) // Ensure node runtime is initialized require.NoError(network.readNodes()) diff --git a/tests/log.go b/tests/log.go index 77877369bba3..8e6271b8c014 100644 --- a/tests/log.go +++ b/tests/log.go @@ -12,8 +12,8 @@ import ( "github.com/ava-labs/avalanchego/utils/logging" ) -// Define a default encoder appropriate for testing -var defaultEncoderConfig = zapcore.EncoderConfig{ +// Define a simple encoder config appropriate for testing +var simpleEncoderConfig = zapcore.EncoderConfig{ TimeKey: "", LevelKey: "level", NameKey: "", @@ -24,19 +24,33 @@ var defaultEncoderConfig = zapcore.EncoderConfig{ EncodeLevel: zapcore.LowercaseLevelEncoder, } -// NewDefaultTestLogger returns a logger that writes to stdout -func NewDefaultTestLogger() logging.Logger { - return NewTestLogger(os.Stdout) -} - -// NewDefaultTestLogger returns a logger for the specified WriteCloser -func NewTestLogger(writeCloser io.WriteCloser) logging.Logger { +// NewSimpleLogger returns a logger with limited output for the specified WriteCloser +func NewSimpleLogger(writeCloser io.WriteCloser) logging.Logger { return logging.NewLogger( "", logging.NewWrappedCore( logging.Verbo, writeCloser, - zapcore.NewConsoleEncoder(defaultEncoderConfig), + zapcore.NewConsoleEncoder(simpleEncoderConfig), ), ) } + +func NewDefaultLogger(prefix string) logging.Logger { + log, err := LoggerForFormat(prefix, "auto") + if err != nil { + // This should never happen since auto is a valid log format + panic(err) + } + return log +} + +// TODO(marun) Does/should the logging package have a function like this? +func LoggerForFormat(prefix string, rawLogFormat string) (logging.Logger, error) { + writeCloser := os.Stdout + logFormat, err := logging.ToFormat(rawLogFormat, writeCloser.Fd()) + if err != nil { + return nil, err + } + return logging.NewLogger(prefix, logging.NewWrappedCore(logging.Verbo, writeCloser, logFormat.ConsoleEncoder())), nil +} diff --git a/tests/simple_test_context.go b/tests/simple_test_context.go index b5597718da96..3cadba134b98 100644 --- a/tests/simple_test_context.go +++ b/tests/simple_test_context.go @@ -18,19 +18,19 @@ import ( const failNowMessage = "SimpleTestContext.FailNow called" type SimpleTestContext struct { - logger logging.Logger + log logging.Logger cleanupFuncs []func() cleanupCalled bool } -func NewTestContext() *SimpleTestContext { +func NewTestContext(log logging.Logger) *SimpleTestContext { return &SimpleTestContext{ - logger: logging.NewLogger("", logging.NewWrappedCore(logging.Verbo, os.Stdout, logging.Plain.ConsoleEncoder())), + log: log, } } func (tc *SimpleTestContext) Errorf(format string, args ...interface{}) { - tc.logger.Error(fmt.Sprintf(format, args...)) + tc.log.Error(fmt.Sprintf(format, args...)) } func (*SimpleTestContext) FailNow() { @@ -90,7 +90,7 @@ func (tc *SimpleTestContext) By(_ string, _ ...func()) { } func (tc *SimpleTestContext) Log() logging.Logger { - return tc.logger + return tc.log } // Helper simplifying use of a timed context by canceling the context on ginkgo teardown. From 0f24b3eb3ef382c424e03ccbdc69a8879b3634a4 Mon Sep 17 00:00:00 2001 From: marun Date: Thu, 21 Nov 2024 18:17:50 +0100 Subject: [PATCH 07/22] Update tests/antithesis/avalanchego/main.go Co-authored-by: Stephen Buttolph Signed-off-by: marun --- tests/antithesis/avalanchego/main.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/antithesis/avalanchego/main.go b/tests/antithesis/avalanchego/main.go index e89c58cef5d9..b6875144dbdb 100644 --- a/tests/antithesis/avalanchego/main.go +++ b/tests/antithesis/avalanchego/main.go @@ -604,7 +604,7 @@ func (w *workload) confirmXChainTx(ctx context.Context, tx *xtxs.Tx) { for _, uri := range w.uris { client := avm.NewClient(uri, "X") if err := avm.AwaitTxAccepted(client, ctx, txID, 100*time.Millisecond); err != nil { - w.log.Error("failed to confirm X-chain transaction", + w.log.Warn("failed to confirm X-chain transaction", zap.Stringer("txID", txID), zap.String("uri", uri), zap.Error(err), From 35ba87955eddcc13f2401cb146c2c109fac0a1e5 Mon Sep 17 00:00:00 2001 From: marun Date: Thu, 21 Nov 2024 18:19:17 +0100 Subject: [PATCH 08/22] Update tests/antithesis/avalanchego/main.go Co-authored-by: Stephen Buttolph Signed-off-by: marun --- tests/antithesis/avalanchego/main.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/antithesis/avalanchego/main.go b/tests/antithesis/avalanchego/main.go index b6875144dbdb..c06adccbcb90 100644 --- a/tests/antithesis/avalanchego/main.go +++ b/tests/antithesis/avalanchego/main.go @@ -626,7 +626,7 @@ func (w *workload) confirmPChainTx(ctx context.Context, tx *ptxs.Tx) { for _, uri := range w.uris { client := platformvm.NewClient(uri) if err := platformvm.AwaitTxAccepted(client, ctx, txID, 100*time.Millisecond); err != nil { - w.log.Error("failed to confirm P-chain transaction", + w.log.Warn("failed to confirm P-chain transaction", zap.Stringer("txID", txID), zap.String("uri", uri), zap.Error(err), From 7cd40f16cee6588fac4ef66a319a0f3a4874c960 Mon Sep 17 00:00:00 2001 From: marun Date: Thu, 21 Nov 2024 18:19:50 +0100 Subject: [PATCH 09/22] Update tests/antithesis/xsvm/main.go Co-authored-by: Stephen Buttolph Signed-off-by: marun --- tests/antithesis/xsvm/main.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/antithesis/xsvm/main.go b/tests/antithesis/xsvm/main.go index e9f735f8f5e4..7828ab3df0cc 100644 --- a/tests/antithesis/xsvm/main.go +++ b/tests/antithesis/xsvm/main.go @@ -175,7 +175,7 @@ func (w *workload) run(ctx context.Context) { }, ) if err != nil { - w.log.Error("failed to issue transfer", + w.log.Warn("failed to issue transfer", zap.Int("worker", w.id), zap.Error(err), ) From 0ea4cd54bf88327f10496ad7c861d4d109493ce0 Mon Sep 17 00:00:00 2001 From: marun Date: Thu, 21 Nov 2024 18:20:08 +0100 Subject: [PATCH 10/22] Update tests/antithesis/xsvm/main.go Co-authored-by: Stephen Buttolph Signed-off-by: marun --- tests/antithesis/xsvm/main.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/antithesis/xsvm/main.go b/tests/antithesis/xsvm/main.go index 7828ab3df0cc..70ac0d16b406 100644 --- a/tests/antithesis/xsvm/main.go +++ b/tests/antithesis/xsvm/main.go @@ -204,7 +204,7 @@ func (w *workload) confirmTransferTx(ctx context.Context, tx *status.TxIssuance) for _, uri := range w.uris { client := api.NewClient(uri, w.chainID.String()) if err := api.AwaitTxAccepted(ctx, client, w.key.Address(), tx.Nonce, PollingInterval); err != nil { - w.log.Error("failed to confirm transaction", + w.log.Warn("failed to confirm transaction", zap.Int("worker", w.id), zap.Stringer("txID", tx.TxID), zap.String("uri", uri), From 81e0c55997bb005fa58b5c0c7032f64db8a05d8c Mon Sep 17 00:00:00 2001 From: marun Date: Thu, 21 Nov 2024 18:22:34 +0100 Subject: [PATCH 11/22] Update tests/e2e/x/transfer/virtuous.go Co-authored-by: Stephen Buttolph Signed-off-by: marun --- tests/e2e/x/transfer/virtuous.go | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/tests/e2e/x/transfer/virtuous.go b/tests/e2e/x/transfer/virtuous.go index c77aec5b8285..a072a3764ae8 100644 --- a/tests/e2e/x/transfer/virtuous.go +++ b/tests/e2e/x/transfer/virtuous.go @@ -224,13 +224,13 @@ var _ = e2e.DescribeXChainSerial("[Virtuous Transfer Tx AVAX]", func() { }) tc.Log().Info("issuing transfer", - zap.Stringer("fromAddress", shortAddrs[fromIdx]), - zap.Uint64("senderOrigBal", senderOrigBal), - zap.Uint64("senderNewBal", senderNewBal), + zap.Stringer("sender", shortAddrs[fromIdx]), + zap.Uint64("senderOriginalBalance", senderOrigBal), + zap.Uint64("senderNewBalance", senderNewBal), zap.Uint64("amountToTransfer", amountToTransfer), - zap.Stringer("toAddress", shortAddrs[toIdx]), - zap.Uint64("receiverOrigBal", receiverOrigBal), - zap.Uint64("receiverNewBal", receiverNewBal), + zap.Stringer("receiver", shortAddrs[toIdx]), + zap.Uint64("receiverOriginalBalance", receiverOrigBal), + zap.Uint64("receiverNewBalance", receiverNewBal), ) tx, err := wallets[fromIdx].X().IssueBaseTx( From 1b0abce57cf1aad5cf681e67037d1f4ac15db919 Mon Sep 17 00:00:00 2001 From: marun Date: Thu, 21 Nov 2024 18:23:04 +0100 Subject: [PATCH 12/22] Update tests/fixture/bootstrapmonitor/e2e/e2e_test.go Co-authored-by: Stephen Buttolph Signed-off-by: marun --- tests/fixture/bootstrapmonitor/e2e/e2e_test.go | 1 - 1 file changed, 1 deletion(-) diff --git a/tests/fixture/bootstrapmonitor/e2e/e2e_test.go b/tests/fixture/bootstrapmonitor/e2e/e2e_test.go index 13508a7ec0d2..d9a91ec8916f 100644 --- a/tests/fixture/bootstrapmonitor/e2e/e2e_test.go +++ b/tests/fixture/bootstrapmonitor/e2e/e2e_test.go @@ -441,7 +441,6 @@ func waitForLogOutput(tc tests.TestContext, clientset *kubernetes.Clientset, nam zap.String("pod", podName), zap.String("container", containerName), ) - tc.Log().Info(strings.Repeat("=", 80)) req := clientset.CoreV1().Pods(namespace).GetLogs(podName, &corev1.PodLogOptions{ Container: containerName, From bde8d7239526de3f2a7b6def264b09bc55735ea0 Mon Sep 17 00:00:00 2001 From: marun Date: Thu, 21 Nov 2024 18:23:57 +0100 Subject: [PATCH 13/22] Update tests/fixture/e2e/helpers.go Co-authored-by: Stephen Buttolph Signed-off-by: marun --- tests/fixture/e2e/helpers.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/fixture/e2e/helpers.go b/tests/fixture/e2e/helpers.go index ffa1b88ab0a7..24b7daa674b2 100644 --- a/tests/fixture/e2e/helpers.go +++ b/tests/fixture/e2e/helpers.go @@ -288,7 +288,7 @@ func StartNetwork( // Symlink the path of the created network to the default owner path (e.g. latest_avalanchego-e2e) // to enable easy discovery for reuse. require.NoError(os.Symlink(network.Dir, symlinkPath)) - tc.Log().Warn("symlinked network dir for reuse", + tc.Log().Info("symlinked network dir for reuse", zap.String("networkDir", network.Dir), zap.String("symlinkPath", symlinkPath), ) From a6cad4ada85d8007622a866b160544a9914c1226 Mon Sep 17 00:00:00 2001 From: marun Date: Thu, 21 Nov 2024 18:24:10 +0100 Subject: [PATCH 14/22] Update tests/fixture/e2e/helpers.go Co-authored-by: Stephen Buttolph Signed-off-by: marun --- tests/fixture/e2e/helpers.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/fixture/e2e/helpers.go b/tests/fixture/e2e/helpers.go index 24b7daa674b2..ff2f5fec8717 100644 --- a/tests/fixture/e2e/helpers.go +++ b/tests/fixture/e2e/helpers.go @@ -304,7 +304,7 @@ func StartNetwork( } if skipShutdown { - tc.Log().Warn("skipping shutdown for network", + tc.Log().Info("skipping shutdown for network", zap.String("networkDir", network.Dir), ) return From 9c4e037fefdf37401a309195355f12db666b7e4a Mon Sep 17 00:00:00 2001 From: marun Date: Thu, 21 Nov 2024 18:24:33 +0100 Subject: [PATCH 15/22] Update tests/fixture/e2e/helpers.go Co-authored-by: Stephen Buttolph Signed-off-by: marun --- tests/fixture/e2e/helpers.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/fixture/e2e/helpers.go b/tests/fixture/e2e/helpers.go index ff2f5fec8717..d61689c5b3fa 100644 --- a/tests/fixture/e2e/helpers.go +++ b/tests/fixture/e2e/helpers.go @@ -296,7 +296,7 @@ func StartNetwork( tc.DeferCleanup(func() { if reuseNetwork { - tc.Log().Warn("skipping shutdown for network intended for reuse", + tc.Log().Info("skipping shutdown for network intended for reuse", zap.String("networkDir", network.Dir), zap.String("symlinkPath", symlinkPath), ) From 292016a43d31e3af946f5a2793e4083e4ef01b7c Mon Sep 17 00:00:00 2001 From: Maru Newby Date: Thu, 21 Nov 2024 18:41:53 +0100 Subject: [PATCH 16/22] fixup: Respond to review feedback --- tests/antithesis/avalanchego/gencomposeconfig/main.go | 3 +++ tests/antithesis/xsvm/gencomposeconfig/main.go | 3 +++ tests/e2e/etna/suites.go | 7 ++----- tests/fixture/tmpnet/cmd/main.go | 3 ++- tests/log.go | 2 +- 5 files changed, 11 insertions(+), 7 deletions(-) diff --git a/tests/antithesis/avalanchego/gencomposeconfig/main.go b/tests/antithesis/avalanchego/gencomposeconfig/main.go index 1681ad78e421..dcdd6e8c63c2 100644 --- a/tests/antithesis/avalanchego/gencomposeconfig/main.go +++ b/tests/antithesis/avalanchego/gencomposeconfig/main.go @@ -4,6 +4,8 @@ package main import ( + "os" + "go.uber.org/zap" "github.com/ava-labs/avalanchego/tests" @@ -20,5 +22,6 @@ func main() { tests.NewDefaultLogger("").Fatal("failed to generate compose config", zap.Error(err), ) + os.Exit(1) } } diff --git a/tests/antithesis/xsvm/gencomposeconfig/main.go b/tests/antithesis/xsvm/gencomposeconfig/main.go index 8bed3a982133..b292cf89cefb 100644 --- a/tests/antithesis/xsvm/gencomposeconfig/main.go +++ b/tests/antithesis/xsvm/gencomposeconfig/main.go @@ -4,6 +4,8 @@ package main import ( + "os" + "go.uber.org/zap" "github.com/ava-labs/avalanchego/genesis" @@ -25,5 +27,6 @@ func main() { tests.NewDefaultLogger("").Fatal("failed to generate compose config", zap.Error(err), ) + os.Exit(1) } } diff --git a/tests/e2e/etna/suites.go b/tests/e2e/etna/suites.go index 703249e0abdd..fb033726d6ce 100644 --- a/tests/e2e/etna/suites.go +++ b/tests/e2e/etna/suites.go @@ -29,13 +29,10 @@ var _ = ginkgo.Describe("[Etna]", func() { require.NoError(err) now := time.Now() - msg := "etna is activated" - if !upgrades.IsEtnaActivated(now) { - msg = "etna is not activated" - } - tc.Log().Info(msg, + tc.Log().Info("detected if Etna is activated", zap.Time("now", now), zap.Time("etnaTime", upgrades.EtnaTime), + zap.Bool("isEtnaActivated", upgrades.IsEtnaActivated(now)), ) }) }) diff --git a/tests/fixture/tmpnet/cmd/main.go b/tests/fixture/tmpnet/cmd/main.go index 96859fba4d8f..f8eff5782c51 100644 --- a/tests/fixture/tmpnet/cmd/main.go +++ b/tests/fixture/tmpnet/cmd/main.go @@ -17,6 +17,7 @@ import ( "github.com/ava-labs/avalanchego/tests" "github.com/ava-labs/avalanchego/tests/fixture/tmpnet" + "github.com/ava-labs/avalanchego/utils/logging" "github.com/ava-labs/avalanchego/version" ) @@ -37,7 +38,7 @@ func main() { Short: "tmpnetctl commands", } rootCmd.PersistentFlags().StringVar(&networkDir, "network-dir", os.Getenv(tmpnet.NetworkDirEnvName), "The path to the configuration directory of a temporary network") - rootCmd.PersistentFlags().StringVar(&rawLogFormat, "log-format", "auto", "The structure of log format. Defaults to 'auto' which formats terminal-like logs, when the output is a terminal. Otherwise, should be one of {auto, plain, colors, json}") + rootCmd.PersistentFlags().StringVar(&rawLogFormat, "log-format", logging.AutoString, logging.FormatDescription) versionCmd := &cobra.Command{ Use: "version", diff --git a/tests/log.go b/tests/log.go index 8e6271b8c014..c3aea0d30bfc 100644 --- a/tests/log.go +++ b/tests/log.go @@ -37,7 +37,7 @@ func NewSimpleLogger(writeCloser io.WriteCloser) logging.Logger { } func NewDefaultLogger(prefix string) logging.Logger { - log, err := LoggerForFormat(prefix, "auto") + log, err := LoggerForFormat(prefix, logging.AutoString) if err != nil { // This should never happen since auto is a valid log format panic(err) From b960199f2dd7b3ba1da3734f01e6536f844059f7 Mon Sep 17 00:00:00 2001 From: Maru Newby Date: Thu, 21 Nov 2024 20:38:37 +0100 Subject: [PATCH 17/22] fixup: Rename and move ginkgo-specific logger and fix level output --- tests/fixture/e2e/ginkgo_test_context.go | 29 +++++++++++++++++++++++- tests/log.go | 27 ---------------------- utils/logging/format.go | 4 ++-- 3 files changed, 30 insertions(+), 30 deletions(-) diff --git a/tests/fixture/e2e/ginkgo_test_context.go b/tests/fixture/e2e/ginkgo_test_context.go index 2f70fa9afcd1..57299d57ed89 100644 --- a/tests/fixture/e2e/ginkgo_test_context.go +++ b/tests/fixture/e2e/ginkgo_test_context.go @@ -5,10 +5,12 @@ package e2e import ( "context" + "io" "time" "github.com/onsi/ginkgo/v2" "github.com/stretchr/testify/require" + "go.uber.org/zap/zapcore" "github.com/ava-labs/avalanchego/tests" "github.com/ava-labs/avalanchego/utils/logging" @@ -27,13 +29,38 @@ func (*ginkgoWriteCloser) Close() error { return nil } +// Define a simple encoder config appropriate for logging with ginkgo +var ginkgoEncoderConfig = zapcore.EncoderConfig{ + // Time, name and caller are omitted for consistency with previous output. + // TODO(marun) Maybe revisit this decision + TimeKey: "", + LevelKey: "level", + NameKey: "", + CallerKey: "", + MessageKey: "msg", + StacktraceKey: "stacktrace", + EncodeLevel: logging.ConsoleColorLevelEncoder, +} + +// NewGinkgoLogger returns a logger with limited output for the specified WriteCloser +func newGinkgoLogger(writeCloser io.WriteCloser) logging.Logger { + return logging.NewLogger( + "", + logging.NewWrappedCore( + logging.Verbo, + writeCloser, + zapcore.NewConsoleEncoder(ginkgoEncoderConfig), + ), + ) +} + type GinkgoTestContext struct { logger logging.Logger } func NewTestContext() *GinkgoTestContext { return &GinkgoTestContext{ - logger: tests.NewSimpleLogger(&ginkgoWriteCloser{}), + logger: newGinkgoLogger(&ginkgoWriteCloser{}), } } diff --git a/tests/log.go b/tests/log.go index c3aea0d30bfc..a431feb3c1ec 100644 --- a/tests/log.go +++ b/tests/log.go @@ -4,38 +4,11 @@ package tests import ( - "io" "os" - "go.uber.org/zap/zapcore" - "github.com/ava-labs/avalanchego/utils/logging" ) -// Define a simple encoder config appropriate for testing -var simpleEncoderConfig = zapcore.EncoderConfig{ - TimeKey: "", - LevelKey: "level", - NameKey: "", - CallerKey: "", - MessageKey: "msg", - StacktraceKey: "stacktrace", - // TODO(marun) Figure out why this is outputting e.g. `Level(-6)` instead of `INFO` - EncodeLevel: zapcore.LowercaseLevelEncoder, -} - -// NewSimpleLogger returns a logger with limited output for the specified WriteCloser -func NewSimpleLogger(writeCloser io.WriteCloser) logging.Logger { - return logging.NewLogger( - "", - logging.NewWrappedCore( - logging.Verbo, - writeCloser, - zapcore.NewConsoleEncoder(simpleEncoderConfig), - ), - ) -} - func NewDefaultLogger(prefix string) logging.Logger { log, err := LoggerForFormat(prefix, logging.AutoString) if err != nil { diff --git a/utils/logging/format.go b/utils/logging/format.go index c591f15ece84..e649cddec7ae 100644 --- a/utils/logging/format.go +++ b/utils/logging/format.go @@ -100,7 +100,7 @@ func (f Format) WrapPrefix(prefix string) string { func (f Format) ConsoleEncoder() zapcore.Encoder { switch f { case Colors: - return zapcore.NewConsoleEncoder(newTermEncoderConfig(consoleColorLevelEncoder)) + return zapcore.NewConsoleEncoder(newTermEncoderConfig(ConsoleColorLevelEncoder)) case JSON: return zapcore.NewJSONEncoder(jsonEncoderConfig) default: @@ -133,7 +133,7 @@ func jsonLevelEncoder(l zapcore.Level, enc zapcore.PrimitiveArrayEncoder) { enc.AppendString(Level(l).LowerString()) } -func consoleColorLevelEncoder(l zapcore.Level, enc zapcore.PrimitiveArrayEncoder) { +func ConsoleColorLevelEncoder(l zapcore.Level, enc zapcore.PrimitiveArrayEncoder) { s, ok := levelToCapitalColorString[Level(l)] if !ok { s = unknownLevelColor.Wrap(l.String()) From 34ababd6219e424f0e76be024a0b1a670848e973 Mon Sep 17 00:00:00 2001 From: Maru Newby Date: Thu, 21 Nov 2024 20:55:30 +0100 Subject: [PATCH 18/22] fixup: Update tmpnet network test to define its own logger --- tests/fixture/tmpnet/network_test.go | 14 ++++++++++++-- 1 file changed, 12 insertions(+), 2 deletions(-) diff --git a/tests/fixture/tmpnet/network_test.go b/tests/fixture/tmpnet/network_test.go index f13628b9d742..a350351298d7 100644 --- a/tests/fixture/tmpnet/network_test.go +++ b/tests/fixture/tmpnet/network_test.go @@ -8,8 +8,9 @@ import ( "testing" "github.com/stretchr/testify/require" + "go.uber.org/zap/zapcore" - "github.com/ava-labs/avalanchego/tests" + "github.com/ava-labs/avalanchego/utils/logging" ) func TestNetworkSerialization(t *testing.T) { @@ -18,7 +19,16 @@ func TestNetworkSerialization(t *testing.T) { tmpDir := t.TempDir() network := NewDefaultNetwork("testnet") - require.NoError(network.EnsureDefaultConfig(tests.NewSimpleLogger(os.Stdout), "/path/to/avalanche/go", "")) + // TODO(marun) Remove when zap.NewNop() is possible + log := logging.NewLogger( + "", + logging.NewWrappedCore( + logging.Verbo, + os.Stdout, + zapcore.NewConsoleEncoder(zapcore.EncoderConfig{}), + ), + ) + require.NoError(network.EnsureDefaultConfig(log, "/path/to/avalanche/go", "")) require.NoError(network.Create(tmpDir)) // Ensure node runtime is initialized require.NoError(network.readNodes()) From 64f611d2d8510554292c772a416dbc8789c0bdb8 Mon Sep 17 00:00:00 2001 From: marun Date: Thu, 21 Nov 2024 21:29:18 +0100 Subject: [PATCH 19/22] Update tests/antithesis/avalanchego/main.go Co-authored-by: Stephen Buttolph Signed-off-by: marun --- tests/antithesis/avalanchego/main.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/antithesis/avalanchego/main.go b/tests/antithesis/avalanchego/main.go index c06adccbcb90..926e84a64685 100644 --- a/tests/antithesis/avalanchego/main.go +++ b/tests/antithesis/avalanchego/main.go @@ -423,7 +423,7 @@ func (w *workload) issueXToPTransfer(ctx context.Context) { ) balances, err := xBuilder.GetFTBalance() if err != nil { - w.log.Warn("failed to fetch X-chain balances", + w.log.Error("failed to fetch X-chain balances", zap.Error(err), ) assert.Unreachable("failed to fetch X-chain balances", map[string]any{ From f2a5882fd0d32629035bdfda4b42dbbd4968a2d5 Mon Sep 17 00:00:00 2001 From: Maru Newby Date: Thu, 21 Nov 2024 21:58:39 +0100 Subject: [PATCH 20/22] fixup: Use logging.NoLog --- tests/fixture/tmpnet/network_test.go | 13 +------------ 1 file changed, 1 insertion(+), 12 deletions(-) diff --git a/tests/fixture/tmpnet/network_test.go b/tests/fixture/tmpnet/network_test.go index a350351298d7..f1fa7358fcd4 100644 --- a/tests/fixture/tmpnet/network_test.go +++ b/tests/fixture/tmpnet/network_test.go @@ -4,11 +4,9 @@ package tmpnet import ( - "os" "testing" "github.com/stretchr/testify/require" - "go.uber.org/zap/zapcore" "github.com/ava-labs/avalanchego/utils/logging" ) @@ -19,16 +17,7 @@ func TestNetworkSerialization(t *testing.T) { tmpDir := t.TempDir() network := NewDefaultNetwork("testnet") - // TODO(marun) Remove when zap.NewNop() is possible - log := logging.NewLogger( - "", - logging.NewWrappedCore( - logging.Verbo, - os.Stdout, - zapcore.NewConsoleEncoder(zapcore.EncoderConfig{}), - ), - ) - require.NoError(network.EnsureDefaultConfig(log, "/path/to/avalanche/go", "")) + require.NoError(network.EnsureDefaultConfig(logging.NoLog{}, "/path/to/avalanche/go", "")) require.NoError(network.Create(tmpDir)) // Ensure node runtime is initialized require.NoError(network.readNodes()) From 01b3eb0bd02aa28badb56717960caeb422650822 Mon Sep 17 00:00:00 2001 From: Maru Newby Date: Thu, 21 Nov 2024 22:01:23 +0100 Subject: [PATCH 21/22] Fixup: Moar level changes --- tests/antithesis/node_health.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/antithesis/node_health.go b/tests/antithesis/node_health.go index e5f524b65a67..b4376052b262 100644 --- a/tests/antithesis/node_health.go +++ b/tests/antithesis/node_health.go @@ -37,7 +37,7 @@ func awaitHealthyNode(ctx context.Context, log logging.Logger, uri string) error res, err := client.Health(ctx, nil) switch { case err != nil: - log.Error("failed to reach node", + log.Warn("failed to reach node", zap.String("uri", uri), zap.Error(err), ) From c16d28f5238b9cbc8111c6ae14009e7cc91d6128 Mon Sep 17 00:00:00 2001 From: Maru Newby Date: Thu, 21 Nov 2024 22:10:42 +0100 Subject: [PATCH 22/22] fixup: Simplify ginkgo logger definition --- tests/fixture/e2e/ginkgo_test_context.go | 9 ++++----- 1 file changed, 4 insertions(+), 5 deletions(-) diff --git a/tests/fixture/e2e/ginkgo_test_context.go b/tests/fixture/e2e/ginkgo_test_context.go index 57299d57ed89..601fe78b22f0 100644 --- a/tests/fixture/e2e/ginkgo_test_context.go +++ b/tests/fixture/e2e/ginkgo_test_context.go @@ -5,7 +5,6 @@ package e2e import ( "context" - "io" "time" "github.com/onsi/ginkgo/v2" @@ -42,13 +41,13 @@ var ginkgoEncoderConfig = zapcore.EncoderConfig{ EncodeLevel: logging.ConsoleColorLevelEncoder, } -// NewGinkgoLogger returns a logger with limited output for the specified WriteCloser -func newGinkgoLogger(writeCloser io.WriteCloser) logging.Logger { +// NewGinkgoLogger returns a logger with limited output +func newGinkgoLogger() logging.Logger { return logging.NewLogger( "", logging.NewWrappedCore( logging.Verbo, - writeCloser, + &ginkgoWriteCloser{}, zapcore.NewConsoleEncoder(ginkgoEncoderConfig), ), ) @@ -60,7 +59,7 @@ type GinkgoTestContext struct { func NewTestContext() *GinkgoTestContext { return &GinkgoTestContext{ - logger: newGinkgoLogger(&ginkgoWriteCloser{}), + logger: newGinkgoLogger(), } }