Merge lp:~thumper/juju-core/default-command-info into lp:~go-bot/juju-core/trunk

[Tim Penhey]

Add standard functions for command output.

Add simple function support and flags around changing how the command output
works by default. Add flag options for '-q' and '--quiet'. Also updated the text for the flags.

There are now two methods on the cmd.Context object that should be used for output:
  func (ctx *Context) Infof(format string, params ...interface{})
and
  func (ctx *Context) Verbosef(format string, params ...interface{})

If quiet is specified, both are logged instead of written out. If verbose is
specified, both are written out, if the defaults are used, Info is written
out, but verbose is logged.

Add standard functions for command output.

Add simple function support and flags around changing how the command output
works by default. Add flag options for '-q' and '--quiet', and provider a
short '-d' for '--debug'. Also updated the text for the flags.

There are now two methods in the cmd package that should be used for output:
  cmd.Infof(...)
and
  cmd.Verbosef(...)

If quiet is specified, both are logged instead of written out. If verbose is
specified, both are written out, if the defaults are used, Info is written
out, but verbose is logged.

Ideally I'd like to tweak loggo so we can specify the call depth of the
caller, so we can grab the appropriate line numbers etc, but this can happen
later. Also, now any use of these methods will have the 'juju.cmd' module. Not
sure if we want to really parameterize that.

The only thing I'm wondering about is Stderr vs. Stdout. Ideally I'd prefer
to use Stdout where possible, but for the format oriented commands, we still
want users to be able to go:
  'juju status --format=json | other-thing'
So we don't want to polute Stdout in those situations with output.

There are a number of options here:
 * we just write to Stdout, and have people add '-q'
 * we write the info and verbose info to Stderr so it just works

Then do we have some go to Stdout and some Stderr?

Logging now goes to Stderr, so we could just send all output there (except for
the actual formatted output).

https://codereview.appspot.com/22320043/

[Tim Penhey (thumper)]

Reviewers: mp+194061_code.launchpad.net,

Message:
Please take a look.

Description:
Add standard functions for command output.

Add simple function support and flags around changing how the command
output
works by default. Add flag options for '-q' and '--quiet', and provider
a
short '-d' for '--debug'. Also updated the text for the flags.

There are now two methods in the cmd package that should be used for
output:
   cmd.Infof(...)
and
   cmd.Verbosef(...)

If quiet is specified, both are logged instead of written out. If
verbose is
specified, both are written out, if the defaults are used, Info is
written
out, but verbose is logged.

Ideally I'd like to tweak loggo so we can specify the call depth of the
caller, so we can grab the appropriate line numbers etc, but this can
happen
later. Also, now any use of these methods will have the 'juju.cmd'
module. Not
sure if we want to really parameterize that.

The only thing I'm wondering about is Stderr vs. Stdout. Ideally I'd
prefer
to use Stdout where possible, but for the format oriented commands, we
still
want users to be able to go:
   'juju status --format=json | other-thing'
So we don't want to polute Stdout in those situations with output.

There are a number of options here:
  * we just write to Stdout, and have people add '-q'
  * we write the info and verbose info to Stderr so it just works

Then do we have some go to Stdout and some Stderr?

Logging now goes to Stderr, so we could just send all output there
(except for
the actual formatted output).

https://code.launchpad.net/~thumper/juju-core/default-command-info/+merge/194061

(do not edit description out of merge proposal)

Please review this at https://codereview.appspot.com/22320043/

Affected files (+139, -28 lines):
   A [revision details]
   M cmd/export_test.go
   M cmd/logging.go
   M cmd/logging_test.go

[Ian Booth (wallyworld)]

A few questions.

1. -d for debug is sorta bad

There's a number of existing commands that use the -d option (eg for
specifying a directory) so I think we want to stcik with just --debug

2. Does it make sense to allow -q and --debug together?

If you want debug, then I think you would want everything else as well

3. show-log

I think if verbose is specified, that could turn on show-log. Do we
still need show-log? I'm not sure we do. For a user's perspective, I
want to see either:

