From a87a2b0e2b96268538d9528f9935b003dd2db534 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E4=B8=96=E7=95=8C?= Date: Sat, 28 Mar 2026 02:00:27 +0800 Subject: [PATCH] ocm: log think level --- service/ocm/request_log.go | 62 +++++++++++++++++++++++++ service/ocm/request_log_test.go | 80 ++++++++++++++++++++++++++++++++ service/ocm/service_handler.go | 29 ++---------- service/ocm/service_websocket.go | 20 ++------ 4 files changed, 151 insertions(+), 40 deletions(-) create mode 100644 service/ocm/request_log.go create mode 100644 service/ocm/request_log_test.go diff --git a/service/ocm/request_log.go b/service/ocm/request_log.go new file mode 100644 index 000000000..2459381ac --- /dev/null +++ b/service/ocm/request_log.go @@ -0,0 +1,62 @@ +package ocm + +import "encoding/json" + +type requestLogMetadata struct { + Model string + ServiceTier string + ReasoningEffort string +} + +type requestLogReasoning struct { + Effort string `json:"effort"` +} + +type requestLogPayload struct { + Model string `json:"model"` + ServiceTier string `json:"service_tier"` + Reasoning *requestLogReasoning `json:"reasoning"` + ReasoningEffort string `json:"reasoning_effort"` +} + +func (p requestLogPayload) metadata() requestLogMetadata { + metadata := requestLogMetadata{ + Model: p.Model, + ServiceTier: p.ServiceTier, + } + if p.Reasoning != nil { + metadata.ReasoningEffort = p.Reasoning.Effort + } + if metadata.ReasoningEffort == "" { + metadata.ReasoningEffort = p.ReasoningEffort + } + return metadata +} + +func parseRequestLogMetadata(data []byte) requestLogMetadata { + var payload requestLogPayload + if json.Unmarshal(data, &payload) != nil { + return requestLogMetadata{} + } + return payload.metadata() +} + +func buildAssignedCredentialLogParts(credentialTag string, sessionID string, username string, metadata requestLogMetadata) []any { + logParts := []any{"assigned credential ", credentialTag} + if sessionID != "" { + logParts = append(logParts, " for session ", sessionID) + } + if username != "" { + logParts = append(logParts, " by user ", username) + } + if metadata.Model != "" { + logParts = append(logParts, ", model=", metadata.Model) + } + if metadata.ReasoningEffort != "" { + logParts = append(logParts, ", think=", metadata.ReasoningEffort) + } + if metadata.ServiceTier == "priority" { + logParts = append(logParts, ", fast") + } + return logParts +} diff --git a/service/ocm/request_log_test.go b/service/ocm/request_log_test.go new file mode 100644 index 000000000..27a2a287e --- /dev/null +++ b/service/ocm/request_log_test.go @@ -0,0 +1,80 @@ +package ocm + +import ( + "strings" + "testing" + + F "github.com/sagernet/sing/common/format" +) + +func TestParseRequestLogMetadata(t *testing.T) { + t.Parallel() + + metadata := parseRequestLogMetadata([]byte(`{ + "model":"gpt-5.4", + "service_tier":"priority", + "reasoning":{"effort":"xhigh"} + }`)) + + if metadata.Model != "gpt-5.4" { + t.Fatalf("expected model gpt-5.4, got %q", metadata.Model) + } + if metadata.ServiceTier != "priority" { + t.Fatalf("expected priority service tier, got %q", metadata.ServiceTier) + } + if metadata.ReasoningEffort != "xhigh" { + t.Fatalf("expected xhigh reasoning effort, got %q", metadata.ReasoningEffort) + } +} + +func TestParseRequestLogMetadataFallsBackToTopLevelReasoningEffort(t *testing.T) { + t.Parallel() + + metadata := parseRequestLogMetadata([]byte(`{ + "model":"gpt-5.4", + "reasoning_effort":"high" + }`)) + + if metadata.ReasoningEffort != "high" { + t.Fatalf("expected high reasoning effort, got %q", metadata.ReasoningEffort) + } +} + +func TestBuildAssignedCredentialLogPartsIncludesThinkLevel(t *testing.T) { + t.Parallel() + + message := F.ToString(buildAssignedCredentialLogParts("a", "session-1", "alice", requestLogMetadata{ + Model: "gpt-5.4", + ServiceTier: "priority", + ReasoningEffort: "xhigh", + })...) + + for _, fragment := range []string{ + "assigned credential a", + "for session session-1", + "by user alice", + "model=gpt-5.4", + "think=xhigh", + "fast", + } { + if !strings.Contains(message, fragment) { + t.Fatalf("expected %q in %q", fragment, message) + } + } +} + +func TestParseWebSocketResponseCreateRequestIncludesThinkLevel(t *testing.T) { + t.Parallel() + + request, ok := parseWebSocketResponseCreateRequest([]byte(`{ + "type":"response.create", + "model":"gpt-5.4", + "reasoning":{"effort":"xhigh"} + }`)) + if !ok { + t.Fatal("expected websocket response.create request to parse") + } + if request.metadata().ReasoningEffort != "xhigh" { + t.Fatalf("expected xhigh reasoning effort, got %q", request.metadata().ReasoningEffort) + } +} diff --git a/service/ocm/service_handler.go b/service/ocm/service_handler.go index cfb34e15b..3c10d01f9 100644 --- a/service/ocm/service_handler.go +++ b/service/ocm/service_handler.go @@ -170,9 +170,9 @@ func (s *Service) ServeHTTP(w http.ResponseWriter, r *http.Request) { // Read body for model extraction and retry buffer when JSON replay is useful. var bodyBytes []byte + var requestMetadata requestLogMetadata var requestModel string - var requestServiceTier string - if r.Body != nil && (shouldTrackUsage || canRetryRequest) { + if r.Body != nil && (isNew || shouldTrackUsage || canRetryRequest) { mediaType, _, parseErr := mime.ParseMediaType(r.Header.Get("Content-Type")) isJSONRequest := parseErr == nil && (mediaType == "application/json" || strings.HasSuffix(mediaType, "+json")) if isJSONRequest { @@ -182,33 +182,14 @@ func (s *Service) ServeHTTP(w http.ResponseWriter, r *http.Request) { writeJSONError(w, r, http.StatusInternalServerError, "api_error", "failed to read request body") return } - var request struct { - Model string `json:"model"` - ServiceTier string `json:"service_tier"` - } - if json.Unmarshal(bodyBytes, &request) == nil { - requestModel = request.Model - requestServiceTier = request.ServiceTier - } + requestMetadata = parseRequestLogMetadata(bodyBytes) + requestModel = requestMetadata.Model r.Body = io.NopCloser(bytes.NewReader(bodyBytes)) } } if isNew { - logParts := []any{"assigned credential ", selectedCredential.tagName()} - if sessionID != "" { - logParts = append(logParts, " for session ", sessionID) - } - if username != "" { - logParts = append(logParts, " by user ", username) - } - if requestModel != "" { - logParts = append(logParts, ", model=", requestModel) - } - if requestServiceTier == "priority" { - logParts = append(logParts, ", fast") - } - s.logger.DebugContext(ctx, logParts...) + s.logger.DebugContext(ctx, buildAssignedCredentialLogParts(selectedCredential.tagName(), sessionID, username, requestMetadata)...) } requestContext := selectedCredential.wrapRequestContext(ctx) diff --git a/service/ocm/service_websocket.go b/service/ocm/service_websocket.go index 6691a49af..cdcdb22b8 100644 --- a/service/ocm/service_websocket.go +++ b/service/ocm/service_websocket.go @@ -50,10 +50,9 @@ func (s *webSocketSession) Close() { } type webSocketResponseCreateRequest struct { - Type string `json:"type"` - Model string `json:"model"` - ServiceTier string `json:"service_tier"` - Generate *bool `json:"generate"` + requestLogPayload + Type string `json:"type"` + Generate *bool `json:"generate"` } func parseWebSocketResponseCreateRequest(data []byte) (webSocketResponseCreateRequest, bool) { @@ -364,18 +363,7 @@ func (s *Service) proxyWebSocketClientToUpstream(ctx context.Context, clientConn isWarmup := request.isWarmup() if !isWarmup && isNew && !logged { logged = true - logParts := []any{"assigned credential ", selectedCredential.tagName()} - if sessionID != "" { - logParts = append(logParts, " for session ", sessionID) - } - if username != "" { - logParts = append(logParts, " by user ", username) - } - logParts = append(logParts, ", model=", request.Model) - if request.ServiceTier == "priority" { - logParts = append(logParts, ", fast") - } - s.logger.DebugContext(ctx, logParts...) + s.logger.DebugContext(ctx, buildAssignedCredentialLogParts(selectedCredential.tagName(), sessionID, username, request.metadata())...) } if !isWarmup && selectedCredential.usageTrackerOrNil() != nil { select {