Skip to content

Commit 08da5d2

Browse files
github-actions[bot]github-actions[bot]
committed
Merge upstream/main (auto-sync feat/copilot)
- 11f0f90 feat(logging): add `SetTranslatedReasoningEffort` to track reasoning levels in usage reporting - 94c1b25 feat(executor): add TTFT tracking and reporting for enhanced performance metrics - d9c01a6 chore(models): remove deprecated GPT-5.x models from `codex-free` catalog - 2bcc762 feat(logging): improve file-backed source cleanup and directory recreation logic
2 parents 332e8ca + 2bcc762 commit 08da5d2

21 files changed

Lines changed: 481 additions & 88 deletions

‎internal/logging/request_logger.go‎

Lines changed: 18 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -110,6 +110,9 @@ func (s *FileBodySource) CreatePart(prefix string) (*os.File, error) {
110110
return nil, fmt.Errorf("file body source has been cleaned")
111111
}
112112
prefix = sanitizeTempPrefix(prefix)
113+
if errMkdir := os.MkdirAll(s.dir, 0755); errMkdir != nil {
114+
return nil, errMkdir
115+
}
113116
file, errCreate := os.CreateTemp(s.dir, prefix+"-*.tmp")
114117
if errCreate != nil {
115118
return nil, errCreate
@@ -165,16 +168,23 @@ func (s *FileBodySource) WriteTo(w io.Writer) error {
165168
return nil
166169
}
167170
paths := s.Paths()
168-
for i, path := range paths {
169-
if i > 0 {
170-
if _, errWrite := io.WriteString(w, "\n"); errWrite != nil {
171-
return errWrite
172-
}
173-
}
171+
wrote := false
172+
for _, path := range paths {
174173
file, errOpen := os.Open(path)
175174
if errOpen != nil {
175+
if os.IsNotExist(errOpen) {
176+
continue
177+
}
176178
return errOpen
177179
}
180+
if wrote {
181+
if _, errWrite := io.WriteString(w, "\n"); errWrite != nil {
182+
if errClose := file.Close(); errClose != nil {
183+
log.WithError(errClose).Warn("failed to close log part file")
184+
}
185+
return errWrite
186+
}
187+
}
178188
_, errCopy := io.Copy(w, file)
179189
if errClose := file.Close(); errClose != nil {
180190
log.WithError(errClose).Warn("failed to close log part file")
@@ -185,6 +195,7 @@ func (s *FileBodySource) WriteTo(w io.Writer) error {
185195
if errCopy != nil {
186196
return errCopy
187197
}
198+
wrote = true
188199
}
189200
return nil
190201
}
@@ -222,7 +233,7 @@ func (s *FileBodySource) Cleanup() error {
222233
}
223234
}
224235
if dir != "" {
225-
if errRemove := os.Remove(dir); errRemove != nil && !os.IsNotExist(errRemove) && firstErr == nil {
236+
if errRemove := os.RemoveAll(dir); errRemove != nil && firstErr == nil {
226237
firstErr = errRemove
227238
}
228239
}

‎internal/logging/request_logger_home_test.go‎

Lines changed: 54 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@ import (
66
"encoding/json"
77
"net/http"
88
"os"
9+
"path/filepath"
910
"strings"
1011
"testing"
1112
"time"
@@ -23,6 +24,57 @@ func (c *stubHomeRequestLogClient) RPushRequestLog(_ context.Context, payload []
2324
return nil
2425
}
2526

27+
func assertFileBodySourceCleaned(t *testing.T, partPaths []string) {
28+
t.Helper()
29+
30+
dirs := make(map[string]struct{}, len(partPaths))
31+
for _, path := range partPaths {
32+
if _, errStat := os.Stat(path); !os.IsNotExist(errStat) {
33+
t.Fatalf("expected part %s to be removed, stat err=%v", path, errStat)
34+
}
35+
dirs[filepath.Dir(path)] = struct{}{}
36+
}
37+
for dir := range dirs {
38+
if _, errStat := os.Stat(dir); !os.IsNotExist(errStat) {
39+
t.Fatalf("expected part dir %s to be removed, stat err=%v", dir, errStat)
40+
}
41+
}
42+
}
43+
44+
func TestFileBodySource_RecreatesPartDirAfterManualCleanup(t *testing.T) {
45+
logsDir := t.TempDir()
46+
source, errSource := NewFileBodySourceInDir(logsDir, "websocket-timeline-test")
47+
if errSource != nil {
48+
t.Fatalf("NewFileBodySourceInDir: %v", errSource)
49+
}
50+
if errAppend := source.AppendPart([]byte("before manual cleanup")); errAppend != nil {
51+
t.Fatalf("AppendPart before cleanup: %v", errAppend)
52+
}
53+
if errRemove := os.RemoveAll(logsDir); errRemove != nil {
54+
t.Fatalf("RemoveAll logs dir: %v", errRemove)
55+
}
56+
if errAppend := source.AppendPart([]byte("after manual cleanup")); errAppend != nil {
57+
t.Fatalf("AppendPart after cleanup: %v", errAppend)
58+
}
59+
60+
raw, errBytes := source.Bytes()
61+
if errBytes != nil {
62+
t.Fatalf("Bytes after cleanup: %v", errBytes)
63+
}
64+
if bytes.Contains(raw, []byte("before manual cleanup")) {
65+
t.Fatalf("expected manually removed part to be skipped, got %q", string(raw))
66+
}
67+
if !bytes.Contains(raw, []byte("after manual cleanup")) {
68+
t.Fatalf("expected recreated part content, got %q", string(raw))
69+
}
70+
71+
partPaths := source.Paths()
72+
if errCleanup := source.Cleanup(); errCleanup != nil {
73+
t.Fatalf("Cleanup: %v", errCleanup)
74+
}
75+
assertFileBodySourceCleaned(t, partPaths)
76+
}
77+
2678
func TestFileRequestLogger_HomeEnabled_ForwardsWhenRequestLogEnabled(t *testing.T) {
2779
original := currentHomeRequestLogClient
2880
defer func() {
@@ -143,11 +195,7 @@ func TestFileRequestLogger_LogRequestWithSourcesWritesLocalLogAndCleansParts(t *
143195
t.Fatalf("LogRequestWithOptionsAndSources error: %v", errLog)
144196
}
145197

146-
for _, path := range partPaths {
147-
if _, errStat := os.Stat(path); !os.IsNotExist(errStat) {
148-
t.Fatalf("expected part %s to be removed, stat err=%v", path, errStat)
149-
}
150-
}
198+
assertFileBodySourceCleaned(t, partPaths)
151199

152200
entries, errRead := os.ReadDir(logsDir)
153201
if errRead != nil {
@@ -245,11 +293,7 @@ func TestFileRequestLogger_HomeEnabled_ForwardsSourceLogAndCleansParts(t *testin
245293
if !strings.Contains(got.RequestLog, "Event: websocket.request") {
246294
t.Fatalf("forwarded request_log missing websocket request: %s", got.RequestLog)
247295
}
248-
for _, path := range partPaths {
249-
if _, errStat := os.Stat(path); !os.IsNotExist(errStat) {
250-
t.Fatalf("expected part %s to be removed, stat err=%v", path, errStat)
251-
}
252-
}
296+
assertFileBodySourceCleaned(t, partPaths)
253297
}
254298

255299
func TestFileRequestLogger_HomeEnabled_ForwardsStreamingRequestID(t *testing.T) {

‎internal/redisqueue/plugin.go‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -78,6 +78,7 @@ func (p *usageQueuePlugin) HandleUsage(ctx context.Context, record coreusage.Rec
7878
detail := requestDetail{
7979
Timestamp: timestamp,
8080
LatencyMs: record.Latency.Milliseconds(),
81+
TTFTMs: record.TTFT.Milliseconds(),
8182
Source: record.Source,
8283
AuthIndex: record.AuthIndex,
8384
Tokens: tokens,
@@ -118,6 +119,7 @@ type queuedUsageDetail struct {
118119
type requestDetail struct {
119120
Timestamp time.Time `json:"timestamp"`
120121
LatencyMs int64 `json:"latency_ms"`
122+
TTFTMs int64 `json:"ttft_ms"`
121123
Source string `json:"source"`
122124
AuthIndex string `json:"auth_index"`
123125
Tokens tokenStats `json:"tokens"`

‎internal/registry/models/models.json‎

Lines changed: 0 additions & 70 deletions
Original file line numberDiff line numberDiff line change
@@ -1314,76 +1314,6 @@
13141314
}
13151315
],
13161316
"codex-free": [
1317-
{
1318-
"id": "gpt-5.2",
1319-
"object": "model",
1320-
"created": 1765440000,
1321-
"owned_by": "openai",
1322-
"type": "openai",
1323-
"display_name": "GPT 5.2",
1324-
"version": "gpt-5.2",
1325-
"description": "Stable version of GPT 5.2",
1326-
"context_length": 400000,
1327-
"max_completion_tokens": 128000,
1328-
"supported_parameters": [
1329-
"tools"
1330-
],
1331-
"thinking": {
1332-
"levels": [
1333-
"none",
1334-
"low",
1335-
"medium",
1336-
"high",
1337-
"xhigh"
1338-
]
1339-
}
1340-
},
1341-
{
1342-
"id": "gpt-5.3-codex",
1343-
"object": "model",
1344-
"created": 1770307200,
1345-
"owned_by": "openai",
1346-
"type": "openai",
1347-
"display_name": "GPT 5.3 Codex",
1348-
"version": "gpt-5.3",
1349-
"description": "Stable version of GPT 5.3 Codex, The best model for coding and agentic tasks across domains.",
1350-
"context_length": 400000,
1351-
"max_completion_tokens": 128000,
1352-
"supported_parameters": [
1353-
"tools"
1354-
],
1355-
"thinking": {
1356-
"levels": [
1357-
"low",
1358-
"medium",
1359-
"high",
1360-
"xhigh"
1361-
]
1362-
}
1363-
},
1364-
{
1365-
"id": "gpt-5.4",
1366-
"object": "model",
1367-
"created": 1772668800,
1368-
"owned_by": "openai",
1369-
"type": "openai",
1370-
"display_name": "GPT 5.4",
1371-
"version": "gpt-5.4",
1372-
"description": "Stable version of GPT 5.4",
1373-
"context_length": 1050000,
1374-
"max_completion_tokens": 128000,
1375-
"supported_parameters": [
1376-
"tools"
1377-
],
1378-
"thinking": {
1379-
"levels": [
1380-
"low",
1381-
"medium",
1382-
"high",
1383-
"xhigh"
1384-
]
1385-
}
1386-
},
13871317
{
13881318
"id": "gpt-5.4-mini",
13891319
"object": "model",

‎internal/runtime/executor/aistudio_executor.go‎

Lines changed: 14 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -135,6 +135,7 @@ func (e *AIStudioExecutor) Execute(ctx context.Context, auth *cliproxyauth.Auth,
135135
if err != nil {
136136
return resp, err
137137
}
138+
reporter.SetTranslatedReasoningEffort(body.payload, body.toFormat.String())
138139

139140
endpoint := e.buildEndpoint(baseModel, body.action, opts.Alt)
140141
wsReq := &wsrelay.HTTPRequest{
@@ -167,13 +168,16 @@ func (e *AIStudioExecutor) Execute(ctx context.Context, auth *cliproxyauth.Auth,
167168
AuthValue: authValue,
168169
})
169170

171+
reporter.StartResponseTTFT()
170172
wsResp, err := e.relay.NonStream(ctx, authID, wsReq)
171173
if err != nil {
172174
helps.RecordAPIResponseError(ctx, e.cfg, err)
173175
return resp, err
174176
}
175177
helps.RecordAPIResponseMetadata(ctx, e.cfg, wsResp.Status, wsResp.Headers.Clone())
178+
reporter.StartResponseTTFT()
176179
if len(wsResp.Body) > 0 {
180+
reporter.MarkFirstResponseByte()
177181
helps.AppendAPIResponseChunk(ctx, e.cfg, wsResp.Body)
178182
}
179183
if wsResp.Status < 200 || wsResp.Status >= 300 {
@@ -199,6 +203,7 @@ func (e *AIStudioExecutor) ExecuteStream(ctx context.Context, auth *cliproxyauth
199203
if err != nil {
200204
return nil, err
201205
}
206+
reporter.SetTranslatedReasoningEffort(body.payload, body.toFormat.String())
202207

203208
endpoint := e.buildEndpoint(baseModel, body.action, opts.Alt)
204209
wsReq := &wsrelay.HTTPRequest{
@@ -229,6 +234,7 @@ func (e *AIStudioExecutor) ExecuteStream(ctx context.Context, auth *cliproxyauth
229234
AuthType: authType,
230235
AuthValue: authValue,
231236
})
237+
reporter.StartResponseTTFT()
232238
wsStream, err := e.relay.Stream(ctx, authID, wsReq)
233239
if err != nil {
234240
helps.RecordAPIResponseError(ctx, e.cfg, err)
@@ -244,10 +250,12 @@ func (e *AIStudioExecutor) ExecuteStream(ctx context.Context, auth *cliproxyauth
244250
metadataLogged := false
245251
if firstEvent.Status > 0 {
246252
helps.RecordAPIResponseMetadata(ctx, e.cfg, firstEvent.Status, firstEvent.Headers.Clone())
253+
reporter.StartResponseTTFT()
247254
metadataLogged = true
248255
}
249256
var body bytes.Buffer
250257
if len(firstEvent.Payload) > 0 {
258+
reporter.MarkFirstResponseByte()
251259
helps.AppendAPIResponseChunk(ctx, e.cfg, firstEvent.Payload)
252260
body.Write(firstEvent.Payload)
253261
}
@@ -264,9 +272,11 @@ func (e *AIStudioExecutor) ExecuteStream(ctx context.Context, auth *cliproxyauth
264272
}
265273
if !metadataLogged && event.Status > 0 {
266274
helps.RecordAPIResponseMetadata(ctx, e.cfg, event.Status, event.Headers.Clone())
275+
reporter.StartResponseTTFT()
267276
metadataLogged = true
268277
}
269278
if len(event.Payload) > 0 {
279+
reporter.MarkFirstResponseByte()
270280
helps.AppendAPIResponseChunk(ctx, e.cfg, event.Payload)
271281
body.Write(event.Payload)
272282
}
@@ -295,10 +305,12 @@ func (e *AIStudioExecutor) ExecuteStream(ctx context.Context, auth *cliproxyauth
295305
case wsrelay.MessageTypeStreamStart:
296306
if !metadataLogged && event.Status > 0 {
297307
helps.RecordAPIResponseMetadata(ctx, e.cfg, event.Status, event.Headers.Clone())
308+
reporter.StartResponseTTFT()
298309
metadataLogged = true
299310
}
300311
case wsrelay.MessageTypeStreamChunk:
301312
if len(event.Payload) > 0 {
313+
reporter.MarkFirstResponseByte()
302314
helps.AppendAPIResponseChunk(ctx, e.cfg, event.Payload)
303315
filtered := helps.FilterSSEUsageMetadata(event.Payload)
304316
if detail, ok := helps.ParseGeminiStreamUsage(filtered); ok {
@@ -319,9 +331,11 @@ func (e *AIStudioExecutor) ExecuteStream(ctx context.Context, auth *cliproxyauth
319331
case wsrelay.MessageTypeHTTPResp:
320332
if !metadataLogged && event.Status > 0 {
321333
helps.RecordAPIResponseMetadata(ctx, e.cfg, event.Status, event.Headers.Clone())
334+
reporter.StartResponseTTFT()
322335
metadataLogged = true
323336
}
324337
if len(event.Payload) > 0 {
338+
reporter.MarkFirstResponseByte()
325339
helps.AppendAPIResponseChunk(ctx, e.cfg, event.Payload)
326340
}
327341
lines := sdktranslator.TranslateStream(ctx, body.toFormat, opts.SourceFormat, req.Model, opts.OriginalRequest, translatedReq, event.Payload, &param)

0 commit comments

Comments
 (0)