debug(backend/copilot): add detailed UUID logging for merge diagnosis

This commit is contained in:
Zamil Majdy
2026-03-06 16:46:17 +07:00
parent 6c83a91ae3
commit 8ec706c125
2 changed files with 27 additions and 581 deletions

View File

@@ -1,566 +0,0 @@
2026-03-06 16:35:34,059 INFO Initializing LaunchDarkly Client 9.15.0
2026-03-06 16:35:34,061 INFO Starting event processor
2026-03-06 16:35:34,061 INFO Starting StreamingUpdateProcessor connecting to uri: https://stream.launchdarkly.com/all
2026-03-06 16:35:34,061 INFO Waiting up to 5 seconds for LaunchDarkly client to initialize...
2026-03-06 16:35:34,061 INFO Connecting to stream at https://stream.launchdarkly.com/all
2026-03-06 16:35:34,301 INFO StreamingUpdateProcessor initialized ok.
2026-03-06 16:35:34,301 INFO Started LaunchDarkly Client: OK
2026-03-06 16:35:34,301 INFO LaunchDarkly client initialized successfully
2026-03-06 16:35:36,165 WARNING Provider LINEAR implements OAuth but the required env vars LINEAR_CLIENT_ID and LINEAR_CLIENT_SECRET are not both set
2026-03-06 16:35:36,395 INFO Metrics endpoint exposed at /metrics for external-api
2026-03-06 16:35:36,400 INFO Metrics endpoint exposed at /metrics for rest-api
2026-03-06 16:35:36,499 INFO Metrics endpoint exposed at /metrics for websocket-server
2026-03-06 16:35:36,634 INFO OTEL tracing configured for Claude Agent SDK → https://cloud.langfuse.com [local]
2026-03-06 16:35:36,653 WARNING Postmark server API token not found, email sending disabled
2026-03-06 16:35:36,726 INFO [DatabaseManager] started with PID 1316
2026-03-06 16:35:36,728 INFO [Scheduler] started with PID 1318
2026-03-06 16:35:36,731 INFO [NotificationManager] started with PID 1319
2026-03-06 16:35:36,734 INFO [WebsocketServer] started with PID 1320
2026-03-06 16:35:36,738 INFO [AgentServer] started with PID 1321
2026-03-06 16:35:36,744 INFO [ExecutionManager] started with PID 1322
2026-03-06 16:35:36,745 INFO [CoPilotExecutor] Starting...
2026-03-06 16:35:36,745 INFO [CoPilotExecutor] Pod assigned executor_id: 8686d0ee-09a9-4277-9d64-f0dbcfcf77c2
2026-03-06 16:35:36,745 INFO [CoPilotExecutor] Spawn max-5 workers...
2026-03-06 16:35:36,797 INFO [PID-1262|THREAD-6441815|CoPilotExecutor|RabbitMQ-8ceb2763-3499-48ef-bdbc-de4afc265ec8] Acquiring connection started...
2026-03-06 16:35:36,800 INFO [PID-1262|THREAD-6441818|CoPilotExecutor|RabbitMQ-8ceb2763-3499-48ef-bdbc-de4afc265ec8] Acquiring connection started...
2026-03-06 16:35:36,806 INFO Pika version 1.3.2 connecting to ('::1', 5672, 0, 0)
2026-03-06 16:35:36,810 INFO Socket connected: <socket.socket fd=29, family=30, type=1, proto=6, laddr=('::1', 57157, 0, 0), raddr=('::1', 5672, 0, 0)>
2026-03-06 16:35:36,820 INFO Streaming transport linked up: (<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x11ded8050>, _StreamingProtocolShim: <SelectConnection PROTOCOL transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x11ded8050> params=<ConnectionParameters host=localhost port=5672 virtual_host=/ ssl=False>>).
2026-03-06 16:35:36,826 INFO Pika version 1.3.2 connecting to ('::1', 5672, 0, 0)
2026-03-06 16:35:36,830 INFO Socket connected: <socket.socket fd=30, family=30, type=1, proto=6, laddr=('::1', 57158, 0, 0), raddr=('::1', 5672, 0, 0)>
2026-03-06 16:35:36,830 INFO Streaming transport linked up: (<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x11de9d1d0>, _StreamingProtocolShim: <SelectConnection PROTOCOL transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x11de9d1d0> params=<ConnectionParameters host=localhost port=5672 virtual_host=/ ssl=False>>).
2026-03-06 16:35:36,843 INFO AMQPConnector - reporting success: <SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x11ded8050> params=<ConnectionParameters host=localhost port=5672 virtual_host=/ ssl=False>>
2026-03-06 16:35:36,843 INFO AMQPConnectionWorkflow - reporting success: <SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x11ded8050> params=<ConnectionParameters host=localhost port=5672 virtual_host=/ ssl=False>>
2026-03-06 16:35:36,844 INFO Connection workflow succeeded: <SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x11ded8050> params=<ConnectionParameters host=localhost port=5672 virtual_host=/ ssl=False>>
2026-03-06 16:35:36,844 INFO Created channel=1
2026-03-06 16:35:36,844 INFO AMQPConnector - reporting success: <SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x11de9d1d0> params=<ConnectionParameters host=localhost port=5672 virtual_host=/ ssl=False>>
2026-03-06 16:35:36,845 INFO AMQPConnectionWorkflow - reporting success: <SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x11de9d1d0> params=<ConnectionParameters host=localhost port=5672 virtual_host=/ ssl=False>>
2026-03-06 16:35:36,846 INFO Connection workflow succeeded: <SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x11de9d1d0> params=<ConnectionParameters host=localhost port=5672 virtual_host=/ ssl=False>>
2026-03-06 16:35:36,846 INFO Created channel=1
2026-03-06 16:35:36,877 INFO [PID-1262|THREAD-6441815|CoPilotExecutor|RabbitMQ-8ceb2763-3499-48ef-bdbc-de4afc265ec8] Acquiring connection completed successfully.
2026-03-06 16:35:36,879 INFO [PID-1262|THREAD-6441818|CoPilotExecutor|RabbitMQ-8ceb2763-3499-48ef-bdbc-de4afc265ec8] Acquiring connection completed successfully.
2026-03-06 16:35:36,882 INFO [CoPilotExecutor] Starting to consume cancel messages...
2026-03-06 16:35:36,884 INFO [CoPilotExecutor] Starting to consume run messages...
2026-03-06 16:35:38,805 INFO Initializing LaunchDarkly Client 9.15.0
2026-03-06 16:35:38,810 INFO Starting event processor
2026-03-06 16:35:38,811 INFO Starting StreamingUpdateProcessor connecting to uri: https://stream.launchdarkly.com/all
2026-03-06 16:35:38,811 INFO Connecting to stream at https://stream.launchdarkly.com/all
2026-03-06 16:35:38,812 INFO Waiting up to 5 seconds for LaunchDarkly client to initialize...
2026-03-06 16:35:39,093 INFO StreamingUpdateProcessor initialized ok.
2026-03-06 16:35:39,093 INFO Started LaunchDarkly Client: OK
2026-03-06 16:35:39,094 INFO LaunchDarkly client initialized successfully
2026-03-06 16:35:39,817 INFO Initializing LaunchDarkly Client 9.15.0
2026-03-06 16:35:39,819 INFO Starting event processor
2026-03-06 16:35:39,820 INFO Starting StreamingUpdateProcessor connecting to uri: https://stream.launchdarkly.com/all
2026-03-06 16:35:39,820 INFO Connecting to stream at https://stream.launchdarkly.com/all
2026-03-06 16:35:39,821 INFO Waiting up to 5 seconds for LaunchDarkly client to initialize...
2026-03-06 16:35:39,928 INFO Initializing LaunchDarkly Client 9.15.0
2026-03-06 16:35:39,931 INFO Starting event processor
2026-03-06 16:35:39,932 INFO Starting StreamingUpdateProcessor connecting to uri: https://stream.launchdarkly.com/all
2026-03-06 16:35:39,932 INFO Connecting to stream at https://stream.launchdarkly.com/all
2026-03-06 16:35:39,933 INFO Waiting up to 5 seconds for LaunchDarkly client to initialize...
2026-03-06 16:35:40,050 INFO StreamingUpdateProcessor initialized ok.
2026-03-06 16:35:40,050 INFO Started LaunchDarkly Client: OK
2026-03-06 16:35:40,051 INFO LaunchDarkly client initialized successfully
2026-03-06 16:35:40,158 INFO StreamingUpdateProcessor initialized ok.
2026-03-06 16:35:40,159 INFO Started LaunchDarkly Client: OK
2026-03-06 16:35:40,159 INFO LaunchDarkly client initialized successfully
2026-03-06 16:35:40,998 INFO [NotificationManager] Starting...
2026-03-06 16:35:41,070 INFO Metrics endpoint exposed at /metrics for NotificationManager
2026-03-06 16:35:41,078 INFO [PID-1319|THREAD-6442353|NotificationManager|FastAPI server-576423d0-606d-4b37-ba59-67ae4a9fa3b7] Running FastAPI server started...
2026-03-06 16:35:41,080 INFO [NotificationManager] Starting RPC server at http://localhost:8007
2026-03-06 16:35:41,086 INFO [NotificationManager] [NotificationManager] ⏳ Configuring RabbitMQ...
2026-03-06 16:35:41,087 INFO [PID-1319|THREAD-6442354|NotificationManager|AsyncRabbitMQ-998b0654-7ef3-4401-b905-576488df915c] Acquiring async connection started...
2026-03-06 16:35:41,118 INFO Started server process [1319]
2026-03-06 16:35:41,120 INFO Waiting for application startup.
2026-03-06 16:35:41,124 INFO Application startup complete.
2026-03-06 16:35:41,129 INFO Uvicorn running on http://localhost:8007 (Press CTRL+C to quit)
2026-03-06 16:35:41,311 INFO [PID-1319|THREAD-6442354|NotificationManager|AsyncRabbitMQ-998b0654-7ef3-4401-b905-576488df915c] Acquiring async connection completed successfully.
2026-03-06 16:35:41,313 INFO [NotificationManager] [NotificationManager] Started notification service
2026-03-06 16:35:41,315 INFO [NotificationManager] Starting consumer for queue: immediate_notifications
2026-03-06 16:35:41,316 INFO [NotificationManager] Starting consumer for queue: admin_notifications
2026-03-06 16:35:41,317 INFO [NotificationManager] Starting consumer for queue: batch_notifications
2026-03-06 16:35:41,317 INFO [NotificationManager] Starting consumer for queue: summary_notifications
2026-03-06 16:35:41,617 INFO Initializing LaunchDarkly Client 9.15.0
2026-03-06 16:35:41,619 INFO Starting event processor
2026-03-06 16:35:41,620 INFO Starting StreamingUpdateProcessor connecting to uri: https://stream.launchdarkly.com/all
2026-03-06 16:35:41,621 INFO Waiting up to 5 seconds for LaunchDarkly client to initialize...
2026-03-06 16:35:41,621 INFO Connecting to stream at https://stream.launchdarkly.com/all
2026-03-06 16:35:41,637 INFO Initializing LaunchDarkly Client 9.15.0
2026-03-06 16:35:41,638 INFO Initializing LaunchDarkly Client 9.15.0
2026-03-06 16:35:41,640 INFO Starting event processor
2026-03-06 16:35:41,640 INFO Starting event processor
2026-03-06 16:35:41,641 INFO Starting StreamingUpdateProcessor connecting to uri: https://stream.launchdarkly.com/all
2026-03-06 16:35:41,641 INFO Starting StreamingUpdateProcessor connecting to uri: https://stream.launchdarkly.com/all
2026-03-06 16:35:41,641 INFO Connecting to stream at https://stream.launchdarkly.com/all
2026-03-06 16:35:41,641 INFO Waiting up to 5 seconds for LaunchDarkly client to initialize...
2026-03-06 16:35:41,642 INFO Waiting up to 5 seconds for LaunchDarkly client to initialize...
2026-03-06 16:35:41,642 INFO Connecting to stream at https://stream.launchdarkly.com/all
2026-03-06 16:35:41,802 INFO Metrics endpoint exposed at /metrics for websocket-server
2026-03-06 16:35:41,804 INFO [WebsocketServer] Starting...
2026-03-06 16:35:41,804 INFO CORS allow origins: ['http://localhost:3000', 'http://127.0.0.1:3000']
2026-03-06 16:35:41,868 INFO Started server process [1320]
2026-03-06 16:35:41,868 INFO Waiting for application startup.
2026-03-06 16:35:41,871 INFO Application startup complete.
2026-03-06 16:35:41,874 INFO [PID-1320|THREAD-6441789|WebsocketServer|AsyncRedis-e4b6fb9d-7774-4ac2-812e-054989ed3777] Acquiring connection started...
2026-03-06 16:35:41,875 INFO [PID-1320|THREAD-6441789|WebsocketServer|AsyncRedis-e4b6fb9d-7774-4ac2-812e-054989ed3777] Acquiring connection started...
2026-03-06 16:35:41,876 INFO Uvicorn running on http://0.0.0.0:8001 (Press CTRL+C to quit)
2026-03-06 16:35:41,892 INFO [PID-1320|THREAD-6441789|WebsocketServer|AsyncRedis-e4b6fb9d-7774-4ac2-812e-054989ed3777] Acquiring connection completed successfully.
2026-03-06 16:35:41,893 INFO [PID-1320|THREAD-6441789|WebsocketServer|AsyncRedis-e4b6fb9d-7774-4ac2-812e-054989ed3777] Acquiring connection completed successfully.
2026-03-06 16:35:41,954 INFO StreamingUpdateProcessor initialized ok.
2026-03-06 16:35:41,955 INFO Started LaunchDarkly Client: OK
2026-03-06 16:35:41,955 INFO LaunchDarkly client initialized successfully
2026-03-06 16:35:41,958 INFO StreamingUpdateProcessor initialized ok.
2026-03-06 16:35:41,959 INFO Started LaunchDarkly Client: OK
2026-03-06 16:35:41,960 INFO LaunchDarkly client initialized successfully
2026-03-06 16:35:41,960 INFO StreamingUpdateProcessor initialized ok.
2026-03-06 16:35:41,961 INFO Started LaunchDarkly Client: OK
2026-03-06 16:35:41,961 INFO LaunchDarkly client initialized successfully
2026-03-06 16:35:43,408 INFO [DatabaseManager] Starting...
2026-03-06 16:35:43,444 INFO Metrics endpoint exposed at /metrics for DatabaseManager
2026-03-06 16:35:43,500 INFO [Scheduler] Starting...
2026-03-06 16:35:43,505 INFO [PID-1316|THREAD-6442661|DatabaseManager|FastAPI server-ba0decaf-f63f-4a91-91d7-dc9cec853b75] Running FastAPI server started...
2026-03-06 16:35:43,506 INFO [DatabaseManager] Starting RPC server at http://localhost:8005
2026-03-06 16:35:43,509 INFO [ExecutionManager] Starting...
2026-03-06 16:35:43,510 INFO [GraphExecutor] [ExecutionManager] 🆔 Pod assigned executor_id: 2900d4de-4491-404c-a724-378136dee6f2
2026-03-06 16:35:43,511 INFO [GraphExecutor] [ExecutionManager] ⏳ Spawn max-10 workers...
2026-03-06 16:35:43,516 INFO [PID-1322|THREAD-6442680|ExecutionManager|RabbitMQ-eef4b964-09fa-4eb0-8bc9-5312b20dbabc] Acquiring connection started...
2026-03-06 16:35:43,517 INFO [PID-1322|THREAD-6442681|ExecutionManager|RabbitMQ-eef4b964-09fa-4eb0-8bc9-5312b20dbabc] Acquiring connection started...
2026-03-06 16:35:43,519 INFO Pika version 1.3.2 connecting to ('::1', 5672, 0, 0)
2026-03-06 16:35:43,519 INFO [DatabaseManager] ⏳ Connecting to Database...
2026-03-06 16:35:43,519 INFO Pika version 1.3.2 connecting to ('::1', 5672, 0, 0)
2026-03-06 16:35:43,520 INFO [PID-1316|THREAD-6442677|DatabaseManager|Prisma-3e1656b8-e704-4389-8951-eba601327f2a] Acquiring connection started...
2026-03-06 16:35:43,521 INFO Socket connected: <socket.socket fd=20, family=30, type=1, proto=6, laddr=('::1', 57197, 0, 0), raddr=('::1', 5672, 0, 0)>
2026-03-06 16:35:43,521 INFO Socket connected: <socket.socket fd=21, family=30, type=1, proto=6, laddr=('::1', 57198, 0, 0), raddr=('::1', 5672, 0, 0)>
2026-03-06 16:35:43,522 INFO Streaming transport linked up: (<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x11b83ecf0>, _StreamingProtocolShim: <SelectConnection PROTOCOL transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x11b83ecf0> params=<ConnectionParameters host=localhost port=5672 virtual_host=/ ssl=False>>).
2026-03-06 16:35:43,524 INFO Streaming transport linked up: (<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x11b8c6710>, _StreamingProtocolShim: <SelectConnection PROTOCOL transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x11b8c6710> params=<ConnectionParameters host=localhost port=5672 virtual_host=/ ssl=False>>).
2026-03-06 16:35:43,532 INFO AMQPConnector - reporting success: <SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x11b8c6710> params=<ConnectionParameters host=localhost port=5672 virtual_host=/ ssl=False>>
2026-03-06 16:35:43,532 INFO AMQPConnectionWorkflow - reporting success: <SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x11b8c6710> params=<ConnectionParameters host=localhost port=5672 virtual_host=/ ssl=False>>
2026-03-06 16:35:43,533 INFO Connection workflow succeeded: <SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x11b8c6710> params=<ConnectionParameters host=localhost port=5672 virtual_host=/ ssl=False>>
2026-03-06 16:35:43,533 INFO Created channel=1
2026-03-06 16:35:43,533 INFO AMQPConnector - reporting success: <SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x11b83ecf0> params=<ConnectionParameters host=localhost port=5672 virtual_host=/ ssl=False>>
2026-03-06 16:35:43,534 INFO AMQPConnectionWorkflow - reporting success: <SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x11b83ecf0> params=<ConnectionParameters host=localhost port=5672 virtual_host=/ ssl=False>>
2026-03-06 16:35:43,534 INFO Connection workflow succeeded: <SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x11b83ecf0> params=<ConnectionParameters host=localhost port=5672 virtual_host=/ ssl=False>>
2026-03-06 16:35:43,535 INFO Created channel=1
2026-03-06 16:35:43,538 INFO Metrics endpoint exposed at /metrics for Scheduler
2026-03-06 16:35:43,544 INFO [PID-1322|THREAD-6442680|ExecutionManager|RabbitMQ-eef4b964-09fa-4eb0-8bc9-5312b20dbabc] Acquiring connection completed successfully.
2026-03-06 16:35:43,545 INFO [PID-1322|THREAD-6442681|ExecutionManager|RabbitMQ-eef4b964-09fa-4eb0-8bc9-5312b20dbabc] Acquiring connection completed successfully.
2026-03-06 16:35:43,547 INFO [GraphExecutor] [ExecutionManager] ⏳ Starting cancel message consumer...
2026-03-06 16:35:43,549 INFO [GraphExecutor] [ExecutionManager] ⏳ Starting to consume run messages...
2026-03-06 16:35:43,549 INFO [PID-1318|THREAD-6442688|Scheduler|FastAPI server-cea361d4-6aa2-4c35-befe-9ae2dde5e540] Running FastAPI server started...
2026-03-06 16:35:43,550 INFO [Scheduler] Starting RPC server at http://localhost:8003
2026-03-06 16:35:43,683 INFO [PID-1316|THREAD-6442677|DatabaseManager|Prisma-3e1656b8-e704-4389-8951-eba601327f2a] Acquiring connection completed successfully.
2026-03-06 16:35:43,684 INFO [DatabaseManager] ✅ Ready
2026-03-06 16:35:43,700 INFO [Scheduler] [APScheduler] Adding job tentatively -- it will be properly scheduled when the scheduler starts
2026-03-06 16:35:43,701 INFO [Scheduler] [APScheduler] Adding job tentatively -- it will be properly scheduled when the scheduler starts
2026-03-06 16:35:43,701 INFO [Scheduler] [APScheduler] Adding job tentatively -- it will be properly scheduled when the scheduler starts
2026-03-06 16:35:43,701 INFO [Scheduler] [APScheduler] Adding job tentatively -- it will be properly scheduled when the scheduler starts
2026-03-06 16:35:43,701 INFO [Scheduler] [APScheduler] Adding job tentatively -- it will be properly scheduled when the scheduler starts
2026-03-06 16:35:43,702 INFO [Scheduler] [APScheduler] Adding job tentatively -- it will be properly scheduled when the scheduler starts
2026-03-06 16:35:43,702 INFO [Scheduler] [APScheduler] Adding job tentatively -- it will be properly scheduled when the scheduler starts
2026-03-06 16:35:43,855 INFO [Scheduler] [APScheduler] Added job "process_weekly_summary" to job store "weekly_notifications"
2026-03-06 16:35:43,882 INFO [Scheduler] [APScheduler] Added job "report_late_executions" to job store "execution"
2026-03-06 16:35:43,901 INFO [Scheduler] [APScheduler] Added job "report_block_error_rates" to job store "execution"
2026-03-06 16:35:43,920 INFO [Scheduler] [APScheduler] Added job "cleanup_expired_files" to job store "execution"
2026-03-06 16:35:43,931 INFO [Scheduler] [APScheduler] Added job "cleanup_oauth_tokens" to job store "execution"
2026-03-06 16:35:43,943 INFO [Scheduler] [APScheduler] Added job "execution_accuracy_alerts" to job store "execution"
2026-03-06 16:35:43,951 INFO [Scheduler] [APScheduler] Added job "ensure_embeddings_coverage" to job store "execution"
2026-03-06 16:35:43,952 INFO [Scheduler] [APScheduler] Scheduler started
2026-03-06 16:35:43,955 INFO [Scheduler] Running embedding backfill on startup...
2026-03-06 16:35:44,148 INFO [PID-1318|THREAD-6441786|Scheduler|AppService client-84024962-0324-4c9f-806d-5f94331e678a] Creating service client started...
2026-03-06 16:35:44,149 INFO [PID-1318|THREAD-6441786|Scheduler|AppService client-84024962-0324-4c9f-806d-5f94331e678a] Creating service client completed successfully.
2026-03-06 16:35:44,688 WARNING Provider LINEAR implements OAuth but the required env vars LINEAR_CLIENT_ID and LINEAR_CLIENT_SECRET are not both set
2026-03-06 16:35:45,034 INFO Metrics endpoint exposed at /metrics for external-api
2026-03-06 16:35:45,041 INFO Metrics endpoint exposed at /metrics for rest-api
2026-03-06 16:35:45,150 INFO [AgentServer] Starting...
2026-03-06 16:35:45,165 INFO Started server process [1321]
2026-03-06 16:35:45,166 INFO Waiting for application startup.
2026-03-06 16:35:45,167 WARNING ⚠ JWT_SIGN_ALGORITHM is set to 'HS256', a symmetric shared-key signature algorithm. We highly recommend using an asymmetric algorithm such as ES256, because when leaked, a shared secret would allow anyone to forge valid tokens and impersonate users. More info: https://supabase.com/docs/guides/auth/signing-keys#choosing-the-right-signing-algorithm
2026-03-06 16:35:45,168 INFO [PID-1321|THREAD-6441790|AgentServer|Prisma-cdcfac80-c53e-4e93-b4e4-b4c97f4b7142] Acquiring connection started...
2026-03-06 16:35:45,337 INFO [PID-1321|THREAD-6441790|AgentServer|Prisma-cdcfac80-c53e-4e93-b4e4-b4c97f4b7142] Acquiring connection completed successfully.
2026-03-06 16:35:45,352 INFO Thread pool size set to 60 for sync endpoint/dependency performance
2026-03-06 16:35:45,352 INFO Successfully patched IntegrationCredentialsStore.get_all_creds
2026-03-06 16:35:45,353 INFO Syncing provider costs to blocks...
2026-03-06 16:35:45,598 WARNING ⚠ JWT_SIGN_ALGORITHM is set to 'HS256', a symmetric shared-key signature algorithm. We highly recommend using an asymmetric algorithm such as ES256, because when leaked, a shared secret would allow anyone to forge valid tokens and impersonate users. More info: https://supabase.com/docs/guides/auth/signing-keys#choosing-the-right-signing-algorithm
2026-03-06 16:35:45,599 INFO ('127.0.0.1', 57231) - "WebSocket /ws?token=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJzdWIiOiI1NTA2YjNhZi1iNjFjLTQzYTQtOWQ4YS0yNGRlZTE0NzhjZGUiLCJhdWQiOiJhdXRoZW50aWNhdGVkIiwiZXhwIjoxNzcyNzkxNDA5LCJpYXQiOjE3NzI3ODc4MDksImVtYWlsIjoidGVzdGVlZXNlckBnbWFpbC5jb20iLCJwaG9uZSI6IiIsImFwcF9tZXRhZGF0YSI6eyJwcm92aWRlciI6ImVtYWlsIiwicHJvdmlkZXJzIjpbImVtYWlsIl19LCJ1c2VyX21ldGFkYXRhIjp7ImVtYWlsIjoidGVzdGVlZXNlckBnbWFpbC5jb20iLCJlbWFpbF92ZXJpZmllZCI6dHJ1ZSwicGhvbmVfdmVyaWZpZWQiOmZhbHNlLCJzdWIiOiI1NTA2YjNhZi1iNjFjLTQzYTQtOWQ4YS0yNGRlZTE0NzhjZGUifSwicm9sZSI6ImF1dGhlbnRpY2F0ZWQiLCJhYWwiOiJhYWwxIiwiYW1yIjpbeyJtZXRob2QiOiJwYXNzd29yZCIsInRpbWVzdGFtcCI6MTc3MjczNDEyNn1dLCJzZXNzaW9uX2lkIjoiYjJiODI2ZWEtZGFlNC00NzI0LWI4OTYtOGJkMDYyZTc4ZWMwIiwiaXNfYW5vbnltb3VzIjpmYWxzZX0.bdTkp3-FoKa_iEiIX4HANqGwdLMxTRXyXng_fEN6dQw" [accepted]
2026-03-06 16:35:45,599 INFO connection open
2026-03-06 16:35:45,936 WARNING Provider WORDPRESS implements OAuth but the required env vars WORDPRESS_CLIENT_ID and WORDPRESS_CLIENT_SECRET are not both set
2026-03-06 16:35:46,056 INFO Registered 1 custom costs for block FirecrawlExtractBlock
2026-03-06 16:35:46,204 WARNING Provider LINEAR implements OAuth but the required env vars LINEAR_CLIENT_ID and LINEAR_CLIENT_SECRET are not both set
/Users/majdyz/Code/AutoGPT2/autogpt_platform/backend/backend/blocks/exa/helpers.py:56: UserWarning: Field name "schema" in "SummarySettings" shadows an attribute in parent "BaseModel"
class SummarySettings(BaseModel):
2026-03-06 16:35:46,551 WARNING Provider WORDPRESS implements OAuth but the required env vars WORDPRESS_CLIENT_ID and WORDPRESS_CLIENT_SECRET are not both set
2026-03-06 16:35:46,557 WARNING Provider AIRTABLE implements OAuth but the required env vars AIRTABLE_CLIENT_ID and AIRTABLE_CLIENT_SECRET are not both set
2026-03-06 16:35:46,628 INFO Registered 1 custom costs for block FirecrawlExtractBlock
/Users/majdyz/Code/AutoGPT2/autogpt_platform/backend/backend/blocks/exa/helpers.py:56: UserWarning: Field name "schema" in "SummarySettings" shadows an attribute in parent "BaseModel"
class SummarySettings(BaseModel):
2026-03-06 16:35:47,046 WARNING Provider AIRTABLE implements OAuth but the required env vars AIRTABLE_CLIENT_ID and AIRTABLE_CLIENT_SECRET are not both set
2026-03-06 16:35:48,937 INFO Successfully patched IntegrationCredentialsStore.get_all_creds
2026-03-06 16:35:49,147 WARNING Block WordPressCreatePostBlock credential input 'credentials' provider 'wordpress' has no authentication methods configured - Disabling
2026-03-06 16:35:49,148 WARNING Block WordPressGetAllPostsBlock credential input 'credentials' provider 'wordpress' has no authentication methods configured - Disabling
2026-03-06 16:35:49,296 INFO Successfully patched IntegrationCredentialsStore.get_all_creds
2026-03-06 16:35:49,312 INFO [Scheduler] BLOCK: 36 items without embeddings (90.2% coverage)
2026-03-06 16:35:49,312 INFO [Scheduler] Total: 36 items without embeddings (99.3% coverage) - processing all
2026-03-06 16:35:49,315 INFO Processing BLOCK content type...
2026-03-06 16:35:49,323 INFO Processing STORE_AGENT content type...
2026-03-06 16:35:49,328 INFO Processing DOCUMENTATION content type...
2026-03-06 16:35:49,390 INFO [Scheduler] Embedding backfill completed: 0/0 succeeded, 0 failed
2026-03-06 16:35:49,390 INFO [Scheduler] Running cleanup for orphaned embeddings (blocks/docs)...
2026-03-06 16:35:49,409 INFO STORE_AGENT: No orphaned embeddings found
2026-03-06 16:35:49,413 INFO BLOCK: No orphaned embeddings found
2026-03-06 16:35:49,456 INFO DOCUMENTATION: No orphaned embeddings found
2026-03-06 16:35:49,458 INFO [Scheduler] Cleanup completed: no orphaned embeddings found
2026-03-06 16:35:49,458 INFO [Scheduler] Startup embedding backfill complete: {'backfill': {'processed': 0, 'success': 0, 'failed': 0}, 'cleanup': {'deleted': 0}}
2026-03-06 16:35:49,496 INFO Started server process [1318]
2026-03-06 16:35:49,497 INFO Waiting for application startup.
2026-03-06 16:35:49,515 INFO Application startup complete.
2026-03-06 16:35:49,520 INFO Uvicorn running on http://localhost:8003 (Press CTRL+C to quit)
2026-03-06 16:35:49,522 WARNING Block WordPressCreatePostBlock credential input 'credentials' provider 'wordpress' has no authentication methods configured - Disabling
2026-03-06 16:35:49,523 WARNING Block WordPressGetAllPostsBlock credential input 'credentials' provider 'wordpress' has no authentication methods configured - Disabling
2026-03-06 16:35:49,641 INFO Synced 82 costs to 82 blocks
2026-03-06 16:35:49,642 WARNING Executing <Task pending name='Task-2' coro=<LifespanOn.main() running at /Users/majdyz/Code/AutoGPT2/autogpt_platform/autogpt_libs/autogpt_platform/autogpt_libs/.venv/lib/python3.13/site-packages/uvicorn/lifespan/on.py:86> created at /Users/majdyz/Code/AutoGPT2/autogpt_platform/autogpt_libs/autogpt_platform/autogpt_libs/.venv/lib/python3.13/site-packages/uvicorn/lifespan/on.py:51> took 4.305 seconds
2026-03-06 16:35:51,479 INFO ('127.0.0.1', 57274) - "WebSocket /ws?token=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJzdWIiOiI1NTA2YjNhZi1iNjFjLTQzYTQtOWQ4YS0yNGRlZTE0NzhjZGUiLCJhdWQiOiJhdXRoZW50aWNhdGVkIiwiZXhwIjoxNzcyNzkxNDA5LCJpYXQiOjE3NzI3ODc4MDksImVtYWlsIjoidGVzdGVlZXNlckBnbWFpbC5jb20iLCJwaG9uZSI6IiIsImFwcF9tZXRhZGF0YSI6eyJwcm92aWRlciI6ImVtYWlsIiwicHJvdmlkZXJzIjpbImVtYWlsIl19LCJ1c2VyX21ldGFkYXRhIjp7ImVtYWlsIjoidGVzdGVlZXNlckBnbWFpbC5jb20iLCJlbWFpbF92ZXJpZmllZCI6dHJ1ZSwicGhvbmVfdmVyaWZpZWQiOmZhbHNlLCJzdWIiOiI1NTA2YjNhZi1iNjFjLTQzYTQtOWQ4YS0yNGRlZTE0NzhjZGUifSwicm9sZSI6ImF1dGhlbnRpY2F0ZWQiLCJhYWwiOiJhYWwxIiwiYW1yIjpbeyJtZXRob2QiOiJwYXNzd29yZCIsInRpbWVzdGFtcCI6MTc3MjczNDEyNn1dLCJzZXNzaW9uX2lkIjoiYjJiODI2ZWEtZGFlNC00NzI0LWI4OTYtOGJkMDYyZTc4ZWMwIiwiaXNfYW5vbnltb3VzIjpmYWxzZX0.bdTkp3-FoKa_iEiIX4HANqGwdLMxTRXyXng_fEN6dQw" [accepted]
2026-03-06 16:35:51,480 INFO connection open
2026-03-06 16:35:53,139 INFO Migrating integration credentials for 0 users
2026-03-06 16:35:53,152 INFO Fixing LLM credential inputs on 0 nodes
2026-03-06 16:35:53,153 INFO Migrating LLM models
2026-03-06 16:35:53,180 INFO Migrated 0 node triggers to triggered presets
2026-03-06 16:35:53,181 INFO Application startup complete.
2026-03-06 16:35:53,181 INFO Uvicorn running on http://0.0.0.0:8006 (Press CTRL+C to quit)
2026-03-06 16:35:54,407 INFO 127.0.0.1:57288 - "GET /api/library/agents?page=1&page_size=100 HTTP/1.1" 200
2026-03-06 16:35:54,456 INFO 127.0.0.1:57288 - "GET /api/store/profile HTTP/1.1" 200
/Users/majdyz/Code/AutoGPT2/autogpt_platform/autogpt_libs/autogpt_platform/autogpt_libs/.venv/lib/python3.13/site-packages/pyiceberg/expressions/parser.py:72: PyparsingDeprecationWarning: 'enablePackrat' deprecated - use 'enable_packrat'
ParserElement.enablePackrat()
/Users/majdyz/Code/AutoGPT2/autogpt_platform/autogpt_libs/autogpt_platform/autogpt_libs/.venv/lib/python3.13/site-packages/pyiceberg/expressions/parser.py:85: PyparsingDeprecationWarning: 'escChar' argument is deprecated, use 'esc_char'
quoted_identifier = QuotedString('"', escChar="\\", unquoteResults=True)
/Users/majdyz/Code/AutoGPT2/autogpt_platform/autogpt_libs/autogpt_platform/autogpt_libs/.venv/lib/python3.13/site-packages/pyiceberg/expressions/parser.py:85: PyparsingDeprecationWarning: 'unquoteResults' argument is deprecated, use 'unquote_results'
quoted_identifier = QuotedString('"', escChar="\\", unquoteResults=True)
/Users/majdyz/Code/AutoGPT2/autogpt_platform/autogpt_libs/autogpt_platform/autogpt_libs/.venv/lib/python3.13/site-packages/pyiceberg/table/metadata.py:365: PydanticDeprecatedSince212: Using `@model_validator` with mode='after' on a classmethod is deprecated. Instead, use an instance method. See the documentation at https://docs.pydantic.dev/2.12/concepts/validators/#model-after-validator. Deprecated in Pydantic V2.12 to be removed in V3.0.
@model_validator(mode="after")
/Users/majdyz/Code/AutoGPT2/autogpt_platform/autogpt_libs/autogpt_platform/autogpt_libs/.venv/lib/python3.13/site-packages/pyiceberg/table/metadata.py:494: PydanticDeprecatedSince212: Using `@model_validator` with mode='after' on a classmethod is deprecated. Instead, use an instance method. See the documentation at https://docs.pydantic.dev/2.12/concepts/validators/#model-after-validator. Deprecated in Pydantic V2.12 to be removed in V3.0.
@model_validator(mode="after")
/Users/majdyz/Code/AutoGPT2/autogpt_platform/autogpt_libs/autogpt_platform/autogpt_libs/.venv/lib/python3.13/site-packages/pyiceberg/table/metadata.py:498: PydanticDeprecatedSince212: Using `@model_validator` with mode='after' on a classmethod is deprecated. Instead, use an instance method. See the documentation at https://docs.pydantic.dev/2.12/concepts/validators/#model-after-validator. Deprecated in Pydantic V2.12 to be removed in V3.0.
@model_validator(mode="after")
/Users/majdyz/Code/AutoGPT2/autogpt_platform/autogpt_libs/autogpt_platform/autogpt_libs/.venv/lib/python3.13/site-packages/pyiceberg/table/metadata.py:502: PydanticDeprecatedSince212: Using `@model_validator` with mode='after' on a classmethod is deprecated. Instead, use an instance method. See the documentation at https://docs.pydantic.dev/2.12/concepts/validators/#model-after-validator. Deprecated in Pydantic V2.12 to be removed in V3.0.
@model_validator(mode="after")
/Users/majdyz/Code/AutoGPT2/autogpt_platform/autogpt_libs/autogpt_platform/autogpt_libs/.venv/lib/python3.13/site-packages/pyiceberg/table/metadata.py:506: PydanticDeprecatedSince212: Using `@model_validator` with mode='after' on a classmethod is deprecated. Instead, use an instance method. See the documentation at https://docs.pydantic.dev/2.12/concepts/validators/#model-after-validator. Deprecated in Pydantic V2.12 to be removed in V3.0.
@model_validator(mode="after")
/Users/majdyz/Code/AutoGPT2/autogpt_platform/autogpt_libs/autogpt_platform/autogpt_libs/.venv/lib/python3.13/site-packages/pyiceberg/table/metadata.py:538: PydanticDeprecatedSince212: Using `@model_validator` with mode='after' on a classmethod is deprecated. Instead, use an instance method. See the documentation at https://docs.pydantic.dev/2.12/concepts/validators/#model-after-validator. Deprecated in Pydantic V2.12 to be removed in V3.0.
@model_validator(mode="after")
/Users/majdyz/Code/AutoGPT2/autogpt_platform/autogpt_libs/autogpt_platform/autogpt_libs/.venv/lib/python3.13/site-packages/pyiceberg/table/metadata.py:542: PydanticDeprecatedSince212: Using `@model_validator` with mode='after' on a classmethod is deprecated. Instead, use an instance method. See the documentation at https://docs.pydantic.dev/2.12/concepts/validators/#model-after-validator. Deprecated in Pydantic V2.12 to be removed in V3.0.
@model_validator(mode="after")
/Users/majdyz/Code/AutoGPT2/autogpt_platform/autogpt_libs/autogpt_platform/autogpt_libs/.venv/lib/python3.13/site-packages/pyiceberg/table/metadata.py:546: PydanticDeprecatedSince212: Using `@model_validator` with mode='after' on a classmethod is deprecated. Instead, use an instance method. See the documentation at https://docs.pydantic.dev/2.12/concepts/validators/#model-after-validator. Deprecated in Pydantic V2.12 to be removed in V3.0.
@model_validator(mode="after")
/Users/majdyz/Code/AutoGPT2/autogpt_platform/autogpt_libs/autogpt_platform/autogpt_libs/.venv/lib/python3.13/site-packages/pyiceberg/table/metadata.py:550: PydanticDeprecatedSince212: Using `@model_validator` with mode='after' on a classmethod is deprecated. Instead, use an instance method. See the documentation at https://docs.pydantic.dev/2.12/concepts/validators/#model-after-validator. Deprecated in Pydantic V2.12 to be removed in V3.0.
@model_validator(mode="after")
2026-03-06 16:35:54,737 INFO 127.0.0.1:57290 - "GET /api/executions HTTP/1.1" 200
2026-03-06 16:35:54,739 WARNING Executing <Task finished name='Task-9' coro=<RequestResponseCycle.run_asgi() done, defined at /Users/majdyz/Code/AutoGPT2/autogpt_platform/autogpt_libs/autogpt_platform/autogpt_libs/.venv/lib/python3.13/site-packages/uvicorn/protocols/http/httptools_impl.py:414> result=None created at /Users/majdyz/Code/AutoGPT2/autogpt_platform/autogpt_libs/autogpt_platform/autogpt_libs/.venv/lib/python3.13/site-packages/uvicorn/protocols/http/httptools_impl.py:295> took 0.268 seconds
2026-03-06 16:35:54,740 INFO 127.0.0.1:57288 - "GET /api/credits HTTP/1.1" 200
2026-03-06 16:35:54,743 INFO [PID-1321|THREAD-6441790|AgentServer|AsyncRedis-41c5d3d5-985c-4ec6-89e3-98049106a7f1] Acquiring connection started...
2026-03-06 16:35:54,757 INFO [PID-1321|THREAD-6441790|AgentServer|AsyncRedis-41c5d3d5-985c-4ec6-89e3-98049106a7f1] Acquiring connection completed successfully.
2026-03-06 16:35:54,760 INFO Loading session b9bc24cf-9794-42c9-87e7-8231d9e366ce from cache: message_count=8, roles=['user', 'assistant', 'user', 'assistant', 'user', 'assistant', 'user', 'assistant']
2026-03-06 16:35:54,762 INFO 127.0.0.1:57296 - "GET /api/chat/sessions?limit=50 HTTP/1.1" 200
2026-03-06 16:35:54,764 INFO [GET_SESSION] session=b9bc24cf-9794-42c9-87e7-8231d9e366ce, active_session=False, msg_count=8, last_role=assistant
2026-03-06 16:35:54,764 INFO 127.0.0.1:57294 - "GET /api/chat/sessions/b9bc24cf-9794-42c9-87e7-8231d9e366ce HTTP/1.1" 200
2026-03-06 16:35:54,790 INFO 127.0.0.1:57288 - "GET /api/credits HTTP/1.1" 200
2026-03-06 16:36:49,131 INFO 127.0.0.1:57346 - "GET /api/onboarding HTTP/1.1" 200
2026-03-06 16:36:49,149 INFO 127.0.0.1:57348 - "GET /api/library/folders HTTP/1.1" 200
2026-03-06 16:36:49,163 INFO 127.0.0.1:57350 - "GET /api/library/agents?page=1&page_size=20&sort_by=updatedAt&include_root_only=true HTTP/1.1" 200
2026-03-06 16:36:49,169 INFO 127.0.0.1:57352 - "GET /api/library/agents/favorites?page=1&page_size=10 HTTP/1.1" 200
2026-03-06 16:36:49,593 INFO 127.0.0.1:57346 - "GET /api/integrations/providers HTTP/1.1" 200
2026-03-06 16:36:49,598 INFO 127.0.0.1:57348 - "GET /api/integrations/providers/system HTTP/1.1" 200
2026-03-06 16:36:49,863 INFO 127.0.0.1:57346 - "GET /api/library/agents?page=1&page_size=100 HTTP/1.1" 200
2026-03-06 16:36:49,884 INFO 127.0.0.1:57348 - "GET /api/store/profile HTTP/1.1" 200
2026-03-06 16:36:49,895 INFO 127.0.0.1:57346 - "GET /api/library/folders HTTP/1.1" 200
2026-03-06 16:36:49,909 INFO 127.0.0.1:57350 - "GET /api/executions HTTP/1.1" 200
2026-03-06 16:36:49,926 INFO 127.0.0.1:57348 - "GET /api/library/agents?page=1&page_size=20&sort_by=updatedAt&include_root_only=true HTTP/1.1" 200
2026-03-06 16:36:49,934 INFO 127.0.0.1:57346 - "GET /api/library/agents/favorites?page=1&page_size=10 HTTP/1.1" 200
2026-03-06 16:36:49,989 INFO 127.0.0.1:57346 - "GET /api/onboarding HTTP/1.1" 200
2026-03-06 16:36:50,001 INFO 127.0.0.1:57348 - "GET /api/executions HTTP/1.1" 200
2026-03-06 16:36:50,013 INFO 127.0.0.1:57350 - "GET /api/store/profile HTTP/1.1" 200
2026-03-06 16:36:50,030 INFO 127.0.0.1:57352 - "GET /api/library/agents?page=1&page_size=100 HTTP/1.1" 200
2026-03-06 16:36:50,035 INFO 127.0.0.1:57374 - "GET /api/library/agents/favorites?page=1&page_size=10 HTTP/1.1" 200
2026-03-06 16:36:50,040 INFO 127.0.0.1:57346 - "GET /api/library/agents?page=1&page_size=20&sort_by=updatedAt&include_root_only=true HTTP/1.1" 200
2026-03-06 16:36:50,137 INFO 127.0.0.1:57346 - "GET /api/library/folders HTTP/1.1" 200
2026-03-06 16:36:50,150 INFO 127.0.0.1:57348 - "GET /api/integrations/credentials HTTP/1.1" 200
2026-03-06 16:36:50,156 INFO 127.0.0.1:57346 - "GET /api/credits HTTP/1.1" 200
2026-03-06 16:36:50,242 INFO 127.0.0.1:57346 - "GET /api/credits HTTP/1.1" 200
2026-03-06 16:36:50,302 INFO ('127.0.0.1', 57376) - "WebSocket /ws?token=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJzdWIiOiI1NTA2YjNhZi1iNjFjLTQzYTQtOWQ4YS0yNGRlZTE0NzhjZGUiLCJhdWQiOiJhdXRoZW50aWNhdGVkIiwiZXhwIjoxNzcyNzkxNDA5LCJpYXQiOjE3NzI3ODc4MDksImVtYWlsIjoidGVzdGVlZXNlckBnbWFpbC5jb20iLCJwaG9uZSI6IiIsImFwcF9tZXRhZGF0YSI6eyJwcm92aWRlciI6ImVtYWlsIiwicHJvdmlkZXJzIjpbImVtYWlsIl19LCJ1c2VyX21ldGFkYXRhIjp7ImVtYWlsIjoidGVzdGVlZXNlckBnbWFpbC5jb20iLCJlbWFpbF92ZXJpZmllZCI6dHJ1ZSwicGhvbmVfdmVyaWZpZWQiOmZhbHNlLCJzdWIiOiI1NTA2YjNhZi1iNjFjLTQzYTQtOWQ4YS0yNGRlZTE0NzhjZGUifSwicm9sZSI6ImF1dGhlbnRpY2F0ZWQiLCJhYWwiOiJhYWwxIiwiYW1yIjpbeyJtZXRob2QiOiJwYXNzd29yZCIsInRpbWVzdGFtcCI6MTc3MjczNDEyNn1dLCJzZXNzaW9uX2lkIjoiYjJiODI2ZWEtZGFlNC00NzI0LWI4OTYtOGJkMDYyZTc4ZWMwIiwiaXNfYW5vbnltb3VzIjpmYWxzZX0.bdTkp3-FoKa_iEiIX4HANqGwdLMxTRXyXng_fEN6dQw" [accepted]
2026-03-06 16:36:50,305 INFO connection open
2026-03-06 16:36:51,316 INFO Loading session b9bc24cf-9794-42c9-87e7-8231d9e366ce from cache: message_count=8, roles=['user', 'assistant', 'user', 'assistant', 'user', 'assistant', 'user', 'assistant']
2026-03-06 16:36:51,319 INFO [GET_SESSION] session=b9bc24cf-9794-42c9-87e7-8231d9e366ce, active_session=False, msg_count=8, last_role=assistant
2026-03-06 16:36:51,319 INFO 127.0.0.1:57346 - "GET /api/chat/sessions/b9bc24cf-9794-42c9-87e7-8231d9e366ce HTTP/1.1" 200
2026-03-06 16:36:51,467 INFO Loading session b9bc24cf-9794-42c9-87e7-8231d9e366ce from cache: message_count=8, roles=['user', 'assistant', 'user', 'assistant', 'user', 'assistant', 'user', 'assistant']
2026-03-06 16:36:51,471 INFO [GET_SESSION] session=b9bc24cf-9794-42c9-87e7-8231d9e366ce, active_session=False, msg_count=8, last_role=assistant
2026-03-06 16:36:51,475 INFO 127.0.0.1:57346 - "GET /api/chat/sessions/b9bc24cf-9794-42c9-87e7-8231d9e366ce HTTP/1.1" 200
2026-03-06 16:36:51,517 INFO Loading session b9bc24cf-9794-42c9-87e7-8231d9e366ce from cache: message_count=8, roles=['user', 'assistant', 'user', 'assistant', 'user', 'assistant', 'user', 'assistant']
2026-03-06 16:36:51,521 INFO [GET_SESSION] session=b9bc24cf-9794-42c9-87e7-8231d9e366ce, active_session=False, msg_count=8, last_role=assistant
2026-03-06 16:36:51,522 INFO 127.0.0.1:57346 - "GET /api/chat/sessions/b9bc24cf-9794-42c9-87e7-8231d9e366ce HTTP/1.1" 200
2026-03-06 16:36:53,360 INFO 127.0.0.1:57346 - "GET /api/chat/sessions?limit=50 HTTP/1.1" 200
2026-03-06 16:36:54,894 INFO Creating session with user_id: ...e1478cde
2026-03-06 16:36:54,921 INFO 127.0.0.1:57346 - "POST /api/chat/sessions HTTP/1.1" 200
2026-03-06 16:36:55,000 INFO 127.0.0.1:57346 - "GET /api/chat/sessions?limit=50 HTTP/1.1" 200
2026-03-06 16:36:55,075 INFO Loading session 1ec5b199-7aeb-4173-b633-eec072cf711f from cache: message_count=0, roles=[]
2026-03-06 16:36:55,077 INFO [GET_SESSION] session=1ec5b199-7aeb-4173-b633-eec072cf711f, active_session=False, msg_count=0, last_role=none
2026-03-06 16:36:55,077 INFO 127.0.0.1:57346 - "GET /api/chat/sessions/1ec5b199-7aeb-4173-b633-eec072cf711f HTTP/1.1" 200
2026-03-06 16:36:55,121 INFO 127.0.0.1:57384 - "OPTIONS /api/chat/sessions/1ec5b199-7aeb-4173-b633-eec072cf711f/stream HTTP/1.1" 200
2026-03-06 16:36:55,125 INFO [TIMING] stream_chat_post STARTED, session=1ec5b199-7aeb-4173-b633-eec072cf711f, user=5506b3af-b61c-43a4-9d8a-24dee1478cde, message_len=54
2026-03-06 16:36:55,131 INFO Loading session 1ec5b199-7aeb-4173-b633-eec072cf711f from cache: message_count=0, roles=[]
2026-03-06 16:36:55,132 INFO [TIMING] session validated in 6.9ms
2026-03-06 16:36:55,132 INFO [STREAM] Saving user message to session 1ec5b199-7aeb-4173-b633-eec072cf711f
2026-03-06 16:36:55,134 INFO Loading session 1ec5b199-7aeb-4173-b633-eec072cf711f from cache: message_count=0, roles=[]
2026-03-06 16:36:55,157 INFO Saving 1 new messages to DB for session 1ec5b199-7aeb-4173-b633-eec072cf711f: roles=['user'], start_sequence=0
2026-03-06 16:36:55,181 INFO [STREAM] User message saved for session 1ec5b199-7aeb-4173-b633-eec072cf711f
2026-03-06 16:36:55,181 INFO [TIMING] create_session STARTED, session=1ec5b199-7aeb-4173-b633-eec072cf711f, user=5506b3af-b61c-43a4-9d8a-24dee1478cde, turn_id=e8b04b0e-5cb6-4caa-b850-b8ec507bfc17
2026-03-06 16:36:55,181 INFO [TIMING] get_redis_async took 0.0ms
2026-03-06 16:36:55,184 INFO [TIMING] redis.hset took 2.5ms
2026-03-06 16:36:55,186 INFO [TIMING] create_session COMPLETED in 4.8ms; session=1ec5b199-7aeb-4173-b633-eec072cf711f
2026-03-06 16:36:55,186 INFO [TIMING] create_session completed in 5.1ms
2026-03-06 16:36:55,188 INFO [PID-1321|THREAD-6441790|AgentServer|AsyncRabbitMQ-829c8117-4516-4959-8d38-1051f2494ddb] Acquiring async connection started...
2026-03-06 16:36:55,287 INFO [PID-1321|THREAD-6441790|AgentServer|AsyncRabbitMQ-829c8117-4516-4959-8d38-1051f2494ddb] Acquiring async connection completed successfully.
2026-03-06 16:36:55,295 INFO [TIMING] Task enqueued to RabbitMQ, setup=169.8ms
2026-03-06 16:36:55,296 INFO [TIMING] event_generator STARTED, turn=e8b04b0e-5cb6-4caa-b850-b8ec507bfc17, session=1ec5b199-7aeb-4173-b633-eec072cf711f, user=5506b3af-b61c-43a4-9d8a-24dee1478cde
2026-03-06 16:36:55,297 INFO [TIMING] subscribe_to_session STARTED, session=1ec5b199-7aeb-4173-b633-eec072cf711f, user=5506b3af-b61c-43a4-9d8a-24dee1478cde, last_msg=0-0
2026-03-06 16:36:55,299 INFO [TIMING] Redis hgetall took 2.5ms
2026-03-06 16:36:55,302 INFO [TIMING] Redis xread (replay) took 2.5ms, status=running
2026-03-06 16:36:55,303 INFO [TIMING] Replayed 0 messages, last_id=0-0
2026-03-06 16:36:55,303 INFO [TIMING] Session still running, starting _stream_listener
2026-03-06 16:36:55,303 INFO [TIMING] subscribe_to_session COMPLETED in 6.9ms; session=1ec5b199-7aeb-4173-b633-eec072cf711f, n_messages_replayed=0
2026-03-06 16:36:55,304 INFO [TIMING] Starting to read from subscriber_queue
2026-03-06 16:36:55,305 INFO [TIMING] _stream_listener STARTED, session=1ec5b199-7aeb-4173-b633-eec072cf711f, last_id=0-0
2026-03-06 16:36:55,306 INFO [PID-1262|THREAD-6441818|CoPilotExecutor|Redis-083641e1-2e27-4c19-b07b-0aed74bf5f80] Acquiring connection started...
2026-03-06 16:36:55,316 INFO [PID-1262|THREAD-6441818|CoPilotExecutor|Redis-083641e1-2e27-4c19-b07b-0aed74bf5f80] Acquiring connection completed successfully.
2026-03-06 16:36:55,318 INFO [CoPilotExecutor] Acquired cluster lock for 1ec5b199-7aeb-4173-b633-eec072cf711f, executor_id=8686d0ee-09a9-4277-9d64-f0dbcfcf77c2
2026-03-06 16:36:55,340 INFO Using bundled Claude Code CLI: /Users/majdyz/Code/AutoGPT2/autogpt_platform/autogpt_libs/autogpt_platform/autogpt_libs/.venv/lib/python3.13/site-packages/claude_agent_sdk/_bundled/claude
2026-03-06 16:36:55,834 INFO [CoPilotExecutor] [CoPilotExecutor] CLI pre-warm done: /Users/majdyz/Code/AutoGPT2/autogpt_platform/autogpt_libs/autogpt_platform/autogpt_libs/.venv/lib/python3.13/site-packages/claude_agent_sdk/_bundled/claude
2026-03-06 16:36:55,834 INFO [CoPilotExecutor] [CoPilotExecutor] Worker 12935360512 started
2026-03-06 16:36:55,835 INFO [CoPilotExecutor|session_id:1ec5b199-7aeb-4173-b633-eec072cf711f|user_id:5506b3af-b61c-43a4-9d8a-24dee1478cde] Starting execution
2026-03-06 16:36:55,848 INFO [CoPilotExecutor|session_id:1ec5b199-7aeb-4173-b633-eec072cf711f|user_id:5506b3af-b61c-43a4-9d8a-24dee1478cde] Using SDK service
2026-03-06 16:36:55,848 INFO [PID-1262|THREAD-6445184|CoPilotExecutor|AsyncRedis-d33655ce-26c5-4e2e-a673-300d9dcac6d0] Acquiring connection started...
2026-03-06 16:36:55,854 INFO [PID-1262|THREAD-6445184|CoPilotExecutor|AsyncRedis-d33655ce-26c5-4e2e-a673-300d9dcac6d0] Acquiring connection completed successfully.
2026-03-06 16:36:55,856 INFO Loading session 1ec5b199-7aeb-4173-b633-eec072cf711f from cache: message_count=1, roles=['user']
2026-03-06 16:36:55,856 INFO [PID-1262|THREAD-6445184|CoPilotExecutor|AppService client-788d2a2d-2fdd-4af3-b6e8-9ce62e3be6c5] Creating service client started...
2026-03-06 16:36:55,857 INFO [PID-1262|THREAD-6445184|CoPilotExecutor|AppService client-788d2a2d-2fdd-4af3-b6e8-9ce62e3be6c5] Creating service client completed successfully.
2026-03-06 16:36:55,874 INFO 127.0.0.1:57346 - "GET /api/store/profile HTTP/1.1" 200
2026-03-06 16:36:55,935 INFO 127.0.0.1:57346 - "GET /api/chat/sessions?limit=50 HTTP/1.1" 200
2026-03-06 16:36:55,942 INFO 127.0.0.1:57397 - "GET /api/executions HTTP/1.1" 200
2026-03-06 16:36:55,958 INFO Loading session 1ec5b199-7aeb-4173-b633-eec072cf711f from cache: message_count=1, roles=['user']
2026-03-06 16:36:55,968 WARNING [E2B] [1ec5b199-7ae] E2B sandbox enabled but no API key configured (CHAT_E2B_API_KEY / E2B_API_KEY) — falling back to bubblewrap
2026-03-06 16:36:55,974 INFO [PID-1316|THREAD-6442677|DatabaseManager|AsyncRedis-093b82dc-d342-4c42-929b-9ef7874d3d2d] Acquiring connection started...
2026-03-06 16:36:55,981 INFO [PID-1316|THREAD-6442677|DatabaseManager|AsyncRedis-093b82dc-d342-4c42-929b-9ef7874d3d2d] Acquiring connection completed successfully.
2026-03-06 16:36:56,803 INFO [TIMING] xread #1 returned 1 messages in 1498.5ms
2026-03-06 16:36:56,804 INFO [TIMING] publish_chunk StreamStart in 4.0ms (xadd=3.0ms)
2026-03-06 16:36:56,805 INFO [TIMING] FIRST live message at 1500.2ms, type=StreamStart
2026-03-06 16:36:56,805 INFO [TIMING] FIRST CHUNK from queue at 1.51s, type=StreamStart
2026-03-06 16:36:56,806 INFO 127.0.0.1:57384 - "POST /api/chat/sessions/1ec5b199-7aeb-4173-b633-eec072cf711f/stream HTTP/1.1" 200
2026-03-06 16:36:57,358 INFO Claude Code subscription mode: CLI version 2.1.29 (Claude Code)
2026-03-06 16:36:57,376 INFO Using bundled Claude Code CLI: /Users/majdyz/Code/AutoGPT2/autogpt_platform/autogpt_libs/autogpt_platform/autogpt_libs/.venv/lib/python3.13/site-packages/claude_agent_sdk/_bundled/claude
2026-03-06 16:36:57,397 INFO Loading session 1ec5b199-7aeb-4173-b633-eec072cf711f from cache: message_count=1, roles=['user']
2026-03-06 16:36:59,285 INFO [SDK][1ec5b199-7ae][T1] Sending query — resume=False, total_msgs=1, query_len=54, attached_files=0, image_blocks=0
2026-03-06 16:36:59,290 WARNING Run compression is not enabled. Please update to the latest version of LangSmith. Falling back to regular multipart ingestion.
2026-03-06 16:36:59,361 INFO [SDK][1ec5b199-7ae][T1] Received: SystemMessage init (unresolved=0, current=0, resolved=0)
2026-03-06 16:36:59,363 INFO [TIMING] xread #2 returned 1 messages in 2558.2ms
2026-03-06 16:37:03,619 INFO [SDK][1ec5b199-7ae][T1] Received: AssistantMessage (unresolved=0, current=0, resolved=0)
2026-03-06 16:37:03,620 INFO [SDK] [1ec5b199-7ae] Flush called but all 0 tool(s) already resolved
2026-03-06 16:37:04,415 INFO [TIMING] xread #3 timeout after 5050.9ms
2026-03-06 16:37:05,583 INFO [SDK][1ec5b199-7ae][T1] Received: AssistantMessage (unresolved=0, current=0, resolved=0)
2026-03-06 16:37:05,584 INFO [SDK] [1ec5b199-7ae] Flush called but all 0 tool(s) already resolved
2026-03-06 16:37:05,590 INFO [TIMING] xread #4 returned 1 messages in 1166.7ms
2026-03-06 16:37:05,593 INFO [TIMING] publish_chunk StreamTextStart in 9.2ms (xadd=6.3ms)
2026-03-06 16:37:05,595 INFO [TIMING] xread #5 returned 1 messages in 2.7ms
2026-03-06 16:37:05,600 INFO [SDK] Stop hook: transcript_path=/Users/majdyz/.claude/projects/-private-tmp-copilot-1ec5b199-7aeb-4173-b633-eec072cf711f/dae0ef9b-4645-4c01-86b7-8b1afa9ecf10.jsonl, sdk_session_id=dae0ef9b-464...
2026-03-06 16:37:05,601 INFO [SDK][1ec5b199-7ae][T1] Stop hook: captured 2516B, 4 lines from /Users/majdyz/.claude/projects/-private-tmp-copilot-1ec5b199-7aeb-4173-b633-eec072cf711f/dae0ef9b-4645-4c01-86b7-8b1afa9ecf10.jsonl
2026-03-06 16:37:05,611 INFO [SDK][1ec5b199-7ae][T1] Received: ResultMessage success (unresolved=0, current=0, resolved=0)
2026-03-06 16:37:05,612 INFO [SDK][1ec5b199-7ae][T1] Received: ResultMessage success (unresolved=0, current=0, resolved=0)
2026-03-06 16:37:05,612 INFO [SDK] [1ec5b199-7ae] Flush called but all 0 tool(s) already resolved
2026-03-06 16:37:05,613 INFO [TIMING] publish_chunk StreamTextEnd in 1.6ms (xadd=1.0ms)
2026-03-06 16:37:05,614 INFO [TIMING] xread #6 returned 1 messages in 17.1ms
2026-03-06 16:37:05,616 INFO [TIMING] xread #7 returned 1 messages in 1.2ms
2026-03-06 16:37:05,626 INFO [SDK][1ec5b199-7ae][T1] Stream completed successfully with 2 messages
2026-03-06 16:37:05,658 INFO Saving 1 new messages to DB for session 1ec5b199-7aeb-4173-b633-eec072cf711f: roles=['assistant'], start_sequence=1
2026-03-06 16:37:05,673 INFO Loading session 1ec5b199-7aeb-4173-b633-eec072cf711f from cache: message_count=1, roles=['user']
2026-03-06 16:37:05,674 INFO [SDK][1ec5b199-7ae][T1] Session persisted in finally with 2 messages
2026-03-06 16:37:05,674 INFO [SDK][1ec5b199-7ae][T1] Transcript upload: source=stop_hook, stop_hook_fired=True, captured_len=2516, raw_len=2516, use_resume=False
2026-03-06 16:37:05,689 INFO Using local workspace storage: default
2026-03-06 16:37:05,690 INFO [SDK][1ec5b199-7ae][T1] Uploaded 2171B (stripped from 2516B, msg_count=2)
2026-03-06 16:37:05,697 INFO [TIMING] xread #8 returned 1 messages in 80.4ms
2026-03-06 16:37:05,697 INFO [TIMING] publish_chunk StreamFinish in 1.1ms (xadd=0.6ms)
2026-03-06 16:37:05,697 INFO [CoPilotExecutor|session_id:1ec5b199-7aeb-4173-b633-eec072cf711f|user_id:5506b3af-b61c-43a4-9d8a-24dee1478cde] Execution completed in 9.86s
2026-03-06 16:37:05,697 INFO [CoPilotExecutor] Run completed for 1ec5b199-7aeb-4173-b633-eec072cf711f
2026-03-06 16:37:05,697 INFO [TIMING] StreamFinish received in 10.4s; delivered=7
2026-03-06 16:37:05,697 INFO [TIMING] _stream_listener FINISHED in 10.4s; session=1ec5b199-7aeb-4173-b633-eec072cf711f, delivered=7, xread_count=8
2026-03-06 16:37:05,698 INFO [CoPilotExecutor] Releasing cluster lock for 1ec5b199-7aeb-4173-b633-eec072cf711f
2026-03-06 16:37:05,698 INFO [TIMING] StreamFinish received in 10.40s; n_chunks=8
2026-03-06 16:37:05,698 INFO [TIMING] event_generator FINISHED in 10.40s; turn=e8b04b0e-5cb6-4caa-b850-b8ec507bfc17, session=1ec5b199-7aeb-4173-b633-eec072cf711f, n_chunks=8
2026-03-06 16:37:05,699 INFO [CoPilotExecutor] Cleaned up completed session 1ec5b199-7aeb-4173-b633-eec072cf711f
2026-03-06 16:37:05,748 WARNING Invalid type dict for attribute 'langsmith.metadata.usage_metadata' value. Expected one of ['bool', 'str', 'bytes', 'int', 'float'] or a sequence of those types
2026-03-06 16:37:05,812 INFO Loading session 1ec5b199-7aeb-4173-b633-eec072cf711f from cache: message_count=2, roles=['user', 'assistant']
2026-03-06 16:37:05,814 INFO [GET_SESSION] session=1ec5b199-7aeb-4173-b633-eec072cf711f, active_session=False, msg_count=2, last_role=assistant
2026-03-06 16:37:05,814 INFO 127.0.0.1:57435 - "GET /api/chat/sessions/1ec5b199-7aeb-4173-b633-eec072cf711f HTTP/1.1" 200
2026-03-06 16:37:05,836 INFO Loading session 1ec5b199-7aeb-4173-b633-eec072cf711f from cache: message_count=2, roles=['user', 'assistant']
2026-03-06 16:37:05,837 INFO [GET_SESSION] session=1ec5b199-7aeb-4173-b633-eec072cf711f, active_session=False, msg_count=2, last_role=assistant
2026-03-06 16:37:05,838 INFO 127.0.0.1:57435 - "GET /api/chat/sessions/1ec5b199-7aeb-4173-b633-eec072cf711f HTTP/1.1" 200
2026-03-06 16:37:05,843 INFO 127.0.0.1:57437 - "GET /api/chat/sessions?limit=50 HTTP/1.1" 200
2026-03-06 16:37:11,049 INFO [TIMING] stream_chat_post STARTED, session=1ec5b199-7aeb-4173-b633-eec072cf711f, user=5506b3af-b61c-43a4-9d8a-24dee1478cde, message_len=17
2026-03-06 16:37:11,054 INFO Loading session 1ec5b199-7aeb-4173-b633-eec072cf711f from cache: message_count=2, roles=['user', 'assistant']
2026-03-06 16:37:11,055 INFO [TIMING] session validated in 6.2ms
2026-03-06 16:37:11,055 INFO [STREAM] Saving user message to session 1ec5b199-7aeb-4173-b633-eec072cf711f
2026-03-06 16:37:11,058 INFO Loading session 1ec5b199-7aeb-4173-b633-eec072cf711f from cache: message_count=2, roles=['user', 'assistant']
2026-03-06 16:37:11,083 INFO Saving 1 new messages to DB for session 1ec5b199-7aeb-4173-b633-eec072cf711f: roles=['user'], start_sequence=2
2026-03-06 16:37:11,100 INFO [STREAM] User message saved for session 1ec5b199-7aeb-4173-b633-eec072cf711f
2026-03-06 16:37:11,100 INFO [TIMING] create_session STARTED, session=1ec5b199-7aeb-4173-b633-eec072cf711f, user=5506b3af-b61c-43a4-9d8a-24dee1478cde, turn_id=ad978a4a-bfae-4570-a886-a968191f074d
2026-03-06 16:37:11,101 INFO [TIMING] get_redis_async took 0.0ms
2026-03-06 16:37:11,104 INFO [TIMING] redis.hset took 2.5ms
2026-03-06 16:37:11,105 INFO [TIMING] create_session COMPLETED in 4.3ms; session=1ec5b199-7aeb-4173-b633-eec072cf711f
2026-03-06 16:37:11,105 INFO [TIMING] create_session completed in 4.5ms
2026-03-06 16:37:11,115 INFO [TIMING] Task enqueued to RabbitMQ, setup=66.8ms
2026-03-06 16:37:11,117 INFO [TIMING] event_generator STARTED, turn=ad978a4a-bfae-4570-a886-a968191f074d, session=1ec5b199-7aeb-4173-b633-eec072cf711f, user=5506b3af-b61c-43a4-9d8a-24dee1478cde
2026-03-06 16:37:11,117 INFO [TIMING] subscribe_to_session STARTED, session=1ec5b199-7aeb-4173-b633-eec072cf711f, user=5506b3af-b61c-43a4-9d8a-24dee1478cde, last_msg=0-0
2026-03-06 16:37:11,117 INFO [CoPilotExecutor] Acquired cluster lock for 1ec5b199-7aeb-4173-b633-eec072cf711f, executor_id=8686d0ee-09a9-4277-9d64-f0dbcfcf77c2
2026-03-06 16:37:11,118 INFO [TIMING] Redis hgetall took 1.0ms
2026-03-06 16:37:11,118 INFO [CoPilotExecutor|session_id:1ec5b199-7aeb-4173-b633-eec072cf711f|user_id:5506b3af-b61c-43a4-9d8a-24dee1478cde] Starting execution
2026-03-06 16:37:11,119 INFO [TIMING] Redis xread (replay) took 0.9ms, status=running
2026-03-06 16:37:11,120 INFO [TIMING] Replayed 0 messages, last_id=0-0
2026-03-06 16:37:11,120 INFO [TIMING] Session still running, starting _stream_listener
2026-03-06 16:37:11,120 INFO [TIMING] subscribe_to_session COMPLETED in 3.0ms; session=1ec5b199-7aeb-4173-b633-eec072cf711f, n_messages_replayed=0
2026-03-06 16:37:11,120 INFO [TIMING] Starting to read from subscriber_queue
2026-03-06 16:37:11,120 INFO [TIMING] _stream_listener STARTED, session=1ec5b199-7aeb-4173-b633-eec072cf711f, last_id=0-0
2026-03-06 16:37:11,131 INFO [CoPilotExecutor|session_id:1ec5b199-7aeb-4173-b633-eec072cf711f|user_id:5506b3af-b61c-43a4-9d8a-24dee1478cde] Using SDK service
2026-03-06 16:37:11,133 INFO Loading session 1ec5b199-7aeb-4173-b633-eec072cf711f from cache: message_count=3, roles=['user', 'assistant', 'user']
2026-03-06 16:37:11,165 INFO Loading session 1ec5b199-7aeb-4173-b633-eec072cf711f from cache: message_count=3, roles=['user', 'assistant', 'user']
2026-03-06 16:37:11,167 WARNING [E2B] [1ec5b199-7ae] E2B sandbox enabled but no API key configured (CHAT_E2B_API_KEY / E2B_API_KEY) — falling back to bubblewrap
2026-03-06 16:37:11,184 INFO [SDK][1ec5b199-7ae][T2] Downloaded 2171B (msg_count=2)
2026-03-06 16:37:11,188 INFO [SDK][1ec5b199-7ae][T2] Downloaded transcript: 2171B, 2 lines, msg_count=2, valid=True
2026-03-06 16:37:11,188 INFO [Transcript] Wrote resume file: /private/tmp/copilot-1ec5b199-7aeb-4173-b633-eec072cf711f/transcript-1ec5b199.jsonl
2026-03-06 16:37:11,190 INFO [TIMING] xread #1 returned 1 messages in 69.5ms
2026-03-06 16:37:11,191 INFO [TIMING] publish_chunk StreamStart in 2.6ms (xadd=1.8ms)
2026-03-06 16:37:11,191 INFO [TIMING] FIRST live message at 70.6ms, type=StreamStart
2026-03-06 16:37:11,192 INFO [TIMING] FIRST CHUNK from queue at 0.08s, type=StreamStart
2026-03-06 16:37:11,192 INFO 127.0.0.1:57386 - "POST /api/chat/sessions/1ec5b199-7aeb-4173-b633-eec072cf711f/stream HTTP/1.1" 200
2026-03-06 16:37:11,209 INFO Using bundled Claude Code CLI: /Users/majdyz/Code/AutoGPT2/autogpt_platform/autogpt_libs/autogpt_platform/autogpt_libs/.venv/lib/python3.13/site-packages/claude_agent_sdk/_bundled/claude
2026-03-06 16:37:12,239 INFO [SDK][1ec5b199-7ae][T2] Sending query — resume=True, total_msgs=3, query_len=17, attached_files=0, image_blocks=0
2026-03-06 16:37:12,256 INFO [SDK][1ec5b199-7ae][T2] Received: SystemMessage init (unresolved=0, current=0, resolved=0)
2026-03-06 16:37:12,258 INFO [TIMING] xread #2 returned 1 messages in 1066.8ms
2026-03-06 16:37:16,556 INFO [SDK][1ec5b199-7ae][T2] Received: AssistantMessage (unresolved=0, current=0, resolved=0)
2026-03-06 16:37:16,557 INFO [SDK] [1ec5b199-7ae] Flush called but all 0 tool(s) already resolved
2026-03-06 16:37:17,273 INFO [TIMING] xread #3 timeout after 5014.4ms
2026-03-06 16:37:18,505 INFO [SDK][1ec5b199-7ae][T2] Received: AssistantMessage (unresolved=0, current=0, resolved=0)
2026-03-06 16:37:18,506 INFO [SDK] [1ec5b199-7ae] Flush called but all 0 tool(s) already resolved
2026-03-06 16:37:18,511 INFO [TIMING] xread #4 returned 1 messages in 1233.0ms
2026-03-06 16:37:18,513 INFO [TIMING] publish_chunk StreamTextStart in 6.7ms (xadd=4.2ms)
2026-03-06 16:37:18,516 INFO [TIMING] xread #5 returned 1 messages in 3.0ms
2026-03-06 16:37:18,588 INFO [SDK] Stop hook: transcript_path=/Users/majdyz/.claude/projects/-private-tmp-copilot-1ec5b199-7aeb-4173-b633-eec072cf711f/ba9147c7-9eec-46f6-9f0a-9e3ab5f651a3.jsonl, sdk_session_id=ba9147c7-9ee...
2026-03-06 16:37:18,590 INFO [SDK][1ec5b199-7ae][T2] Stop hook: captured 3720B, 6 lines from /Users/majdyz/.claude/projects/-private-tmp-copilot-1ec5b199-7aeb-4173-b633-eec072cf711f/ba9147c7-9eec-46f6-9f0a-9e3ab5f651a3.jsonl
2026-03-06 16:37:18,599 INFO [SDK][1ec5b199-7ae][T2] Received: ResultMessage success (unresolved=0, current=0, resolved=0)
2026-03-06 16:37:18,600 INFO [SDK][1ec5b199-7ae][T2] Received: ResultMessage success (unresolved=0, current=0, resolved=0)
2026-03-06 16:37:18,600 INFO [SDK] [1ec5b199-7ae] Flush called but all 0 tool(s) already resolved
2026-03-06 16:37:18,603 INFO [TIMING] publish_chunk StreamTextEnd in 3.0ms (xadd=1.8ms)
2026-03-06 16:37:18,603 INFO [TIMING] xread #6 returned 1 messages in 84.2ms
2026-03-06 16:37:18,607 INFO [TIMING] xread #7 returned 1 messages in 2.7ms
2026-03-06 16:37:18,619 INFO [SDK][1ec5b199-7ae][T2] Stream completed successfully with 4 messages
2026-03-06 16:37:18,638 INFO Saving 1 new messages to DB for session 1ec5b199-7aeb-4173-b633-eec072cf711f: roles=['assistant'], start_sequence=3
2026-03-06 16:37:18,653 INFO Loading session 1ec5b199-7aeb-4173-b633-eec072cf711f from cache: message_count=3, roles=['user', 'assistant', 'user']
2026-03-06 16:37:18,655 INFO [SDK][1ec5b199-7ae][T2] Session persisted in finally with 4 messages
2026-03-06 16:37:18,655 INFO [SDK][1ec5b199-7ae][T2] Transcript upload: source=stop_hook, stop_hook_fired=True, captured_len=3720, raw_len=3720, use_resume=True
2026-03-06 16:37:18,677 INFO [SDK][1ec5b199-7ae][T2] Uploaded 3412B (stripped from 3720B, msg_count=4)
2026-03-06 16:37:18,683 INFO [TIMING] publish_chunk StreamFinish in 1.0ms (xadd=0.5ms)
2026-03-06 16:37:18,683 INFO [CoPilotExecutor|session_id:1ec5b199-7aeb-4173-b633-eec072cf711f|user_id:5506b3af-b61c-43a4-9d8a-24dee1478cde] Execution completed in 7.56s
2026-03-06 16:37:18,683 INFO [TIMING] xread #8 returned 1 messages in 75.0ms
2026-03-06 16:37:18,683 INFO [CoPilotExecutor] Run completed for 1ec5b199-7aeb-4173-b633-eec072cf711f
2026-03-06 16:37:18,683 INFO [CoPilotExecutor] Releasing cluster lock for 1ec5b199-7aeb-4173-b633-eec072cf711f
2026-03-06 16:37:18,683 INFO [TIMING] StreamFinish received in 7.6s; delivered=7
2026-03-06 16:37:18,684 INFO [TIMING] _stream_listener FINISHED in 7.6s; session=1ec5b199-7aeb-4173-b633-eec072cf711f, delivered=7, xread_count=8
2026-03-06 16:37:18,684 INFO [TIMING] StreamFinish received in 7.57s; n_chunks=8
2026-03-06 16:37:18,684 INFO [TIMING] event_generator FINISHED in 7.57s; turn=ad978a4a-bfae-4570-a886-a968191f074d, session=1ec5b199-7aeb-4173-b633-eec072cf711f, n_chunks=8
2026-03-06 16:37:18,684 INFO [CoPilotExecutor] Cleaned up completed session 1ec5b199-7aeb-4173-b633-eec072cf711f
2026-03-06 16:37:18,735 WARNING Invalid type dict for attribute 'langsmith.metadata.usage_metadata' value. Expected one of ['bool', 'str', 'bytes', 'int', 'float'] or a sequence of those types
2026-03-06 16:37:18,781 INFO Loading session 1ec5b199-7aeb-4173-b633-eec072cf711f from cache: message_count=4, roles=['user', 'assistant', 'user', 'assistant']
2026-03-06 16:37:18,783 INFO [GET_SESSION] session=1ec5b199-7aeb-4173-b633-eec072cf711f, active_session=False, msg_count=4, last_role=assistant
2026-03-06 16:37:18,783 INFO 127.0.0.1:57475 - "GET /api/chat/sessions/1ec5b199-7aeb-4173-b633-eec072cf711f HTTP/1.1" 200
2026-03-06 16:37:18,810 INFO 127.0.0.1:57475 - "GET /api/chat/sessions?limit=50 HTTP/1.1" 200
2026-03-06 16:37:18,828 INFO Loading session 1ec5b199-7aeb-4173-b633-eec072cf711f from cache: message_count=4, roles=['user', 'assistant', 'user', 'assistant']
2026-03-06 16:37:18,831 INFO [GET_SESSION] session=1ec5b199-7aeb-4173-b633-eec072cf711f, active_session=False, msg_count=4, last_role=assistant
2026-03-06 16:37:18,831 INFO 127.0.0.1:57475 - "GET /api/chat/sessions/1ec5b199-7aeb-4173-b633-eec072cf711f HTTP/1.1" 200
2026-03-06 16:37:21,530 INFO [TIMING] stream_chat_post STARTED, session=1ec5b199-7aeb-4173-b633-eec072cf711f, user=5506b3af-b61c-43a4-9d8a-24dee1478cde, message_len=71
2026-03-06 16:37:21,534 INFO Loading session 1ec5b199-7aeb-4173-b633-eec072cf711f from cache: message_count=4, roles=['user', 'assistant', 'user', 'assistant']
2026-03-06 16:37:21,534 INFO [TIMING] session validated in 4.3ms
2026-03-06 16:37:21,535 INFO [STREAM] Saving user message to session 1ec5b199-7aeb-4173-b633-eec072cf711f
2026-03-06 16:37:21,537 INFO Loading session 1ec5b199-7aeb-4173-b633-eec072cf711f from cache: message_count=4, roles=['user', 'assistant', 'user', 'assistant']
2026-03-06 16:37:21,560 INFO Saving 1 new messages to DB for session 1ec5b199-7aeb-4173-b633-eec072cf711f: roles=['user'], start_sequence=4
2026-03-06 16:37:21,588 INFO [STREAM] User message saved for session 1ec5b199-7aeb-4173-b633-eec072cf711f
2026-03-06 16:37:21,588 INFO [TIMING] create_session STARTED, session=1ec5b199-7aeb-4173-b633-eec072cf711f, user=5506b3af-b61c-43a4-9d8a-24dee1478cde, turn_id=5f1feccc-b06a-4d56-960a-a111481d9f9f
2026-03-06 16:37:21,589 INFO [TIMING] get_redis_async took 0.0ms
2026-03-06 16:37:21,591 INFO [TIMING] redis.hset took 1.9ms
2026-03-06 16:37:21,594 INFO [TIMING] create_session COMPLETED in 5.4ms; session=1ec5b199-7aeb-4173-b633-eec072cf711f
2026-03-06 16:37:21,595 INFO [TIMING] create_session completed in 6.4ms
2026-03-06 16:37:21,603 INFO [TIMING] Task enqueued to RabbitMQ, setup=72.8ms
2026-03-06 16:37:21,603 INFO [CoPilotExecutor] Acquired cluster lock for 1ec5b199-7aeb-4173-b633-eec072cf711f, executor_id=8686d0ee-09a9-4277-9d64-f0dbcfcf77c2
2026-03-06 16:37:21,604 INFO [CoPilotExecutor|session_id:1ec5b199-7aeb-4173-b633-eec072cf711f|user_id:5506b3af-b61c-43a4-9d8a-24dee1478cde] Starting execution
2026-03-06 16:37:21,604 INFO [TIMING] event_generator STARTED, turn=5f1feccc-b06a-4d56-960a-a111481d9f9f, session=1ec5b199-7aeb-4173-b633-eec072cf711f, user=5506b3af-b61c-43a4-9d8a-24dee1478cde
2026-03-06 16:37:21,605 INFO [TIMING] subscribe_to_session STARTED, session=1ec5b199-7aeb-4173-b633-eec072cf711f, user=5506b3af-b61c-43a4-9d8a-24dee1478cde, last_msg=0-0
2026-03-06 16:37:21,607 INFO [TIMING] Redis hgetall took 1.4ms
2026-03-06 16:37:21,608 INFO [TIMING] Redis xread (replay) took 1.3ms, status=running
2026-03-06 16:37:21,609 INFO [TIMING] Replayed 0 messages, last_id=0-0
2026-03-06 16:37:21,609 INFO [TIMING] Session still running, starting _stream_listener
2026-03-06 16:37:21,609 INFO [TIMING] subscribe_to_session COMPLETED in 4.4ms; session=1ec5b199-7aeb-4173-b633-eec072cf711f, n_messages_replayed=0
2026-03-06 16:37:21,610 INFO [TIMING] Starting to read from subscriber_queue
2026-03-06 16:37:21,610 INFO [TIMING] _stream_listener STARTED, session=1ec5b199-7aeb-4173-b633-eec072cf711f, last_id=0-0
2026-03-06 16:37:21,618 INFO [CoPilotExecutor|session_id:1ec5b199-7aeb-4173-b633-eec072cf711f|user_id:5506b3af-b61c-43a4-9d8a-24dee1478cde] Using SDK service
2026-03-06 16:37:21,621 INFO Loading session 1ec5b199-7aeb-4173-b633-eec072cf711f from cache: message_count=5, roles=['user', 'assistant', 'user', 'assistant', 'user']
2026-03-06 16:37:21,638 INFO Loading session 1ec5b199-7aeb-4173-b633-eec072cf711f from cache: message_count=5, roles=['user', 'assistant', 'user', 'assistant', 'user']
2026-03-06 16:37:21,640 WARNING [E2B] [1ec5b199-7ae] E2B sandbox enabled but no API key configured (CHAT_E2B_API_KEY / E2B_API_KEY) — falling back to bubblewrap
2026-03-06 16:37:21,658 INFO [SDK][1ec5b199-7ae][T3] Downloaded 3412B (msg_count=4)
2026-03-06 16:37:21,661 INFO [SDK][1ec5b199-7ae][T3] Downloaded transcript: 3412B, 4 lines, msg_count=4, valid=True
2026-03-06 16:37:21,661 INFO [Transcript] Wrote resume file: /private/tmp/copilot-1ec5b199-7aeb-4173-b633-eec072cf711f/transcript-1ec5b199.jsonl
2026-03-06 16:37:21,663 INFO [TIMING] publish_chunk StreamStart in 1.4ms (xadd=1.0ms)
2026-03-06 16:37:21,663 INFO [TIMING] xread #1 returned 1 messages in 52.6ms
2026-03-06 16:37:21,663 INFO [TIMING] FIRST live message at 53.3ms, type=StreamStart
2026-03-06 16:37:21,664 INFO [TIMING] FIRST CHUNK from queue at 0.06s, type=StreamStart
2026-03-06 16:37:21,664 INFO 127.0.0.1:57386 - "POST /api/chat/sessions/1ec5b199-7aeb-4173-b633-eec072cf711f/stream HTTP/1.1" 200
2026-03-06 16:37:21,681 INFO Using bundled Claude Code CLI: /Users/majdyz/Code/AutoGPT2/autogpt_platform/autogpt_libs/autogpt_platform/autogpt_libs/.venv/lib/python3.13/site-packages/claude_agent_sdk/_bundled/claude
2026-03-06 16:37:22,709 INFO [SDK][1ec5b199-7ae][T3] Sending query — resume=True, total_msgs=5, query_len=71, attached_files=0, image_blocks=0
2026-03-06 16:37:22,724 INFO [SDK][1ec5b199-7ae][T3] Received: SystemMessage init (unresolved=0, current=0, resolved=0)
2026-03-06 16:37:22,727 INFO [TIMING] xread #2 returned 1 messages in 1063.3ms
2026-03-06 16:37:27,786 INFO [TIMING] xread #3 timeout after 5058.2ms
2026-03-06 16:37:32,735 INFO [TIMING] xread #4 returned 1 messages in 4944.1ms
2026-03-06 16:37:32,858 INFO [SDK][1ec5b199-7ae][T3] Received: AssistantMessage (unresolved=0, current=0, resolved=0)
2026-03-06 16:37:32,859 INFO [SDK] [1ec5b199-7ae] Flush called but all 0 tool(s) already resolved
2026-03-06 16:37:34,993 INFO [SDK][1ec5b199-7ae][T3] Received: AssistantMessage (unresolved=0, current=0, resolved=0)
2026-03-06 16:37:34,993 INFO [SDK] [1ec5b199-7ae] Flush called but all 0 tool(s) already resolved
2026-03-06 16:37:34,997 INFO [TIMING] publish_chunk StreamTextStart in 3.2ms (xadd=2.2ms)
2026-03-06 16:37:34,996 INFO [TIMING] xread #5 returned 1 messages in 2259.0ms
2026-03-06 16:37:35,002 INFO [TIMING] xread #6 returned 1 messages in 3.1ms
2026-03-06 16:37:35,044 INFO [SDK] Stop hook: transcript_path=/Users/majdyz/.claude/projects/-private-tmp-copilot-1ec5b199-7aeb-4173-b633-eec072cf711f/0a1e6852-eed6-44c5-b342-db5470cece05.jsonl, sdk_session_id=0a1e6852-eed...
2026-03-06 16:37:35,046 INFO [SDK][1ec5b199-7ae][T3] Stop hook: captured 7734B, 8 lines from /Users/majdyz/.claude/projects/-private-tmp-copilot-1ec5b199-7aeb-4173-b633-eec072cf711f/0a1e6852-eed6-44c5-b342-db5470cece05.jsonl
2026-03-06 16:37:35,055 INFO [SDK][1ec5b199-7ae][T3] Received: ResultMessage success (unresolved=0, current=0, resolved=0)
2026-03-06 16:37:35,055 INFO [SDK][1ec5b199-7ae][T3] Received: ResultMessage success (unresolved=0, current=0, resolved=0)
2026-03-06 16:37:35,055 INFO [SDK] [1ec5b199-7ae] Flush called but all 0 tool(s) already resolved
2026-03-06 16:37:35,059 INFO [TIMING] publish_chunk StreamTextEnd in 3.1ms (xadd=2.1ms)
2026-03-06 16:37:35,058 INFO [TIMING] xread #7 returned 1 messages in 54.4ms
2026-03-06 16:37:35,062 INFO [TIMING] xread #8 returned 1 messages in 2.3ms
2026-03-06 16:37:35,075 INFO [SDK][1ec5b199-7ae][T3] Stream completed successfully with 6 messages
2026-03-06 16:37:35,101 INFO Saving 1 new messages to DB for session 1ec5b199-7aeb-4173-b633-eec072cf711f: roles=['assistant'], start_sequence=5
2026-03-06 16:37:35,128 INFO Loading session 1ec5b199-7aeb-4173-b633-eec072cf711f from cache: message_count=5, roles=['user', 'assistant', 'user', 'assistant', 'user']
2026-03-06 16:37:35,133 INFO [SDK][1ec5b199-7ae][T3] Session persisted in finally with 6 messages
2026-03-06 16:37:35,133 INFO [SDK][1ec5b199-7ae][T3] Transcript upload: source=stop_hook, stop_hook_fired=True, captured_len=7734, raw_len=7734, use_resume=True
2026-03-06 16:37:35,156 INFO [SDK][1ec5b199-7ae][T3] Uploaded 7372B (stripped from 7734B, msg_count=6)
2026-03-06 16:37:35,163 INFO [TIMING] publish_chunk StreamFinish in 1.5ms (xadd=0.9ms)
2026-03-06 16:37:35,163 INFO [TIMING] xread #9 returned 1 messages in 99.8ms
2026-03-06 16:37:35,164 INFO [CoPilotExecutor|session_id:1ec5b199-7aeb-4173-b633-eec072cf711f|user_id:5506b3af-b61c-43a4-9d8a-24dee1478cde] Execution completed in 13.56s
2026-03-06 16:37:35,164 INFO [CoPilotExecutor] Run completed for 1ec5b199-7aeb-4173-b633-eec072cf711f
2026-03-06 16:37:35,164 INFO [CoPilotExecutor] Releasing cluster lock for 1ec5b199-7aeb-4173-b633-eec072cf711f
2026-03-06 16:37:35,164 INFO [TIMING] StreamFinish received in 13.6s; delivered=8
2026-03-06 16:37:35,164 INFO [TIMING] _stream_listener FINISHED in 13.6s; session=1ec5b199-7aeb-4173-b633-eec072cf711f, delivered=8, xread_count=9
2026-03-06 16:37:35,164 INFO [TIMING] StreamFinish received in 13.56s; n_chunks=9
2026-03-06 16:37:35,165 INFO [CoPilotExecutor] Cleaned up completed session 1ec5b199-7aeb-4173-b633-eec072cf711f
2026-03-06 16:37:35,165 INFO [TIMING] event_generator FINISHED in 13.56s; turn=5f1feccc-b06a-4d56-960a-a111481d9f9f, session=1ec5b199-7aeb-4173-b633-eec072cf711f, n_chunks=9
2026-03-06 16:37:35,213 WARNING Invalid type dict for attribute 'langsmith.metadata.usage_metadata' value. Expected one of ['bool', 'str', 'bytes', 'int', 'float'] or a sequence of those types
2026-03-06 16:37:35,263 INFO Loading session 1ec5b199-7aeb-4173-b633-eec072cf711f from cache: message_count=6, roles=['user', 'assistant', 'user', 'assistant', 'user', 'assistant']
2026-03-06 16:37:35,268 INFO [GET_SESSION] session=1ec5b199-7aeb-4173-b633-eec072cf711f, active_session=False, msg_count=6, last_role=assistant
2026-03-06 16:37:35,268 INFO 127.0.0.1:57506 - "GET /api/chat/sessions/1ec5b199-7aeb-4173-b633-eec072cf711f HTTP/1.1" 200
2026-03-06 16:37:35,293 INFO 127.0.0.1:57508 - "GET /api/chat/sessions?limit=50 HTTP/1.1" 200
2026-03-06 16:37:35,318 INFO Loading session 1ec5b199-7aeb-4173-b633-eec072cf711f from cache: message_count=6, roles=['user', 'assistant', 'user', 'assistant', 'user', 'assistant']
2026-03-06 16:37:35,320 INFO [GET_SESSION] session=1ec5b199-7aeb-4173-b633-eec072cf711f, active_session=False, msg_count=6, last_role=assistant
2026-03-06 16:37:35,320 INFO 127.0.0.1:57506 - "GET /api/chat/sessions/1ec5b199-7aeb-4173-b633-eec072cf711f HTTP/1.1" 200
2026-03-06 16:37:50,884 INFO 127.0.0.1:57526 - "GET /api/store/profile HTTP/1.1" 200
2026-03-06 16:37:50,891 INFO 127.0.0.1:57528 - "GET /api/executions HTTP/1.1" 200

