Switch log/slog

server/go.mod

@@ -1,6 +1,6 @@
 module github.com/whywaita/shoes-lxd-multi/server
 
-go 1.19
+go 1.21
 
 require (
 	github.com/docker/go-units v0.5.0

server/go.sum

@@ -58,8 +58,6 @@ github.com/creack/pty v1.1.9/go.mod h1:oKZEueFk5CKHvIhNR5MUki03XCEU+Q6VDXinZuGJ3
 github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c=
 github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
-github.com/docker/go-units v0.4.0 h1:3uh0PgVws3nIA0Q+MwDC8yjEPf9zjRfZZWXZYDct3Tw=
-github.com/docker/go-units v0.4.0/go.mod h1:fgPhTUdO+D/Jk86RDLlptpiXQzgHJF7gydDDbaIK4Dk=
 github.com/docker/go-units v0.5.0 h1:69rxXcBk27SvSaaxTtLh/8llcHD8vYHT7WSdRZ/jvr4=
 github.com/docker/go-units v0.5.0/go.mod h1:fgPhTUdO+D/Jk86RDLlptpiXQzgHJF7gydDDbaIK4Dk=
 github.com/envoyproxy/go-control-plane v0.9.0/go.mod h1:YTl/9mNaCwkRvm6d1a2C3ymFceY/DCBVvsKhRF0iEA4=
@@ -136,6 +134,7 @@ github.com/google/go-cmp v0.5.4/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/
 github.com/google/go-cmp v0.5.5/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE=
 github.com/google/go-cmp v0.5.6/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE=
 github.com/google/go-cmp v0.5.9 h1:O2Tfq5qg4qc4AmwVlvv0oLiVAGB7enBSJ2x2DqQFi38=
+github.com/google/go-cmp v0.5.9/go.mod h1:17dUlkBOakJ0+DkrSSNjCkIjxS6bF9zb3elmeNGIjoY=
 github.com/google/go-github/v41 v41.0.0 h1:HseJrM2JFf2vfiZJ8anY2hqBjdfY1Vlj/K27ueww4gg=
 github.com/google/go-github/v41 v41.0.0/go.mod h1:XgmCA5H323A9rtgExdTcnDkcqp6S30AVACCBDOonIxg=
 github.com/google/go-github/v47 v47.1.0 h1:Cacm/WxQBOa9lF0FT0EMjZ2BWMetQ1TQfyurn4yF1z8=
@@ -283,6 +282,7 @@ github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXf
 github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI=
 github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4=
 github.com/stretchr/testify v1.7.0 h1:nwc3DEeHmmLAfoZucVR881uASk0Mfjw8xYJ99tb5CcY=
+github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
 github.com/whywaita/myshoes v1.14.0 h1:wIJoInogzSErsdVEwiKjWJuqXzg0mKpxxf5YKeaT334=
 github.com/whywaita/myshoes v1.14.0/go.mod h1:Fea/XeUlwjWSZdqfG/Ub3+U278kGilIG9o9f6DxRpq8=
 github.com/whywaita/shoes-lxd-multi/proto.go v0.0.0-20230331051154-d763b94b0dd7 h1:MdNKtHc/T+46wn7JfEi5P72Q/GHVPHLInqLldZB4eWE=
@@ -607,6 +607,7 @@ gopkg.in/yaml.v2 v2.3.0/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=
 gopkg.in/yaml.v2 v2.4.0 h1:D8xgwECY7CYvx+Y2n4sBz93Jn9JRvxdiyyo8CTfuKaY=
 gopkg.in/yaml.v2 v2.4.0/go.mod h1:RDklbk79AGWmwhnvt/jBztapEOGDOx6ZbXqjP6csGnQ=
 gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b h1:h8qDotaEPuJATrMmW04NCwg7v22aHH28wwpauUhK9Oo=
+gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=
 honnef.co/go/tools v0.0.0-20190102054323-c2f93a96b099/go.mod h1:rf3lG4BRIbNafJWhAfAdb/ePZxsR/4RtNHQocxwk9r4=
 honnef.co/go/tools v0.0.0-20190106161140-3f1c8253044a/go.mod h1:rf3lG4BRIbNafJWhAfAdb/ePZxsR/4RtNHQocxwk9r4=
 honnef.co/go/tools v0.0.0-20190418001031-e561f6794a2a/go.mod h1:rf3lG4BRIbNafJWhAfAdb/ePZxsR/4RtNHQocxwk9r4=

server/main.go

@@ -4,9 +4,10 @@ import (
 	"context"
 	"fmt"
 	"log"
-	"math/rand"
+	"log/slog"
 	"net/http"
 	_ "net/http/pprof"
+	"os"
 	"time"
 
 	"github.com/prometheus/client_golang/prometheus"
@@ -19,7 +20,7 @@ import (
 )
 
 func main() {
-	rand.Seed(time.Now().UnixNano())
+	slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stderr, nil)))
 
 	if err := run(); err != nil {
 		log.Fatal(err)
@@ -83,9 +84,7 @@ func serveMetrics(ctx context.Context, hostConfigs *config.HostConfigMap) {
 
 func setLXDResourceCacheWithTicker(hcs []config.HostConfig, ticker *time.Ticker) {
 	for {
-		_ = <-ticker.C
-
-		log.Print("LXD cache is updating")
+		<-ticker.C
 		if err := setLXDResourceCache(hcs); err != nil {
 			log.Fatal(err)
 		}

server/pkg/api/server.go

@@ -3,6 +3,7 @@ package api
 import (
 	"fmt"
 	"log"
+	"log/slog"
 	"net"
 	"sync"
 
@@ -52,13 +53,14 @@ func (s *ShoesLXDMultiServer) Run(listenPort int) error {
 	return nil
 }
 
-func (s *ShoesLXDMultiServer) validateTargetHosts(targetHosts []string) ([]lxdclient.LXDHost, error) {
+func (s *ShoesLXDMultiServer) validateTargetHosts(targetHosts []string, logger *slog.Logger) ([]lxdclient.LXDHost, error) {
 	var hostConfigs []config.HostConfig
 
 	for _, target := range targetHosts {
+		l := logger.With("target", target)
 		host, err := s.hostConfigs.Load(target)
 		if err != nil {
-			log.Printf("ignore host in target (target: %s): %+v\n", target, err)
+			l.Warn("ignore host in target", "err", err.Error())
 			continue
 		}
 

server/pkg/api/server_add_instance.go

@@ -5,6 +5,7 @@ import (
 	"errors"
 	"fmt"
 	"log"
+	"log/slog"
 	"math/rand"
 	"net/url"
 	"strconv"
@@ -30,36 +31,38 @@ import (
 
 // AddInstance add instance to LXD server
 func (s *ShoesLXDMultiServer) AddInstance(ctx context.Context, req *pb.AddInstanceRequest) (*pb.AddInstanceResponse, error) {
-	log.Printf("AddInstance req: %+v\n", req)
+	slog.Info("AddInstance", "req", req)
+	l := slog.With("method", "AddInstance")
 	if _, err := runner.ToUUID(req.RunnerName); err != nil {
 		return nil, status.Errorf(codes.InvalidArgument, "failed to parse request name: %+v", err)
 	}
 	instanceName := req.RunnerName
+	l = l.With("runnerName", instanceName)
 
 	instanceSource, err := parseAlias(req.ImageAlias)
 	if err != nil {
 		return nil, status.Errorf(codes.InvalidArgument, "failed to parse image alias: %+v", err)
 	}
 
-	targetLXDHosts, err := s.validateTargetHosts(req.TargetHosts)
+	targetLXDHosts, err := s.validateTargetHosts(req.TargetHosts, l)
 	if err != nil {
 		return nil, status.Errorf(codes.InvalidArgument, "failed to validate target hosts: %+v", err)
 	}
 
-	host, err := s.isExistInstance(targetLXDHosts, instanceName)
+	host, err := s.isExistInstance(targetLXDHosts, instanceName, l)
 	if err != nil && !errors.Is(err, ErrInstanceIsNotFound) {
 		return nil, status.Errorf(codes.Internal, "failed to get instance: %+v", err)
 	}
 
 	var client lxd.InstanceServer
-	var reqInstance api.InstancesPost
+	var reqInstance *api.InstancesPost
 	if errors.Is(err, ErrInstanceIsNotFound) {
 		host, reqInstance, err = s.setLXDStatusCache(targetLXDHosts, instanceName, instanceSource, req)
 		if err != nil {
-			return nil, err
+			return nil, status.Errorf(codes.Internal, "failed to set LXD status cache: %+v", err)
 		}
 		client = host.Client
-		op, err := client.CreateInstance(reqInstance)
+		op, err := client.CreateInstance(*reqInstance)
 		if err != nil {
 			return nil, status.Errorf(codes.Internal, "failed to create instance: %+v", err)
 		}
@@ -96,17 +99,23 @@ func (s *ShoesLXDMultiServer) AddInstance(ctx context.Context, req *pb.AddInstan
 	}, nil
 }
 
-func (s *ShoesLXDMultiServer) setLXDStatusCache(targetLXDHosts []lxdclient.LXDHost, instanceName string, instanceSource *api.InstanceSource, req *pb.AddInstanceRequest) (*lxdclient.LXDHost, api.InstancesPost, error) {
+func (s *ShoesLXDMultiServer) setLXDStatusCache(
+	targetLXDHosts []lxdclient.LXDHost,
+	instanceName string,
+	instanceSource *api.InstanceSource,
+	req *pb.AddInstanceRequest,
+) (*lxdclient.LXDHost, *api.InstancesPost, error) {
 	s.mu.Lock()
 	defer s.mu.Unlock()
 
 	host, err := s.scheduleHost(targetLXDHosts)
 	if err != nil {
-		return nil, api.InstancesPost{}, status.Errorf(codes.InvalidArgument, "failed to schedule host: %+v", err)
+		return nil, nil, status.Errorf(codes.InvalidArgument, "failed to schedule host: %+v", err)
 	}
-	log.Printf("AddInstance scheduled host: %s, runnerName: %s\n", host.HostConfig.LxdHost, instanceName)
+	l := slog.With("host", host.HostConfig.LxdHost)
+	l.Info("AddInstance scheduled host", "runnerName", instanceName)
 
-	reqInstance := api.InstancesPost{
+	reqInstance := &api.InstancesPost{
 		InstancePut: api.InstancePut{
 			Config:  s.getInstanceConfig(req.SetupScript, req.ResourceType),
 			Devices: s.getInstanceDevices(),
@@ -117,22 +126,22 @@ func (s *ShoesLXDMultiServer) setLXDStatusCache(targetLXDHosts []lxdclient.LXDHo
 
 	cpu, err := strconv.ParseUint(reqInstance.InstancePut.Config["limits.cpu"], 10, 64)
 	if err != nil {
-		return nil, api.InstancesPost{}, fmt.Errorf("failde to parse limits.cpu: %w", err)
+		return nil, nil, fmt.Errorf("failde to parse limits.cpu: %w", err)
 	}
 
 	memory, err := units.FromHumanSize(reqInstance.InstancePut.Config["limits.memory"])
 	if err != nil {
-		return nil, api.InstancesPost{}, fmt.Errorf("failde to parse limits.memory: %w", err)
+		return nil, nil, fmt.Errorf("failde to parse limits.memory: %w", err)
 	}
 
 	cache, err := lxdclient.GetStatusCache(host.HostConfig.LxdHost)
 	if err != nil {
-		return nil, api.InstancesPost{}, err
+		return nil, nil, err
 	}
 	cache.Resource.CPUUsed += cpu
 	cache.Resource.MemoryUsed += uint64(memory)
 	if err := lxdclient.SetStatusCache(host.HostConfig.LxdHost, cache); err != nil {
-		return nil, api.InstancesPost{}, fmt.Errorf("failed to set status cache: %s", err)
+		return nil, nil, fmt.Errorf("failed to set status cache: %s", err)
 	}
 	return host, reqInstance, nil
 }
@@ -198,9 +207,10 @@ func getResources(targetLXDHosts []lxdclient.LXDHost) ([]targetHost, error) {
 	for _, t := range targetLXDHosts {
 		t := t
 		eg.Go(func() error {
+			l := slog.With("host", t.HostConfig.LxdHost)
 			resources, err := lxdclient.GetResource(t.HostConfig)
 			if err != nil {
-				log.Printf("failed to get resource (host: %s): %+v\n", t.HostConfig.LxdHost, err)
+				l.Warn("failed to get resource", "err", err.Error())
 				return nil
 			}
 
@@ -231,10 +241,11 @@ var (
 func schedule(targets []targetHost, limitOverCommit uint64) (*targetHost, error) {
 	var schedulableTargets []targetHost
 	for _, target := range targets {
+		l := slog.With("host", target.host.HostConfig.LxdHost)
 		if target.percentOverCommit < limitOverCommit {
 			schedulableTargets = append(schedulableTargets, target)
 		} else {
-			log.Printf("%s is percentage of over-commit is high. ignore (now: %d, limit: %d)", target.host.HostConfig.LxdHost, target.percentOverCommit, limitOverCommit)
+			l.Info("is percentage of over-commit is high. ignore", "now", target.percentOverCommit, "limit", limitOverCommit)
 		}
 	}
 	if len(schedulableTargets) == 0 {

server/pkg/api/server_delete_instance.go

@@ -3,7 +3,7 @@ package api
 import (
 	"context"
 	"errors"
-	"log"
+	"log/slog"
 	"strings"
 
 	"github.com/lxc/lxd/shared/api"
@@ -15,17 +15,19 @@ import (
 
 // DeleteInstance delete instance to LXD server
 func (s *ShoesLXDMultiServer) DeleteInstance(ctx context.Context, req *pb.DeleteInstanceRequest) (*pb.DeleteInstanceResponse, error) {
-	log.Printf("DeleteInstance req: %+v\n", req)
+	slog.Info("DeleteInstance", "req", req)
+	l := slog.With("method", "DeleteInstance")
 	if _, err := runner.ToUUID(req.CloudId); err != nil {
 		return nil, status.Errorf(codes.InvalidArgument, "failed to parse request id: %+v", err)
 	}
 	instanceName := req.CloudId
-	targetLXDHosts, err := s.validateTargetHosts(req.TargetHosts)
+	l = l.With("instanceName", instanceName)
+	targetLXDHosts, err := s.validateTargetHosts(req.TargetHosts, l)
 	if err != nil {
 		return nil, status.Errorf(codes.InvalidArgument, "failed to validate target hosts: %+v", err)
 	}
 
-	host, err := s.isExistInstance(targetLXDHosts, instanceName)
+	host, err := s.isExistInstance(targetLXDHosts, instanceName, l)
 	if err != nil {
 		switch {
 		case errors.Is(err, ErrInstanceIsNotFound):
@@ -35,6 +37,7 @@ func (s *ShoesLXDMultiServer) DeleteInstance(ctx context.Context, req *pb.Delete
 		}
 	}
 
+	l.Info("will stop instance")
 	client := host.Client
 	reqState := api.InstanceStatePut{
 		Action:  "stop",
@@ -48,6 +51,7 @@ func (s *ShoesLXDMultiServer) DeleteInstance(ctx context.Context, req *pb.Delete
 		return nil, status.Errorf(codes.Internal, "failed to wait stopping instance: %+v", err)
 	}
 
+	l.Info("will delete instance")
 	op, err = client.DeleteInstance(instanceName)
 	if err != nil {
 		return nil, status.Errorf(codes.Internal, "failed to delete instance: %+v", err)

server/pkg/api/server_host.go

@@ -3,7 +3,7 @@ package api
 import (
 	"errors"
 	"fmt"
-	"log"
+	"log/slog"
 	"time"
 
 	"golang.org/x/sync/errgroup"
@@ -17,20 +17,21 @@ var (
 )
 
 // isExistInstance search created instance in same name
-func (s *ShoesLXDMultiServer) isExistInstance(targetLXDHosts []lxdclient.LXDHost, instanceName string) (*lxdclient.LXDHost, error) {
+func (s *ShoesLXDMultiServer) isExistInstance(targetLXDHosts []lxdclient.LXDHost, instanceName string, logger *slog.Logger) (*lxdclient.LXDHost, error) {
 	eg := errgroup.Group{}
 	var foundHost *lxdclient.LXDHost
 	foundHost = nil
 
 	for _, host := range targetLXDHosts {
 		host := host
 		eg.Go(func() error {
+			l := logger.With("host", host.HostConfig.LxdHost)
 			err := isExistInstanceWithTimeout(host, instanceName)
 			if err != nil && !errors.Is(err, ErrTimeoutGetInstance) {
-				log.Printf("failed to get instance with timeout (host: %s): %+v\n", host.HostConfig.LxdHost, err)
+				l.Warn("failed to get instance (not ErrTimeoutGetInstance)", "err", err.Error())
 				return nil
 			} else if errors.Is(err, ErrTimeoutGetInstance) {
-				log.Printf("failed to get instance (reach timeout), So ignore host (host: %s)\n", host.HostConfig.LxdHost)
+				l.Warn("failed to get instance (reach timeout), So ignore host", "err", err.Error())
 				return nil
 			}
 

server/pkg/config/config.go

@@ -3,6 +3,7 @@ package config
 import (
 	"encoding/json"
 	"fmt"
+	"log"
 	"os"
 	"strconv"
 
@@ -57,6 +58,7 @@ func Load() (*HostConfigMap, map[myshoespb.ResourceType]Mapping, int64, int, uin
 			return nil, nil, 0, -1, 0, fmt.Errorf("failed to parse %s, need to uint: %w", EnvOverCommit, err)
 		}
 	}
+	log.Printf("periodSec: %d\n", periodSec)
 
 	envPort := os.Getenv(EnvPort)
 	var port int
@@ -79,6 +81,7 @@ func Load() (*HostConfigMap, map[myshoespb.ResourceType]Mapping, int64, int, uin
 			return nil, nil, 0, -1, 0, fmt.Errorf("failed to parse %s, need to uint: %w", EnvOverCommit, err)
 		}
 	}
+	log.Printf("overCommitPercent: %d\n", overCommitPercent)
 
 	return hostConfigs, m, periodSec, port, overCommitPercent, nil
 }

server/pkg/lxdclient/connect.go

@@ -3,7 +3,7 @@ package lxdclient
 import (
 	"errors"
 	"fmt"
-	"log"
+	"log/slog"
 	"sync"
 	"time"
 
@@ -28,13 +28,14 @@ func ConnectLXDs(hostConfigs []config.HostConfig) ([]LXDHost, error) {
 
 	for _, hc := range hostConfigs {
 		hc := hc
+		l := slog.With("host", hc.LxdHost)
 		eg.Go(func() error {
 			conn, err := ConnectLXDWithTimeout(hc.LxdHost, hc.LxdClientCert, hc.LxdClientKey)
 			if err != nil && !errors.Is(err, ErrTimeoutConnectLXD) {
-				log.Printf("failed to connect LXD with timeout (host: %s): %+v\n", err, hc.LxdHost)
+				l.Warn("failed to connect LXD with timeout (not ErrTimeoutConnectLXD)", "err", err.Error())
 				return nil
 			} else if errors.Is(err, ErrTimeoutConnectLXD) {
-				log.Printf("failed to connect LXD, So ignore host (host: %s)\n", hc.LxdHost)
+				l.Warn("failed to connect LXD, So ignore host")
 				return nil
 			}
 

server/pkg/lxdclient/resource.go

@@ -37,6 +37,8 @@ func GetResource(hostConfig config.HostConfig) (*Resource, error) {
 		return nil, fmt.Errorf("failed to get status from cache: %w", err)
 	}
 
+	log.Printf("failed to get status from cache, so scrape from lxd")
+
 	client, err := ConnectLXDWithTimeout(hostConfig.LxdHost, hostConfig.LxdClientCert, hostConfig.LxdClientKey)
 	if err != nil {
 		return nil, fmt.Errorf("failed to connect lxd: %w", err)

server/pkg/metric/collector.go

@@ -3,7 +3,7 @@ package metric
 import (
 	"context"
 	"fmt"
-	"log"
+	"log/slog"
 	"sync"
 	"time"
 
@@ -48,7 +48,7 @@ func (c *Collector) Describe(ch chan<- *prometheus.Desc) {
 	c.metrics.ScrapeErrors.Describe(ch)
 }
 
-// Collect collect metrics
+// Collect metrics
 func (c *Collector) Collect(ch chan<- prometheus.Metric) {
 	c.scrape(c.ctx, ch)
 
@@ -69,7 +69,7 @@ func (c *Collector) scrape(ctx context.Context, ch chan<- prometheus.Metric) {
 			label := fmt.Sprintf("collect.%s", scraper.Name())
 			scrapeStartTime := time.Now()
 			if err := scraper.Scrape(ctx, c.hostConfigs, ch); err != nil {
-				log.Printf("failed to scrape metrics (name: %s): %+v\n", scraper.Name(), err)
+				slog.Warn("failed to scrape metrics", "name", scraper.Name(), "err", err.Error())
 				c.metrics.ScrapeErrors.WithLabelValues(label).Inc()
 				c.metrics.Error.Set(1)
 			}