Merge lp:~thumper/juju-core/logger-worker into lp:~go-bot/juju-core/trunk

[Tim Penhey]

Add a worker to update loggo configuration.

With the logging config now specified in the
environment configuration, we can watch to
see if it changes. If it does, this worker
updates the loggo configuration.

You can now change the logging levels of a
running juju environment using:
  juju set-env 'logging-config=<root>=WARNING;juju=INFO;juju.api=DEBUG'

https://codereview.appspot.com/13587045/

Add a worker to update loggo configuration.

With the logging config now specified in the
environment configuration, we can watch to
see if it changes. If it does, this worker
updates the loggo configuration.

You can now change the logging levels of a
running juju environment using:
  juju set-env 'logging-config=<root>=WARNING;juju=INFO;juju.api=DEBUG'

https://codereview.appspot.com/13587045/

[Tim Penhey (thumper)]

Reviewers: mp+185421_code.launchpad.net,

Message:
Please take a look.

Description:
Add a worker to update loggo configuration.

With the logging config now specified in the
environment configuration, we can watch to
see if it changes. If it does, this worker
updates the loggo configuration.

You can now change the logging levels of a
running juju environment using:
   juju set-env 'logging-config=<root>=WARNING;juju=INFO;juju.api=DEBUG'

https://code.launchpad.net/~thumper/juju-core/logger-worker/+merge/185421

(do not edit description out of merge proposal)

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

Affected files (+229, -3 lines):
   A [revision details]
   M agent/agent.go
   M cmd/jujud/machine.go
   M cmd/jujud/unit.go
   M upstart/service.go
   A worker/logger/logger.go
   A worker/logger/logger_test.go
   A worker/logger/package_test.go

[William Reade (fwereade)]

LGTM in itself, but I feel the agent.Config stuff is risky, and want to
know what the plan is there.

https://codereview.appspot.com/13587045/diff/1/worker/logger/logger.go
File worker/logger/logger.go (right):

