From 8fc5840bc28692d8847a38be2f88839d7b229723 Mon Sep 17 00:00:00 2001 From: George Kudrayvtsev Date: Tue, 3 Nov 2020 14:47:56 -0800 Subject: [PATCH 01/16] Allow the stellarCoreRunner to have a configurable logger instance --- ingest/ledgerbackend/captive_core_backend.go | 8 ++++++++ ingest/ledgerbackend/stellar_core_runner.go | 9 +++++++++ services/horizon/internal/ingest/main.go | 5 +++-- 3 files changed, 20 insertions(+), 2 deletions(-) diff --git a/ingest/ledgerbackend/captive_core_backend.go b/ingest/ledgerbackend/captive_core_backend.go index 08d30f894c..0314107ecc 100644 --- a/ingest/ledgerbackend/captive_core_backend.go +++ b/ingest/ledgerbackend/captive_core_backend.go @@ -109,6 +109,8 @@ type CaptiveStellarCore struct { // waitIntervalPrepareRange defines a time to wait between checking if the buffer // is empty. Default 1s, lower in tests to make them faster. waitIntervalPrepareRange time.Duration + + log *log.Entry } // NewCaptive returns a new CaptiveStellarCore. @@ -139,6 +141,10 @@ func NewCaptive(executablePath, configPath, networkPassphrase string, historyURL }, nil } +func (c *CaptiveStellarCore) SetLogger(logger *log.Entry) { + c.log = logger +} + func (c *CaptiveStellarCore) getLatestCheckpointSequence() (uint32, error) { has, err := c.archive.GetRootHAS() if err != nil { @@ -175,6 +181,7 @@ func (c *CaptiveStellarCore) openOfflineReplaySubprocess(from, to uint32) error if err != nil { return errors.Wrap(err, "error creating stellar-core runner") } + c.stellarCoreRunner.setLogger(c.log) } err = c.stellarCoreRunner.catchup(from, to) if err != nil { @@ -234,6 +241,7 @@ func (c *CaptiveStellarCore) openOnlineReplaySubprocess(from uint32) error { if err != nil { return errors.Wrap(err, "error creating stellar-core runner") } + c.stellarCoreRunner.setLogger(c.log) } runFrom, ledgerHash, nextLedger, err := c.runFromParams(from) diff --git a/ingest/ledgerbackend/stellar_core_runner.go b/ingest/ledgerbackend/stellar_core_runner.go index 950fa31ccc..1cfb9df66c 100644 --- a/ingest/ledgerbackend/stellar_core_runner.go +++ b/ingest/ledgerbackend/stellar_core_runner.go @@ -15,6 +15,7 @@ import ( "time" "github.com/pkg/errors" + "github.com/stellar/go/support/log" ) type stellarCoreRunnerInterface interface { @@ -22,6 +23,7 @@ type stellarCoreRunnerInterface interface { runFrom(from uint32, hash string) error getMetaPipe() io.Reader getProcessExitChan() <-chan error + setLogger(*log.Entry) close() error } @@ -42,6 +44,9 @@ type stellarCoreRunner struct { metaPipe io.Reader tempDir string nonce string + + // Optionally, logging can be done to something other than stdout. + Log *log.Entry } func newStellarCoreRunner(executablePath, configPath, networkPassphrase string, historyURLs []string) (*stellarCoreRunner, error) { @@ -221,6 +226,10 @@ func (r *stellarCoreRunner) getProcessExitChan() <-chan error { return r.processExit } +func (c *stellarCoreRunner) setLogger(logger *log.Entry) { + c.Log = logger.WithField("subservice", "stellar-core") +} + func (r *stellarCoreRunner) close() error { var err1, err2 error diff --git a/services/horizon/internal/ingest/main.go b/services/horizon/internal/ingest/main.go index 401d60498e..ec40a27879 100644 --- a/services/horizon/internal/ingest/main.go +++ b/services/horizon/internal/ingest/main.go @@ -171,8 +171,7 @@ func NewSystem(config Config) (System, error) { return nil, errors.Wrap(err, "error creating captive core backend") } } else { - // - ledgerBackend, err = ledgerbackend.NewCaptive( + captiveCoreBackend, err := ledgerbackend.NewCaptive( config.StellarCoreBinaryPath, config.StellarCoreConfigPath, config.NetworkPassphrase, @@ -182,6 +181,8 @@ func NewSystem(config Config) (System, error) { cancel() return nil, errors.Wrap(err, "error creating captive core backend") } + captiveCoreBackend.SetLogger(log) + ledgerBackend = captiveCoreBackend } } else { coreSession := config.CoreSession.Clone() From 353967940115ca540a3c65dbbe7690202c8fb613 Mon Sep 17 00:00:00 2001 From: George Kudrayvtsev Date: Tue, 3 Nov 2020 14:48:08 -0800 Subject: [PATCH 02/16] Translate Core logs into Horizon logs --- ingest/ledgerbackend/captive_core_backend.go | 1 + ingest/ledgerbackend/stellar_core_runner.go | 27 ++++++++++++++++++-- 2 files changed, 26 insertions(+), 2 deletions(-) diff --git a/ingest/ledgerbackend/captive_core_backend.go b/ingest/ledgerbackend/captive_core_backend.go index 0314107ecc..b97f85b0b1 100644 --- a/ingest/ledgerbackend/captive_core_backend.go +++ b/ingest/ledgerbackend/captive_core_backend.go @@ -110,6 +110,7 @@ type CaptiveStellarCore struct { // is empty. Default 1s, lower in tests to make them faster. waitIntervalPrepareRange time.Duration + // Optionally, pass along a custom logger to the underlying runner. log *log.Entry } diff --git a/ingest/ledgerbackend/stellar_core_runner.go b/ingest/ledgerbackend/stellar_core_runner.go index 1cfb9df66c..345bbb0394 100644 --- a/ingest/ledgerbackend/stellar_core_runner.go +++ b/ingest/ledgerbackend/stellar_core_runner.go @@ -111,7 +111,7 @@ func (r *stellarCoreRunner) getConfFileName() string { return filepath.Join(r.tempDir, "stellar-core.conf") } -func (*stellarCoreRunner) getLogLineWriter() io.Writer { +func (runner *stellarCoreRunner) getLogLineWriter() io.Writer { r, w := io.Pipe() br := bufio.NewReader(r) // Strip timestamps from log lines from captive stellar-core. We emit our own. @@ -123,7 +123,30 @@ func (*stellarCoreRunner) getLogLineWriter() io.Writer { break } line = dateRx.ReplaceAllString(line, "") - fmt.Print(line) + + // If there's a logger, we attempt to extract metadata about the log + // entry, then redirect it to the logger. Otherwise, we just use + // stdout. + if runner.Log != nil { + levelRx := regexp.MustCompile(`\[(default )?([A-Z]+)\]`) + indices := levelRx.FindStringSubmatchIndex(line) + if indices != nil { + loc := indices[len(indices)-2:] // last pair is the "level" + level := line[loc[0]:loc[1]] // extract the substring + line = line[loc[1]+2:] // dump the start of the line + switch level { + case "ERROR": + case "FATAL": + runner.Log.Errorf(line) + default: + runner.Log.Infof(line) + } + } else { + runner.Log.Infof(line) + } + } else { + fmt.Print(line) + } } }() return w From ef15de05b47823310b27c480beae119ae6a6f87e Mon Sep 17 00:00:00 2001 From: George Kudrayvtsev Date: Tue, 3 Nov 2020 15:22:55 -0800 Subject: [PATCH 03/16] Reformat the function to have less indentation --- ingest/ledgerbackend/stellar_core_runner.go | 36 ++++++++++----------- 1 file changed, 18 insertions(+), 18 deletions(-) diff --git a/ingest/ledgerbackend/stellar_core_runner.go b/ingest/ledgerbackend/stellar_core_runner.go index 345bbb0394..54e2069023 100644 --- a/ingest/ledgerbackend/stellar_core_runner.go +++ b/ingest/ledgerbackend/stellar_core_runner.go @@ -125,27 +125,27 @@ func (runner *stellarCoreRunner) getLogLineWriter() io.Writer { line = dateRx.ReplaceAllString(line, "") // If there's a logger, we attempt to extract metadata about the log - // entry, then redirect it to the logger. Otherwise, we just use - // stdout. - if runner.Log != nil { - levelRx := regexp.MustCompile(`\[(default )?([A-Z]+)\]`) - indices := levelRx.FindStringSubmatchIndex(line) - if indices != nil { - loc := indices[len(indices)-2:] // last pair is the "level" - level := line[loc[0]:loc[1]] // extract the substring - line = line[loc[1]+2:] // dump the start of the line - switch level { - case "ERROR": - case "FATAL": - runner.Log.Errorf(line) - default: - runner.Log.Infof(line) - } - } else { + // entry, then redirect it to the logger. Otherwise, we just use stdout. + if runner.Log == nil { + fmt.Print(line) + continue + } + + levelRx := regexp.MustCompile(`\[(default )?([A-Z]+)\]`) + indices := levelRx.FindStringSubmatchIndex(line) + if indices != nil { + loc := indices[len(indices)-2:] // last pair is the "level" + level := line[loc[0]:loc[1]] // extract the substring + line = line[loc[1]+2:] // dump the start of the line + switch level { + case "ERROR": + case "FATAL": + runner.Log.Errorf(line) + default: runner.Log.Infof(line) } } else { - fmt.Print(line) + runner.Log.Infof(line) } } }() From 5f85b28ae7fa1ccee67faa300a96031f77a77566 Mon Sep 17 00:00:00 2001 From: George Kudrayvtsev Date: Tue, 3 Nov 2020 15:25:10 -0800 Subject: [PATCH 04/16] Use a map rather than switch/case to relate logging levels to writers --- ingest/ledgerbackend/stellar_core_runner.go | 15 ++++++++++----- 1 file changed, 10 insertions(+), 5 deletions(-) diff --git a/ingest/ledgerbackend/stellar_core_runner.go b/ingest/ledgerbackend/stellar_core_runner.go index 54e2069023..8ce1e740fb 100644 --- a/ingest/ledgerbackend/stellar_core_runner.go +++ b/ingest/ledgerbackend/stellar_core_runner.go @@ -137,11 +137,16 @@ func (runner *stellarCoreRunner) getLogLineWriter() io.Writer { loc := indices[len(indices)-2:] // last pair is the "level" level := line[loc[0]:loc[1]] // extract the substring line = line[loc[1]+2:] // dump the start of the line - switch level { - case "ERROR": - case "FATAL": - runner.Log.Errorf(line) - default: + + levelMapping := map[string]func(string, ...interface{}){ + "ERROR": runner.Log.Errorf, + "FATAL": runner.Log.Errorf, + "WARN": runner.Log.Warnf, + } + + if writer, ok := levelMapping[level]; ok { + writer(line) + } else { runner.Log.Infof(line) } } else { From 890875941f97a75e05d87e0737e3e23818be78c5 Mon Sep 17 00:00:00 2001 From: George Kudrayvtsev Date: Tue, 3 Nov 2020 15:39:46 -0800 Subject: [PATCH 05/16] Improve output format, extracting log category as well We go from "abcde" [category LEVEL] stuff here getting rendered as LVEL[time] stuff here to LVEL[time] category: stuff here --- ingest/ledgerbackend/stellar_core_runner.go | 25 +++++++++++++-------- 1 file changed, 16 insertions(+), 9 deletions(-) diff --git a/ingest/ledgerbackend/stellar_core_runner.go b/ingest/ledgerbackend/stellar_core_runner.go index 8ce1e740fb..250304cc98 100644 --- a/ingest/ledgerbackend/stellar_core_runner.go +++ b/ingest/ledgerbackend/stellar_core_runner.go @@ -131,21 +131,28 @@ func (runner *stellarCoreRunner) getLogLineWriter() io.Writer { continue } - levelRx := regexp.MustCompile(`\[(default )?([A-Z]+)\]`) + levelRx := regexp.MustCompile(`\[(\w+) ([A-Z]+)\]`) indices := levelRx.FindStringSubmatchIndex(line) if indices != nil { - loc := indices[len(indices)-2:] // last pair is the "level" - level := line[loc[0]:loc[1]] // extract the substring - line = line[loc[1]+2:] // dump the start of the line + + categoryIdx := indices[2:4] + levelIdx := indices[4:6] + + category := line[categoryIdx[0]:categoryIdx[1]] + level := line[levelIdx[0]:levelIdx[1]] + + end := indices[1] + line = line[end+1:] // dump the matched part of the line levelMapping := map[string]func(string, ...interface{}){ - "ERROR": runner.Log.Errorf, - "FATAL": runner.Log.Errorf, - "WARN": runner.Log.Warnf, + "FATAL": runner.Log.Errorf, + "ERROR": runner.Log.Errorf, + "WARNING": runner.Log.Warnf, + "INFO": runner.Log.Infof, } - if writer, ok := levelMapping[level]; ok { - writer(line) + if writer, ok := levelMapping[strings.ToUpper(level)]; ok { + writer("%s: %s", category, line) } else { runner.Log.Infof(line) } From e22f2b653c06e392c93997ed7956c94659161812 Mon Sep 17 00:00:00 2001 From: George Kudrayvtsev Date: Tue, 3 Nov 2020 15:43:30 -0800 Subject: [PATCH 06/16] Make mocked type conform to updated interface, appease govet --- ingest/ledgerbackend/captive_core_backend_test.go | 3 +++ services/horizon/internal/ingest/main.go | 3 ++- 2 files changed, 5 insertions(+), 1 deletion(-) diff --git a/ingest/ledgerbackend/captive_core_backend_test.go b/ingest/ledgerbackend/captive_core_backend_test.go index 711d7ba628..bad2c1f82a 100644 --- a/ingest/ledgerbackend/captive_core_backend_test.go +++ b/ingest/ledgerbackend/captive_core_backend_test.go @@ -10,6 +10,7 @@ import ( "github.com/stellar/go/historyarchive" "github.com/stellar/go/network" "github.com/stellar/go/support/errors" + "github.com/stellar/go/support/log" "github.com/stellar/go/xdr" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/mock" @@ -47,6 +48,8 @@ func (m *stellarCoreRunnerMock) close() error { return a.Error(0) } +func (m *stellarCoreRunnerMock) setLogger(*log.Entry) {} + func buildLedgerCloseMeta(sequence uint32) xdr.LedgerCloseMeta { opResults := []xdr.OperationResult{} opMeta := []xdr.OperationMeta{} diff --git a/services/horizon/internal/ingest/main.go b/services/horizon/internal/ingest/main.go index ec40a27879..d743c2a127 100644 --- a/services/horizon/internal/ingest/main.go +++ b/services/horizon/internal/ingest/main.go @@ -171,7 +171,8 @@ func NewSystem(config Config) (System, error) { return nil, errors.Wrap(err, "error creating captive core backend") } } else { - captiveCoreBackend, err := ledgerbackend.NewCaptive( + var captiveCoreBackend *ledgerbackend.CaptiveStellarCore + captiveCoreBackend, err = ledgerbackend.NewCaptive( config.StellarCoreBinaryPath, config.StellarCoreConfigPath, config.NetworkPassphrase, From 410e82f857350ef340cc1662bd66a464d69d3dc6 Mon Sep 17 00:00:00 2001 From: George Kudrayvtsev Date: Tue, 3 Nov 2020 15:48:11 -0800 Subject: [PATCH 07/16] Slightly harden code to blowups --- ingest/ledgerbackend/stellar_core_runner.go | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/ingest/ledgerbackend/stellar_core_runner.go b/ingest/ledgerbackend/stellar_core_runner.go index 250304cc98..0be2abf313 100644 --- a/ingest/ledgerbackend/stellar_core_runner.go +++ b/ingest/ledgerbackend/stellar_core_runner.go @@ -133,16 +133,16 @@ func (runner *stellarCoreRunner) getLogLineWriter() io.Writer { levelRx := regexp.MustCompile(`\[(\w+) ([A-Z]+)\]`) indices := levelRx.FindStringSubmatchIndex(line) - if indices != nil { - + if len(indices) >= 6 { + // Identify the indices that match our regex subexpressions categoryIdx := indices[2:4] levelIdx := indices[4:6] + // Extract the substrings from the log entry category := line[categoryIdx[0]:categoryIdx[1]] level := line[levelIdx[0]:levelIdx[1]] - end := indices[1] - line = line[end+1:] // dump the matched part of the line + line = line[indices[1]+1:] // dump the matched part of the line levelMapping := map[string]func(string, ...interface{}){ "FATAL": runner.Log.Errorf, From 8923b6c1aa68ac238ba1a16cae4e3e9be2e36d7e Mon Sep 17 00:00:00 2001 From: George Kudrayvtsev Date: Wed, 4 Nov 2020 09:50:57 -0800 Subject: [PATCH 08/16] Reconfigure the factory to set the logger in all cases (per PR comments) --- ingest/ledgerbackend/captive_core_backend.go | 17 +++++++++++------ 1 file changed, 11 insertions(+), 6 deletions(-) diff --git a/ingest/ledgerbackend/captive_core_backend.go b/ingest/ledgerbackend/captive_core_backend.go index b97f85b0b1..0228d5dfdf 100644 --- a/ingest/ledgerbackend/captive_core_backend.go +++ b/ingest/ledgerbackend/captive_core_backend.go @@ -109,9 +109,6 @@ type CaptiveStellarCore struct { // waitIntervalPrepareRange defines a time to wait between checking if the buffer // is empty. Default 1s, lower in tests to make them faster. waitIntervalPrepareRange time.Duration - - // Optionally, pass along a custom logger to the underlying runner. - log *log.Entry } // NewCaptive returns a new CaptiveStellarCore. @@ -143,7 +140,17 @@ func NewCaptive(executablePath, configPath, networkPassphrase string, historyURL } func (c *CaptiveStellarCore) SetLogger(logger *log.Entry) { - c.log = logger + // If the caller decides to set a custom logger, we recreate the factory to + // pass this along to all subsequently-created instances. + previousFactory := c.stellarCoreRunnerFactory + c.stellarCoreRunnerFactory = func(configPath string) (stellarCoreRunnerInterface, error) { + core, err := previousFactory(configPath) + if err != nil { + return core, err + } + core.setLogger(logger) + return core, nil + } } func (c *CaptiveStellarCore) getLatestCheckpointSequence() (uint32, error) { @@ -182,7 +189,6 @@ func (c *CaptiveStellarCore) openOfflineReplaySubprocess(from, to uint32) error if err != nil { return errors.Wrap(err, "error creating stellar-core runner") } - c.stellarCoreRunner.setLogger(c.log) } err = c.stellarCoreRunner.catchup(from, to) if err != nil { @@ -242,7 +248,6 @@ func (c *CaptiveStellarCore) openOnlineReplaySubprocess(from uint32) error { if err != nil { return errors.Wrap(err, "error creating stellar-core runner") } - c.stellarCoreRunner.setLogger(c.log) } runFrom, ledgerHash, nextLedger, err := c.runFromParams(from) From 165595686fe04f72ccaf41093e18ec7924a836f1 Mon Sep 17 00:00:00 2001 From: George Kudrayvtsev Date: Wed, 4 Nov 2020 09:51:14 -0800 Subject: [PATCH 09/16] Allow proper reset of logger --- ingest/ledgerbackend/stellar_core_runner.go | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/ingest/ledgerbackend/stellar_core_runner.go b/ingest/ledgerbackend/stellar_core_runner.go index 0be2abf313..a48d637302 100644 --- a/ingest/ledgerbackend/stellar_core_runner.go +++ b/ingest/ledgerbackend/stellar_core_runner.go @@ -261,8 +261,12 @@ func (r *stellarCoreRunner) getProcessExitChan() <-chan error { return r.processExit } -func (c *stellarCoreRunner) setLogger(logger *log.Entry) { - c.Log = logger.WithField("subservice", "stellar-core") +func (r *stellarCoreRunner) setLogger(logger *log.Entry) { + if logger != nil { + r.Log = logger.WithField("subservice", "stellar-core") + } else { + r.Log = nil + } } func (r *stellarCoreRunner) close() error { From 03fe249ab7fac3bea4c7bb9d789631f50614b8f8 Mon Sep 17 00:00:00 2001 From: George Kudrayvtsev Date: Wed, 4 Nov 2020 09:52:33 -0800 Subject: [PATCH 10/16] Rename function receiver name to match other methods (per PR comments) --- ingest/ledgerbackend/stellar_core_runner.go | 23 +++++++++++---------- 1 file changed, 12 insertions(+), 11 deletions(-) diff --git a/ingest/ledgerbackend/stellar_core_runner.go b/ingest/ledgerbackend/stellar_core_runner.go index a48d637302..a6a947c021 100644 --- a/ingest/ledgerbackend/stellar_core_runner.go +++ b/ingest/ledgerbackend/stellar_core_runner.go @@ -111,9 +111,10 @@ func (r *stellarCoreRunner) getConfFileName() string { return filepath.Join(r.tempDir, "stellar-core.conf") } -func (runner *stellarCoreRunner) getLogLineWriter() io.Writer { - r, w := io.Pipe() - br := bufio.NewReader(r) +func (r *stellarCoreRunner) getLogLineWriter() io.Writer { + rd, wr := io.Pipe() + br := bufio.NewReader(rd) + // Strip timestamps from log lines from captive stellar-core. We emit our own. dateRx := regexp.MustCompile(`^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3} `) go func() { @@ -126,7 +127,7 @@ func (runner *stellarCoreRunner) getLogLineWriter() io.Writer { // If there's a logger, we attempt to extract metadata about the log // entry, then redirect it to the logger. Otherwise, we just use stdout. - if runner.Log == nil { + if r.Log == nil { fmt.Print(line) continue } @@ -145,23 +146,23 @@ func (runner *stellarCoreRunner) getLogLineWriter() io.Writer { line = line[indices[1]+1:] // dump the matched part of the line levelMapping := map[string]func(string, ...interface{}){ - "FATAL": runner.Log.Errorf, - "ERROR": runner.Log.Errorf, - "WARNING": runner.Log.Warnf, - "INFO": runner.Log.Infof, + "FATAL": r.Log.Errorf, + "ERROR": r.Log.Errorf, + "WARNING": r.Log.Warnf, + "INFO": r.Log.Infof, } if writer, ok := levelMapping[strings.ToUpper(level)]; ok { writer("%s: %s", category, line) } else { - runner.Log.Infof(line) + r.Log.Infof(line) } } else { - runner.Log.Infof(line) + r.Log.Infof(line) } } }() - return w + return wr } // Makes the temp directory and writes the config file to it; called by the From 675b09b572e842d98053ce2a7c1579250648343a Mon Sep 17 00:00:00 2001 From: George Kudrayvtsev Date: Thu, 5 Nov 2020 19:17:30 -0800 Subject: [PATCH 11/16] Modify the factory directly instead of wrapping it in a secondary factory --- ingest/ledgerbackend/captive_core_backend.go | 41 ++++++++++---------- 1 file changed, 20 insertions(+), 21 deletions(-) diff --git a/ingest/ledgerbackend/captive_core_backend.go b/ingest/ledgerbackend/captive_core_backend.go index 0228d5dfdf..d16025d598 100644 --- a/ingest/ledgerbackend/captive_core_backend.go +++ b/ingest/ledgerbackend/captive_core_backend.go @@ -109,6 +109,9 @@ type CaptiveStellarCore struct { // waitIntervalPrepareRange defines a time to wait between checking if the buffer // is empty. Default 1s, lower in tests to make them faster. waitIntervalPrepareRange time.Duration + + // Optionally, pass along a custom logger to the underlying runner. + Log *log.Entry } // NewCaptive returns a new CaptiveStellarCore. @@ -126,31 +129,27 @@ func NewCaptive(executablePath, configPath, networkPassphrase string, historyURL return nil, errors.Wrap(err, "error connecting to history archive") } - return &CaptiveStellarCore{ - archive: archive, - executablePath: executablePath, - configPath: configPath, - historyURLs: historyURLs, - networkPassphrase: networkPassphrase, - stellarCoreRunnerFactory: func(configPath2 string) (stellarCoreRunnerInterface, error) { - return newStellarCoreRunner(executablePath, configPath2, networkPassphrase, historyURLs) - }, + c := &CaptiveStellarCore{ + archive: archive, + executablePath: executablePath, + configPath: configPath, + historyURLs: historyURLs, + networkPassphrase: networkPassphrase, waitIntervalPrepareRange: time.Second, - }, nil + } + c.stellarCoreRunnerFactory = func(configPath2 string) (stellarCoreRunnerInterface, error) { + runner, innerErr := newStellarCoreRunner(executablePath, configPath2, networkPassphrase, historyURLs) + if innerErr != nil { + return runner, innerErr + } + runner.setLogger(c.Log) + return runner, nil + } + return c, nil } func (c *CaptiveStellarCore) SetLogger(logger *log.Entry) { - // If the caller decides to set a custom logger, we recreate the factory to - // pass this along to all subsequently-created instances. - previousFactory := c.stellarCoreRunnerFactory - c.stellarCoreRunnerFactory = func(configPath string) (stellarCoreRunnerInterface, error) { - core, err := previousFactory(configPath) - if err != nil { - return core, err - } - core.setLogger(logger) - return core, nil - } + c.Log = logger } func (c *CaptiveStellarCore) getLatestCheckpointSequence() (uint32, error) { From 336eec2c87a103b11989939216ea59b98b8d9ae2 Mon Sep 17 00:00:00 2001 From: George Kudrayvtsev Date: Thu, 5 Nov 2020 19:28:22 -0800 Subject: [PATCH 12/16] Make the logger private (only accessible via the method) --- ingest/ledgerbackend/captive_core_backend.go | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/ingest/ledgerbackend/captive_core_backend.go b/ingest/ledgerbackend/captive_core_backend.go index d16025d598..a70befa0a3 100644 --- a/ingest/ledgerbackend/captive_core_backend.go +++ b/ingest/ledgerbackend/captive_core_backend.go @@ -111,7 +111,7 @@ type CaptiveStellarCore struct { waitIntervalPrepareRange time.Duration // Optionally, pass along a custom logger to the underlying runner. - Log *log.Entry + log *log.Entry } // NewCaptive returns a new CaptiveStellarCore. @@ -142,14 +142,14 @@ func NewCaptive(executablePath, configPath, networkPassphrase string, historyURL if innerErr != nil { return runner, innerErr } - runner.setLogger(c.Log) + runner.setLogger(c.log) return runner, nil } return c, nil } -func (c *CaptiveStellarCore) SetLogger(logger *log.Entry) { - c.Log = logger +func (c *CaptiveStellarCore) SetStellarCoreLogger(logger *log.Entry) { + c.log = logger } func (c *CaptiveStellarCore) getLatestCheckpointSequence() (uint32, error) { From a7908581859bcd4eb55f18d6a949f564f39daf51 Mon Sep 17 00:00:00 2001 From: George Kudrayvtsev Date: Thu, 5 Nov 2020 19:28:44 -0800 Subject: [PATCH 13/16] Move subservice demarkation to higher level --- ingest/ledgerbackend/stellar_core_runner.go | 6 +----- services/horizon/internal/ingest/main.go | 3 ++- 2 files changed, 3 insertions(+), 6 deletions(-) diff --git a/ingest/ledgerbackend/stellar_core_runner.go b/ingest/ledgerbackend/stellar_core_runner.go index a6a947c021..e7a89cf5e8 100644 --- a/ingest/ledgerbackend/stellar_core_runner.go +++ b/ingest/ledgerbackend/stellar_core_runner.go @@ -263,11 +263,7 @@ func (r *stellarCoreRunner) getProcessExitChan() <-chan error { } func (r *stellarCoreRunner) setLogger(logger *log.Entry) { - if logger != nil { - r.Log = logger.WithField("subservice", "stellar-core") - } else { - r.Log = nil - } + r.Log = logger } func (r *stellarCoreRunner) close() error { diff --git a/services/horizon/internal/ingest/main.go b/services/horizon/internal/ingest/main.go index d743c2a127..3837b5030b 100644 --- a/services/horizon/internal/ingest/main.go +++ b/services/horizon/internal/ingest/main.go @@ -182,7 +182,8 @@ func NewSystem(config Config) (System, error) { cancel() return nil, errors.Wrap(err, "error creating captive core backend") } - captiveCoreBackend.SetLogger(log) + captiveCoreBackend.SetStellarCoreLogger( + log.WithField("subservice", "stellar-core")) ledgerBackend = captiveCoreBackend } } else { From 71873746d3a8478b072a2ad2018e73a4a5c82446 Mon Sep 17 00:00:00 2001 From: George Kudrayvtsev Date: Thu, 5 Nov 2020 19:29:10 -0800 Subject: [PATCH 14/16] Match strings directly and indices separately for cleaner code --- ingest/ledgerbackend/stellar_core_runner.go | 17 +++++++---------- 1 file changed, 7 insertions(+), 10 deletions(-) diff --git a/ingest/ledgerbackend/stellar_core_runner.go b/ingest/ledgerbackend/stellar_core_runner.go index e7a89cf5e8..9a95a7f28c 100644 --- a/ingest/ledgerbackend/stellar_core_runner.go +++ b/ingest/ledgerbackend/stellar_core_runner.go @@ -118,6 +118,7 @@ func (r *stellarCoreRunner) getLogLineWriter() io.Writer { // Strip timestamps from log lines from captive stellar-core. We emit our own. dateRx := regexp.MustCompile(`^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3} `) go func() { + levelRx := regexp.MustCompile(`\[(\w+) ([A-Z]+)\]`) for { line, err := br.ReadString('\n') if err != nil { @@ -132,18 +133,14 @@ func (r *stellarCoreRunner) getLogLineWriter() io.Writer { continue } - levelRx := regexp.MustCompile(`\[(\w+) ([A-Z]+)\]`) - indices := levelRx.FindStringSubmatchIndex(line) - if len(indices) >= 6 { - // Identify the indices that match our regex subexpressions - categoryIdx := indices[2:4] - levelIdx := indices[4:6] - + matches := levelRx.FindStringSubmatch(line) + if len(matches) >= 3 { // Extract the substrings from the log entry - category := line[categoryIdx[0]:categoryIdx[1]] - level := line[levelIdx[0]:levelIdx[1]] + category, level := matches[1], matches[2] - line = line[indices[1]+1:] // dump the matched part of the line + // Dump the matched part of the line + endIdx := levelRx.FindStringIndex(line)[1] + line = line[endIdx+1:] levelMapping := map[string]func(string, ...interface{}){ "FATAL": r.Log.Errorf, From 30d512a36063ef02ef5410092c06fb3d25fb20dd Mon Sep 17 00:00:00 2001 From: George Kudrayvtsev Date: Mon, 9 Nov 2020 11:42:09 -0800 Subject: [PATCH 15/16] Match & trim the line all in one go --- ingest/ledgerbackend/stellar_core_runner.go | 11 ++++------- 1 file changed, 4 insertions(+), 7 deletions(-) diff --git a/ingest/ledgerbackend/stellar_core_runner.go b/ingest/ledgerbackend/stellar_core_runner.go index 9a95a7f28c..7119508112 100644 --- a/ingest/ledgerbackend/stellar_core_runner.go +++ b/ingest/ledgerbackend/stellar_core_runner.go @@ -118,7 +118,7 @@ func (r *stellarCoreRunner) getLogLineWriter() io.Writer { // Strip timestamps from log lines from captive stellar-core. We emit our own. dateRx := regexp.MustCompile(`^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3} `) go func() { - levelRx := regexp.MustCompile(`\[(\w+) ([A-Z]+)\]`) + levelRx := regexp.MustCompile(`G[A-Z]{4} \[(\w+) ([A-Z]+)\] (.*)`) for { line, err := br.ReadString('\n') if err != nil { @@ -134,13 +134,10 @@ func (r *stellarCoreRunner) getLogLineWriter() io.Writer { } matches := levelRx.FindStringSubmatch(line) - if len(matches) >= 3 { - // Extract the substrings from the log entry + if len(matches) >= 4 { + // Extract the substrings from the log entry and trim it category, level := matches[1], matches[2] - - // Dump the matched part of the line - endIdx := levelRx.FindStringIndex(line)[1] - line = line[endIdx+1:] + line = matches[3] levelMapping := map[string]func(string, ...interface{}){ "FATAL": r.Log.Errorf, From ae7e582a029cabcea03a9a32e8015276b234eece Mon Sep 17 00:00:00 2001 From: George Kudrayvtsev Date: Mon, 9 Nov 2020 11:50:07 -0800 Subject: [PATCH 16/16] y u do dis --- ingest/ledgerbackend/captive_core_backend.go | 1 + 1 file changed, 1 insertion(+) diff --git a/ingest/ledgerbackend/captive_core_backend.go b/ingest/ledgerbackend/captive_core_backend.go index a2b1f84e61..1d85f6765c 100644 --- a/ingest/ledgerbackend/captive_core_backend.go +++ b/ingest/ledgerbackend/captive_core_backend.go @@ -7,6 +7,7 @@ import ( "github.com/pkg/errors" "github.com/stellar/go/historyarchive" + "github.com/stellar/go/support/log" "github.com/stellar/go/xdr" )