From 192888f9b1df18bbfb3bd1c6ca115df10fae682f Mon Sep 17 00:00:00 2001 From: hkfires <10558748+hkfires@users.noreply.github.com> Date: Thu, 25 Jun 2026 20:51:20 +0800 Subject: [PATCH] feat(pluginhost): enhance logging with plugin name and path fields --- .../api/handlers/management/plugin_store.go | 1 + internal/logging/global_logger.go | 12 ++- internal/logging/global_logger_test.go | 46 +++++++++ internal/pluginhost/host.go | 39 ++++---- internal/pluginhost/host_test.go | 95 +++++++++++++++++++ internal/pluginhost/logging.go | 28 ++++++ internal/pluginhost/logging_test.go | 34 +++++++ internal/pluginhost/platform.go | 6 +- 8 files changed, 238 insertions(+), 23 deletions(-) create mode 100644 internal/pluginhost/logging.go create mode 100644 internal/pluginhost/logging_test.go diff --git a/internal/api/handlers/management/plugin_store.go b/internal/api/handlers/management/plugin_store.go index 097f00482..d83eb8144 100644 --- a/internal/api/handlers/management/plugin_store.go +++ b/internal/api/handlers/management/plugin_store.go @@ -253,6 +253,7 @@ func (h *Handler) installPluginFromStore(c *gin.Context, goos, goarch string) { h.reloadConfigAfterManagementSaveAsync(c.Request.Context(), cfgSnapshot) log.WithFields(log.Fields{ "plugin_id": result.ID, + "plugin_name": plugin.Name, "source_id": source.ID, "version": result.Version, "path": result.Path, diff --git a/internal/logging/global_logger.go b/internal/logging/global_logger.go index 0fe621a3c..2038a0128 100644 --- a/internal/logging/global_logger.go +++ b/internal/logging/global_logger.go @@ -30,7 +30,12 @@ var ( type LogFormatter struct{} // logFieldOrder defines the display order for common log fields. -var logFieldOrder = []string{"provider", "model", "version", "mode", "budget", "level", "original_mode", "original_value", "min", "max", "clamped_to", "error"} +var logFieldOrder = []string{ + "provider", "model", + "plugin_id", "plugin_name", "source_id", + "version", "overwritten", + "mode", "budget", "level", "original_mode", "original_value", "min", "max", "clamped_to", "error", +} // Format renders a single log entry with custom formatting. func (m *LogFormatter) Format(entry *log.Entry) ([]byte, error) { @@ -64,6 +69,11 @@ func (m *LogFormatter) Format(entry *log.Entry) ([]byte, error) { fields = append(fields, fmt.Sprintf("%s=%v", k, v)) } } + if pluginID, ok := entry.Data["plugin_id"]; ok && strings.TrimSpace(fmt.Sprint(pluginID)) != "" { + if v, ok := entry.Data["path"]; ok { + fields = append(fields, fmt.Sprintf("path=%v", v)) + } + } if len(fields) > 0 { fieldsStr = " " + strings.Join(fields, " ") } diff --git a/internal/logging/global_logger_test.go b/internal/logging/global_logger_test.go index a90bf404f..f041e3dc0 100644 --- a/internal/logging/global_logger_test.go +++ b/internal/logging/global_logger_test.go @@ -25,3 +25,49 @@ func TestLogFormatterPrintsVersionField(t *testing.T) { t.Fatalf("formatted line %q missing version field", line) } } + +func TestLogFormatterPrintsPluginFields(t *testing.T) { + entry := log.NewEntry(log.New()) + entry.Time = time.Date(2026, 6, 25, 20, 10, 0, 0, time.Local) + entry.Level = log.InfoLevel + entry.Message = "pluginhost: plugin loaded" + entry.Data["plugin_id"] = "sample-provider" + entry.Data["plugin_name"] = "Sample Provider" + entry.Data["version"] = "0.2.0" + entry.Data["path"] = "plugins/windows/amd64/sample-provider-v0.2.0.dll" + + formatted, errFormat := (&LogFormatter{}).Format(entry) + if errFormat != nil { + t.Fatalf("Format() error = %v", errFormat) + } + + line := string(formatted) + for _, want := range []string{ + "plugin_id=sample-provider", + "plugin_name=Sample Provider", + "version=0.2.0", + "path=plugins/windows/amd64/sample-provider-v0.2.0.dll", + } { + if !strings.Contains(line, want) { + t.Fatalf("formatted line %q missing %s", line, want) + } + } +} + +func TestLogFormatterOmitsGenericPathField(t *testing.T) { + entry := log.NewEntry(log.New()) + entry.Time = time.Date(2026, 6, 25, 20, 20, 0, 0, time.Local) + entry.Level = log.WarnLevel + entry.Message = "failed to roll back token" + entry.Data["path"] = "auths/private-token.json" + + formatted, errFormat := (&LogFormatter{}).Format(entry) + if errFormat != nil { + t.Fatalf("Format() error = %v", errFormat) + } + + line := string(formatted) + if strings.Contains(line, "path=") { + t.Fatalf("formatted line %q contains generic path field", line) + } +} diff --git a/internal/pluginhost/host.go b/internal/pluginhost/host.go index 259d0dc8e..082632687 100644 --- a/internal/pluginhost/host.go +++ b/internal/pluginhost/host.go @@ -21,6 +21,7 @@ type loadedPlugin struct { id string path string version string + name string registered bool client pluginClient } @@ -32,6 +33,7 @@ type modelExecutor interface { type pluginUnloadTarget struct { id string + name string path string version string client pluginClient @@ -235,6 +237,7 @@ func (h *Host) ApplyConfig(ctx context.Context, cfg *config.Config) { continue } + loadedNow := false if lp == nil { h.mu.Lock() h.loading[file.ID] = struct{}{} @@ -257,12 +260,9 @@ func (h *Host) ApplyConfig(ctx context.Context, cfg *config.Config) { h.removePluginRuntimeStateLocked(file.ID) } h.loaded[file.ID] = lp + loadedNow = true h.mu.Unlock() - log.WithFields(log.Fields{ - "plugin_id": file.ID, - "version": file.Version, - "path": file.Path, - }).Info("pluginhost: plugin loaded") + log.WithFields(pluginLogFields(file.ID, "", file.Version, file.Path)).Info("pluginhost: plugin loaded") } plugin, okCall := h.callRegister(ctx, lp, item) @@ -270,6 +270,17 @@ func (h *Host) ApplyConfig(ctx context.Context, cfg *config.Config) { continue } plugin.Metadata = clonePluginMetadata(plugin.Metadata) + h.mu.Lock() + if lp != nil { + lp.name = strings.TrimSpace(plugin.Metadata.Name) + if strings.TrimSpace(lp.version) == "" { + lp.version = strings.TrimSpace(plugin.Metadata.Version) + } + } + h.mu.Unlock() + if loadedNow { + log.WithFields(pluginLogFieldsFromMetadata(file.ID, plugin.Metadata, file.Path)).Info("pluginhost: plugin registered") + } records = append(records, capabilityRecord{ id: file.ID, path: file.Path, @@ -329,13 +340,13 @@ func (h *Host) UnloadPlugin(id string) bool { h.mu.Lock() lp := h.loaded[id] if lp != nil { - targets = append(targets, pluginUnloadTarget{id: lp.id, path: lp.path, version: lp.version, client: lp.client}) + targets = append(targets, pluginUnloadTarget{id: lp.id, name: lp.name, path: lp.path, version: lp.version, client: lp.client}) } for _, retired := range h.retired[id] { if retired == nil { continue } - targets = append(targets, pluginUnloadTarget{id: retired.id, path: retired.path, version: retired.version, client: retired.client}) + targets = append(targets, pluginUnloadTarget{id: retired.id, name: retired.name, path: retired.path, version: retired.version, client: retired.client}) } if len(targets) == 0 { h.mu.Unlock() @@ -360,11 +371,7 @@ func (h *Host) UnloadPlugin(id string) bool { if target.client != nil { target.client.Shutdown() } - log.WithFields(log.Fields{ - "plugin_id": target.id, - "version": target.version, - "path": target.path, - }).Info("pluginhost: plugin unloaded") + log.WithFields(pluginLogFields(target.id, target.name, target.version, target.path)).Info("pluginhost: plugin unloaded") } return true } @@ -386,6 +393,7 @@ func (h *Host) ShutdownAll() { } targets = append(targets, pluginUnloadTarget{ id: lp.id, + name: lp.name, path: lp.path, version: lp.version, client: lp.client, @@ -398,6 +406,7 @@ func (h *Host) ShutdownAll() { } targets = append(targets, pluginUnloadTarget{ id: lp.id, + name: lp.name, path: lp.path, version: lp.version, client: lp.client, @@ -427,11 +436,7 @@ func (h *Host) ShutdownAll() { h.RegisterFrontendAuthProviders() for _, target := range targets { target.client.Shutdown() - log.WithFields(log.Fields{ - "plugin_id": target.id, - "version": target.version, - "path": target.path, - }).Info("pluginhost: plugin unloaded") + log.WithFields(pluginLogFields(target.id, target.name, target.version, target.path)).Info("pluginhost: plugin unloaded") } } diff --git a/internal/pluginhost/host_test.go b/internal/pluginhost/host_test.go index 726089f62..d1a2d1764 100644 --- a/internal/pluginhost/host_test.go +++ b/internal/pluginhost/host_test.go @@ -1,9 +1,11 @@ package pluginhost import ( + "bytes" "context" "encoding/json" "net/http" + "strings" "sync" "sync/atomic" "testing" @@ -13,6 +15,7 @@ import ( "github.com/router-for-me/CLIProxyAPI/v7/internal/thinking" "github.com/router-for-me/CLIProxyAPI/v7/sdk/pluginabi" "github.com/router-for-me/CLIProxyAPI/v7/sdk/pluginapi" + log "github.com/sirupsen/logrus" "github.com/tidwall/gjson" ) @@ -553,6 +556,98 @@ func TestHostApplyConfig_ReconfigureCalledOnReload(t *testing.T) { } } +func TestHostApplyConfigLogsLoadedAndRegisteredOnlyOnInitialLoad(t *testing.T) { + var out bytes.Buffer + originalOut := log.StandardLogger().Out + originalFormatter := log.StandardLogger().Formatter + originalLevel := log.GetLevel() + log.SetOutput(&out) + log.SetFormatter(&log.TextFormatter{ + DisableColors: true, + DisableTimestamp: true, + }) + log.SetLevel(log.InfoLevel) + t.Cleanup(func() { + log.SetOutput(originalOut) + log.SetFormatter(originalFormatter) + log.SetLevel(originalLevel) + }) + + loader := newTestSymbolLoader() + plugin := &testPlugin{ + registerResult: validTestPlugin("alpha"), + reconfigureResult: validTestPlugin("alpha"), + } + loader.lookups["alpha"] = newTestSymbolLookup(plugin) + h := NewForTest(loader) + t.Cleanup(h.ShutdownAll) + cfg := &config.Config{ + Plugins: config.PluginsConfig{ + Enabled: true, + Dir: makePluginDir(t, "alpha"), + Configs: enabledPluginConfigs("alpha"), + }, + } + + h.ApplyConfig(context.Background(), cfg) + h.ApplyConfig(context.Background(), cfg) + + logs := out.String() + if count := strings.Count(logs, `msg="pluginhost: plugin loaded"`); count != 1 { + t.Fatalf("plugin loaded log count = %d, want 1\n%s", count, logs) + } + if count := strings.Count(logs, `msg="pluginhost: plugin registered"`); count != 1 { + t.Fatalf("plugin registered log count = %d, want 1\n%s", count, logs) + } + if !strings.Contains(logs, "plugin_name=alpha") { + t.Fatalf("plugin registered log missing plugin_name:\n%s", logs) + } + if !strings.Contains(logs, "path=") { + t.Fatalf("plugin logs missing path:\n%s", logs) + } +} + +func TestHostApplyConfigLogsLoadedWhenRegistrationInvalid(t *testing.T) { + var out bytes.Buffer + originalOut := log.StandardLogger().Out + originalFormatter := log.StandardLogger().Formatter + originalLevel := log.GetLevel() + log.SetOutput(&out) + log.SetFormatter(&log.TextFormatter{ + DisableColors: true, + DisableTimestamp: true, + }) + log.SetLevel(log.InfoLevel) + t.Cleanup(func() { + log.SetOutput(originalOut) + log.SetFormatter(originalFormatter) + log.SetLevel(originalLevel) + }) + + loader := newTestSymbolLoader() + loader.lookups["empty-name"] = newTestSymbolLookup(&testPlugin{ + registerResult: validTestPlugin(""), + }) + h := NewForTest(loader) + t.Cleanup(h.ShutdownAll) + + h.ApplyConfig(context.Background(), &config.Config{ + Plugins: config.PluginsConfig{ + Enabled: true, + Dir: makePluginDir(t, "empty-name"), + Configs: enabledPluginConfigs("empty-name"), + }, + }) + + logs := out.String() + if count := strings.Count(logs, `msg="pluginhost: plugin loaded"`); count != 1 { + t.Fatalf("plugin loaded log count = %d, want 1\n%s", count, logs) + } + if strings.Contains(logs, `msg="pluginhost: plugin registered"`) { + t.Fatalf("plugin registered log emitted for invalid registration:\n%s", logs) + } +} + func TestRegisteredPluginsIncludesMetadataAndOAuthCapability(t *testing.T) { loader := newTestSymbolLoader() plugin := &testPlugin{ diff --git a/internal/pluginhost/logging.go b/internal/pluginhost/logging.go new file mode 100644 index 000000000..838573115 --- /dev/null +++ b/internal/pluginhost/logging.go @@ -0,0 +1,28 @@ +package pluginhost + +import ( + "strings" + + "github.com/router-for-me/CLIProxyAPI/v7/sdk/pluginapi" + log "github.com/sirupsen/logrus" +) + +func pluginLogFields(id, name, version, path string) log.Fields { + fields := log.Fields{ + "plugin_id": strings.TrimSpace(id), + } + if name = strings.TrimSpace(name); name != "" { + fields["plugin_name"] = name + } + if version = strings.TrimSpace(version); version != "" { + fields["version"] = version + } + if path = strings.TrimSpace(path); path != "" { + fields["path"] = path + } + return fields +} + +func pluginLogFieldsFromMetadata(id string, meta pluginapi.Metadata, path string) log.Fields { + return pluginLogFields(id, meta.Name, meta.Version, path) +} diff --git a/internal/pluginhost/logging_test.go b/internal/pluginhost/logging_test.go new file mode 100644 index 000000000..fd0c14609 --- /dev/null +++ b/internal/pluginhost/logging_test.go @@ -0,0 +1,34 @@ +package pluginhost + +import ( + "testing" + + "github.com/router-for-me/CLIProxyAPI/v7/sdk/pluginapi" +) + +func TestPluginLogFieldsIncludesNameVersionAndPath(t *testing.T) { + fields := pluginLogFieldsFromMetadata("sample", pluginapi.Metadata{ + Name: "Sample Provider", + Version: "0.2.0", + }, "/tmp/plugins/sample-v0.2.0.dll") + + if fields["plugin_id"] != "sample" { + t.Fatalf("plugin_id = %v, want sample", fields["plugin_id"]) + } + if fields["plugin_name"] != "Sample Provider" { + t.Fatalf("plugin_name = %v, want Sample Provider", fields["plugin_name"]) + } + if fields["version"] != "0.2.0" { + t.Fatalf("version = %v, want 0.2.0", fields["version"]) + } + if fields["path"] != "/tmp/plugins/sample-v0.2.0.dll" { + t.Fatalf("path = %v, want /tmp/plugins/sample-v0.2.0.dll", fields["path"]) + } +} + +func TestPluginLogFieldsOmitsEmptyName(t *testing.T) { + fields := pluginLogFields("sample", "", "0.2.0", "") + if _, ok := fields["plugin_name"]; ok { + t.Fatalf("plugin_name = %v, want omitted", fields["plugin_name"]) + } +} diff --git a/internal/pluginhost/platform.go b/internal/pluginhost/platform.go index a5a81d0d3..7d43c86d3 100644 --- a/internal/pluginhost/platform.go +++ b/internal/pluginhost/platform.go @@ -252,11 +252,7 @@ func cleanupUnselectedPluginFiles(root string, loaded []pluginFile) error { log.WithError(errRemove).Warnf("pluginhost: failed to remove old plugin file %s", candidate.Path) continue } - log.WithFields(log.Fields{ - "plugin_id": candidate.ID, - "version": candidate.Version, - "path": candidate.Path, - }).Info("pluginhost: old plugin file removed") + log.WithFields(pluginLogFields(candidate.ID, "", candidate.Version, candidate.Path)).Info("pluginhost: old plugin file removed") } return errors.Join(errs...) }