Merge pull request juju#18768 from SimonRichardson/logger-context-v3

juju#18768

Introduces `context.Context` to the `logger.Logger` interface. The main driver behind this is the following:

- For all model facade requests, a model uuid is inserted into the context[1]. This will allow us to annotate all lot messages with a model uuid. This will pay dividends when we're exporting all logs to loki or similar. This also has the advantage that logs can be bifurcated based on the uuid to different log files for machines.
- Trace IDs can also be associated with log messages, so it will be possible to see which logs are associated with a trace.
- Status history epic. Long term we don't want to store the information in the database, instead we want the information be part of the logging system. For this to work, we need the model UUID to be part of the logs (first point), but more work is required to make sure the model UUID is part of the model workers. That will have to be added later.
- This opens up the avenue for using the std library slog package in the future.

1. https://github.com/juju/juju/blob/5e972995681ae74a95bef063a31e4e253e6157c7/apiserver/apiserver.go#L1085-L1088

---

The code is relatively simple, it just introduces a context.Context as part of the method signature and the wire up of the context either via a TODO or Background context is used.

---

This pull request introduces the use of the `context.TODO()` function in multiple logging statements across various files. The main goal is to ensure that context is passed consistently to logging functions. The most important changes include modifications in the logging statements within the `agent` package and its sub-packages.

### Changes to logging statements:

