Consider Helper() Function to Fix Log Entry @caller Information

[bflad]

terraform-plugin-log version

v0.2.1

Use cases

When implementing subsystem loggers, it can be helpful to create a package and wrapper functions for the tflog.SubsystemX() (or for the SDKs, tfsdklog.SubsystemX()) calls to simplify and potentially clarify the code, e.g.

//
// NOTE: This is a SDK-specific example. Providers should always use the tflog package.
//
package logging

import (
	"context"

	"github.com/hashicorp/terraform-plugin-log/tfsdklog"
)

const (
	// SubsystemProto is the tfsdklog subsystem name for protocol logging.
	SubsystemProto = "proto"
)

// ProtocolError emits a protocol subsystem log at ERROR level.
func ProtocolError(ctx context.Context, msg string, args ...interface{}) {
	tfsdklog.SubsystemError(ctx, SubsystemProto, msg, args)
}

// ProtocolTrace emits a protocol subsystem log at TRACE level.
func ProtocolTrace(ctx context.Context, msg string, args ...interface{}) {
	tfsdklog.SubsystemTrace(ctx, SubsystemProto, msg, args)
}

Which makes calling code fairly concise:

logging.ProtocolTrace(ctx, "Received request")

When doing this, the log entries are then off by one frame in the @caller (pretty printed for clarity):

{
    "@caller": "/Users/bflad/go/pkg/mod/github.com/hashicorp/terraform-plugin-go@v0.7.0/internal/logging/protocol.go:21",
    "@level": "trace",
    "@message": "Received request",
    "@module": "sdk.proto",
    "@timestamp": "2022-02-04T16:28:52.602080-05:00",
    "EXTRA_VALUE_AT_END": null,
    "tf_proto_version": "5.2",
    "tf_provider_addr": "",
    "tf_req_id": "a24b8a29-628a-01c2-0516-08b260627109",
    "tf_rpc": "GetProviderSchema"
}

Which makes troubleshooting slightly harder.

Proposal

Similar to how the Go standard library testing package implements T.Helper(), which is defined as:

Helper marks the calling function as a test helper function. When printing file and line information, that function will be skipped. Helper may be called simultaneously from multiple goroutines.

It might be possible to do something similar with these packages so callers can signify that the final frame in the stack should be ignored for file and line information.

[bflad]

This is more complex as hc-log supports LoggerOptions.AdditionalLocationOffset, but LoggerOptions are used when creating a Logger and there is no ability to update it later at the moment. As a workaround, we may be able to also save our logger options separately in the context so we can recreate the logger with the additional value, but ideally upstream would support the ability to update the location offset, similar to updating the log level.

[bflad]

A more trivial, but less flexible approach would be allowing callers to set the additional offset on subsystem creation via a new logger.Option. This is probably good enough for now.

[bflad]

Went with a new WithAdditionalLocationOffset() function to be used with NewSubsystem() for now, which can be used to remove additional calls from the caller stack when using helpers. If desirable, the SDKs can also surface this functionality for the root provider logger.

[github-actions]

I'm going to lock this issue because it has been closed for 30 days ⏳. This helps our maintainers find and focus on the active issues.
If you have found a problem that seems similar to this, please open a new issue and complete the issue template so we can capture all the details necessary to investigate further.