Make E2E more consistent, change log file setup (prysmaticlabs#4696)

* Make E2E more consistent, change log file setup
* Merge branch 'master' into fix-e2e-sync

endtoend/beacon_node.go

@@ -3,9 +3,7 @@ package endtoend
 import (
 	"fmt"
 	"io/ioutil"
-	"os"
 	"os/exec"
-	"path"
 	"strings"
 	"testing"
 
@@ -50,7 +48,7 @@ func startNewBeaconNode(t *testing.T, config *end2EndConfig, beaconNodes []*ev.B
 		t.Fatal("beacon chain binary not found")
 	}
 
-	stdOutFile, err := os.Create(path.Join(tmpPath, fmt.Sprintf(beaconNodeLogFileName, index)))
+	stdOutFile, err := deleteAndCreateFile(tmpPath, fmt.Sprintf(beaconNodeLogFileName, index))
 	if err != nil {
 		t.Fatal(err)
 	}
@@ -70,6 +68,7 @@ func startNewBeaconNode(t *testing.T, config *end2EndConfig, beaconNodes []*ev.B
 		fmt.Sprintf("--grpc-gateway-port=%d", 3400+index),
 		fmt.Sprintf("--contract-deployment-block=%d", 0),
 		fmt.Sprintf("--rpc-max-page-size=%d", params.BeaconConfig().MinGenesisActiveValidatorCount),
+		fmt.Sprintf("--log-file=%s", stdOutFile.Name()),
 	}
 	args = append(args, config.beaconFlags...)
 
@@ -82,8 +81,6 @@ func startNewBeaconNode(t *testing.T, config *end2EndConfig, beaconNodes []*ev.B
 
 	t.Logf("Starting beacon chain %d with flags: %s", index, strings.Join(args, " "))
 	cmd := exec.Command(binaryPath, args...)
-	cmd.Stdout = stdOutFile
-	cmd.Stderr = stdOutFile
 	if err := cmd.Start(); err != nil {
 		t.Fatalf("Failed to start beacon node: %v", err)
 	}

endtoend/endtoend_test.go

@@ -100,11 +100,11 @@ func runEndToEndTest(t *testing.T, config *end2EndConfig) {
 
 	syncNodeInfo := startNewBeaconNode(t, config, beaconNodes)
 	beaconNodes = append(beaconNodes, syncNodeInfo)
-	index := len(beaconNodes) - 1
+	index := uint64(len(beaconNodes)-1)
 
 	// Sleep until the next epoch to give time for the newly started node to sync.
-	nextEpochSeconds := (config.epochsToRun+2)*epochSeconds + epochSeconds/2
-	genesisTime.Add(time.Duration(nextEpochSeconds) * time.Second)
+	extraTimeToSync := (config.epochsToRun+3)*epochSeconds+60
+	genesisTime.Add(time.Duration(extraTimeToSync) * time.Second)
 	// Wait until middle of epoch to request to prevent conflicts.
 	time.Sleep(time.Until(genesisTime))
 
@@ -128,5 +128,6 @@ func runEndToEndTest(t *testing.T, config *end2EndConfig) {
 		}
 	})
 
+	defer logErrorOutput(t, syncLogFile, "beacon chain node", index)
 	defer killProcesses(t, []int{syncNodeInfo.ProcessID})
 }

endtoend/helpers.go

@@ -14,7 +14,7 @@ import (
 )
 
 const (
-	maxPollingWaitTime  = 36 * time.Second
+	maxPollingWaitTime  = 60 * time.Second
 	filePollingInterval = 1 * time.Second
 )
 
@@ -33,6 +33,20 @@ func killProcesses(t *testing.T, pIDs []int) {
 	}
 }
 
+func deleteAndCreateFile(tmpPath string, fileName string) (*os.File, error) {
+	filePath := path.Join(tmpPath, fileName)
+	if _, err := os.Stat(filePath); os.IsExist(err) {
+		if err := os.Remove(filePath); err != nil {
+			return nil, err
+		}
+	}
+	newFile, err := os.Create(path.Join(tmpPath, fileName))
+	if err != nil {
+		return nil, err
+	}
+	return newFile, nil
+}
+
 func waitForTextInFile(file *os.File, text string) error {
 	d := time.Now().Add(maxPollingWaitTime)
 	ctx, cancel := context.WithDeadline(context.Background(), d)
@@ -48,12 +62,8 @@ func waitForTextInFile(file *os.File, text string) error {
 			if err != nil {
 				return err
 			}
-			return fmt.Errorf("could not find requested text \"%s\" in logs:\n%s", text, string(contents))
+			return fmt.Errorf("could not find requested text \"%s\" in logs:\n%s", text, contents)
 		case <-ticker.C:
-			_, err := file.Seek(0, io.SeekStart)
-			if err != nil {
-				return err
-			}
 			fileScanner := bufio.NewScanner(file)
 			for fileScanner.Scan() {
 				scanned := fileScanner.Text()
@@ -64,6 +74,10 @@ func waitForTextInFile(file *os.File, text string) error {
 			if err := fileScanner.Err(); err != nil {
 				return err
 			}
+			_, err := file.Seek(0, io.SeekStart)
+			if err != nil {
+				return err
+			}
 		}
 	}
 }

endtoend/validator.go

@@ -6,9 +6,7 @@ import (
 	"fmt"
 	"io/ioutil"
 	"math/big"
-	"os"
 	"os/exec"
-	"path"
 	"strings"
 	"testing"
 
@@ -50,7 +48,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(validatorLogFileName, n)))
+		file, err := deleteAndCreateFile(tmpPath, fmt.Sprintf(validatorLogFileName, n))
 		if err != nil {
 			t.Fatal(err)
 		}
@@ -61,12 +59,11 @@ func initializeValidators(
 			fmt.Sprintf("--monitoring-port=%d", 9280+n),
 			fmt.Sprintf("--datadir=%s/eth2-val-%d", tmpPath, n),
 			fmt.Sprintf("--beacon-rpc-provider=localhost:%d", 4200+n),
+			fmt.Sprintf("--log-file=%s",file.Name()),
 		}
 		args = append(args, config.validatorFlags...)
 
 		cmd := exec.Command(binaryPath, args...)
-		cmd.Stdout = file
-		cmd.Stderr = file
 		t.Logf("Starting validator client %d with flags: %s", n, strings.Join(args, " "))
 		if err := cmd.Start(); err != nil {
 			t.Fatal(err)