feat(pluginhost): enhance logging with plugin name and path fields

This commit is contained in:
hkfires
2026-06-25 20:51:20 +08:00
parent 29b53434b2
commit 192888f9b1
8 changed files with 238 additions and 23 deletions

View File

@@ -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,

View File

@@ -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, " ")
}

View File

@@ -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)
}
}

View File

@@ -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")
}
}

View File

@@ -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{

View File

@@ -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)
}

View File

@@ -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"])
}
}

View File

@@ -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...)
}