feat: log output

This commit is contained in:
Julian Tölle 2024-04-30 23:48:59 +02:00
parent 4f57df5b66
commit 904e5e0bed
8 changed files with 133 additions and 23 deletions

8
go.mod
View file

@ -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
)

14
go.sum
View file

@ -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=

View file

@ -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 {
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

View file

@ -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{})
}

View file

@ -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 }

View file

@ -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
}

View file

@ -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)

View file

@ -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 {