99
1010import json
1111import logging
12+ import time
1213from typing import Any
1314
1415from services .database import Database
@@ -68,7 +69,7 @@ def _validate_plan(self, plan: list[dict]) -> None:
6869 raise ValueError ("generate_image must be the last step in plan" )
6970 has_image = True
7071
71- logger .info (f"[AGENT ] Plan validated: { len (plan )} steps" )
72+ logger .info (f"[AUTOPOST ] Plan validated: { len (plan )} steps" )
7273
7374 async def run (self ) -> dict [str , Any ]:
7475 """
@@ -85,16 +86,15 @@ async def run(self) -> dict[str, Any]:
8586 Returns:
8687 Summary of what happened.
8788 """
88- logger .info ("=" * 60 )
89- logger .info ("[AGENT] Starting agent autopost" )
90- logger .info ("=" * 60 )
89+ start_time = time .time ()
90+ logger .info ("[AUTOPOST] === Starting ===" )
9191
9292 try :
9393 # Step 0: Check if posting is allowed (tier limits)
9494 if self .tier_manager :
9595 can_post , reason = self .tier_manager .can_post ()
9696 if not can_post :
97- logger .warning (f"[AGENT] Posting blocked : { reason } " )
97+ logger .warning (f"[AUTOPOST] Blocked : { reason } " )
9898 return {
9999 "success" : False ,
100100 "error" : f"posting_blocked: { reason } " ,
@@ -103,9 +103,9 @@ async def run(self) -> dict[str, Any]:
103103 }
104104
105105 # Step 1: Get context
106- logger .info ("[AGENT] Step 1: Getting context from database " )
106+ logger .info ("[AUTOPOST] [1/5] Loading context... " )
107107 previous_posts = await self .db .get_recent_posts_formatted (limit = 50 )
108- logger .info (f"[AGENT] Loaded { len (previous_posts )} chars of previous posts context " )
108+ logger .info (f"[AUTOPOST] [1/5] Loaded { len (previous_posts )} chars of previous posts" )
109109
110110 # Step 2: Build initial messages
111111 system_prompt = SYSTEM_PROMPT + get_agent_system_prompt ()
@@ -120,58 +120,61 @@ async def run(self) -> dict[str, Any]:
120120 ]
121121
122122 # Step 3: Get plan from LLM
123- logger .info ("[AGENT] Step 2: Getting plan from LLM" )
123+ logger .info ("[AUTOPOST] [2/5] Creating plan - calling LLM... " )
124124 plan_result = await self .llm .chat (messages , PLAN_SCHEMA )
125125
126- logger .info (f"[AGENT] Plan received:" )
127- logger .info (f"[AGENT] Reasoning: { plan_result ['reasoning' ]} " )
128- logger .info (f"[AGENT] Plan: { json .dumps (plan_result ['plan' ], indent = 2 )} " )
126+ plan = plan_result ["plan" ]
127+ tools_list = " -> " .join ([s ["tool" ] for s in plan ]) if plan else "none"
128+ logger .info (f"[AUTOPOST] [2/5] Plan: { len (plan )} tools ({ tools_list } )" )
129+ logger .info (f"[AUTOPOST] [2/5] Reasoning: { plan_result ['reasoning' ][:100 ]} ..." )
129130
130131 # Add assistant response to conversation
131132 messages .append ({"role" : "assistant" , "content" : json .dumps (plan_result )})
132133
133134 # Step 4: Validate plan
134- logger .info ("[AGENT] Step 3: Validating plan" )
135- plan = plan_result ["plan" ]
136135 self ._validate_plan (plan )
137136
138137 # Step 5: Execute plan (each tool result goes back as user message)
139- logger .info ("[AGENT] Step 4: Executing plan " )
138+ logger .info ("[AUTOPOST] [3/5] Executing tools... " )
140139 image_bytes = None
140+ tools_used = []
141141
142142 for i , step in enumerate (plan ):
143143 tool_name = step ["tool" ]
144144 params = step ["params" ]
145+ tools_used .append (tool_name )
145146
146- logger .info (f"[AGENT] Executing step { i + 1 } /{ len (plan )} : { tool_name } " )
147- logger .info (f"[AGENT] Params: { params } " )
147+ if tool_name == "web_search" :
148+ query = params .get ("query" , "" )
149+ logger .info (f"[AUTOPOST] [3/5] [{ i + 1 } /{ len (plan )} ] web_search - query: { query [:50 ]} ..." )
148150
149- try :
150- if tool_name == "web_search" :
151- result = await TOOLS [tool_name ](params .get ("query" , "" ))
151+ result = await TOOLS [tool_name ](query )
152152
153- # Add tool result as user message
153+ if result .get ("error" ):
154+ logger .warning (f"[AUTOPOST] [3/5] web_search: FAILED - { result ['content' ]} " )
155+ messages .append ({"role" : "user" , "content" : f"Tool result (web_search): { result ['content' ]} " })
156+ else :
157+ logger .info (f"[AUTOPOST] [3/5] web_search: OK ({ len (result ['sources' ])} sources)" )
154158 tool_result_msg = f"""Tool result (web_search):
155159Content: { result ['content' ]}
156160Sources found: { len (result ['sources' ])} """
157-
158161 messages .append ({"role" : "user" , "content" : tool_result_msg })
159- logger .info (f"[AGENT] web_search completed: { len (result ['sources' ])} sources" )
160- logger .info (f"[AGENT] Content preview: { result ['content' ][:200 ]} ..." )
161162
162- elif tool_name == "generate_image" :
163- image_bytes = await TOOLS [tool_name ](params .get ("prompt" , "" ))
163+ elif tool_name == "generate_image" :
164+ prompt = params .get ("prompt" , "" )
165+ logger .info (f"[AUTOPOST] [3/5] [{ i + 1 } /{ len (plan )} ] generate_image - prompt: { prompt [:50 ]} ..." )
164166
165- # Add tool result as user message
166- messages .append ({"role" : "user" , "content" : "Tool result (generate_image): Image generated successfully. It will be attached to your post." })
167- logger .info (f"[AGENT] generate_image completed: { len (image_bytes )} bytes" )
167+ image_bytes = await TOOLS [tool_name ](prompt )
168168
169- except Exception as e :
170- logger .error (f"[AGENT] Tool { tool_name } failed: { e } " )
171- messages .append ({"role" : "user" , "content" : f"Tool result ({ tool_name } ): Error - { e } " })
169+ if image_bytes :
170+ logger .info (f"[AUTOPOST] [3/5] generate_image: OK ({ len (image_bytes )} bytes)" )
171+ messages .append ({"role" : "user" , "content" : "Tool result (generate_image): Image generated successfully. It will be attached to your post." })
172+ else :
173+ logger .warning (f"[AUTOPOST] [3/5] generate_image: FAILED - continuing without image" )
174+ messages .append ({"role" : "user" , "content" : "Tool result (generate_image): Failed to generate image. Continue without it." })
172175
173176 # Step 6: Get final post text
174- logger .info ("[AGENT] Step 5: Getting final post text " )
177+ logger .info ("[AUTOPOST] [4/5] Generating tweet - calling LLM... " )
175178
176179 messages .append ({"role" : "user" , "content" : "Now write your final tweet text (max 280 characters). Just the tweet, nothing else." })
177180
@@ -182,46 +185,52 @@ async def run(self) -> dict[str, Any]:
182185 if len (post_text ) > 280 :
183186 post_text = post_text [:277 ] + "..."
184187
185- logger .info (f"[AGENT] Final post text ({ len (post_text )} chars): { post_text } " )
188+ logger .info (f"[AUTOPOST] [4/5] Tweet: { post_text [: 50 ] } ... ({ len (post_text )} chars)" )
186189
187190 # Step 7: Upload image if generated
188191 media_ids = None
189192 if image_bytes :
190- logger .info ("[AGENT] Step 6: Uploading image to Twitter " )
193+ logger .info ("[AUTOPOST] [5/5] Uploading image... " )
191194 try :
192195 media_id = await self .twitter .upload_media (image_bytes )
193196 media_ids = [media_id ]
194- logger .info (f"[AGENT] Image uploaded: media_id= { media_id } " )
197+ logger .info (f"[AUTOPOST] [5/5] Image uploaded: { media_id } " )
195198 except Exception as e :
196- logger .error (f"[AGENT] Image upload failed: { e } " )
199+ logger .error (f"[AUTOPOST] [5/5] Image upload FAILED: { e } " )
200+ image_bytes = None # Mark as no image for summary
197201
198202 # Step 8: Post to Twitter
199- logger .info ("[AGENT] Step 7: Posting to Twitter" )
203+ logger .info ("[AUTOPOST] [5/5] Posting to Twitter... " )
200204 tweet_data = await self .twitter .post (post_text , media_ids = media_ids )
201- logger .info (f"[AGENT] Posted! tweet_id={ tweet_data ['id' ]} " )
202205
203206 # Step 9: Save to database
204- logger .info ("[AGENT] Step 8: Saving to database" )
205207 include_picture = image_bytes is not None
206208 await self .db .save_post (post_text , tweet_data ["id" ], include_picture )
207209
208- logger .info ("=" * 60 )
209- logger .info ("[AGENT] Agent autopost completed successfully!" )
210- logger .info ("=" * 60 )
210+ # Summary
211+ duration = round (time .time () - start_time , 1 )
212+ tools_str = "," .join (tools_used ) if tools_used else "none"
213+ logger .info (f"[AUTOPOST] === Completed in { duration } s ===" )
214+ logger .info (f"[AUTOPOST] Summary: tweet_id={ tweet_data ['id' ]} | tools={ tools_str } | image={ 'yes' if include_picture else 'no' } | chars={ len (post_text )} " )
211215
212216 return {
213217 "success" : True ,
214218 "tweet_id" : tweet_data ["id" ],
215219 "text" : post_text ,
216220 "plan" : plan_result ["plan" ],
217221 "reasoning" : plan_result ["reasoning" ],
218- "conversation_length" : len (messages )
222+ "tools_used" : tools_used ,
223+ "has_image" : include_picture ,
224+ "duration_seconds" : duration
219225 }
220226
221227 except Exception as e :
222- logger .error (f"[AGENT] Agent autopost failed: { e } " )
228+ duration = round (time .time () - start_time , 1 )
229+ logger .error (f"[AUTOPOST] === FAILED after { duration } s ===" )
230+ logger .error (f"[AUTOPOST] Error: { e } " )
223231 logger .exception (e )
224232 return {
225233 "success" : False ,
226- "error" : str (e )
234+ "error" : str (e ),
235+ "duration_seconds" : duration
227236 }
0 commit comments