hashicorp / hashicorp/terraform-plugin-framework
Trace and Debug logging inside MarkComputedNilsAsUnknown is not properly disabled by default
- Dominant language
- Go
- Stars
- 384
- Forks
- 107
- Avg merge
- 3m
- Merged PRs (30d)
- 1
Description
### 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 https://github.com/hashicorp/terraform-plugin-framework/issues/721
Contributor guide
Assessment
This issue has not been assessed yet.