Merge pull request #10345 from hashicorp/dnephin/backport-logging-fix

[1.9.x] agent: remove leading whitespace from agent log lines

.changelog/10338.txt

@@ -0,0 +1,3 @@
+```release-note:bug
+agent: fix logging output by removing leading whitespace from every log line
+```

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"
+	consulversion "github.com/hashicorp/consul/version"
-	"github.com/hashicorp/go-hclog"
-	"github.com/mitchellh/cli"
 )
 
-func New(ui cli.Ui, revision, version, versionPre, versionHuman string, shutdownCh <-chan struct{}) *cmd {
+func New(ui cli.Ui) *cmd {
-	ui = &cli.PrefixedUi{
-		OutputPrefix: "==> ",
-		InfoPrefix:   "    ",
-		ErrorPrefix:  "==> ",
-		Ui:           ui,
-	}
-
 	c := &cmd{
-		UI:                ui,
+		ui:                ui,
-		revision:          revision,
+		revision:          consulversion.GitCommit,
-		version:           version,
+		version:           consulversion.Version,
-		versionPrerelease: versionPre,
+		versionPrerelease: consulversion.VersionPrerelease,
-		versionHuman:      versionHuman,
+		versionHuman:      consulversion.GetHumanVersion(),
-		shutdownCh:        shutdownCh,
+		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
-
+	if config.Logging.LogJSON {
-	// Setup gate to check if we should output CLI information
+		// Hide all non-error output when JSON logging is enabled.
-	cli := GatedUi{
+		ui.Ui = &cli.BasicUI{
-		JSONoutput: config.Logging.LogJSON,
+			BasicUi: mcli.BasicUi{ErrorWriter: c.ui.Stderr(), Writer: ioutil.Discard},
-		ui:         c.UI,
+		}
 	}
 
-	// Create the agent
+	ui.Output("Starting Consul agent...")
-	cli.output("Starting Consul agent...")
 
 	segment := config.SegmentName
 	if config.ServerMode {
 		segment = "<all>"
 	}
-	cli.info(fmt.Sprintf("       Version: '%s'", c.versionHuman))
+	ui.Info(fmt.Sprintf("       Version: '%s'", c.versionHuman))
-	cli.info(fmt.Sprintf("       Node ID: '%s'", config.NodeID))
+	ui.Info(fmt.Sprintf("       Node ID: '%s'", config.NodeID))
-	cli.info(fmt.Sprintf("     Node name: '%s'", config.NodeName))
+	ui.Info(fmt.Sprintf("     Node name: '%s'", config.NodeName))
-	cli.info(fmt.Sprintf("    Datacenter: '%s' (Segment: '%s')", config.Datacenter, segment))
+	ui.Info(fmt.Sprintf("    Datacenter: '%s' (Segment: '%s')", config.Datacenter, segment))
-	cli.info(fmt.Sprintf("        Server: %v (Bootstrap: %v)", config.ServerMode, config.Bootstrap))
+	ui.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("   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("")
+	ui.Output("")
-	cli.output("Log data will now stream in as it occurs:\n")
+	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
 }

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()
+	ui := newCaptureUI()
-	cmd := New(ui, "", "", "", "", nil)
+	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()
+	ui := newCaptureUI()
-	cmd := New(ui, "", "", "", "", nil)
+	cmd := New(ui)
 
 	args := []string{
 		"-server",
@@ -172,8 +173,8 @@ func TestProtectDataDir(t *testing.T) {
 		t.Fatalf("err: %v", err)
 	}
 
-	ui := cli.NewMockUi()
+	ui := newCaptureUI()
-	cmd := New(ui, "", "", "", "", nil)
+	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()
+	ui := newCaptureUI()
-	cmd := New(ui, "", "", "", "", nil)
+	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()}
+}

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

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) {
+	Register("agent", func(ui cli.Ui) (cli.Command, error) { return agent.New(ui), nil })
-		return agent.New(ui, rev, ver, verPre, verHuman, make(chan struct{})), 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 })

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 {
+func CommandsFromRegistry(ui cli.Ui) map[string]mcli.CommandFactory {
-	m := make(map[string]cli.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)
 		}
 	}

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}
+	ui := &cli.BasicUI{
-	cmds := command.Map(ui)
+		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,
 	}