i. nothing at all except errors... option = "--quiet"
ii. informational lines that signpost where the command is up to as it
executes (without timestamps etc)... the default, option = ""
iii. verbose output with timestamps and some more detail... option =
"--verbose"

As a developer, I also want:

iv. debug output with everything... option = "--debug"

I'm not sure with the above if show-log is still relevant.

As for the stdout vs stderr thing, I can see both sides. My initial view
is that stderr is for all log outout and stdout is for command results
in json/yaml etc

https://codereview.appspot.com/22320043/diff/1/cmd/logging.go
File cmd/logging.go (right):

https://codereview.appspot.com/22320043/diff/1/cmd/logging.go#newcode77
cmd/logging.go:77: return fmt.Errorf(`"verbose" and "quiet" flags
clash`)
perhaps

"verbose" and "quiet" flags clash, please use one or the other, not both

https://codereview.appspot.com/22320043/

[William Reade (fwereade)]

On 2013/11/06 04:04:42, thumper wrote:
> Please take a look.

I'm sure we want to keep informational messages to stderr. Still
thinking about the other points raised.

https://codereview.appspot.com/22320043/

[John A Meinel (jameinel)]

We have a cmd.Context object which is passed to all the commands, and is
something that we can then pass into internal code.

It seems better to have it on an object, rather than as a package level
function.

does that make sense to you?

https://codereview.appspot.com/22320043/

[William Reade (fwereade)]

On 2013/11/06 11:45:34, jameinel wrote:
> We have a cmd.Context object which is passed to all the commands, and
is
> something that we can then pass into internal code.

> It seems better to have it on an object, rather than as a package
level
> function.

> does that make sense to you?

That's actually starting to make more and more sense, because:

1) the value of this gets lower and lower as more functionality moves
behind the API -- it becomes more and more convenient to just write to
the cmd.Context that's right there in Run

2) bootstrap and (manual) add-machine feel like the major exceptions to
the above, but both of those need the context anyway for sudo (and given
that we probably ought not to be reading env vars directly, we probably
ought to be communicating those to bootstrap via some such context too).

What's the actual set of potential users for this code once the CLI
talks API?

https://codereview.appspot.com/22320043/

[William Reade (fwereade)]

WIPping -- any further thoughts, tim?

[Tim Penhey (thumper)]

Please take a look.

https://codereview.appspot.com/22320043/

[Tim Penhey (thumper)]

On 2013/11/06 04:31:25, wallyworld wrote:
> A few questions.

> 1. -d for debug is sorta bad

> There's a number of existing commands that use the -d option (eg for
specifying
> a directory) so I think we want to stcik with just --debug

Removed -d

> 2. Does it make sense to allow -q and --debug together?

> If you want debug, then I think you would want everything else as well

Yes -q and --debug is fine (IMO). In fact I force the fact, as if you
say
--debug, by forcing -q we get all the info, and verbose output as log
file
entries.

> 3. show-log

> I think if verbose is specified, that could turn on show-log. Do we
still need
> show-log? I'm not sure we do. For a user's perspective, I want to see
either:

> i. nothing at all except errors... option = "--quiet"
> ii. informational lines that signpost where the command is up to as it
executes
> (without timestamps etc)... the default, option = ""
> iii. verbose output with timestamps and some more detail... option =
"--verbose"

> As a developer, I also want:

> iv. debug output with everything... option = "--debug"

> I'm not sure with the above if show-log is still relevant.

Perhaps not... but outside the scope of this for now.

> As for the stdout vs stderr thing, I can see both sides. My initial
view is that
> stderr is for all log outout and stdout is for command results in
json/yaml etc

> https://codereview.appspot.com/22320043/diff/1/cmd/logging.go
> File cmd/logging.go (right):

https://codereview.appspot.com/22320043/diff/1/cmd/logging.go#newcode77
> cmd/logging.go:77: return fmt.Errorf(`"verbose" and "quiet" flags
clash`)
> perhaps

