Skip to content

Commit 0f7f7dd

Browse files
ksamorayclaude
andcommitted
Add diagnostics for cache-population race investigation
terraform-cache-brownfield started failing on config_scope/global mode assertions after passing consistently through build #3. Static tracing couldn't fully confirm whether the cause is an NSX search-index consistency race or a runID mismatch across separate terraform apply processes, so add targeted logging (no behavior change) to make the next failure self-evident: log the resourceType/id/runID/currentTags when a provider-managed tag gets re-patched, and log the populated bucket size when a resourceID is still missing right after a bulk search just populated that bucket. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
1 parent e9926db commit 0f7f7dd

3 files changed

Lines changed: 67 additions & 5 deletions

File tree

nsxt/cache.go

Lines changed: 29 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -502,6 +502,12 @@ func (c *typeScopedCache) readCache(resourceID string, resourceType string, d *s
502502
if val != nil {
503503
return val, nil
504504
}
505+
// Diagnostic only (no behavior change): a non-zero bucketSize here means the bulk
506+
// search that just populated this bucket returned other objects of this type just fine,
507+
// but not the one this read was for — evidence of an NSX search-index consistency lag
508+
// (the object exists but wasn't indexed yet) rather than a cold/empty bucket.
509+
bucketSize := len(tc.data[query])
510+
populateEvents = append(populateEvents, cacheLogEvent{"DEBUG", fmt.Sprintf("Cache post-populate miss: resourceType=%s id=%s query=%q bucketSize=%d", resourceType, resourceID, query, bucketSize)})
505511
return nil, errCacheUseBackendDirect
506512
}
507513

