From 1819976011baf34f0b5473cf8361d6586d8fd672 Mon Sep 17 00:00:00 2001 From: Daniel Nephin Date: Thu, 3 Jun 2021 14:42:30 -0400 Subject: [PATCH] Merge pull request #10345 from hashicorp/dnephin/backport-logging-fix [1.9.x] agent: remove leading whitespace from agent log lines --- .changelog/10338.txt | 3 + command/agent/agent.go | 117 ++++++++++++++++-------------------- command/agent/agent_test.go | 37 +++++++++--- command/cli/cli.go | 32 ++++++++++ command/commands_oss.go | 13 +--- command/registry.go | 12 ++-- main.go | 14 +++-- 7 files changed, 131 insertions(+), 97 deletions(-) create mode 100644 .changelog/10338.txt create mode 100644 command/cli/cli.go diff --git a/.changelog/10338.txt b/.changelog/10338.txt new file mode 100644 index 0000000000..2b0b955b28 --- /dev/null +++ b/.changelog/10338.txt @@ -0,0 +1,3 @@ +```release-note:bug +agent: fix logging output by removing leading whitespace from every log line +``` diff --git a/command/agent/agent.go b/command/agent/agent.go index 7da6613066..85b5f89ad1 100644 --- a/command/agent/agent.go +++ b/command/agent/agent.go @@ -4,6 +4,7 @@ import ( "context" "flag" "fmt" + "io/ioutil" "os" "os/signal" "path/filepath" @@ -11,32 +12,28 @@ import ( "syscall" "time" + "github.com/hashicorp/go-checkpoint" + "github.com/hashicorp/go-hclog" + mcli "github.com/mitchellh/cli" + "github.com/hashicorp/consul/agent" "github.com/hashicorp/consul/agent/config" + "github.com/hashicorp/consul/command/cli" "github.com/hashicorp/consul/command/flags" "github.com/hashicorp/consul/lib" "github.com/hashicorp/consul/logging" "github.com/hashicorp/consul/service_os" - "github.com/hashicorp/go-checkpoint" - "github.com/hashicorp/go-hclog" - "github.com/mitchellh/cli" + consulversion "github.com/hashicorp/consul/version" ) -func New(ui cli.Ui, revision, version, versionPre, versionHuman string, shutdownCh <-chan struct{}) *cmd { - ui = &cli.PrefixedUi{ - OutputPrefix: "==> ", - InfoPrefix: " ", - ErrorPrefix: "==> ", - Ui: ui, - } - +func New(ui cli.Ui) *cmd { c := &cmd{ - UI: ui, - revision: revision, - version: version, - versionPrerelease: versionPre, - versionHuman: versionHuman, - shutdownCh: shutdownCh, + ui: ui, + revision: consulversion.GitCommit, + version: consulversion.Version, + versionPrerelease: consulversion.VersionPrerelease, + versionHuman: consulversion.GetHumanVersion(), + flags: flag.NewFlagSet("", flag.ContinueOnError), } c.init() return c @@ -47,7 +44,7 @@ func New(ui cli.Ui, revision, version, versionPre, versionHuman string, shutdown // ShutdownCh. If two messages are sent on the ShutdownCh it will forcibly // exit. type cmd struct { - UI cli.Ui + ui cli.Ui flags *flag.FlagSet http *flags.HTTPFlags help string @@ -55,7 +52,6 @@ type cmd struct { version string versionPrerelease string versionHuman string - shutdownCh <-chan struct{} flagArgs config.BuilderOpts logger hclog.InterceptLogger } @@ -122,7 +118,7 @@ func (c *cmd) startupJoin(agent *agent.Agent, cfg *config.RuntimeConfig) error { return nil } - c.UI.Output("Joining cluster...") + c.logger.Info("Joining cluster") n, err := agent.JoinLAN(cfg.StartJoinAddrsLAN) if err != nil { return err @@ -138,74 +134,82 @@ func (c *cmd) startupJoinWan(agent *agent.Agent, cfg *config.RuntimeConfig) erro return nil } - c.UI.Output("Joining -wan cluster...") + c.logger.Info("Joining wan cluster") n, err := agent.JoinWAN(cfg.StartJoinAddrsWAN) if err != nil { return err } - c.logger.Info("Join -wan completed. Initial agents synced with", "agent_count", n) + c.logger.Info("Join wan completed. Initial agents synced with", "agent_count", n) return nil } func (c *cmd) run(args []string) int { + ui := &mcli.PrefixedUi{ + OutputPrefix: "==> ", + InfoPrefix: " ", + ErrorPrefix: "==> ", + Ui: c.ui, + } + if err := c.flags.Parse(args); err != nil { if !strings.Contains(err.Error(), "help requested") { - c.UI.Error(fmt.Sprintf("error parsing flags: %v", err)) + ui.Error(fmt.Sprintf("error parsing flags: %v", err)) } return 1 } if len(c.flags.Args()) > 0 { - c.UI.Error(fmt.Sprintf("Unexpected extra arguments: %v", c.flags.Args())) + ui.Error(fmt.Sprintf("Unexpected extra arguments: %v", c.flags.Args())) return 1 } - logGate := &logging.GatedWriter{Writer: &cli.UiWriter{Ui: c.UI}} + // FIXME: logs should always go to stderr, but previously they were sent to + // stdout, so continue to use Stdout for now, and fix this in a future release. + logGate := &logging.GatedWriter{Writer: c.ui.Stdout()} loader := func(source config.Source) (cfg *config.RuntimeConfig, warnings []string, err error) { return config.Load(c.flagArgs, source) } bd, err := agent.NewBaseDeps(loader, logGate) if err != nil { - c.UI.Error(err.Error()) + ui.Error(err.Error()) return 1 } c.logger = bd.Logger agent, err := agent.New(bd) if err != nil { - c.UI.Error(err.Error()) + ui.Error(err.Error()) return 1 } config := bd.RuntimeConfig - - // Setup gate to check if we should output CLI information - cli := GatedUi{ - JSONoutput: config.Logging.LogJSON, - ui: c.UI, + if config.Logging.LogJSON { + // Hide all non-error output when JSON logging is enabled. + ui.Ui = &cli.BasicUI{ + BasicUi: mcli.BasicUi{ErrorWriter: c.ui.Stderr(), Writer: ioutil.Discard}, + } } - // Create the agent - cli.output("Starting Consul agent...") + ui.Output("Starting Consul agent...") segment := config.SegmentName if config.ServerMode { segment = "" } - cli.info(fmt.Sprintf(" Version: '%s'", c.versionHuman)) - cli.info(fmt.Sprintf(" Node ID: '%s'", config.NodeID)) - cli.info(fmt.Sprintf(" Node name: '%s'", config.NodeName)) - cli.info(fmt.Sprintf(" Datacenter: '%s' (Segment: '%s')", config.Datacenter, segment)) - cli.info(fmt.Sprintf(" Server: %v (Bootstrap: %v)", config.ServerMode, config.Bootstrap)) - cli.info(fmt.Sprintf(" Client Addr: %v (HTTP: %d, HTTPS: %d, gRPC: %d, DNS: %d)", config.ClientAddrs, + ui.Info(fmt.Sprintf(" Version: '%s'", c.versionHuman)) + ui.Info(fmt.Sprintf(" Node ID: '%s'", config.NodeID)) + ui.Info(fmt.Sprintf(" Node name: '%s'", config.NodeName)) + ui.Info(fmt.Sprintf(" Datacenter: '%s' (Segment: '%s')", config.Datacenter, segment)) + ui.Info(fmt.Sprintf(" Server: %v (Bootstrap: %v)", config.ServerMode, config.Bootstrap)) + ui.Info(fmt.Sprintf(" Client Addr: %v (HTTP: %d, HTTPS: %d, gRPC: %d, DNS: %d)", config.ClientAddrs, config.HTTPPort, config.HTTPSPort, config.GRPCPort, config.DNSPort)) - cli.info(fmt.Sprintf(" Cluster Addr: %v (LAN: %d, WAN: %d)", config.AdvertiseAddrLAN, + ui.Info(fmt.Sprintf(" Cluster Addr: %v (LAN: %d, WAN: %d)", config.AdvertiseAddrLAN, config.SerfPortLAN, config.SerfPortWAN)) - cli.info(fmt.Sprintf(" Encrypt: Gossip: %v, TLS-Outgoing: %v, TLS-Incoming: %v, Auto-Encrypt-TLS: %t", + ui.Info(fmt.Sprintf(" Encrypt: Gossip: %v, TLS-Outgoing: %v, TLS-Incoming: %v, Auto-Encrypt-TLS: %t", config.EncryptKey != "", config.VerifyOutgoing, config.VerifyIncoming, config.AutoEncryptTLS || config.AutoEncryptAllowTLS)) // Enable log streaming - cli.output("") - cli.output("Log data will now stream in as it occurs:\n") + ui.Output("") + ui.Output("Log data will now stream in as it occurs:\n") logGate.Flush() // wait for signal @@ -258,19 +262,19 @@ func (c *cmd) run(args []string) int { } if err := c.startupJoin(agent, config); err != nil { - c.logger.Error((err.Error())) + c.logger.Error(err.Error()) return 1 } if err := c.startupJoinWan(agent, config); err != nil { - c.logger.Error((err.Error())) + c.logger.Error(err.Error()) return 1 } // Let the agent know we've finished registration agent.StartSync() - cli.output("Consul agent running!") + c.logger.Info("Consul agent running!") // wait for signal signalCh = make(chan os.Signal, 10) @@ -283,8 +287,6 @@ func (c *cmd) run(args []string) int { sig = s case <-service_os.Shutdown_Channel(): sig = os.Interrupt - case <-c.shutdownCh: - sig = os.Interrupt case err := <-agent.RetryJoinCh(): c.logger.Error("Retry join failed", "error", err) return 1 @@ -340,23 +342,6 @@ func (c *cmd) run(args []string) int { } } -type GatedUi struct { - JSONoutput bool - ui cli.Ui -} - -func (g *GatedUi) output(s string) { - if !g.JSONoutput { - g.ui.Output(s) - } -} - -func (g *GatedUi) info(s string) { - if !g.JSONoutput { - g.ui.Info(s) - } -} - func (c *cmd) Synopsis() string { return synopsis } diff --git a/command/agent/agent_test.go b/command/agent/agent_test.go index 049ddcc19d..e1c0b16273 100644 --- a/command/agent/agent_test.go +++ b/command/agent/agent_test.go @@ -2,18 +2,19 @@ package agent import ( "fmt" + "io" "os" "os/exec" "path/filepath" "strings" "testing" - "github.com/hashicorp/consul/testrpc" + "github.com/mitchellh/cli" "github.com/hashicorp/consul/agent" "github.com/hashicorp/consul/sdk/testutil" "github.com/hashicorp/consul/sdk/testutil/retry" - "github.com/mitchellh/cli" + "github.com/hashicorp/consul/testrpc" ) // TestConfigFail should test command line flags that lead to an immediate error. @@ -110,8 +111,8 @@ func TestRetryJoinFail(t *testing.T) { tmpDir := testutil.TempDir(t, "consul") defer os.RemoveAll(tmpDir) - ui := cli.NewMockUi() - cmd := New(ui, "", "", "", "", nil) + ui := newCaptureUI() + cmd := New(ui) args := []string{ "-bind", "127.0.0.1", @@ -131,8 +132,8 @@ func TestRetryJoinWanFail(t *testing.T) { tmpDir := testutil.TempDir(t, "consul") defer os.RemoveAll(tmpDir) - ui := cli.NewMockUi() - cmd := New(ui, "", "", "", "", nil) + ui := newCaptureUI() + cmd := New(ui) args := []string{ "-server", @@ -172,8 +173,8 @@ func TestProtectDataDir(t *testing.T) { t.Fatalf("err: %v", err) } - ui := cli.NewMockUi() - cmd := New(ui, "", "", "", "", nil) + ui := newCaptureUI() + cmd := New(ui) args := []string{"-config-file=" + cfgFile.Name()} if code := cmd.Run(args); code == 0 { t.Fatalf("should fail") @@ -194,8 +195,8 @@ func TestBadDataDirPermissions(t *testing.T) { } defer os.RemoveAll(dataDir) - ui := cli.NewMockUi() - cmd := New(ui, "", "", "", "", nil) + ui := newCaptureUI() + cmd := New(ui) args := []string{"-data-dir=" + dataDir, "-server=true", "-bind=10.0.0.1"} if code := cmd.Run(args); code == 0 { t.Fatalf("Should fail with bad data directory permissions") @@ -204,3 +205,19 @@ func TestBadDataDirPermissions(t *testing.T) { t.Fatalf("expected permission denied error, got: %s", out) } } + +type captureUI struct { + *cli.MockUi +} + +func (c *captureUI) Stdout() io.Writer { + return c.MockUi.OutputWriter +} + +func (c *captureUI) Stderr() io.Writer { + return c.MockUi.ErrorWriter +} + +func newCaptureUI() *captureUI { + return &captureUI{MockUi: cli.NewMockUi()} +} diff --git a/command/cli/cli.go b/command/cli/cli.go new file mode 100644 index 0000000000..6a7edd7202 --- /dev/null +++ b/command/cli/cli.go @@ -0,0 +1,32 @@ +package cli + +import ( + "io" + + mcli "github.com/mitchellh/cli" +) + +// Ui implements the mitchellh/cli.Ui interface, while exposing the underlying +// io.Writer used for stdout and stderr. +// TODO: rename to UI to match golang style guide +type Ui interface { + mcli.Ui + Stdout() io.Writer + Stderr() io.Writer +} + +// BasicUI augments mitchellh/cli.BasicUi by exposing the underlying io.Writer. +type BasicUI struct { + mcli.BasicUi +} + +func (b *BasicUI) Stdout() io.Writer { + return b.BasicUi.Writer +} + +func (b *BasicUI) Stderr() io.Writer { + return b.BasicUi.ErrorWriter +} + +// Command is an alias to reduce the diff. It can be removed at any time. +type Command mcli.Command diff --git a/command/commands_oss.go b/command/commands_oss.go index 551e259528..91e8180c22 100644 --- a/command/commands_oss.go +++ b/command/commands_oss.go @@ -41,6 +41,7 @@ import ( catlistdc "github.com/hashicorp/consul/command/catalog/list/dc" catlistnodes "github.com/hashicorp/consul/command/catalog/list/nodes" catlistsvc "github.com/hashicorp/consul/command/catalog/list/services" + "github.com/hashicorp/consul/command/cli" "github.com/hashicorp/consul/command/config" configdelete "github.com/hashicorp/consul/command/config/delete" configlist "github.com/hashicorp/consul/command/config/list" @@ -105,17 +106,9 @@ import ( "github.com/hashicorp/consul/command/validate" "github.com/hashicorp/consul/command/version" "github.com/hashicorp/consul/command/watch" - consulversion "github.com/hashicorp/consul/version" - - "github.com/mitchellh/cli" ) func init() { - rev := consulversion.GitCommit - ver := consulversion.Version - verPre := consulversion.VersionPrerelease - verHuman := consulversion.GetHumanVersion() - Register("acl", func(cli.Ui) (cli.Command, error) { return acl.New(), nil }) Register("acl bootstrap", func(ui cli.Ui) (cli.Command, error) { return aclbootstrap.New(ui), nil }) Register("acl policy", func(cli.Ui) (cli.Command, error) { return aclpolicy.New(), nil }) @@ -151,9 +144,7 @@ func init() { Register("acl binding-rule read", func(ui cli.Ui) (cli.Command, error) { return aclbrread.New(ui), nil }) Register("acl binding-rule update", func(ui cli.Ui) (cli.Command, error) { return aclbrupdate.New(ui), nil }) Register("acl binding-rule delete", func(ui cli.Ui) (cli.Command, error) { return aclbrdelete.New(ui), nil }) - Register("agent", func(ui cli.Ui) (cli.Command, error) { - return agent.New(ui, rev, ver, verPre, verHuman, make(chan struct{})), nil - }) + Register("agent", func(ui cli.Ui) (cli.Command, error) { return agent.New(ui), nil }) Register("catalog", func(cli.Ui) (cli.Command, error) { return catalog.New(), nil }) Register("catalog datacenters", func(ui cli.Ui) (cli.Command, error) { return catlistdc.New(ui), nil }) Register("catalog nodes", func(ui cli.Ui) (cli.Command, error) { return catlistnodes.New(ui), nil }) diff --git a/command/registry.go b/command/registry.go index 2b092ae722..a96818c2f3 100644 --- a/command/registry.go +++ b/command/registry.go @@ -6,7 +6,9 @@ import ( "os/signal" "syscall" - "github.com/mitchellh/cli" + mcli "github.com/mitchellh/cli" + + "github.com/hashicorp/consul/command/cli" ) // Factory is a function that returns a new instance of a CLI-sub command. @@ -24,14 +26,14 @@ func Register(name string, fn Factory) { registry[name] = fn } -// Map returns a realized mapping of available CLI commands in a format that +// CommandsFromRegistry returns a realized mapping of available CLI commands in a format that // the CLI class can consume. This should be called after all registration is // complete. -func Map(ui cli.Ui) map[string]cli.CommandFactory { - m := make(map[string]cli.CommandFactory) +func CommandsFromRegistry(ui cli.Ui) map[string]mcli.CommandFactory { + m := make(map[string]mcli.CommandFactory) for name, fn := range registry { thisFn := fn - m[name] = func() (cli.Command, error) { + m[name] = func() (mcli.Command, error) { return thisFn(ui) } } diff --git a/main.go b/main.go index 87e300968f..9697cec896 100644 --- a/main.go +++ b/main.go @@ -6,11 +6,13 @@ import ( "log" "os" + mcli "github.com/mitchellh/cli" + "github.com/hashicorp/consul/command" + "github.com/hashicorp/consul/command/cli" "github.com/hashicorp/consul/command/version" "github.com/hashicorp/consul/lib" _ "github.com/hashicorp/consul/service_os" - "github.com/mitchellh/cli" ) func init() { @@ -24,19 +26,21 @@ func main() { func realMain() int { log.SetOutput(ioutil.Discard) - ui := &cli.BasicUi{Writer: os.Stdout, ErrorWriter: os.Stderr} - cmds := command.Map(ui) + ui := &cli.BasicUI{ + BasicUi: mcli.BasicUi{Writer: os.Stdout, ErrorWriter: os.Stderr}, + } + cmds := command.CommandsFromRegistry(ui) var names []string for c := range cmds { names = append(names, c) } - cli := &cli.CLI{ + cli := &mcli.CLI{ Args: os.Args[1:], Commands: cmds, Autocomplete: true, Name: "consul", - HelpFunc: cli.FilteredHelpFunc(names, cli.BasicHelpFunc("consul")), + HelpFunc: mcli.FilteredHelpFunc(names, mcli.BasicHelpFunc("consul")), HelpWriter: os.Stdout, ErrorWriter: os.Stderr, }