From 5297fd3c8495d80fab97ae511553fa545c69e913 Mon Sep 17 00:00:00 2001 From: Hamed Date: Fri, 13 Nov 2026 22:25:21 +0330 Subject: [PATCH] perf(logging): aggregate disabled-client logs in Xray config generation (#7055) GetXrayConfig logged one INFO line for every client whose traffic row is disabled, on every config generation: each reconcile, restart and node traffic sync, changed or not. With a few thousand expired clients that flooded the journal and pushed everything else out of the panel's in-memory log buffer. The line also said "Remove Inbound User", although nothing is removed there; the client is only left out of the config being built. A successful generation now writes one summary with the number of excluded client entries and affected inbounds, and a failed one writes none. The filter and the generated config are unchanged. Closes #7054 --- internal/web/service/xray.go | 10 +- .../web/service/xray_config_clients_test.go | 154 ++++++++++++++++++ .../web/service/xray_config_scale_test.go | 47 ++++++ 3 files changed, 210 insertions(+), 1 deletion(-) diff --git a/internal/web/service/xray.go b/internal/web/service/xray.go index 02760b311..1109dc9c2 100644 --- a/internal/web/service/xray.go +++ b/internal/web/service/xray.go @@ -204,6 +204,7 @@ func (s *XrayService) GetXrayConfig() (*xray.Config, error) { if err != nil { return nil, err } + excludedClients, excludedInbounds := 0, 0 for _, inbound := range inbounds { if !inbound.Enable { continue @@ -248,10 +249,11 @@ func (s *XrayService) GetXrayConfig() (*xray.Config, error) { finalClients := make([]any, 0, len(dbClients)) var wgPeers []any + excludedBefore := excludedClients for i := range dbClients { c := dbClients[i] if enable, exists := enableMap[c.Email]; exists && !enable { - logger.Infof("Remove Inbound User %s due to expiration or traffic limit", c.Email) + excludedClients++ continue } if !c.Enable { @@ -320,6 +322,9 @@ func (s *XrayService) GetXrayConfig() (*xray.Config, error) { } finalClients = append(finalClients, entry) } + if excludedClients > excludedBefore { + excludedInbounds++ + } var mutated bool if inbound.Protocol == model.WireGuard { @@ -491,6 +496,9 @@ func (s *XrayService) GetXrayConfig() (*xray.Config, error) { xrayConfig.RouterConfig = dropRefusedScript(xrayConfig.RouterConfig, "routing", routingScriptRefused) xrayConfig.DNSConfig = dropRefusedScript(xrayConfig.DNSConfig, "dns", dnsScriptRefused) + if excludedClients > 0 { + logger.Infof("Xray config generated: excluded %d disabled client entries across %d inbounds", excludedClients, excludedInbounds) + } return xrayConfig, nil } diff --git a/internal/web/service/xray_config_clients_test.go b/internal/web/service/xray_config_clients_test.go index 585d60b25..7f4e72542 100644 --- a/internal/web/service/xray_config_clients_test.go +++ b/internal/web/service/xray_config_clients_test.go @@ -2,13 +2,167 @@ package service import ( "encoding/json" + "fmt" + "strings" "testing" "github.com/mhsanaei/3x-ui/v3/internal/database" "github.com/mhsanaei/3x-ui/v3/internal/database/model" + "github.com/mhsanaei/3x-ui/v3/internal/logger" "github.com/mhsanaei/3x-ui/v3/internal/xray" ) +func TestGetXrayConfig_AggregatesExcludedClientLogs(t *testing.T) { + for _, tc := range []struct { + name string + clients int + inbounds int + excluded int + affected int + shared bool + }{ + {"2000 excluded entries", 2000, 5, 2000, 5, false}, + {"mixed clients and inbounds", 8, 4, 3, 2, false}, + {"no excluded entries", 8, 4, 0, 0, false}, + {"shared client counts as two entries", 4, 2, 1, 2, true}, + } { + t.Run(tc.name, func(t *testing.T) { + setupSettingTestDB(t) + ds := seedScaleDataset(t, tc.clients, tc.inbounds) + excluded := make(map[string]bool, tc.excluded) + for _, email := range ds.emails[:tc.excluded] { + excluded[email] = true + } + if tc.shared { + var record model.ClientRecord + if err := database.GetDB().Where("email = ?", ds.emails[0]).First(&record).Error; err != nil { + t.Fatal(err) + } + if err := database.GetDB().Create(&model.ClientInbound{ClientId: record.Id, InboundId: ds.inboundIds[1]}).Error; err != nil { + t.Fatal(err) + } + } + // Manual disablement is a separate filter and must not inflate the summary. + if tc.excluded < tc.clients { + disableClients(t, ds.emails[tc.clients-1]) + } + svc := &XrayService{} + want, err := svc.GetXrayConfig() + if err != nil { + t.Fatal(err) + } + for i, tag := range ds.tags { + clients := make([]map[string]string, 0) + for _, client := range ds.perInbound[i] { + if !excluded[client.Email] && client.Email != ds.emails[tc.clients-1] { + clients = append(clients, map[string]string{"email": client.Email, "id": client.ID}) + } + } + for k := range want.InboundConfigs { + if want.InboundConfigs[k].Tag == tag { + settings, err := json.MarshalIndent(map[string]any{"clients": clients}, "", " ") + if err != nil { + t.Fatal(err) + } + want.InboundConfigs[k].Settings = settings + } + } + } + wantJSON, err := json.Marshal(want) + if err != nil { + t.Fatal(err) + } + if tc.excluded > 0 { + if err := database.GetDB().Model(&xray.ClientTraffic{}). + Where("email IN ?", ds.emails[:tc.excluded]).Update("enable", false).Error; err != nil { + t.Fatal(err) + } + } + for generation := range 2 { + marker := fmt.Sprintf("%s generation %d", t.Name(), generation) + logger.Info(marker) + got, err := svc.GetXrayConfig() + if err != nil { + t.Fatal(err) + } + gotJSON, err := json.Marshal(got) + if err != nil { + t.Fatal(err) + } + if string(gotJSON) != string(wantJSON) { + t.Fatal("generated config changed beyond the expected client exclusions") + } + infoCount := 0 + foundMarker := false + for _, line := range logger.GetLogs(10000, "DEBUG") { + if strings.HasSuffix(line, " INFO - "+marker) { + foundMarker = true + break + } + if strings.Contains(line, "Remove Inbound User") || strings.Contains(line, "@scale") { + t.Fatalf("per-client log emitted: %s", line) + } + for _, clients := range ds.perInbound { + for _, client := range clients { + if strings.Contains(line, client.ID) || strings.Contains(line, client.SubID) { + t.Error("client credential or subscription ID leaked into logs") + } + } + } + if strings.Contains(line, " INFO - ") { + infoCount++ + entries := tc.excluded + if tc.shared { + entries++ + } + message := fmt.Sprintf(" INFO - Xray config generated: excluded %d disabled client entries across %d inbounds", entries, tc.affected) + if !strings.HasSuffix(line, message) { + t.Errorf("unexpected INFO entry: %s", line) + } + } + } + wantCount := 0 + if tc.excluded > 0 { + wantCount = 1 + } + if !foundMarker || infoCount != wantCount { + t.Errorf("generation %d: marker found = %v, INFO entries = %d, want %d", generation, foundMarker, infoCount, wantCount) + } + } + }) + } +} + +func TestGetXrayConfig_FailureDoesNotLogExclusionSummary(t *testing.T) { + setupSettingTestDB(t) + ds := seedScaleDataset(t, 1, 1) + db := database.GetDB() + if err := db.Model(&xray.ClientTraffic{}).Where("email = ?", ds.emails[0]).Update("enable", false).Error; err != nil { + t.Fatal(err) + } + if err := db.Model(&model.Inbound{}).Where("id = ?", ds.inboundIds[0]). + Update("stream_settings", `{"network":"tcp","security":"tls","tlsSettings":{}}`).Error; err != nil { + t.Fatal(err) + } + if err := db.Migrator().DropTable(&model.InboundFallback{}); err != nil { + t.Fatal(err) + } + logger.Info(t.Name()) + cfg, err := (&XrayService{}).GetXrayConfig() + if cfg != nil || err == nil || err.Error() != "no such table: inbound_fallbacks" { + t.Fatalf("GetXrayConfig = %v, %v; want missing fallback table failure", cfg, err) + } + for _, line := range logger.GetLogs(100, "DEBUG") { + if strings.HasSuffix(line, " INFO - "+t.Name()) { + return + } + if strings.Contains(line, "Xray config generated:") || strings.Contains(line, "Remove Inbound User") { + t.Fatalf("failed generation logged a successful summary or per-client removal: %s", line) + } + } + t.Fatal("log boundary not found") +} + func seedVlessInbound(t *testing.T, tag string, port int, clients []model.Client) { t.Helper() setupSettingTestDB(t) diff --git a/internal/web/service/xray_config_scale_test.go b/internal/web/service/xray_config_scale_test.go index 6a0433f1f..e0d8c0107 100644 --- a/internal/web/service/xray_config_scale_test.go +++ b/internal/web/service/xray_config_scale_test.go @@ -3,13 +3,60 @@ package service import ( "encoding/json" "fmt" + "strings" "testing" "time" "github.com/mhsanaei/3x-ui/v3/internal/database" "github.com/mhsanaei/3x-ui/v3/internal/database/model" + "github.com/mhsanaei/3x-ui/v3/internal/logger" + "github.com/mhsanaei/3x-ui/v3/internal/xray" ) +func BenchmarkGetXrayConfigDisabledClients(b *testing.B) { + b.Setenv("XUI_LOG_FOLDER", b.TempDir()) + setupScaleDB(b) + b.Cleanup(logger.CloseLogger) + seedScaleDataset(b, 2000, 5) + db := database.GetDB() + // Fix the generated credentials and lifecycle values for before/after comparisons. + if err := db.Model(&model.ClientRecord{}).Where("id > 0"). + Updates(map[string]any{"uuid": "11111111-1111-1111-1111-111111111111", "expiry_time": 0}).Error; err != nil { + b.Fatal(err) + } + if err := db.Model(&model.Inbound{}).Where("id > 0").Update("settings", `{"clients":[]}`).Error; err != nil { + b.Fatal(err) + } + if err := db.Model(&xray.ClientTraffic{}).Where("id > 0"). + Updates(map[string]any{"enable": false, "expiry_time": 0}).Error; err != nil { + b.Fatal(err) + } + svc := &XrayService{} + b.ReportAllocs() + b.ResetTimer() + for range b.N { + if _, err := svc.GetXrayConfig(); err != nil { + b.Fatal(err) + } + } + b.StopTimer() + const marker = "disabled-client benchmark log boundary" + logger.Info(marker) + if _, err := svc.GetXrayConfig(); err != nil { + b.Fatal(err) + } + entries, bytes := 0, 0 + for _, line := range logger.GetLogs(10000, "DEBUG") { + if strings.HasSuffix(line, " INFO - "+marker) { + break + } + entries++ + bytes += len(line) + 1 + } + b.ReportMetric(float64(entries), "logs/op") + b.ReportMetric(float64(bytes), "buffered-log-bytes/op") +} + // TestGetXrayConfigScale measures building the full Xray config (the path // every restart/reconcile takes) and, separately, how much of the per-inbound // settings rebuild is spent on indented vs plain JSON marshaling.