> "verbose" and "quiet" flags clash, please use one or the other, not
both

done

https://codereview.appspot.com/22320043/

[Tim Penhey (thumper)]

On 2013/11/06 10:44:31, fwereade wrote:
> On 2013/11/06 04:04:42, thumper wrote:
> > Please take a look.

> I'm sure we want to keep informational messages to stderr. Still
thinking about
> the other points raised.

kept them on stderr

https://codereview.appspot.com/22320043/

[Tim Penhey (thumper)]

On 2013/11/06 11:45:34, jameinel wrote:
> We have a cmd.Context object which is passed to all the commands, and
is
> something that we can then pass into internal code.

> It seems better to have it on an object, rather than as a package
level
> function.

> does that make sense to you?

moved the methods to the context object.

I had originally thought that by having them as stand alone functions,
we wouldn't have to pass the context down to the places that are needing
them.

Consider the bastardisation we have with loggers at the moment.

https://codereview.appspot.com/22320043/

[Ian Booth (wallyworld)]

LGTM

https://codereview.appspot.com/22320043/diff/20001/cmd/cmd.go
File cmd/cmd.go (right):

https://codereview.appspot.com/22320043/diff/20001/cmd/cmd.go#newcode110
cmd/cmd.go:110: // the logger if we are.
....?
Doesn't quite parse

https://codereview.appspot.com/22320043/

=== modified file 'cmd/cmd.go'
--- cmd/cmd.go	2014-03-24 13:23:40 +0000
+++ cmd/cmd.go	2014-03-26 01:26:35 +0000
@@ -90,10 +90,40 @@
 // should interpret file names relative to Dir (see AbsPath below), and print
 // output and errors to Stdout and Stderr respectively.
 type Context struct {
-	Dir    string
-	Stdin  io.Reader
-	Stdout io.Writer
-	Stderr io.Writer
+	Dir     string
+	Stdin   io.Reader
+	Stdout  io.Writer
+	Stderr  io.Writer
+	quiet   bool
+	verbose bool
+}
+
+func (ctx *Context) write(format string, params ...interface{}) {
+	output := fmt.Sprintf(format, params...)
+	if !strings.HasSuffix(output, "\n") {
+		output = output + "\n"
+	}
+	fmt.Fprint(ctx.Stderr, output)
+}
+
+// Infof will write the formatted string to Stderr if quiet is false, but if
+// quiet is true the message is logged.
+func (ctx *Context) Infof(format string, params ...interface{}) {
+	if ctx.quiet {
+		logger.Infof(format, params...)
+	} else {
+		ctx.write(format, params...)
+	}
+}
+
+// Verbosef will write the formatted string to Stderr if the verbose is true,
+// and to the logger if not.
+func (ctx *Context) Verbosef(format string, params ...interface{}) {
+	if ctx.verbose {
+		ctx.write(format, params...)
+	} else {
+		logger.Infof(format, params...)
+	}
 }
 
 // AbsPath returns an absolute representation of path, with relative paths

=== modified file 'cmd/juju/deploy.go'
--- cmd/juju/deploy.go	2014-03-18 05:08:25 +0000
+++ cmd/juju/deploy.go	2014-03-26 01:26:35 +0000
@@ -150,7 +150,7 @@
 	}
 
 	if c.BumpRevision {
-		ctx.Stdout.Write([]byte("--upgrade (or -u) is deprecated and ignored; charms are always deployed with a unique revision.\n"))
+		ctx.Infof("--upgrade (or -u) is deprecated and ignored; charms are always deployed with a unique revision.")
 	}
 
 	charmInfo, err := client.CharmInfo(curl.String())
@@ -293,7 +293,6 @@
 	default:
 		return nil, fmt.Errorf("unsupported charm URL schema: %q", curl.Schema)
 	}
-	report := fmt.Sprintf("Added charm %q to the environment.\n", curl)
-	ctx.Stdout.Write([]byte(report))
+	ctx.Infof("Added charm %q to the environment.", curl)
 	return curl, nil
 }

