Trace and Debug logging inside MarkComputedNilsAsUnknown is not properly disabled by default

[kklimonda-cl]

Module version

github.com/hashicorp/terraform-plugin-framework v1.13.0

Relevant provider source code

Not related directly to any of our provider code, but the resource in question has a large ListNestedAttribute (called "rules"). See https://github.com/PaloAltoNetworks/terraform-provider-panos/blob/main/internal/provider/security_policy.go for reference.

Terraform Configuration Files

You can see an example configuration here https://github.com/PaloAltoNetworks/terraform-provider-panos/blob/db762fb977703c4f6e5a0a445b50636ca0385495/test/resource_security_policy_test.go#L399

Debug Output

No output is generated, but the logging inside MarkComputedNilsAsUnknown is still taking excessive amount of time.

Expected Behavior

When all logging is removed from MarkComputedNilsAsUnknown(), the resource in question, with a list of 3,000 rules can be applied within 4 minutes (3:30 of which is spent within our code).

Actual Behavior

It takes 15 minutes to apply this resource, over 10 minutes are spent by terraform without any visible progress.

Steps to Reproduce

No TF_* values are set within my environment (other than TF_REATTACH_PROVIDERS)

I don't have a public reproducer (but you can reach out to me if needed) but this should be reproducible with any provider that has computed attributes:

What I'm seeing is that Trace and Debug calls within MarkComputedNilsAsUnknown are not properly short circuited to return early if given log level is not turned on.

For example:

In the inner function returned by MarkComputedNilsAsUnknown() we call logging.FrameworkTrace():

   400:			if !attribute.IsComputed() {
=> 401:				logging.FrameworkTrace(ctx, "attribute is not computed in schema, not marking unknown")
   402:
   403:				return val, nil
   404:			}

and then within SubsystemTrace we call subsystemWouldLog:

   106:	func SubsystemTrace(ctx context.Context, subsystem, msg string, additionalFields ...map[string]interface{}) {
=> 107:		if !subsystemWouldLog(subsystem, hclog.Trace) {
   108:			return
   109:		}

and then this calls wouldLog:

    56:
=>  57:		return wouldLog(setLevel, level)
    58:	}
(dlv) print level
Trace (1)
(dlv) print setLevel
NoLevel (0)

within wouldLog we get to this point:

    79:
=>  80:		return checkLevel >= setLevel
    81:	}
(dlv) print checkLevel
Trace (1)
(dlv) print setLevel
NoLevel (0)
(dlv)

where checkLevel (1) >= setLevel (0), and so logging is not skipped within SubsystemTrace and just goes on to create logger etc.:

   110:
=> 111:		logger := logging.GetSDKSubsystemLogger(ctx, subsystem)
   112:		if logger == nil {
   113:			if logging.GetSDKRootLogger(ctx) == nil {

References

Seems related to #721

[austinvalle]

Drive-by note 🚗

Provider logging in-general defaults to TRACE and the subsystem logger has it's level copied from there, so it should also be defaulting to TRACE (It may be a bug that the cached variable is defaulting to NoLevel, because the underlying logger itself will be TRACE, but the outcome ends up being the same as TRACE).

The reason provider logging defaults to TRACE is historical, as during a normal plugin context, all of the provider logs are sent back to Terraform core via a separate RPC service, which core then does the level filtering on our behalf.

If you wanted to prevent the logging events you're referencing from occurring today, you'd have to explicitly set the TF_LOG_SDK_FRAMEWORK environment variable to do so:

export TF_LOG_SDK_FRAMEWORK=ERROR
terraform plan

---

So, what we'd need to consider to resolve this issue is to adjust the default log level of framework or potentially the provider logging in general. If we do so, we'd likely need to fix that bug I mentioned above, as the subsystem's are not currently inheriting the level's correctly: https://developer.hashicorp.com/terraform/plugin/log/managing#enable-logging

[austinvalle]

Of all the SDK subsystem loggers, TF_LOG_SDK_FRAMEWORK is definitely the most used, as it logs traces at each attribute in an object value during multiple pieces of logic that occur a couple times in a plan (marking computed as nil, semantic equality, upcoming write-only attribute nullification #1044).