@@ -870,7 +876,7 @@ func CacheAwareResourceRead[T any](d *schema.ResourceData, m interface{}, connec
870876

871877
// Only stamp provider-managed tags in config_scope mode.
872878
if isConfigScopedCacheMode(m) {
873-
_, patchErr := ensureProviderManagedTagsWithPatchFunc(obj, m, patchFunc)
879+
_, patchErr := ensureProviderManagedTagsWithPatchFunc(obj, m, resourceType, resourceID, patchFunc)
874880
if patchErr != nil {
875881
log.Printf("[WARNING] Failed to patch provider-managed tags for %s %s: %v", resourceType, resourceID, patchErr) //nolint:gosec
876882
}
@@ -1006,8 +1012,27 @@ func stripProviderManagedTagsFromAny(obj interface{}) {
10061012
tagsField.Set(reflect.ValueOf(userTags))
10071013
}
10081014

1015+
// formatModelTagsForLog renders tags as scope=tag pairs for diagnostic log lines.
1016+
func formatModelTagsForLog(tags []model.Tag) string {
1017+
parts := make([]string, 0, len(tags))
1018+
for _, tag := range tags {
1019+
scope := ""
1020+
if tag.Scope != nil {
1021+
scope = *tag.Scope
1022+
}
1023+
val := ""
1024+
if tag.Tag != nil {
1025+
val = *tag.Tag
1026+
}
1027+
parts = append(parts, fmt.Sprintf("%s=%s", scope, val))
1028+
}
1029+
return "[" + strings.Join(parts, ", ") + "]"
1030+
}
1031+
10091032
// ensureProviderManagedTagsWithPatchFunc adds provider-managed tags to obj via patchFunc when missing.
1010-
func ensureProviderManagedTagsWithPatchFunc[T any](obj T, m interface{}, patchFunc func(obj T) error) (interface{}, error) {
1033+
// resourceType/resourceID are for diagnostic logging only (identifying which object this
1034+
// decision was made for) and do not affect the decision itself.
1035+
func ensureProviderManagedTagsWithPatchFunc[T any](obj T, m interface{}, resourceType string, resourceID string, patchFunc func(obj T) error) (interface{}, error) {
10111036
objValue := reflect.ValueOf(obj)
10121037
for objValue.IsValid() && objValue.Kind() == reflect.Pointer {
10131038
if objValue.IsNil() {
@@ -1056,7 +1081,8 @@ func ensureProviderManagedTagsWithPatchFunc[T any](obj T, m interface{}, patchFu
10561081
if !needsPatch {
10571082
return nil, nil
10581083
}
1059-
log.Printf("[DEBUG] Provider-managed tag missing; patching object to add scope=%s", managedDefaultTagScope) //nolint:gosec
1084+
log.Printf("[DEBUG] Provider-managed tag missing; patching object to add scope=%s resourceType=%s id=%s runID=%q expectedManagedTags=%s currentTags=%s", //nolint:gosec
1085+
managedDefaultTagScope, resourceType, resourceID, runID, formatModelTagsForLog(expectedManagedTags), formatModelTagsForLog(currentTags))
10601086

10611087
userTags := make([]model.Tag, 0)
10621088
for _, tag := range currentTags {

nsxt/cache_test.go

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -174,7 +174,7 @@ func TestUnitNsxt_ensureProviderManagedTagsWithPatchFunc(t *testing.T) {
174174
}}
175175
called := false
176176

177-
patched, err := ensureProviderManagedTagsWithPatchFunc(obj, m, func(o *testTagObj) error {
177+
patched, err := ensureProviderManagedTagsWithPatchFunc(obj, m, "TestType", "test-id", func(o *testTagObj) error {
178178
called = true
179179
return nil
180180
})
@@ -196,7 +196,7 @@ func TestUnitNsxt_ensureProviderManagedTagsWithPatchFunc(t *testing.T) {
196196
}}
197197
called := false
198198

199-
patched, err := ensureProviderManagedTagsWithPatchFunc(obj, m, func(o *testTagObj) error {
199+
patched, err := ensureProviderManagedTagsWithPatchFunc(obj, m, "TestType", "test-id", func(o *testTagObj) error {
200200
called = true
201201
return nil
202202
})

nsxt/cache_unit_test.go

Lines changed: 36 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -7,7 +7,9 @@
77
package nsxt
88

99
import (
10+
"bytes"
1011
"errors"
12+
"log"
1113
"testing"
1214

1315
"github.com/hashicorp/terraform-plugin-sdk/v2/helper/schema"
@@ -264,6 +266,40 @@ func TestUnitNsxt_readCacheMissingIDBypassesBackend(t *testing.T) {
264266
assert.True(t, errors.Is(err, errCacheUseBackendDirect))
265267
}
266268

269+
// TestUnitNsxt_readCachePostPopulateMissLogsBucketSize is a diagnostic-only regression
270+
// test (see brownfield_cache_test investigation): when the bulk search that just populated
271+
// a bucket returns other objects of the type but not the one this read was for, readCache
272+
// must log "Cache post-populate miss" with the actual (non-zero) bucket size, distinguishing
273+
// this from a cold/empty bucket — the signal used to tell an NSX search-index consistency
274+
// race apart from a genuinely absent object.
275+
func TestUnitNsxt_readCachePostPopulateMissLogsBucketSize(t *testing.T) {
276+
sv := groupStructValue(t, "g1", "my-group", "/infra/domains/default/groups/g1")
277+
stub := &seqQueryListClient{responses: []nsxModel.SearchResponse{
278+
{Results: []*data.StructValue{sv}, ResultCount: i64(1)},
279+
}}
280+
defer setupCliQueryClientStub(t, stub)()
281+
282+
d := schema.TestResourceDataRaw(t, cacheTestSchema(), map[string]interface{}{})
283+
m := nsxtClients{CommonConfig: commonProviderConfig{CacheMode: "config_scope"}}
284+
c := &typeScopedCache{byTyp: make(map[string]*resourceTypeCache)}
285+
286+
var logBuf bytes.Buffer
287+
origOutput := log.Writer()
288+
log.SetOutput(&logBuf)
289+
defer log.SetOutput(origOutput)
290+
291+
_, err := c.readCache("g2", resourceTypeGroup, d, m, nil)
292+
assert.True(t, errors.Is(err, errCacheUseBackendDirect))
293+
294+
logged := logBuf.String()
295+
assert.Contains(t, logged, "Cache post-populate miss: resourceType=Group id=g2")
296+
// converListToMapByType indexes the populated object (g1) under multiple keys (id and
297+
// display_name), so bucketSize is >1 here — the point is just that it's non-zero,
298+
// proving the bucket really was populated with other objects rather than staying empty.
299+
assert.NotContains(t, logged, "bucketSize=0", "bucket held the other populated object (g1), so size must not be reported as 0")
300+
assert.Contains(t, logged, "bucketSize=2")
301+
}
302+
267303
func TestUnitNsxt_getListOfPolicyResourcesCompositeMergesRules(t *testing.T) {
268304
parentPath := "/infra/domains/default/security-policies/sp1"
269305
converter := bindings.NewTypeConverter()

0 commit comments

Comments
 (0)