Vastly improve E2E logs and add README (#4440)

* Improve E2E logs to help debugging
* Add README to E2E
* Remove newline logs
* Remove removedb
* Try releasing after killing process
* Fix validator output
* Fix e2e
* Solve eth1 issue by clearing eth1 db
* Whoops
* Fix log spacing

endtoend/README.md

@@ -0,0 +1,23 @@
+# End-to-end Testing Package
+
+This is the main project folder of the end-to-end testing suite for Prysm. This performs a full end-to-end test for Prysm, including spinning up an ETH1 dev chain, sending deposits to the deposit contract, and making sure the beacon node and it's validators are running and performing properly for a few epochs.
+
+## How it works
+Through the `end2EndConfig` struct, you can declare several options such as how many epochs the test should run for, and what `BeaconConfig` the test should use. You can also declare how many beacon nodes and validator clients are run, the E2E will automatically divide the validators evently among the beacon nodes.
+
+In order to "evaluate" the state of the beacon chain while the E2E is running, there are `Evaluators`  that use the beacon chain node API to determine if the network is performing as it should. This can evaluate for conditions like validator activation, finalization, validator participation and more.
+
+Evaluators have 3 parts, the name for it's test name, a `policy` which declares which epoch(s) the evaluator should run, and then the `evaluation` which uses the beacon chain API to determine if the beacon chain passes certain conditions like finality.
+
+## Current end-to-end tests
+* Minimal Config - 4 beacon nodes, 64 validators, running for 5 epochs
+* Demo Config - 4 beacon nodes, 64 validators, running for 5 epochs
+
+## Instructions
+If you wish to run all the E2E tests, you can run them through bazel with:
+
+```bazel test //endtoend:go_default_test --test_output=streamed```
+
+To test only for a specific config, run:
+
+```bazel test //endtoend:go_default_test --test_output=streamed --test_filter=TestEndToEnd_DemoConfig```

endtoend/beacon_node.go

@@ -37,6 +37,8 @@ type end2EndConfig struct {
 	evaluators     []ev.Evaluator
 }
 
+var beaconNodeLogFileName = "beacon-%d.log"
+
 // startBeaconNodes starts the requested amount of beacon nodes, passing in the deposit contract given.
 func startBeaconNodes(t *testing.T, config *end2EndConfig) []*beaconNodeInfo {
 	numNodes := config.numBeaconNodes
@@ -58,7 +60,8 @@ func startNewBeaconNode(t *testing.T, config *end2EndConfig, beaconNodes []*beac
 		t.Log(binaryPath)
 		t.Fatal("beacon chain binary not found")
 	}
-	file, err := os.Create(path.Join(tmpPath, fmt.Sprintf("beacon-%d.log", index)))
+
+	stdOutFile, err := os.Create(path.Join(tmpPath, fmt.Sprintf(beaconNodeLogFileName, index)))
 	if err != nil {
 		t.Fatal(err)
 	}
@@ -90,19 +93,19 @@ func startNewBeaconNode(t *testing.T, config *end2EndConfig, beaconNodes []*beac
 		}
 	}
 
-	t.Logf("Starting beacon chain with flags %s", strings.Join(args, " "))
+	t.Logf("Starting beacon chain with flags: %s", strings.Join(args, " "))
 	cmd := exec.Command(binaryPath, args...)
-	cmd.Stderr = file
-	cmd.Stdout = file
+	cmd.Stdout = stdOutFile
+	cmd.Stderr = stdOutFile
 	if err := cmd.Start(); err != nil {
 		t.Fatalf("Failed to start beacon node: %v", err)
 	}
 
-	if err = waitForTextInFile(file, "Node started p2p server"); err != nil {
+	if err = waitForTextInFile(stdOutFile, "Node started p2p server"); err != nil {
 		t.Fatalf("could not find multiaddr for node %d, this means the node had issues starting: %v", index, err)
 	}
 
-	multiAddr, err := getMultiAddrFromLogFile(file.Name())
+	multiAddr, err := getMultiAddrFromLogFile(stdOutFile.Name())
 	if err != nil {
 		t.Fatalf("could not get multiaddr for node %d: %v", index, err)
 	}
@@ -139,7 +142,7 @@ func getMultiAddrFromLogFile(name string) (string, error) {
 
 func waitForTextInFile(file *os.File, text string) error {
 	wait := 0
-	// Putting the wait cap at 36 seconds.
+	// Cap the wait in case there are issues starting.
 	maxWait := 36
 	for wait < maxWait {
 		time.Sleep(2 * time.Second)

endtoend/endtoend_test.go

@@ -24,7 +24,8 @@ import (
 func runEndToEndTest(t *testing.T, config *end2EndConfig) {
 	tmpPath := bazel.TestTmpDir()
 	config.tmpPath = tmpPath
-	t.Logf("Test Path: %s\n", tmpPath)
+	t.Logf("Starting time: %s\n", time.Now().String())
+	t.Logf("Test Path: %s\n\n", tmpPath)
 
 	contractAddr, keystorePath, eth1PID := startEth1(t, tmpPath)
 	config.contractAddr = contractAddr
@@ -37,7 +38,7 @@ func runEndToEndTest(t *testing.T, config *end2EndConfig) {
 	for _, bb := range beaconNodes {
 		processIDs = append(processIDs, bb.processID)
 	}
-	defer logOutput(t, tmpPath)
+	defer logOutput(t, tmpPath, config)
 	defer killProcesses(t, processIDs)
 
 	if config.numBeaconNodes > 1 {
@@ -50,7 +51,7 @@ func runEndToEndTest(t *testing.T, config *end2EndConfig) {
 		})
 	}
 
-	beaconLogFile, err := os.Open(path.Join(tmpPath, "beacon-0.log"))
+	beaconLogFile, err := os.Open(path.Join(tmpPath, fmt.Sprintf(beaconNodeLogFileName, 0)))
 	if err != nil {
 		t.Fatal(err)
 	}
@@ -143,21 +144,54 @@ func killProcesses(t *testing.T, pIDs []int) {
 		if err := process.Kill(); err != nil {
 			t.Fatal(err)
 		}
+		if err := process.Release(); err != nil {
+			t.Fatal(err)
+		}
 	}
 }
 
-func logOutput(t *testing.T, tmpPath string) {
+
+func logOutput(t *testing.T, tmpPath string, config *end2EndConfig) {
 	if t.Failed() {
-		beacon0LogFile, err := os.Open(path.Join(tmpPath, "beacon-0.log"))
-		if err != nil {
-			t.Fatal(err)
+		// Log out errors from beacon chain nodes.
+		for i := uint64(0); i < config.numBeaconNodes; i++ {
+			beaconLogFile, err := os.Open(path.Join(tmpPath, fmt.Sprintf(beaconNodeLogFileName, i)))
+			if err != nil {
+				t.Fatal(err)
+			}
+			logErrorOutput(t, beaconLogFile, "beacon chain node", i)
+
+			validatorLogFile, err := os.Open(path.Join(tmpPath, fmt.Sprintf(validatorLogFileName, i)))
+			if err != nil {
+				t.Fatal(err)
+			}
+			logErrorOutput(t, validatorLogFile, "validator client", i)
 		}
-		scanner := bufio.NewScanner(beacon0LogFile)
-		t.Log("Beacon chain node output:")
-		for scanner.Scan() {
-			currentLine := scanner.Text()
-			t.Log(currentLine)
-		}
-		t.Log("End of beacon chain node output")
 	}
 }
+
+func logErrorOutput(t *testing.T, file *os.File, title string, index uint64) {
+	var errorLines []string
+
+	scanner := bufio.NewScanner(file)
+	for scanner.Scan() {
+		currentLine := scanner.Text()
+		if strings.Contains(currentLine, "level=error") {
+			errorLines = append(errorLines, currentLine)
+		}
+	}
+
+	if len(errorLines) < 1 {
+		return
+	}
+
+	t.Log("===================================================================")
+	t.Logf("Start of %s %d error output:\n", title, index)
+
+	for _, err := range errorLines {
+		t.Log(err)
+	}
+
+	t.Logf("\nEnd of %s %d error output:", title, index)
+	t.Log("===================================================================")
+}

endtoend/eth1.go

@@ -31,8 +31,16 @@ func startEth1(t *testing.T, tmpPath string) (common.Address, string, int) {
 		t.Fatal("go-ethereum binary not found")
 	}
 
+	eth1Path := path.Join(tmpPath, "eth1data/")
+	// Clear out ETH1 to prevent issues.
+	if _, err := os.Stat(eth1Path); !os.IsNotExist(err) {
+		if err := os.RemoveAll(eth1Path); err != nil {
+			t.Fatal(err)
+		}
+	}
+
 	args := []string{
-		fmt.Sprintf("--datadir=%s", path.Join(tmpPath, "eth1data/")),
+		fmt.Sprintf("--datadir=%s", eth1Path),
 		"--rpc",
 		"--rpcaddr=0.0.0.0",
 		"--rpccorsdomain=\"*\"",

endtoend/validator.go

@@ -27,6 +27,8 @@ type validatorClientInfo struct {
 	monitorPort uint64
 }
 
+var validatorLogFileName = "vals-%d.log"
+
 // initializeValidators sends the deposits to the eth1 chain and starts the validator clients.
 func initializeValidators(
 	t *testing.T,
@@ -48,7 +50,7 @@ func initializeValidators(
 	valClients := make([]*validatorClientInfo, beaconNodeNum)
 	validatorsPerNode := validatorNum / beaconNodeNum
 	for n := uint64(0); n < beaconNodeNum; n++ {
-		file, err := os.Create(path.Join(tmpPath, fmt.Sprintf("vals-%d.log", n)))
+		file, err := os.Create(path.Join(tmpPath, fmt.Sprintf(validatorLogFileName, n)))
 		if err != nil {
 			t.Fatal(err)
 		}
@@ -61,7 +63,7 @@ func initializeValidators(
 		cmd := exec.Command(binaryPath, args...)
 		cmd.Stdout = file
 		cmd.Stderr = file
-		t.Logf("Starting validator client with flags %s", strings.Join(args, " "))
+		t.Logf("Starting validator client with flags: %s", strings.Join(args, " "))
 		if err := cmd.Start(); err != nil {
 			t.Fatal(err)
 		}