Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

agent: remove leading whitespace from agent log lines #10338

Merged
merged 6 commits into from
Jun 3, 2021
Merged

agent: remove leading whitespace from agent log lines #10338

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
e573641
cmd: remove unnecessary args to agent.New
dnephin Jun 2, 2021
2fc988d
cmd: introduce a shim to expose Stdout/Stderr writers
dnephin Jun 2, 2021
b4b85bd
agent: fix agent logging
dnephin Jun 2, 2021
2261a46
cmd: move agent running message to logs
dnephin Jun 2, 2021
cec8bc8
cmd: remove unnecessary GatedUi
dnephin Jun 2, 2021
99956cd
Add changelog
dnephin Jun 2, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
3 changes: 3 additions & 0 deletions .changelog/10338.txt
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,3 @@
```release-note:bug
agent: fix logging output by removing leading whitespace from every log line
```
111 changes: 47 additions & 64 deletions command/agent/agent.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,7 @@ import (
"context"
"flag"
"fmt"
"io"
"os"
"os/signal"
"path/filepath"
Expand All @@ -13,31 +14,25 @@ import (

"github.com/hashicorp/go-checkpoint"
"github.com/hashicorp/go-hclog"
"github.com/mitchellh/cli"
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"
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),
}
config.AddFlags(c.flags, &c.configLoadOpts)
Expand All @@ -50,15 +45,14 @@ 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
revision string
version string
versionPrerelease string
versionHuman string
shutdownCh <-chan struct{}
configLoadOpts config.LoadOpts
logger hclog.InterceptLogger
}
Expand Down Expand Up @@ -119,7 +113,7 @@ func (c *cmd) startupJoin(agent *agent.Agent, cfg *config.RuntimeConfig) error {
return nil
}

c.UI.Output("Joining cluster...")
c.logger.Info("Joining cluster")
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This change to use a logger (and mentioned in the commit message). Using the logger for this seems much better, that way the output is not lost when json logging is enabled.

Same below.

n, err := agent.JoinLAN(cfg.StartJoinAddrsLAN)
if err != nil {
return err
Expand All @@ -135,75 +129,83 @@ 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()}
Comment on lines +161 to +163
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is the fix for the primary issue, but other changes were required to make this possible.

loader := func(source config.Source) (config.LoadResult, error) {
c.configLoadOpts.DefaultConfig = source
return config.Load(c.configLoadOpts)
}
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: io.Discard},
}
}

// Create the agent
cli.output("Starting Consul agent...")
ui.Output("Starting Consul agent...")

segment := config.SegmentName
if config.ServerMode {
segment = "<all>"
}
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
Expand Down Expand Up @@ -256,19 +258,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!")
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This also changed to use the logger (as mentioned in the commit message). Previously this was leading to very odd looking output, where the log lines were broken up by a random ==> Consul agent running!" line.

With this change the message will be included in the logs when json logs are enabled.


// wait for signal
signalCh = make(chan os.Signal, 10)
Expand All @@ -281,8 +283,6 @@ func (c *cmd) run(args []string) int {
sig = s
case <-service_os.Shutdown_Channel():
sig = os.Interrupt
case <-c.shutdownCh:
sig = os.Interrupt
Comment on lines -284 to -285
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This was removed because it did nothing (the channel was never closed), and we already have a case for handling signals.

case err := <-agent.RetryJoinCh():
c.logger.Error("Retry join failed", "error", err)
return 1
Expand Down Expand Up @@ -341,23 +341,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
}
Expand Down
37 changes: 27 additions & 10 deletions command/agent/agent_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down Expand Up @@ -120,8 +121,8 @@ func TestRetryJoinFail(t *testing.T) {
t.Parallel()
tmpDir := testutil.TempDir(t, "consul")

ui := cli.NewMockUi()
cmd := New(ui, "", "", "", "", nil)
ui := newCaptureUI()
cmd := New(ui)

args := []string{
"-bind", "127.0.0.1",
Expand All @@ -144,8 +145,8 @@ func TestRetryJoinWanFail(t *testing.T) {
t.Parallel()
tmpDir := testutil.TempDir(t, "consul")

ui := cli.NewMockUi()
cmd := New(ui, "", "", "", "", nil)
ui := newCaptureUI()
cmd := New(ui)

args := []string{
"-server",
Expand Down Expand Up @@ -183,8 +184,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")
Expand All @@ -202,8 +203,8 @@ func TestBadDataDirPermissions(t *testing.T) {
t.Fatalf("err: %v", err)
}

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")
Expand All @@ -212,3 +213,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()}
}
32 changes: 32 additions & 0 deletions command/cli/cli.go
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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
13 changes: 2 additions & 11 deletions command/commands_oss.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -108,17 +109,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 })
Expand Down Expand Up @@ -154,9 +147,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 })
Expand Down
Loading