=== modified file 'cmd/juju/deploy_test.go'
--- cmd/juju/deploy_test.go	2014-03-13 07:54:56 +0000
+++ cmd/juju/deploy_test.go	2014-03-26 01:26:35 +0000
@@ -83,8 +83,8 @@
 	ctx, err := coretesting.RunCommand(c, &DeployCommand{}, []string{"local:dummy", "-u"})
 	c.Assert(err, gc.IsNil)
 
-	c.Assert(coretesting.Stderr(ctx), gc.Equals, "")
-	output := strings.Split(coretesting.Stdout(ctx), "\n")
+	c.Assert(coretesting.Stdout(ctx), gc.Equals, "")
+	output := strings.Split(coretesting.Stderr(ctx), "\n")
 	c.Check(output[0], gc.Matches, `Added charm ".*" to the environment.`)
 	c.Check(output[1], gc.Equals, "--upgrade (or -u) is deprecated and ignored; charms are always deployed with a unique revision.")
 }

=== modified file 'cmd/juju/main_test.go'
--- cmd/juju/main_test.go	2014-02-27 05:22:46 +0000
+++ cmd/juju/main_test.go	2014-03-26 01:26:35 +0000
@@ -316,6 +316,7 @@
 	"-h, --help .*",
 	"--log-file .*",
 	"--logging-config .*",
+	"-q, --quiet .*",
 	"--show-log .*",
 	"-v, --verbose .*",
 }