View File

@@ -95,16 +95,21 @@ def merge_with_previous_transcript(
if entry.get("type") == "assistant" and (uid := entry.get("uuid")):
prev_by_uuid[uid] = line
logger.debug(
"%s Indexed %d assistant entries from previous", log_prefix, len(prev_by_uuid)
logger.info(
"%s Indexed %d assistant UUIDs from previous: %s",
log_prefix,
len(prev_by_uuid),
list(prev_by_uuid.keys())[:5], # Show first 5 UUIDs
)
if not prev_by_uuid:
logger.warning("%s No assistant entries in previous transcript!", log_prefix)
return new_content
# Replace assistant entries that exist in previous transcript (hydrate real content)
merged_lines: list[str] = []
replaced = 0
new_assistant_uuids = []
for line in new_content.strip().split("\n"):
try:
@@ -113,19 +118,26 @@ def merge_with_previous_transcript(
merged_lines.append(line)
continue
# If this is an assistant entry with a UUID that exists in previous, use previous version
if (
entry.get("type") == "assistant"
and (uid := entry.get("uuid"))
and uid in prev_by_uuid
):
merged_lines.append(prev_by_uuid[uid])
replaced += 1
logger.debug(
"%s Replaced assistant uuid=%s with version from previous",
log_prefix,
uid[:12],
)
# Track assistant UUIDs in new transcript
if entry.get("type") == "assistant" and (uid := entry.get("uuid")):
new_assistant_uuids.append(uid)
# If this UUID exists in previous, use previous version
if uid in prev_by_uuid:
merged_lines.append(prev_by_uuid[uid])
replaced += 1
logger.info(
"%s Replaced assistant uuid=%s with version from previous",
log_prefix,
uid[:12],
)
else:
logger.info(
"%s Assistant uuid=%s NOT in previous (keeping new)",
log_prefix,
uid[:12],
)
merged_lines.append(line)
else:
merged_lines.append(line)