From 904e5e0bed6ba87e0f4063c27a0678a9c85b7371 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Julian=20T=C3=B6lle?= Date: Tue, 30 Apr 2024 23:48:59 +0200 Subject: [PATCH] feat: log output --- go.mod | 8 +++- go.sum | 14 ++++++ snapshot.go | 86 ++++++++++++++++++++++++++--------- util/contextlogger/context.go | 24 ++++++++++ util/contextlogger/discard.go | 15 ++++++ util/control/retry.go | 5 ++ util/randomid/randomid.go | 2 + util/sshkey/ssh_key.go | 2 + 8 files changed, 133 insertions(+), 23 deletions(-) create mode 100644 util/contextlogger/context.go create mode 100644 util/contextlogger/discard.go diff --git a/go.mod b/go.mod index d74cc19..f666efd 100644 --- a/go.mod +++ b/go.mod @@ -3,7 +3,7 @@ module github.com/apricote/hcloud-upload-image go 1.22.2 require ( - github.com/hetznercloud/hcloud-go/v2 v2.7.1-0.20240418173523-ca1e95747811 + github.com/hetznercloud/hcloud-go/v2 v2.7.3-0.20240430130644-7bb1a7b9ae5f github.com/stretchr/testify v1.9.0 golang.org/x/crypto v0.22.0 ) @@ -11,17 +11,23 @@ require ( require ( github.com/beorn7/perks v1.0.1 // indirect github.com/cespare/xxhash/v2 v2.2.0 // indirect + github.com/dave/jennifer v1.6.0 // indirect github.com/davecgh/go-spew v1.1.1 // indirect + github.com/jessevdk/go-flags v1.4.1-0.20181029123624-5de817a9aa20 // indirect + github.com/jmattheis/goverter v1.4.0 // indirect github.com/pmezard/go-difflib v1.0.0 // indirect github.com/prometheus/client_golang v1.19.0 // indirect github.com/prometheus/client_model v0.5.0 // indirect github.com/prometheus/common v0.48.0 // indirect github.com/prometheus/procfs v0.12.0 // indirect github.com/samber/lo v1.39.0 // indirect + github.com/vburenin/ifacemaker v1.2.1 // indirect golang.org/x/exp v0.0.0-20220303212507-bbda1eaf7a17 // indirect + golang.org/x/mod v0.14.0 // indirect golang.org/x/net v0.24.0 // indirect golang.org/x/sys v0.19.0 // indirect golang.org/x/text v0.14.0 // indirect + golang.org/x/tools v0.17.0 // indirect google.golang.org/protobuf v1.32.0 // indirect gopkg.in/yaml.v3 v3.0.1 // indirect ) diff --git a/go.sum b/go.sum index f5aec51..dbf0781 100644 --- a/go.sum +++ b/go.sum @@ -2,12 +2,20 @@ github.com/beorn7/perks v1.0.1 h1:VlbKKnNfV8bJzeqoa4cOKqO6bYr3WgKZxO8Z16+hsOM= github.com/beorn7/perks v1.0.1/go.mod h1:G2ZrVWU2WbWT9wwq4/hrbKbnv/1ERSJQ0ibhJ6rlkpw= github.com/cespare/xxhash/v2 v2.2.0 h1:DC2CZ1Ep5Y4k3ZQ899DldepgrayRUGE6BBZ/cd9Cj44= github.com/cespare/xxhash/v2 v2.2.0/go.mod h1:VGX0DQ3Q6kWi7AoAeZDth3/j3BFtOZR5XLFGgcrjCOs= +github.com/dave/jennifer v1.6.0 h1:MQ/6emI2xM7wt0tJzJzyUik2Q3Tcn2eE0vtYgh4GPVI= +github.com/dave/jennifer v1.6.0/go.mod h1:AxTG893FiZKqxy3FP1kL80VMshSMuz2G+EgvszgGRnk= 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/google/go-cmp v0.6.0 h1:ofyhxvXcZhMsU5ulbFiLKl/XBFqE1GSq7atu8tAmTRI= github.com/google/go-cmp v0.6.0/go.mod h1:17dUlkBOakJ0+DkrSSNjCkIjxS6bF9zb3elmeNGIjoY= github.com/hetznercloud/hcloud-go/v2 v2.7.1-0.20240418173523-ca1e95747811 h1:rmDCSIDubTNJDJNYzHVqcVNYp3RzPuA3gy6/qtkZAEo= github.com/hetznercloud/hcloud-go/v2 v2.7.1-0.20240418173523-ca1e95747811/go.mod h1:58Ka180ZDH5wifuxRaoRsZXVlo4lK7R+vxTnAqWuoOs= +github.com/hetznercloud/hcloud-go/v2 v2.7.3-0.20240430130644-7bb1a7b9ae5f h1:c1ahn6OKXkSqwOfCoqyFrjVh14BEC9rD3ok0dehbCno= +github.com/hetznercloud/hcloud-go/v2 v2.7.3-0.20240430130644-7bb1a7b9ae5f/go.mod h1:jvpP3qAWMIZ3WQwQLYa97ia6t98iPCgsJNwRts+Jnrk= +github.com/jessevdk/go-flags v1.4.1-0.20181029123624-5de817a9aa20 h1:dAOsPLhnBzIyxu0VvmnKjlNcIlgMK+erD6VRHDtweMI= +github.com/jessevdk/go-flags v1.4.1-0.20181029123624-5de817a9aa20/go.mod h1:4FA24M0QyGHXBuZZK/XkWh8h0e1EYbRYJSGM75WSRxI= +github.com/jmattheis/goverter v1.4.0 h1:SrboBYMpGkj1XSgFhWwqzdP024zIa1+58YzUm+0jcBE= +github.com/jmattheis/goverter v1.4.0/go.mod h1:iVIl/4qItWjWj2g3vjouGoYensJbRqDHpzlEVMHHFeY= github.com/kr/pretty v0.3.1 h1:flRD4NNwYAUpkphVc1HcthR4KEIFJ65n8Mw5qdRn3LE= github.com/kr/pretty v0.3.1/go.mod h1:hoEshYVHaxMs3cyo3Yncou5ZscifuDolrwPKZanG3xk= github.com/kr/text v0.2.0 h1:5Nx0Ya0ZqY2ygV366QzturHI13Jq95ApcVaJBhpS+AY= @@ -28,10 +36,14 @@ github.com/samber/lo v1.39.0 h1:4gTz1wUhNYLhFSKl6O+8peW0v2F4BCY034GRpU9WnuA= github.com/samber/lo v1.39.0/go.mod h1:+m/ZKRl6ClXCE2Lgf3MsQlWfh4bn1bz6CXEOxnEXnEA= github.com/stretchr/testify v1.9.0 h1:HtqpIVDClZ4nwg75+f6Lvsy/wHu+3BoSGCbBAcpTsTg= github.com/stretchr/testify v1.9.0/go.mod h1:r2ic/lqez/lEtzL7wO/rwa5dbSLXVDPFyf8C91i36aY= +github.com/vburenin/ifacemaker v1.2.1 h1:3Vq8B/bfBgjWTkv+jDg4dVL1KHt3k1K4lO7XRxYA2sk= +github.com/vburenin/ifacemaker v1.2.1/go.mod h1:5WqrzX2aD7/hi+okBjcaEQJMg4lDGrpuEX3B8L4Wgrs= golang.org/x/crypto v0.22.0 h1:g1v0xeRhjcugydODzvb3mEM9SQ0HGp9s/nh3COQ/C30= golang.org/x/crypto v0.22.0/go.mod h1:vr6Su+7cTlO45qkww3VDJlzDn0ctJvRgYbC2NvXHt+M= golang.org/x/exp v0.0.0-20220303212507-bbda1eaf7a17 h1:3MTrJm4PyNL9NBqvYDSj3DHl46qQakyfqfWo4jgfaEM= golang.org/x/exp v0.0.0-20220303212507-bbda1eaf7a17/go.mod h1:lgLbSvA5ygNOMpwM/9anMpWVlVJ7Z+cHWq/eFuinpGE= +golang.org/x/mod v0.14.0 h1:dGoOF9QVLYng8IHTm7BAyWqCqSheQ5pYWGhzW00YJr0= +golang.org/x/mod v0.14.0/go.mod h1:hTbmBsO62+eylJbnUtE2MGJUyE7QWk4xUqPFrRgJ+7c= golang.org/x/net v0.24.0 h1:1PcaxkF854Fu3+lvBIx5SYn9wRlBzzcnHZSiaFFAb0w= golang.org/x/net v0.24.0/go.mod h1:2Q7sJY5mzlzWjKtYUEXSlBWCdyaioyXzRB2RtU8KVE8= golang.org/x/sys v0.19.0 h1:q5f1RH2jigJ1MoAWp2KTp3gm5zAGFUTarQZ5U386+4o= @@ -40,6 +52,8 @@ golang.org/x/term v0.19.0 h1:+ThwsDv+tYfnJFhF4L8jITxu1tdTWRTZpdsWgEgjL6Q= golang.org/x/term v0.19.0/go.mod h1:2CuTdWZ7KHSQwUzKva0cbMg6q2DMI3Mmxp+gKJbskEk= golang.org/x/text v0.14.0 h1:ScX5w1eTa3QqT8oi6+ziP7dTV1S2+ALU0bI+0zXKWiQ= golang.org/x/text v0.14.0/go.mod h1:18ZOQIKpY8NJVqYksKHtTdi31H5itFRjB5/qKTNYzSU= +golang.org/x/tools v0.17.0 h1:FvmRgNOcs3kOa+T20R1uhfP9F6HgG2mfxDv1vrx1Htc= +golang.org/x/tools v0.17.0/go.mod h1:xsh6VxdV005rRVaS6SSAf9oiAqljS7UZUacMZ8Bnsps= google.golang.org/protobuf v1.32.0 h1:pPC6BG5ex8PDFnkbrGU3EixyhKcQ2aDuBS36lqK/C7I= google.golang.org/protobuf v1.32.0/go.mod h1:c6P6GXX6sHbq/GpV6MGZEdwhWPcYBgnhAHhKbcUYpos= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= diff --git a/snapshot.go b/snapshot.go index fc17de8..29464ee 100644 --- a/snapshot.go +++ b/snapshot.go @@ -3,12 +3,12 @@ package hcloud_upload_image import ( "context" "fmt" - "log" "time" "github.com/hetznercloud/hcloud-go/v2/hcloud" "golang.org/x/crypto/ssh" + "github.com/apricote/hcloud-upload-image/util/contextlogger" "github.com/apricote/hcloud-upload-image/util/control" "github.com/apricote/hcloud-upload-image/util/randomid" "github.com/apricote/hcloud-upload-image/util/sshkey" @@ -50,15 +50,21 @@ type snapshotClient struct { } func (s snapshotClient) Upload(ctx context.Context, options UploadOptions) (*hcloud.Image, error) { + logger := contextlogger.From(ctx).With( + "library", "hcloud-upload-image", + "method", "upload", + ) + id, err := randomid.Generate() if err != nil { return nil, err } + logger = logger.With("run-id", id) // For simplicity, we use the name random name for SSH Key + Server resourceName := resourcePrefix + id // 1. Create SSH Key - log.Print("Step 1: Generating SSH Key") + logger.InfoContext(ctx, "# Step 1: Generating SSH Key") publicKey, privateKey, err := sshkey.GenerateKeyPair() if err != nil { return nil, fmt.Errorf("failed to generate temporary ssh key pair: %w", err) @@ -72,25 +78,35 @@ func (s snapshotClient) Upload(ctx context.Context, options UploadOptions) (*hcl if err != nil { return nil, fmt.Errorf("failed to submit temporary ssh key to API: %w", err) } + logger.DebugContext(ctx, "Uploaded ssh key", "ssh-key-id", key.ID) defer func() { // Cleanup SSH Key if options.DebugSkipResourceCleanup { + logger.InfoContext(ctx, "Cleanup: Skipping cleanup of temporary ssh key") return } + logger.InfoContext(ctx, "Cleanup: Deleting temporary ssh key") + _, err := s.client.SSHKey.Delete(ctx, key) if err != nil { + logger.WarnContext(ctx, "Cleanup: ssh key could not be deleted", "error", err) // TODO } }() // 2. Create Server - log.Print("Step 2: Creating Server") + logger.InfoContext(ctx, "# Step 2: Creating Server") serverType, ok := serverTypePerArchitecture[options.Architecture] if !ok { return nil, fmt.Errorf("unknown architecture %q, valid options: %q, %q", options.Architecture, hcloud.ArchitectureX86, hcloud.ArchitectureARM) } + logger.DebugContext(ctx, "creating server with config", + "image", defaultImage.Name, + "location", defaultLocation.Name, + "serverType", serverType.Name, + ) serverCreateResult, _, err := s.client.Server.Create(ctx, hcloud.ServerCreateOpts{ Name: resourceName, ServerType: serverType, @@ -108,27 +124,34 @@ func (s snapshotClient) Upload(ctx context.Context, options UploadOptions) (*hcl if err != nil { return nil, fmt.Errorf("creating the temporary server failed: %w", err) } + logger = logger.With("server", serverCreateResult.Server.ID) + logger.DebugContext(ctx, "Created Server") - _, err = s.client.Action.WaitForActions(ctx, append(serverCreateResult.NextActions, serverCreateResult.Action)...) + logger.DebugContext(ctx, "waiting on actions") + err = s.client.Action.WaitFor(ctx, append(serverCreateResult.NextActions, serverCreateResult.Action)...) if err != nil { return nil, fmt.Errorf("creating the temporary server failed: %w", err) } + logger.DebugContext(ctx, "actions finished") server := serverCreateResult.Server defer func() { // Cleanup Server if options.DebugSkipResourceCleanup { + logger.InfoContext(ctx, "Cleanup: Skipping cleanup of temporary server") return } + logger.InfoContext(ctx, "Cleanup: Deleting temporary server") + _, _, err := s.client.Server.DeleteWithResult(ctx, server) if err != nil { - // TODO + logger.WarnContext(ctx, "Cleanup: server could not be deleted", "error", err) } }() // 3. Activate Rescue System - log.Print("Step 3: Activating Rescue System") + logger.InfoContext(ctx, "# Step 4: Activating Rescue System") enableRescueResult, _, err := s.client.Server.EnableRescue(ctx, server, hcloud.ServerEnableRescueOpts{ Type: defaultRescueType, SSHKeys: []*hcloud.SSHKey{key}, @@ -137,25 +160,31 @@ func (s snapshotClient) Upload(ctx context.Context, options UploadOptions) (*hcl return nil, fmt.Errorf("enabling the rescue system on the temporary server failed: %w", err) } - _, err = s.client.Action.WaitForAction(ctx, enableRescueResult.Action) + logger.DebugContext(ctx, "rescue system requested, waiting on action") + + err = s.client.Action.WaitFor(ctx, enableRescueResult.Action) if err != nil { return nil, fmt.Errorf("enabling the rescue system on the temporary server failed: %w", err) } + logger.DebugContext(ctx, "action finished, rescue system enabled") // 4. Boot Server - log.Print("Step 4: Booting Server") + logger.InfoContext(ctx, "# Step 4: Booting Server") powerOnAction, _, err := s.client.Server.Poweron(ctx, server) if err != nil { return nil, fmt.Errorf("starting the temporary server failed: %w", err) } - _, err = s.client.Action.WaitForAction(ctx, powerOnAction) + logger.DebugContext(ctx, "boot requested, waiting on action") + + err = s.client.Action.WaitFor(ctx, powerOnAction) if err != nil { return nil, fmt.Errorf("starting the temporary server failed: %w", err) } + logger.DebugContext(ctx, "action finished, server is booting") // 5. Open SSH Session - log.Print("Step 5: Opening SSH Connection") + logger.InfoContext(ctx, "# Step 5: Opening SSH Connection") signer, err := ssh.ParsePrivateKey(privateKey) if err != nil { return nil, fmt.Errorf("parsing the automatically generated temporary private key failed: %w", err) @@ -174,18 +203,23 @@ func (s snapshotClient) Upload(ctx context.Context, options UploadOptions) (*hcl // the server needs some time until its properly started and ssh is available var sshClient *ssh.Client - err = control.Retry(ctx, 10, func() error { - var err error - sshClient, err = ssh.Dial("tcp", server.PublicNet.IPv4.IP.String()+":ssh", sshClientConfig) - return err - }) + err = control.Retry( + contextlogger.New(ctx, logger.With("operation", "ssh")), + 10, + func() error { + var err error + logger.DebugContext(ctx, "trying to connect to server", "ip", server.PublicNet.IPv4.IP) + sshClient, err = ssh.Dial("tcp", server.PublicNet.IPv4.IP.String()+":ssh", sshClientConfig) + return err + }, + ) if err != nil { return nil, fmt.Errorf("failed to ssh into temporary server: %w", err) } defer sshClient.Close() // 6. SSH On Server: Download Image, Decompress, Write to Root Disk - log.Print("Step 6: Downloading image and writing to disk") + logger.InfoContext(ctx, "# Step 6: Downloading image and writing to disk") decompressionCommand := "" if options.ImageCompression != CompressionNone { switch options.ImageCompression { @@ -196,22 +230,26 @@ func (s snapshotClient) Upload(ctx context.Context, options UploadOptions) (*hcl } } - output, err := sshsession.Run(sshClient, fmt.Sprintf("wget --no-verbose -O - %q %s | dd of=/dev/sda && sync", options.ImageURL.String(), decompressionCommand)) - log.Print(string(output)) + fullCmd := fmt.Sprintf("wget --no-verbose -O - %q %s | dd of=/dev/sda bs=4M && sync", options.ImageURL.String(), decompressionCommand) + logger.DebugContext(ctx, "running download, decompress and write to disk command", "cmd", fullCmd) + + output, err := sshsession.Run(sshClient, fullCmd) + logger.InfoContext(ctx, "# Step 6: Finished writing image to disk") + logger.DebugContext(ctx, string(output)) if err != nil { return nil, fmt.Errorf("failed to download and write the image: %w", err) } // 7. SSH On Server: Shutdown - log.Print("Step 7: Shutting down server") + logger.InfoContext(ctx, "# Step 7: Shutting down server") _, err = sshsession.Run(sshClient, "shutdown now") if err != nil { // TODO Verify if shutdown error, otherwise return - fmt.Printf("shutdown error: %+v", err) + logger.WarnContext(ctx, "shutdown returned error", "err", err) } // 8. Create Image from Server - log.Print("Step 7: Creating Image") + logger.InfoContext(ctx, "# Step 8: Creating Image") createImageResult, _, err := s.client.Server.CreateImage(ctx, server, &hcloud.ServerCreateImageOpts{ Type: hcloud.ImageTypeSnapshot, Description: options.Description, @@ -220,12 +258,16 @@ func (s snapshotClient) Upload(ctx context.Context, options UploadOptions) (*hcl if err != nil { return nil, fmt.Errorf("failed to create snapshot: %w", err) } - _, err = s.client.Action.WaitForAction(ctx, createImageResult.Action) + logger.DebugContext(ctx, "image creation requested, waiting on action") + + err = s.client.Action.WaitFor(ctx, createImageResult.Action) if err != nil { return nil, fmt.Errorf("failed to create snapshot: %w", err) } + logger.DebugContext(ctx, "action finished, image was created") image := createImageResult.Image + logger.InfoContext(ctx, "# Image was created", "image", image.ID) // Resource cleanup is happening in `defer` return image, nil diff --git a/util/contextlogger/context.go b/util/contextlogger/context.go new file mode 100644 index 0000000..811e29a --- /dev/null +++ b/util/contextlogger/context.go @@ -0,0 +1,24 @@ +package contextlogger + +import ( + "context" + "log/slog" +) + +type key int + +var loggerKey key + +func New(ctx context.Context, logger *slog.Logger) context.Context { + return context.WithValue(ctx, loggerKey, logger) +} + +func From(ctx context.Context) *slog.Logger { + if ctxLogger := ctx.Value(loggerKey); ctxLogger != nil { + if logger, ok := ctxLogger.(*slog.Logger); ok { + return logger + } + } + + return slog.New(discardHandler{}) +} diff --git a/util/contextlogger/discard.go b/util/contextlogger/discard.go new file mode 100644 index 0000000..545f6ac --- /dev/null +++ b/util/contextlogger/discard.go @@ -0,0 +1,15 @@ +package contextlogger + +import ( + "context" + "log/slog" +) + +// discardHandler is a [slog.Handler] that just discards any input. It is a safe default if any library +// method does not get passed a logger through the context. +type discardHandler struct{} + +func (discardHandler) Enabled(_ context.Context, _ slog.Level) bool { return false } +func (discardHandler) Handle(_ context.Context, _ slog.Record) error { return nil } +func (d discardHandler) WithAttrs(_ []slog.Attr) slog.Handler { return d } +func (d discardHandler) WithGroup(_ string) slog.Handler { return d } diff --git a/util/control/retry.go b/util/control/retry.go index f73a2c5..1240467 100644 --- a/util/control/retry.go +++ b/util/control/retry.go @@ -7,6 +7,8 @@ import ( "time" "github.com/hetznercloud/hcloud-go/v2/hcloud" + + "github.com/apricote/hcloud-upload-image/util/contextlogger" ) // From https://github.com/hetznercloud/terraform-provider-hcloud/blob/v1.46.1/internal/control/retry.go @@ -57,6 +59,8 @@ func AbortRetry(err error) error { // Retry executes f at most maxTries times. func Retry(ctx context.Context, maxTries int, f func() error) error { + logger := contextlogger.From(ctx) + var err error backoff := ExponentialBackoffWithLimit(2, 1*time.Second, 30*time.Second) @@ -74,6 +78,7 @@ func Retry(ctx context.Context, maxTries int, f func() error) error { } if err != nil { sleep := backoff(try) + logger.DebugContext(ctx, "operation failed, waiting before trying again", "try", try, "backoff", sleep) time.Sleep(sleep) continue } diff --git a/util/randomid/randomid.go b/util/randomid/randomid.go index ab6881f..5f19cd9 100644 --- a/util/randomid/randomid.go +++ b/util/randomid/randomid.go @@ -6,6 +6,8 @@ import ( "fmt" ) +// From https://gitlab.com/hetznercloud/fleeting-plugin-hetzner/-/blob/0f60204582289c243599f8ca0f5be4822789131d/internal/utils/random.go + func Generate() (string, error) { b := make([]byte, 4) _, err := rand.Read(b) diff --git a/util/sshkey/ssh_key.go b/util/sshkey/ssh_key.go index 96377dc..45c1de1 100644 --- a/util/sshkey/ssh_key.go +++ b/util/sshkey/ssh_key.go @@ -7,6 +7,8 @@ import ( "golang.org/x/crypto/ssh" ) +// From https://gitlab.com/hetznercloud/fleeting-plugin-hetzner/-/blob/0f60204582289c243599f8ca0f5be4822789131d/internal/utils/ssh_key.go + func GenerateKeyPair() ([]byte, []byte, error) { pub, priv, err := ed25519.GenerateKey(nil) if err != nil {