=== modified file 'cmd/logging.go'
--- cmd/logging.go	2014-03-05 19:41:34 +0000
+++ cmd/logging.go	2014-03-26 01:26:35 +0000
@@ -26,6 +26,7 @@
 type Log struct {
 	Path    string
 	Verbose bool
+	Quiet   bool
 	Debug   bool
 	ShowLog bool
 	Config  string
@@ -43,45 +44,51 @@
 // AddFlags adds appropriate flags to f.
 func (l *Log) AddFlags(f *gnuflag.FlagSet) {
 	f.StringVar(&l.Path, "log-file", "", "path to write log to")
-	// TODO(thumper): rename verbose to --show-log
-	f.BoolVar(&l.Verbose, "v", false, "if set, log additional messages")
-	f.BoolVar(&l.Verbose, "verbose", false, "if set, log additional messages")
-	f.BoolVar(&l.Debug, "debug", false, "if set, log debugging messages")
+	f.BoolVar(&l.Verbose, "v", false, "show more verbose output")
+	f.BoolVar(&l.Verbose, "verbose", false, "show more verbose output")
+	f.BoolVar(&l.Quiet, "q", false, "show no informational output")
+	f.BoolVar(&l.Quiet, "quiet", false, "show no informational output")
+	f.BoolVar(&l.Debug, "debug", false, "equivalent to --show-log --log-config=<root>=DEBUG")
 	defaultLogConfig := os.Getenv(osenv.JujuLoggingConfigEnvKey)
 	f.StringVar(&l.Config, "logging-config", defaultLogConfig, "specify log levels for modules")
 	f.BoolVar(&l.ShowLog, "show-log", false, "if set, write the log file to stderr")
 }
 
 // Start starts logging using the given Context.
-func (l *Log) Start(ctx *Context) error {
-	if l.Path != "" {
-		path := ctx.AbsPath(l.Path)
+func (log *Log) Start(ctx *Context) error {
+	if log.Verbose && log.Quiet {
+		return fmt.Errorf(`"verbose" and "quiet" flags clash, please use one or the other, not both`)
+	}
+	ctx.quiet = log.Quiet
+	ctx.verbose = log.Verbose
+	if log.Path != "" {
+		path := ctx.AbsPath(log.Path)
 		target, err := os.OpenFile(path, os.O_WRONLY|os.O_APPEND|os.O_CREATE, 0644)
 		if err != nil {
 			return err
 		}
-		writer := l.GetLogWriter(target)
+		writer := log.GetLogWriter(target)
 		err = loggo.RegisterWriter("logfile", writer, loggo.TRACE)
 		if err != nil {
 			return err
 		}
 	}
 	level := loggo.WARNING
-	if l.Verbose {
-		ctx.Stdout.Write([]byte("Flag --verbose is deprecated with the current meaning, use --show-log\n"))
-		l.ShowLog = true
-	}
-	if l.ShowLog {
+	if log.ShowLog {
 		level = loggo.INFO
 	}
-	if l.Debug {
-		l.ShowLog = true
+	if log.Debug {
+		log.ShowLog = true
 		level = loggo.DEBUG
+		// override quiet or verbose if set, this way all the information goes
+		// to the log file.
+		ctx.quiet = true
+		ctx.verbose = false
 	}
 
-	if l.ShowLog {
+	if log.ShowLog {
 		// We replace the default writer to use ctx.Stderr rather than os.Stderr.
-		writer := l.GetLogWriter(ctx.Stderr)
+		writer := log.GetLogWriter(ctx.Stderr)
 		_, err := loggo.ReplaceDefaultWriter(writer)
 		if err != nil {
 			return err
@@ -99,7 +106,7 @@
 	// Set the level on the root logger.
 	loggo.GetLogger("").SetLogLevel(level)
 	// Override the logging config with specified logging config.
-	loggo.ConfigureLoggers(l.Config)
+	loggo.ConfigureLoggers(log.Config)
 	return nil
 }
 

=== modified file 'cmd/logging_test.go'
--- cmd/logging_test.go	2014-03-18 15:43:41 +0000
+++ cmd/logging_test.go	2014-03-26 01:26:35 +0000
@@ -25,6 +25,7 @@
 var _ = gc.Suite(&LogSuite{})
 
 func (s *LogSuite) SetUpTest(c *gc.C) {
+	s.CleanupSuite.SetUpTest(c)
 	s.PatchEnvironment(osenv.JujuLoggingConfigEnvKey, "")
 	s.AddCleanup(func(_ *gc.C) {
 		loggo.ResetLoggers()
@@ -44,6 +45,7 @@
 func (s *LogSuite) TestNoFlags(c *gc.C) {
 	log := newLogWithFlags(c, []string{})
 	c.Assert(log.Path, gc.Equals, "")
+	c.Assert(log.Quiet, gc.Equals, false)
 	c.Assert(log.Verbose, gc.Equals, false)
 	c.Assert(log.Debug, gc.Equals, false)
 	c.Assert(log.Config, gc.Equals, "")
@@ -68,17 +70,6 @@
 	c.Assert(log.Config, gc.Equals, config)
 }
 
-func (s *LogSuite) TestVerboseSetsLogLevel(c *gc.C) {
-	l := &cmd.Log{Verbose: true}
-	ctx := coretesting.Context(c)
-	err := l.Start(ctx)
-	c.Assert(err, gc.IsNil)
-
-	c.Assert(loggo.GetLogger("").LogLevel(), gc.Equals, loggo.INFO)
-	c.Assert(coretesting.Stderr(ctx), gc.Equals, "")
-	c.Assert(coretesting.Stdout(ctx), gc.Equals, "Flag --verbose is deprecated with the current meaning, use --show-log\n")
-}
-
 func (s *LogSuite) TestDebugSetsLogLevel(c *gc.C) {
 	l := &cmd.Log{Debug: true}
 	ctx := coretesting.Context(c)
@@ -102,7 +93,7 @@
 }
 
 func (s *LogSuite) TestStderr(c *gc.C) {
-	l := &cmd.Log{Verbose: true, Config: "<root>=INFO"}
+	l := &cmd.Log{ShowLog: true, Config: "<root>=INFO"}
 	ctx := coretesting.Context(c)
 	err := l.Start(ctx)
 	c.Assert(err, gc.IsNil)
@@ -161,3 +152,88 @@
 	c.Assert(coretesting.Stderr(ctx), gc.Matches, `^.*WARNING a warning\n.*ERROR an error\n.*`)
 	c.Assert(coretesting.Stdout(ctx), gc.Equals, "")
 }
+
+func (s *LogSuite) TestQuietAndVerbose(c *gc.C) {
+	l := &cmd.Log{Verbose: true, Quiet: true}
+	ctx := coretesting.Context(c)
+	err := l.Start(ctx)
+	c.Assert(err, gc.ErrorMatches, `"verbose" and "quiet" flags clash, please use one or the other, not both`)
+}
+
+func (s *LogSuite) TestOutputDefault(c *gc.C) {
+	l := &cmd.Log{}
+	ctx := coretesting.Context(c)
+	err := l.Start(ctx)
+	c.Assert(err, gc.IsNil)
+
+	ctx.Infof("Writing info output")
+	ctx.Verbosef("Writing verbose output")
+
+	c.Assert(coretesting.Stderr(ctx), gc.Equals, "Writing info output\n")
+}
+
+func (s *LogSuite) TestOutputVerbose(c *gc.C) {
+	l := &cmd.Log{Verbose: true}
+	ctx := coretesting.Context(c)
+	err := l.Start(ctx)
+	c.Assert(err, gc.IsNil)
+
+	ctx.Infof("Writing info output")
+	ctx.Verbosef("Writing verbose output")
+
+	c.Assert(coretesting.Stderr(ctx), gc.Equals, "Writing info output\nWriting verbose output\n")
+}
+
+func (s *LogSuite) TestOutputQuiet(c *gc.C) {
+	l := &cmd.Log{Quiet: true}
+	ctx := coretesting.Context(c)
+	err := l.Start(ctx)
+	c.Assert(err, gc.IsNil)
+
+	ctx.Infof("Writing info output")
+	ctx.Verbosef("Writing verbose output")
+
+	c.Assert(coretesting.Stderr(ctx), gc.Equals, "")
+}
+
+func (s *LogSuite) TestOutputQuietLogs(c *gc.C) {
+	l := &cmd.Log{Quiet: true, Path: "foo.log", Config: "<root>=INFO"}
+	ctx := coretesting.Context(c)
+	err := l.Start(ctx)
+	c.Assert(err, gc.IsNil)
+
+	ctx.Infof("Writing info output")
+	ctx.Verbosef("Writing verbose output")
+
+	content, err := ioutil.ReadFile(filepath.Join(ctx.Dir, "foo.log"))
+	c.Assert(err, gc.IsNil)
+	c.Assert(coretesting.Stderr(ctx), gc.Equals, "")
+	c.Assert(string(content), gc.Matches, `^.*INFO .* Writing info output\n.*INFO .*Writing verbose output\n.*`)
+}
+
+func (s *LogSuite) TestOutputDefaultLogsVerbose(c *gc.C) {
+	l := &cmd.Log{Path: "foo.log", Config: "<root>=INFO"}
+	ctx := coretesting.Context(c)
+	err := l.Start(ctx)
+	c.Assert(err, gc.IsNil)
+
+	ctx.Infof("Writing info output")
+	ctx.Verbosef("Writing verbose output")
+
+	content, err := ioutil.ReadFile(filepath.Join(ctx.Dir, "foo.log"))
+	c.Assert(err, gc.IsNil)
+	c.Assert(coretesting.Stderr(ctx), gc.Equals, "Writing info output\n")
+	c.Assert(string(content), gc.Matches, `^.*INFO .*Writing verbose output\n.*`)
+}
+
+func (s *LogSuite) TestOutputDebugForcesQuiet(c *gc.C) {
+	l := &cmd.Log{Verbose: true, Debug: true}
+	ctx := coretesting.Context(c)
+	err := l.Start(ctx)
+	c.Assert(err, gc.IsNil)
+
+	ctx.Infof("Writing info output")
+	ctx.Verbosef("Writing verbose output")
+
+	c.Assert(coretesting.Stderr(ctx), gc.Matches, `^.*INFO .* Writing info output\n.*INFO .*Writing verbose output\n.*`)
+}