https://codereview.appspot.com/13587045/diff/1/worker/logger/logger.go#newcode57
worker/logger/logger.go:57: if err := logger.agentConfig.Write(); err !=
nil {
The way I see it, we have now used our one strike. We can't write
anything else to the agent config now, because any two writes can race
and cause one to be overwritten... but nothing has happened around the
config itself that might tip us off to that fact.

And I'm really worried that we *won't* write agent config soon enough
that anyone remembers this pitfall exists when we come to do so. Do you
have any suggestions for mitigation?

https://codereview.appspot.com/13587045/

[William Reade (fwereade)]

NOT LGTM I'm afraid. I know it's just writing a field that's not
currently read by other things, but there's literally no way to tell
it's dangerous.

https://codereview.appspot.com/13587045/diff/1/worker/logger/logger.go
File worker/logger/logger.go (right):

https://codereview.appspot.com/13587045/diff/1/worker/logger/logger.go#newcode57
worker/logger/logger.go:57: if err := logger.agentConfig.Write(); err !=
nil {
On 2013/09/13 10:06:59, fwereade wrote:
> The way I see it, we have now used our one strike. We can't write
anything else
> to the agent config now, because any two writes can race and cause one
to be
> overwritten... but nothing has happened around the config itself that
might tip
> us off to that fact.

> And I'm really worried that we *won't* write agent config soon enough
that
> anyone remembers this pitfall exists when we come to do so. Do you
have any
> suggestions for mitigation?

Actually it's worse... this write is past our zeroth strike, because
this object is shared by multiple goroutines. I think that config needs
fixes before this can go in.

https://codereview.appspot.com/13587045/

[Tim Penhey (thumper)]

Please take a look.

https://codereview.appspot.com/13587045/diff/1/worker/logger/logger.go
File worker/logger/logger.go (right):

https://codereview.appspot.com/13587045/diff/1/worker/logger/logger.go#newcode57
worker/logger/logger.go:57: if err := logger.agentConfig.Write(); err !=
nil {
On 2013/09/13 14:03:20, fwereade wrote:
> On 2013/09/13 10:06:59, fwereade wrote:
> > The way I see it, we have now used our one strike. We can't write
anything
> else
> > to the agent config now, because any two writes can race and cause
one to be
> > overwritten... but nothing has happened around the config itself
that might
> tip
> > us off to that fact.
> >
> > And I'm really worried that we *won't* write agent config soon
enough that
> > anyone remembers this pitfall exists when we come to do so. Do you
have any
> > suggestions for mitigation?

> Actually it's worse... this write is past our zeroth strike, because
this object
> is shared by multiple goroutines. I think that config needs fixes
before this
> can go in.

No, I don't see any problem here at all.

In order to avoid the controversy at this stage, I have moved the actual
saving of the updated logging config to a different branch so we can
continue the discussion there and not block the dynamic logging changes.

Ok, so here is what happens to the agent config when changes are made.
There is exactly one copy of the agent config instance that is passed
between the different go routines and workers inside the unit and
machine agents. Any update to the values stored in the the agent are
protected by the agent mutex for both writes and reads of that config
value. One worker writing to a value and another worker reading from
that value has no race conditions. It is immediately available in the
other go routine once the mutex is unlocked.

Since the write is also protected by the mutex, there is no possibility
of overwriting the changes made by a different worker. Ok, there is one
possibility, where two different workers are trying to modify and save
one value, but that is somewhat outside the scope of the agent config as
it is a normal race condition that needs to be handled by the competing
tasks and has nothing to do with the synchronization of the agent config
itself. Also, not an issue here.

Why do you think that once we have written something, we can't write
something else? This doesn't make sense to me and I can't see where you
are coming from. Can you please explain?

The config has fixes around synchronization of writes and setting and
getting values. What other fixes do you think are needed?

What are your concerns about this object being used in multiple go
routines?

https://codereview.appspot.com/13587045/

[Tim Penhey (thumper)]

Also had a chat with Ian about this just now.

We have decided that we don't actually need to save the new logging
config in the agent config at all. The main use case for it was for
dealing with the initial debugging of the agent process starting prior
to the worker getting the initial config over the API. My next branch
handles this by passing the information over the command line in the
upstart script.

Since this initial logging config is used only until the worker starts
and gets the updated config, we don't really need to save it at all.
Which does make me a little frustrated that I spent all that time
futzing with the config, but at least it is in a cleaner state now.

https://codereview.appspot.com/13587045/

[Tim Penhey (thumper)]

Please take a look.

https://codereview.appspot.com/13587045/

[William Reade (fwereade)]

LGTM. Sorry about the frustration -- maybe we can argue about
appropriate use of a Config over beers at some point :).

https://codereview.appspot.com/13587045/

=== modified file 'cmd/jujud/machine.go'
--- cmd/jujud/machine.go	2013-09-12 21:32:12 +0000
+++ cmd/jujud/machine.go	2013-09-15 23:43:09 +0000
@@ -28,6 +28,7 @@
 	"launchpad.net/juju-core/worker/cleaner"
 	"launchpad.net/juju-core/worker/deployer"
 	"launchpad.net/juju-core/worker/firewaller"
+	"launchpad.net/juju-core/worker/logger"
 	"launchpad.net/juju-core/worker/machiner"
 	"launchpad.net/juju-core/worker/minunitsworker"
 	"launchpad.net/juju-core/worker/provisioner"
@@ -173,14 +174,15 @@
 		ensureStateWorker()
 	}
 	runner := newRunner(connectionIsFatal(st), moreImportant)
-	// Only the machiner currently connects to the API.
-	// Add other workers here as they are ready.
 	runner.StartWorker("machiner", func() (worker.Worker, error) {
 		return machiner.NewMachiner(st.Machiner(), agentConfig), nil
 	})
 	runner.StartWorker("upgrader", func() (worker.Worker, error) {
 		return upgrader.NewUpgrader(st.Upgrader(), agentConfig), nil
 	})
+	runner.StartWorker("logger", func() (worker.Worker, error) {
+		return logger.NewLogger(st.Logger(), agentConfig), nil
+	})
 	for _, job := range entity.Jobs() {
 		switch job {
 		case params.JobHostUnits:

=== modified file 'cmd/jujud/unit.go'
--- cmd/jujud/unit.go	2013-09-12 17:10:20 +0000
+++ cmd/jujud/unit.go	2013-09-15 23:43:09 +0000
@@ -14,6 +14,7 @@
 	"launchpad.net/juju-core/names"
 	"launchpad.net/juju-core/state"
 	"launchpad.net/juju-core/worker"
+	"launchpad.net/juju-core/worker/logger"
 	"launchpad.net/juju-core/worker/uniter"
 	"launchpad.net/juju-core/worker/upgrader"
 )
@@ -87,6 +88,9 @@
 	runner.StartWorker("upgrader", func() (worker.Worker, error) {
 		return upgrader.NewUpgrader(st.Upgrader(), agentConfig), nil
 	})
+	runner.StartWorker("logger", func() (worker.Worker, error) {
+		return logger.NewLogger(st.Logger(), agentConfig), nil
+	})
 	runner.StartWorker("uniter", func() (worker.Worker, error) {
 		return uniter.NewUniter(st.Uniter(), entity.Tag(), dataDir), nil
 	})

=== added directory 'worker/logger'
=== added file 'worker/logger/logger.go'
--- worker/logger/logger.go	1970-01-01 00:00:00 +0000
+++ worker/logger/logger.go	2013-09-15 23:43:09 +0000
@@ -0,0 +1,75 @@
+// Copyright 2013 Canonical Ltd.
+// Licensed under the AGPLv3, see LICENCE file for details.
+
+package logger
+
+import (
+	"launchpad.net/loggo"
+
+	"launchpad.net/juju-core/agent"
+	"launchpad.net/juju-core/state/api/logger"
+	"launchpad.net/juju-core/state/api/watcher"
+	"launchpad.net/juju-core/worker"
+)
+
+var log = loggo.GetLogger("juju.worker.logger")
+
+// Logger is responsible for updating the loggo configuration when the
+// environment watcher tells the agent that the value has changed.
+type Logger struct {
+	api         *logger.State
+	agentConfig agent.Config
+	lastConfig  string
+}
+
+var _ worker.NotifyWatchHandler = (*Logger)(nil)
+
+// NewLogger returns a worker.Worker that uses the notify watcher returned
+// from the setup.
+func NewLogger(api *logger.State, agentConfig agent.Config) worker.Worker {
+	logger := &Logger{
+		api:         api,
+		agentConfig: agentConfig,
+		lastConfig:  loggo.LoggerInfo(),
+	}
+	log.Debugf("initial log config: %q", logger.lastConfig)
+	return worker.NewNotifyWorker(logger)
+}
+
+func (logger *Logger) setLogging() {
+	loggingConfig, err := logger.api.LoggingConfig(logger.agentConfig.Tag())
+	if err != nil {
+		log.Errorf("%v", err)
+	} else {
+		if loggingConfig != logger.lastConfig {
+			log.Debugf("reconfiguring logging from %q to %q", logger.lastConfig, loggingConfig)
+			loggo.ResetLoggers()
+			if err := loggo.ConfigureLoggers(loggingConfig); err != nil {
+				// This shouldn't occur as the loggingConfig should be
+				// validated by the original Config before it gets here.
+				log.Warningf("configure loggers failed: %v", err)
+				// Try to reset to what we had before
+				loggo.ConfigureLoggers(logger.lastConfig)
+			}
+			logger.lastConfig = loggingConfig
+		}
+	}
+}
+
+func (logger *Logger) SetUp() (watcher.NotifyWatcher, error) {
+	log.Debugf("logger setup")
+	// We need to set this up initially as the NotifyWorker sucks up the first
+	// event.
+	logger.setLogging()
+	return logger.api.WatchLoggingConfig(logger.agentConfig.Tag())
+}
+
+func (logger *Logger) Handle() error {
+	logger.setLogging()
+	return nil
+}
+
+func (logger *Logger) TearDown() error {
+	// Nothing to cleanup, only state is the watcher
+	return nil
+}

=== added file 'worker/logger/logger_test.go'
--- worker/logger/logger_test.go	1970-01-01 00:00:00 +0000
+++ worker/logger/logger_test.go	2013-09-15 23:43:09 +0000
@@ -0,0 +1,103 @@
+// Copyright 2013 Canonical Ltd.
+// Licensed under the AGPLv3, see LICENCE file for details.
+
+package logger_test
+
+import (
+	"time"
+
+	gc "launchpad.net/gocheck"
+	"launchpad.net/loggo"
+
+	"launchpad.net/juju-core/agent"
+	"launchpad.net/juju-core/juju/testing"
+	"launchpad.net/juju-core/state"
+	"launchpad.net/juju-core/state/api"
+	apilogger "launchpad.net/juju-core/state/api/logger"
+	"launchpad.net/juju-core/worker"
+	"launchpad.net/juju-core/worker/logger"
+)
+
+// worstCase is used for timeouts when timing out
+// will fail the test. Raising this value should
+// not affect the overall running time of the tests
+// unless they fail.
+const worstCase = 5 * time.Second
+
+type LoggerSuite struct {
+	testing.JujuConnSuite
+
+	apiRoot   *api.State
+	loggerApi *apilogger.State
+	machine   *state.Machine
+}
+
+var _ = gc.Suite(&LoggerSuite{})
+
+func (s *LoggerSuite) SetUpTest(c *gc.C) {
+	s.JujuConnSuite.SetUpTest(c)
+	s.apiRoot, s.machine = s.OpenAPIAsNewMachine(c)
+	s.AddCleanup(func() { s.apiRoot.Close() })
+	// Create the machiner API facade.
+	s.loggerApi = s.apiRoot.Logger()
+	c.Assert(s.loggerApi, gc.NotNil)
+}
+
+func (s *LoggerSuite) waitLoggingInfo(c *gc.C, expected string) {
+	timeout := time.After(worstCase)
+	for {
+		select {
+		case <-timeout:
+			c.Fatalf("timeout while waiting for logging info to change")
+		case <-time.After(10 * time.Millisecond):
+			loggerInfo := loggo.LoggerInfo()
+			if loggerInfo != expected {
+				c.Logf("logging is %q, still waiting", loggerInfo)
+				continue
+			}
+			return
+		}
+	}
+}
+
+type mockConfig struct {
+	agent.Config
+	c   *gc.C
+	tag string
+}
+
+func (mock *mockConfig) Tag() string {
+	return mock.tag
+}
+
+func agentConfig(c *gc.C, tag string) *mockConfig {
+	return &mockConfig{c: c, tag: tag}
+}
+
+func (s *LoggerSuite) makeLogger(c *gc.C) (worker.Worker, *mockConfig) {
+	config := agentConfig(c, s.machine.Tag())
+	return logger.NewLogger(s.loggerApi, config), config
+}
+
+func (s *LoggerSuite) TestRunStop(c *gc.C) {
+	loggingWorker, _ := s.makeLogger(c)
+	c.Assert(worker.Stop(loggingWorker), gc.IsNil)
+}
+
+func (s *LoggerSuite) TestInitialState(c *gc.C) {
+	config, err := s.State.EnvironConfig()
+	c.Assert(err, gc.IsNil)
+	expected := config.LoggingConfig()
+
+	initial := "<root>=DEBUG;wibble=ERROR"
+	c.Assert(expected, gc.Not(gc.Equals), initial)
+
+	loggo.ResetLoggers()
+	err = loggo.ConfigureLoggers(initial)
+	c.Assert(err, gc.IsNil)
+
+	loggingWorker, _ := s.makeLogger(c)
+	defer worker.Stop(loggingWorker)
+
+	s.waitLoggingInfo(c, expected)
+}

=== added file 'worker/logger/package_test.go'
--- worker/logger/package_test.go	1970-01-01 00:00:00 +0000
+++ worker/logger/package_test.go	2013-09-15 23:43:09 +0000
@@ -0,0 +1,14 @@
+// Copyright 2013 Canonical Ltd.
+// Licensed under the AGPLv3, see LICENCE file for details.
+
+package logger_test
+
+import (
+	stdtesting "testing"
+
+	"launchpad.net/juju-core/testing"
+)
+
+func TestAll(t *stdtesting.T) {
+	testing.MgoTestPackage(t)
+}