Skip to content

Commit ade4738

Browse files
SantiagoDePoloniaSantiagoDePolonia
authored
fix(providers): reduce metadata enrichment log noise (#187)
1 parent 3740a6c commit ade4738

4 files changed

Lines changed: 151 additions & 24 deletions

File tree

‎internal/modeldata/enricher.go‎

Lines changed: 12 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -1,8 +1,6 @@
11
package modeldata
22

33
import (
4-
"log/slog"
5-
64
"gomodel/internal/core"
75
)
86

@@ -18,11 +16,17 @@ type ModelInfoAccessor interface {
1816
SetMetadata(modelID string, meta *core.ModelMetadata)
1917
}
2018

19+
// EnrichStats summarizes one metadata enrichment pass.
20+
type EnrichStats struct {
21+
Enriched int
22+
Total int
23+
}
24+
2125
// Enrich iterates all models accessible via the accessor and attaches resolved
2226
// metadata from the model list. Models not found in the list are left unchanged.
23-
func Enrich(accessor ModelInfoAccessor, list *ModelList) {
27+
func Enrich(accessor ModelInfoAccessor, list *ModelList) EnrichStats {
2428
if list == nil || accessor == nil {
25-
return
29+
return EnrichStats{}
2630
}
2731

2832
var enriched int
@@ -37,8 +41,8 @@ func Enrich(accessor ModelInfoAccessor, list *ModelList) {
3741
}
3842
}
3943

40-
slog.Info("enriched models with metadata",
41-
"enriched", enriched,
42-
"total", len(ids),
43-
)
44+
return EnrichStats{
45+
Enriched: enriched,
46+
Total: len(ids),
47+
}
4448
}

‎internal/providers/init.go‎

Lines changed: 5 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -114,16 +114,18 @@ func Init(ctx context.Context, result *config.LoadResult, factory *ProviderFacto
114114
}
115115

116116
registry.SetModelList(list, raw)
117-
registry.EnrichModels()
117+
metadataStats := registry.enrichModels()
118118

119119
if err := registry.SaveToCache(fetchCtx); err != nil {
120120
slog.Warn("failed to save cache after model list fetch", "error", err)
121121
}
122-
slog.Info("model list loaded",
122+
attrs := []any{
123123
"models", len(list.Models),
124124
"providers", len(list.Providers),
125125
"provider_models", len(list.ProviderModels),
126-
)
126+
}
127+
attrs = append(attrs, metadataStats.slogAttrs()...)
128+
slog.Info("model list loaded", attrs...)
127129
}()
128130
}
129131

‎internal/providers/registry.go‎

Lines changed: 45 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -50,6 +50,20 @@ type ModelRegistry struct {
5050
categoryCache map[core.ModelCategory][]ModelWithProvider
5151
}
5252

