From 6c2d8bb176bfc323d9d35794fa925682872ebfa3 Mon Sep 17 00:00:00 2001 From: Andras Banki-Horvath Date: Wed, 8 Sep 2021 15:10:11 +0200 Subject: [PATCH 1/3] etcd: enable optional log file for embedded etcd log output In this commit we add an extra config for enabling logging to an external file when using embedded etcd. This can be useful when running integration tests to see more details about etcd related issues. --- kvdb/backend.go | 2 +- kvdb/etcd/config.go | 2 ++ kvdb/etcd/embed.go | 11 ++++++++--- kvdb/etcd/fixture.go | 2 +- kvdb/kvdb_etcd.go | 6 +++--- kvdb/kvdb_no_etcd.go | 4 ++-- lncfg/db.go | 2 +- lntest/itest/lnd_etcd_failover_test.go | 2 +- sample-lnd.conf | 4 ++++ 9 files changed, 23 insertions(+), 12 deletions(-) diff --git a/kvdb/backend.go b/kvdb/backend.go index a5307dfa5..9bf210c41 100644 --- a/kvdb/backend.go +++ b/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 } diff --git a/kvdb/etcd/config.go b/kvdb/etcd/config.go index 5ae91c220..8798bcb60 100644 --- a/kvdb/etcd/config.go +++ b/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."` diff --git a/kvdb/etcd/embed.go b/kvdb/etcd/embed.go index c045e6cb8..a4f969149 100644 --- a/kvdb/etcd/embed.go +++ b/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) ( - *Config, func(), error) { +func NewEmbeddedEtcdInstance(path string, clientPort, peerPort uint16, + 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 { diff --git a/kvdb/etcd/fixture.go b/kvdb/etcd/fixture.go index 8fcfb9f5c..3a32ba09b 100644 --- a/kvdb/etcd/fixture.go +++ b/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) } diff --git a/kvdb/kvdb_etcd.go b/kvdb/kvdb_etcd.go index 2b798d88f..0637baf24 100644 --- a/kvdb/kvdb_etcd.go +++ b/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) ( - *etcd.Config, func(), error) { +func StartEtcdTestBackend(path string, clientPort, peerPort uint16, + logFile string) (*etcd.Config, func(), error) { return etcd.NewEmbeddedEtcdInstance( - path, clientPort, peerPort, + path, clientPort, peerPort, logFile, ) } diff --git a/kvdb/kvdb_no_etcd.go b/kvdb/kvdb_no_etcd.go index ec7abf775..588fce37f 100644 --- a/kvdb/kvdb_no_etcd.go +++ b/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) ( - *etcd.Config, func(), error) { +func StartEtcdTestBackend(path string, clientPort, peerPort uint16, + logFile string) (*etcd.Config, func(), error) { return nil, func() {}, errEtcdNotAvailable } diff --git a/lncfg/db.go b/lncfg/db.go index 63023c918..aa0dcd602 100644 --- a/lncfg/db.go +++ b/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 diff --git a/lntest/itest/lnd_etcd_failover_test.go b/lntest/itest/lnd_etcd_failover_test.go index bf3ca7ec3..14c15ab97 100644 --- a/lntest/itest/lnd_etcd_failover_test.go +++ b/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) diff --git a/sample-lnd.conf b/sample-lnd.conf index 61d285e4c..59b7231c8 100644 --- a/sample-lnd.conf +++ b/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] From 9bf04f9870996192d0effcb6e4896cb7d863bb9a Mon Sep 17 00:00:00 2001 From: Andras Banki-Horvath Date: Wed, 8 Sep 2021 16:31:27 +0200 Subject: [PATCH 2/3] itest+etcd: save etcd logs along the node logs --- lntest/node.go | 76 ++++++++++++++++++++++++++++++++++++-------------- 1 file changed, 55 insertions(+), 21 deletions(-) diff --git a/lntest/node.go b/lntest/node.go index 69dc26ad6..1b33d55d1 100644 --- a/lntest/node.go +++ b/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 - // renamed. - finalizeLogfile = func() { - if hn.logFile != nil { - hn.logFile.Close() + // Once the node has done its work, the log file can be + // renamed. + finalizeLogfile = func() { + if hn.logFile != nil { + hn.logFile.Close() - pubKeyHex := hex.EncodeToString( - hn.PubKey[:logPubKeyBytes], - ) - newFileName := fmt.Sprintf("%s/"+ - "%d-%s-%s-%s.log", - 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) - } - } + newFileName := fmt.Sprintf("%v.log", + getFinalizedLogFilePrefix(), + ) + + renameFile(fileName, newFileName) } } @@ -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. From 400cc0eb9657f05116c7a7bb6dd8af4ea3025f1e Mon Sep 17 00:00:00 2001 From: Andras Banki-Horvath Date: Wed, 8 Sep 2021 16:36:59 +0200 Subject: [PATCH 3/3] docs: update release-notes-0.14.0.md --- docs/release-notes/release-notes-0.14.0.md | 2 ++ 1 file changed, 2 insertions(+) diff --git a/docs/release-notes/release-notes-0.14.0.md b/docs/release-notes/release-notes-0.14.0.md index 017a8dc91..2155b60fd 100644 --- a/docs/release-notes/release-notes-0.14.0.md +++ b/docs/release-notes/release-notes-0.14.0.md @@ -198,6 +198,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