* [`agent/addons/addons.go`](diffhunk://#diff-0191ac6f46a09950e162024d968a73443d818f06ee6723204b5da9bdfd4e569cL59-R60): Added `context.TODO()` to logging statements in the `StartIntrospection` function. [[1]](diffhunk://#diff-0191ac6f46a09950e162024d968a73443d818f06ee6723204b5da9bdfd4e569cL59-R60) [[2]](diffhunk://#diff-0191ac6f46a09950e162024d968a73443d818f06ee6723204b5da9bdfd4e569cL82-R86)
* [`agent/agent.go`](diffhunk://#diff-62b6ad581fe3a3059ae8c85ef0f31dde4092bfdecfa7d6857c470bcacaa8cc8bL674-R675): Added `context.TODO()` to logging statements in several functions, including `ReadConfig`, `ParseConfigData`, and `SetAPIHostPorts`. [[1]](diffhunk://#diff-62b6ad581fe3a3059ae8c85ef0f31dde4092bfdecfa7d6857c470bcacaa8cc8bL674-R675) [[2]](diffhunk://#diff-62b6ad581fe3a3059ae8c85ef0f31dde4092bfdecfa7d6857c470bcacaa8cc8bL685-R686) [[3]](diffhunk://#diff-62b6ad581fe3a3059ae8c85ef0f31dde4092bfdecfa7d6857c470bcacaa8cc8bL725-R726)
* [`agent/agentbootstrap/bootstrap.go`](diffhunk://#diff-ea4f262b8f5d83da16a99c2bcc52a1156553e069197bb2dd9476f3a6db6b88ffL297-R298): Added `context.TODO()` to logging statements in the `Initialize` and `initBootstrapMachine` functions. [[1]](diffhunk://#diff-ea4f262b8f5d83da16a99c2bcc52a1156553e069197bb2dd9476f3a6db6b88ffL297-R298) [[2]](diffhunk://#diff-ea4f262b8f5d83da16a99c2bcc52a1156553e069197bb2dd9476f3a6db6b88ffL324-R325) [[3]](diffhunk://#diff-ea4f262b8f5d83da16a99c2bcc52a1156553e069197bb2dd9476f3a6db6b88ffL382-R383) [[4]](diffhunk://#diff-ea4f262b8f5d83da16a99c2bcc52a1156553e069197bb2dd9476f3a6db6b88ffL461-R462) [[5]](diffhunk://#diff-ea4f262b8f5d83da16a99c2bcc52a1156553e069197bb2dd9476f3a6db6b88ffL530-R537) [[6]](diffhunk://#diff-ea4f262b8f5d83da16a99c2bcc52a1156553e069197bb2dd9476f3a6db6b88ffL558-R559)
* [`agent/errors/errors.go`](diffhunk://#diff-8cbdaee7b46342e4d485da5552e2d068ff1036ef7c1fa2298099a069304c2c4fL44-R44): Added `context.TODO()` to logging statements in `ChangeAgentTools` and `PingerIsFatal` functions. [[1]](diffhunk://#diff-8cbdaee7b46342e4d485da5552e2d068ff1036ef7c1fa2298099a069304c2c4fL44-R44) [[2]](diffhunk://#diff-8cbdaee7b46342e4d485da5552e2d068ff1036ef7c1fa2298099a069304c2c4fL164-R164)
* [`api/apiclient.go`](diffhunk://#diff-5dad8af7a39fbc96262fc8f20b0829d71567703b4d4553c1578cb8fb49aad5d8L501-R505): Added `context.TODO()` to logging statements in several functions, including `dialAPI`, `next`, and `lookupIPAddr`. [[1]](diffhunk://#diff-5dad8af7a39fbc96262fc8f20b0829d71567703b4d4553c1578cb8fb49aad5d8L501-R505) [[2]](diffhunk://#diff-5dad8af7a39fbc96262fc8f20b0829d71567703b4d4553c1578cb8fb49aad5d8L563-R563) [[3]](diffhunk://#diff-5dad8af7a39fbc96262fc8f20b0829d71567703b4d4553c1578cb8fb49aad5d8L681-R681) [[4]](diffhunk://#diff-5dad8af7a39fbc96262fc8f20b0829d71567703b4d4553c1578cb8fb49aad5d8L786-R794) [[5]](diffhunk://#diff-5dad8af7a39fbc96262fc8f20b0829d71567703b4d4553c1578cb8fb49aad5d8L918-R918) [[6]](diffhunk://#diff-5dad8af7a39fbc96262fc8f20b0829d71567703b4d4553c1578cb8fb49aad5d8L930-R930) [[7]](diffhunk://#diff-5dad8af7a39fbc96262fc8f20b0829d71567703b4d4553c1578cb8fb49aad5d8L1012-R1012) [[8]](diffhunk://#diff-5dad8af7a39fbc96262fc8f20b0829d71567703b4d4553c1578cb8fb49aad5d8L1025-R1028) [[9]](diffhunk://#diff-5dad8af7a39fbc96262fc8f20b0829d71567703b4d4553c1578cb8fb49aad5d8L1055-R1055)

## QA Steps

```sh
$ juju bootstrap lxd test
$ juju add-model default
$ juju deploy ubuntu
```

agent/addons/addons.go

@@ -4,6 +4,7 @@
 package addons
 
 import (
+	"context"
 	"path"
 	"runtime"
 
@@ -56,7 +57,7 @@ type IntrospectionConfig struct {
 // life to that of the engine that is returned.
 func StartIntrospection(cfg IntrospectionConfig) error {
 	if runtime.GOOS != "linux" {
-		cfg.Logger.Debugf("introspection worker not supported on %q", runtime.GOOS)
+		cfg.Logger.Debugf(context.TODO(), "introspection worker not supported on %q", runtime.GOOS)
 		return nil
 	}
 
@@ -79,10 +80,10 @@ func StartIntrospection(cfg IntrospectionConfig) error {
 	}
 	go func() {
 		_ = cfg.Engine.Wait()
-		cfg.Logger.Debugf("engine stopped, stopping introspection")
+		cfg.Logger.Debugf(context.TODO(), "engine stopped, stopping introspection")
 		w.Kill()
 		_ = w.Wait()
-		cfg.Logger.Debugf("introspection stopped")
+		cfg.Logger.Debugf(context.TODO(), "introspection stopped")
 	}()
 
 	return nil

agent/agent.go

@@ -5,6 +5,7 @@ package agent
 
 import (
 	"bytes"
+	"context"
 	"fmt"
 	"net"
 	"os"
@@ -671,7 +672,7 @@ func ReadConfig(configFilePath string) (ConfigSetterWriter, error) {
 	if err != nil {
 		return nil, err
 	}
-	logger.Debugf("read agent config, format %q", format.version())
+	logger.Debugf(context.TODO(), "read agent config, format %q", format.version())
 	config.configFilePath = configFilePath
 	return config, nil
 }
@@ -682,7 +683,7 @@ func ParseConfigData(configData []byte) (ConfigSetterWriter, error) {
 	if err != nil {
 		return nil, errors.Trace(err)
 	}
-	logger.Debugf("parsing agent config, format %q", format.version())
+	logger.Debugf(context.TODO(), "parsing agent config, format %q", format.version())
 	config.configFilePath = ConfigPath(config.paths.DataDir, config.tag)
 	return config, nil
 }
@@ -722,7 +723,7 @@ func (c *configInternal) SetAPIHostPorts(servers []network.HostPorts) error {
 		addrs = append(addrs, hps...)
 	}
 	c.apiDetails.addresses = addrs
-	logger.Debugf("API server address details %q written to agent config as %q", servers, addrs)
+	logger.Debugf(context.TODO(), "API server address details %q written to agent config as %q", servers, addrs)
 	return nil
 }
 
@@ -1119,7 +1120,7 @@ func (c *configInternal) MongoInfo() (info *mongo.MongoInfo, ok bool) {
 	// in any case (lp:1644009). Review.
 	local := net.JoinHostPort("localhost", strconv.Itoa(ssi.StatePort))
 	mongoAddrs = append([]string{local}, mongoAddrs...)
-	logger.Debugf("potential mongo addresses: %v", mongoAddrs)
+	logger.Debugf(context.TODO(), "potential mongo addresses: %v", mongoAddrs)
 	return &mongo.MongoInfo{
 		Info: mongo.Info{
 			Addrs:  mongoAddrs,

agent/agentbootstrap/bootstrap.go

@@ -4,6 +4,7 @@
 package agentbootstrap
 
 import (
+	"context"
 	stdcontext "context"
 	"fmt"
 
@@ -294,7 +295,7 @@ func (b *AgentBootstrap) Initialize(ctx stdcontext.Context) (_ *state.Controller
 	}
 	defer session.Close()
 
-	b.logger.Debugf("initializing address %v", info.Addrs)
+	b.logger.Debugf(context.TODO(), "initializing address %v", info.Addrs)
 
 	ctrl, err := state.Initialize(state.InitializeParams{
 		Clock: clock.WallClock,
@@ -321,7 +322,7 @@ func (b *AgentBootstrap) Initialize(ctx stdcontext.Context) (_ *state.Controller
 	if err != nil {
 		return nil, errors.Errorf("failed to initialize state: %v", err)
 	}
-	b.logger.Debugf("connected to initial state")
+	b.logger.Debugf(context.TODO(), "connected to initial state")
 	defer func() {
 		if resultErr != nil {
 			_ = ctrl.Close()
@@ -379,7 +380,7 @@ func (b *AgentBootstrap) Initialize(ctx stdcontext.Context) (_ *state.Controller
 	// Read the machine agent's password and change it to
 	// a new password (other agents will change their password
 	// via the API connection).
-	b.logger.Debugf("create new random password for controller %v", controllerNode.Id())
+	b.logger.Debugf(context.TODO(), "create new random password for controller %v", controllerNode.Id())
 
 	newPassword, err := password.RandomPassword()
 	if err != nil {
@@ -458,7 +459,7 @@ func (b *AgentBootstrap) initBootstrapMachine(
 	bootstrapMachineAddresses corenetwork.ProviderAddresses,
 ) (bootstrapController, error) {
 	stateParams := b.stateInitializationParams
-	b.logger.Infof("initialising bootstrap machine with config: %+v", stateParams)
+	b.logger.Infof(context.TODO(), "initialising bootstrap machine with config: %+v", stateParams)
 
 	jobs := make([]state.MachineJob, len(b.bootstrapMachineJobs))
 	for i, job := range b.bootstrapMachineJobs {
@@ -527,13 +528,13 @@ func (b *AgentBootstrap) initControllerCloudService(
 	addrs := b.getAlphaSpaceAddresses(svc.Addresses)
 
 	svcId := controllerUUID
-	b.logger.Infof("creating cloud service for k8s controller %q", svcId)
+	b.logger.Infof(context.TODO(), "creating cloud service for k8s controller %q", svcId)
 	cloudSvc, err := st.SaveCloudService(state.SaveCloudServiceArgs{
 		Id:         svcId,
 		ProviderId: svc.Id,
 		Addresses:  addrs,
 	})
-	b.logger.Debugf("created cloud service %v for controller", cloudSvc)
+	b.logger.Debugf(context.TODO(), "created cloud service %v for controller", cloudSvc)
 	return errors.Trace(err)
 }
 
@@ -555,7 +556,7 @@ func (b *AgentBootstrap) getAlphaSpaceAddresses(providerAddresses corenetwork.Pr
 func (b *AgentBootstrap) initBootstrapNode(
 	st *state.State,
 ) (bootstrapController, error) {
-	b.logger.Debugf("initialising bootstrap node for with config: %+v", b.stateInitializationParams)
+	b.logger.Debugf(context.TODO(), "initialising bootstrap node for with config: %+v", b.stateInitializationParams)
 
 	node, err := st.AddControllerNode()
 	if err != nil {

agent/errors/errors.go

@@ -41,7 +41,7 @@ func (e *UpgradeReadyError) ChangeAgentTools(logger logger.Logger) error {
 	if err != nil {
 		return err
 	}
-	logger.Infof("upgraded from %v to %v (%q)", e.OldTools, agentTools.Version, agentTools.URL)
+	logger.Infof(context.TODO(), "upgraded from %v to %v (%q)", e.OldTools, agentTools.Version, agentTools.URL)
 	return nil
 }
 
@@ -161,7 +161,7 @@ func PingerIsFatal(logger logger.Logger, conns ...Pinger) func(err error) bool {
 // PingerIsDead returns true if the given pinger fails to ping.
 var PingerIsDead = func(logger logger.Logger, conn Pinger) bool {
 	if err := conn.Ping(); err != nil {
-		logger.Infof("error pinging %T: %v", conn, err)
+		logger.Infof(context.TODO(), "error pinging %T: %v", conn, err)
 		return true
 	}
 	return false

agent/identity.go

@@ -4,6 +4,7 @@
 package agent
 
 import (
+	"context"
 	"os"
 
 	"github.com/juju/errors"
@@ -19,13 +20,13 @@ func WriteSystemIdentityFile(c Config) error {
 	}
 	// Write non-empty contents to the file, otherwise delete it
 	if info.SystemIdentity != "" {
-		logger.Infof("writing system identity file")
+		logger.Infof(context.TODO(), "writing system identity file")
 		err := utils.AtomicWriteFile(c.SystemIdentityPath(), []byte(info.SystemIdentity), 0600)
 		if err != nil {
 			return errors.Annotate(err, "cannot write system identity")
 		}
 	} else {
-		logger.Infof("removing system identity file")
+		logger.Infof(context.TODO(), "removing system identity file")
 		os.Remove(c.SystemIdentityPath())
 	}
 	return nil

agent/tools/symlinks.go

@@ -4,6 +4,7 @@
 package tools
 
 import (
+	"context"
 	"os"
 	"path/filepath"
 
@@ -17,7 +18,7 @@ import (
 // command. If the commands already exist, this operation does nothing.
 // If dir is a symbolic link, it will be dereferenced first.
 func EnsureSymlinks(jujuDir, dir string, commands []string) (err error) {
-	logger.Infof("ensure jujuc symlinks in %s", dir)
+	logger.Infof(context.TODO(), "ensure jujuc symlinks in %s", dir)
 	defer func() {
 		if err != nil {
 			err = errors.Annotatef(err, "cannot initialize commands in %q", dir)
@@ -33,21 +34,21 @@ func EnsureSymlinks(jujuDir, dir string, commands []string) (err error) {
 			return err
 		}
 		if !filepath.IsAbs(link) {
-			logger.Infof("%s is relative", link)
+			logger.Infof(context.TODO(), "%s is relative", link)
 			link = filepath.Join(filepath.Dir(dir), link)
 		}
 		jujuDir = link
-		logger.Infof("was a symlink, now looking at %s", jujuDir)
+		logger.Infof(context.TODO(), "was a symlink, now looking at %s", jujuDir)
 	}
 
 	jujucPath := filepath.Join(jujuDir, names.Jujuc)
 	targetPath := jujucPath
 	if _, err := os.Stat(jujucPath); os.IsNotExist(err) {
 		jujudPath := filepath.Join(jujuDir, names.Jujud)
-		logger.Debugf("jujuc not found at %s using jujud path %s", jujucPath, jujudPath)
+		logger.Debugf(context.TODO(), "jujuc not found at %s using jujud path %s", jujucPath, jujudPath)
 		targetPath = jujudPath
 	}
-	logger.Debugf("target tools path %s", targetPath)
+	logger.Debugf(context.TODO(), "target tools path %s", targetPath)
 	for _, name := range commands {
 		// The link operation fails when the target already exists,
 		// so this is a no-op when the command names already

agent/tools/toolsdir.go

@@ -6,6 +6,7 @@ package tools
 import (
 	"archive/tar"
 	"compress/gzip"
+	"context"
 	"crypto/sha256"
 	"encoding/json"
 	"fmt"
@@ -142,7 +143,7 @@ func removeAll(dir string) {
 	if err == nil || os.IsNotExist(err) {
 		return
 	}
-	logger.Errorf("cannot remove %q: %v", dir, err)
+	logger.Errorf(context.TODO(), "cannot remove %q: %v", dir, err)
 }
 
 func writeFile(name string, mode os.FileMode, r io.Reader) error {

api/apiclient.go

@@ -498,11 +498,11 @@ func dialAPI(ctx context.Context, info *Info, opts0 DialOpts) (*dialResult, erro
 		if err := info.Proxier.Start(ctx); err != nil {
 			return nil, errors.Annotate(err, "starting proxy for api connection")
 		}
-		logger.Debugf("starting proxier for connection")
+		logger.Debugf(context.TODO(), "starting proxier for connection")
 
 		switch p := info.Proxier.(type) {
 		case jujuproxy.TunnelProxier:
-			logger.Debugf("tunnel proxy in use at %s on port %s", p.Host(), p.Port())
+			logger.Debugf(context.TODO(), "tunnel proxy in use at %s on port %s", p.Host(), p.Port())
 			addrs = []string{
 				net.JoinHostPort(p.Host(), p.Port()),
 			}
@@ -560,7 +560,7 @@ func dialAPI(ctx context.Context, info *Info, opts0 DialOpts) (*dialResult, erro
 	if err != nil {
 		return nil, errors.Trace(err)
 	}
-	logger.Infof("connection established to %q", dialInfo.urlStr)
+	logger.Infof(context.TODO(), "connection established to %q", dialInfo.urlStr)
 	dialInfo.proxier = info.Proxier
 	return dialInfo, nil
 }
@@ -678,7 +678,7 @@ func (ap *addressProvider) next(ctx context.Context) (*resolvedAddress, error) {
 					return nil, errors.Errorf("cannot resolve %q: %v", host, err)
 				}
 				ap.dnsCache.Add(host, ips)
-				logger.Debugf("looked up %v -> %v", host, ips)
+				logger.Debugf(context.TODO(), "looked up %v -> %v", host, ips)
 			}
 
 			for _, ip := range ips {
@@ -783,15 +783,15 @@ func verifyCAMulti(ctx context.Context, addrs []string, opts *dialOpts) error {
 	// VerifyCA implementation was provided.
 	result, err := try.Result()
 	if err != nil || result == nil {
-		logger.Debugf("unable to retrieve CA cert from remote host; skipping CA verification")
+		logger.Debugf(context.TODO(), "unable to retrieve CA cert from remote host; skipping CA verification")
 		return nil
 	}
 
 	// Try to verify CA cert using the system roots. If the verification
 	// succeeds then we are done; tls connections will work out of the box.
 	res := result.(caRetrieveRes)
 	if _, err = res.caCert.Verify(x509.VerifyOptions{}); err == nil {
-		logger.Debugf("remote CA certificate trusted by system roots")
+		logger.Debugf(context.TODO(), "remote CA certificate trusted by system roots")
 		return nil
 	}
 
@@ -915,7 +915,7 @@ func lookupIPAddr(ctx context.Context, host string, resolver IPAddrResolver) ([]
 		if addr.Zone != "" {
 			// Ignore IPv6 zone. Hopefully this shouldn't
 			// cause any problems in practice.
-			logger.Infof("ignoring IP address with zone %q", addr)
+			logger.Infof(context.TODO(), "ignoring IP address with zone %q", addr)
 			continue
 		}
 		ips = append(ips, addr.IP.String())
@@ -927,7 +927,7 @@ func lookupIPAddr(ctx context.Context, host string, resolver IPAddrResolver) ([]
 // This is so that we can use the usual Try error combination
 // logic even for errors that happen before we start a try.
 func recordTryError(try *parallel.Try, err error) {
-	logger.Infof("%v", err)
+	logger.Infof(context.TODO(), "%v", err)
 	_ = try.Start(func(_ <-chan struct{}) (io.Closer, error) {
 		return nil, errors.Trace(err)
 	})
@@ -1009,7 +1009,7 @@ func (d dialer) dial(_ <-chan struct{}) (io.Closer, error) {
 		lastErr = err
 	}
 	if lastErr == nil {
-		logger.Debugf("no error, but not connected, probably cancelled before we started")
+		logger.Debugf(context.TODO(), "no error, but not connected, probably cancelled before we started")
 		return nil, parallel.ErrStopped
 	}
 	return nil, errors.Trace(lastErr)
@@ -1022,10 +1022,10 @@ func (d dialer) dial1() (jsoncodec.JSONConn, *tls.Config, error) {
 	if d.opts.certPool == nil {
 		tlsConfig.ServerName = d.serverName
 	}
-	logger.Tracef("dialing: %q %v", d.urlStr, d.ipAddr)
+	logger.Tracef(context.TODO(), "dialing: %q %v", d.urlStr, d.ipAddr)
 	conn, err := d.opts.DialWebsocket(d.ctx, d.urlStr, tlsConfig, d.ipAddr)
 	if err == nil {
-		logger.Debugf("successfully dialed %q", d.urlStr)
+		logger.Debugf(context.TODO(), "successfully dialed %q", d.urlStr)
 		return conn, tlsConfig, nil
 	}
 	if !isX509Error(err) {
@@ -1052,7 +1052,7 @@ func (d dialer) dial1() (jsoncodec.JSONConn, *tls.Config, error) {
 	tlsConfig.ServerName = d.serverName
 	conn, rootCAErr := d.opts.DialWebsocket(d.ctx, d.urlStr, tlsConfig, d.ipAddr)
 	if rootCAErr != nil {
-		logger.Debugf("failed to dial websocket using fallback public CA: %v", rootCAErr)
+		logger.Debugf(context.TODO(), "failed to dial websocket using fallback public CA: %v", rootCAErr)
 		// We return the original error as it's usually more meaningful.
 		return nil, nil, errors.Trace(err)
 	}
@@ -1160,12 +1160,12 @@ func (c *conn) IsBroken(ctx context.Context) bool {
 	case <-c.broken:
 		return true
 	case <-ctx.Done():
-		logger.Debugf("connection ping context expired")
+		logger.Debugf(context.TODO(), "connection ping context expired")
 		return true
 	default:
 	}
 	if err := c.ping(ctx); err != nil {
-		logger.Debugf("connection ping failed: %v", err)
+		logger.Debugf(context.TODO(), "connection ping failed: %v", err)
 		return true
 	}
 	return false