Merge pull request #5702 from bhandras/itest_etcd_logs

itest: save etcd logs along node logs in separate files

docs/release-notes/release-notes-0.14.0.md

@@ -205,6 +205,8 @@ you.
 
 * [Fixed wallet recovery itests on Travis ARM](https://github.com/lightningnetwork/lnd/pull/5688)
 
+* [Integration tests save embedded etcd logs to help debugging flakes](https://github.com/lightningnetwork/lnd/pull/5702)
+
 ## Database
 
 * [Ensure single writer for legacy

kvdb/backend.go

@@ -256,7 +256,7 @@ func GetTestBackend(path, name string) (Backend, func(), error) {
 		}
 		return db, empty, nil
 	} else if TestBackend == EtcdBackendName {
-		etcdConfig, cancel, err := StartEtcdTestBackend(path, 0, 0)
+		etcdConfig, cancel, err := StartEtcdTestBackend(path, 0, 0, "")
 		if err != nil {
 			return nil, empty, err
 		}

kvdb/etcd/config.go

@@ -10,6 +10,8 @@ type Config struct {
 
 	EmbeddedPeerPort uint16 `long:"embedded_peer_port" description:"Peer port to use for the embedded instance. Note: use for testing only."`
 
+	EmbeddedLogFile string `long:"embedded_log_file" description:"Optional log file to use for embedded instance logs. note: use for testing only."`
+
 	Host string `long:"host" description:"Etcd database host."`
 
 	User string `long:"user" description:"Etcd database user."`

kvdb/etcd/embed.go

@@ -60,8 +60,8 @@ func getFreePort() int {
 // NewEmbeddedEtcdInstance creates an embedded etcd instance for testing,
 // listening on random open ports. Returns the backend config and a cleanup
 // func that will stop the etcd instance.
-func NewEmbeddedEtcdInstance(path string, clientPort, peerPort uint16) (
+func NewEmbeddedEtcdInstance(path string, clientPort, peerPort uint16,
-	*Config, func(), error) {
+	logFile string) (*Config, func(), error) {
 
 	cfg := embed.NewConfig()
 	cfg.Dir = path
@@ -70,7 +70,12 @@ func NewEmbeddedEtcdInstance(path string, clientPort, peerPort uint16) (
 	cfg.MaxTxnOps = 8192
 	cfg.MaxRequestBytes = 16384 * 1024
 	cfg.Logger = "zap"
-	cfg.LogLevel = "error"
+	if logFile != "" {
+		cfg.LogLevel = "info"
+		cfg.LogOutputs = []string{logFile}
+	} else {
+		cfg.LogLevel = "error"
+	}
 
 	// Listen on random free ports if no ports were specified.
 	if clientPort == 0 {

kvdb/etcd/fixture.go

@@ -34,7 +34,7 @@ type EtcdTestFixture struct {
 func NewTestEtcdInstance(t *testing.T, path string) (*Config, func()) {
 	t.Helper()
 
-	config, cleanup, err := NewEmbeddedEtcdInstance(path, 0, 0)
+	config, cleanup, err := NewEmbeddedEtcdInstance(path, 0, 0, "")
 	if err != nil {
 		t.Fatalf("error while staring embedded etcd instance: %v", err)
 	}

kvdb/kvdb_etcd.go

@@ -12,10 +12,10 @@ const TestBackend = EtcdBackendName
 
 // GetEtcdTestBackend creates an embedded etcd backend for testing
 // storig the database at the passed path.
-func StartEtcdTestBackend(path string, clientPort, peerPort uint16) (
+func StartEtcdTestBackend(path string, clientPort, peerPort uint16,
-	*etcd.Config, func(), error) {
+	logFile string) (*etcd.Config, func(), error) {
 
 	return etcd.NewEmbeddedEtcdInstance(
-		path, clientPort, peerPort,
+		path, clientPort, peerPort, logFile,
 	)
 }

kvdb/kvdb_no_etcd.go

@@ -15,8 +15,8 @@ const TestBackend = BoltBackendName
 var errEtcdNotAvailable = fmt.Errorf("etcd backend not available")
 
 // StartEtcdTestBackend  is a stub returning nil, and errEtcdNotAvailable error.
-func StartEtcdTestBackend(path string, clientPort, peerPort uint16) (
+func StartEtcdTestBackend(path string, clientPort, peerPort uint16,
-	*etcd.Config, func(), error) {
+	logFile string) (*etcd.Config, func(), error) {
 
 	return nil, func() {}, errEtcdNotAvailable
 }

lncfg/db.go

@@ -92,7 +92,7 @@ func (db *DB) Init(ctx context.Context, dbPath string) error {
 	if db.Backend == EtcdBackend && db.Etcd.Embedded {
 		cfg, _, err := kvdb.StartEtcdTestBackend(
 			dbPath, db.Etcd.EmbeddedClientPort,
-			db.Etcd.EmbeddedPeerPort,
+			db.Etcd.EmbeddedPeerPort, db.Etcd.EmbeddedLogFile,
 		)
 		if err != nil {
 			return err

lntest/itest/lnd_etcd_failover_test.go

@@ -70,7 +70,7 @@ func testEtcdFailoverCase(net *lntest.NetworkHarness, ht *harnessTest,
 	tmpDir, err := ioutil.TempDir("", "etcd")
 	etcdCfg, cleanup, err := kvdb.StartEtcdTestBackend(
 		tmpDir, uint16(lntest.NextAvailablePort()),
-		uint16(lntest.NextAvailablePort()),
+		uint16(lntest.NextAvailablePort()), "",
 	)
 	if err != nil {
 		ht.Fatalf("Failed to start etcd instance: %v", err)

lntest/node.go

@@ -11,6 +11,7 @@ import (
 	"net"
 	"os"
 	"os/exec"
+	"path"
 	"path/filepath"
 	"strings"
 	"sync"
@@ -324,6 +325,12 @@ func (cfg NodeConfig) genArgs() []string {
 				NextAvailablePort(),
 			),
 		)
+		args = append(
+			args, fmt.Sprintf(
+				"--db.etcd.embedded_log_file=%v",
+				path.Join(cfg.LogDir, "etcd.log"),
+			),
+		)
 	}
 
 	if cfg.FeeURL != "" {
@@ -558,6 +565,15 @@ func (hn *HarnessNode) InvoiceMacPath() string {
 	return hn.Cfg.InvoiceMacPath
 }
 
+// renameFile is a helper to rename (log) files created during integration tests.
+func renameFile(fromFileName, toFileName string) {
+	err := os.Rename(fromFileName, toFileName)
+	if err != nil {
+		fmt.Printf("could not rename %s to %s: %v\n",
+			fromFileName, toFileName, err)
+	}
+}
+
 // Start launches a new process running lnd. Additionally, the PID of the
 // launched process is saved in order to possibly kill the process forcibly
 // later.
@@ -584,6 +600,30 @@ func (hn *HarnessNode) start(lndBinary string, lndError chan<- error,
 		}
 	}
 
+	getFinalizedLogFilePrefix := func() string {
+		pubKeyHex := hex.EncodeToString(
+			hn.PubKey[:logPubKeyBytes],
+		)
+
+		return fmt.Sprintf("%s/%d-%s-%s-%s",
+			GetLogDir(), hn.NodeID,
+			hn.Cfg.LogFilenamePrefix,
+			hn.Cfg.Name, pubKeyHex)
+	}
+
+	finalizeEtcdLog := func() {
+		if hn.Cfg.DbBackend != BackendEtcd {
+			return
+		}
+
+		etcdLogFileName := fmt.Sprintf("%s/etcd.log", hn.Cfg.LogDir)
+		newEtcdLogFileName := fmt.Sprintf("%v-etcd.log",
+			getFinalizedLogFilePrefix(),
+		)
+
+		renameFile(etcdLogFileName, newEtcdLogFileName)
+	}
+
 	// If the logoutput flag is passed, redirect output from the nodes to
 	// log files.
 	if *logOutput {
@@ -600,29 +640,19 @@ func (hn *HarnessNode) start(lndBinary string, lndError chan<- error,
 			fileName = fmt.Sprintf("%s/%d-%s-%s-tmp__.log", dir,
 				hn.NodeID, hn.Cfg.LogFilenamePrefix,
 				hn.Cfg.Name)
+		}
 
-			// Once the node has done its work, the log file can be
+		// Once the node has done its work, the log file can be
-			// renamed.
+		// renamed.
-			finalizeLogfile = func() {
+		finalizeLogfile = func() {
-				if hn.logFile != nil {
+			if hn.logFile != nil {
-					hn.logFile.Close()
+				hn.logFile.Close()
 
-					pubKeyHex := hex.EncodeToString(
+				newFileName := fmt.Sprintf("%v.log",
-						hn.PubKey[:logPubKeyBytes],
+					getFinalizedLogFilePrefix(),
-					)
+				)
-					newFileName := fmt.Sprintf("%s/"+
+
-						"%d-%s-%s-%s.log",
+				renameFile(fileName, newFileName)
-						dir, hn.NodeID,
-						hn.Cfg.LogFilenamePrefix,
-						hn.Cfg.Name, pubKeyHex)
-					err := os.Rename(fileName, newFileName)
-					if err != nil {
-						fmt.Printf("could not rename "+
-							"%s to %s: %v\n",
-							fileName, newFileName,
-							err)
-					}
-				}
 			}
 		}
 
@@ -666,6 +696,10 @@ func (hn *HarnessNode) start(lndBinary string, lndError chan<- error,
 
 		// Make sure log file is closed and renamed if necessary.
 		finalizeLogfile()
+
+		// Rename the etcd.log file if the node was running on embedded
+		// etcd.
+		finalizeEtcdLog()
 	}()
 
 	// Write process ID to a file.

sample-lnd.conf

@@ -1131,6 +1131,10 @@ litecoin.node=ltcd
 ; If non zero, LND will use this as peer port for the embedded etcd instance.
 ; db.etcd.embedded_peer_port=1235
 
+; If set the embedded etcd instance will log to the specified file. Useful when
+; testing with embedded etcd.
+; db.etcd.embedded_log_file=/path/etcd.log
+
 
 [cluster]