diff --git a/cluster/utils/adaptivesvc.go b/cluster/utils/adaptivesvc.go index e92f549ece..03529cb394 100644 --- a/cluster/utils/adaptivesvc.go +++ b/cluster/utils/adaptivesvc.go @@ -35,12 +35,12 @@ func DoesAdaptiveServiceReachLimitation(err error) bool { if err == nil { return false } - return err.Error() == ReachLimitationErrorString + return strings.HasSuffix(err.Error(), ReachLimitationErrorString) } func IsAdaptiveServiceFailed(err error) bool { if err == nil { return false } - return strings.HasPrefix(err.Error(), adaptivesvc.ErrAdaptiveSvcInterrupted.Error()) + return strings.Contains(err.Error(), adaptivesvc.ErrAdaptiveSvcInterrupted.Error()) } diff --git a/cluster/utils/adaptivesvc_test.go b/cluster/utils/adaptivesvc_test.go new file mode 100644 index 0000000000..9a6faa618c --- /dev/null +++ b/cluster/utils/adaptivesvc_test.go @@ -0,0 +1,41 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package utils + +import ( + "errors" + "testing" +) + +import ( + "github.com/stretchr/testify/assert" +) + +func TestDoesAdaptiveServiceReachLimitation(t *testing.T) { + assert.False(t, DoesAdaptiveServiceReachLimitation(nil)) + assert.True(t, DoesAdaptiveServiceReachLimitation(errors.New(ReachLimitationErrorString))) + assert.True(t, DoesAdaptiveServiceReachLimitation(errors.New("unknown: "+ReachLimitationErrorString))) + assert.False(t, DoesAdaptiveServiceReachLimitation(errors.New("adaptive service interrupted: another error"))) +} + +func TestIsAdaptiveServiceFailed(t *testing.T) { + assert.False(t, IsAdaptiveServiceFailed(nil)) + assert.True(t, IsAdaptiveServiceFailed(errors.New("adaptive service interrupted: reach limitation"))) + assert.True(t, IsAdaptiveServiceFailed(errors.New("unknown: adaptive service interrupted: reach limitation"))) + assert.False(t, IsAdaptiveServiceFailed(errors.New("unavailable: network error"))) +} diff --git a/filter/adaptivesvc/filter.go b/filter/adaptivesvc/filter.go index 6bb146073e..eb40ab0f95 100644 --- a/filter/adaptivesvc/filter.go +++ b/filter/adaptivesvc/filter.go @@ -99,16 +99,8 @@ func (f *adaptiveServiceProviderFilter) Invoke(ctx context.Context, invoker base func (f *adaptiveServiceProviderFilter) OnResponse(_ context.Context, res result.Result, invoker base.Invoker, invocation base.Invocation) result.Result { - var asEnabled string - asEnabledIface := res.Attachment(constant.AdaptiveServiceEnabledKey, nil) - if asEnabledIface != nil { - if str, strOK := asEnabledIface.(string); strOK { - asEnabled = str - } else if strArr, strArrOK := asEnabledIface.([]string); strArrOK && len(strArr) > 0 { - asEnabled = strArr[0] - } - } - if asEnabled != constant.AdaptiveServiceIsEnabled { + if invocation.GetAttachmentWithDefaultValue(constant.AdaptiveServiceEnabledKey, "") != + constant.AdaptiveServiceIsEnabled { // the adaptive service is enabled on the invocation return res } diff --git a/filter/adaptivesvc/filter_test.go b/filter/adaptivesvc/filter_test.go index 29eb2d8a5d..aa77955119 100644 --- a/filter/adaptivesvc/filter_test.go +++ b/filter/adaptivesvc/filter_test.go @@ -100,7 +100,9 @@ func TestAdaptiveServiceProviderFilter_OnResponse(t *testing.T) { }) t.Run("InterruptedErrorShouldSkip", func(t *testing.T) { - invoc := invocation.NewRPCInvocation(methodName, nil, nil) + invoc := invocation.NewRPCInvocation(methodName, nil, map[string]any{ + constant.AdaptiveServiceEnabledKey: constant.AdaptiveServiceIsEnabled, + }) res := &result.RPCResult{Err: wrapErrAdaptiveSvcInterrupted("limit exceeded")} invoker := mock.NewMockInvoker(ctrl) @@ -109,12 +111,13 @@ func TestAdaptiveServiceProviderFilter_OnResponse(t *testing.T) { }) t.Run("SuccessWithAttachments", func(t *testing.T) { - invoc := invocation.NewRPCInvocation(methodName, nil, nil) + invoc := invocation.NewRPCInvocation(methodName, nil, map[string]any{ + constant.AdaptiveServiceEnabledKey: constant.AdaptiveServiceIsEnabled, + }) updater := &mockUpdater{} invoc.SetAttribute(constant.AdaptiveServiceUpdaterKey, updater) res := &result.RPCResult{Rest: "ok"} - res.AddAttachment(constant.AdaptiveServiceEnabledKey, constant.AdaptiveServiceIsEnabled) invoker := mock.NewMockInvoker(ctrl) invoker.EXPECT().GetURL().Return(u).AnyTimes() diff --git a/filter/adaptivesvc/limiter/hill_climbing.go b/filter/adaptivesvc/limiter/hill_climbing.go index f14632d5b0..6a2c96fc99 100644 --- a/filter/adaptivesvc/limiter/hill_climbing.go +++ b/filter/adaptivesvc/limiter/hill_climbing.go @@ -107,6 +107,20 @@ func (l *HillClimbing) Remaining() uint64 { return limitation - inflight } +func (l *HillClimbing) Snapshot() Snapshot { + limitation := l.limitation.Load() + inflight := l.inflight.Load() + remaining := uint64(0) + if limitation >= inflight { + remaining = limitation - inflight + } + return Snapshot{ + Inflight: inflight, + Remaining: remaining, + Limitation: limitation, + } +} + func (l *HillClimbing) Acquire() (Updater, error) { if l.Remaining() == 0 { return nil, ErrReachLimitation diff --git a/filter/adaptivesvc/limiter/hill_climbing_test.go b/filter/adaptivesvc/limiter/hill_climbing_test.go index 24df9f4222..541173b2b2 100644 --- a/filter/adaptivesvc/limiter/hill_climbing_test.go +++ b/filter/adaptivesvc/limiter/hill_climbing_test.go @@ -88,3 +88,20 @@ func TestHillClimbing_Remaining(t *testing.T) { remaining = limiter.Remaining() assert.Equal(t, uint64(0), remaining) } + +func TestHillClimbing_Snapshot(t *testing.T) { + limiter := NewHillClimbing().(*HillClimbing) + limiter.limitation.Store(100) + limiter.inflight.Store(30) + + snapshot := limiter.Snapshot() + assert.Equal(t, uint64(100), snapshot.Limitation) + assert.Equal(t, uint64(30), snapshot.Inflight) + assert.Equal(t, uint64(70), snapshot.Remaining) + + limiter.inflight.Store(120) + snapshot = limiter.Snapshot() + assert.Equal(t, uint64(100), snapshot.Limitation) + assert.Equal(t, uint64(120), snapshot.Inflight) + assert.Equal(t, uint64(0), snapshot.Remaining) +} diff --git a/filter/adaptivesvc/limiter/limiter.go b/filter/adaptivesvc/limiter/limiter.go index 82424fc99a..e8c5536176 100644 --- a/filter/adaptivesvc/limiter/limiter.go +++ b/filter/adaptivesvc/limiter/limiter.go @@ -34,12 +34,19 @@ const ( type Limiter interface { Inflight() uint64 Remaining() uint64 + Snapshot() Snapshot // Acquire inspects the current status of the system: // - if reaches the limitation, reject the request immediately. // - if not, grant this request and return an Updater defined below. Acquire() (Updater, error) } +type Snapshot struct { + Inflight uint64 + Remaining uint64 + Limitation uint64 +} + type Updater interface { // DoUpdate is called once an invocation is finished, it tells Updater that the invocation is finished, and please // update the Remaining, Inflight parameters of the Limiter. diff --git a/filter/adaptivesvc/limiter_mapper.go b/filter/adaptivesvc/limiter_mapper.go index e9343ed6e1..0ac10b79b7 100644 --- a/filter/adaptivesvc/limiter_mapper.go +++ b/filter/adaptivesvc/limiter_mapper.go @@ -19,6 +19,7 @@ package adaptivesvc import ( "fmt" + "strings" "sync" ) @@ -51,7 +52,7 @@ func newLimiterMapper() *limiterMapper { } func (m *limiterMapper) newAndSetMethodLimiter(url *common.URL, methodName string, limiterType int) (limiter.Limiter, error) { - key := fmt.Sprintf("%s%s", url.Path, methodName) + key := methodLimiterKey(url.Path, methodName) var ( l limiter.Limiter @@ -75,7 +76,7 @@ func (m *limiterMapper) newAndSetMethodLimiter(url *common.URL, methodName strin func (m *limiterMapper) getMethodLimiter(url *common.URL, methodName string) ( limiter.Limiter, error) { - key := fmt.Sprintf("%s%s", url.Path, methodName) + key := methodLimiterKey(url.Path, methodName) m.rwMutex.RLock() l, ok := limiterMapperSingleton.mapper[key] m.rwMutex.RUnlock() @@ -84,3 +85,20 @@ func (m *limiterMapper) getMethodLimiter(url *common.URL, methodName string) ( } return l, nil } + +func GetMethodLimiterSnapshot(interfaceName string, methodName string) (limiter.Snapshot, bool) { + limiterMapperSingleton.rwMutex.RLock() + l, ok := limiterMapperSingleton.mapper[methodLimiterKey(interfaceName, methodName)] + if !ok && !strings.HasPrefix(interfaceName, "/") { + l, ok = limiterMapperSingleton.mapper[methodLimiterKey("/"+interfaceName, methodName)] + } + limiterMapperSingleton.rwMutex.RUnlock() + if !ok { + return limiter.Snapshot{}, false + } + return l.Snapshot(), true +} + +func methodLimiterKey(interfaceName string, methodName string) string { + return fmt.Sprintf("%s%s", interfaceName, methodName) +} diff --git a/filter/adaptivesvc/limiter_mapper_test.go b/filter/adaptivesvc/limiter_mapper_test.go index 51cddc787d..cc92956ae0 100644 --- a/filter/adaptivesvc/limiter_mapper_test.go +++ b/filter/adaptivesvc/limiter_mapper_test.go @@ -70,3 +70,43 @@ func TestLimiterMapper_getMethodLimiter(t *testing.T) { assert.Nil(t, l) assert.Equal(t, ErrLimiterNotFoundOnMapper, err) } + +func TestGetMethodLimiterSnapshot(t *testing.T) { + mapper := newLimiterMapper() + oldMapper := limiterMapperSingleton + limiterMapperSingleton = mapper + t.Cleanup(func() { + limiterMapperSingleton = oldMapper + }) + + url := &common.URL{Path: "/testService"} + methodName := "testMethod" + _, err := mapper.newAndSetMethodLimiter(url, methodName, limiter.HillClimbingLimiter) + require.NoError(t, err) + + snapshot, ok := GetMethodLimiterSnapshot(url.Path, methodName) + require.True(t, ok) + assert.Equal(t, uint64(50), snapshot.Limitation) + + snapshot, ok = GetMethodLimiterSnapshot("/unknownService", methodName) + assert.False(t, ok) + assert.Equal(t, limiter.Snapshot{}, snapshot) +} + +func TestGetMethodLimiterSnapshot_WithInterfaceNameWithoutLeadingSlash(t *testing.T) { + mapper := newLimiterMapper() + oldMapper := limiterMapperSingleton + limiterMapperSingleton = mapper + t.Cleanup(func() { + limiterMapperSingleton = oldMapper + }) + + url := &common.URL{Path: "/testService"} + methodName := "testMethod" + _, err := mapper.newAndSetMethodLimiter(url, methodName, limiter.HillClimbingLimiter) + require.NoError(t, err) + + snapshot, ok := GetMethodLimiterSnapshot("testService", methodName) + require.True(t, ok) + assert.Equal(t, uint64(50), snapshot.Limitation) +} diff --git a/graceful_shutdown/closing_registry.go b/graceful_shutdown/closing_registry.go index 66d91e9eff..35c0094ac6 100644 --- a/graceful_shutdown/closing_registry.go +++ b/graceful_shutdown/closing_registry.go @@ -142,10 +142,10 @@ func (h *closingEventHandler) HandleClosingEvent(event ClosingEvent) bool { defaultClosingAckTracker.record(event, removed) if isActiveClosingSource(event.Source) { if removed { - logger.Infof("Graceful shutdown --- Active closing ack handled, source=%s service=%s address=%s instance=%s", + logger.Infof("[GracefulShutdown] active closing ack handled, source=%s service=%s address=%s instance=%s", event.Source, event.ServiceKey, event.Address, event.InstanceKey) } else { - logger.Warnf("Graceful shutdown --- Active closing ack missed local directory, source=%s service=%s address=%s instance=%s", + logger.Warnf("[GracefulShutdown] active closing ack missed local directory, source=%s service=%s address=%s instance=%s", event.Source, event.ServiceKey, event.Address, event.InstanceKey) } } diff --git a/graceful_shutdown/common.go b/graceful_shutdown/common.go index 19bfc8d15b..a538ad7b16 100644 --- a/graceful_shutdown/common.go +++ b/graceful_shutdown/common.go @@ -38,7 +38,7 @@ func init() { func parseDuration(timeout string, desc string, def time.Duration) time.Duration { res, err := time.ParseDuration(timeout) if err != nil { - logger.Errorf("The %s configuration is invalid: %s, and we will use the default value: %s, err: %v", + logger.Errorf("[GracefulShutdown] the %s configuration is invalid: %s, and we will use the default value: %s, err=%v", desc, timeout, def.String(), err) res = def } diff --git a/graceful_shutdown/shutdown.go b/graceful_shutdown/shutdown.go index dba11298cb..7acfac3008 100644 --- a/graceful_shutdown/shutdown.go +++ b/graceful_shutdown/shutdown.go @@ -113,14 +113,14 @@ func Init(opts ...Option) { go func() { sig := <-signals - logger.Infof("get signal %s, applicationConfig will shutdown.", sig) + logger.Infof("[GracefulShutdown] get signal %s, applicationConfig will shutdown.", sig) // fallback timeout time.AfterFunc(totalTimeout(newOpts.Shutdown), func() { - logger.Warn("Shutdown gracefully timeout, applicationConfig will shutdown immediately. ") + logger.Warn("[GracefulShutdown] shutdown gracefully timeout, applicationConfig will shutdown immediately. ") os.Exit(0) }) if err := Shutdown(context.Background()); err != nil { - logger.Warnf("Graceful shutdown --- shutdown completed with error: %v", err) + logger.Warnf("[GracefulShutdown] shutdown completed, err=%v", err) } // those signals' original behavior is exit with dump ths stack, so we try to keep the behavior for _, dumpSignal := range DumpHeapShutdownSignals { @@ -185,7 +185,7 @@ func totalTimeout(shutdown *global.ShutdownConfig) time.Duration { func beforeShutdown(shutdown *global.ShutdownConfig) { // 1. mark closing state - logger.Info("Graceful shutdown --- Mark closing state.") + logger.Info("[GracefulShutdown] mark closing state.") shutdown.Closing.Store(true) probe.SetReady(false) @@ -217,7 +217,7 @@ func startShutdownOnce() { go func() { defer func() { if recovered := recover(); recovered != nil { - logger.Warnf("Graceful shutdown --- shutdown panicked --- %v", recovered) + logger.Warnf("[GracefulShutdown] shutdown panicked, err=%v", recovered) shutdownResult = fmt.Errorf("graceful shutdown panic: %v", recovered) } close(shutdownDone) @@ -233,10 +233,10 @@ func startShutdownOnce() { // unregisterRegistries unregisters exported services from registries during graceful shutdown. // If the registry protocol does not expose a narrower unregister capability, it falls back to Destroy. func unregisterRegistries() { - logger.Info("Graceful shutdown --- Unregister exported services from registries.") + logger.Info("[GracefulShutdown] unregister exported services from registries.") registryProtocol, ok := getProtocolSafely(constant.RegistryProtocol) if !ok { - logger.Warnf("Graceful shutdown --- Registry protocol %s is not registered, skip unregistering registries.", constant.RegistryProtocol) + logger.Warnf("[GracefulShutdown] registry protocol %s is not registered, skip unregistering registries.", constant.RegistryProtocol) return } @@ -245,13 +245,13 @@ func unregisterRegistries() { return } - logger.Warnf("Graceful shutdown --- Registry protocol %s does not support unregister-only shutdown, falling back to Destroy().", constant.RegistryProtocol) + logger.Warnf("[GracefulShutdown] registry protocol %s does not support unregister-only shutdown, falling back to Destroy().", constant.RegistryProtocol) registryProtocol.Destroy() } // notifyLongConnectionConsumers notifies all connected consumers via long connections func notifyLongConnectionConsumers(shutdown *global.ShutdownConfig) { - logger.Info("Graceful shutdown --- Notify long connection consumers.") + logger.Info("[GracefulShutdown] notify long connection consumers.") notifyTimeout := parseDuration(shutdown.NotifyTimeout, notifyTimeoutDesc, defaultNotifyTimeout) callbacks := extension.GracefulShutdownCallbacks() @@ -280,26 +280,26 @@ func notifyWithRetry(ctx context.Context, name string, callback extension.Gracef attempts++ err := invokeGracefulShutdownCallback(ctx, name, callback) if err == nil { - logger.Infof("Graceful shutdown --- Notify %s completed", name) + logger.Infof("[GracefulShutdown] notify %s completed", name) return nil } - logger.Warnf("Graceful shutdown --- Notify %s attempt %d failed --- %v", name, attempts, err) + logger.Warnf("[GracefulShutdown] notify %s attempt %d failed, err=%v", name, attempts, err) return err } notify := func(err error, delay time.Duration) { - logger.Infof("Graceful shutdown --- Notify %s retrying in %v (attempt %d/%d)", name, delay, attempts, defaultMaxRetries) + logger.Infof("[GracefulShutdown] notify %s retrying in %v (attempt %d/%d)", name, delay, attempts, defaultMaxRetries) } retryPolicy := backoff.WithContext(backoff.WithMaxRetries(backOff, uint64(defaultMaxRetries)), ctx) if err := backoff.RetryNotify(operation, retryPolicy, notify); err != nil { if ctx.Err() != nil { - logger.Warnf("Graceful shutdown --- Notify %s timeout after %d attempts, continuing...", name, attempts) + logger.Warnf("[GracefulShutdown] notify %s timeout after %d attempts, continuing...", name, attempts) return } - logger.Warnf("Graceful shutdown --- Notify %s failed after %d attempts --- %v", name, attempts, err) + logger.Warnf("[GracefulShutdown] notify %s failed after %d attempts, err=%v", name, attempts, err) } } @@ -308,7 +308,7 @@ func invokeGracefulShutdownCallback(ctx context.Context, name string, callback e go func() { defer func() { if recovered := recover(); recovered != nil { - logger.Warnf("Graceful shutdown --- Notify %s panicked --- %v", name, recovered) + logger.Warnf("[GracefulShutdown] notify %s panicked, err=%v", name, recovered) done <- fmt.Errorf("graceful shutdown callback panic: %v", recovered) } }() @@ -324,7 +324,7 @@ func invokeGracefulShutdownCallback(ctx context.Context, name string, callback e } func waitAndAcceptNewRequests(shutdown *global.ShutdownConfig) { - logger.Info("Graceful shutdown --- Keep waiting and accept new requests for a short time. ") + logger.Info("[GracefulShutdown] keep waiting and accept new requests for a short time. ") updateWaitTime := parseDuration(shutdown.ConsumerUpdateWaitTime, consumerUpdateWaitTimeDesc, defaultConsumerUpdateWaitTime) time.Sleep(updateWaitTime) @@ -347,14 +347,14 @@ func waitingProviderProcessedTimeout(shutdown *global.ShutdownConfig, timeout ti (shutdown.ProviderActiveCount.Load() > 0 || time.Now().Before(shutdown.ProviderLastReceivedRequestTime.Load().Add(offlineRequestWindowTimeout))) { // sleep 10 ms and then we check it again time.Sleep(10 * time.Millisecond) - logger.Infof("waiting for provider active invocation count = %d, provider last received request time: %v", + logger.Infof("[GracefulShutdown] waiting for provider active invocation count = %d, provider last received request time=%v", shutdown.ProviderActiveCount.Load(), shutdown.ProviderLastReceivedRequestTime.Load()) } } // For provider. It will wait for processing receiving requests func waitForSendingAndReceivingRequests(shutdown *global.ShutdownConfig) { - logger.Info("Graceful shutdown --- Keep waiting until sending/accepting requests finish or timeout. ") + logger.Info("[GracefulShutdown] keep waiting until sending/accepting requests finish or timeout. ") shutdown.RejectRequest.Store(true) waitingConsumerProcessedTimeout(shutdown) } @@ -370,18 +370,18 @@ func waitingConsumerProcessedTimeout(shutdown *global.ShutdownConfig) { for time.Now().Before(deadline) && shutdown.ConsumerActiveCount.Load() > 0 { // sleep 10 ms and then we check it again time.Sleep(10 * time.Millisecond) - logger.Infof("waiting for consumer active invocation count = %d", shutdown.ConsumerActiveCount.Load()) + logger.Infof("[GracefulShutdown] waiting for consumer active invocation count = %d", shutdown.ConsumerActiveCount.Load()) } } // destroyProtocols destroys protocols that have been registered. func destroyProtocols() { - logger.Info("Graceful shutdown --- Destroy protocols. ") + logger.Info("[GracefulShutdown] destroy protocols. ") for _, name := range registeredProtocolsSnapshot() { protocol, ok := getProtocolSafely(name) if !ok { - logger.Warnf("Graceful shutdown --- Protocol %s is not registered, skip destroying it.", name) + logger.Warnf("[GracefulShutdown] protocol %s is not registered, skip destroying it.", name) continue } protocol.Destroy() @@ -400,7 +400,7 @@ func registeredProtocolsSnapshot() []string { } func executeCustomShutdownCallbacks(shutdown *global.ShutdownConfig) { - logger.Info("Graceful shutdown --- Execute the custom callbacks.") + logger.Info("[GracefulShutdown] execute the custom callbacks.") callbackTimeout := totalTimeout(shutdown) customCallbacks := extension.GetAllCustomShutdownCallbacks() for callback := customCallbacks.Front(); callback != nil; callback = callback.Next() { @@ -413,7 +413,7 @@ func invokeCustomShutdownCallback(timeout time.Duration, callback func()) { go func() { defer func() { if recovered := recover(); recovered != nil { - logger.Warnf("Graceful shutdown --- Custom shutdown callback panicked --- %v", recovered) + logger.Warnf("[GracefulShutdown] custom shutdown callback panicked, err=%v", recovered) } done <- struct{}{} }() @@ -423,7 +423,7 @@ func invokeCustomShutdownCallback(timeout time.Duration, callback func()) { select { case <-done: case <-time.After(timeout): - logger.Warnf("Graceful shutdown --- Custom shutdown callback timed out after %v", timeout) + logger.Warnf("[GracefulShutdown] custom shutdown callback timed out after %v", timeout) } } diff --git a/internal/config.go b/internal/config.go index 0db82681af..0606949537 100644 --- a/internal/config.go +++ b/internal/config.go @@ -94,7 +94,7 @@ func toURLs(registriesConfig *global.RegistryConfig, roleType common.RoleType) ( var registryURL *common.URL if address == "" || address == constant.NotAvailable { - logger.Infof("Empty or N/A registry address found, the process will work with no registry enabled " + + logger.Info("[Internal] empty or N/A registry address found, the process will work with no registry enabled " + "which means that the address of this instance will not be registered and not able to be found by other consumer instances.") return urls, nil } diff --git a/metadata/client.go b/metadata/client.go index f42a31235d..7d49e92ef9 100644 --- a/metadata/client.go +++ b/metadata/client.go @@ -85,7 +85,7 @@ func (m *triMetadataServiceV2) getMetadataInfo(ctx context.Context, revision str inv, _ := generateInvocation(m.invoker.GetURL(), methodName, req, metadataInfo, constant.CallUnary) res := m.invoker.Invoke(context.Background(), inv) if res.Error() != nil { - logger.Errorf("could not get the metadata info from remote provider: %v", res.Error()) + logger.Errorf("[Metadata] could not get the metadata info from remote provider, err=%v", res.Error()) return nil, res.Error() } return convertMetadataInfoV2(metadataInfo), nil @@ -156,7 +156,7 @@ func (m *remoteMetadataServiceV1) getMetadataInfo(ctx context.Context, revision res := m.invoker.Invoke(context.Background(), inv) if res.Error() != nil { - logger.Errorf("[MetadataRPC] RPC call failed to %s: %v", m.invoker.GetURL().Location, res.Error()) + logger.Errorf("[Metadata] RPC call failed to %s, err=%v", m.invoker.GetURL().Location, res.Error()) return nil, res.Error() } @@ -164,7 +164,7 @@ func (m *remoteMetadataServiceV1) getMetadataInfo(ctx context.Context, revision // Handle nil response (e.g., Java service not fully initialized) if rawResult == nil { - logger.Warnf("[MetadataRPC] Provider %s returned nil metadata (service may not be ready), revision: %s", + logger.Warnf("[Metadata] Provider %s returned nil metadata (service may not be ready), revision=%s", m.invoker.GetURL().Location, revision) return nil, perrors.Errorf("metadata is nil from %s, revision: %s", m.invoker.GetURL().Location, revision) } @@ -177,18 +177,18 @@ func (m *remoteMetadataServiceV1) getMetadataInfo(ctx context.Context, revision } else if strValue, ok := rawResult.(string); ok { // Old Java Dubbo version returns JSON string instead of MetadataInfo object // Try to parse it as JSON for backward compatibility - logger.Warnf("[MetadataRPC] Provider %s returned string type (old Dubbo version), attempting JSON parse", m.invoker.GetURL().Location) + logger.Warnf("[Metadata] Provider %s returned string type (old Dubbo version), attempting JSON parse", m.invoker.GetURL().Location) metadataInfo = &info.MetadataInfo{} if err := json.Unmarshal([]byte(strValue), metadataInfo); err != nil { - logger.Errorf("[MetadataRPC] Failed to parse JSON string from provider %s: %v", m.invoker.GetURL().Location, err) - logger.Errorf("[MetadataRPC] - String content: %s", truncateString(strValue, 1000)) + logger.Errorf("[Metadata] failed to parse JSON string from provider %s, err=%v", m.invoker.GetURL().Location, err) + logger.Errorf("[Metadata] - String content: %s", truncateString(strValue, 1000)) return nil, perrors.Errorf("failed to parse metadata JSON from %s: %v", m.invoker.GetURL().Location, err) } } else { // Neither MetadataInfo nor String - this is unexpected - logger.Errorf("[MetadataRPC] Unexpected metadata type from %s: got %T, expected *info.MetadataInfo or string", + logger.Errorf("[Metadata] unexpected metadata type from %s: got %T, expected *info.MetadataInfo or string", m.invoker.GetURL().Location, rawResult) return nil, perrors.Errorf("unexpected metadata type from %s: got %T, expected *info.MetadataInfo or string", m.invoker.GetURL().Location, rawResult) @@ -254,7 +254,7 @@ func getMetadataServiceUrlParams(ins registry.ServiceInstance) map[string]string if str, ok := ps[constant.MetadataServiceURLParamsPropertyName]; ok && len(str) > 0 { err := json.Unmarshal([]byte(str), &res) if err != nil { - logger.Errorf("could not parse the metadata service url parameters to map: %v", err) + logger.Errorf("[Metadata] could not parse the metadata service url parameters to map, err=%v", err) } } diff --git a/metadata/metadata_service.go b/metadata/metadata_service.go index d2cce72e66..5e822c6206 100644 --- a/metadata/metadata_service.go +++ b/metadata/metadata_service.go @@ -100,7 +100,7 @@ func (mts *DefaultMetadataService) GetMetadataInfo(revision string) (*info.Metad return metadataInfo, nil } } - logger.Warnf("metadata not found for revision: %s", revision) + logger.Warnf("[Metadata] metadata not found for revision=%s", revision) return nil, nil } @@ -187,7 +187,7 @@ func (e *serviceExporter) exportDubbo(port string) error { if err != nil { formatErr := perrors.Errorf("The service %v needExport the protocol %v error! Error message is %v.", ivkURL.Interface(), ivkURL.Protocol, err.Error()) - logger.Errorf(formatErr.Error()) + logger.Error("[Metadata] " + formatErr.Error()) return formatErr } ivkURL.Methods = strings.Split(methods, ",") diff --git a/metadata/options.go b/metadata/options.go index 22636a51fe..483ed2f04f 100644 --- a/metadata/options.go +++ b/metadata/options.go @@ -71,7 +71,7 @@ func (opts *Options) Init() error { // config test -> metadata exporter -> dubbo protocol/remoting -> config,cycle import will occur // some day we fix the cycle import then can remove this recover if err := recover(); err != nil { - logger.Errorf("metadata export failed,please check if dubbo protocol is imported, error: %v", err) + logger.Errorf("[Metadata] metadata export failed, please check if dubbo protocol is imported, err=%v", err) } }() err = exporter.Export() @@ -143,7 +143,7 @@ func fromRegistry(id string, rc *global.RegistryConfig) *ReportOptions { if rc.Timeout != "" { timeout, err := time.ParseDuration(rc.Timeout) if err != nil { - logger.Errorf("parse registry timeout config error %v", rc.Timeout) + logger.Errorf("[Metadata] parse registry timeout config, err=%v", rc.Timeout) } else { WithTimeout(timeout)(opts) } @@ -154,7 +154,7 @@ func fromRegistry(id string, rc *global.RegistryConfig) *ReportOptions { func (opts *ReportOptions) Init() error { url, err := opts.toUrl() if err != nil { - logger.Errorf("metadata report create error %v", err) + logger.Errorf("[Metadata] metadata report create error, err=%v", err) return err } return addMetadataReport(opts.registryId, url) diff --git a/metadata/report/etcd/report.go b/metadata/report/etcd/report.go index 0b325247bf..a69cdcb768 100644 --- a/metadata/report/etcd/report.go +++ b/metadata/report/etcd/report.go @@ -119,7 +119,7 @@ func (e *etcdMetadataReportFactory) CreateMetadataReport(url *common.URL) report addresses := strings.Split(url.Location, ",") client, err := gxetcd.NewClient(gxetcd.MetadataETCDV3Client, addresses, timeout, 1) if err != nil { - logger.Errorf("Could not create etcd metadata report. URL: %s,error:{%v}", url.String(), err) + logger.Errorf("[Metadata][Etcd] could not create etcd metadata report, url=%s, err=%v", url.String(), err) return nil } group := url.GetParam(constant.MetadataReportGroupKey, DEFAULT_ROOT) diff --git a/metadata/report/nacos/report.go b/metadata/report/nacos/report.go index d93beb48a8..a1772d5cae 100644 --- a/metadata/report/nacos/report.go +++ b/metadata/report/nacos/report.go @@ -125,7 +125,7 @@ func (n *nacosMetadataReport) storeMetadata(param vo.ConfigParam) error { func (n *nacosMetadataReport) getConfig(param vo.ConfigParam) (string, error) { cfg, err := n.client.Client().GetConfig(param) if err != nil { - logger.Errorf("Finding the configuration failed: %v", param) + logger.Errorf("[Metadata][Nacos] finding the configuration failed, param=%v", param) return "", err } return cfg, nil @@ -148,7 +148,7 @@ func callback(notify mapping.MappingListener, dataId, data string) { set.Add(app) } if err := notify.OnEvent(registry.NewServiceMappingChangedEvent(dataId, set)); err != nil { - logger.Errorf("serviceMapping callback err: %s", err.Error()) + logger.Errorf("[Metadata][Nacos] serviceMapping callback err=%v", err) } } @@ -188,7 +188,7 @@ func (n *nacosMetadataReport) GetServiceAppMapping(key string, group string, lis // add service mapping listener if listener != nil { if err := n.addListener(key, group, listener); err != nil { - logger.Errorf("add serviceMapping listener err: %s", err.Error()) + logger.Errorf("[Metadata][Nacos] add serviceMapping listener err=%v", err) } } v, err := n.getConfig(vo.ConfigParam{ @@ -226,7 +226,7 @@ func (n *nacosMetadataReportFactory) CreateMetadataReport(url *common.URL) repor url.SetParam(constant.NacosPassword, url.Password) client, err := nacos.NewNacosConfigClientByUrl(url) if err != nil { - logger.Errorf("Could not create nacos metadata report. URL: %s", url.String()) + logger.Errorf("[Metadata][Nacos] could not create nacos metadata report, url=%s", url.String()) return nil } return &nacosMetadataReport{client: client, group: group} diff --git a/metadata/report/zookeeper/listener.go b/metadata/report/zookeeper/listener.go index c91429bf3f..97fb159874 100644 --- a/metadata/report/zookeeper/listener.go +++ b/metadata/report/zookeeper/listener.go @@ -128,7 +128,7 @@ func (l *CacheListener) DataChange(event remoting.Event) bool { return listener.OnEvent(registry.NewServiceMappingChangedEvent(l.pathToKey(event.Path), set)) }) if err != nil { - logger.Error("Error notify mapping change event.", err) + logger.Errorf("[Metadata][Zookeeper] error notify mapping change event, err=%v", err) return false } return true diff --git a/metadata/report/zookeeper/report.go b/metadata/report/zookeeper/report.go index 0cdb0adc81..5772678478 100644 --- a/metadata/report/zookeeper/report.go +++ b/metadata/report/zookeeper/report.go @@ -83,7 +83,7 @@ func (m *zookeeperMetadataReport) PublishAppMetadata(application, revision strin } err = m.client.CreateWithValue(k, data) if perrors.Is(err, zk.ErrNodeExists) { - logger.Debugf("Try to create the node data failed. In most cases, it's not a problem. ") + logger.Debug("[Metadata][Zookeeper] try to create the node data failed. In most cases, it's not a problem. ") return nil } return err diff --git a/metadata/report_instance.go b/metadata/report_instance.go index f7bceb4584..f1157ca18a 100644 --- a/metadata/report_instance.go +++ b/metadata/report_instance.go @@ -44,7 +44,7 @@ var ( func addMetadataReport(registryId string, url *common.URL) error { fac := extension.GetMetadataReportFactory(url.Protocol) if fac == nil { - logger.Warnf("no metadata report factory of protocol %s found, please check if the metadata report factory is imported", url.Protocol) + logger.Warnf("[Metadata] no metadata report factory of protocol %s found, please check if the metadata report factory is imported", url.Protocol) return nil } instances[registryId] = &DelegateMetadataReport{instance: fac.CreateMetadataReport(url)} diff --git a/metrics/api.go b/metrics/api.go index ea30082b85..37f3cfe596 100644 --- a/metrics/api.go +++ b/metrics/api.go @@ -280,7 +280,7 @@ func (d *DefaultRtVec) Record(labels map[string]string, v float64) { func labelsToString(labels map[string]string) string { labelsJson, err := json.Marshal(labels) if err != nil { - logger.Errorf("json.Marshal(labels) = error:%v", err) + logger.Errorf("[Metrics] json.Marshal(labels) = err=%v", err) return "" } return string(labelsJson) diff --git a/metrics/probe/server.go b/metrics/probe/server.go index f327bb8dac..e8612e8273 100644 --- a/metrics/probe/server.go +++ b/metrics/probe/server.go @@ -93,14 +93,14 @@ func Init(cfg *Config) { ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) defer cancel() if err := srv.Shutdown(ctx); err != nil { - logger.Errorf("[kubernetes probe] probe server shutdown failed: %v", err) + logger.Errorf("[Metrics][Probe] probe server shutdown failed, err=%v", err) } }) go func() { - logger.Infof("[kubernetes probe] probe server listening on :%s", cfg.Port) + logger.Infof("[Metrics][Probe] probe server listening on :%s", cfg.Port) if err := srv.ListenAndServe(); err != nil && err != http.ErrServerClosed { - logger.Errorf("[kubernetes probe] probe server stopped with error: %v", err) + logger.Errorf("[Metrics][Probe] probe server stopped with err=%v", err) } }() }) @@ -117,7 +117,7 @@ func BuildProbeConfig(probeCfg *global.ProbeConfig) *Config { if port == "" { port = constant.ProbeDefaultPort } else if p, err := strconv.Atoi(port); p < 1 || p > 65535 || err != nil { - logger.Error("[kubernetes probe] unsupported probe server port, set to default ", constant.ProbeDefaultPort) + logger.Errorf("[Metrics][Probe] unsupported probe server port, set to default %s", constant.ProbeDefaultPort) } livenessPath := probeCfg.LivenessPath diff --git a/metrics/prometheus/registry.go b/metrics/prometheus/registry.go index 0eec66e47e..9ffac37504 100644 --- a/metrics/prometheus/registry.go +++ b/metrics/prometheus/registry.go @@ -160,21 +160,21 @@ func (p *promMetricRegistry) exportHttp() { ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) defer cancel() if err := srv.Shutdown(ctx); nil != err { - logger.Fatalf("prometheus server shutdown failed, err: %v", err) + logger.Fatalf("[Metrics][Prometheus] prometheus server shutdown failed, err=%v", err) } else { - logger.Info("prometheus server gracefully shutdown success") + logger.Info("[Metrics][Prometheus] prometheus server gracefully shutdown success") } }) - logger.Infof("prometheus endpoint :%s%s", port, path) + logger.Infof("[Metrics][Prometheus] prometheus endpoint :%s%s", port, path) if err := srv.ListenAndServe(); err != nil && err != http.ErrServerClosed { // except Shutdown or Close - logger.Errorf("new prometheus server with error: %v", err) + logger.Errorf("[Metrics][Prometheus] new prometheus server with err=%v", err) } } func (p *promMetricRegistry) exportPushgateway() { baseUrl, exist := p.url.GetNonDefaultParam(constant.PrometheusPushgatewayBaseUrlKey) if !exist { - logger.Error("no pushgateway base url found in config path: metrics.prometheus.pushgateway.base-url, please check your config") + logger.Error("[Metrics][Prometheus] no pushgateway base url found in config path: metrics.prometheus.pushgateway.base-url, please check your config") return } username := p.url.GetParam(constant.PrometheusPushgatewayUsernameKey, "") @@ -185,15 +185,15 @@ func (p *promMetricRegistry) exportPushgateway() { if len(username) != 0 { pusher.BasicAuth(username, password) } - logger.Infof("prometheus pushgateway will push to %s every %d seconds", baseUrl, pushInterval) + logger.Infof("[Metrics][Prometheus] prometheus pushgateway will push to %s every %d seconds", baseUrl, pushInterval) ticker := time.NewTicker(time.Duration(pushInterval) * time.Second) go func() { for range ticker.C { err := pusher.Add() if err != nil { - logger.Errorf("push metric data to prometheus pushgateway error: %v", err) + logger.Errorf("[Metrics][Prometheus] push metric data to prometheus pushgateway err=%v", err) } else { - logger.Debugf("prometheus pushgateway push to %s success", baseUrl) + logger.Debugf("[Metrics][Prometheus] prometheus pushgateway push to %s success", baseUrl) } } }() diff --git a/metrics/rpc/collector.go b/metrics/rpc/collector.go index c757331728..cac74b8edc 100644 --- a/metrics/rpc/collector.go +++ b/metrics/rpc/collector.go @@ -65,7 +65,7 @@ func (c *rpcCollector) start() { default: } } else { - logger.Error("Bad metrics event found in RPC collector") + logger.Error("[Metrics][RPC] bad metrics event found in RPC collector") } } } diff --git a/metrics/rpc/util.go b/metrics/rpc/util.go index 0049d36126..0eed893781 100644 --- a/metrics/rpc/util.go +++ b/metrics/rpc/util.go @@ -53,8 +53,8 @@ func getRole(url *common.URL) (role string) { } else if isConsumer(url) { role = constant.SideConsumer } else { - logger.Warnf("The url belongs neither the consumer nor the provider, "+ - "so the invocation will be ignored. url: %s", url.String()) + logger.Warnf("[Metrics][RPC] the url belongs neither the consumer nor the provider, "+ + "so the invocation will be ignored. url=%s", url.String()) } return } diff --git a/otel/trace/exporter.go b/otel/trace/exporter.go index ee3ec2d486..7f2292a634 100644 --- a/otel/trace/exporter.go +++ b/otel/trace/exporter.go @@ -75,7 +75,7 @@ func NewExporter(config *ExporterConfig, customFunc func() (sdktrace.SpanExporte exporter, err := customFunc() if err != nil { err = fmt.Errorf("failed to create %s exporter: %v", config.Exporter, err) - logger.Error(err) + logger.Errorf("[OTel][Trace] failed to create %s exporter, err=%v", config.Exporter, err) return } @@ -89,7 +89,7 @@ func NewExporter(config *ExporterConfig, customFunc func() (sdktrace.SpanExporte samplerOption = sdktrace.WithSampler(sdktrace.ParentBased(sdktrace.NeverSample())) default: err = fmt.Errorf("otel sample mode %s not supported", config.SampleMode) - logger.Error(err) + logger.Errorf("[OTel][Trace] otel sample mode %s not supported", config.SampleMode) return } diff --git a/presee_test/adaptive_service/p2c_healthy/README.md b/presee_test/adaptive_service/p2c_healthy/README.md new file mode 100644 index 0000000000..eafd846563 --- /dev/null +++ b/presee_test/adaptive_service/p2c_healthy/README.md @@ -0,0 +1,86 @@ +# Adaptive Service P2C Healthy Provider Sample + +This sample verifies the full adaptive service path across multiple direct providers: + +```text +provider adaptive filter computes remaining -> response attachment returns remaining -> consumer adaptive cluster writes metrics -> P2C reads metrics -> traffic shifts toward the provider with higher remaining +``` + +It does not use a registry, change the proto, read response attachments in sample code, or use logs as the acceptance signal. + +In this project, provider health for adaptive service is the current remaining capacity: + +```text +remaining = limitation - inflight +``` + +## Run + +Start three providers with different handler costs: + +```bash +go run ./presee_test/adaptive_service/p2c_healthy/server \ + -id fast \ + -port 20101 \ + -stats-port 21101 \ + -work-ms 20 +``` + +```bash +go run ./presee_test/adaptive_service/p2c_healthy/server \ + -id medium \ + -port 20102 \ + -stats-port 21102 \ + -work-ms 100 +``` + +```bash +go run ./presee_test/adaptive_service/p2c_healthy/server \ + -id slow \ + -port 20103 \ + -stats-port 21103 \ + -work-ms 300 +``` + +Start the client: + +```bash +go run ./presee_test/adaptive_service/p2c_healthy/client \ + -urls 'tri://127.0.0.1:20101;tri://127.0.0.1:20102;tri://127.0.0.1:20103' \ + -stats-urls 'http://127.0.0.1:21101/stats;http://127.0.0.1:21102/stats;http://127.0.0.1:21103/stats' \ + -concurrency 200 \ + -duration 60s +``` + +The client writes `p2c_healthy_result.csv` by default. Use `-out ""` to disable CSV output. The `latency_avg_ms` and `latency_p95_ms` columns are calculated from successful requests in the current report interval. + +The console and CSV output include both cumulative and current-window routing signals: + +- `interval_providers`: successful request distribution in the last report interval. +- `providers`: cumulative successful request distribution since startup. +- `healthiest`: provider with the highest current `limiter_remaining`. +- `limiters`: latest limiter snapshot for every provider. + +## Success Signals + +- After warmup, every provider reports `limiter_found=true`. +- `healthiest` identifies the provider with the highest `limiter_remaining`. +- `interval_providers` is biased toward the current `healthiest` provider more often than the slower or lower-remaining providers. +- `providers` shows the cumulative hit ratio moving toward providers that repeatedly appear as `healthiest`. +- `failed` stays close to `0`. + +## Useful Stats + +Each provider exposes `GET /stats` with: + +- `id` +- `work_ms` +- `active` +- `max_active` +- `started` +- `completed` +- `avg_handler_latency_ms` +- `limiter_found` +- `limiter_limitation` +- `limiter_remaining` +- `limiter_inflight` diff --git a/presee_test/adaptive_service/p2c_healthy/client/main.go b/presee_test/adaptive_service/p2c_healthy/client/main.go new file mode 100644 index 0000000000..c67f50002a --- /dev/null +++ b/presee_test/adaptive_service/p2c_healthy/client/main.go @@ -0,0 +1,618 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package main + +import ( + "context" + "encoding/csv" + "encoding/json" + "flag" + "fmt" + "math" + "net/http" + "os" + "sort" + "strconv" + "strings" + "sync" + "sync/atomic" + "time" +) + +import ( + "github.com/dubbogo/gost/log/logger" +) + +import ( + "dubbo.apache.org/dubbo-go/v3/client" + clsutils "dubbo.apache.org/dubbo-go/v3/cluster/utils" + _ "dubbo.apache.org/dubbo-go/v3/imports" + protectpb "dubbo.apache.org/dubbo-go/v3/presee_test/adaptive_service/protect_provider/proto" +) + +type clientConfig struct { + urls string + statsURLs []string + concurrency int + duration time.Duration + timeout time.Duration + out string + reportInterval time.Duration +} + +type clientStats struct { + started atomic.Int64 + success atomic.Int64 + rejected atomic.Int64 + failed atomic.Int64 + latencies latencyRecorder + intervalLatencies latencyRecorder + hits hitCounter + intervalHits hitCounter +} + +type hitCounter struct { + mu sync.Mutex + hits map[string]int64 +} + +type latencyRecorder struct { + mu sync.Mutex + values []time.Duration +} + +type serverSnapshot struct { + ID string `json:"id"` + WorkMS int64 `json:"work_ms"` + Active int64 `json:"active"` + MaxActive int64 `json:"max_active"` + Started int64 `json:"started"` + Completed int64 `json:"completed"` + AvgHandlerLatencyMS float64 `json:"avg_handler_latency_ms"` + LimiterFound bool `json:"limiter_found"` + LimiterLimitation uint64 `json:"limiter_limitation"` + LimiterRemaining uint64 `json:"limiter_remaining"` + LimiterInflight uint64 `json:"limiter_inflight"` +} + +type snapshotUpdate struct { + index int + snapshot serverSnapshot +} + +type sampleRow struct { + TimeUnixSec int64 + ElapsedSec float64 + Started int64 + Success int64 + Rejected int64 + Failed int64 + SuccessQPS float64 + RejectRate float64 + LatencyAvgMS float64 + LatencyP95MS float64 + IntervalProviders string + ProviderSummary string + Healthiest string + LimiterSummary string + SnapshotSummaries string +} + +func (h *hitCounter) add(providerID string) { + if providerID == "" { + providerID = "unknown" + } + h.mu.Lock() + defer h.mu.Unlock() + if h.hits == nil { + h.hits = make(map[string]int64) + } + h.hits[providerID]++ +} + +func (h *hitCounter) snapshot(reset bool) map[string]int64 { + h.mu.Lock() + defer h.mu.Unlock() + cp := make(map[string]int64, len(h.hits)) + for id, count := range h.hits { + cp[id] = count + } + if reset { + h.hits = nil + } + return cp +} + +func (r *latencyRecorder) record(d time.Duration) { + r.mu.Lock() + defer r.mu.Unlock() + r.values = append(r.values, d) +} + +func (r *latencyRecorder) snapshot(reset bool) (count int, avgMS float64, p95MS float64) { + r.mu.Lock() + defer r.mu.Unlock() + + count = len(r.values) + if count == 0 { + return 0, 0, 0 + } + + values := append([]time.Duration(nil), r.values...) + if reset { + r.values = nil + } + sort.Slice(values, func(i, j int) bool { + return values[i] < values[j] + }) + + var total time.Duration + for _, value := range values { + total += value + } + avgMS = float64(total) / float64(count) / float64(time.Millisecond) + p95Index := int(math.Ceil(float64(count)*0.95)) - 1 + if p95Index < 0 { + p95Index = 0 + } + p95MS = float64(values[p95Index]) / float64(time.Millisecond) + return count, avgMS, p95MS +} + +func runLoad(ctx context.Context, svc protectpb.ProtectService, cfg clientConfig, stats *clientStats) { + var wg sync.WaitGroup + wg.Add(cfg.concurrency) + + for workerID := 0; workerID < cfg.concurrency; workerID++ { + go func(workerID int) { + defer wg.Done() + for { + select { + case <-ctx.Done(): + return + default: + } + + seq := stats.started.Add(1) + reqCtx, cancel := context.WithTimeout(ctx, cfg.timeout) + start := time.Now() + resp, err := svc.Work(reqCtx, &protectpb.WorkRequest{ + Name: fmt.Sprintf("worker-%d-%d", workerID, seq), + }) + cancel() + + if err == nil { + stats.success.Add(1) + providerID := providerIDFromMessage(resp.GetMessage()) + stats.hits.add(providerID) + stats.intervalHits.add(providerID) + latency := time.Since(start) + stats.latencies.record(latency) + stats.intervalLatencies.record(latency) + continue + } + if isAdaptiveReject(err) { + stats.rejected.Add(1) + continue + } + if ctx.Err() != nil { + return + } + stats.failed.Add(1) + } + }(workerID) + } + + wg.Wait() +} + +func providerIDFromMessage(message string) string { + providerID, _, ok := strings.Cut(message, ":") + if !ok { + return "unknown" + } + return providerID +} + +func isAdaptiveReject(err error) bool { + return clsutils.DoesAdaptiveServiceReachLimitation(err) +} + +func pollServerStats(ctx context.Context, index int, statsURL string, interval time.Duration, sink chan<- snapshotUpdate) { + ticker := time.NewTicker(interval) + defer ticker.Stop() + + httpClient := &http.Client{Timeout: interval} + warned := false + for { + select { + case <-ctx.Done(): + return + case <-ticker.C: + } + + req, err := http.NewRequestWithContext(ctx, http.MethodGet, statsURL, nil) + if err != nil { + if !warned { + logger.Warnf("build stats request failed for %s: %v", statsURL, err) + warned = true + } + continue + } + + resp, err := httpClient.Do(req) + if err != nil { + if !warned { + logger.Warnf("poll server stats failed for %s: %v", statsURL, err) + warned = true + } + continue + } + + var snapshot serverSnapshot + err = json.NewDecoder(resp.Body).Decode(&snapshot) + closeErr := resp.Body.Close() + if err != nil { + if !warned { + logger.Warnf("decode server stats failed for %s: %v", statsURL, err) + warned = true + } + continue + } + if closeErr != nil { + if !warned { + logger.Warnf("close stats response failed for %s: %v", statsURL, closeErr) + } + warned = true + } else { + warned = false + } + + select { + case sink <- snapshotUpdate{index: index, snapshot: snapshot}: + case <-ctx.Done(): + return + default: + } + } +} + +func reportLoop(ctx context.Context, cfg clientConfig, stats *clientStats, updates <-chan snapshotUpdate) error { + var file *os.File + var writer *csv.Writer + if cfg.out != "" { + var err error + file, err = os.Create(cfg.out) + if err != nil { + return err + } + defer file.Close() + + writer = csv.NewWriter(file) + defer writer.Flush() + if err := writer.Write([]string{ + "time_unix", "elapsed_sec", "started", "success", "rejected", "failed", "success_qps", + "reject_rate", "latency_avg_ms", "latency_p95_ms", "interval_providers", "providers", + "healthiest", "limiters", "snapshots", + }); err != nil { + return err + } + } + + start := time.Now() + ticker := time.NewTicker(cfg.reportInterval) + defer ticker.Stop() + + lastSuccess := int64(0) + lastReport := start + snapshots := make([]serverSnapshot, len(cfg.statsURLs)) + + for { + select { + case update := <-updates: + if update.index >= 0 && update.index < len(snapshots) { + snapshots[update.index] = update.snapshot + } + continue + default: + } + + select { + case <-ctx.Done(): + return nil + case update := <-updates: + if update.index >= 0 && update.index < len(snapshots) { + snapshots[update.index] = update.snapshot + } + case now := <-ticker.C: + row := buildSampleRow(now, start, lastReport, lastSuccess, stats, snapshots) + lastReport = now + lastSuccess = row.Success + printRow(row) + if writer != nil { + if err := writeRow(writer, row); err != nil { + return err + } + writer.Flush() + if err := writer.Error(); err != nil { + return err + } + } + } + } +} + +func buildSampleRow(now time.Time, start time.Time, lastReport time.Time, lastSuccess int64, stats *clientStats, + snapshots []serverSnapshot) sampleRow { + started := stats.started.Load() + success := stats.success.Load() + rejected := stats.rejected.Load() + failed := stats.failed.Load() + _, avgMS, p95MS := stats.intervalLatencies.snapshot(true) + + elapsed := now.Sub(start).Seconds() + interval := now.Sub(lastReport).Seconds() + var successQPS float64 + if interval > 0 { + successQPS = float64(success-lastSuccess) / interval + } + + var rejectRate float64 + if started > 0 { + rejectRate = float64(rejected) / float64(started) * 100 + } + + hits := stats.hits.snapshot(false) + intervalHits := stats.intervalHits.snapshot(true) + return sampleRow{ + TimeUnixSec: now.Unix(), + ElapsedSec: elapsed, + Started: started, + Success: success, + Rejected: rejected, + Failed: failed, + SuccessQPS: successQPS, + RejectRate: rejectRate, + LatencyAvgMS: avgMS, + LatencyP95MS: p95MS, + IntervalProviders: formatProviderSummary(intervalHits, success-lastSuccess), + ProviderSummary: formatProviderSummary(hits, success), + Healthiest: formatHealthiest(snapshots), + LimiterSummary: formatLimiterSummary(snapshots), + SnapshotSummaries: formatSnapshotSummaries(snapshots), + } +} + +func formatProviderSummary(hits map[string]int64, success int64) string { + if len(hits) == 0 { + return "none" + } + ids := make([]string, 0, len(hits)) + for id := range hits { + ids = append(ids, id) + } + sort.Strings(ids) + + parts := make([]string, 0, len(ids)) + for _, id := range ids { + ratio := float64(0) + if success > 0 { + ratio = float64(hits[id]) / float64(success) * 100 + } + parts = append(parts, fmt.Sprintf("%s=%d/%.1f%%", id, hits[id], ratio)) + } + return strings.Join(parts, ",") +} + +func formatLimiterSummary(snapshots []serverSnapshot) string { + parts := make([]string, 0, len(snapshots)) + for index, snapshot := range snapshots { + id := snapshot.ID + if id == "" { + id = fmt.Sprintf("provider-%d", index+1) + } + parts = append(parts, fmt.Sprintf("%s found=%t remaining=%d limitation=%d inflight=%d", + id, snapshot.LimiterFound, snapshot.LimiterRemaining, snapshot.LimiterLimitation, snapshot.LimiterInflight)) + } + if len(parts) == 0 { + return "none" + } + return strings.Join(parts, ";") +} + +func formatHealthiest(snapshots []serverSnapshot) string { + var ( + bestID string + bestRemaining uint64 + found bool + ) + for index, snapshot := range snapshots { + if !snapshot.LimiterFound { + continue + } + if !found || snapshot.LimiterRemaining > bestRemaining { + found = true + bestRemaining = snapshot.LimiterRemaining + bestID = snapshot.ID + if bestID == "" { + bestID = fmt.Sprintf("provider-%d", index+1) + } + } + } + if !found { + return "none" + } + return fmt.Sprintf("%s remaining=%d", bestID, bestRemaining) +} + +func formatSnapshotSummaries(snapshots []serverSnapshot) string { + parts := make([]string, 0, len(snapshots)) + for index, snapshot := range snapshots { + id := snapshot.ID + if id == "" { + id = fmt.Sprintf("provider-%d", index+1) + } + parts = append(parts, fmt.Sprintf("%s work_ms=%d active=%d max_active=%d started=%d completed=%d avg_handler_latency_ms=%.1f", + id, snapshot.WorkMS, snapshot.Active, snapshot.MaxActive, snapshot.Started, snapshot.Completed, snapshot.AvgHandlerLatencyMS)) + } + if len(parts) == 0 { + return "none" + } + return strings.Join(parts, ";") +} + +func printRow(row sampleRow) { + fmt.Printf( + "elapsed=%.0fs started=%d success=%d rejected=%d failed=%d qps=%.1f reject_rate=%.1f%% avg=%.0fms p95=%.0fms interval_providers=[%s] providers=[%s] healthiest=[%s] limiters=[%s] snapshots=[%s]\n", + row.ElapsedSec, + row.Started, + row.Success, + row.Rejected, + row.Failed, + row.SuccessQPS, + row.RejectRate, + row.LatencyAvgMS, + row.LatencyP95MS, + row.IntervalProviders, + row.ProviderSummary, + row.Healthiest, + row.LimiterSummary, + row.SnapshotSummaries, + ) +} + +func writeRow(writer *csv.Writer, row sampleRow) error { + return writer.Write([]string{ + strconv.FormatInt(row.TimeUnixSec, 10), + strconv.FormatFloat(row.ElapsedSec, 'f', 3, 64), + strconv.FormatInt(row.Started, 10), + strconv.FormatInt(row.Success, 10), + strconv.FormatInt(row.Rejected, 10), + strconv.FormatInt(row.Failed, 10), + strconv.FormatFloat(row.SuccessQPS, 'f', 3, 64), + strconv.FormatFloat(row.RejectRate, 'f', 3, 64), + strconv.FormatFloat(row.LatencyAvgMS, 'f', 3, 64), + strconv.FormatFloat(row.LatencyP95MS, 'f', 3, 64), + row.IntervalProviders, + row.ProviderSummary, + row.Healthiest, + row.LimiterSummary, + row.SnapshotSummaries, + }) +} + +func parseConfig() clientConfig { + var cfg clientConfig + var statsURLs string + flag.StringVar(&cfg.urls, "urls", "tri://127.0.0.1:20101;tri://127.0.0.1:20102;tri://127.0.0.1:20103", "semicolon-separated Triple provider URLs") + flag.StringVar(&statsURLs, "stats-urls", "http://127.0.0.1:21101/stats;http://127.0.0.1:21102/stats;http://127.0.0.1:21103/stats", "semicolon-separated server stats URLs") + flag.IntVar(&cfg.concurrency, "concurrency", 200, "worker concurrency") + flag.DurationVar(&cfg.duration, "duration", 60*time.Second, "load duration") + flag.DurationVar(&cfg.timeout, "timeout", 3*time.Second, "per-request timeout") + flag.StringVar(&cfg.out, "out", "p2c_healthy_result.csv", "CSV output path, empty disables CSV") + flag.DurationVar(&cfg.reportInterval, "report-interval", time.Second, "report interval") + flag.Parse() + + cfg.urls = normalizeDirectURLs(cfg.urls) + cfg.statsURLs = splitSemicolonList(statsURLs) + return cfg +} + +func normalizeDirectURLs(urls string) string { + parts := splitSemicolonList(urls) + for i, part := range parts { + if !strings.Contains(part, "://") { + parts[i] = "tri://" + part + } + } + return strings.Join(parts, ";") +} + +func splitSemicolonList(value string) []string { + rawParts := strings.Split(value, ";") + parts := make([]string, 0, len(rawParts)) + for _, part := range rawParts { + part = strings.TrimSpace(part) + if part != "" { + parts = append(parts, part) + } + } + return parts +} + +func main() { + cfg := parseConfig() + cli, err := client.NewClient( + client.WithClientURL(cfg.urls), + ) + if err != nil { + panic(err) + } + + svc, err := protectpb.NewProtectService( + cli, + client.WithProtocolTriple(), + client.WithClusterAdaptiveService(), + client.WithLoadBalanceP2C(), + client.WithRetries(0), + ) + if err != nil { + panic(err) + } + + ctx, cancel := context.WithTimeout(context.Background(), cfg.duration) + defer cancel() + + stats := &clientStats{} + updates := make(chan snapshotUpdate, len(cfg.statsURLs)) + reportErr := make(chan error, 1) + for index, statsURL := range cfg.statsURLs { + go pollServerStats(ctx, index, statsURL, cfg.reportInterval, updates) + } + go func() { + reportErr <- reportLoop(ctx, cfg, stats, updates) + }() + + runLoad(ctx, svc, cfg, stats) + + if err := <-reportErr; err != nil { + panic(err) + } + + _, avgMS, p95MS := stats.latencies.snapshot(false) + started := stats.started.Load() + success := stats.success.Load() + rejected := stats.rejected.Load() + failed := stats.failed.Load() + var rejectRate float64 + if started > 0 { + rejectRate = float64(rejected) / float64(started) * 100 + } + fmt.Printf( + "final started=%d success=%d rejected=%d failed=%d reject_rate=%.1f%% avg=%.0fms p95=%.0fms providers=[%s] out=%s\n", + started, + success, + rejected, + failed, + rejectRate, + avgMS, + p95MS, + formatProviderSummary(stats.hits.snapshot(false), success), + cfg.out, + ) +} diff --git a/presee_test/adaptive_service/p2c_healthy/server/main.go b/presee_test/adaptive_service/p2c_healthy/server/main.go new file mode 100644 index 0000000000..ec74239c38 --- /dev/null +++ b/presee_test/adaptive_service/p2c_healthy/server/main.go @@ -0,0 +1,174 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package main + +import ( + "context" + "encoding/json" + "flag" + "fmt" + "net/http" + "sync/atomic" + "time" +) + +import ( + "github.com/dubbogo/gost/log/logger" +) + +import ( + "dubbo.apache.org/dubbo-go/v3/filter/adaptivesvc" + _ "dubbo.apache.org/dubbo-go/v3/imports" + protectpb "dubbo.apache.org/dubbo-go/v3/presee_test/adaptive_service/protect_provider/proto" + "dubbo.apache.org/dubbo-go/v3/protocol" + "dubbo.apache.org/dubbo-go/v3/server" +) + +type HealthyServer struct { + id string + workDelay time.Duration + stats *serverStats +} + +type serverStats struct { + active atomic.Int64 + maxActive atomic.Int64 + started atomic.Int64 + completed atomic.Int64 + totalLatencyNS atomic.Int64 +} + +type statsResponse struct { + ID string `json:"id"` + WorkMS int64 `json:"work_ms"` + Active int64 `json:"active"` + MaxActive int64 `json:"max_active"` + Started int64 `json:"started"` + Completed int64 `json:"completed"` + AvgHandlerLatencyMS float64 `json:"avg_handler_latency_ms"` + LimiterFound bool `json:"limiter_found"` + LimiterLimitation uint64 `json:"limiter_limitation"` + LimiterRemaining uint64 `json:"limiter_remaining"` + LimiterInflight uint64 `json:"limiter_inflight"` +} + +func (s *HealthyServer) Work(_ context.Context, req *protectpb.WorkRequest) (*protectpb.WorkResponse, error) { + start := time.Now() + seq := s.stats.started.Add(1) + s.stats.begin() + defer s.stats.end(start) + + time.Sleep(s.workDelay) + + return &protectpb.WorkResponse{ + Message: fmt.Sprintf("%s:ok:%s", s.id, req.GetName()), + Sequence: seq, + }, nil +} + +func (s *serverStats) begin() int64 { + current := s.active.Add(1) + for { + oldMax := s.maxActive.Load() + if current <= oldMax { + return current + } + if s.maxActive.CompareAndSwap(oldMax, current) { + return current + } + } +} + +func (s *serverStats) end(start time.Time) { + s.active.Add(-1) + s.completed.Add(1) + s.totalLatencyNS.Add(time.Since(start).Nanoseconds()) +} + +func serveStats(addr string, provider *HealthyServer) error { + mux := http.NewServeMux() + mux.HandleFunc("/stats", func(w http.ResponseWriter, _ *http.Request) { + completed := provider.stats.completed.Load() + var avgHandlerLatencyMS float64 + if completed > 0 { + avgHandlerLatencyMS = float64(provider.stats.totalLatencyNS.Load()) / float64(completed) / float64(time.Millisecond) + } + + limiterSnapshot, limiterFound := adaptivesvc.GetMethodLimiterSnapshot(protectpb.ProtectServiceName, "Work") + w.Header().Set("Content-Type", "application/json") + if err := json.NewEncoder(w).Encode(statsResponse{ + ID: provider.id, + WorkMS: provider.workDelay.Milliseconds(), + Active: provider.stats.active.Load(), + MaxActive: provider.stats.maxActive.Load(), + Started: provider.stats.started.Load(), + Completed: completed, + AvgHandlerLatencyMS: avgHandlerLatencyMS, + LimiterFound: limiterFound, + LimiterLimitation: limiterSnapshot.Limitation, + LimiterRemaining: limiterSnapshot.Remaining, + LimiterInflight: limiterSnapshot.Inflight, + }); err != nil { + logger.Warnf("write stats response failed: %v", err) + } + }) + + return http.ListenAndServe(addr, mux) +} + +func main() { + id := flag.String("id", "provider-1", "provider ID returned in WorkResponse.Message") + port := flag.Int("port", 20101, "Triple service port") + statsPort := flag.Int("stats-port", 21101, "HTTP stats port") + workMS := flag.Int("work-ms", 20, "handler work duration in milliseconds") + flag.Parse() + + provider := &HealthyServer{ + id: *id, + workDelay: time.Duration(*workMS) * time.Millisecond, + stats: &serverStats{}, + } + + statsAddr := fmt.Sprintf("127.0.0.1:%d", *statsPort) + go func() { + logger.Infof("stats listening at http://%s/stats", statsAddr) + if err := serveStats(statsAddr, provider); err != nil { + logger.Errorf("stats server stopped: %v", err) + } + }() + + srv, err := server.NewServer( + server.WithServerProtocol( + protocol.WithTriple(), + protocol.WithPort(*port), + ), + server.WithServerAdaptiveService(), + ) + if err != nil { + panic(err) + } + + if err := protectpb.RegisterProtectServiceHandler(srv, provider); err != nil { + panic(err) + } + + logger.Infof("p2c healthy provider %s listening at tri://127.0.0.1:%d", *id, *port) + if err := srv.Serve(); err != nil { + panic(err) + } +} diff --git a/presee_test/adaptive_service/protect_provider/README.md b/presee_test/adaptive_service/protect_provider/README.md new file mode 100644 index 0000000000..cb7d4a6b43 --- /dev/null +++ b/presee_test/adaptive_service/protect_provider/README.md @@ -0,0 +1,48 @@ +# Adaptive Service Protect Provider Demo + +This demo verifies provider-side adaptive service protection under high concurrency. + +The server enables provider adaptive service and records how many requests actually enter the business handler. Rejected requests happen in the provider filter before the handler, so they do not increase `active` or `max_active`. + +## Generate + +```bash +protoc \ + --go_out=. --go_opt=paths=source_relative \ + --plugin=protoc-gen-go-triple=./tools/protoc-gen-go-triple/protoc-gen-go-triple \ + --go-triple_out=. \ + presee_test/adaptive_service/protect_provider/proto/protect.proto +``` + +## Run + +Start the provider: + +```bash +go run ./presee_test/adaptive_service/protect_provider/server -port 20001 -stats-port 21001 -work-ms 200 +``` + +Start the load client: + +```bash +go run ./presee_test/adaptive_service/protect_provider/client \ + -url 127.0.0.1:20001 \ + -stats-url http://127.0.0.1:21001/stats \ + -concurrency 200 \ + -duration 30s +``` + +The client prints one summary line per second and writes `protect_provider_result.csv` by default. Use `-out ""` to disable CSV output. + +Expected signal: + +- `started` keeps increasing. +- `rejected` is greater than zero. +- `failed` stays near zero. +- `server_max_active` remains clearly below `-concurrency=200`. + +Example output: + +```text +elapsed=10s started=840 success=610 rejected=180 failed=0 qps=61.0 reject_rate=21.4% avg=205ms p95=240ms server_active=50 server_max_active=53 +``` diff --git a/presee_test/adaptive_service/protect_provider/client/main.go b/presee_test/adaptive_service/protect_provider/client/main.go new file mode 100644 index 0000000000..d9e17f9047 --- /dev/null +++ b/presee_test/adaptive_service/protect_provider/client/main.go @@ -0,0 +1,444 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package main + +import ( + "context" + "encoding/csv" + "encoding/json" + "flag" + "fmt" + "math" + "net/http" + "os" + "sort" + "strconv" + "strings" + "sync" + "sync/atomic" + "time" +) + +import ( + "github.com/dubbogo/gost/log/logger" +) + +import ( + "dubbo.apache.org/dubbo-go/v3/client" + _ "dubbo.apache.org/dubbo-go/v3/imports" + protectpb "dubbo.apache.org/dubbo-go/v3/presee_test/adaptive_service/protect_provider/proto" +) + +type clientConfig struct { + url string + statsURL string + concurrency int + duration time.Duration + timeout time.Duration + out string + reportInterval time.Duration +} + +type clientStats struct { + started atomic.Int64 + success atomic.Int64 + rejected atomic.Int64 + failed atomic.Int64 + latencies latencyRecorder +} + +type latencyRecorder struct { + mu sync.Mutex + values []time.Duration +} + +type serverSnapshot struct { + Active int64 `json:"active"` + MaxActive int64 `json:"max_active"` + Started int64 `json:"started"` + Completed int64 `json:"completed"` +} + +type sampleRow struct { + TimeUnixSec int64 + ElapsedSec float64 + Started int64 + Success int64 + Rejected int64 + Failed int64 + SuccessQPS float64 + RejectRate float64 + LatencyAvgMS float64 + LatencyP95MS float64 + ServerActive int64 + ServerMaxActive int64 + ServerStarted int64 + ServerCompleted int64 +} + +func (r *latencyRecorder) record(d time.Duration) { + r.mu.Lock() + defer r.mu.Unlock() + r.values = append(r.values, d) +} + +func (r *latencyRecorder) snapshot() (count int, avgMS float64, p95MS float64) { + r.mu.Lock() + defer r.mu.Unlock() + + count = len(r.values) + if count == 0 { + return 0, 0, 0 + } + + values := append([]time.Duration(nil), r.values...) + sort.Slice(values, func(i, j int) bool { + return values[i] < values[j] + }) + + var total time.Duration + for _, value := range values { + total += value + } + avgMS = float64(total) / float64(count) / float64(time.Millisecond) + p95Index := int(math.Ceil(float64(count)*0.95)) - 1 + if p95Index < 0 { + p95Index = 0 + } + p95MS = float64(values[p95Index]) / float64(time.Millisecond) + return count, avgMS, p95MS +} + +func runLoad(ctx context.Context, svc protectpb.ProtectService, cfg clientConfig, stats *clientStats) { + var wg sync.WaitGroup + wg.Add(cfg.concurrency) + + for workerID := 0; workerID < cfg.concurrency; workerID++ { + go func(workerID int) { + defer wg.Done() + for { + select { + case <-ctx.Done(): + return + default: + } + + seq := stats.started.Add(1) + reqCtx, cancel := context.WithTimeout(ctx, cfg.timeout) + start := time.Now() + _, err := svc.Work(reqCtx, &protectpb.WorkRequest{ + Name: fmt.Sprintf("worker-%d-%d", workerID, seq), + }) + cancel() + + if err == nil { + stats.success.Add(1) + stats.latencies.record(time.Since(start)) + continue + } + if isAdaptiveReject(err) { + stats.rejected.Add(1) + continue + } + if ctx.Err() != nil { + return + } + stats.failed.Add(1) + } + }(workerID) + } + + wg.Wait() +} + +func isAdaptiveReject(err error) bool { + if err == nil { + return false + } + errText := err.Error() + return strings.Contains(errText, "adaptive service interrupted") && strings.Contains(errText, "reach limitation") +} + +func pollServerStats(ctx context.Context, statsURL string, interval time.Duration, sink chan<- serverSnapshot) { + ticker := time.NewTicker(interval) + defer ticker.Stop() + + httpClient := &http.Client{Timeout: interval} + warned := false + for { + select { + case <-ctx.Done(): + return + case <-ticker.C: + } + + req, err := http.NewRequestWithContext(ctx, http.MethodGet, statsURL, nil) + if err != nil { + if !warned { + logger.Warnf("build stats request failed: %v", err) + warned = true + } + continue + } + + resp, err := httpClient.Do(req) + if err != nil { + if !warned { + logger.Warnf("poll server stats failed: %v", err) + warned = true + } + continue + } + + var snapshot serverSnapshot + err = json.NewDecoder(resp.Body).Decode(&snapshot) + closeErr := resp.Body.Close() + if err != nil { + if !warned { + logger.Warnf("decode server stats failed: %v", err) + warned = true + } + continue + } + if closeErr != nil { + if !warned { + logger.Warnf("close stats response failed: %v", closeErr) + } + warned = true + } else { + warned = false + } + + select { + case sink <- snapshot: + case <-ctx.Done(): + return + default: + } + } +} + +func reportLoop(ctx context.Context, cfg clientConfig, stats *clientStats, snapshots <-chan serverSnapshot) error { + var file *os.File + var writer *csv.Writer + if cfg.out != "" { + var err error + file, err = os.Create(cfg.out) + if err != nil { + return err + } + defer file.Close() + + writer = csv.NewWriter(file) + defer writer.Flush() + if err := writer.Write([]string{ + "time_unix", "elapsed_sec", "started", "success", "rejected", "failed", "success_qps", + "reject_rate", "latency_avg_ms", "latency_p95_ms", "server_active", "server_max_active", + "server_started", "server_completed", + }); err != nil { + return err + } + } + + start := time.Now() + ticker := time.NewTicker(cfg.reportInterval) + defer ticker.Stop() + + lastSuccess := int64(0) + lastReport := start + var snapshot serverSnapshot + + for { + select { + case nextSnapshot := <-snapshots: + snapshot = nextSnapshot + continue + default: + } + + select { + case <-ctx.Done(): + return nil + case nextSnapshot := <-snapshots: + snapshot = nextSnapshot + case now := <-ticker.C: + row := buildSampleRow(now, start, lastReport, lastSuccess, stats, snapshot) + lastReport = now + lastSuccess = row.Success + printRow(row) + if writer != nil { + if err := writeRow(writer, row); err != nil { + return err + } + writer.Flush() + if err := writer.Error(); err != nil { + return err + } + } + } + } +} + +func buildSampleRow(now time.Time, start time.Time, lastReport time.Time, lastSuccess int64, stats *clientStats, snapshot serverSnapshot) sampleRow { + started := stats.started.Load() + success := stats.success.Load() + rejected := stats.rejected.Load() + failed := stats.failed.Load() + _, avgMS, p95MS := stats.latencies.snapshot() + + elapsed := now.Sub(start).Seconds() + interval := now.Sub(lastReport).Seconds() + var successQPS float64 + if interval > 0 { + successQPS = float64(success-lastSuccess) / interval + } + + var rejectRate float64 + if started > 0 { + rejectRate = float64(rejected) / float64(started) * 100 + } + + return sampleRow{ + TimeUnixSec: now.Unix(), + ElapsedSec: elapsed, + Started: started, + Success: success, + Rejected: rejected, + Failed: failed, + SuccessQPS: successQPS, + RejectRate: rejectRate, + LatencyAvgMS: avgMS, + LatencyP95MS: p95MS, + ServerActive: snapshot.Active, + ServerMaxActive: snapshot.MaxActive, + ServerStarted: snapshot.Started, + ServerCompleted: snapshot.Completed, + } +} + +func printRow(row sampleRow) { + fmt.Printf( + "elapsed=%.0fs started=%d success=%d rejected=%d failed=%d qps=%.1f reject_rate=%.1f%% avg=%.0fms p95=%.0fms server_active=%d server_max_active=%d\n", + row.ElapsedSec, + row.Started, + row.Success, + row.Rejected, + row.Failed, + row.SuccessQPS, + row.RejectRate, + row.LatencyAvgMS, + row.LatencyP95MS, + row.ServerActive, + row.ServerMaxActive, + ) +} + +func writeRow(writer *csv.Writer, row sampleRow) error { + return writer.Write([]string{ + strconv.FormatInt(row.TimeUnixSec, 10), + strconv.FormatFloat(row.ElapsedSec, 'f', 3, 64), + strconv.FormatInt(row.Started, 10), + strconv.FormatInt(row.Success, 10), + strconv.FormatInt(row.Rejected, 10), + strconv.FormatInt(row.Failed, 10), + strconv.FormatFloat(row.SuccessQPS, 'f', 3, 64), + strconv.FormatFloat(row.RejectRate, 'f', 3, 64), + strconv.FormatFloat(row.LatencyAvgMS, 'f', 3, 64), + strconv.FormatFloat(row.LatencyP95MS, 'f', 3, 64), + strconv.FormatInt(row.ServerActive, 10), + strconv.FormatInt(row.ServerMaxActive, 10), + strconv.FormatInt(row.ServerStarted, 10), + strconv.FormatInt(row.ServerCompleted, 10), + }) +} + +func parseConfig() clientConfig { + var cfg clientConfig + flag.StringVar(&cfg.url, "url", "127.0.0.1:20001", "Triple provider URL") + flag.StringVar(&cfg.statsURL, "stats-url", "http://127.0.0.1:21001/stats", "server stats URL") + flag.IntVar(&cfg.concurrency, "concurrency", 200, "worker concurrency") + flag.DurationVar(&cfg.duration, "duration", 30*time.Second, "load duration") + flag.DurationVar(&cfg.timeout, "timeout", 3*time.Second, "per-request timeout") + flag.StringVar(&cfg.out, "out", "protect_provider_result.csv", "CSV output path, empty disables CSV") + flag.DurationVar(&cfg.reportInterval, "report-interval", time.Second, "report interval") + flag.Parse() + + if !strings.Contains(cfg.url, "://") { + cfg.url = "tri://" + cfg.url + } + return cfg +} + +func main() { + cfg := parseConfig() + cli, err := client.NewClient( + client.WithClientURL(cfg.url), + ) + if err != nil { + panic(err) + } + + svc, err := protectpb.NewProtectService( + cli, + client.WithProtocolTriple(), + client.WithClusterAdaptiveService(), + client.WithLoadBalanceP2C(), + client.WithRetries(0), + ) + if err != nil { + panic(err) + } + + ctx, cancel := context.WithTimeout(context.Background(), cfg.duration) + defer cancel() + + stats := &clientStats{} + snapshots := make(chan serverSnapshot, 1) + reportErr := make(chan error, 1) + go pollServerStats(ctx, cfg.statsURL, cfg.reportInterval, snapshots) + go func() { + reportErr <- reportLoop(ctx, cfg, stats, snapshots) + }() + + runLoad(ctx, svc, cfg, stats) + + if err := <-reportErr; err != nil { + panic(err) + } + + _, avgMS, p95MS := stats.latencies.snapshot() + started := stats.started.Load() + success := stats.success.Load() + rejected := stats.rejected.Load() + failed := stats.failed.Load() + var rejectRate float64 + if started > 0 { + rejectRate = float64(rejected) / float64(started) * 100 + } + fmt.Printf( + "final started=%d success=%d rejected=%d failed=%d reject_rate=%.1f%% avg=%.0fms p95=%.0fms out=%s\n", + started, + success, + rejected, + failed, + rejectRate, + avgMS, + p95MS, + cfg.out, + ) +} diff --git a/presee_test/adaptive_service/protect_provider/proto/protect.pb.go b/presee_test/adaptive_service/protect_provider/proto/protect.pb.go new file mode 100644 index 0000000000..401ed8a7ee --- /dev/null +++ b/presee_test/adaptive_service/protect_provider/proto/protect.pb.go @@ -0,0 +1,207 @@ +// +// Licensed to the Apache Software Foundation (ASF) under one or more +// contributor license agreements. See the NOTICE file distributed with +// this work for additional information regarding copyright ownership. +// The ASF licenses this file to You under the Apache License, Version 2.0 +// (the "License"); you may not use this file except in compliance with +// the License. You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +// Code generated by protoc-gen-go. DO NOT EDIT. +// versions: +// protoc-gen-go v1.36.11 +// protoc v3.12.4 +// source: presee_test/adaptive_service/protect_provider/proto/protect.proto + +package protectpb + +import ( + protoreflect "google.golang.org/protobuf/reflect/protoreflect" + protoimpl "google.golang.org/protobuf/runtime/protoimpl" + reflect "reflect" + sync "sync" + unsafe "unsafe" +) + +const ( + // Verify that this generated code is sufficiently up-to-date. + _ = protoimpl.EnforceVersion(20 - protoimpl.MinVersion) + // Verify that runtime/protoimpl is sufficiently up-to-date. + _ = protoimpl.EnforceVersion(protoimpl.MaxVersion - 20) +) + +type WorkRequest struct { + state protoimpl.MessageState `protogen:"open.v1"` + Name string `protobuf:"bytes,1,opt,name=name,proto3" json:"name,omitempty"` + PayloadBytes int32 `protobuf:"varint,2,opt,name=payload_bytes,json=payloadBytes,proto3" json:"payload_bytes,omitempty"` + unknownFields protoimpl.UnknownFields + sizeCache protoimpl.SizeCache +} + +func (x *WorkRequest) Reset() { + *x = WorkRequest{} + mi := &file_presee_test_adaptive_service_protect_provider_proto_protect_proto_msgTypes[0] + ms := protoimpl.X.MessageStateOf(protoimpl.Pointer(x)) + ms.StoreMessageInfo(mi) +} + +func (x *WorkRequest) String() string { + return protoimpl.X.MessageStringOf(x) +} + +func (*WorkRequest) ProtoMessage() {} + +func (x *WorkRequest) ProtoReflect() protoreflect.Message { + mi := &file_presee_test_adaptive_service_protect_provider_proto_protect_proto_msgTypes[0] + if x != nil { + ms := protoimpl.X.MessageStateOf(protoimpl.Pointer(x)) + if ms.LoadMessageInfo() == nil { + ms.StoreMessageInfo(mi) + } + return ms + } + return mi.MessageOf(x) +} + +// Deprecated: Use WorkRequest.ProtoReflect.Descriptor instead. +func (*WorkRequest) Descriptor() ([]byte, []int) { + return file_presee_test_adaptive_service_protect_provider_proto_protect_proto_rawDescGZIP(), []int{0} +} + +func (x *WorkRequest) GetName() string { + if x != nil { + return x.Name + } + return "" +} + +func (x *WorkRequest) GetPayloadBytes() int32 { + if x != nil { + return x.PayloadBytes + } + return 0 +} + +type WorkResponse struct { + state protoimpl.MessageState `protogen:"open.v1"` + Message string `protobuf:"bytes,1,opt,name=message,proto3" json:"message,omitempty"` + Sequence int64 `protobuf:"varint,2,opt,name=sequence,proto3" json:"sequence,omitempty"` + unknownFields protoimpl.UnknownFields + sizeCache protoimpl.SizeCache +} + +func (x *WorkResponse) Reset() { + *x = WorkResponse{} + mi := &file_presee_test_adaptive_service_protect_provider_proto_protect_proto_msgTypes[1] + ms := protoimpl.X.MessageStateOf(protoimpl.Pointer(x)) + ms.StoreMessageInfo(mi) +} + +func (x *WorkResponse) String() string { + return protoimpl.X.MessageStringOf(x) +} + +func (*WorkResponse) ProtoMessage() {} + +func (x *WorkResponse) ProtoReflect() protoreflect.Message { + mi := &file_presee_test_adaptive_service_protect_provider_proto_protect_proto_msgTypes[1] + if x != nil { + ms := protoimpl.X.MessageStateOf(protoimpl.Pointer(x)) + if ms.LoadMessageInfo() == nil { + ms.StoreMessageInfo(mi) + } + return ms + } + return mi.MessageOf(x) +} + +// Deprecated: Use WorkResponse.ProtoReflect.Descriptor instead. +func (*WorkResponse) Descriptor() ([]byte, []int) { + return file_presee_test_adaptive_service_protect_provider_proto_protect_proto_rawDescGZIP(), []int{1} +} + +func (x *WorkResponse) GetMessage() string { + if x != nil { + return x.Message + } + return "" +} + +func (x *WorkResponse) GetSequence() int64 { + if x != nil { + return x.Sequence + } + return 0 +} + +var File_presee_test_adaptive_service_protect_provider_proto_protect_proto protoreflect.FileDescriptor + +const file_presee_test_adaptive_service_protect_provider_proto_protect_proto_rawDesc = "" + + "\n" + + "=presee_test/adaptive_service/protect_provider/proto/protect.proto\x12\x10adaptive.protect\"F\n" + + "\vWorkRequest\x12\x12\n" + + "\x04name\x18\x01 \x01(\tR\x04name\x12#\n" + + "\rpayload_bytes\x18\x02 \x01(\x05R\fpayloadBytes\"D\n" + + "\fWorkResponse\x12\x18\n" + + "\amessage\x18\x01 \x01(\tR\amessage\x12\x1a\n" + + "\bsequence\x18\x02 \x01(\x03R\bsequence2Y\n" + + "\x0eProtectService\x12G\n" + + "\x04Work\x12\x1d.adaptive.protect.WorkRequest\x1a\x1e.adaptive.protect.WorkResponse\"\x00BXZVdubbo.apache.org/dubbo-go/v3/presee_test/adaptive_service/protect_provider/proto;protectpbb\x06proto3" + +var ( + file_presee_test_adaptive_service_protect_provider_proto_protect_proto_rawDescOnce sync.Once + file_presee_test_adaptive_service_protect_provider_proto_protect_proto_rawDescData []byte +) + +func file_presee_test_adaptive_service_protect_provider_proto_protect_proto_rawDescGZIP() []byte { + file_presee_test_adaptive_service_protect_provider_proto_protect_proto_rawDescOnce.Do(func() { + file_presee_test_adaptive_service_protect_provider_proto_protect_proto_rawDescData = protoimpl.X.CompressGZIP(unsafe.Slice(unsafe.StringData(file_presee_test_adaptive_service_protect_provider_proto_protect_proto_rawDesc), len(file_presee_test_adaptive_service_protect_provider_proto_protect_proto_rawDesc))) + }) + return file_presee_test_adaptive_service_protect_provider_proto_protect_proto_rawDescData +} + +var file_presee_test_adaptive_service_protect_provider_proto_protect_proto_msgTypes = make([]protoimpl.MessageInfo, 2) +var file_presee_test_adaptive_service_protect_provider_proto_protect_proto_goTypes = []any{ + (*WorkRequest)(nil), // 0: adaptive.protect.WorkRequest + (*WorkResponse)(nil), // 1: adaptive.protect.WorkResponse +} +var file_presee_test_adaptive_service_protect_provider_proto_protect_proto_depIdxs = []int32{ + 0, // 0: adaptive.protect.ProtectService.Work:input_type -> adaptive.protect.WorkRequest + 1, // 1: adaptive.protect.ProtectService.Work:output_type -> adaptive.protect.WorkResponse + 1, // [1:2] is the sub-list for method output_type + 0, // [0:1] is the sub-list for method input_type + 0, // [0:0] is the sub-list for extension type_name + 0, // [0:0] is the sub-list for extension extendee + 0, // [0:0] is the sub-list for field type_name +} + +func init() { file_presee_test_adaptive_service_protect_provider_proto_protect_proto_init() } +func file_presee_test_adaptive_service_protect_provider_proto_protect_proto_init() { + if File_presee_test_adaptive_service_protect_provider_proto_protect_proto != nil { + return + } + type x struct{} + out := protoimpl.TypeBuilder{ + File: protoimpl.DescBuilder{ + GoPackagePath: reflect.TypeOf(x{}).PkgPath(), + RawDescriptor: unsafe.Slice(unsafe.StringData(file_presee_test_adaptive_service_protect_provider_proto_protect_proto_rawDesc), len(file_presee_test_adaptive_service_protect_provider_proto_protect_proto_rawDesc)), + NumEnums: 0, + NumMessages: 2, + NumExtensions: 0, + NumServices: 1, + }, + GoTypes: file_presee_test_adaptive_service_protect_provider_proto_protect_proto_goTypes, + DependencyIndexes: file_presee_test_adaptive_service_protect_provider_proto_protect_proto_depIdxs, + MessageInfos: file_presee_test_adaptive_service_protect_provider_proto_protect_proto_msgTypes, + }.Build() + File_presee_test_adaptive_service_protect_provider_proto_protect_proto = out.File + file_presee_test_adaptive_service_protect_provider_proto_protect_proto_goTypes = nil + file_presee_test_adaptive_service_protect_provider_proto_protect_proto_depIdxs = nil +} diff --git a/presee_test/adaptive_service/protect_provider/proto/protect.proto b/presee_test/adaptive_service/protect_provider/proto/protect.proto new file mode 100644 index 0000000000..559296f322 --- /dev/null +++ b/presee_test/adaptive_service/protect_provider/proto/protect.proto @@ -0,0 +1,36 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +syntax = "proto3"; + +package adaptive.protect; + +option go_package = "dubbo.apache.org/dubbo-go/v3/presee_test/adaptive_service/protect_provider/proto;protectpb"; + +message WorkRequest { + string name = 1; + int32 payload_bytes = 2; +} + +message WorkResponse { + string message = 1; + int64 sequence = 2; +} + +service ProtectService { + rpc Work(WorkRequest) returns (WorkResponse) {} +} diff --git a/presee_test/adaptive_service/protect_provider/proto/protect.triple.go b/presee_test/adaptive_service/protect_provider/proto/protect.triple.go new file mode 100644 index 0000000000..9dda45a1e1 --- /dev/null +++ b/presee_test/adaptive_service/protect_provider/proto/protect.triple.go @@ -0,0 +1,145 @@ +// +// Licensed to the Apache Software Foundation (ASF) under one or more +// contributor license agreements. See the NOTICE file distributed with +// this work for additional information regarding copyright ownership. +// The ASF licenses this file to You under the Apache License, Version 2.0 +// (the "License"); you may not use this file except in compliance with +// the License. You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +// Code generated by protoc-gen-triple. DO NOT EDIT. +// +// Source: presee_test/adaptive_service/protect_provider/proto/protect.proto +package protectpb + +import ( + client "dubbo.apache.org/dubbo-go/v3/client" + common "dubbo.apache.org/dubbo-go/v3/common" + constant "dubbo.apache.org/dubbo-go/v3/common/constant" + triple_protocol "dubbo.apache.org/dubbo-go/v3/protocol/triple/triple_protocol" + server "dubbo.apache.org/dubbo-go/v3/server" +) + +import ( + "context" + "reflect" +) + +import ( + "dubbo.apache.org/dubbo-go/v3" +) + +// This is a compile-time assertion to ensure that this generated file and the Triple package +// are compatible. If you get a compiler error that this constant is not defined, this code was +// generated with a version of Triple newer than the one compiled into your binary. You can fix the +// problem by either regenerating this code with an older version of Triple or updating the Triple +// version compiled into your binary. +const _ = triple_protocol.IsAtLeastVersion0_1_0 + +const ( + // ProtectServiceName is the fully-qualified name of the ProtectService service. + ProtectServiceName = "adaptive.protect.ProtectService" +) + +// These constants are the fully-qualified names of the RPCs defined in this package. They're +// exposed at runtime as procedure and as the final two segments of the HTTP route. +// +// Note that these are different from the fully-qualified method names used by +// google.golang.org/protobuf/reflect/protoreflect. To convert from these constants to +// reflection-formatted method names, remove the leading slash and convert the remaining slash to a +// period. +const ( + // ProtectServiceWorkProcedure is the fully-qualified name of the ProtectService's Work RPC. + ProtectServiceWorkProcedure = "/adaptive.protect.ProtectService/Work" +) + +var ( + _ ProtectService = (*ProtectServiceImpl)(nil) +) + +// ProtectService is a client for the adaptive.protect.ProtectService service. +type ProtectService interface { + Work(ctx context.Context, req *WorkRequest, opts ...client.CallOption) (*WorkResponse, error) +} + +// NewProtectService constructs a client for the protectpb.ProtectService service. +func NewProtectService(cli *client.Client, opts ...client.ReferenceOption) (ProtectService, error) { + conn, err := cli.DialWithInfo("adaptive.protect.ProtectService", &ProtectService_ClientInfo, opts...) + if err != nil { + return nil, err + } + return &ProtectServiceImpl{ + conn: conn, + }, nil +} + +func SetConsumerProtectService(srv common.RPCService) { + dubbo.SetConsumerServiceWithInfo(srv, &ProtectService_ClientInfo) +} + +// ProtectServiceImpl implements ProtectService. +type ProtectServiceImpl struct { + conn *client.Connection +} + +func (c *ProtectServiceImpl) Work(ctx context.Context, req *WorkRequest, opts ...client.CallOption) (*WorkResponse, error) { + resp := new(WorkResponse) + if err := c.conn.CallUnary(ctx, []interface{}{req}, resp, "Work", opts...); err != nil { + return nil, err + } + return resp, nil +} + +var ProtectService_ClientInfo = client.ClientInfo{ + InterfaceName: "adaptive.protect.ProtectService", + MethodNames: []string{"Work"}, + ConnectionInjectFunc: func(dubboCliRaw interface{}, conn *client.Connection) { + dubboCli := dubboCliRaw.(*ProtectServiceImpl) + dubboCli.conn = conn + }, +} + +// ProtectServiceHandler is an implementation of the adaptive.protect.ProtectService service. +type ProtectServiceHandler interface { + Work(context.Context, *WorkRequest) (*WorkResponse, error) +} + +func RegisterProtectServiceHandler(srv *server.Server, hdlr ProtectServiceHandler, opts ...server.ServiceOption) error { + return srv.Register(hdlr, &ProtectService_ServiceInfo, opts...) +} + +func SetProviderProtectService(srv common.RPCService) { + dubbo.SetProviderServiceWithInfo(srv, &ProtectService_ServiceInfo) +} + +var ProtectService_ServiceInfo = server.ServiceInfo{ + InterfaceName: "adaptive.protect.ProtectService", + ServiceType: (*ProtectServiceHandler)(nil), + Methods: []server.MethodInfo{ + { + Name: "Work", + Type: constant.CallUnary, + ReqInitFunc: func() interface{} { + return new(WorkRequest) + }, + MethodFunc: func(ctx context.Context, args []interface{}, handler interface{}) (interface{}, error) { + req := args[0].(*WorkRequest) + res, err := handler.(ProtectServiceHandler).Work(ctx, req) + if err != nil { + return nil, err + } + return triple_protocol.NewResponse(res), nil + }, + Meta: map[string]interface{}{ + "response.type": reflect.TypeOf(new(WorkResponse)), + }, + }, + }, +} diff --git a/presee_test/adaptive_service/protect_provider/server/main.go b/presee_test/adaptive_service/protect_provider/server/main.go new file mode 100644 index 0000000000..d575dcbcdc --- /dev/null +++ b/presee_test/adaptive_service/protect_provider/server/main.go @@ -0,0 +1,161 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package main + +import ( + "context" + "encoding/json" + "flag" + "fmt" + "net/http" + "sync/atomic" + "time" +) + +import ( + "github.com/dubbogo/gost/log/logger" +) + +import ( + _ "dubbo.apache.org/dubbo-go/v3/imports" + protectpb "dubbo.apache.org/dubbo-go/v3/presee_test/adaptive_service/protect_provider/proto" + "dubbo.apache.org/dubbo-go/v3/protocol" + "dubbo.apache.org/dubbo-go/v3/server" +) + +type ProtectServer struct { + workDelay time.Duration + stats *serverStats +} + +type serverStats struct { + active atomic.Int64 + maxActive atomic.Int64 + started atomic.Int64 + completed atomic.Int64 + totalLatencyNS atomic.Int64 +} + +type statsResponse struct { + Active int64 `json:"active"` + MaxActive int64 `json:"max_active"` + Started int64 `json:"started"` + Completed int64 `json:"completed"` + WorkMS int64 `json:"work_ms"` + AvgHandlerLatencyMS float64 `json:"avg_handler_latency_ms"` +} + +func (s *ProtectServer) Work(_ context.Context, req *protectpb.WorkRequest) (*protectpb.WorkResponse, error) { + start := time.Now() + seq := s.stats.started.Add(1) + s.stats.begin() + defer s.stats.end(start) + + time.Sleep(s.workDelay) + + return &protectpb.WorkResponse{ + Message: "ok:" + req.GetName(), + Sequence: seq, + }, nil +} + +func (s *serverStats) begin() int64 { + current := s.active.Add(1) + for { + oldMax := s.maxActive.Load() + if current <= oldMax { + return current + } + if s.maxActive.CompareAndSwap(oldMax, current) { + return current + } + } +} + +func (s *serverStats) end(start time.Time) { + s.active.Add(-1) + s.completed.Add(1) + s.totalLatencyNS.Add(time.Since(start).Nanoseconds()) +} + +func serveStats(addr string, stats *serverStats, workDelay time.Duration) error { + mux := http.NewServeMux() + mux.HandleFunc("/stats", func(w http.ResponseWriter, _ *http.Request) { + completed := stats.completed.Load() + var avgHandlerLatencyMS float64 + if completed > 0 { + avgHandlerLatencyMS = float64(stats.totalLatencyNS.Load()) / float64(completed) / float64(time.Millisecond) + } + + w.Header().Set("Content-Type", "application/json") + if err := json.NewEncoder(w).Encode(statsResponse{ + Active: stats.active.Load(), + MaxActive: stats.maxActive.Load(), + Started: stats.started.Load(), + Completed: completed, + WorkMS: workDelay.Milliseconds(), + AvgHandlerLatencyMS: avgHandlerLatencyMS, + }); err != nil { + logger.Warnf("write stats response failed: %v", err) + } + }) + + return http.ListenAndServe(addr, mux) +} + +func main() { + port := flag.Int("port", 20001, "Triple service port") + statsPort := flag.Int("stats-port", 21001, "HTTP stats port") + workMS := flag.Int("work-ms", 200, "handler work duration in milliseconds") + flag.Parse() + + workDelay := time.Duration(*workMS) * time.Millisecond + stats := &serverStats{} + provider := &ProtectServer{ + workDelay: workDelay, + stats: stats, + } + + statsAddr := fmt.Sprintf("127.0.0.1:%d", *statsPort) + go func() { + logger.Infof("stats listening at http://%s/stats", statsAddr) + if err := serveStats(statsAddr, stats, workDelay); err != nil { + logger.Errorf("stats server stopped: %v", err) + } + }() + + srv, err := server.NewServer( + server.WithServerProtocol( + protocol.WithTriple(), + protocol.WithPort(*port), + ), + server.WithServerAdaptiveService(), + ) + if err != nil { + panic(err) + } + + if err := protectpb.RegisterProtectServiceHandler(srv, provider); err != nil { + panic(err) + } + + logger.Infof("protect provider listening at tri://127.0.0.1:%d", *port) + if err := srv.Serve(); err != nil { + panic(err) + } +} diff --git a/presee_test/adaptive_service/rtt_shrink/README.md b/presee_test/adaptive_service/rtt_shrink/README.md new file mode 100644 index 0000000000..a7a797b2ad --- /dev/null +++ b/presee_test/adaptive_service/rtt_shrink/README.md @@ -0,0 +1,65 @@ +# Adaptive Service RTT Shrink Sample + +This sample verifies that provider-side adaptive service shrinks the method limiter after handler RTT increases. + +The verification does not depend on log files or response attachments. The server exposes `GET /stats`, which reads the provider filter middleware limiter through `adaptivesvc.GetMethodLimiterSnapshot` and returns the current `limiter_limitation`. + +## Run + +Start the provider: + +```bash +go run ./presee_test/adaptive_service/rtt_shrink/server \ + -port 20002 \ + -stats-port 21002 \ + -stages fast:20:30s,medium:100:20s,slow:500:30s +``` + +Start the client: + +```bash +go run ./presee_test/adaptive_service/rtt_shrink/client \ + -url 127.0.0.1:20002 \ + -stats-url http://127.0.0.1:21002/stats \ + -concurrency 200 \ + -duration 60s +``` + +The client writes `rtt_shrink_result.csv` by default. Use `-out ""` to disable CSV output. The `latency_avg_ms` and `latency_p95_ms` columns are calculated from successful requests in the current report interval, not from all successful requests since startup. + +For backward-compatible two-stage runs, the server also supports: + +```bash +go run ./presee_test/adaptive_service/rtt_shrink/server \ + -port 20002 \ + -stats-port 21002 \ + -work-ms 50 \ + -slow-after 20s \ + -slow-work-ms 300 +``` + +## Success Signals + +- `phase` changes across the configured stages. +- `latency_avg_ms` and `latency_p95_ms` increase in higher-latency stages. +- `limiter_found` is `true`. +- During the slow phase, `limiter_limitation` drops below the fast-phase peak or stable value. +- `rejected` increases because adaptive service rejects requests at the provider-side limiter. +- `failed` stays close to `0`. +- `server_active` is controlled by the limiter and does not grow without bound with client concurrency. + +## Useful Stats + +`GET http://127.0.0.1:21002/stats` returns: + +- `phase` +- `work_ms` +- `active` +- `max_active` +- `started` +- `completed` +- `avg_handler_latency_ms` +- `limiter_found` +- `limiter_inflight` +- `limiter_remaining` +- `limiter_limitation` diff --git a/presee_test/adaptive_service/rtt_shrink/client/main.go b/presee_test/adaptive_service/rtt_shrink/client/main.go new file mode 100644 index 0000000000..18918a39a0 --- /dev/null +++ b/presee_test/adaptive_service/rtt_shrink/client/main.go @@ -0,0 +1,472 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package main + +import ( + "context" + "encoding/csv" + "encoding/json" + "flag" + "fmt" + "math" + "net/http" + "os" + "sort" + "strconv" + "strings" + "sync" + "sync/atomic" + "time" +) + +import ( + "github.com/dubbogo/gost/log/logger" +) + +import ( + "dubbo.apache.org/dubbo-go/v3/client" + clsutils "dubbo.apache.org/dubbo-go/v3/cluster/utils" + _ "dubbo.apache.org/dubbo-go/v3/imports" + protectpb "dubbo.apache.org/dubbo-go/v3/presee_test/adaptive_service/protect_provider/proto" +) + +type clientConfig struct { + url string + statsURL string + concurrency int + duration time.Duration + timeout time.Duration + out string + reportInterval time.Duration +} + +type clientStats struct { + started atomic.Int64 + success atomic.Int64 + rejected atomic.Int64 + failed atomic.Int64 + latencies latencyRecorder + intervalLatencies latencyRecorder +} + +type latencyRecorder struct { + mu sync.Mutex + values []time.Duration +} + +type serverSnapshot struct { + Phase string `json:"phase"` + WorkMS int64 `json:"work_ms"` + Active int64 `json:"active"` + MaxActive int64 `json:"max_active"` + Started int64 `json:"started"` + Completed int64 `json:"completed"` + AvgHandlerLatencyMS float64 `json:"avg_handler_latency_ms"` + LimiterFound bool `json:"limiter_found"` + LimiterInflight uint64 `json:"limiter_inflight"` + LimiterRemaining uint64 `json:"limiter_remaining"` + LimiterLimitation uint64 `json:"limiter_limitation"` +} + +type sampleRow struct { + TimeUnixSec int64 + ElapsedSec float64 + Phase string + Started int64 + Success int64 + Rejected int64 + Failed int64 + SuccessQPS float64 + RejectRate float64 + LatencyAvgMS float64 + LatencyP95MS float64 + ServerActive int64 + ServerMaxActive int64 + ServerWorkMS int64 + LimiterFound bool + LimiterLimitation uint64 + LimiterRemaining uint64 + LimiterInflight uint64 +} + +func (r *latencyRecorder) record(d time.Duration) { + r.mu.Lock() + defer r.mu.Unlock() + r.values = append(r.values, d) +} + +func (r *latencyRecorder) snapshot(reset bool) (count int, avgMS float64, p95MS float64) { + r.mu.Lock() + defer r.mu.Unlock() + + count = len(r.values) + if count == 0 { + return 0, 0, 0 + } + + values := append([]time.Duration(nil), r.values...) + if reset { + r.values = nil + } + sort.Slice(values, func(i, j int) bool { + return values[i] < values[j] + }) + + var total time.Duration + for _, value := range values { + total += value + } + avgMS = float64(total) / float64(count) / float64(time.Millisecond) + p95Index := int(math.Ceil(float64(count)*0.95)) - 1 + if p95Index < 0 { + p95Index = 0 + } + p95MS = float64(values[p95Index]) / float64(time.Millisecond) + return count, avgMS, p95MS +} + +func runLoad(ctx context.Context, svc protectpb.ProtectService, cfg clientConfig, stats *clientStats) { + var wg sync.WaitGroup + wg.Add(cfg.concurrency) + + for workerID := 0; workerID < cfg.concurrency; workerID++ { + go func(workerID int) { + defer wg.Done() + for { + select { + case <-ctx.Done(): + return + default: + } + + seq := stats.started.Add(1) + reqCtx, cancel := context.WithTimeout(ctx, cfg.timeout) + start := time.Now() + _, err := svc.Work(reqCtx, &protectpb.WorkRequest{ + Name: fmt.Sprintf("worker-%d-%d", workerID, seq), + }) + cancel() + + if err == nil { + stats.success.Add(1) + latency := time.Since(start) + stats.latencies.record(latency) + stats.intervalLatencies.record(latency) + continue + } + if isAdaptiveReject(err) { + stats.rejected.Add(1) + continue + } + if ctx.Err() != nil { + return + } + stats.failed.Add(1) + } + }(workerID) + } + + wg.Wait() +} + +func isAdaptiveReject(err error) bool { + return clsutils.DoesAdaptiveServiceReachLimitation(err) +} + +func pollServerStats(ctx context.Context, statsURL string, interval time.Duration, sink chan<- serverSnapshot) { + ticker := time.NewTicker(interval) + defer ticker.Stop() + + httpClient := &http.Client{Timeout: interval} + warned := false + for { + select { + case <-ctx.Done(): + return + case <-ticker.C: + } + + req, err := http.NewRequestWithContext(ctx, http.MethodGet, statsURL, nil) + if err != nil { + if !warned { + logger.Warnf("build stats request failed: %v", err) + warned = true + } + continue + } + + resp, err := httpClient.Do(req) + if err != nil { + if !warned { + logger.Warnf("poll server stats failed: %v", err) + warned = true + } + continue + } + + var snapshot serverSnapshot + err = json.NewDecoder(resp.Body).Decode(&snapshot) + closeErr := resp.Body.Close() + if err != nil { + if !warned { + logger.Warnf("decode server stats failed: %v", err) + warned = true + } + continue + } + if closeErr != nil { + if !warned { + logger.Warnf("close stats response failed: %v", closeErr) + } + warned = true + } else { + warned = false + } + + select { + case sink <- snapshot: + case <-ctx.Done(): + return + default: + } + } +} + +func reportLoop(ctx context.Context, cfg clientConfig, stats *clientStats, snapshots <-chan serverSnapshot) error { + var file *os.File + var writer *csv.Writer + if cfg.out != "" { + var err error + file, err = os.Create(cfg.out) + if err != nil { + return err + } + defer file.Close() + + writer = csv.NewWriter(file) + defer writer.Flush() + if err := writer.Write([]string{ + "time_unix", "elapsed_sec", "phase", "started", "success", "rejected", "failed", "success_qps", + "reject_rate", "latency_avg_ms", "latency_p95_ms", "server_active", "server_max_active", + "server_work_ms", "limiter_found", "limiter_limitation", "limiter_remaining", "limiter_inflight", + }); err != nil { + return err + } + } + + start := time.Now() + ticker := time.NewTicker(cfg.reportInterval) + defer ticker.Stop() + + lastSuccess := int64(0) + lastReport := start + var snapshot serverSnapshot + + for { + select { + case nextSnapshot := <-snapshots: + snapshot = nextSnapshot + continue + default: + } + + select { + case <-ctx.Done(): + return nil + case nextSnapshot := <-snapshots: + snapshot = nextSnapshot + case now := <-ticker.C: + row := buildSampleRow(now, start, lastReport, lastSuccess, stats, snapshot) + lastReport = now + lastSuccess = row.Success + printRow(row) + if writer != nil { + if err := writeRow(writer, row); err != nil { + return err + } + writer.Flush() + if err := writer.Error(); err != nil { + return err + } + } + } + } +} + +func buildSampleRow(now time.Time, start time.Time, lastReport time.Time, lastSuccess int64, stats *clientStats, snapshot serverSnapshot) sampleRow { + started := stats.started.Load() + success := stats.success.Load() + rejected := stats.rejected.Load() + failed := stats.failed.Load() + _, avgMS, p95MS := stats.intervalLatencies.snapshot(true) + + elapsed := now.Sub(start).Seconds() + interval := now.Sub(lastReport).Seconds() + var successQPS float64 + if interval > 0 { + successQPS = float64(success-lastSuccess) / interval + } + + var rejectRate float64 + if started > 0 { + rejectRate = float64(rejected) / float64(started) * 100 + } + + return sampleRow{ + TimeUnixSec: now.Unix(), + ElapsedSec: elapsed, + Phase: snapshot.Phase, + Started: started, + Success: success, + Rejected: rejected, + Failed: failed, + SuccessQPS: successQPS, + RejectRate: rejectRate, + LatencyAvgMS: avgMS, + LatencyP95MS: p95MS, + ServerActive: snapshot.Active, + ServerMaxActive: snapshot.MaxActive, + ServerWorkMS: snapshot.WorkMS, + LimiterFound: snapshot.LimiterFound, + LimiterLimitation: snapshot.LimiterLimitation, + LimiterRemaining: snapshot.LimiterRemaining, + LimiterInflight: snapshot.LimiterInflight, + } +} + +func printRow(row sampleRow) { + fmt.Printf( + "elapsed=%.0fs phase=%s started=%d success=%d rejected=%d failed=%d qps=%.1f reject_rate=%.1f%% avg=%.0fms p95=%.0fms server_active=%d server_max_active=%d work_ms=%d limiter_found=%t limiter_limitation=%d limiter_remaining=%d limiter_inflight=%d\n", + row.ElapsedSec, + row.Phase, + row.Started, + row.Success, + row.Rejected, + row.Failed, + row.SuccessQPS, + row.RejectRate, + row.LatencyAvgMS, + row.LatencyP95MS, + row.ServerActive, + row.ServerMaxActive, + row.ServerWorkMS, + row.LimiterFound, + row.LimiterLimitation, + row.LimiterRemaining, + row.LimiterInflight, + ) +} + +func writeRow(writer *csv.Writer, row sampleRow) error { + return writer.Write([]string{ + strconv.FormatInt(row.TimeUnixSec, 10), + strconv.FormatFloat(row.ElapsedSec, 'f', 3, 64), + row.Phase, + strconv.FormatInt(row.Started, 10), + strconv.FormatInt(row.Success, 10), + strconv.FormatInt(row.Rejected, 10), + strconv.FormatInt(row.Failed, 10), + strconv.FormatFloat(row.SuccessQPS, 'f', 3, 64), + strconv.FormatFloat(row.RejectRate, 'f', 3, 64), + strconv.FormatFloat(row.LatencyAvgMS, 'f', 3, 64), + strconv.FormatFloat(row.LatencyP95MS, 'f', 3, 64), + strconv.FormatInt(row.ServerActive, 10), + strconv.FormatInt(row.ServerMaxActive, 10), + strconv.FormatInt(row.ServerWorkMS, 10), + strconv.FormatBool(row.LimiterFound), + strconv.FormatUint(row.LimiterLimitation, 10), + strconv.FormatUint(row.LimiterRemaining, 10), + strconv.FormatUint(row.LimiterInflight, 10), + }) +} + +func parseConfig() clientConfig { + var cfg clientConfig + flag.StringVar(&cfg.url, "url", "127.0.0.1:20002", "Triple provider URL") + flag.StringVar(&cfg.statsURL, "stats-url", "http://127.0.0.1:21002/stats", "server stats URL") + flag.IntVar(&cfg.concurrency, "concurrency", 200, "worker concurrency") + flag.DurationVar(&cfg.duration, "duration", 60*time.Second, "load duration") + flag.DurationVar(&cfg.timeout, "timeout", 3*time.Second, "per-request timeout") + flag.StringVar(&cfg.out, "out", "rtt_shrink_result.csv", "CSV output path, empty disables CSV") + flag.DurationVar(&cfg.reportInterval, "report-interval", time.Second, "report interval") + flag.Parse() + + if !strings.Contains(cfg.url, "://") { + cfg.url = "tri://" + cfg.url + } + return cfg +} + +func main() { + cfg := parseConfig() + cli, err := client.NewClient( + client.WithClientURL(cfg.url), + ) + if err != nil { + panic(err) + } + + svc, err := protectpb.NewProtectService( + cli, + client.WithProtocolTriple(), + client.WithClusterAdaptiveService(), + client.WithLoadBalanceP2C(), + client.WithRetries(0), + ) + if err != nil { + panic(err) + } + + ctx, cancel := context.WithTimeout(context.Background(), cfg.duration) + defer cancel() + + stats := &clientStats{} + snapshots := make(chan serverSnapshot, 1) + reportErr := make(chan error, 1) + go pollServerStats(ctx, cfg.statsURL, cfg.reportInterval, snapshots) + go func() { + reportErr <- reportLoop(ctx, cfg, stats, snapshots) + }() + + runLoad(ctx, svc, cfg, stats) + + if err := <-reportErr; err != nil { + panic(err) + } + + _, avgMS, p95MS := stats.latencies.snapshot(false) + started := stats.started.Load() + success := stats.success.Load() + rejected := stats.rejected.Load() + failed := stats.failed.Load() + var rejectRate float64 + if started > 0 { + rejectRate = float64(rejected) / float64(started) * 100 + } + fmt.Printf( + "final started=%d success=%d rejected=%d failed=%d reject_rate=%.1f%% avg=%.0fms p95=%.0fms out=%s\n", + started, + success, + rejected, + failed, + rejectRate, + avgMS, + p95MS, + cfg.out, + ) +} diff --git a/presee_test/adaptive_service/rtt_shrink/server/main.go b/presee_test/adaptive_service/rtt_shrink/server/main.go new file mode 100644 index 0000000000..39b3e2c791 --- /dev/null +++ b/presee_test/adaptive_service/rtt_shrink/server/main.go @@ -0,0 +1,256 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package main + +import ( + "context" + "encoding/json" + "flag" + "fmt" + "net/http" + "strconv" + "strings" + "sync/atomic" + "time" +) + +import ( + "github.com/dubbogo/gost/log/logger" +) + +import ( + "dubbo.apache.org/dubbo-go/v3/filter/adaptivesvc" + _ "dubbo.apache.org/dubbo-go/v3/imports" + protectpb "dubbo.apache.org/dubbo-go/v3/presee_test/adaptive_service/protect_provider/proto" + "dubbo.apache.org/dubbo-go/v3/protocol" + "dubbo.apache.org/dubbo-go/v3/server" +) + +type ShrinkServer struct { + start time.Time + stages []workStage + stats *serverStats +} + +type workStage struct { + name string + delay time.Duration + duration time.Duration +} + +type serverStats struct { + active atomic.Int64 + maxActive atomic.Int64 + started atomic.Int64 + completed atomic.Int64 + totalLatencyNS atomic.Int64 +} + +type statsResponse struct { + Phase string `json:"phase"` + WorkMS int64 `json:"work_ms"` + Active int64 `json:"active"` + MaxActive int64 `json:"max_active"` + Started int64 `json:"started"` + Completed int64 `json:"completed"` + AvgHandlerLatencyMS float64 `json:"avg_handler_latency_ms"` + LimiterFound bool `json:"limiter_found"` + LimiterInflight uint64 `json:"limiter_inflight"` + LimiterRemaining uint64 `json:"limiter_remaining"` + LimiterLimitation uint64 `json:"limiter_limitation"` +} + +func (s *ShrinkServer) Work(_ context.Context, req *protectpb.WorkRequest) (*protectpb.WorkResponse, error) { + start := time.Now() + seq := s.stats.started.Add(1) + s.stats.begin() + defer s.stats.end(start) + + time.Sleep(s.currentStage(start).delay) + + return &protectpb.WorkResponse{ + Message: "ok:" + req.GetName(), + Sequence: seq, + }, nil +} + +func (s *ShrinkServer) currentDelay(now time.Time) time.Duration { + return s.currentStage(now).delay +} + +func (s *ShrinkServer) phase(now time.Time) string { + return s.currentStage(now).name +} + +func (s *ShrinkServer) currentStage(now time.Time) workStage { + elapsed := now.Sub(s.start) + var passed time.Duration + for _, stage := range s.stages { + passed += stage.duration + if elapsed < passed { + return stage + } + } + return s.stages[len(s.stages)-1] +} + +func (s *serverStats) begin() int64 { + current := s.active.Add(1) + for { + oldMax := s.maxActive.Load() + if current <= oldMax { + return current + } + if s.maxActive.CompareAndSwap(oldMax, current) { + return current + } + } +} + +func (s *serverStats) end(start time.Time) { + s.active.Add(-1) + s.completed.Add(1) + s.totalLatencyNS.Add(time.Since(start).Nanoseconds()) +} + +func serveStats(addr string, provider *ShrinkServer) error { + mux := http.NewServeMux() + mux.HandleFunc("/stats", func(w http.ResponseWriter, _ *http.Request) { + now := time.Now() + completed := provider.stats.completed.Load() + var avgHandlerLatencyMS float64 + if completed > 0 { + avgHandlerLatencyMS = float64(provider.stats.totalLatencyNS.Load()) / float64(completed) / float64(time.Millisecond) + } + + limiterSnapshot, limiterFound := adaptivesvc.GetMethodLimiterSnapshot(protectpb.ProtectServiceName, "Work") + w.Header().Set("Content-Type", "application/json") + if err := json.NewEncoder(w).Encode(statsResponse{ + Phase: provider.phase(now), + WorkMS: provider.currentDelay(now).Milliseconds(), + Active: provider.stats.active.Load(), + MaxActive: provider.stats.maxActive.Load(), + Started: provider.stats.started.Load(), + Completed: completed, + AvgHandlerLatencyMS: avgHandlerLatencyMS, + LimiterFound: limiterFound, + LimiterInflight: limiterSnapshot.Inflight, + LimiterRemaining: limiterSnapshot.Remaining, + LimiterLimitation: limiterSnapshot.Limitation, + }); err != nil { + logger.Warnf("write stats response failed: %v", err) + } + }) + + return http.ListenAndServe(addr, mux) +} + +func main() { + port := flag.Int("port", 20002, "Triple service port") + statsPort := flag.Int("stats-port", 21002, "HTTP stats port") + workMS := flag.Int("work-ms", 50, "fast phase handler work duration in milliseconds") + slowAfter := flag.Duration("slow-after", 20*time.Second, "duration before switching to slow phase") + slowWorkMS := flag.Int("slow-work-ms", 300, "slow phase handler work duration in milliseconds") + stagesFlag := flag.String("stages", "", "comma-separated phases as name:work_ms:duration, for example fast:20:30s,medium:100:20s,slow:500:30s") + flag.Parse() + + stages, err := parseStages(*stagesFlag, *workMS, *slowAfter, *slowWorkMS) + if err != nil { + panic(err) + } + + provider := &ShrinkServer{ + start: time.Now(), + stages: stages, + stats: &serverStats{}, + } + + statsAddr := fmt.Sprintf("127.0.0.1:%d", *statsPort) + go func() { + logger.Infof("stats listening at http://%s/stats", statsAddr) + if serveErr := serveStats(statsAddr, provider); serveErr != nil { + logger.Errorf("stats server stopped: %v", serveErr) + } + }() + + srv, err := server.NewServer( + server.WithServerProtocol( + protocol.WithTriple(), + protocol.WithPort(*port), + ), + server.WithServerAdaptiveService(), + ) + if err != nil { + panic(err) + } + + if err := protectpb.RegisterProtectServiceHandler(srv, provider); err != nil { + panic(err) + } + + logger.Infof("rtt shrink provider listening at tri://127.0.0.1:%d", *port) + if err := srv.Serve(); err != nil { + panic(err) + } +} + +func parseStages(stagesFlag string, workMS int, slowAfter time.Duration, slowWorkMS int) ([]workStage, error) { + if strings.TrimSpace(stagesFlag) == "" { + return []workStage{ + { + name: "fast", + delay: time.Duration(workMS) * time.Millisecond, + duration: slowAfter, + }, + { + name: "slow", + delay: time.Duration(slowWorkMS) * time.Millisecond, + duration: time.Duration(1<<63 - 1), + }, + }, nil + } + + parts := strings.Split(stagesFlag, ",") + stages := make([]workStage, 0, len(parts)) + for _, part := range parts { + fields := strings.Split(strings.TrimSpace(part), ":") + if len(fields) != 3 { + return nil, fmt.Errorf("invalid stage %q, want name:work_ms:duration", part) + } + workMS, err := strconv.Atoi(fields[1]) + if err != nil { + return nil, fmt.Errorf("invalid work_ms in stage %q: %w", part, err) + } + duration, err := time.ParseDuration(fields[2]) + if err != nil { + return nil, fmt.Errorf("invalid duration in stage %q: %w", part, err) + } + if duration <= 0 { + return nil, fmt.Errorf("stage %q duration must be positive", part) + } + stages = append(stages, workStage{ + name: fields[0], + delay: time.Duration(workMS) * time.Millisecond, + duration: duration, + }) + } + if len(stages) == 0 { + return nil, fmt.Errorf("at least one stage is required") + } + return stages, nil +} diff --git a/protocol/base/base_exporter.go b/protocol/base/base_exporter.go index c844befdf9..ea2621e7d7 100644 --- a/protocol/base/base_exporter.go +++ b/protocol/base/base_exporter.go @@ -56,7 +56,7 @@ func (de *BaseExporter) GetInvoker() Invoker { // UnExport un export service. func (de *BaseExporter) UnExport() { - logger.Infof("Exporter unexport.") + logger.Info("[Protocol][Exporter] exporter unexport.") de.invoker.Destroy() de.exporterMap.Delete(de.key) } diff --git a/protocol/base/base_invoker.go b/protocol/base/base_invoker.go index c253faad10..e7ffd53241 100644 --- a/protocol/base/base_invoker.go +++ b/protocol/base/base_invoker.go @@ -111,7 +111,7 @@ func (bi *BaseInvoker) Invoke(context context.Context, invocation Invocation) re // Destroy changes available and destroyed flag and release the url's allocated memory func (bi *BaseInvoker) Destroy() { - logger.Infof("Destroy invoker: %s", bi.GetURL()) + logger.Infof("[Protocol][Invoker] destroy invoker, url=%s", bi.GetURL()) bi.destroyed.Store(true) bi.available.Store(false) if url := bi.url.Load(); url != nil { diff --git a/protocol/base/rpc_status.go b/protocol/base/rpc_status.go index 4402e654bb..093d939dd6 100644 --- a/protocol/base/rpc_status.go +++ b/protocol/base/rpc_status.go @@ -211,14 +211,14 @@ func GetInvokerHealthyStatus(invoker Invoker) bool { // SetInvokerUnhealthyStatus add target invoker to black list func SetInvokerUnhealthyStatus(invoker Invoker) { invokerBlackList.Store(invoker.GetURL().GetCacheInvokerMapKey(), invoker) - logger.Info("Add invoker ip = ", invoker.GetURL().Location, " to black list") + logger.Infof("[Protocol] add invoker to black list, ip=%s", invoker.GetURL().Location) blackListCacheDirty.Store(true) } // RemoveInvokerUnhealthyStatus remove unhealthy status of target invoker from blacklist func RemoveInvokerUnhealthyStatus(invoker Invoker) { invokerBlackList.Delete(invoker.GetURL().GetCacheInvokerMapKey()) - logger.Info("Remove invoker ip = ", invoker.GetURL().Location, " from black list") + logger.Infof("[Protocol] remove invoker from black list, ip=%s", invoker.GetURL().Location) blackListCacheDirty.Store(true) } @@ -238,7 +238,7 @@ func GetBlackListInvokers(blockSize int) []Invoker { // RemoveUrlKeyUnhealthyStatus called when event of provider unregister, delete from black list func RemoveUrlKeyUnhealthyStatus(key string) { invokerBlackList.Delete(key) - logger.Info("Remove invoker key = ", key, " from black list") + logger.Infof("[Protocol] remove invoker from black list, key=%s", key) blackListCacheDirty.Store(true) } @@ -258,7 +258,7 @@ func TryRefreshBlackList() { }() ivks := GetBlackListInvokers(constant.DefaultBlackListRecoverBlock) - logger.Debug("blackList len = ", len(ivks)) + logger.Debugf("[Protocol] blackList len=%d", len(ivks)) for i := 0; i < 3; i++ { wg.Add(1) diff --git a/protocol/dubbo/dubbo_codec.go b/protocol/dubbo/dubbo_codec.go index 338ec7e57a..00ca3ae291 100644 --- a/protocol/dubbo/dubbo_codec.go +++ b/protocol/dubbo/dubbo_codec.go @@ -60,7 +60,7 @@ func (c *DubboCodec) EncodeRequest(request *remoting.Request) (*bytes.Buffer, er invoc, ok := request.Data.(*base.Invocation) if !ok { err := perrors.Errorf("encode request failed for parameter type :%+v", request) - logger.Errorf(err.Error()) + logger.Errorf("[Dubbo][Codec] decode failed, err=%v", err) return nil, err } invocation := *invoc @@ -207,7 +207,7 @@ func (c *DubboCodec) decodeRequest(data []byte) (*remoting.Request, int, error) if originErr == hessian.ErrBodyNotEnough { return nil, hessian.HEADER_LENGTH + pkg.GetBodyLen(), nil } - logger.Errorf("pkg.Unmarshal(len(@data):%d) = error:%+v", buf.Len(), err) + logger.Errorf("[Dubbo][Codec] pkg.Unmarshal failed, dataLen=%d, err=%v", buf.Len(), err) return request, 0, perrors.WithStack(err) } @@ -260,7 +260,7 @@ func (c *DubboCodec) decodeResponse(data []byte) (*remoting.Response, int, error return nil, hessian.HEADER_LENGTH + pkg.GetBodyLen(), nil } - logger.Warnf("pkg.Unmarshal(len(@data):%d) = error:%+v", buf.Len(), err) + logger.Warnf("[Dubbo][Codec] pkg.Unmarshal failed, dataLen=%d, err=%v", buf.Len(), err) return nil, 0, perrors.WithStack(err) } response := &remoting.Response{ @@ -273,19 +273,19 @@ func (c *DubboCodec) decodeResponse(data []byte) (*remoting.Response, int, error var pkgerr error if pkg.Header.Type&impl.PackageHeartbeat != 0x00 { if pkg.Header.Type&impl.PackageResponse != 0x00 { - logger.Debugf("get rpc heartbeat response{header: %#v, body: %#v}", pkg.Header, pkg.Body) + logger.Debugf("[Dubbo][Codec] get rpc heartbeat response, header=%#v, body=%#v", pkg.Header, pkg.Body) if pkg.Err != nil { - logger.Errorf("rpc heartbeat response{error: %#v}", pkg.Err) + logger.Errorf("[Dubbo][Codec] rpc heartbeat response, err=%v", pkg.Err) pkgerr = pkg.Err } } else { - logger.Debugf("get rpc heartbeat request{header: %#v, service: %#v, body: %#v}", pkg.Header, pkg.Service, pkg.Body) + logger.Debugf("[Dubbo][Codec] get rpc heartbeat request, header=%#v, service=%#v, body=%#v", pkg.Header, pkg.Service, pkg.Body) response.Status = hessian.Response_OK // reply(session, p, hessian.PackageHeartbeat) } return response, hessian.HEADER_LENGTH + pkg.Header.BodyLen, pkgerr } - logger.Debugf("get rpc response{header: %#v, body: %#v}", pkg.Header, pkg.Body) + logger.Debugf("[Dubbo][Codec] get rpc response, header=%#v, body=%#v", pkg.Header, pkg.Body) rpcResult := &result.RPCResult{} response.Result = rpcResult if pkg.Header.Type&impl.PackageRequest == 0x00 { diff --git a/protocol/dubbo/dubbo_exporter.go b/protocol/dubbo/dubbo_exporter.go index 57618e877f..11dcf2b197 100644 --- a/protocol/dubbo/dubbo_exporter.go +++ b/protocol/dubbo/dubbo_exporter.go @@ -48,7 +48,7 @@ func (de *DubboExporter) UnExport() { interfaceName := de.GetInvoker().GetURL().GetParam(constant.InterfaceKey, "") err := common.ServiceMap.UnRegister(interfaceName, DUBBO, de.GetInvoker().GetURL().ServiceKey()) if err != nil { - logger.Errorf("[DubboExporter.UnExport] error: %v", err) + logger.Errorf("[Dubbo][Exporter] unexport failed, err=%v", err) } de.BaseExporter.UnExport() } diff --git a/protocol/dubbo/dubbo_invoker.go b/protocol/dubbo/dubbo_invoker.go index 3dfe1c009c..2cc5abed48 100644 --- a/protocol/dubbo/dubbo_invoker.go +++ b/protocol/dubbo/dubbo_invoker.go @@ -97,7 +97,7 @@ func (di *DubboInvoker) Invoke(ctx context.Context, ivc base.Invocation) result. if !di.BaseInvoker.IsAvailable() { // Generally, the case will not happen, because the invoker has been removed // from the invoker list before destroy,so no new request will enter the destroyed invoker - logger.Warnf("this dubboInvoker is destroyed") + logger.Warnf("[Dubbo][Invoker] this dubbo invoker is destroyed") res.SetError(base.ErrDestroyedInvoker) return &res } @@ -105,7 +105,7 @@ func (di *DubboInvoker) Invoke(ctx context.Context, ivc base.Invocation) result. client := di.getClient() if client == nil { res.SetError(base.ErrClientClosed) - logger.Debugf("result.Err: %v", res.Error()) + logger.Debug("[Dubbo][Invoker] result err, err=%v", res.Error()) return &res } @@ -129,7 +129,7 @@ func (di *DubboInvoker) Invoke(ctx context.Context, ivc base.Invocation) result. // async async, err := strconv.ParseBool(inv.GetAttachmentWithDefaultValue(constant.AsyncKey, "false")) if err != nil { - logger.Errorf("ParseBool - error: %v", err) + logger.Errorf("[Dubbo][Invoker] parse bool failed, err=%v", err) async = false } // response := NewResponse(inv.Reply(), nil) @@ -212,7 +212,7 @@ func (di *DubboInvoker) appendCtx(ctx context.Context, ivc *invocation.RPCInvoca if currentSpan != nil { err := injectTraceCtx(currentSpan, ivc) if err != nil { - logger.Errorf("Could not inject the span context into attachments: %v", err) + logger.Errorf("[Dubbo][Invoker] could not inject the span context into attachments, err=%v", err) } } } diff --git a/protocol/dubbo/dubbo_protocol.go b/protocol/dubbo/dubbo_protocol.go index 3f0de43d09..4b1a9020e3 100644 --- a/protocol/dubbo/dubbo_protocol.go +++ b/protocol/dubbo/dubbo_protocol.go @@ -82,7 +82,7 @@ func (dp *DubboProtocol) Export(invoker base.Invoker) base.Exporter { serviceKey := url.ServiceKey() exporter := NewDubboExporter(serviceKey, invoker, dp.ExporterMap()) dp.SetExporterMap(serviceKey, exporter) - logger.Infof("[DUBBO Protocol] Export service: %s", url.String()) + logger.Infof("[Dubbo] export service, url=%s", url.String()) // start server dp.openServer(url) return exporter @@ -92,18 +92,18 @@ func (dp *DubboProtocol) Export(invoker base.Invoker) base.Exporter { func (dp *DubboProtocol) Refer(url *common.URL) base.Invoker { exchangeClient := getExchangeClient(url) if exchangeClient == nil { - logger.Warnf("can't dial the server: %+v", url.Location) + logger.Warnf("[Dubbo] can't dial the server, location=%v", url.Location) return nil } invoker := NewDubboInvoker(url, exchangeClient) dp.SetInvokers(invoker) - logger.Infof("[DUBBO Protocol] Refer service: %s", url.String()) + logger.Infof("[Dubbo] refer service, url=%s", url.String()) return invoker } // Destroy destroy dubbo service. func (dp *DubboProtocol) Destroy() { - logger.Infof("DubboProtocol destroy.") + logger.Infof("[Dubbo] dubbo protocol destroy.") dp.BaseProtocol.Destroy() @@ -149,7 +149,7 @@ func doHandleRequest(rpcInvocation *invocation.RPCInvocation) result.RPCResult { result := result.RPCResult{} if exporter == nil { err := fmt.Errorf("don't have this exporter, key: %s", rpcInvocation.ServiceKey()) - logger.Errorf(err.Error()) + logger.Errorf("[Dubbo] decode failed, err=%v", err) result.Err = err // reply(session, p, hessian.PackageResponse) return result diff --git a/protocol/dubbo/hessian2/hessian_request.go b/protocol/dubbo/hessian2/hessian_request.go index 42481a3043..83cfdc237c 100644 --- a/protocol/dubbo/hessian2/hessian_request.go +++ b/protocol/dubbo/hessian2/hessian_request.go @@ -132,16 +132,16 @@ func packRequest(service Service, header DubboHeader, req any) ([]byte, error) { // dubbo version + path + version + method if err = encoder.Encode(DEFAULT_DUBBO_PROTOCOL_VERSION); err != nil { - logger.Warnf("Encode(DEFAULT_DUBBO_PROTOCOL_VERSION) = error: %v", err) + logger.Warnf("[Dubbo][Hessian2] encode default dubbo protocol version failed, err=%v", err) } if err = encoder.Encode(service.Path); err != nil { - logger.Warnf("Encode(service.Path) = error: %v", err) + logger.Warnf("[Dubbo][Hessian2] encode service path failed, err=%v", err) } if err = encoder.Encode(service.Version); err != nil { - logger.Warnf("Encode(service.Version) = error: %v", err) + logger.Warnf("[Dubbo][Hessian2] encode service version failed, err=%v", err) } if err = encoder.Encode(service.Method); err != nil { - logger.Warnf("Encode(service.Method) = error: %v", err) + logger.Warnf("[Dubbo][Hessian2] encode service method failed, err=%v", err) } // args = args type list + args value list @@ -171,7 +171,7 @@ END: byteArray = encoder.Buffer() pkgLen = len(byteArray) if pkgLen > int(DEFAULT_LEN) { // recommand 8M - logger.Warnf("Data length %d too large, recommand max payload %d. "+ + logger.Warnf("[Dubbo][Hessian2] data length %d too large, recommand max payload %d. "+ "Dubbo java can't handle the package whose size is greater than %d!!!", pkgLen, DEFAULT_LEN, DEFAULT_LEN) } // byteArray{body length} diff --git a/protocol/dubbo/hessian2/hessian_response.go b/protocol/dubbo/hessian2/hessian_response.go index c7f5da20e4..b3dc37f8e8 100644 --- a/protocol/dubbo/hessian2/hessian_response.go +++ b/protocol/dubbo/hessian2/hessian_response.go @@ -141,7 +141,7 @@ func packResponse(header DubboHeader, ret any) ([]byte, error) { if header.ResponseStatus == Response_OK { if hb { if err := encoder.Encode(nil); err != nil { - logger.Warnf("Encode(nil) = %v", err) + logger.Warnf("[Dubbo][Hessian2] encode nil failed, err=%v", err) } } else { atta := isSupportResponseAttachment(response.Attachments[DUBBO_VERSION_KEY]) @@ -213,7 +213,7 @@ func packResponse(header DubboHeader, ret any) ([]byte, error) { byteArray = hessian.EncNull(byteArray) // if not, "java client" will throw exception "unexpected end of file" pkgLen := len(byteArray) if pkgLen > int(DEFAULT_LEN) { // recommand 8M - logger.Warnf("Data length %d too large, recommand max payload %d. "+ + logger.Warnf("[Dubbo][Hessian2] data length %d too large, recommand max payload %d. "+ "Dubbo java can't handle the package whose size greater than %d!!!", pkgLen, DEFAULT_LEN, DEFAULT_LEN) } // byteArray{body length} diff --git a/protocol/dubbo/impl/codec.go b/protocol/dubbo/impl/codec.go index f629f9133c..9998f66ba6 100644 --- a/protocol/dubbo/impl/codec.go +++ b/protocol/dubbo/impl/codec.go @@ -166,7 +166,7 @@ func (c *ProtocolCodec) Decode(p *DubboPackage) error { return err } if p.IsResponseWithException() { - logger.Infof("response with exception: %+v", p.Header) + logger.Infof("[Dubbo] response with exception, header=%v", p.Header) decoder := hessian.NewDecoder(body) p.Body = &ResponsePayload{} exception, err := decoder.Decode() @@ -234,7 +234,7 @@ func packRequest(p DubboPackage, serializer Serializer) ([]byte, error) { } pkgLen = len(body) if pkgLen > int(DEFAULT_LEN) { // recommand 8M - logger.Warnf("Data length %d too large, recommand max payload %d. "+ + logger.Warnf("[Dubbo] data length %d too large, recommand max payload %d. "+ "Dubbo java can't handle the package whose size is greater than %d!!!", pkgLen, DEFAULT_LEN, DEFAULT_LEN) } byteArray = append(byteArray, body...) @@ -272,7 +272,7 @@ func packResponse(p DubboPackage, serializer Serializer) ([]byte, error) { pkgLen := len(body) if pkgLen > int(DEFAULT_LEN) { // recommand 8M - logger.Warnf("Data length %d too large, recommand max payload %d. "+ + logger.Warnf("[Dubbo] data length %d too large, recommand max payload %d. "+ "Dubbo java can't handle the package whose size is greater than %d!!!", pkgLen, DEFAULT_LEN, DEFAULT_LEN) } // byteArray{body length} diff --git a/protocol/dubbo/impl/hessian.go b/protocol/dubbo/impl/hessian.go index d541366727..76fae02969 100644 --- a/protocol/dubbo/impl/hessian.go +++ b/protocol/dubbo/impl/hessian.go @@ -133,7 +133,7 @@ func marshalRequest(encoder *hessian.Encoder, p DubboPackage) ([]byte, error) { args, ok := request.Params.([]any) if !ok { - logger.Infof("request args are: %+v", request.Params) + logger.Infof("[Dubbo] request args, params=%v", request.Params) return nil, perrors.Errorf("@params is not of type: []any") } types, err := GetArgsTypeList(args) diff --git a/protocol/dubbo3/dubbo3_exporter.go b/protocol/dubbo3/dubbo3_exporter.go index d151b99043..2b018b7214 100644 --- a/protocol/dubbo3/dubbo3_exporter.go +++ b/protocol/dubbo3/dubbo3_exporter.go @@ -54,7 +54,7 @@ func (de *DubboExporter) UnExport() { interfaceName := url.GetParam(constant.InterfaceKey, "") err := common.ServiceMap.UnRegister(interfaceName, tripleConstant.TRIPLE, url.ServiceKey()) if err != nil { - logger.Errorf("[DubboExporter.UnExport] error: %v", err) + logger.Errorf("[Dubbo3][Exporter] unexport failed, err=%v", err) } de.serviceMap.Delete(interfaceName) de.BaseExporter.UnExport() diff --git a/protocol/dubbo3/dubbo3_invoker.go b/protocol/dubbo3/dubbo3_invoker.go index cc058cd073..f23c15375f 100644 --- a/protocol/dubbo3/dubbo3_invoker.go +++ b/protocol/dubbo3/dubbo3_invoker.go @@ -113,7 +113,7 @@ func NewDubboInvoker(url *common.URL) (*DubboInvoker, error) { if tracingConfRaw, ok := url.GetAttribute(constant.TracingConfigKey); ok { tracingConfig, ok := tracingConfRaw.(*global.TracingConfig) if !ok { - logger.Warnf("invalid tracing config type %T, expected *global.TracingConfig", tracingConfRaw) + logger.Warnf("[Dubbo3] invalid tracing config type %T, expected *global.TracingConfig", tracingConfRaw) } else if tracingConfig != nil { if tracingConfig.Name == "jaeger" { serviceName := tracingConfig.ServiceName @@ -125,7 +125,7 @@ func NewDubboInvoker(url *common.URL) (*DubboInvoker, error) { useAgent = *tracingConfig.UseAgent } if serviceName == "" { - logger.Warnf("jaeger tracing skipped: no service name available for %s", url.String()) + logger.Warnf("[Dubbo3] jaeger tracing skipped: no service name available for %s", url.String()) } else { opts = append(opts, triConfig.WithJaegerConfig( tracingConfig.Address, @@ -134,7 +134,7 @@ func NewDubboInvoker(url *common.URL) (*DubboInvoker, error) { )) } } else { - logger.Warnf("unsupported tracing name %s, now triple only support jaeger", tracingConfig.Name) + logger.Warnf("[Dubbo3] unsupported tracing name %s, now triple only support jaeger", tracingConfig.Name) } } } @@ -145,7 +145,7 @@ func NewDubboInvoker(url *common.URL) (*DubboInvoker, error) { // use global TLSConfig handle tls tlsConf, ok := tlsConfRaw.(*global.TLSConfig) if !ok { - logger.Errorf("DUBBO3 Client initialized the TLSConfig configuration failed") + logger.Errorf("[Dubbo3] DUBBO3 Client initialized the TLSConfig configuration failed") return nil, errors.New("DUBBO3 Client initialized the TLSConfig configuration failed") } if dubbotls.IsClientTLSValid(tlsConf) { @@ -153,7 +153,7 @@ func NewDubboInvoker(url *common.URL) (*DubboInvoker, error) { triOption.TLSCertFile = tlsConf.TLSCertFile triOption.TLSKeyFile = tlsConf.TLSKeyFile triOption.TLSServerName = tlsConf.TLSServerName - logger.Infof("DUBBO3 Server initialized the TLSConfig configuration") + logger.Infof("[Dubbo3] DUBBO3 Server initialized the TLSConfig configuration") } } client, err := triple.NewTripleClient(consumerService, triOption) @@ -193,7 +193,7 @@ func (di *DubboInvoker) Invoke(ctx context.Context, invocation base.Invocation) if !di.BaseInvoker.IsAvailable() { // Generally, the case will not happen, because the invoker has been removed // from the invoker list before destroy,so no new request will enter the destroyed invoker - logger.Warnf("this dubboInvoker is destroyed") + logger.Warnf("[Dubbo3] this dubboInvoker is destroyed") result.Err = base.ErrDestroyedInvoker return &result } @@ -209,7 +209,7 @@ func (di *DubboInvoker) Invoke(ctx context.Context, invocation base.Invocation) if !di.BaseInvoker.IsAvailable() { // Generally, the case will not happen, because the invoker has been removed // from the invoker list before destroy,so no new request will enter the destroyed invoker - logger.Warnf("this grpcInvoker is destroying") + logger.Warnf("[Dubbo3] this grpcInvoker is destroying") result.Err = base.ErrDestroyedInvoker return &result } @@ -242,7 +242,7 @@ func (di *DubboInvoker) Invoke(ctx context.Context, invocation base.Invocation) gRPCMD.Set(k, str...) continue } - logger.Warnf("[Triple Protocol]Triple attachment value with key = %s is invalid, which should be string or []string", k) + logger.Warnf("[Dubbo3] triple attachment value with key=%s is invalid, which should be string or []string", k) } ctx = metadata.NewOutgoingContext(ctx, gRPCMD) ctx = context.WithValue(ctx, tripleConstant.InterfaceKey, di.BaseInvoker.GetURL().GetParam(constant.InterfaceKey, "")) diff --git a/protocol/dubbo3/dubbo3_protocol.go b/protocol/dubbo3/dubbo3_protocol.go index da878e8472..4e97702f82 100644 --- a/protocol/dubbo3/dubbo3_protocol.go +++ b/protocol/dubbo3/dubbo3_protocol.go @@ -84,7 +84,7 @@ func (dp *DubboProtocol) Export(invoker base.Invoker) base.Exporter { service = rpcService } if service == nil { - panic(fmt.Sprintf("[Triple Protocol] no rpc service found in url attribute %s for service key: %s", constant.RpcServiceKey, key)) + panic(fmt.Sprintf("[Dubbo3] no rpc service found in url attribute %s for service key: %s", constant.RpcServiceKey, key)) } serializationType := url.GetParam(constant.SerializationKey, constant.ProtobufSerialization) @@ -93,7 +93,7 @@ func (dp *DubboProtocol) Export(invoker base.Invoker) base.Exporter { if serializationType == constant.ProtobufSerialization { m, ok := reflect.TypeOf(service).MethodByName("XXX_SetProxyImpl") if !ok { - logger.Errorf("PB service with key = %s is not support XXX_SetProxyImpl to pb."+ + logger.Errorf("[Dubbo3] PB service with key=%s is not support XXX_SetProxyImpl to pb. "+ "Please run go install github.com/dubbogo/dubbogo-cli/cmd/protoc-gen-go-triple@latest to update your "+ "protoc-gen-go-triple and re-generate your pb file again.", key) return nil @@ -128,7 +128,7 @@ func (dp *DubboProtocol) Export(invoker base.Invoker) base.Exporter { exporter := NewDubboExporter(serviceKey, invoker, dp.ExporterMap(), dp.serviceMap) dp.SetExporterMap(serviceKey, exporter) - logger.Infof("[Triple Protocol] Export service: %s", url.String()) + logger.Infof("[Dubbo3] Export service: %s", url.String()) dp.serviceMap.Store(url.GetParam(constant.InterfaceKey, ""), service) @@ -141,11 +141,11 @@ func (dp *DubboProtocol) Export(invoker base.Invoker) base.Exporter { func (dp *DubboProtocol) Refer(url *common.URL) base.Invoker { invoker, err := NewDubboInvoker(url) if err != nil { - logger.Errorf("Refer url = %+v, with error = %s", url, err.Error()) + logger.Errorf("[Dubbo3] Refer url=%v, err=%v", url, err) return nil } dp.SetInvokers(invoker) - logger.Infof("[Triple Protocol] Refer service: %s", url.String()) + logger.Infof("[Dubbo3] Refer service: %s", url.String()) return invoker } @@ -231,7 +231,7 @@ func (dp *DubboProtocol) openServer(url *common.URL, tripleCodecType tripleConst if tracingConfRaw, tracingAttrOk := url.GetAttribute(constant.TracingConfigKey); tracingAttrOk { tracingConfig, tracingConfigOk := tracingConfRaw.(*global.TracingConfig) if !tracingConfigOk { - logger.Warnf("invalid tracing config type %T, expected *global.TracingConfig", tracingConfRaw) + logger.Warnf("[Dubbo3] invalid tracing config type %T, expected *global.TracingConfig", tracingConfRaw) } else if tracingConfig != nil { if tracingConfig.Name == "jaeger" { serviceName := tracingConfig.ServiceName @@ -243,7 +243,7 @@ func (dp *DubboProtocol) openServer(url *common.URL, tripleCodecType tripleConst useAgent = *tracingConfig.UseAgent } if serviceName == "" { - logger.Warnf("jaeger tracing skipped: no service name available for %s", url.String()) + logger.Warnf("[Dubbo3] jaeger tracing skipped: no service name available for %s", url.String()) } else { opts = append(opts, triConfig.WithJaegerConfig( tracingConfig.Address, @@ -252,7 +252,7 @@ func (dp *DubboProtocol) openServer(url *common.URL, tripleCodecType tripleConst )) } } else { - logger.Warnf("unsupported tracing name %s, now triple only support jaeger", tracingConfig.Name) + logger.Warnf("[Dubbo3] unsupported tracing name %s, now triple only support jaeger", tracingConfig.Name) } } } @@ -274,7 +274,7 @@ func (dp *DubboProtocol) openServer(url *common.URL, tripleCodecType tripleConst // use global TLSConfig handle tls tlsConf, RawOk := tlsConfRaw.(*global.TLSConfig) if !RawOk { - logger.Errorf("DUBBO3 Server initialized the TLSConfig configuration failed") + logger.Errorf("[Dubbo3] DUBBO3 Server initialized the TLSConfig configuration failed") return } if dubbotls.IsServerTLSValid(tlsConf) { @@ -282,7 +282,7 @@ func (dp *DubboProtocol) openServer(url *common.URL, tripleCodecType tripleConst triOption.TLSCertFile = tlsConf.TLSCertFile triOption.TLSKeyFile = tlsConf.TLSKeyFile triOption.TLSServerName = tlsConf.TLSServerName - logger.Infof("DUBBO3 Server initialized the TLSConfig configuration") + logger.Infof("[Dubbo3] DUBBO3 Server initialized the TLSConfig configuration") } } diff --git a/protocol/grpc/client.go b/protocol/grpc/client.go index 62c6002eda..4e327860a9 100644 --- a/protocol/grpc/client.go +++ b/protocol/grpc/client.go @@ -97,7 +97,7 @@ func NewClient(url *common.URL) (*Client, error) { // use global TLSConfig handle tls tlsConf, ok := tlsConfRaw.(*global.TLSConfig) if !ok { - logger.Errorf("Grpc Client initialized the TLSConfig configuration failed") + logger.Error("[GRPC][Client] grpc client initialized the TLSConfig configuration failed") return nil, errors.New("DUBBO3 Client initialized the TLSConfig configuration failed") } @@ -107,7 +107,7 @@ func NewClient(url *common.URL) (*Client, error) { return nil, err } if cfg != nil { - logger.Infof("Grpc Client initialized the TLSConfig configuration") + logger.Info("[GRPC][Client] grpc client initialized the TLSConfig configuration") transportCreds = credentials.NewTLS(cfg) } } @@ -116,7 +116,7 @@ func NewClient(url *common.URL) (*Client, error) { conn, err := grpc.Dial(url.Location, dialOpts...) if err != nil { - logger.Errorf("grpc dial error: %v", err) + logger.Errorf("[GRPC][Client] grpc dial failed, err=%v", err) return nil, err } @@ -132,7 +132,7 @@ func NewClient(url *common.URL) (*Client, error) { invoker := getInvoker(consumerService, conn) if invoker == nil { err := fmt.Errorf("grpc client invoker is nil, interface=%s", key) - logger.Errorf("failed to get grpc client invoker: %v", err) + logger.Errorf("[GRPC][Client] failed to get grpc client invoker, err=%v", err) conn.Close() return nil, err } @@ -164,16 +164,16 @@ func clientInit(url *common.URL) { } protocolConf, ok := protocolConfRaw.(map[string]*global.ProtocolConfig) if !ok { - logger.Warnf("protocolConfig assert failed") + logger.Warn("[GRPC][Client] protocolConfig assert failed") return } if protocolConf == nil { - logger.Warnf("protocolConfig is nil") + logger.Warn("[GRPC][Client] protocolConfig is nil") return } grpcConf := protocolConf[GRPC] if grpcConf == nil { - logger.Warnf("grpcConf is nil") + logger.Warn("[GRPC][Client] grpcConf is nil") return } grpcConfByte, err := yaml.Marshal(grpcConf) diff --git a/protocol/grpc/grpc_exporter.go b/protocol/grpc/grpc_exporter.go index febd88b884..bada52a3c0 100644 --- a/protocol/grpc/grpc_exporter.go +++ b/protocol/grpc/grpc_exporter.go @@ -48,7 +48,7 @@ func (gg *GrpcExporter) UnExport() { interfaceName := gg.GetInvoker().GetURL().GetParam(constant.InterfaceKey, "") err := common.ServiceMap.UnRegister(interfaceName, GRPC, gg.GetInvoker().GetURL().ServiceKey()) if err != nil { - logger.Errorf("[GrpcExporter.UnExport] error: %v", err) + logger.Errorf("[GRPC][Exporter] unexport failed, err=%v", err) } gg.BaseExporter.UnExport() } diff --git a/protocol/grpc/grpc_invoker.go b/protocol/grpc/grpc_invoker.go index 25b76aac49..1144e4918b 100644 --- a/protocol/grpc/grpc_invoker.go +++ b/protocol/grpc/grpc_invoker.go @@ -87,7 +87,7 @@ func (gi *GrpcInvoker) Invoke(ctx context.Context, invocation base.Invocation) r if !gi.BaseInvoker.IsAvailable() { // Generally, the case will not happen, because the invoker has been removed // from the invoker list before destroy,so no new request will enter the destroyed invoker - logger.Warnf("this grpcInvoker is destroyed") + logger.Warn("[GRPC][Invoker] this grpcInvoker is destroyed") result.SetError(base.ErrDestroyedInvoker) return &result } @@ -183,7 +183,7 @@ func (gi *GrpcInvoker) startHealthWatch(handler gracefulshutdown.ClosingEventHan healthClient := grpc_health_v1.NewHealthClient(client.ClientConn) stream, err := healthClient.Watch(ctx, &grpc_health_v1.HealthCheckRequest{Service: gi.GetURL().ServiceKey()}) if err != nil { - logger.Debugf("[GRPC Protocol] health watch start failed for %s: %v", gi.GetURL().String(), err) + logger.Debugf("[GRPC][Invoker] health watch start failed, url=%s err=%v", gi.GetURL().String(), err) return } @@ -191,7 +191,7 @@ func (gi *GrpcInvoker) startHealthWatch(handler gracefulshutdown.ClosingEventHan resp, recvErr := stream.Recv() if recvErr != nil { if ctx.Err() == nil { - logger.Debugf("[GRPC Protocol] health watch recv failed for %s: %v", gi.GetURL().String(), recvErr) + logger.Debugf("[GRPC][Invoker] health watch recv failed, url=%s err=%v", gi.GetURL().String(), recvErr) } return } diff --git a/protocol/grpc/grpc_protocol.go b/protocol/grpc/grpc_protocol.go index 0955bf2bb0..7c4fc8d8c2 100644 --- a/protocol/grpc/grpc_protocol.go +++ b/protocol/grpc/grpc_protocol.go @@ -92,7 +92,7 @@ func (gp *GrpcProtocol) Export(invoker base.Invoker) base.Exporter { serviceKey := url.ServiceKey() exporter := NewGrpcExporter(serviceKey, invoker, gp.ExporterMap()) gp.SetExporterMap(serviceKey, exporter) - logger.Infof("[GRPC Protocol] Export service: %s", url.String()) + logger.Infof("[GRPC] export service, url=%s", url.String()) srv := gp.openServer(url) srv.SetServingStatus(serviceKey, grpc_health_v1.HealthCheckResponse_SERVING) return exporter @@ -120,18 +120,18 @@ func (gp *GrpcProtocol) openServer(url *common.URL) *Server { func (gp *GrpcProtocol) Refer(url *common.URL) base.Invoker { client, err := NewClient(url) if err != nil { - logger.Warnf("can't dial the server: %s", url.Key()) + logger.Warnf("[GRPC] can't dial the server, url=%s", url.Key()) return nil } invoker := NewGrpcInvoker(url, client) gp.SetInvokers(invoker) - logger.Infof("[GRPC Protcol] Refer service: %s", url.String()) + logger.Infof("[GRPC] refer service, url=%s", url.String()) return invoker } // Destroy will destroy gRPC all invoker and exporter, so it only is called once. func (gp *GrpcProtocol) Destroy() { - logger.Infof("GrpcProtocol destroy.") + logger.Info("[GRPC] grpc protocol destroy.") for _, server := range gp.drainServers() { grpcServerGracefulStop(server) diff --git a/protocol/grpc/server.go b/protocol/grpc/server.go index 9c1b31e89e..64582af72c 100644 --- a/protocol/grpc/server.go +++ b/protocol/grpc/server.go @@ -124,7 +124,7 @@ func (s *Server) Start(url *common.URL) { // use global TLSConfig handle tls tlsConf, ok := tlsConfRaw.(*global.TLSConfig) if !ok { - logger.Errorf("gRPC Server initialized the TLSConfig configuration failed") + logger.Error("[GRPC][Server] gRPC server initialized the TLSConfig configuration failed") return } if dubbotls.IsServerTLSValid(tlsConf) { @@ -133,7 +133,7 @@ func (s *Server) Start(url *common.URL) { return } if cfg != nil { - logger.Infof("gRPC Server initialized the TLSConfig configuration") + logger.Info("[GRPC][Server] gRPC server initialized the TLSConfig configuration") transportCreds = credentials.NewTLS(cfg) } } @@ -148,7 +148,7 @@ func (s *Server) Start(url *common.URL) { go func() { providerServices := getProviderServices(url) if providerServices == nil { - logger.Error("no provider service found") + logger.Error("[GRPC][Server] no provider service found") return } // wait all exporter ready, then set proxy impl and grpc registerService @@ -156,7 +156,7 @@ func (s *Server) Start(url *common.URL) { registerService(providerServices, server) reflection.Register(server) if err := server.Serve(lis); err != nil { - logger.Errorf("server serve failed with err: %v", err) + logger.Errorf("[GRPC][Server] server serve failed, err=%v", err) } }() } @@ -190,7 +190,7 @@ func getProviderServices(url *common.URL) map[string]*global.ServiceConfig { if providerConf, ok := providerConfRaw.(*global.ProviderConfig); ok && providerConf != nil { return providerConf.Services } - logger.Error("illegal provider config") + logger.Error("[GRPC][Server] illegal provider config") } return nil } diff --git a/protocol/jsonrpc/http.go b/protocol/jsonrpc/http.go index ceefa0f853..39c8e1aa02 100644 --- a/protocol/jsonrpc/http.go +++ b/protocol/jsonrpc/http.go @@ -127,7 +127,7 @@ func (c *HTTPClient) Call(ctx context.Context, service *common.URL, req *Request if span := opentracing.SpanFromContext(ctx); span != nil { err := opentracing.GlobalTracer().Inject(span.Context(), opentracing.HTTPHeaders, opentracing.HTTPHeadersCarrier(httpHeader)) if err != nil { - logger.Error("Could not inject the Context into http header.") + logger.Error("[Jsonrpc] could not inject the Context into http header.") } } diff --git a/protocol/jsonrpc/jsonrpc_exporter.go b/protocol/jsonrpc/jsonrpc_exporter.go index 39b303c266..cd474e2523 100644 --- a/protocol/jsonrpc/jsonrpc_exporter.go +++ b/protocol/jsonrpc/jsonrpc_exporter.go @@ -48,7 +48,7 @@ func (je *JsonrpcExporter) UnExport() { interfaceName := je.GetInvoker().GetURL().GetParam(constant.InterfaceKey, "") err := common.ServiceMap.UnRegister(interfaceName, JSONRPC, je.GetInvoker().GetURL().ServiceKey()) if err != nil { - logger.Errorf("[JsonrpcExporter.UnExport] error: %v", err) + logger.Errorf("[Jsonrpc][Exporter] unexport failed, err=%v", err) } je.BaseExporter.UnExport() } diff --git a/protocol/jsonrpc/jsonrpc_invoker.go b/protocol/jsonrpc/jsonrpc_invoker.go index a707f7b22e..8fcc57e954 100644 --- a/protocol/jsonrpc/jsonrpc_invoker.go +++ b/protocol/jsonrpc/jsonrpc_invoker.go @@ -63,7 +63,7 @@ func (ji *JsonrpcInvoker) Invoke(ctx context.Context, inv base.Invocation) resul if result.Err == nil { result.Rest = rpcInv.Reply() } - logger.Debugf("result.Err: %v, result.Rest: %v", result.Err, result.Rest) + logger.Debugf("[Jsonrpc][Invoker] invoke result, err=%v, rest=%v", result.Err, result.Rest) return &result } diff --git a/protocol/jsonrpc/jsonrpc_protocol.go b/protocol/jsonrpc/jsonrpc_protocol.go index 8eec7f4b21..0cb26198d0 100644 --- a/protocol/jsonrpc/jsonrpc_protocol.go +++ b/protocol/jsonrpc/jsonrpc_protocol.go @@ -69,7 +69,7 @@ func (jp *JsonrpcProtocol) Export(invoker base.Invoker) base.Exporter { exporter := NewJsonrpcExporter(serviceKey, invoker, jp.ExporterMap()) jp.SetExporterMap(serviceKey, exporter) - logger.Infof("[JSONRPC protocol] Export service: %s", url.String()) + logger.Infof("[Jsonrpc] Export service: %s", url.String()) // start server jp.openServer(url) @@ -92,13 +92,13 @@ func (jp *JsonrpcProtocol) Refer(url *common.URL) base.Invoker { HTTPTimeout: requestTimeout, })) jp.SetInvokers(invoker) - logger.Infof("[JSONRPC Protocol] Refer service: %s", url.String()) + logger.Infof("[Jsonrpc] Refer service: %s", url.String()) return invoker } // Destroy will destroy all invoker and exporter, so it only is called once. func (jp *JsonrpcProtocol) Destroy() { - logger.Infof("jsonrpcProtocol destroy.") + logger.Infof("[Jsonrpc] jsonrpcProtocol destroy.") jp.BaseProtocol.Destroy() diff --git a/protocol/jsonrpc/server.go b/protocol/jsonrpc/server.go index 5157d523e8..1a4c36b52e 100644 --- a/protocol/jsonrpc/server.go +++ b/protocol/jsonrpc/server.go @@ -81,7 +81,7 @@ func NewServer() *Server { func (s *Server) handlePkg(conn net.Conn) { defer func() { if r := recover(); r != nil { - logger.Warnf("connection{local:%v, remote:%v} panic error:%#v, debug stack:%s", + logger.Warnf("[Jsonrpc][Server] connection panic, local=%v, remote=%v, err=%v, debug stack=%s", conn.LocalAddr(), conn.RemoteAddr(), r, string(debug.Stack())) } @@ -95,7 +95,7 @@ func (s *Server) handlePkg(conn net.Conn) { } if err := conn.SetDeadline(t); err != nil { - logger.Error("connection.SetDeadline(t:%v) = error:%v", t, err) + logger.Errorf("[Jsonrpc][Server] connection.SetDeadline failed, t=%v, err=%v", t, err) } } @@ -129,7 +129,7 @@ func (s *Server) handlePkg(conn net.Conn) { } r, err := http.ReadRequest(bufReader) if err != nil { - logger.Warnf("[ReadRequest] error: %v", err) + logger.Warnf("[Jsonrpc][Server] read request failed, err=%v", err) return } @@ -156,7 +156,7 @@ func (s *Server) handlePkg(conn net.Conn) { setTimeout(conn, httpTimeout) errMsg := "unsupported content type: " + contentType if errRsp := sendErrorResp(r.Header, []byte(errMsg)); errRsp != nil { - logger.Warnf("sendErrorResp(header:%#v, error:%v) = error:%s", + logger.Warnf("[Jsonrpc][Server] sendErrorResp failed, header=%v, err_msg=%v, send_err=%v", r.Header, errMsg, errRsp) } return @@ -184,11 +184,11 @@ func (s *Server) handlePkg(conn net.Conn) { if err := serveRequest(ctx, reqHeader, reqBody, conn); err != nil { if errRsp := sendErrorResp(r.Header, []byte(perrors.WithStack(err).Error())); errRsp != nil { - logger.Warnf("sendErrorResp(header:%#v, error:%v) = error:%s", + logger.Warnf("[Jsonrpc][Server] sendErrorResp failed, header=%v, err=%v, send_err=%v", r.Header, perrors.WithStack(err), errRsp) } - logger.Infof("Unexpected error serving request, closing socket: %v", err) + logger.Infof("[Jsonrpc][Server] unexpected error serving request, closing socket, err=%v", err) return } } @@ -213,7 +213,7 @@ func accept(listener net.Listener, fn func(net.Conn)) error { if tmpDelay > DefaultMaxSleepTime { tmpDelay = DefaultMaxSleepTime } - logger.Infof("http: Accept error: %v; retrying in %v\n", err, tmpDelay) + logger.Infof("[Jsonrpc][Server] http accept error, retrying, err=%v, retry_in=%v", err, tmpDelay) time.Sleep(tmpDelay) continue } @@ -226,7 +226,7 @@ func accept(listener net.Listener, fn func(net.Conn)) error { const size = 64 << 10 buf := make([]byte, size) buf = buf[:runtime.Stack(buf, false)] - logger.Errorf("http: panic serving %v: %v\n%s", c.RemoteAddr(), r, buf) + logger.Errorf("[Jsonrpc][Server] http panic serving, remote=%v, err=%v\n%s", c.RemoteAddr(), r, buf) c.Close() } }() @@ -240,15 +240,15 @@ func accept(listener net.Listener, fn func(net.Conn)) error { func (s *Server) Start(url *common.URL) { listener, err := net.Listen("tcp", url.Location) if err != nil { - logger.Errorf("jsonrpc server [%s] start failed: %v", url.Path, err) + logger.Errorf("[Jsonrpc][Server] jsonrpc server start failed, path=%s, err=%v", url.Path, err) return } - logger.Infof("rpc server start to listen on %s", listener.Addr()) + logger.Infof("[Jsonrpc][Server] rpc server start to listen on %s", listener.Addr()) s.wg.Add(1) go func() { if err := accept(listener, func(conn net.Conn) { s.handlePkg(conn) }); err != nil { - logger.Error("accept() = error:%v", err) + logger.Errorf("[Jsonrpc][Server] accept failed, err=%v", err) } s.wg.Done() }() @@ -259,7 +259,7 @@ func (s *Server) Start(url *common.URL) { <-s.done // step1: block to wait for done channel(wait Server.Stop step2) err = listener.Close() // step2: and then close listener if err != nil { - logger.Warnf("listener{addr:%s}.Close() = error{%#v}", listener.Addr(), err) + logger.Warnf("[Jsonrpc][Server] listener close failed, addr=%s, err=%v", listener.Addr(), err) } s.wg.Done() }() @@ -347,7 +347,7 @@ func serveRequest(ctx context.Context, header map[string]string, body []byte, co if err = codec.ReadBody(&args); err != nil { return perrors.WithStack(err) } - logger.Debugf("args: %v", args) + logger.Debugf("[Jsonrpc][Server] args=%v", args) // exporter invoke exporter, ok := jsonrpcProtocol.ExporterMap().Load(path) @@ -366,7 +366,7 @@ func serveRequest(ctx context.Context, header map[string]string, body []byte, co return perrors.WithStack(codecErr) } if errRsp := sendErrorResp(header, rspStream); errRsp != nil { - logger.Warnf("Exporter: sendErrorResp(header:%#v, error:%v) = error:%s", + logger.Warnf("[Jsonrpc][Server] sendErrorResp failed, header=%v, err=%v, send_err=%v", header, err, errRsp) } } else { @@ -376,7 +376,7 @@ func serveRequest(ctx context.Context, header map[string]string, body []byte, co return perrors.WithStack(err) } if errRsp := sendResp(header, rspStream); errRsp != nil { - logger.Warnf("Exporter: sendResp(header:%#v, error:%v) = error:%s", + logger.Warnf("[Jsonrpc][Server] sendResp failed, header=%v, err=%v, send_err=%v", header, err, errRsp) } } diff --git a/protocol/protocolwrapper/protocol_filter_wrapper.go b/protocol/protocolwrapper/protocol_filter_wrapper.go index 7f398606e1..2e4093f69c 100644 --- a/protocol/protocolwrapper/protocol_filter_wrapper.go +++ b/protocol/protocolwrapper/protocol_filter_wrapper.go @@ -92,10 +92,10 @@ func BuildInvokerChain(invoker base.Invoker, key string) base.Invoker { } switch key { case constant.ServiceFilterKey: - logger.Debugf("[BuildInvokerChain] The provider invocation link is %s, invoker: %s", + logger.Debugf("[ProtocolWrapper] The provider invocation link is %s, invoker: %s", strings.Join(append(filterNames, "proxyInvoker"), " -> "), invoker) case constant.ReferenceFilterKey: - logger.Debugf("[BuildInvokerChain] The consumer filters are %s, invoker: %s", + logger.Debugf("[ProtocolWrapper] The consumer filters are %s, invoker: %s", strings.Join(append(filterNames, "proxyInvoker"), " -> "), invoker) } diff --git a/protocol/rest/config/reader/rest_config_reader.go b/protocol/rest/config/reader/rest_config_reader.go index e5ba7d19ea..a6bb6305ab 100644 --- a/protocol/rest/config/reader/rest_config_reader.go +++ b/protocol/rest/config/reader/rest_config_reader.go @@ -56,7 +56,7 @@ func (cr *RestConfigReader) ReadConsumerConfig(reader *bytes.Buffer) error { restConsumerConfig := &config.RestConsumerConfig{} err := yaml.Unmarshal(reader.Bytes(), restConsumerConfig) if err != nil { - return perrors.Errorf("[Rest ShutdownConfig] unmarshal Consumer error %#v", perrors.WithStack(err)) + return perrors.Errorf("[Rest][Config] unmarshal Consumer error, err=%v", perrors.WithStack(err)) } restConsumerServiceConfigMap := make(map[string]*config.RestServiceConfig, len(restConsumerConfig.RestServiceConfigsMap)) @@ -74,7 +74,7 @@ func (cr *RestConfigReader) ReadProviderConfig(reader *bytes.Buffer) error { restProviderConfig := &config.RestProviderConfig{} err := yaml.Unmarshal(reader.Bytes(), restProviderConfig) if err != nil { - return perrors.Errorf("[Rest ShutdownConfig] unmarshal Provider error %#v", perrors.WithStack(err)) + return perrors.Errorf("[Rest][Config] unmarshal Provider error, err=%v", perrors.WithStack(err)) } restProviderServiceConfigMap := make(map[string]*config.RestServiceConfig, len(restProviderConfig.RestServiceConfigsMap)) for key, rc := range restProviderConfig.RestServiceConfigsMap { @@ -118,7 +118,7 @@ func transformMethodConfig(methodConfig *config.RestMethodConfig) *config.RestMe if len(methodConfig.PathParamsMap) == 0 && len(methodConfig.PathParams) > 0 { paramsMap, err := parseParamsString2Map(methodConfig.PathParams) if err != nil { - logger.Warnf("[Rest ShutdownConfig] Path Param parse error:%v", err) + logger.Warnf("[Rest][Config] path param parse error, err=%v", err) } else { methodConfig.PathParamsMap = paramsMap } @@ -126,7 +126,7 @@ func transformMethodConfig(methodConfig *config.RestMethodConfig) *config.RestMe if len(methodConfig.QueryParamsMap) == 0 && len(methodConfig.QueryParams) > 0 { paramsMap, err := parseParamsString2Map(methodConfig.QueryParams) if err != nil { - logger.Warnf("[Rest ShutdownConfig] Argument Param parse error:%v", err) + logger.Warnf("[Rest][Config] argument param parse error, err=%v", err) } else { methodConfig.QueryParamsMap = paramsMap } @@ -134,7 +134,7 @@ func transformMethodConfig(methodConfig *config.RestMethodConfig) *config.RestMe if len(methodConfig.HeadersMap) == 0 && len(methodConfig.Headers) > 0 { headersMap, err := parseParamsString2Map(methodConfig.Headers) if err != nil { - logger.Warnf("[Rest ShutdownConfig] Argument Param parse error:%v", err) + logger.Warnf("[Rest][Config] argument param parse error, err=%v", err) } else { methodConfig.HeadersMap = headersMap } diff --git a/protocol/rest/rest_exporter.go b/protocol/rest/rest_exporter.go index 222346c027..5442375dbe 100644 --- a/protocol/rest/rest_exporter.go +++ b/protocol/rest/rest_exporter.go @@ -48,7 +48,7 @@ func (re *RestExporter) UnExport() { interfaceName := re.GetInvoker().GetURL().GetParam(constant.InterfaceKey, "") err := common.ServiceMap.UnRegister(interfaceName, REST, re.GetInvoker().GetURL().ServiceKey()) if err != nil { - logger.Errorf("[RestExporter.UnExport] error: %v", err) + logger.Errorf("[Rest][Exporter] unexport failed, err=%v", err) } re.BaseExporter.UnExport() } diff --git a/protocol/rest/rest_protocol.go b/protocol/rest/rest_protocol.go index 8b26a3bbdf..bdf5e5a6e2 100644 --- a/protocol/rest/rest_protocol.go +++ b/protocol/rest/rest_protocol.go @@ -74,7 +74,7 @@ func (rp *RestProtocol) Export(invoker base.Invoker) base.Exporter { id := url.GetParam(constant.BeanNameKey, "") restServiceConfig := rest_config.GetRestProviderServiceConfig(id) if restServiceConfig == nil { - logger.Errorf("%s service doesn't has provider config", url.Path) + logger.Errorf("[Rest] %s service doesn't has provider config", url.Path) return nil } rp.SetExporterMap(serviceKey, exporter) @@ -101,7 +101,7 @@ func (rp *RestProtocol) Refer(url *common.URL) base.Invoker { id := url.GetParam(constant.BeanNameKey, "") restServiceConfig := rest_config.GetRestConsumerServiceConfig(id) if restServiceConfig == nil { - logger.Errorf("%s service doesn't has consumer config", url.Path) + logger.Errorf("[Rest] %s service doesn't has consumer config", url.Path) return nil } restOptions := client.RestOptions{RequestTimeout: requestTimeout, ConnectTimeout: connectTimeout, KeppAliveTimeout: keepAliveTimeout} diff --git a/protocol/rest/server/rest_server.go b/protocol/rest/server/rest_server.go index e27a7b21f0..de5a788595 100644 --- a/protocol/rest/server/rest_server.go +++ b/protocol/rest/server/rest_server.go @@ -104,23 +104,23 @@ func GetRouteFunc(invoker base.Invoker, methodConfig *rest_config.RestMethodConf args, err = getArgsFromRequest(req, argsTypes, methodConfig) } if err != nil { - logger.Errorf("[Go Restful] parsing http parameters error:%v", err) + logger.Errorf("[Rest][Server] parsing http parameters error, err=%v", err) err = resp.WriteError(http.StatusInternalServerError, errors.New(parseParameterErrorStr)) if err != nil { - logger.Errorf("[Go Restful] WriteErrorString error:%v", err) + logger.Errorf("[Rest][Server] write error string failed, err=%v", err) } } result := invoker.Invoke(context.Background(), invocation.NewRPCInvocation(methodConfig.MethodName, args, make(map[string]any))) if result.Error() != nil { err = resp.WriteError(http.StatusInternalServerError, result.Error()) if err != nil { - logger.Errorf("[Go Restful] WriteError error:%v", err) + logger.Errorf("[Rest][Server] write error failed, err=%v", err) } return } err = resp.WriteEntity(result.Result()) if err != nil { - logger.Errorf("[Go Restful] WriteEntity error:%v", err) + logger.Errorf("[Rest][Server] write entity failed, err=%v", err) } } } @@ -160,7 +160,7 @@ func getArgsInterfaceFromRequest(req RestServerRequest, methodConfig *rest_confi m := make(map[string]any) // TODO read as a slice if err := req.ReadEntity(&m); err != nil { - return nil, perrors.Errorf("[Go restful] Read body entity as map[string]any error:%v", err) + return nil, perrors.Errorf("[Rest][Server] read body entity as map[string]any, err=%v", err) } argsMap[methodConfig.Body] = m } @@ -200,7 +200,7 @@ func assembleArgsFromHeaders(methodConfig *rest_config.RestMethodConfig, req Res for k, v := range methodConfig.HeadersMap { param := req.HeaderParameter(v) if k < 0 || k >= argsLength { - return perrors.Errorf("[Go restful] Header param parse error, the index %v args of method:%v doesn't exist", k, methodConfig.MethodName) + return perrors.Errorf("[Rest][Server] header param parse error, the index %v args of method:%v doesn't exist", k, methodConfig.MethodName) } t := argsTypes[k] if t.Kind() == reflect.Ptr { @@ -209,7 +209,7 @@ func assembleArgsFromHeaders(methodConfig *rest_config.RestMethodConfig, req Res if t.Kind() == reflect.String { args[k] = param } else { - return perrors.Errorf("[Go restful] Header param parse error, the index %v args's type isn't string", k) + return perrors.Errorf("[Rest][Server] header param parse error, the index %v args's type isn't string", k) } } return nil @@ -235,7 +235,7 @@ func assembleArgsFromBody(methodConfig *rest_config.RestMethodConfig, argsTypes } } if err := req.ReadEntity(&ni); err != nil { - return perrors.Errorf("[Go restful] Read body entity error, error is %v", perrors.WithStack(err)) + return perrors.Errorf("[Rest][Server] read body entity error, err=%v", perrors.WithStack(err)) } args[methodConfig.Body] = ni } @@ -251,7 +251,7 @@ func assembleArgsFromQueryParams(methodConfig *rest_config.RestMethodConfig, arg ) for k, v := range methodConfig.QueryParamsMap { if k < 0 || k >= argsLength { - return perrors.Errorf("[Go restful] Query param parse error, the index %v args of method:%v doesn't exist", k, methodConfig.MethodName) + return perrors.Errorf("[Rest][Server] query param parse error, the index %v args of method:%v doesn't exist", k, methodConfig.MethodName) } t := argsTypes[k] kind := t.Kind() @@ -274,11 +274,11 @@ func assembleArgsFromQueryParams(methodConfig *rest_config.RestMethodConfig, arg case reflect.Int64: param, err = strconv.ParseInt(req.QueryParameter(v), 10, 64) default: - return perrors.Errorf("[Go restful] Query param parse error, the index %v args's type isn't int or string or slice", k) + return perrors.Errorf("[Rest][Server] query param parse error, the index %v args's type isn't int or string or slice", k) } if err != nil { - return perrors.Errorf("[Go restful] Query param parse error, error:%v", perrors.WithStack(err)) + return perrors.Errorf("[Rest][Server] query param parse error, err=%v", perrors.WithStack(err)) } args[k] = param } @@ -294,7 +294,7 @@ func assembleArgsFromPathParams(methodConfig *rest_config.RestMethodConfig, args ) for k, v := range methodConfig.PathParamsMap { if k < 0 || k >= argsLength { - return perrors.Errorf("[Go restful] Path param parse error, the index %v args of method:%v doesn't exist", k, methodConfig.MethodName) + return perrors.Errorf("[Rest][Server] path param parse error, the index %v args of method:%v doesn't exist", k, methodConfig.MethodName) } t := argsTypes[k] kind := t.Kind() @@ -316,11 +316,11 @@ func assembleArgsFromPathParams(methodConfig *rest_config.RestMethodConfig, args case reflect.String: param = req.PathParameter(v) default: - return perrors.Errorf("[Go restful] Path param parse error, the index %v args's type isn't int or string", k) + return perrors.Errorf("[Rest][Server] path param parse error, the index %v args's type isn't int or string", k) } if err != nil { - return perrors.Errorf("[Go restful] Path param parse error, error is %v", perrors.WithStack(err)) + return perrors.Errorf("[Rest][Server] path param parse error, err=%v", perrors.WithStack(err)) } args[k] = param } diff --git a/protocol/rest/server/server_impl/go_restful_server.go b/protocol/rest/server/server_impl/go_restful_server.go index e2b7a6c643..15e9729d38 100644 --- a/protocol/rest/server/server_impl/go_restful_server.go +++ b/protocol/rest/server/server_impl/go_restful_server.go @@ -81,7 +81,7 @@ func (grs *GoRestfulServer) Start(url *common.URL) { go func() { err := grs.srv.Serve(ln) if err != nil && err != http.ErrServerClosed { - logger.Errorf("[Go Restful] http.server.Serve(addr{%s}) = err{%+v}", url.Location, err) + logger.Errorf("[Rest][Server] http.server.Serve failed, addr=%s, err=%v", url.Location, err) } }() } @@ -102,7 +102,7 @@ func (grs *GoRestfulServer) Deploy(restMethodConfig *config.RestMethodConfig, ro func (grs *GoRestfulServer) UnDeploy(restMethodConfig *config.RestMethodConfig) { err := grs.ws.RemoveRoute(restMethodConfig.Path, restMethodConfig.MethodType) if err != nil { - logger.Warnf("[Go restful] Remove web service error:%v", err) + logger.Warnf("[Rest][Server] remove web service failed, err=%v", err) } } @@ -111,9 +111,9 @@ func (grs *GoRestfulServer) Destroy() { ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) defer cancel() if err := grs.srv.Shutdown(ctx); err != nil { - logger.Errorf("[Go Restful] Server Shutdown:", err) + logger.Errorf("[Rest][Server] server shutdown failed, err=%v", err) } - logger.Infof("[Go Restful] Server exiting") + logger.Infof("[Rest][Server] server exiting") } // AddGoRestfulServerFilter let user add the http server of go-restful diff --git a/protocol/triple/client.go b/protocol/triple/client.go index 3c632f6e9a..1e548d2e15 100644 --- a/protocol/triple/client.go +++ b/protocol/triple/client.go @@ -159,7 +159,7 @@ func newClientManager(url *common.URL) (*clientManager, error) { return nil, err } if cfg != nil { - logger.Infof("TRIPLE clientManager initialized the TLSConfig configuration") + logger.Info("[Triple][Client] triple clientManager initialized the TLSConfig configuration") tlsFlag = true } } @@ -174,7 +174,7 @@ func newClientManager(url *common.URL) (*clientManager, error) { // handle keepalive options cliKeepAliveOpts, keepAliveInterval, keepAliveTimeout, genKeepAliveOptsErr := genKeepAliveOptions(url, tripleConf) if genKeepAliveOptsErr != nil { - logger.Errorf("genKeepAliveOpts err: %v", genKeepAliveOptsErr) + logger.Errorf("[Triple][Client] genKeepAliveOpts failed, err=%v", genKeepAliveOptsErr) return nil, genKeepAliveOptsErr } cliOpts = append(cliOpts, cliKeepAliveOpts...) @@ -236,7 +236,7 @@ func newClientManager(url *common.URL) (*clientManager, error) { }, } - logger.Infof("Triple http3 client transport init successfully") + logger.Info("[Triple][Client] triple http3 client transport init successfully") case constant.CallHTTP2AndHTTP3: if !tlsFlag { return nil, fmt.Errorf("TRIPLE HTTP/2 and HTTP/3 client must have TLS config, but TLS config is nil") @@ -244,7 +244,7 @@ func newClientManager(url *common.URL) (*clientManager, error) { // Create a dual transport that can handle both HTTP/2 and HTTP/3 transport = newDualTransport(cfg, keepAliveInterval, keepAliveTimeout) - logger.Infof("Triple HTTP/2 and HTTP/3 client transport init successfully") + logger.Info("[Triple][Client] triple HTTP/2 and HTTP/3 client transport init successfully") default: return nil, fmt.Errorf("unsupported http protocol: %s", callProtocol) } diff --git a/protocol/triple/dual_transport.go b/protocol/triple/dual_transport.go index ca84e62c17..f963d158fd 100644 --- a/protocol/triple/dual_transport.go +++ b/protocol/triple/dual_transport.go @@ -128,7 +128,7 @@ func (dt *dualTransport) RoundTrip(req *http.Request) (*http.Response, error) { return resp, nil } if dt.shouldMarkH3Failure(req, err) { - logger.Warnf("HTTP/3 request failed for %s: %v", req.URL.String(), err) + logger.Warnf("[Triple] HTTP/3 request failed for %s, err=%v", req.URL.String(), err) dt.markH3Failure(host) } return nil, err @@ -171,7 +171,7 @@ func (dt *dualTransport) shouldUseH3(host string) bool { return false } - logger.Debugf("HTTP/3 cooldown expired for %s", host) + logger.Debugf("[Triple] HTTP/3 cooldown expired for %s", host) dt.state.mode = originCandidate dt.state.cooldownUntil = time.Time{} return false @@ -199,7 +199,7 @@ func (dt *dualTransport) markH3Success(host string) { dt.state.mode = originH3Healthy dt.state.failures = 0 dt.state.cooldownUntil = time.Time{} - logger.Debugf("HTTP/3 ready for %s", host) + logger.Debugf("[Triple] HTTP/3 ready for %s", host) } func (dt *dualTransport) markH3Failure(host string) { @@ -210,7 +210,7 @@ func (dt *dualTransport) markH3Failure(host string) { dt.state.mode = originCooldown dt.state.cooldownUntil = time.Now().Add(dt.nextCooldown(dt.state.failures)) logger.Debugf( - "HTTP/3 cooldown for %s until %s after %d failure(s)", + "[Triple] HTTP/3 cooldown for %s until %s after %d failure(s)", host, dt.state.cooldownUntil.Format(time.RFC3339), dt.state.failures, @@ -236,13 +236,13 @@ func (dt *dualTransport) observeH2Response(u *url.URL, headers http.Header) { switch dt.state.mode { case originUnknown: dt.state.mode = originCandidate - logger.Debugf("HTTP/3 advertised by %s", u.Host) + logger.Debugf("[Triple] HTTP/3 advertised by %s", u.Host) case originCooldown: if !now.Before(dt.state.cooldownUntil) { dt.state.mode = originCandidate dt.state.cooldownUntil = time.Time{} - logger.Debugf("HTTP/3 reprobe enabled for %s", u.Host) + logger.Debugf("[Triple] HTTP/3 reprobe enabled for %s", u.Host) } case originCandidate, originProbing, originH3Healthy: @@ -292,7 +292,7 @@ func (dt *dualTransport) maybeStartProbe(u *url.URL) { dt.state.mode = originProbing dt.mu.Unlock() - logger.Debugf("Start HTTP/3 probe for %s via %s", host, probeURL.String()) + logger.Debugf("[Triple] start HTTP/3 probe for %s via %s", host, probeURL.String()) go dt.runProbe(probeURL) } @@ -309,13 +309,13 @@ func (dt *dualTransport) runProbe(probeURL *url.URL) { // to be replayed across transports. req, err := http.NewRequestWithContext(ctx, http.MethodOptions, probeURL.String(), nil) if err != nil { - logger.Debugf("Create HTTP/3 probe request failed for %s: %v", host, err) + logger.Debugf("[Triple] create HTTP/3 probe request failed for %s, err=%v", host, err) dt.markH3Failure(host) return } resp, err := dt.http3Transport.RoundTrip(req) if err != nil { - logger.Debugf("HTTP/3 probe failed for %s: %v", host, err) + logger.Debugf("[Triple] HTTP/3 probe failed for %s, err=%v", host, err) dt.markH3Failure(host) return } diff --git a/protocol/triple/dubbo3_invoker.go b/protocol/triple/dubbo3_invoker.go index 60b85704dc..87da158955 100644 --- a/protocol/triple/dubbo3_invoker.go +++ b/protocol/triple/dubbo3_invoker.go @@ -128,7 +128,7 @@ func NewDubbo3Invoker(url *common.URL) (*DubboInvoker, error) { *tracingConfig.UseAgent, )) } else { - logger.Warnf("unsupported tracing name %s, now triple only support jaeger", tracingConfig.Name) + logger.Warnf("[Triple][Invoker] unsupported tracing name %s, now triple only support jaeger", tracingConfig.Name) } } } @@ -146,7 +146,7 @@ func NewDubbo3Invoker(url *common.URL) (*DubboInvoker, error) { triOption.TLSCertFile = tlsConf.TLSCertFile triOption.TLSKeyFile = tlsConf.TLSKeyFile triOption.TLSServerName = tlsConf.TLSServerName - logger.Infof("DUBBO3 Client initialized the TLSConfig configuration") + logger.Info("[Triple][Invoker] DUBBO3 Client initialized the TLSConfig configuration") } } @@ -187,7 +187,7 @@ func (di *DubboInvoker) Invoke(ctx context.Context, invocation base.Invocation) if !di.BaseInvoker.IsAvailable() { // Generally, the case will not happen, because the invoker has been removed // from the invoker list before destroy,so no new request will enter the destroyed invoker - logger.Warnf("this dubboInvoker is destroyed") + logger.Warn("[Triple][Invoker] this dubboInvoker is destroyed") result.SetError(base.ErrDestroyedInvoker) return &result } @@ -226,7 +226,7 @@ func (di *DubboInvoker) Invoke(ctx context.Context, invocation base.Invocation) gRPCMD.Set(k, str...) continue } - logger.Warnf("[Triple Protocol]Triple attachment value with key = %s is invalid, which should be string or []string", k) + logger.Warnf("[Triple][Invoker] triple attachment value with key=%s is invalid, which should be string or []string", k) } ctx = metadata.NewOutgoingContext(ctx, gRPCMD) ctx = context.WithValue(ctx, tripleConstant.InterfaceKey, di.BaseInvoker.GetURL().GetParam(constant.InterfaceKey, "")) diff --git a/protocol/triple/health/healthServer.go b/protocol/triple/health/healthServer.go index ec4715b4bd..1afbc9caef 100644 --- a/protocol/triple/health/healthServer.go +++ b/protocol/triple/health/healthServer.go @@ -120,7 +120,7 @@ func (srv *HealthTripleServer) SetServingStatus(service string, servingStatus tr srv.mu.Lock() defer srv.mu.Unlock() if srv.shutdown { - logger.Infof("health: status changing for %s to %v is ignored because health service is shutdown", service, servingStatus) + logger.Infof("[Triple][Health] health: status changing for %s to %v is ignored because health service is shutdown", service, servingStatus) return } diff --git a/protocol/triple/openapi/integration.go b/protocol/triple/openapi/integration.go index 4359f72d10..fe9e21171f 100644 --- a/protocol/triple/openapi/integration.go +++ b/protocol/triple/openapi/integration.go @@ -49,7 +49,7 @@ func NewOpenAPIIntegration(cfg *global.OpenAPIConfig) *OpenAPIIntegration { swaggerHandler: NewSwaggerUIHandler(svc, cfg), redocHandler: NewRedocHandler(svc, cfg), } - logger.Info("OpenAPI service initialized") + logger.Infof("[Triple][OpenAPI] OpenAPI service initialized") return integration } diff --git a/protocol/triple/openapi/service.go b/protocol/triple/openapi/service.go index 477f02babc..290930754a 100644 --- a/protocol/triple/openapi/service.go +++ b/protocol/triple/openapi/service.go @@ -145,7 +145,7 @@ func (s *DefaultService) Refresh() { s.mu.Lock() defer s.mu.Unlock() s.openAPIs = nil - logger.Debug("OpenAPI documents refreshed") + logger.Debugf("[Triple][OpenAPI] OpenAPI documents refreshed") } func (s *DefaultService) getOpenAPIs() map[string]*model.OpenAPI { diff --git a/protocol/triple/options.go b/protocol/triple/options.go index e052160dc9..f0710b2cce 100644 --- a/protocol/triple/options.go +++ b/protocol/triple/options.go @@ -108,7 +108,7 @@ func WithCORS(opts ...CORSOption) Option { opt(cors) } if err := validateCorsConfig(cors); err != nil { - logger.Errorf("[TRIPLE] invalid CORS config: %v", err) + logger.Errorf("[Triple] invalid CORS config, err=%v", err) // Return a no-op function to ignore invalid CORS configuration return func(*Options) {} } diff --git a/protocol/triple/server.go b/protocol/triple/server.go index b3faa13262..806938b5d9 100644 --- a/protocol/triple/server.go +++ b/protocol/triple/server.go @@ -133,7 +133,7 @@ func resolveServerTransport(url *common.URL) (*transportSettings, error) { if err != nil { return nil, fmt.Errorf("TRIPLE server initialized the TLSConfig configuration failed: %w", err) } - logger.Infof("TRIPLE Server initialized the TLSConfig configuration") + logger.Info("[Triple][Server] triple Server initialized the TLSConfig configuration") } return &transportSettings{ @@ -238,7 +238,7 @@ func (s *Server) startTransport(callProtocol string, tlsConf *tls.Config) { go func() { if runErr := s.triServer.Run(callProtocol, tlsConf); runErr != nil { - logger.Errorf("server serve failed with err: %v", runErr) + logger.Errorf("[Triple][Server] server serve failed, err=%v", runErr) } }() } @@ -410,7 +410,7 @@ func getHanOpts(url *common.URL, tripleConf *global.TripleConfig) (hanOpts []tri } if tripleConf.MaxServerRecvMsgSize != "" { - logger.Debugf("MaxServerRecvMsgSize: %v", tripleConf.MaxServerRecvMsgSize) + logger.Debugf("[Triple][Server] MaxServerRecvMsgSize=%v", tripleConf.MaxServerRecvMsgSize) if recvMsgSize, convertErr := humanize.ParseBytes(tripleConf.MaxServerRecvMsgSize); convertErr == nil && recvMsgSize != 0 { maxServerRecvMsgSize = int(recvMsgSize) } @@ -418,7 +418,7 @@ func getHanOpts(url *common.URL, tripleConf *global.TripleConfig) (hanOpts []tri } if tripleConf.MaxServerSendMsgSize != "" { - logger.Debugf("MaxServerSendMsgSize: %v", tripleConf.MaxServerSendMsgSize) + logger.Debugf("[Triple][Server] MaxServerSendMsgSize=%v", tripleConf.MaxServerSendMsgSize) if sendMsgSize, convertErr := humanize.ParseBytes(tripleConf.MaxServerSendMsgSize); convertErr == nil && sendMsgSize != 0 { maxServerSendMsgSize = int(sendMsgSize) } @@ -452,7 +452,7 @@ func (s *Server) compatHandleService(url *common.URL, interfaceName string, grou } } if len(providerServices) == 0 { - logger.Info("Provider service map is null, please register ProviderServices") + logger.Info("[Triple][Server] provider service map is null, please register ProviderServices") return } for key, providerService := range providerServices { @@ -461,13 +461,13 @@ func (s *Server) compatHandleService(url *common.URL, interfaceName string, grou } service, _ := url.GetAttribute(constant.RpcServiceKey) if service == nil { - logger.Warnf("no rpc service found for key: %v", key) + logger.Warnf("[Triple][Server] no rpc service found for key=%v", key) continue } serviceKey := common.ServiceKey(providerService.Interface, providerService.Group, providerService.Version) exporter, _ := tripleProtocol.ExporterMap().Load(serviceKey) if exporter == nil { - logger.Warnf("no exporter found for serviceKey: %v", serviceKey) + logger.Warnf("[Triple][Server] no exporter found for serviceKey=%v", serviceKey) continue } invoker := exporter.(base.Exporter).GetInvoker() @@ -726,7 +726,7 @@ func (s *Server) GracefulStop() { defer cancel() if err := s.triServer.GracefulStop(shutdownCtx); err != nil { - logger.Errorf("Triple server shutdown error: %v", err) + logger.Errorf("[Triple][Server] triple server shutdown failed, err=%v", err) } } @@ -764,7 +764,7 @@ func buildMethodInfoWithReflection(methodType reflect.Method) *common.MethodInfo paramsNum := methodType.Type.NumIn() // the first param is receiver itself, the second param is ctx if paramsNum < 2 { - logger.Fatalf("TRIPLE does not support %s method that does not have any parameter", methodType.Name) + logger.Fatalf("[Triple][Server] triple does not support %s method that does not have any parameter", methodType.Name) return nil } diff --git a/protocol/triple/triple.go b/protocol/triple/triple.go index caf3f8ad2c..14afb3712d 100644 --- a/protocol/triple/triple.go +++ b/protocol/triple/triple.go @@ -96,9 +96,9 @@ func (tp *TripleProtocol) Export(invoker base.Invoker) base.Exporter { } exporter := NewTripleExporter(serviceKey, invoker, tp.ExporterMap()) tp.SetExporterMap(serviceKey, exporter) - logger.Infof("[TRIPLE Protocol] Export service: %s", url.String()) + logger.Infof("[Triple] export service: %s", url.String()) if err := tp.openServer(invoker, info); err != nil { - logger.Errorf("[TRIPLE Protocol] Export service failed: %s, err: %v", url.String(), err) + logger.Errorf("[Triple] export service failed, %s, err=%v", url.String(), err) exporter.UnExport() panic(err) } @@ -122,7 +122,7 @@ func (tp *TripleProtocol) openServer(invoker base.Invoker, info *common.ServiceI } if _, ok := tp.ExporterMap().Load(url.ServiceKey()); !ok { - panic("[TRIPLE Protocol]" + url.Key() + "is not existing") + panic("[Triple]" + url.Key() + "is not existing") } // Do not freeze listener configuration at construction time. The shared @@ -160,17 +160,17 @@ func (tp *TripleProtocol) Refer(url *common.URL) base.Invoker { invoker, err = NewDubbo3Invoker(url) } if err != nil { - logger.Warnf("can't dial the server: %s", url.Key()) + logger.Warnf("[Triple] can't dial the server: %s", url.Key()) return nil } tp.SetInvokers(invoker) - logger.Infof("[TRIPLE Protocol] Refer service: %s", url.String()) + logger.Infof("[Triple] refer service: %s", url.String()) return invoker } func (tp *TripleProtocol) Destroy() { - logger.Infof("TripleProtocol destroy.") + logger.Info("[Triple] TripleProtocol destroy.") for _, server := range tp.drainServers() { tripleServerGracefulStop(server) diff --git a/protocol/triple/triple_exporter.go b/protocol/triple/triple_exporter.go index 6ece6f4a64..9bc4b2b1a4 100644 --- a/protocol/triple/triple_exporter.go +++ b/protocol/triple/triple_exporter.go @@ -48,7 +48,7 @@ func (te *TripleExporter) UnExport() { // todo: move UnRegister logic to a better place err := common.ServiceMap.UnRegister(interfaceName, TRIPLE, te.GetInvoker().GetURL().ServiceKey()) if err != nil { - logger.Errorf("[GrpcNewExporter.UnExport] error: %v", err) + logger.Errorf("[Triple][Exporter] unexport failed, err=%v", err) } te.BaseExporter.UnExport() } diff --git a/protocol/triple/triple_invoker.go b/protocol/triple/triple_invoker.go index 64ea5d0b32..f79b5af104 100644 --- a/protocol/triple/triple_invoker.go +++ b/protocol/triple/triple_invoker.go @@ -74,7 +74,7 @@ func (ti *TripleInvoker) Invoke(ctx context.Context, invocation base.Invocation) if !ti.BaseInvoker.IsAvailable() { // Generally, the case will not happen, because the invoker has been removed // from the invoker list before destroy,so no new request will enter the destroyed invoker - logger.Warnf("TripleInvoker is destroyed") + logger.Warnf("[Triple][Invoker] TripleInvoker is destroyed") result.SetError(base.ErrDestroyedInvoker) return &result } @@ -285,7 +285,7 @@ func (ti *TripleInvoker) startHealthWatch(handler gracefulshutdown.ClosingEventH go func() { stream, err := cm.callHealthWatch(ctx, ti.GetURL().ServiceKey()) if err != nil { - logger.Debugf("[TRIPLE Protocol] health watch start failed for %s: %v", ti.GetURL().String(), err) + logger.Debugf("[Triple][Invoker] health watch start failed for %s, err=%v", ti.GetURL().String(), err) return } @@ -293,7 +293,7 @@ func (ti *TripleInvoker) startHealthWatch(handler gracefulshutdown.ClosingEventH resp := new(grpc_health_v1.HealthCheckResponse) if ok := stream.Receive(resp); !ok { if ctx.Err() == nil { - logger.Debugf("[TRIPLE Protocol] health watch recv failed for %s: %v", ti.GetURL().String(), stream.Err()) + logger.Debugf("[Triple][Invoker] health watch recv failed for %s, err=%v", ti.GetURL().String(), stream.Err()) } return } diff --git a/protocol/triple/triple_protocol/cors.go b/protocol/triple/triple_protocol/cors.go index c3c031955a..57fa457f08 100644 --- a/protocol/triple/triple_protocol/cors.go +++ b/protocol/triple/triple_protocol/cors.go @@ -74,7 +74,7 @@ func buildCorsPolicy(cfg *CorsConfig, handlers []protocolHandler) *CorsConfig { } if built.hasWildcard() && !cfg.AllowCredentials && len(cfg.AllowOrigins) > 1 { - logger.Warnf("[TRIPLE] CORS: wildcard \"*\" will override other origins when allowCredentials=false") + logger.Warnf("[Triple][CORS] CORS: wildcard \"*\" will override other origins when allowCredentials=false") } return built @@ -231,7 +231,7 @@ func (c *CorsConfig) handlePreflight(w http.ResponseWriter, r *http.Request) boo origin := r.Header.Get(corsOrigin) if origin == "" || !c.matchOrigin(origin) { if origin != "" { - logger.Debugf("[TRIPLE] CORS forbidden origin: %s", origin) + logger.Debugf("[Triple][CORS] CORS forbidden origin: %s", origin) } w.Header().Add(corsVary, corsOrigin) w.WriteHeader(http.StatusForbidden) @@ -240,7 +240,7 @@ func (c *CorsConfig) handlePreflight(w http.ResponseWriter, r *http.Request) boo requestedMethod := r.Header.Get(corsRequestMethod) if requestedMethod != "" && !c.containsMethod(requestedMethod) { - logger.Debugf("[TRIPLE] CORS forbidden method: %s (origin: %s)", requestedMethod, origin) + logger.Debugf("[Triple][CORS] CORS forbidden method: %s (origin: %s)", requestedMethod, origin) w.Header().Add(corsVary, corsOrigin) w.WriteHeader(http.StatusForbidden) return true diff --git a/protocol/triple/triple_protocol/envelope.go b/protocol/triple/triple_protocol/envelope.go index 01e2691e42..a7822d6a16 100644 --- a/protocol/triple/triple_protocol/envelope.go +++ b/protocol/triple/triple_protocol/envelope.go @@ -76,7 +76,7 @@ func (w *envelopeWriter) Marshal(message any) *Error { raw, err := w.codec.Marshal(message) if err != nil { if w.backupCodec != nil && w.codec.Name() != w.backupCodec.Name() { - logger.Debugf("failed to marshal message with primary codec %s, trying fallback codec %s", w.codec.Name(), w.backupCodec.Name()) + logger.Debugf("[Triple][Codec] failed to marshal message with primary codec %s, trying fallback codec %s", w.codec.Name(), w.backupCodec.Name()) raw, err = w.backupCodec.Marshal(message) } if err != nil { @@ -202,7 +202,7 @@ func (r *envelopeReader) Unmarshal(message any) *Error { if err := r.codec.Unmarshal(data.Bytes(), message); err != nil { if r.backupCodec != nil && r.backupCodec.Name() != r.codec.Name() { - logger.Debugf("failed to unmarshal message with primary codec %s, trying fallback codec %s", r.codec.Name(), r.backupCodec.Name()) + logger.Debugf("[Triple][Codec] failed to unmarshal message with primary codec %s, trying fallback codec %s", r.codec.Name(), r.backupCodec.Name()) err = r.backupCodec.Unmarshal(data.Bytes(), message) } if err != nil { diff --git a/protocol/triple/triple_protocol/handler_compat.go b/protocol/triple/triple_protocol/handler_compat.go index 69dadbe178..836dbcae6e 100644 --- a/protocol/triple/triple_protocol/handler_compat.go +++ b/protocol/triple/triple_protocol/handler_compat.go @@ -66,12 +66,12 @@ func (t *tripleCompatInterceptor) compatUnaryServerInterceptor(ctx context.Conte } dubbo3RespRaw, err := handler(ctx, typed.Any()) if dubbo3RespRaw == nil && err == nil { - logger.Errorf("Procedure %s unexpectedly returned both nil response and nil error, which should not happen", t.procedure) + logger.Errorf("[Triple][Handler] procedure %s unexpectedly returned both nil response and nil error, which should not happen", t.procedure) return nil, errorf(CodeInternal, "Procedure %s unexpectedly returned both nil response and nil error, which should not happen", t.procedure) } dubbo3Resp, ok := dubbo3RespRaw.(*dubbo_protocol.RPCResult) if !ok { - logger.Errorf("Procedure %s returned an unexpected response type. Expected *dubbo_protocol.RPCResult, but got %T", t.procedure, dubbo3RespRaw) + logger.Errorf("[Triple][Handler] procedure %s returned an unexpected response type, expected *dubbo_protocol.RPCResult, but got %T", t.procedure, dubbo3RespRaw) return nil, errorf(CodeInternal, "Procedure %s returned an unexpected response type. Expected *dubbo_protocol.RPCResult, but got %T", t.procedure, dubbo3RespRaw) } dubbo3Err, ok := compatError(err) diff --git a/protocol/triple/triple_protocol/negotiation.go b/protocol/triple/triple_protocol/negotiation.go index 2899bff163..3431291dc6 100644 --- a/protocol/triple/triple_protocol/negotiation.go +++ b/protocol/triple/triple_protocol/negotiation.go @@ -127,7 +127,7 @@ func (c *AltSvcCache) UpdateFromHeaders(host string, headers http.Header) { if preferredAltSvc != nil { c.Set(host, preferredAltSvc) - logger.Debugf("Updated alt-svc cache for %s: %s", host, preferredAltSvc.Protocol) + logger.Debugf("[Triple][Negotiation] updated alt-svc cache for %s, protocol=%s", host, preferredAltSvc.Protocol) } } @@ -245,7 +245,7 @@ func (h *AltSvcHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { // Only add Alt-Svc headers if negotiation is enabled if h.negotiation && r.ProtoMajor < 3 { if err := h.http3Server.SetQUICHeaders(w.Header()); err != nil { - logger.Warnf("Failed to set QUIC headers for %s: %v", r.URL.String(), err) + logger.Warnf("[Triple][Negotiation] failed to set QUIC headers for %s, err=%v", r.URL.String(), err) } } diff --git a/protocol/triple/triple_protocol/protocol_triple.go b/protocol/triple/triple_protocol/protocol_triple.go index 81ad4d5485..f3a32b53dc 100644 --- a/protocol/triple/triple_protocol/protocol_triple.go +++ b/protocol/triple/triple_protocol/protocol_triple.go @@ -497,7 +497,7 @@ func (m *tripleUnaryMarshaler) Marshal(message any) *Error { data, err := m.codec.Marshal(message) if err != nil { if m.backupCodec != nil && m.codec.Name() != m.backupCodec.Name() { - logger.Warnf("failed to marshal message with primary codec %s, trying fallback codec %s", m.codec.Name(), m.backupCodec.Name()) + logger.Warnf("[Triple] failed to marshal message with primary codec %s, trying fallback codec %s", m.codec.Name(), m.backupCodec.Name()) data, err = m.backupCodec.Marshal(message) } if err != nil { @@ -557,7 +557,7 @@ func (u *tripleUnaryUnmarshaler) Unmarshal(message any) *Error { err := u.UnmarshalFunc(message, u.codec.Unmarshal) if err != nil { if u.backupCodec != nil && u.codec.Name() != u.backupCodec.Name() { - logger.Warnf("failed to unmarshal message with primary codec %s, trying fallback codec %s", u.codec.Name(), u.backupCodec.Name()) + logger.Warnf("[Triple] failed to unmarshal message with primary codec %s, trying fallback codec %s", u.codec.Name(), u.backupCodec.Name()) err = u.UnmarshalFunc(message, u.backupCodec.Unmarshal) } } diff --git a/protocol/triple/triple_protocol/server.go b/protocol/triple/triple_protocol/server.go index 95121c06a2..6402b9c7f4 100644 --- a/protocol/triple/triple_protocol/server.go +++ b/protocol/triple/triple_protocol/server.go @@ -203,7 +203,7 @@ func (s *Server) startHttp2(tlsConf *tls.Config) error { TLSConfig: tlsConf, } - logger.Debugf("TRIPLE HTTP/2 Server starting on %v", s.addr) + logger.Debugf("[Triple][Server] triple HTTP/2 Server starting on %v", s.addr) var err error @@ -232,7 +232,7 @@ func (s *Server) startHttp3(tlsConf *tls.Config) error { QUICConfig: &quic.Config{}, } - logger.Debugf("TRIPLE HTTP/3 Server starting on %v", s.addr) + logger.Debugf("[Triple][Server] triple HTTP/3 Server starting on %v", s.addr) return s.http3Srv.ListenAndServe() } @@ -265,7 +265,7 @@ func (s *Server) startHttp2AndHttp3(tlsConf *tls.Config) error { TLSConfig: tlsConf, } - logger.Debugf("TRIPLE HTTP/2 and HTTP/3 Server starting on %v", s.addr) + logger.Debugf("[Triple][Server] triple HTTP/2 and HTTP/3 Server starting on %v", s.addr) // Use errgroup to manage concurrent server startup eg := &errgroup.Group{} diff --git a/server/options.go b/server/options.go index c336393770..6877fcd7ff 100644 --- a/server/options.go +++ b/server/options.go @@ -584,6 +584,7 @@ func (svcOpts *ServiceOptions) init(srv *Server, opts ...ServiceOption) error { if err != nil { panic(err) } + svcOpts.adaptiveService = svcOpts.Provider.AdaptiveService svcOpts.needExport = true return commonCfg.Verify(svcOpts) } diff --git a/server/options_test.go b/server/options_test.go index e0005a4dc6..cef258c34d 100644 --- a/server/options_test.go +++ b/server/options_test.go @@ -143,6 +143,33 @@ func TestServiceOptionsInitTranslatesRegistryIDs(t *testing.T) { assert.Equal(t, []string{"r1", "r2"}, svcOpts.Service.RegistryIDs) } +func TestServiceOptionsInitCopiesProviderAdaptiveService(t *testing.T) { + srv := &Server{ + cfg: &ServerOptions{ + Provider: &global.ProviderConfig{ + AdaptiveService: true, + ProtocolIDs: []string{"triple"}, + }, + Protocols: map[string]*global.ProtocolConfig{ + "triple": {Name: "triple"}, + }, + Application: global.DefaultApplicationConfig(), + Metrics: global.DefaultMetricsConfig(), + Otel: global.DefaultOtelConfig(), + }, + } + svcOpts := defaultServiceOptions() + svcOpts.Protocols = srv.cfg.Protocols + svcOpts.Provider = srv.cfg.Provider + + err := svcOpts.init(srv) + require.NoError(t, err) + assert.True(t, svcOpts.adaptiveService) + + urlMap := svcOpts.getUrlMap() + assert.Contains(t, urlMap.Get(constant.ServiceFilterKey), constant.AdaptiveServiceProviderFilterKey) +} + func TestServiceOptionsInitFailsOnInvalidMethodConfig(t *testing.T) { srv := &Server{ cfg: &ServerOptions{