--- r2-before-app.log +++ r2-after-app.log @@ -1,35 +1,39 @@ -{"source":"d73fd1279a9cbf3ef4677b88b4ad82f0a55583c7","driverSha256":"ffcff06fe66e8214c7f250066f58af1b3f93ffd3aa76fcc0076584b9fc554a74","command":"node app-driver.mjs /home/ubuntu/wt/pr-25696-base /tmp/lead-25696-r2/capture/app-before-r2-20261027T1601 32767","node":"v26.12.1","sqlite":"3.54.0","os":"linux x64","machine":"fs-20","home":"/home/ubuntu/wt/pr-25696-base/.t3","recipe":"A: own server fresh database; RPC creates project/thread; stop server; synthetic projection bulk clones; restart; no copied data","expectedCount":32767} -{"start":"empty-initialize","command":"T3CODE_DEV_SEED=0 T3CODE_AUTO_BOOTSTRAP_PROJECT_FROM_CWD=0 T3CODE_LOG_LEVEL=Debug vp run dev --home-dir /home/ubuntu/wt/pr-25696-base/.t3 --no-seed --no-browser","auth":"ephemeral generated dev token, never printed"} -{"spawnPid":1710012} -SERVER [15:59:29.727] INFO (#1): [dev-runner] mode=dev source=worktree /home/ubuntu/wt/pr-25696-base serverPort=16627 webPort=8587 baseDir=/home/ubuntu/wt/pr-25696-base/.t3 -SERVER [15:59:44.032] DEBUG (#6801): Accepting commands -SERVER [15:59:44.033] DEBUG (#6801): startup phase: publishing ready event -{"startup":"empty-initialize","ready":true,"serverPort":16627} -{"spawnedServerPid":1710411,"nodeExecutable":"/home/ubuntu/.local/share/vite-plus/js_runtime/node/26.12.1/bin/node","nodeVersion":"v26.12.1"} -{"spawnedServerPid":1710423,"nodeExecutable":"/home/ubuntu/.local/share/vite-plus/js_runtime/node/26.12.1/bin/node","nodeVersion":"v26.12.1"} -SERVER [15:59:44.034] DEBUG (#7174): startup phase: recording startup heartbeat +{"source":"20d22421d54cce014bfacdeb9d86de83a00a1e4b","driverSha256":"ffcff06fe66e8214c7f250066f58af1b3f93ffd3aa76fcc0076584b9fc554a74","command":"node app-driver.mjs /home/ubuntu/wt/pr-25696 /tmp/lead-25696-r2/capture/app-after-r2-20261027T1601 32767","node":"v26.12.1","sqlite":"3.54.0","os":"linux x64","machine":"fs-20","home":"/home/ubuntu/wt/pr-25696/.t3","recipe":"A: own server fresh database; RPC creates project/thread; stop server; synthetic projection bulk clones; restart; no copied data","expectedCount":32767} +{"start":"empty-initialize","command":"T3CODE_DEV_SEED=0 T3CODE_AUTO_BOOTSTRAP_PROJECT_FROM_CWD=0 T3CODE_LOG_LEVEL=Debug vp run dev --home-dir /home/ubuntu/wt/pr-25696/.t3 --no-seed --no-browser","auth":"ephemeral generated dev token, never printed"} +{"spawnPid":1709953} +SERVER [15:59:28.354] INFO (#1): [dev-runner] mode=dev source=worktree /home/ubuntu/wt/pr-25696 serverPort=16067 webPort=8027 baseDir=/home/ubuntu/wt/pr-25696/.t3 +SERVER [15:59:42.094] DEBUG (#6815): Accepting commands +SERVER [15:59:42.102] DEBUG (#6815): startup phase: publishing ready event +{"startup":"empty-initialize","ready":true,"serverPort":16067} +{"spawnedServerPid":1710101,"nodeExecutable":"/home/ubuntu/.local/share/vite-plus/js_runtime/node/26.12.1/bin/node","nodeVersion":"v26.12.1"} +{"spawnedServerPid":1710137,"nodeExecutable":"/home/ubuntu/.local/share/vite-plus/js_runtime/node/26.12.1/bin/node","nodeVersion":"v26.12.1"} +SERVER [15:59:42.114] DEBUG (#7179): startup phase: recording startup heartbeat {"rpc":"POST /api/projects/mutate","status":200,"projectId":"project:app"} -{"rpc":"orchestration.dispatchCommand","input":{"type":"thread.create","commandId":"c4dbb37c-e74c-4860-9092-af49e0cb253c","threadId":"thread:app:00000","projectId":"project:app","title":"Synthetic thread","createdBy":"user","creationSource":"web","modelSelection":{"instanceId":"codex","model":"gpt-5.4"},"runtimeMode":"full-access","interactionMode":"default","branch":null,"worktreePath":null},"response":{"_tag":"Exit","requestId":"1","exit":{"_tag":"Success","value":{"sequence":2}}}} -{"stopTrackedPids":[1710012,1710023,1710086,1710326,1710410,1710411,1710423,1711236]} +{"rpc":"orchestration.dispatchCommand","input":{"type":"thread.create","commandId":"6b4c43f2-d067-4cf1-a138-20eb5526ab81","threadId":"thread:app:00000","projectId":"project:app","title":"Synthetic thread","createdBy":"user","creationSource":"web","modelSelection":{"instanceId":"codex","model":"gpt-5.4"},"runtimeMode":"full-access","interactionMode":"default","branch":null,"worktreePath":null},"response":{"_tag":"Exit","requestId":"1","exit":{"_tag":"Success","value":{"sequence":2}}}} +{"stopTrackedPids":[1709953,1709963,1709991,1710046,1710099,1710101,1710137,1710964]} {"seed":"synthetic projection fixture","sqlite":{"version":"3.54.0"},"compileOptions":[{"compile_options":"MAX_VARIABLE_NUMBER=32766"}]} {"sqlRowCounts":[{"name":"threads","n":32767},{"name":"runs","n":0},{"name":"items","n":0},{"name":"providers","n":0}],"seedIdDigest":"06b8863b0195e584b138edfd055f707c095f9501877c8d12727a4934b7c16c5e"} -{"start":"seeded-startup","command":"T3CODE_DEV_SEED=0 T3CODE_AUTO_BOOTSTRAP_PROJECT_FROM_CWD=0 T3CODE_LOG_LEVEL=Debug vp run dev --home-dir /home/ubuntu/wt/pr-25696-base/.t3 --no-seed --no-browser","auth":"ephemeral generated dev token, never printed"} -{"spawnPid":1711496} -SERVER [15:59:46.549] INFO (#1): [dev-runner] mode=dev source=worktree /home/ubuntu/wt/pr-25696-base serverPort=16627 webPort=8587 baseDir=/home/ubuntu/wt/pr-25696-base/.t3 -SERVER [16:00:02.230] DEBUG (#6495): Accepting commands -SERVER [16:00:02.232] DEBUG (#6495): startup phase: publishing ready event -{"startup":"seeded-startup","ready":true,"serverPort":16627} -{"spawnedServerPid":1711633,"nodeExecutable":"/home/ubuntu/.local/share/vite-plus/js_runtime/node/26.12.1/bin/node","nodeVersion":"v26.12.1"} -{"spawnedServerPid":1711645,"nodeExecutable":"/home/ubuntu/.local/share/vite-plus/js_runtime/node/26.12.1/bin/node","nodeVersion":"v26.12.1"} +{"start":"seeded-startup","command":"T3CODE_DEV_SEED=0 T3CODE_AUTO_BOOTSTRAP_PROJECT_FROM_CWD=0 T3CODE_LOG_LEVEL=Debug vp run dev --home-dir /home/ubuntu/wt/pr-25696/.t3 --no-seed --no-browser","auth":"ephemeral generated dev token, never printed"} +{"spawnPid":1711400} +SERVER [15:59:45.188] INFO (#1): [dev-runner] mode=dev source=worktree /home/ubuntu/wt/pr-25696 serverPort=16067 webPort=8027 baseDir=/home/ubuntu/wt/pr-25696/.t3 +SERVER [15:59:58.712] DEBUG (#6497): Accepting commands +SERVER [15:59:58.712] DEBUG (#6497): startup phase: publishing ready event +{"startup":"seeded-startup","ready":true,"serverPort":16067} +{"spawnedServerPid":1711533,"nodeExecutable":"/home/ubuntu/.local/share/vite-plus/js_runtime/node/26.12.1/bin/node","nodeVersion":"v26.12.1"} +{"spawnedServerPid":1711553,"nodeExecutable":"/home/ubuntu/.local/share/vite-plus/js_runtime/node/26.12.1/bin/node","nodeVersion":"v26.12.1"} {"postStartupRowCounts":[{"name":"threads","n":32767},{"name":"runs","n":0},{"name":"items","n":0},{"name":"providers","n":0}]} -SERVER [16:00:02.236] DEBUG (#6856): startup phase: recording startup heartbeat -SERVER [16:00:03.456] WARN (#6856): failed to gather V2 startup counts for telemetry -SERVER ' [cause]: Error: too many SQL variables\n' + -SERVER ' [cause]: ProjectionStoreReadError: Failed to read orchestration projection for thread thread:shell.\n' + -SERVER ' [cause]: Error: too many SQL variables\n' + -{"http":"/api/orchestration/shell","status":500,"bytes":145,"error":{"_tag":"EnvironmentInternalError","code":"internal_error","reason":"orchestration_snapshot_failed","traceId":"2c314467527eb062de07fb501b4aa4e0"}} -{"http":"/api/orchestration/shell?omitIdleSubagents=1&omitOlderSettled=1","status":500,"bytes":145,"error":{"_tag":"EnvironmentInternalError","code":"internal_error","reason":"orchestration_snapshot_failed","traceId":"2c314467527eb062de07fb501b4aa4e0"}} -{"ws":"initial marker requested","input":{"requestCompletionMarker":true},"bytes":674,"frames":["Exit"],"items":[],"errors":[{"_tag":"Exit","requestId":"2","exit":{"_tag":"Failure","cause":[{"_tag":"Fail","error":{"_tag":"OrchestrationV2GetShellSnapshotError","message":"Failed to prepare the application shell stream","cause":{"name":"OrchestratorProjectionError","message":"Failed to load orchestration projection for thread thread:shell.","cause":{"name":"ProjectionStoreReadError","message":"Failed to read orchestration projection for thread thread:shell.","cause":{"name":"effect/sql/SqlError","message":"Failed to prepare statement","cause":{"name":"effect/sql/SqlError/UnknownError","message":"Failed to prepare statement","cause":{"name":"Error","message":"too many SQL variables"}}}}}}}]}}]} -R2/R3/R4 baseline ready; HTTP/WS causal failures captured -{"stopTrackedPids":[1711496,1711502,1711568,1711592,1711631,1711633,1711645]} -{"trackedPids":[1710012,1710023,1710086,1710326,1710410,1710411,1710423,1711217,1711236,1711238,1711496,1711502,1711568,1711592,1711631,1711633,1711645,1712468,1712481,1712482]} +SERVER [15:59:58.719] DEBUG (#6858): startup phase: recording startup heartbeat +{"http":"/api/orchestration/shell","status":200,"bytes":46890032,"schemaVersion":2,"snapshotSequence":2,"count":32767,"unique":32767,"idDigest":"06b8863b0195e584b138edfd055f707c095f9501877c8d12727a4934b7c16c5e","archivedThreads":0,"projects":1} +{"http":"/api/orchestration/shell?omitIdleSubagents=1&omitOlderSettled=1","status":200,"bytes":46890114,"schemaVersion":2,"snapshotSequence":2,"count":32767,"unique":32767,"idDigest":"06b8863b0195e584b138edfd055f707c095f9501877c8d12727a4934b7c16c5e","archivedThreads":0,"projects":1} +{"ws":"initial marker requested","input":{"requestCompletionMarker":true},"bytes":46890764,"frames":["Chunk","Chunk"],"items":[{"kind":"snapshot","snapshotSequence":2,"count":32767},{"kind":"snapshot","snapshotSequence":2,"count":0},{"kind":"synchronized"}],"errors":[]} +{"wsMembership":{"schemaVersion":2,"snapshotSequence":2,"count":32767,"unique":32767,"idDigest":"06b8863b0195e584b138edfd055f707c095f9501877c8d12727a4934b7c16c5e","archivedThreads":0,"projects":1}} +{"rpc":"orchestration.dispatchCommand","input":{"type":"thread.metadata.update","commandId":"ddcc5747-b91a-4077-b76f-f6a9cb472cc0","threadId":"thread:app:00000","title":"Synthetic title updated 32767"},"response":{"_tag":"Exit","requestId":"3","exit":{"_tag":"Success","value":{"sequence":3}}}} +{"ws":"initial + live title","input":{"requestCompletionMarker":true},"bytes":46892319,"frames":["Chunk","Chunk","Chunk"],"items":[{"kind":"snapshot","snapshotSequence":2,"count":32767},{"kind":"snapshot","snapshotSequence":2,"count":0},{"kind":"synchronized"},{"kind":"thread.updated","sequence":3,"threadId":"thread:app:00000","title":"Synthetic title updated 32767"}],"errors":[]} +{"ws":"valid-cursor replay","input":{"afterSequence":2,"requestCompletionMarker":true},"bytes":2255,"frames":["Chunk","Chunk","Chunk"],"items":[{"kind":"snapshot","snapshotSequence":3,"count":0},{"kind":"thread.updated","sequence":3,"threadId":"thread:app:00000","title":"Synthetic title updated 32767"},{"kind":"synchronized"}],"errors":[]} +{"ws":"unreplayable-cursor fallback","input":{"afterSequence":1000003,"requestCompletionMarker":true},"bytes":46890777,"frames":["Chunk","Chunk"],"items":[{"kind":"snapshot","snapshotSequence":3,"count":32767},{"kind":"snapshot","snapshotSequence":3,"count":0},{"kind":"synchronized"}],"errors":[]} +{"fallbackMembership":{"schemaVersion":2,"snapshotSequence":3,"count":32767,"unique":32767,"idDigest":"06b8863b0195e584b138edfd055f707c095f9501877c8d12727a4934b7c16c5e","archivedThreads":0,"projects":1}} +{"rpc":"orchestration.dispatchCommand","input":{"type":"thread.metadata.update","commandId":"f2b1810d-40db-483c-8168-6b616e7c6288","threadId":"thread:app:00000","title":"Synthetic no-marker live 32767"},"response":{"_tag":"Exit","requestId":"7","exit":{"_tag":"Success","value":{"sequence":4}}}} +{"ws":"marker omitted; live milestone reached without marker","input":{},"bytes":46892266,"frames":["Chunk","Chunk"],"items":[{"kind":"snapshot","snapshotSequence":3,"count":32767},{"kind":"snapshot","snapshotSequence":3,"count":0},{"kind":"thread.updated","sequence":4,"threadId":"thread:app:00000","title":"Synthetic no-marker live 32767"}],"errors":[]} +ASSERT R1/R2/R3/R4 applicable real-server delivery and synchronization PASS +{"stopTrackedPids":[1711400,1711407,1711460,1711472,1711532,1711533,1711553]} +{"trackedPids":[1709953,1709963,1709991,1710046,1710099,1710101,1710137,1710964,1711400,1711407,1711460,1711472,1711532,1711533,1711553,1711984,1711991,1712001,1712203,1712217]}