Added debug logs for render command (#5328)

cmd/crank/beta/render/cmd.go

@@ -119,7 +119,7 @@ func (c *Cmd) AfterApply() error {
 }
 
 // Run render.
-func (c *Cmd) Run(k *kong.Context, _ logging.Logger) error { //nolint:gocyclo // Only a touch over.
+func (c *Cmd) Run(k *kong.Context, logger logging.Logger) error { //nolint:gocyclo // Only a touch over.
 	xr, err := LoadCompositeResource(c.fs, c.CompositeResource)
 	if err != nil {
 		return errors.Wrapf(err, "cannot load composite resource from %q", c.CompositeResource)
@@ -180,7 +180,7 @@ func (c *Cmd) Run(k *kong.Context, _ logging.Logger) error { //nolint:gocyclo //
 	ctx, cancel := context.WithTimeout(context.Background(), c.Timeout)
 	defer cancel()
 
-	out, err := Render(ctx, Inputs{
+	out, err := Render(ctx, logger, Inputs{
 		CompositeResource: xr,
 		Composition:       comp,
 		Functions:         fns,

cmd/crank/beta/render/render.go

@@ -32,6 +32,7 @@ import (
 
 	xpv1 "github.com/crossplane/crossplane-runtime/apis/common/v1"
 	"github.com/crossplane/crossplane-runtime/pkg/errors"
+	"github.com/crossplane/crossplane-runtime/pkg/logging"
 	"github.com/crossplane/crossplane-runtime/pkg/meta"
 	"github.com/crossplane/crossplane-runtime/pkg/resource"
 	"github.com/crossplane/crossplane-runtime/pkg/resource/unstructured/composed"
@@ -84,26 +85,26 @@ type Outputs struct {
 	// TODO(negz): Allow returning desired XR connection details. Maybe as a
 	// Secret? Should we honor writeConnectionSecretToRef? What if secret stores
 	// are in use?
-
-	// TODO(negz): Allow returning desired XR readiness? Or perhaps just set the
-	// ready status condition on the XR if all supplied observed resources
-	// appear ready?
 }
 
 // Render the desired XR and composed resources, sorted by resource name, given the supplied inputs.
-func Render(ctx context.Context, in Inputs) (Outputs, error) { //nolint:gocyclo // TODO(negz): Should we refactor to break this up a bit?
+func Render(ctx context.Context, logger logging.Logger, in Inputs) (Outputs, error) { //nolint:gocyclo // TODO(negz): Should we refactor to break this up a bit?
 	// Run our Functions.
 	conns := map[string]*grpc.ClientConn{}
 	for _, fn := range in.Functions {
 		runtime, err := GetRuntime(fn)
 		if err != nil {
 			return Outputs{}, errors.Wrapf(err, "cannot get runtime for Function %q", fn.GetName())
 		}
-		rctx, err := runtime.Start(ctx)
+		rctx, err := runtime.Start(ctx, logger)
 		if err != nil {
 			return Outputs{}, errors.Wrapf(err, "cannot start Function %q", fn.GetName())
 		}
-		defer rctx.Stop(ctx) //nolint:errcheck // Not sure what to do with this error. Log it to stderr?
+		defer func() {
+			if err := rctx.Stop(ctx); err != nil {
+				logger.Debug("Error stopping function runtime", "function", fn.GetName(), "error", err)
+			}
+		}()
 
 		conn, err := grpc.DialContext(ctx, rctx.Target,
 			grpc.WithTransportCredentials(insecure.NewCredentials()),

cmd/crank/beta/render/render_test.go

@@ -32,6 +32,7 @@ import (
 	"k8s.io/apimachinery/pkg/apis/meta/v1/unstructured"
 	"k8s.io/apimachinery/pkg/runtime"
 
+	"github.com/crossplane/crossplane-runtime/pkg/logging"
 	"github.com/crossplane/crossplane-runtime/pkg/resource/unstructured/composed"
 	"github.com/crossplane/crossplane-runtime/pkg/resource/unstructured/composite"
 
@@ -739,7 +740,7 @@ func TestRender(t *testing.T) {
 	for name, tc := range cases {
 		t.Run(name, func(t *testing.T) {
 
-			out, err := Render(tc.args.ctx, tc.args.in)
+			out, err := Render(tc.args.ctx, logging.NewNopLogger(), tc.args.in)
 
 			if diff := cmp.Diff(tc.want.out, out, cmpopts.EquateEmpty()); diff != "" {
 				t.Errorf("%s\nRender(...): -want, +got:\n%s", tc.reason, diff)

cmd/crank/beta/render/runtime.go

@@ -20,6 +20,7 @@ import (
 	"context"
 
 	"github.com/crossplane/crossplane-runtime/pkg/errors"
+	"github.com/crossplane/crossplane-runtime/pkg/logging"
 
 	pkgv1beta1 "github.com/crossplane/crossplane/apis/pkg/v1beta1"
 )
@@ -49,7 +50,7 @@ const (
 // A Runtime runs a Function.
 type Runtime interface {
 	// Start the Function.
-	Start(ctx context.Context) (RuntimeContext, error)
+	Start(ctx context.Context, logger logging.Logger) (RuntimeContext, error)
 }
 
 // RuntimeContext contains context on how a Function is being run.

cmd/crank/beta/render/runtime_development.go

@@ -19,6 +19,8 @@ package render
 import (
 	"context"
 
+	"github.com/crossplane/crossplane-runtime/pkg/logging"
+
 	pkgv1beta1 "github.com/crossplane/crossplane/apis/pkg/v1beta1"
 )
 
@@ -35,12 +37,14 @@ type RuntimeDevelopment struct {
 	// Target is the gRPC target for the running function, for example
 	// localhost:9443.
 	Target string
+	// Function is the name of the function to be run.
+	Function string
 }
 
 // GetRuntimeDevelopment extracts RuntimeDevelopment configuration from the
 // supplied Function.
 func GetRuntimeDevelopment(fn pkgv1beta1.Function) *RuntimeDevelopment {
-	r := &RuntimeDevelopment{Target: "localhost:9443"}
+	r := &RuntimeDevelopment{Target: "localhost:9443", Function: fn.GetName()}
 	if t := fn.GetAnnotations()[AnnotationKeyRuntimeDevelopmentTarget]; t != "" {
 		r.Target = t
 	}
@@ -50,6 +54,7 @@ func GetRuntimeDevelopment(fn pkgv1beta1.Function) *RuntimeDevelopment {
 var _ Runtime = &RuntimeDevelopment{}
 
 // Start does nothing. It returns a Stop function that also does nothing.
-func (r *RuntimeDevelopment) Start(_ context.Context) (RuntimeContext, error) {
+func (r *RuntimeDevelopment) Start(_ context.Context, logger logging.Logger) (RuntimeContext, error) {
+	logger.Debug("Starting development runtime. Remember to run the function manually.", "function", r.Function, "target", r.Target)
 	return RuntimeContext{Target: r.Target, Stop: func(_ context.Context) error { return nil }}, nil
 }

cmd/crank/beta/render/runtime_docker.go

@@ -29,6 +29,7 @@ import (
 	"github.com/docker/go-connections/nat"
 
 	"github.com/crossplane/crossplane-runtime/pkg/errors"
+	"github.com/crossplane/crossplane-runtime/pkg/logging"
 
 	pkgv1beta1 "github.com/crossplane/crossplane/apis/pkg/v1beta1"
 )
@@ -149,7 +150,8 @@ func GetRuntimeDocker(fn pkgv1beta1.Function) (*RuntimeDocker, error) {
 var _ Runtime = &RuntimeDocker{}
 
 // Start a Function as a Docker container.
-func (r *RuntimeDocker) Start(ctx context.Context) (RuntimeContext, error) { //nolint:gocyclo // TODO(phisco): Refactor to break this up a bit, not so easy.
+func (r *RuntimeDocker) Start(ctx context.Context, logger logging.Logger) (RuntimeContext, error) { //nolint:gocyclo // TODO(phisco): Refactor to break this up a bit, not so easy.
+	logger.Debug("Starting Docker container runtime", "image", r.Image)
 	c, err := client.NewClientWithOpts(client.FromEnv, client.WithAPIVersionNegotiation())
 	if err != nil {
 		return RuntimeContext{}, errors.Wrap(err, "cannot create Docker client using environment variables")
@@ -180,20 +182,23 @@ func (r *RuntimeDocker) Start(ctx context.Context) (RuntimeContext, error) { //n
 	}
 
 	if r.PullPolicy == AnnotationValueRuntimeDockerPullPolicyAlways {
+		logger.Debug("Pulling image with pullPolicy: Always", "image", r.Image)
 		err = PullImage(ctx, c, r.Image)
 		if err != nil {
 			return RuntimeContext{}, errors.Wrapf(err, "cannot pull Docker image %q", r.Image)
 		}
 	}
 
 	// TODO(negz): Set a container name? Presumably unique across runs.
+	logger.Debug("Creating Docker container", "image", r.Image, "address", addr)
 	rsp, err := c.ContainerCreate(ctx, cfg, hcfg, nil, nil, "")
 	if err != nil {
 		if !errdefs.IsNotFound(err) || r.PullPolicy == AnnotationValueRuntimeDockerPullPolicyNever {
 			return RuntimeContext{}, errors.Wrap(err, "cannot create Docker container")
 		}
 
 		// The image was not found, but we're allowed to pull it.
+		logger.Debug("Image not found, pulling", "image", r.Image)
 		err = PullImage(ctx, c, r.Image)
 		if err != nil {
 			return RuntimeContext{}, errors.Wrapf(err, "cannot pull Docker image %q", r.Image)
@@ -210,7 +215,7 @@ func (r *RuntimeDocker) Start(ctx context.Context) (RuntimeContext, error) { //n
 	}
 
 	stop := func(_ context.Context) error {
-		// TODO(negz): Maybe log to stderr that we're leaving the container running?
+		logger.Debug("Container left running", "container", rsp.ID, "image", r.Image)
 		return nil
 	}
 	if r.Stop {