53+
type metadataEnrichmentStats struct {
54+
Enriched int
55+
Total int
56+
Providers int
57+
}
58+
59+
func (s metadataEnrichmentStats) slogAttrs() []any {
60+
return []any{
61+
"metadata_enriched", s.Enriched,
62+
"metadata_total", s.Total,
63+
"metadata_providers", s.Providers,
64+
}
65+
}
66+
5367
// NewModelRegistry creates a new model registry
5468
func NewModelRegistry() *ModelRegistry {
5569
return &ModelRegistry{
@@ -190,8 +204,9 @@ func (r *ModelRegistry) Initialize(ctx context.Context) error {
190204
r.mu.RLock()
191205
list := r.modelList
192206
r.mu.RUnlock()
207+
metadataStats := metadataEnrichmentStats{}
193208
if list != nil {
194-
enrichProviderModelMaps(list, providerTypes, newModelsByProvider, nil)
209+
metadataStats = enrichProviderModelMaps(list, providerTypes, newModelsByProvider, nil)
195210
}
196211

197212
// Atomically swap the models map and invalidate sorted caches
@@ -206,11 +221,13 @@ func (r *ModelRegistry) Initialize(ctx context.Context) error {
206221
r.initialized = true
207222
r.initMu.Unlock()
208223

209-
slog.Info("model registry initialized",
224+
attrs := []any{
210225
"total_models", totalModels,
211226
"providers", len(providers),
212227
"failed_providers", failedProviders,
213-
)
228+
}
229+
attrs = append(attrs, metadataStats.slogAttrs()...)
230+
slog.Info("model registry initialized", attrs...)
214231

215232
return nil
216233
}
@@ -297,8 +314,9 @@ func (r *ModelRegistry) LoadFromCache(ctx context.Context) (int, error) {
297314
}
298315

299316
// Enrich cached models with model list metadata
317+
metadataStats := metadataEnrichmentStats{}
300318
if list != nil {
301-
enrichProviderModelMaps(list, r.snapshotProviderTypes(), newModelsByProvider, nil)
319+
metadataStats = enrichProviderModelMaps(list, r.snapshotProviderTypes(), newModelsByProvider, nil)
302320
}
303321

304322
r.mu.Lock()
@@ -311,10 +329,12 @@ func (r *ModelRegistry) LoadFromCache(ctx context.Context) (int, error) {
311329
}
312330
r.mu.Unlock()
313331

314-
slog.Info("loaded models from cache",
332+
attrs := []any{
315333
"models", len(newModels),
316334
"cache_updated_at", modelCache.UpdatedAt,
317-
)
335+
}
336+
attrs = append(attrs, metadataStats.slogAttrs()...)
337+
slog.Info("loaded models from cache", attrs...)
318338

319339
return len(newModels), nil
320340
}
@@ -902,24 +922,29 @@ func (r *ModelRegistry) SetModelList(list *modeldata.ModelList, raw json.RawMess
902922
// entries instead of mutating them in place so concurrent readers can safely keep
903923
// using older snapshots after unlocking.
904924
func (r *ModelRegistry) EnrichModels() {
925+
_ = r.enrichModels()
926+
}
927+
928+
func (r *ModelRegistry) enrichModels() metadataEnrichmentStats {
905929
r.mu.Lock()
906930
defer r.mu.Unlock()
907931

908932
if r.modelList == nil || len(r.models) == 0 {
909-
return
933+
return metadataEnrichmentStats{}
910934
}
911935

912936
providerTypes := make(map[core.Provider]string, len(r.providerTypes))
913937
maps.Copy(providerTypes, r.providerTypes)
914938

915939
replacements := make(map[*ModelInfo]*ModelInfo, len(r.models))
916-
enrichProviderModelMaps(r.modelList, providerTypes, r.modelsByProvider, replacements)
940+
stats := enrichProviderModelMaps(r.modelList, providerTypes, r.modelsByProvider, replacements)
917941
for modelID, info := range r.models {
918942
if replacement, ok := replacements[info]; ok {
919943
r.models[modelID] = replacement
920944
}
921945
}
922946
r.invalidateSortedCaches()
947+
return stats
923948
}
924949

925950
// ResolveMetadata resolves metadata for a model directly via the stored model list,
@@ -976,21 +1001,26 @@ func enrichProviderModelMaps(
9761001
providerTypes map[core.Provider]string,
9771002
modelsByProvider map[string]map[string]*ModelInfo,
9781003
replacements map[*ModelInfo]*ModelInfo,
979-
) {
1004+
) metadataEnrichmentStats {
9801005
if list == nil {
981-
return
1006+
return metadataEnrichmentStats{}
9821007
}
1008+
stats := metadataEnrichmentStats{}
9831009
for _, providerModels := range modelsByProvider {
9841010
if len(providerModels) == 0 {
9851011
continue
9861012
}
1013+
stats.Providers++
9871014
accessor := &registryAccessor{
9881015
models: providerModels,
9891016
providerTypes: providerTypes,
9901017
replacements: replacements,
9911018
}
992-
modeldata.Enrich(accessor, list)
1019+
enrichStats := modeldata.Enrich(accessor, list)
1020+
stats.Enriched += enrichStats.Enriched
1021+
stats.Total += enrichStats.Total
9931022
}
1023+
return stats
9941024
}
9951025

9961026
// registryAccessor implements modeldata.ModelInfoAccessor.
@@ -1104,14 +1134,16 @@ func (r *ModelRegistry) refreshModelList(ctx context.Context, url string) {
11041134
}
11051135

11061136
r.SetModelList(list, raw)
1107-
r.EnrichModels()
1137+
metadataStats := r.enrichModels()
11081138

11091139
if err := r.SaveToCache(fetchCtx); err != nil {
11101140
if !isBenignBackgroundRefreshError(ctx, err) {
11111141
slog.Warn("failed to save cache after model list refresh", "error", err)
11121142
}
11131143
}
1114-
slog.Debug("model list refreshed", "models", len(list.Models))
1144+
attrs := []any{"models", len(list.Models)}
1145+
attrs = append(attrs, metadataStats.slogAttrs()...)
1146+
slog.Debug("model list refreshed", attrs...)
11151147
}
11161148

11171149
func isBenignBackgroundRefreshError(parent context.Context, err error) bool {

‎internal/providers/registry_test.go‎

Lines changed: 89 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,11 +1,14 @@
11
package providers
22

33
import (
4+
"bytes"
45
"context"
56
"errors"
67
"io"
8+
"log/slog"
79
"net/http"
810
"net/http/httptest"
11+
"strings"
912
"sync/atomic"
1013
"testing"
1114
"time"
@@ -608,6 +611,92 @@ func TestModelRegistry(t *testing.T) {
608611
})
609612
}
610613

614+
func TestInitialize_LogsSingleMetadataSummaryPerCycle(t *testing.T) {
615+
registry := NewModelRegistry()
616+
617+
openAIProvider := &registryMockProvider{
618+
name: "openai-primary",
619+
modelsResponse: &core.ModelsResponse{
620+
Object: "list",
621+
Data: []core.Model{
622+
{ID: "gpt-test", Object: "model", OwnedBy: "openai"},
623+
},
624+
},
625+
}
626+
anthropicProvider := &registryMockProvider{
627+
name: "anthropic-primary",
628+
modelsResponse: &core.ModelsResponse{
629+
Object: "list",
630+
Data: []core.Model{
631+
{ID: "claude-test", Object: "model", OwnedBy: "anthropic"},
632+
},
633+
},
634+
}
635+
registry.RegisterProviderWithNameAndType(openAIProvider, "openai-primary", "openai")
636+
registry.RegisterProviderWithNameAndType(anthropicProvider, "anthropic-primary", "anthropic")
637+
638+
raw := []byte(`{
639+
"version": 1,
640+
"updated_at": "2025-01-01T00:00:00Z",
641+
"providers": {
642+
"openai": {
643+
"display_name": "OpenAI",
644+
"api_type": "openai",
645+
"supported_modes": ["chat"]
646+
},
647+
"anthropic": {
648+
"display_name": "Anthropic",
649+
"api_type": "openai",
650+
"supported_modes": ["chat"]
651+
}
652+
},
653+
"models": {
654+
"gpt-test": {
655+
"display_name": "GPT Test",
656+
"modes": ["chat"]
657+
},
658+
"claude-test": {
659+
"display_name": "Claude Test",
660+
"modes": ["chat"]
661+
}
662+
},
663+
"provider_models": {}
664+
}`)
665+
list, err := modeldata.Parse(raw)
666+
if err != nil {
667+
t.Fatalf("Parse() error = %v", err)
668+
}
669+
registry.SetModelList(list, raw)
670+
671+
var buf bytes.Buffer
672+
original := slog.Default()
673+
slog.SetDefault(slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelInfo})))
674+
t.Cleanup(func() {
675+
slog.SetDefault(original)
676+
})
677+
678+
if err := registry.Initialize(context.Background()); err != nil {
679+
t.Fatalf("Initialize() error = %v", err)
680+
}
681+
682+
logs := buf.String()
683+
if got := strings.Count(logs, `"msg":"enriched models with metadata"`); got != 0 {
684+
t.Fatalf("expected no standalone enrichment info logs, got %d:\n%s", got, logs)
685+
}
686+
if got := strings.Count(logs, `"msg":"model registry initialized"`); got != 1 {
687+
t.Fatalf("expected one initialization summary log, got %d:\n%s", got, logs)
688+
}
689+
if !strings.Contains(logs, `"metadata_enriched":2`) {
690+
t.Fatalf("expected initialization log to include metadata_enriched=2:\n%s", logs)
691+
}
692+
if !strings.Contains(logs, `"metadata_total":2`) {
693+
t.Fatalf("expected initialization log to include metadata_total=2:\n%s", logs)
694+
}
695+
if !strings.Contains(logs, `"metadata_providers":2`) {
696+
t.Fatalf("expected initialization log to include metadata_providers=2:\n%s", logs)
697+
}
698+
}
699+
611700
func TestListModelsWithProvider_Empty(t *testing.T) {
612701
registry := NewModelRegistry()
613702
models := registry.ListModelsWithProvider()

0 commit comments

Comments
 (0)